This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
pespin gerrit-no-reply at lists.osmocom.orgpespin has uploaded this change for review. ( https://gerrit.osmocom.org/c/libosmo-netif/+/15576 Change subject: stream_test: Log fake time ...................................................................... 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 --- M tests/stream/stream_test.c M tests/stream/stream_test.err M tests/stream/stream_test.ok 3 files changed, 76 insertions(+), 61 deletions(-) git pull ssh://gerrit.osmocom.org:29418/libosmo-netif refs/changes/76/15576/1 diff --git a/tests/stream/stream_test.c b/tests/stream/stream_test.c index 4fd8573..a558e2e 100644 --- a/tests/stream/stream_test.c +++ b/tests/stream/stream_test.c @@ -57,8 +57,12 @@ #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 @@ #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 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,8 +343,11 @@ 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))); @@ -358,6 +371,8 @@ 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); diff --git a/tests/stream/stream_test.err b/tests/stream/stream_test.err index 07cc7b0..04bfcfe 100644 --- a/tests/stream/stream_test.err +++ b/tests/stream/stream_test.err @@ -1,43 +1,43 @@ -autoreconnecting test step 11 [client NA, server OK], FD reg 1 +{2.000001} autoreconnecting test step 11 [client NA, server OK], FD reg 1 -autoreconnecting test step 10 [client NA, server OK], FD reg 1 +{2.000002} autoreconnecting test step 10 [client NA, server OK], FD reg 1 -autoreconnecting test step 9 [client NA, server OK], FD reg 1 +{2.000003} autoreconnecting test step 9 [client NA, server OK], FD reg 1 -autoreconnecting test step 8 [client NA, server OK], FD reg 1 +{2.000004} autoreconnecting test step 8 [client NA, server OK], FD reg 1 -autoreconnecting test step 7 [client OK, server OK], FD reg 1 +{2.000005} autoreconnecting test step 7 [client OK, server OK], FD reg 1 -autoreconnecting test step 6 [client OK, server OK], FD reg 1 +{2.000006} autoreconnecting test step 6 [client OK, server OK], FD reg 1 -autoreconnecting test step 5 [client OK, server OK], FD reg 1 +{2.000007} autoreconnecting test step 5 [client OK, server OK], FD reg 1 [ CONNECTED] osmo_stream_cli_recv(): connection closed with srv [ NONE] osmo_stream_cli_reconnect(): retrying in 9 seconds... -autoreconnecting test step 4 [client OK, server OK], FD reg 0 +{11.000008} autoreconnecting test step 4 [client OK, server OK], FD reg 0 -autoreconnecting test step 3 [client OK, server OK], FD reg 1 +{11.000009} autoreconnecting test step 3 [client OK, server OK], FD reg 1 -autoreconnecting test step 2 [client OK, server OK], FD reg 0 +{11.000010} autoreconnecting test step 2 [client OK, server OK], FD reg 0 connection closed with srv -autoreconnecting test step 1 [client OK, server NA], FD reg 0 +{11.000011} autoreconnecting test step 1 [client OK, server NA], FD reg 0 -non-reconnecting test step 7 [client NA, server OK], FD reg 1 +{11.000012} non-reconnecting test step 7 [client NA, server OK], FD reg 1 -non-reconnecting test step 6 [client NA, server OK], FD reg 1 +{11.000013} non-reconnecting test step 6 [client NA, server OK], FD reg 1 -non-reconnecting test step 5 [client NA, server OK], FD reg 1 +{11.000014} non-reconnecting test step 5 [client NA, server OK], FD reg 1 -non-reconnecting test step 4 [client NA, server OK], FD reg 1 +{11.000015} non-reconnecting test step 4 [client NA, server OK], FD reg 1 -non-reconnecting test step 3 [client OK, server OK], FD reg 1 +{11.000016} non-reconnecting test step 3 [client OK, server OK], FD reg 1 -non-reconnecting test step 2 [client OK, server OK], FD reg 1 +{11.000017} non-reconnecting test step 2 [client OK, server OK], FD reg 1 -non-reconnecting test step 1 [client OK, server OK], FD reg 1 +{11.000018} non-reconnecting test step 1 [client OK, server OK], FD reg 1 [ CONNECTED] osmo_stream_cli_recv(): connection closed with srv [ NONE] osmo_stream_cli_reconnect(): not reconnecting, disabled. -non-reconnecting test step 0 [client OK, server OK], FD reg 0 +{20.000019} non-reconnecting test step 0 [client OK, server OK], FD reg 0 diff --git a/tests/stream/stream_test.ok b/tests/stream/stream_test.ok index 7b6fb95..bccf386 100644 --- a/tests/stream/stream_test.ok +++ b/tests/stream/stream_test.ok @@ -3,26 +3,26 @@ ======================================= Client/Server entering autoreconnecting event loop... ======================================= -[NA] Client's connect_cb_cli(): callback triggered <initial> -[NA] Client's connect_cb_cli(): sent 29 bytes message: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 -[NA|OK] Server's read_cb_srv(): callback triggered -[NA|OK] Server's read_cb_srv(): received 29(29) bytes: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 -[NA|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 -[OK|OK] Server's read_cb_srv(): keep initial client connection -[NA] Client's read_cb_cli(): callback triggered -[NA] Client's read_cb_cli(): received 11(11) bytes: 72 65 61 64 5f 63 62 5f 73 72 76 -[NA] Client's read_cb_cli(): initial read, contacting server -[OK] Client's read_cb_cli(): sent 29 bytes message: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 -[OK|OK] Server's read_cb_srv(): callback triggered -[OK|OK] Server's read_cb_srv(): received 29(29) bytes: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 -[OK|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 -[OK|OK] Server's read_cb_srv(): force client disconnect on subsequent call -[OK] Client's read_cb_cli(): callback triggered -[OK] Client's read_cb_cli(): 0-byte read, auto-reconnect will be triggered if enabled -[OK] Client's connect_cb_cli(): callback triggered <reconnected> -[OK] Client's connect_cb_cli(): closing connection -[NA|OK] Server's read_cb_srv(): callback triggered -[NA|OK] Server's read_cb_srv(): client have already closed connection +{2.000001} [NA] Client's connect_cb_cli(): callback triggered <initial> +{2.000001} [NA] Client's connect_cb_cli(): sent 29 bytes message: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 +{2.000003} [NA|OK] Server's read_cb_srv(): callback triggered +{2.000003} [NA|OK] Server's read_cb_srv(): received 29(29) bytes: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 +{2.000003} [NA|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 +{2.000003} [OK|OK] Server's read_cb_srv(): keep initial client connection +{2.000005} [NA] Client's read_cb_cli(): callback triggered +{2.000005} [NA] Client's read_cb_cli(): received 11(11) bytes: 72 65 61 64 5f 63 62 5f 73 72 76 +{2.000005} [NA] Client's read_cb_cli(): initial read, contacting server +{2.000005} [OK] Client's read_cb_cli(): sent 29 bytes message: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 +{2.000007} [OK|OK] Server's read_cb_srv(): callback triggered +{2.000007} [OK|OK] Server's read_cb_srv(): received 29(29) bytes: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 +{2.000007} [OK|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 +{2.000007} [OK|OK] Server's read_cb_srv(): force client disconnect on subsequent call +{2.000008} [OK] Client's read_cb_cli(): callback triggered +{2.000008} [OK] Client's read_cb_cli(): 0-byte read, auto-reconnect will be triggered if enabled +{11.000010} [OK] Client's connect_cb_cli(): callback triggered <reconnected> +{11.000010} [OK] Client's connect_cb_cli(): closing connection +{11.000011} [NA|OK] Server's read_cb_srv(): callback triggered +{11.000011} [NA|OK] Server's read_cb_srv(): client have already closed connection Server requested test termination autoreconnecting test complete. @@ -30,22 +30,22 @@ ======================================= Client/Server entering non-reconnecting event loop... ======================================= -[NA] Client's connect_cb_cli(): callback triggered <initial> -[NA] Client's connect_cb_cli(): sent 29 bytes message: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 -[NA|OK] Server's read_cb_srv(): callback triggered -[NA|OK] Server's read_cb_srv(): received 29(29) bytes: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 -[NA|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 -[OK|OK] Server's read_cb_srv(): keep initial client connection -[NA] Client's read_cb_cli(): callback triggered -[NA] Client's read_cb_cli(): received 11(11) bytes: 72 65 61 64 5f 63 62 5f 73 72 76 -[NA] Client's read_cb_cli(): initial read, contacting server -[OK] Client's read_cb_cli(): sent 29 bytes message: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 -[OK|OK] Server's read_cb_srv(): callback triggered -[OK|OK] Server's read_cb_srv(): received 29(29) bytes: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 -[OK|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 -[OK|OK] Server's read_cb_srv(): force client disconnect on subsequent call -[OK] Client's read_cb_cli(): callback triggered -[OK] Client's read_cb_cli(): 0-byte read, auto-reconnect will be triggered if enabled +{11.000012} [NA] Client's connect_cb_cli(): callback triggered <initial> +{11.000012} [NA] Client's connect_cb_cli(): sent 29 bytes message: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 +{11.000014} [NA|OK] Server's read_cb_srv(): callback triggered +{11.000014} [NA|OK] Server's read_cb_srv(): received 29(29) bytes: 48 69 21 20 66 72 6f 6d 20 63 6f 6e 6e 65 63 74 20 63 61 6c 6c 62 61 63 6b 20 3a 2d 50 +{11.000014} [NA|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 +{11.000014} [OK|OK] Server's read_cb_srv(): keep initial client connection +{11.000016} [NA] Client's read_cb_cli(): callback triggered +{11.000016} [NA] Client's read_cb_cli(): received 11(11) bytes: 72 65 61 64 5f 63 62 5f 73 72 76 +{11.000016} [NA] Client's read_cb_cli(): initial read, contacting server +{11.000016} [OK] Client's read_cb_cli(): sent 29 bytes message: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 +{11.000018} [OK|OK] Server's read_cb_srv(): callback triggered +{11.000018} [OK|OK] Server's read_cb_srv(): received 29(29) bytes: 44 6f 68 2c 20 72 65 73 70 6f 6e 64 69 6e 67 20 74 6f 20 73 65 72 76 65 72 20 3a 2d 44 +{11.000018} [OK|OK] Server's read_cb_srv(): sent 11 bytes message: 72 65 61 64 5f 63 62 5f 73 72 76 +{11.000018} [OK|OK] Server's read_cb_srv(): force client disconnect on subsequent call +{11.000019} [OK] Client's read_cb_cli(): callback triggered +{11.000019} [OK] Client's read_cb_cli(): 0-byte read, auto-reconnect will be triggered if enabled non-reconnecting test complete. Stream tests completed -- To view, visit https://gerrit.osmocom.org/c/libosmo-netif/+/15576 To unsubscribe, or for help writing mail filters, visit https://gerrit.osmocom.org/settings Gerrit-Project: libosmo-netif Gerrit-Branch: master Gerrit-Change-Id: I86eb1d7a8096011fd273f067255eb8d6484be65c Gerrit-Change-Number: 15576 Gerrit-PatchSet: 1 Gerrit-Owner: pespin <pespin at sysmocom.de> Gerrit-MessageType: newchange -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://lists.osmocom.org/pipermail/gerrit-log/attachments/20190919/cd0fccc7/attachment.htm>