From 979f2df57d044e52cecd7bdc50a29094a515857e Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Fri, 5 May 2023 14:02:07 +0200 Subject: [PATCH] core.network_time.broker: Test reliability improvement I wasn't able to reproduce this locally, but after looking at -B main-loop,tm for a bit it dawned that if the manager is sending ticks too fast, the Broker IO source may consume two ticks in one go before expiring timers and that would explain the observed baseline differences. Solve this by removing the reliance on realtime delays and switch to a request-reply pattern instead. Also fix indentation and bogus messages. Fixes #3013 --- .../core.network_time.broker/manager..stdout | 2 +- .../core.network_time.broker/worker..stdout | 2 +- testing/btest/core/network_time/broker.zeek | 24 ++++++++++++------- 3 files changed, 17 insertions(+), 11 deletions(-) diff --git a/testing/btest/Baseline/core.network_time.broker/manager..stdout b/testing/btest/Baseline/core.network_time.broker/manager..stdout index 658d123ea1..d4c454b893 100644 --- a/testing/btest/Baseline/core.network_time.broker/manager..stdout +++ b/testing/btest/Baseline/core.network_time.broker/manager..stdout @@ -1,4 +1,4 @@ ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. manager: listening -manager: peer added, publishing do_continue_processing +manager: peer added, publishing timer_tick() events manager: peer lost, terminating diff --git a/testing/btest/Baseline/core.network_time.broker/worker..stdout b/testing/btest/Baseline/core.network_time.broker/worker..stdout index d5abbff6b9..9ff86f6f95 100644 --- a/testing/btest/Baseline/core.network_time.broker/worker..stdout +++ b/testing/btest/Baseline/core.network_time.broker/worker..stdout @@ -17,7 +17,7 @@ 44.750, timer_tick, 13, 45.0 45.000, timer, second timer (3 sec) 45.000, timer_tick, 14, 45.25 -45.250, timer, third timer (3.5 sec) +45.250, timer, third timer (3.25 sec) 45.250, timer_tick, 15, 45.5 45.500, timer_tick, 16, 45.75 45.750, timer_tick, 17, 46.0 diff --git a/testing/btest/core/network_time/broker.zeek b/testing/btest/core/network_time/broker.zeek index 9419fb5d3f..7ec26a7a03 100644 --- a/testing/btest/core/network_time/broker.zeek +++ b/testing/btest/core/network_time/broker.zeek @@ -11,6 +11,8 @@ redef allow_network_time_forward = F; +global timer_tock: event(); + event zeek_init() { print network_time(), "zeek_init: broker peering"; @@ -34,7 +36,8 @@ event timer(s: string) print fmt("%.3f", network_time()), "timer", s; } -# The manager tells us our network_time. +# The manager sends timer_tick() with the network time to the worker which +# replies back with a timer_tock(). global received_ticks = 0; event timer_tick(ts: time) &is_used { @@ -48,10 +51,12 @@ event timer_tick(ts: time) &is_used { schedule 0.5sec { timer("first timer (1 sec)") }; schedule 3sec { timer("second timer (3 sec)") }; - schedule 3.25sec { timer("third timer (3.5 sec)") }; + schedule 3.25sec { timer("third timer (3.25 sec)") }; schedule 5sec { timer("fourth timer (10 sec)") }; } + Broker::publish("zeek/event/my_topic", timer_tock); + if ( received_ticks == 30 ) terminate(); } @@ -74,20 +79,21 @@ event zeek_init() { print "manager: listening"; Broker::listen("127.0.0.1", to_port(getenv("BROKER_PORT"))); + Broker::subscribe("zeek/event/my_topic"); } -event local_tick() { +# Received from the worker once it has processed the tick. +event timer_tock() &is_used + { fake_network_time = fake_network_time + double_to_interval(0.25); Broker::publish("zeek/event/my_topic", timer_tick, fake_network_time); - schedule 0.05 sec { local_tick() }; -} + } event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) - { - print "manager: peer added, publishing do_continue_processing"; + { + print "manager: peer added, publishing timer_tick() events"; Broker::publish("zeek/event/my_topic", timer_tick, fake_network_time); - schedule 0.05 sec { local_tick() }; - } + } event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) {