From 8c7d62f6d2041693f6762c3acb03404934d1b52a Mon Sep 17 00:00:00 2001 From: Pau Espin Pedrol Date: Thu, 19 Sep 2019 15:35:39 +0200 Subject: stream_test: Log fake time It allows easy verification that timing is correct and makes it easier to debug time related race conditions. Change-Id: I86eb1d7a8096011fd273f067255eb8d6484be65c --- tests/stream/stream_test.c | 32 ++++++++++++++++++++++++-------- 1 file changed, 24 insertions(+), 8 deletions(-) (limited to 'tests/stream/stream_test.c') diff --git a/tests/stream/stream_test.c b/tests/stream/stream_test.c index 4fd8573..b4846bc 100644 --- a/tests/stream/stream_test.c +++ b/tests/stream/stream_test.c @@ -57,8 +57,12 @@ static struct msgb *make_msgb(const char *m) #define ASTR(rec) ((rec) ? "autoreconnecting" : "non-reconnecting") /* client defs */ -#define LOGCLI(cli, fmt, args...) \ - printf("[%s] Client's %s(): " fmt, osmo_stream_cli_get_data(cli) ? "OK" : "NA", __func__, ##args) +#define LOGCLI(cli, fmt, args...) do { \ + struct timeval tv; \ + osmo_gettimeofday(&tv, NULL); \ + printf("{%lu.%06lu} [%s] Client's %s(): " fmt, tv.tv_sec, tv.tv_usec, \ + osmo_stream_cli_get_data(cli) ? "OK" : "NA", __func__, ##args); \ + } while (0) #define CLI_SND(cli, m) do { \ struct msgb *msg = make_msgb(m); \ @@ -228,9 +232,14 @@ static struct osmo_stream_cli *make_client(void *ctx, const char *host, unsigned #define LOGLNK(lnk, fmt, args...) \ printf("[%s] Server's %s(): " fmt, osmo_stream_srv_link_get_data(lnk) ? "OK" : "NA", __func__, ##args) -#define LOGSRV(srv, fmt, args...) \ - printf("[%s|%s] Server's %s(): " fmt, osmo_stream_srv_get_data(srv) ? "OK" : "NA", \ - osmo_stream_srv_link_get_data(osmo_stream_srv_get_master(srv)) ? "OK" : "NA", __func__, ##args) +#define LOGSRV(srv, fmt, args...) do { \ + struct timeval tv; \ + osmo_gettimeofday(&tv, NULL); \ + printf("{%lu.%06lu} [%s|%s] Server's %s(): " fmt, tv.tv_sec, tv.tv_usec, \ + osmo_stream_srv_get_data(srv) ? "OK" : "NA", \ + osmo_stream_srv_link_get_data(osmo_stream_srv_get_master(srv)) ? "OK" : "NA", \ + __func__, ##args); \ + } while (0) #define SRV_SND(srv, m) do { \ struct msgb *msg = make_msgb(m); \ @@ -322,6 +331,7 @@ static int accept_cb_srv(struct osmo_stream_srv_link *lnk, int fd) static void test_recon(void *ctx, const char *host, unsigned port, unsigned steps, struct osmo_stream_srv_link *lnk, bool autoreconnect) { + struct timeval tv; struct osmo_stream_cli *cli = make_client(ctx, host, port, autoreconnect); if (!cli) return; @@ -333,20 +343,24 @@ static void test_recon(void *ctx, const char *host, unsigned port, unsigned step osmo_stream_srv_link_set_data(lnk, ctx); while(steps--) { + osmo_gettimeofday_override_add(0, 1); /* small increment to easily spot iterations */ osmo_select_main(0); - fprintf(stderr, "\n%s test step %u [client %s, server %s], FD reg %u\n", ASTR(autoreconnect), steps, + osmo_gettimeofday(&tv, NULL); + fprintf(stderr, "\n{%lu.%06lu} %s test step %u [client %s, server %s], FD reg %u\n", + tv.tv_sec, tv.tv_usec, ASTR(autoreconnect), steps, osmo_stream_cli_get_data(cli) ? "OK" : "NA", osmo_stream_srv_link_get_data(lnk) ? "OK" : "NA", osmo_fd_is_registered(osmo_stream_cli_get_ofd(cli))); if (test_stop_requested(lnk)) { - printf("Server requested test termination\n"); + printf("{%lu.%06lu} Server requested test termination\n", + tv.tv_sec, tv.tv_usec); steps = 0; } } osmo_stream_cli_destroy(cli); - printf("%s test complete.\n\n", ASTR(autoreconnect)); + printf("{%lu.%06lu} %s test complete.\n\n", tv.tv_sec, tv.tv_usec, ASTR(autoreconnect)); } @@ -358,6 +372,8 @@ int main(void) void *tall_test = talloc_named_const(NULL, 1, "osmo_stream_test"); osmo_gettimeofday_override = true; + osmo_gettimeofday_override_time.tv_sec = 2; + osmo_gettimeofday_override_time.tv_usec = 0; msgb_talloc_ctx_init(tall_test, 0); osmo_init_logging2(tall_test, &osmo_stream_test_log_info); -- cgit v1.2.3