From a9f8627dd9d6eccacc3e61e184656b42d8585b2c Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Tue, 14 Mar 2023 17:53:43 +0100 Subject: [PATCH 01/13] PktSrc: Move termination pseduo_realtime special case to RunState This also removes setting pseduo_realtime to 0.0 in the main loop when the packet source has been closed. I had tried to understand the implications it actually seems, if we shutdown the iosource::Manager anyway, it shouldn't and it's just confusing. --- src/RunState.cc | 12 ++++-------- src/iosource/PktSrc.cc | 6 ------ 2 files changed, 4 insertions(+), 14 deletions(-) diff --git a/src/RunState.cc b/src/RunState.cc index 67041cc915..3188f4b63c 100644 --- a/src/RunState.cc +++ b/src/RunState.cc @@ -352,17 +352,13 @@ void run_loop() // the future on which we need to wait. have_pending_timers = zeek::detail::timer_mgr->Size() > 0; + // Terminate if we're running pseudo_realtime and + // the interface has been closed. if ( pseudo_realtime && communication_enabled ) { - auto have_active_packet_source = false; - iosource::PktSrc* ps = iosource_mgr->GetPktSrc(); - if ( ps && ps->IsOpen() ) - have_active_packet_source = true; - - if ( ! have_active_packet_source ) - // Can turn off pseudo realtime now - pseudo_realtime = 0.0; + if ( ps && ! ps->IsOpen() ) + iosource_mgr->Terminate(); } } diff --git a/src/iosource/PktSrc.cc b/src/iosource/PktSrc.cc index a7940250df..2ca5d2720e 100644 --- a/src/iosource/PktSrc.cc +++ b/src/iosource/PktSrc.cc @@ -194,12 +194,6 @@ bool PktSrc::ExtractNextPacketInternal() had_packet = false; } - if ( run_state::pseudo_realtime && ! IsOpen() ) - { - if ( broker_mgr->Active() ) - iosource_mgr->Terminate(); - } - return false; } From eefa0150b93b8446ba239a58d347088cb42d6d61 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 14:25:22 +0100 Subject: [PATCH 02/13] PktSrc: Add HasBeenIdleFor() method This method will be used by the main loop to determine if an interface has become idle. Initially this will be used to determine when it is acceptable to update network_time to the current time (wallclock). --- src/iosource/PktSrc.cc | 22 ++++++++++++++++++++++ src/iosource/PktSrc.h | 20 ++++++++++++++++++++ 2 files changed, 42 insertions(+) diff --git a/src/iosource/PktSrc.cc b/src/iosource/PktSrc.cc index 2ca5d2720e..0fa9585621 100644 --- a/src/iosource/PktSrc.cc +++ b/src/iosource/PktSrc.cc @@ -139,6 +139,16 @@ void PktSrc::Done() Close(); } +bool PktSrc::HasBeenIdleFor(double interval) const + { + if ( have_packet || had_packet ) + return false; + + // Take the hit of a current_time() call now. + double now = zeek::util::current_time(true); + return idle_at_wallclock < now - interval; + }; + void PktSrc::Process() { if ( ! IsOpen() ) @@ -191,6 +201,18 @@ bool PktSrc::ExtractNextPacketInternal() } else { + // Update the idle_at timestamp the first time we've failed + // to extract a packet. This assumes ExtractNextPacket() is + // called regularly which is true for non-selectable PktSrc + // instances, but even for selectable ones with an FD the + // main-loop will call Process() on the interface regularly + // and detect it as idle. + if ( had_packet ) + { + DBG_LOG(DBG_PKTIO, "source %s is idle now", props.path.c_str()); + idle_at_wallclock = zeek::util::current_time(true); + } + had_packet = false; } diff --git a/src/iosource/PktSrc.h b/src/iosource/PktSrc.h index d93b5d60bc..a1ef1c6e64 100644 --- a/src/iosource/PktSrc.h +++ b/src/iosource/PktSrc.h @@ -88,6 +88,24 @@ public: */ bool IsError() const; + /** + * Return true if the source has been observed idle for the given + * wallclock interval. + * + * The default implementation looks at failing ExtractNextPacket() calls + * and keeps the wallclock timestamp when there was no packet available. + * The source is considered idle when there has not been a packet since + * \a interval seconds. + * + * Alternative implementations may check internally buffered packets + * or queue lengths. + * + * @param interval Interval in seconds. + * + * @return True if the source has been idle for \a interval seconds. + */ + virtual bool HasBeenIdleFor(double interval) const; + /** * If the source encountered an error, returns a corresponding error * message. Returns an empty string otherwise. @@ -365,6 +383,8 @@ private: // Did the previous call to ExtractNextPacket() yield a packet. bool had_packet; + double idle_at_wallclock = 0.0; + // For BPF filtering support. std::vector filters; From d4e31e7d2bdea31aa060ef7b95066ee27ce628e5 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 15:03:17 +0100 Subject: [PATCH 03/13] RunState: Implement forward_network_time_if_applicable() Add a central place where the decision when it's okay to update network time to the current time (wallclock) is. It checks for pseudo_realtime and packet source existence as well as packet source idleness. A new const &redef allows to completely disable forwarding of network time. --- scripts/base/init-bare.zeek | 26 ++++++++++++++++ src/RunState.cc | 62 ++++++++++++++++++++++++++++++------- src/const.bif | 2 ++ src/zeek-setup.cc | 3 +- 4 files changed, 80 insertions(+), 13 deletions(-) diff --git a/scripts/base/init-bare.zeek b/scripts/base/init-bare.zeek index b69880db55..847c2f21e8 100644 --- a/scripts/base/init-bare.zeek +++ b/scripts/base/init-bare.zeek @@ -161,6 +161,32 @@ type PacketSource: record { netmask: count; }; + +## If a packet source does not yield packets for this amount of time, +## it is considered idle. When a packet source is found to be idle, +## Zeek will update network_time to current time in order for timer expiration +## to function. A packet source queueing up packets and not yielding them for +## longer than this interval without yielding any packets will provoke +## not-very-well-defined timer behavior. +## +## On Zeek workers with low packet rates, timer expiration may be delayed +## by this many milliseconds after the last packet has been received. +const packet_source_inactivity_timeout = 100msec &redef; + +## Whether Zeek will forward network_time to the current time upon +## observing an idle packet source (or no configured packet source). +## +## Only set this to *F* if you really know what you're doing. Setting this to +## *F* on non-worker systems causes :zeek:see:`network_time` to be stuck +## at 0.0 and timer expiration will be non-functional. +## +## The main purpose of this option is to yield control over network time +## to plugins or scripts via broker or other non-timer events. +## +## .. zeek:see:: network_time set_network_time packet_source_inactivity_timeout +## +const allow_network_time_forward = T &redef; + ## A connection's transport-layer protocol. Note that Zeek uses the term ## "connection" broadly, using flow semantics for ICMP and UDP. type transport_proto: enum { diff --git a/src/RunState.cc b/src/RunState.cc index 3188f4b63c..19cc97c0de 100644 --- a/src/RunState.cc +++ b/src/RunState.cc @@ -137,6 +137,44 @@ void update_network_time(double new_network_time) PLUGIN_HOOK_VOID(HOOK_UPDATE_NETWORK_TIME, HookUpdateNetworkTime(new_network_time)); } +// Logic to decide when updating network_time is acceptable: +static bool should_forward_network_time() + { + // In pseudo_realtime mode, always update time once + // we've dispatched and processed the first packet. + // run_state::detail::first_timestamp is currently set + // in PktSrc::ExtractNextPacketInternal() + if ( pseudo_realtime != 0.0 && run_state::detail::first_timestamp != 0.0 ) + return true; + + if ( iosource::PktSrc* ps = iosource_mgr->GetPktSrc() ) + { + // Offline packet sources always control network time + // unless we're running pseudo_realtime, see above. + if ( ! ps->IsLive() ) + return false; + + if ( ! ps->HasBeenIdleFor(BifConst::packet_source_inactivity_timeout) ) + return false; + } + + // We determined that we don't have a packet source, or it is idle. + // Unless it has been disabled, network_time will now be moved forward. + return BifConst::allow_network_time_forward; + } + +static void forward_network_time_if_applicable() + { + if ( ! should_forward_network_time() ) + return; + + double now = util::current_time(true); + if ( now > network_time ) + update_network_time(now); + + return; + } + void init_run(const std::optional& interface, const std::optional& pcap_input_file, const std::optional& pcap_output_file, bool do_watchdog) @@ -319,21 +357,21 @@ void run_loop() // date on timers and events. Because we only // have timers as sources, going to sleep here // doesn't risk blocking on other inputs. - update_network_time(util::current_time()); + // + // TBD: Is this actually still relevant given that the TimerMgr + // is an IO source now? It'll be processed once its + // GetNextTimeout() yields 0 and before that there's nothing + // to expire anyway. + forward_network_time_if_applicable(); expire_timers(); + + // Prevent another forward_network_time_if_applicable() below + // even if time wasn't actually updated. + time_updated = true; } - // Ensure that the time gets updated every pass if we're reading live. - // This is necessary for e.g. packet sources that don't have a selectable - // file descriptor. They'll always be ready on a very short timeout, but - // won't necessarily have a packet to process. In these case, sometimes - // the time won't get updated for a long time and timers don't function - // correctly. - if ( (! time_updated && reading_live) ) - { - update_network_time(util::current_time()); - expire_timers(); - } + if ( ! time_updated ) + forward_network_time_if_applicable(); event_mgr.Drain(); diff --git a/src/const.bif b/src/const.bif index 4d793d82c1..55d5222f47 100644 --- a/src/const.bif +++ b/src/const.bif @@ -2,6 +2,8 @@ ##! internally. Documentation and default values for the scripting-layer ##! variables themselves are found in :doc:`/scripts/base/init-bare.zeek`. +const packet_source_inactivity_timeout: interval; +const allow_network_time_forward: bool; const ignore_keep_alive_rexmit: bool; const skip_http_data: bool; const use_conn_size_analyzer: bool; diff --git a/src/zeek-setup.cc b/src/zeek-setup.cc index 1ba3e4270b..98e87cfcbf 100644 --- a/src/zeek-setup.cc +++ b/src/zeek-setup.cc @@ -1036,7 +1036,8 @@ SetupResult setup(int argc, char** argv, Options* zopts) segment_logger = profiling_logger; } - if ( ! run_state::reading_live && ! run_state::reading_traces ) + if ( ! run_state::reading_live && ! run_state::reading_traces && + id::find_const("allow_network_time_forward")->AsBool() ) // Set up network_time to track real-time, since // we don't have any other source for it. run_state::detail::update_network_time(util::current_time()); From 2e8176305bef63b54538a674f889009f5060fe0d Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 15:05:15 +0100 Subject: [PATCH 04/13] Event: No more network_time updates The whole docs read like this was only used to update the network_time, so there may be a follow-up to ditch EventMgr even being an IOSource (which could be argued it's not IO). --- src/Event.cc | 12 +----------- 1 file changed, 1 insertion(+), 11 deletions(-) diff --git a/src/Event.cc b/src/Event.cc index 2a894cfbfd..065cee5839 100644 --- a/src/Event.cc +++ b/src/Event.cc @@ -189,22 +189,12 @@ void EventMgr::Describe(ODesc* d) const void EventMgr::Process() { - // If we don't have a source, or the source is closed, or we're - // reading live (which includes pseudo-realtime), advance the time - // here to the current time since otherwise it won't move forward. - iosource::PktSrc* pkt_src = iosource_mgr->GetPktSrc(); - if ( ! pkt_src || ! pkt_src->IsOpen() || run_state::reading_live ) - run_state::detail::update_network_time(util::current_time()); - queue_flare.Extinguish(); // While it semes like the most logical thing to do, we dont want // to call Drain() as part of this method. It will get called at // the end of net_run after all of the sources have been processed - // and had the opportunity to spawn new events. We could use - // zeek::iosource_mgr->Wakeup() instead of making EventMgr an IOSource, - // but then we couldn't update the time above and nothing would - // drive it forward. + // and had the opportunity to spawn new events. } void EventMgr::InitPostScript() From c30b5cbc4d2019dfdd942a5b157e30602402f5cc Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 15:06:54 +0100 Subject: [PATCH 05/13] TimerMgr: No network_time updates in Process() network_time forwarding will now happen centrally in the main loop. The TimerMgr returns a valid timeout that can be waited for and will trigger network_time advancement, so we don't need to do it. --- src/Timer.cc | 8 -------- 1 file changed, 8 deletions(-) diff --git a/src/Timer.cc b/src/Timer.cc index 6908e81f95..b92dfd5c1f 100644 --- a/src/Timer.cc +++ b/src/Timer.cc @@ -93,14 +93,6 @@ int TimerMgr::Advance(double arg_t, int max_expire) void TimerMgr::Process() { - // If we don't have a source, or the source is closed, or we're reading live (which includes - // pseudo-realtime), advance the timer here to the current time since otherwise it won't - // move forward and the timers won't fire correctly. - iosource::PktSrc* pkt_src = iosource_mgr->GetPktSrc(); - if ( ! pkt_src || ! pkt_src->IsOpen() || run_state::reading_live || - run_state::is_processing_suspended() ) - run_state::detail::update_network_time(util::current_time()); - // Just advance the timer manager based on the current network time. This won't actually // change the time, but will dispatch any timers that need dispatching. run_state::current_dispatched += Advance(run_state::network_time, From 3269310e61a2a5d60be247edca19678fdf7ec4df Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 15:12:06 +0100 Subject: [PATCH 06/13] broker::Manager: No more network_time forwarding network_time forwarding will happen in the main-loop before draining the EventMgr so timers/events scheduled based on broker messages should behave similarly. This also keeps network_time unaffected during non pseudo-realtime trace processing. --- src/broker/Manager.cc | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/src/broker/Manager.cc b/src/broker/Manager.cc index e35ece26e2..37042d78d1 100644 --- a/src/broker/Manager.cc +++ b/src/broker/Manager.cc @@ -1140,11 +1140,6 @@ void Manager::DispatchMessage(const broker::topic& topic, broker::data msg) void Manager::Process() { - // Ensure that time gets update before processing broker messages, or events - // based on them might get scheduled wrong. - if ( use_real_time ) - run_state::detail::update_network_time(util::current_time()); - auto messages = bstate->subscriber.poll(); bool had_input = ! messages.empty(); @@ -1221,10 +1216,16 @@ void Manager::Process() if ( had_input ) { if ( run_state::network_time == 0 ) + { // If we're getting Broker messages, but still haven't initialized // run_state::network_time, may as well do so now because otherwise the // broker/cluster logs will end up using timestamp 0. - run_state::detail::update_network_time(util::current_time()); + // + // Do not do this when allow_network_time_forard is set to F + // with the assumption that this is unwanted behavior. + if ( get_option("allow_network_time_forward")->AsBool() ) + run_state::detail::update_network_time(util::current_time()); + } } } From 9c5b439e8febf076b8ef957f84c1659d93e6107e Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 15:16:57 +0100 Subject: [PATCH 07/13] btest: More verbose recursive-event output I don't think something broken, but the one line output. --- .../Baseline/core.recursive-event/output | 22 ++++++++++++- testing/btest/core/recursive-event.zeek | 32 +++++++++++-------- 2 files changed, 40 insertions(+), 14 deletions(-) diff --git a/testing/btest/Baseline/core.recursive-event/output b/testing/btest/Baseline/core.recursive-event/output index 8feeb4e0a5..5ce335085a 100644 --- a/testing/btest/Baseline/core.recursive-event/output +++ b/testing/btest/Baseline/core.recursive-event/output @@ -1,2 +1,22 @@ ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. -10 +XXXXXXXXXX.XXXXXX 0 1 +XXXXXXXXXX.XXXXXX 1 2 +XXXXXXXXXX.XXXXXX 0 3 +XXXXXXXXXX.XXXXXX 1 4 +XXXXXXXXXX.XXXXXX 0 5 +XXXXXXXXXX.XXXXXX 1 6 +XXXXXXXXXX.XXXXXX 0 7 +XXXXXXXXXX.XXXXXX 1 8 +XXXXXXXXXX.XXXXXX 0 9 +XXXXXXXXXX.XXXXXX 1 10 +XXXXXXXXXX.XXXXXX 0 11 +XXXXXXXXXX.XXXXXX 1 12 +XXXXXXXXXX.XXXXXX 0 13 +XXXXXXXXXX.XXXXXX 1 14 +XXXXXXXXXX.XXXXXX 0 15 +XXXXXXXXXX.XXXXXX 1 16 +XXXXXXXXXX.XXXXXX 0 17 +XXXXXXXXXX.XXXXXX 1 18 +XXXXXXXXXX.XXXXXX 0 19 +XXXXXXXXXX.XXXXXX 1 20 +unique_nt 11 diff --git a/testing/btest/core/recursive-event.zeek b/testing/btest/core/recursive-event.zeek index fc99638798..3583b369f6 100644 --- a/testing/btest/core/recursive-event.zeek +++ b/testing/btest/core/recursive-event.zeek @@ -1,32 +1,38 @@ -# @TEST-EXEC: zeek -b %INPUT 2>&1 | grep -v termination | sort | uniq | wc -l | awk '{print $1}' >output +# @TEST-EXEC: zeek -b %INPUT >output # @TEST-EXEC: btest-diff output # In old version, the event would keep triggering endlessly, with the network # time not moving forward and Zeek not terminating. -# -# Note that the output will not be 20 because we still execute two rounds -# of events every time we drain and also at startup several (currently 3) -# rounds of events drain with the same network_time. redef exit_only_after_terminate=T; global c = 0; +global last_nt = 0.0; +global unique_nt: set[double]; event test() { c += 1; + local nt = time_to_double(network_time()); + if ( last_nt == 0.0 ) + last_nt = nt; - if ( c == 20 ) + add unique_nt[nt]; + + print fmt("%.5f %d %d", nt, nt != last_nt, c); + last_nt = nt; + + if ( c == 20 ) { + print fmt("unique_nt %d", |unique_nt|); terminate(); return; } - - print network_time(); - event test(); - } + + event test(); + } event zeek_init() - { - event test(); - } + { + event test(); + } From aad66b3cfffb91160c1332b43cc127762e77a418 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 13:03:46 +0100 Subject: [PATCH 08/13] Add a set of suspend_processing tests Placed into core/ but relies on a few not-so-core things. --- .../manager..stdout | 4 + .../worker..stdout | 8 ++ .../core.suspend_processing.config/output | 6 ++ .../output | 16 ++++ .../output | 21 +++++ .../core.suspend_processing.raw-input/output | 6 ++ .../output | 17 ++++ .../btest/core/suspend_processing/broker.zeek | 83 +++++++++++++++++++ .../btest/core/suspend_processing/config.zeek | 42 ++++++++++ .../event-from-zeek-init.zeek | 50 +++++++++++ .../core/suspend_processing/event-order.zeek | 54 ++++++++++++ .../core/suspend_processing/raw-input.zeek | 62 ++++++++++++++ .../scheduled-event-from-zeek-init.zeek | 57 +++++++++++++ 13 files changed, 426 insertions(+) create mode 100644 testing/btest/Baseline/core.suspend_processing.broker/manager..stdout create mode 100644 testing/btest/Baseline/core.suspend_processing.broker/worker..stdout create mode 100644 testing/btest/Baseline/core.suspend_processing.config/output create mode 100644 testing/btest/Baseline/core.suspend_processing.event-from-zeek-init/output create mode 100644 testing/btest/Baseline/core.suspend_processing.event-order/output create mode 100644 testing/btest/Baseline/core.suspend_processing.raw-input/output create mode 100644 testing/btest/Baseline/core.suspend_processing.scheduled-event-from-zeek-init/output create mode 100644 testing/btest/core/suspend_processing/broker.zeek create mode 100644 testing/btest/core/suspend_processing/config.zeek create mode 100644 testing/btest/core/suspend_processing/event-from-zeek-init.zeek create mode 100644 testing/btest/core/suspend_processing/event-order.zeek create mode 100644 testing/btest/core/suspend_processing/raw-input.zeek create mode 100644 testing/btest/core/suspend_processing/scheduled-event-from-zeek-init.zeek diff --git a/testing/btest/Baseline/core.suspend_processing.broker/manager..stdout b/testing/btest/Baseline/core.suspend_processing.broker/manager..stdout new file mode 100644 index 0000000000..658d123ea1 --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.broker/manager..stdout @@ -0,0 +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 lost, terminating diff --git a/testing/btest/Baseline/core.suspend_processing.broker/worker..stdout b/testing/btest/Baseline/core.suspend_processing.broker/worker..stdout new file mode 100644 index 0000000000..739641fb8f --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.broker/worker..stdout @@ -0,0 +1,8 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init: suspend_processing() +0.0, zeek_init: broker peering +0.0, Broker::peer_added +0.0, do_continue_processing +1300475167.096535, network_time_init +1300475173.475401, Pcap::file_done, <...>/wikipedia.trace +1300475173.475401, zeek_done diff --git a/testing/btest/Baseline/core.suspend_processing.config/output b/testing/btest/Baseline/core.suspend_processing.config/output new file mode 100644 index 0000000000..f0442e65bc --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.config/output @@ -0,0 +1,6 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init +0.0, end_of_data, intel-intel.dat, intel.dat +1300475167.096535, network_time_init +1300475173.475401, Pcap::file_done, <...>/wikipedia.trace +1300475173.475401, zeek_done diff --git a/testing/btest/Baseline/core.suspend_processing.event-from-zeek-init/output b/testing/btest/Baseline/core.suspend_processing.event-from-zeek-init/output new file mode 100644 index 0000000000..274823d7fd --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.event-from-zeek-init/output @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init +0.0, zeek_post +0.0, one_line, first line +1467818432.675392, network_time_init +1467818432.675392, raw_packet, [hl=20, tos=0, len=78, id=55704, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818432.675732, raw_packet, [hl=20, tos=0, len=78, id=38782, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818432.676047, raw_packet, [hl=20, tos=0, len=134, id=55705, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818432.676385, raw_packet, [hl=20, tos=0, len=134, id=38783, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818433.677322, raw_packet, [hl=20, tos=0, len=134, id=55737, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818433.677452, raw_packet, [hl=20, tos=0, len=134, id=39026, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818434.678483, raw_packet, [hl=20, tos=0, len=134, id=55959, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818434.678691, raw_packet, [hl=20, tos=0, len=134, id=39224, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818435.680481, raw_packet, [hl=20, tos=0, len=134, id=56032, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818435.680663, raw_packet, [hl=20, tos=0, len=134, id=39359, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818435.680663, zeek_done diff --git a/testing/btest/Baseline/core.suspend_processing.event-order/output b/testing/btest/Baseline/core.suspend_processing.event-order/output new file mode 100644 index 0000000000..fc0454e54a --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.event-order/output @@ -0,0 +1,21 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init +0.0, one_line, first line +1467818432.675392, network_time_init +1467818432.675392, new_connection, CHhAvVGS1DHFjwGM9 +1467818432.675392, raw_packet, [hl=20, tos=0, len=78, id=55704, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818432.675732, new_connection, ClEkJM2Vm5giqnMf4h +1467818432.675732, raw_packet, [hl=20, tos=0, len=78, id=38782, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818432.676047, new_connection, C4J4Th3PJpwUYZZ6gc +1467818432.676047, new_connection, CtPZjS20MLrsMUOJi2 +1467818432.676047, raw_packet, [hl=20, tos=0, len=134, id=55705, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818432.676385, new_connection, CUM0KZ3MLUfNB0cl11 +1467818432.676385, raw_packet, [hl=20, tos=0, len=134, id=38783, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818433.677322, raw_packet, [hl=20, tos=0, len=134, id=55737, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818433.677452, raw_packet, [hl=20, tos=0, len=134, id=39026, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818434.678483, raw_packet, [hl=20, tos=0, len=134, id=55959, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818434.678691, raw_packet, [hl=20, tos=0, len=134, id=39224, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818435.680481, raw_packet, [hl=20, tos=0, len=134, id=56032, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818435.680663, raw_packet, [hl=20, tos=0, len=134, id=39359, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818435.680663, Pcap::file_done, <...>/vxlan.pcap +1467818435.680663, zeek_done diff --git a/testing/btest/Baseline/core.suspend_processing.raw-input/output b/testing/btest/Baseline/core.suspend_processing.raw-input/output new file mode 100644 index 0000000000..cf1ba9fd92 --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.raw-input/output @@ -0,0 +1,6 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init +0.0, one_line, first line +1300475167.096535, network_time_init +1300475173.475401, Pcap::file_done, <...>/wikipedia.trace +1300475173.475401, zeek_done diff --git a/testing/btest/Baseline/core.suspend_processing.scheduled-event-from-zeek-init/output b/testing/btest/Baseline/core.suspend_processing.scheduled-event-from-zeek-init/output new file mode 100644 index 0000000000..b13d7ce3a0 --- /dev/null +++ b/testing/btest/Baseline/core.suspend_processing.scheduled-event-from-zeek-init/output @@ -0,0 +1,17 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init +0.0, zeek_post +0.0, zeek_scheduled +0.0, one_line, first line +1467818432.675392, network_time_init +1467818432.675392, raw_packet, [hl=20, tos=0, len=78, id=55704, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818432.675732, raw_packet, [hl=20, tos=0, len=78, id=38782, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818432.676047, raw_packet, [hl=20, tos=0, len=134, id=55705, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818432.676385, raw_packet, [hl=20, tos=0, len=134, id=38783, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818433.677322, raw_packet, [hl=20, tos=0, len=134, id=55737, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818433.677452, raw_packet, [hl=20, tos=0, len=134, id=39026, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818434.678483, raw_packet, [hl=20, tos=0, len=134, id=55959, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818434.678691, raw_packet, [hl=20, tos=0, len=134, id=39224, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818435.680481, raw_packet, [hl=20, tos=0, len=134, id=56032, ttl=64, p=17, src=192.168.56.11, dst=192.168.56.12] +1467818435.680663, raw_packet, [hl=20, tos=0, len=134, id=39359, ttl=64, p=17, src=192.168.56.12, dst=192.168.56.11] +1467818435.680663, zeek_done diff --git a/testing/btest/core/suspend_processing/broker.zeek b/testing/btest/core/suspend_processing/broker.zeek new file mode 100644 index 0000000000..6bf9606773 --- /dev/null +++ b/testing/btest/core/suspend_processing/broker.zeek @@ -0,0 +1,83 @@ +# @TEST-DOC: Suspend pcap processing on a worker and wait for the manager to trigger continue processing via a broker message. Ensure network_time() is not initialized until continue_processing() is called. +# @TEST-PORT: BROKER_PORT +# @TEST-EXEC: btest-bg-run manager "zeek -b ../manager.zeek" +# @TEST-EXEC: btest-bg-run worker "zeek -r $TRACES/wikipedia.trace -b ../worker.zeek" +# @TEST-EXEC: btest-bg-wait 5 + +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff worker/.stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff manager/.stdout + +@TEST-START-FILE worker.zeek + +# If we're not setting this, broker will initialize network_time. +redef allow_network_time_forward = F; + +event zeek_init() + { + print network_time(), "zeek_init: suspend_processing()"; + suspend_processing(); + } + +event zeek_init() &priority=-5 + { + print network_time(), "zeek_init: broker peering"; + Broker::peer("127.0.0.1", to_port(getenv("BROKER_PORT"))); + Broker::subscribe("zeek/event/my_topic"); + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + print network_time(), "Broker::peer_added"; + } + +event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) + { + print network_time(), "[FAIL] Broker::peer_lost"; + } + +event do_continue_processing() &is_used + { + print network_time(), "do_continue_processing"; + continue_processing(); + } + +event network_time_init() + { + print network_time(), "network_time_init"; + } + +event Pcap::file_done(path: string) + { + print network_time(), "Pcap::file_done", path; + terminate(); + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } +@TEST-END-FILE + + +@TEST-START-FILE manager.zeek +# The manager waits for a peer and directly publishes do_continue_processing() +# to it. It terminates when the peer is lost. +global do_continue_processing: event(); + +event zeek_init() + { + print "manager: listening"; + Broker::listen("127.0.0.1", to_port(getenv("BROKER_PORT"))); + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + print "manager: peer added, publishing do_continue_processing"; + Broker::publish("zeek/event/my_topic", do_continue_processing); + } +event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) + { + print "manager: peer lost, terminating"; + terminate(); + } +@TEST-END-FILE diff --git a/testing/btest/core/suspend_processing/config.zeek b/testing/btest/core/suspend_processing/config.zeek new file mode 100644 index 0000000000..b47a4a1f9f --- /dev/null +++ b/testing/btest/core/suspend_processing/config.zeek @@ -0,0 +1,42 @@ +# @TEST-DOC: Test that finishing reading an intel file resumes processing and network_time() isn't initialized until continue_processing() happens. +# @TEST-EXEC: zeek -b -C -r $TRACES/wikipedia.trace %INPUT >output +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff output + +@load base/frameworks/intel + + +@TEST-START-FILE intel.dat +#fields indicator indicator_type meta.source meta.desc meta.url +putty.exe Intel::FILE_NAME source1 SSH utility https://www.putty.org +zeek.exe Intel::FILE_NAME source1 A network monitor https://zeek.org +@TEST-END-FILE + +redef Intel::read_files += { "intel.dat" }; + +event Input::end_of_data(name: string, source: string) + { + print network_time(), "end_of_data", name, source; + if ( /intel.dat/ in source ) + continue_processing(); + } + +event zeek_init() + { + print network_time(), "zeek_init"; + suspend_processing(); + } + +event network_time_init() + { + print network_time(), "network_time_init"; + } + +event Pcap::file_done(path: string) + { + print network_time(), "Pcap::file_done", path; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } diff --git a/testing/btest/core/suspend_processing/event-from-zeek-init.zeek b/testing/btest/core/suspend_processing/event-from-zeek-init.zeek new file mode 100644 index 0000000000..1f89ddd135 --- /dev/null +++ b/testing/btest/core/suspend_processing/event-from-zeek-init.zeek @@ -0,0 +1,50 @@ +# @TEST-DOC: Previously, the zeek_post() event would have access to the first packet's network_time, even if suspend_processing() was called in zeek_init(). This changed in Zeek 6.0 to return 0.0 as network_time_init() is now available. +# @TEST-EXEC: echo "first line" > raw_file +# @TEST-EXEC: zeek -b -C -r $TRACES/tunnels/vxlan.pcap %INPUT >output +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff output + +type OneLine: record { + s: string; +}; + +event one_line(desc: Input::EventDescription, e: Input::Event, s: string) { + print network_time(), "one_line", s; + continue_processing(); +} + +event zeek_post() + { + print network_time(), "zeek_post"; + } + +event zeek_init() + { + print network_time(), "zeek_init"; + event zeek_post(); + suspend_processing(); + + Input::add_event([ + $name="raw-read", + $source="./raw_file", + $reader=Input::READER_RAW, + $mode=Input::STREAM, + $fields=OneLine, + $ev=one_line, + $want_record=F, + ]); + } + +event network_time_init() + { + print network_time(), "network_time_init"; + } + +event raw_packet(p: raw_pkt_hdr) + { + print network_time(), "raw_packet", p$ip; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } diff --git a/testing/btest/core/suspend_processing/event-order.zeek b/testing/btest/core/suspend_processing/event-order.zeek new file mode 100644 index 0000000000..4d6ebea7f0 --- /dev/null +++ b/testing/btest/core/suspend_processing/event-order.zeek @@ -0,0 +1,54 @@ +# @TEST-DOC: Previously, suspend_processing() within zeek_init() would not prevent packets and connection processing, it does with Zeek 6.0 and later. +# @TEST-EXEC: echo "first line" > raw_file +# @TEST-EXEC: zeek -b -C -r $TRACES/tunnels/vxlan.pcap %INPUT >output +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff output + +type OneLine: record { + s: string; +}; + +event one_line(desc: Input::EventDescription, e: Input::Event, s: string) { + print network_time(), "one_line", s; + continue_processing(); +} + +event zeek_init() + { + print network_time(), "zeek_init"; + suspend_processing(); + + Input::add_event([ + $name="raw-read", + $source="./raw_file", + $reader=Input::READER_RAW, + $mode=Input::STREAM, + $fields=OneLine, + $ev=one_line, + $want_record=F, + ]); + } + +event network_time_init() + { + print network_time(), "network_time_init"; + } + +event raw_packet(p: raw_pkt_hdr) + { + print network_time(), "raw_packet", p$ip; + } + +event new_connection(c: connection) + { + print network_time(), "new_connection", c$uid; + } + +event Pcap::file_done(path: string) + { + print network_time(), "Pcap::file_done", path; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } diff --git a/testing/btest/core/suspend_processing/raw-input.zeek b/testing/btest/core/suspend_processing/raw-input.zeek new file mode 100644 index 0000000000..9ba181a0da --- /dev/null +++ b/testing/btest/core/suspend_processing/raw-input.zeek @@ -0,0 +1,62 @@ +# @TEST-DOC: suspend_processing() in zeek_init() +# @TEST-EXEC: echo "first line" > raw_file +# @TEST-EXEC: zeek -b -C -r $TRACES/wikipedia.trace %INPUT >output +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff output + +type OneLine: record { + s: string; +}; + +event one_line(desc: Input::EventDescription, e: Input::Event, s: string) + { + print network_time(), "one_line", s; + continue_processing(); + } + +event Input::end_of_data(name: string, source: string) + { + print network_time(), "end_of_data", name, source; + } + +event zeek_init() + { + print network_time(), "zeek_init"; + suspend_processing(); + + Input::add_event([ + $name="raw-read", + # Can not use a raw command here because input reading is done + # using heartbeats and those are working based off of network + # time instead of either realtime or actually propagating back + # to the main-loop when there's data ready for reading. + # + # IMO that's a bug in how things are implemented with the + # readers being poll/heartbeat based. If polling based, seems + # wallclock time would've been the better choice. + # + # A file works, because the first DoUpdate() does the job. + # + # $source="sleep 1 |", + $source="./raw_file", + $reader=Input::READER_RAW, + $mode=Input::STREAM, + $fields=OneLine, + $ev=one_line, + $want_record=F, + ]); + } + +event network_time_init() + { + print network_time(), "network_time_init"; + } + +event Pcap::file_done(path: string) + { + print network_time(), "Pcap::file_done", path; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } diff --git a/testing/btest/core/suspend_processing/scheduled-event-from-zeek-init.zeek b/testing/btest/core/suspend_processing/scheduled-event-from-zeek-init.zeek new file mode 100644 index 0000000000..2e0b2c39c8 --- /dev/null +++ b/testing/btest/core/suspend_processing/scheduled-event-from-zeek-init.zeek @@ -0,0 +1,57 @@ +# @TEST-DOC: What network_time() does an event observe that's scheduled from zeek_init() +# @TEST-EXEC: echo "first line" > raw_file +# @TEST-EXEC: zeek -b -C -r $TRACES/tunnels/vxlan.pcap %INPUT >output +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff output + +type OneLine: record { + s: string; +}; + +event one_line(desc: Input::EventDescription, e: Input::Event, s: string) { + print network_time(), "one_line", s; + continue_processing(); +} + +event zeek_post() + { + print network_time(), "zeek_post"; + } + +event zeek_scheduled() + { + print network_time(), "zeek_scheduled"; + } + +event zeek_init() + { + print network_time(), "zeek_init"; + event zeek_post(); + schedule 0.0sec { zeek_scheduled() }; + + suspend_processing(); + + Input::add_event([ + $name="raw-read", + $source="./raw_file", + $reader=Input::READER_RAW, + $mode=Input::STREAM, + $fields=OneLine, + $ev=one_line, + $want_record=F, + ]); + } + +event network_time_init() + { + print network_time(), "network_time_init"; + } + +event raw_packet(p: raw_pkt_hdr) + { + print network_time(), "raw_packet", p$ip; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } From 4a6ce8b2ad2367e19d6755a35102f016fc6ddeb8 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Tue, 14 Mar 2023 17:49:24 +0100 Subject: [PATCH 09/13] Remove suspend-processing test This tested that timers continue working even if one calls suspend_processing() in zeek -r mode. The new behavior is that timers do not function in that scenario and the test invalid. --- .../core.pcap.suspend-processing/.stderr | 4 --- .../core.pcap.suspend-processing/output | 23 ------------- .../btest/core/pcap/suspend-processing.zeek | 34 ------------------- 3 files changed, 61 deletions(-) delete mode 100644 testing/btest/Baseline/core.pcap.suspend-processing/.stderr delete mode 100644 testing/btest/Baseline/core.pcap.suspend-processing/output delete mode 100644 testing/btest/core/pcap/suspend-processing.zeek diff --git a/testing/btest/Baseline/core.pcap.suspend-processing/.stderr b/testing/btest/Baseline/core.pcap.suspend-processing/.stderr deleted file mode 100644 index 5af221391e..0000000000 --- a/testing/btest/Baseline/core.pcap.suspend-processing/.stderr +++ /dev/null @@ -1,4 +0,0 @@ -### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. -XXXXXXXXXX.XXXXXX processing suspended -XXXXXXXXXX.XXXXXX processing continued -XXXXXXXXXX.XXXXXX received termination signal diff --git a/testing/btest/Baseline/core.pcap.suspend-processing/output b/testing/btest/Baseline/core.pcap.suspend-processing/output deleted file mode 100644 index abdfca1c9d..0000000000 --- a/testing/btest/Baseline/core.pcap.suspend-processing/output +++ /dev/null @@ -1,23 +0,0 @@ -### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. -network_time: XXXXXXXXXX.XXXXXX -Processing packet 1 at XXXXXXXXXX.XXXXXX -network_time: XXXXXXXXXX.XXXXXX -Processing packet 2 at XXXXXXXXXX.XXXXXX -Processing packet 3 at XXXXXXXXXX.XXXXXX -Processing packet 4 at XXXXXXXXXX.XXXXXX -Processing packet 5 at XXXXXXXXXX.XXXXXX -Processing packet 6 at XXXXXXXXXX.XXXXXX -Processing packet 7 at XXXXXXXXXX.XXXXXX -Processing packet 8 at XXXXXXXXXX.XXXXXX -Processing packet 9 at XXXXXXXXXX.XXXXXX -Processing packet 10 at XXXXXXXXXX.XXXXXX -Processing packet 11 at XXXXXXXXXX.XXXXXX -Processing packet 12 at XXXXXXXXXX.XXXXXX -Processing packet 13 at XXXXXXXXXX.XXXXXX -Processing packet 14 at XXXXXXXXXX.XXXXXX -Processing packet 15 at XXXXXXXXXX.XXXXXX -Processing packet 16 at XXXXXXXXXX.XXXXXX -Processing packet 17 at XXXXXXXXXX.XXXXXX -Processing packet 18 at XXXXXXXXXX.XXXXXX -Processing packet 19 at XXXXXXXXXX.XXXXXX -Processing packet 20 at XXXXXXXXXX.XXXXXX diff --git a/testing/btest/core/pcap/suspend-processing.zeek b/testing/btest/core/pcap/suspend-processing.zeek deleted file mode 100644 index bbe4c4f471..0000000000 --- a/testing/btest/core/pcap/suspend-processing.zeek +++ /dev/null @@ -1,34 +0,0 @@ -# @TEST-EXEC: zeek -b -C -r $TRACES/wikipedia.trace %INPUT >output -# @TEST-EXEC: btest-diff output -# @TEST-EXEC: btest-diff .stderr - -redef exit_only_after_terminate = T; - -event go_on() - { - continue_processing(); - print fmt("network_time: %f", network_time()); - } - -event pcap_init() - { - print fmt("network_time: %f", network_time()); - suspend_processing(); - # Some asynchronous work - schedule 5sec { go_on() }; - } - -event zeek_init() - { - schedule 0sec { pcap_init() }; - } - -global pkt_cnt: count = 0; - -event new_packet(c: connection, p: pkt_hdr) - { - pkt_cnt += 1; - print fmt("Processing packet %s at %f", pkt_cnt, network_time()); - if ( pkt_cnt >= 20 ) - terminate(); - } From 8734f237248e90402baccd81b843c04e30ff9b22 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Mar 2023 17:36:50 +0100 Subject: [PATCH 10/13] A set of tests around set_network_time() and timer expiration This tests that timer expiration happens after a call to set_network_time() upon the next time around the loop. This should be fairly stable, but suspect major changes in the main loop or around timer expiration may subtly change behavior things. --- .../core.network_time.broker/manager..stdout | 4 + .../core.network_time.broker/worker..stdout | 38 ++++++++ .../core.network_time.no-update/output | 3 + .../output | 10 ++ .../core.network_time.set-network-time/output | 4 + testing/btest/core/network_time/broker.zeek | 97 +++++++++++++++++++ .../btest/core/network_time/no-update.zeek | 15 +++ .../set-network-time-expiration.zeek | 54 +++++++++++ .../core/network_time/set-network-time.zeek | 22 +++++ 9 files changed, 247 insertions(+) create mode 100644 testing/btest/Baseline/core.network_time.broker/manager..stdout create mode 100644 testing/btest/Baseline/core.network_time.broker/worker..stdout create mode 100644 testing/btest/Baseline/core.network_time.no-update/output create mode 100644 testing/btest/Baseline/core.network_time.set-network-time-expiration/output create mode 100644 testing/btest/Baseline/core.network_time.set-network-time/output create mode 100644 testing/btest/core/network_time/broker.zeek create mode 100644 testing/btest/core/network_time/no-update.zeek create mode 100644 testing/btest/core/network_time/set-network-time-expiration.zeek create mode 100644 testing/btest/core/network_time/set-network-time.zeek diff --git a/testing/btest/Baseline/core.network_time.broker/manager..stdout b/testing/btest/Baseline/core.network_time.broker/manager..stdout new file mode 100644 index 0000000000..658d123ea1 --- /dev/null +++ b/testing/btest/Baseline/core.network_time.broker/manager..stdout @@ -0,0 +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 lost, terminating diff --git a/testing/btest/Baseline/core.network_time.broker/worker..stdout b/testing/btest/Baseline/core.network_time.broker/worker..stdout new file mode 100644 index 0000000000..d5abbff6b9 --- /dev/null +++ b/testing/btest/Baseline/core.network_time.broker/worker..stdout @@ -0,0 +1,38 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init: broker peering +0.0, Broker::peer_added +0.000, timer_tick, 1, 42.0 +42.000, timer_tick, 2, 42.25 +42.250, timer_tick, 3, 42.5 +42.500, timer, first timer (1 sec) +42.500, timer_tick, 4, 42.75 +42.750, timer_tick, 5, 43.0 +43.000, timer_tick, 6, 43.25 +43.250, timer_tick, 7, 43.5 +43.500, timer_tick, 8, 43.75 +43.750, timer_tick, 9, 44.0 +44.000, timer_tick, 10, 44.25 +44.250, timer_tick, 11, 44.5 +44.500, timer_tick, 12, 44.75 +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_tick, 15, 45.5 +45.500, timer_tick, 16, 45.75 +45.750, timer_tick, 17, 46.0 +46.000, timer_tick, 18, 46.25 +46.250, timer_tick, 19, 46.5 +46.500, timer_tick, 20, 46.75 +46.750, timer_tick, 21, 47.0 +47.000, timer, fourth timer (10 sec) +47.000, timer_tick, 22, 47.25 +47.250, timer_tick, 23, 47.5 +47.500, timer_tick, 24, 47.75 +47.750, timer_tick, 25, 48.0 +48.000, timer_tick, 26, 48.25 +48.250, timer_tick, 27, 48.5 +48.500, timer_tick, 28, 48.75 +48.750, timer_tick, 29, 49.0 +49.000, timer_tick, 30, 49.25 +49.25, zeek_done diff --git a/testing/btest/Baseline/core.network_time.no-update/output b/testing/btest/Baseline/core.network_time.no-update/output new file mode 100644 index 0000000000..5784957b78 --- /dev/null +++ b/testing/btest/Baseline/core.network_time.no-update/output @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init +0.0, zeek_done diff --git a/testing/btest/Baseline/core.network_time.set-network-time-expiration/output b/testing/btest/Baseline/core.network_time.set-network-time-expiration/output new file mode 100644 index 0000000000..6fd0de44ae --- /dev/null +++ b/testing/btest/Baseline/core.network_time.set-network-time-expiration/output @@ -0,0 +1,10 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init (1) +1.5, zeek_init (2) +2.5, timer, first timer 1.0 +2.5, updating network time to 3.5 +4.0, timer, second timer +4.0, calling terminate() +4.0, net_done, 4.0 +4.0, timer, third timer +4.0, zeek_done diff --git a/testing/btest/Baseline/core.network_time.set-network-time/output b/testing/btest/Baseline/core.network_time.set-network-time/output new file mode 100644 index 0000000000..67e126981f --- /dev/null +++ b/testing/btest/Baseline/core.network_time.set-network-time/output @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +0.0, zeek_init (1) +1.5, zeek_init (2) +2.5, zeek_done diff --git a/testing/btest/core/network_time/broker.zeek b/testing/btest/core/network_time/broker.zeek new file mode 100644 index 0000000000..9419fb5d3f --- /dev/null +++ b/testing/btest/core/network_time/broker.zeek @@ -0,0 +1,97 @@ +# @TEST-DOC: Disable network_time forward on a worker and let a manager completely drive its network_time. +# @TEST-PORT: BROKER_PORT +# @TEST-EXEC: btest-bg-run manager "zeek -b ../manager.zeek" +# @TEST-EXEC: btest-bg-run worker "zeek -b ../worker.zeek" +# @TEST-EXEC: btest-bg-wait 5 + +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff worker/.stdout +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff manager/.stdout + +@TEST-START-FILE worker.zeek + +redef allow_network_time_forward = F; + +event zeek_init() + { + print network_time(), "zeek_init: broker peering"; + Broker::peer("127.0.0.1", to_port(getenv("BROKER_PORT"))); + Broker::subscribe("zeek/event/my_topic"); + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + print network_time(), "Broker::peer_added"; + } + +event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) + { + print network_time(), "[FAIL] Broker::peer_lost"; + exit(1); + } + +event timer(s: string) + { + print fmt("%.3f", network_time()), "timer", s; + } + +# The manager tells us our network_time. +global received_ticks = 0; +event timer_tick(ts: time) &is_used + { + ++received_ticks; + print fmt("%.3f", network_time()), "timer_tick", received_ticks, ts; + set_network_time(ts); + + # On the first tick, schedule a few timer for the future so + # that we can observe them expire. + if ( received_ticks == 1 ) + { + 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 5sec { timer("fourth timer (10 sec)") }; + } + + if ( received_ticks == 30 ) + terminate(); + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } +@TEST-END-FILE + + +@TEST-START-FILE manager.zeek +# The manager waits for a peer to appear, then starts sending timer +# ticks until the peer is gone again. +global timer_tick: event(ts: time); + +global fake_network_time = double_to_time(42.0); + +event zeek_init() + { + print "manager: listening"; + Broker::listen("127.0.0.1", to_port(getenv("BROKER_PORT"))); + } + +event local_tick() { + 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"; + 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) + { + print "manager: peer lost, terminating"; + terminate(); + } +@TEST-END-FILE diff --git a/testing/btest/core/network_time/no-update.zeek b/testing/btest/core/network_time/no-update.zeek new file mode 100644 index 0000000000..2e2e223479 --- /dev/null +++ b/testing/btest/core/network_time/no-update.zeek @@ -0,0 +1,15 @@ +# @TEST-DOC: Ensure network_time stays 0.0 when configured that way. +# @TEST-EXEC: zeek -b %INPUT >output +# @TEST-EXEC: btest-diff output + +redef allow_network_time_forward = F; + +event zeek_init() + { + print network_time(), "zeek_init"; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } diff --git a/testing/btest/core/network_time/set-network-time-expiration.zeek b/testing/btest/core/network_time/set-network-time-expiration.zeek new file mode 100644 index 0000000000..5cdd5a341e --- /dev/null +++ b/testing/btest/core/network_time/set-network-time-expiration.zeek @@ -0,0 +1,54 @@ +# @TEST-DOC: Does setting network trigger timer expiration? It should. +# @TEST-EXEC: zeek -b %INPUT >output +# @TEST-EXEC: btest-diff output + +redef allow_network_time_forward = F; + +# If this is F, we don't enter the IO loop :-( +redef exit_only_after_terminate = T; + +event timer(s: string) { + print network_time(), "timer", s; + if ( /first timer/ in s ) + { + print network_time(), "updating network time to 3.5"; + set_network_time(double_to_time(4.0)); + } + + if ( /second timer/ in s ) + { + print network_time(), "calling terminate()"; + terminate(); + } +} + +event zeek_init() + { + print network_time(), "zeek_init (1)"; + schedule 1sec { timer("first timer 1.0") }; + set_network_time(double_to_time(1.5)); + } + +event zeek_init() &priority=-1 + { + print network_time(), "zeek_init (2)"; + # This runs at network_time=1.5, so the timer is scheduled + # at network_time 3.5 seconds (which the first timer will + # move towards). + schedule 2sec { timer("second timer") }; + + # This is expired after net_done() because it ends + # up at 4.5 seconds and time is not moved that far. + schedule 3sec { timer("third timer") }; + set_network_time(double_to_time(2.5)); + } + +event net_done(t: time) + { + print network_time(), "net_done", t; + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } diff --git a/testing/btest/core/network_time/set-network-time.zeek b/testing/btest/core/network_time/set-network-time.zeek new file mode 100644 index 0000000000..c7fb884449 --- /dev/null +++ b/testing/btest/core/network_time/set-network-time.zeek @@ -0,0 +1,22 @@ +# @TEST-DOC: Ensure setting network time is reflected in following events. +# @TEST-EXEC: zeek -b %INPUT >output +# @TEST-EXEC: btest-diff output + +redef allow_network_time_forward = F; + +event zeek_init() + { + print network_time(), "zeek_init (1)"; + set_network_time(double_to_time(1.5)); + } + +event zeek_init() &priority=-1 + { + print network_time(), "zeek_init (2)"; + set_network_time(double_to_time(2.5)); + } + +event zeek_done() + { + print network_time(), "zeek_done"; + } From 9b8ab7b21054e939ed340cb917c67fb98b87a732 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Mon, 20 Mar 2023 13:11:44 +0100 Subject: [PATCH 11/13] broker::Manager: use_realtime_false when allow_network_time_forward=F Run the broker in non-realtime mode when allow_network_time_forward=F. This may need an extra option for really advanced use-cases, but for now this seems reasonable. --- src/broker/Manager.cc | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/broker/Manager.cc b/src/broker/Manager.cc index 37042d78d1..cd309b51af 100644 --- a/src/broker/Manager.cc +++ b/src/broker/Manager.cc @@ -262,6 +262,12 @@ void Manager::InitPostScript() zeek_table_db_directory = get_option("Broker::table_store_db_directory")->AsString()->CheckString(); + // If Zeek's forwarding of network time to wallclock time was disabled, + // assume that also Broker does not use realtime and instead receives + // time via explicit AdvanceTime() calls. + if ( ! get_option("allow_network_time_forward")->AsBool() ) + use_real_time = false; + detail::opaque_of_data_type = make_intrusive("Broker::Data"); detail::opaque_of_set_iterator = make_intrusive("Broker::SetIterator"); detail::opaque_of_table_iterator = make_intrusive("Broker::TableIterator"); From 833dd158de56948ecfec98c7749c00e8254d7a6a Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Mon, 20 Mar 2023 14:24:48 +0100 Subject: [PATCH 12/13] iosource: Remove non-existing ManagerBase friend --- src/iosource/PktDumper.h | 1 - src/iosource/PktSrc.h | 1 - 2 files changed, 2 deletions(-) diff --git a/src/iosource/PktDumper.h b/src/iosource/PktDumper.h index ed7689e478..7171d9e239 100644 --- a/src/iosource/PktDumper.h +++ b/src/iosource/PktDumper.h @@ -90,7 +90,6 @@ public: protected: friend class Manager; - friend class ManagerBase; /** * Structure to pass back information about the packet dumper to the diff --git a/src/iosource/PktSrc.h b/src/iosource/PktSrc.h index a1ef1c6e64..6b2a007039 100644 --- a/src/iosource/PktSrc.h +++ b/src/iosource/PktSrc.h @@ -225,7 +225,6 @@ public: protected: friend class Manager; - friend class ManagerBase; // Methods to use by derived classes. From fd15a33f8c57e9fd16cd2dec1fb817cf890dc892 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Thu, 23 Mar 2023 12:35:30 +0100 Subject: [PATCH 13/13] NEWS: Some notes about timing related changes --- NEWS | 36 ++++++++++++++++++++++++++++++++++++ 1 file changed, 36 insertions(+) diff --git a/NEWS b/NEWS index 555a10efa2..50edd17230 100644 --- a/NEWS +++ b/NEWS @@ -93,6 +93,11 @@ New Functionality - The supervisor framework can now start worker nodes that read from a trace file. +- Zeek can be prevented from updating ``network_time()`` to the current time + by setting ``allow_network_time_forward=F``. Together with ``set_network_time()`` + or a custom plugin, this allows control of ``network_time()`` without Zeek + interfering. + Changed Functionality --------------------- @@ -125,6 +130,37 @@ Changed Functionality ``io_poll_interval_live`` for ease of testing, development and debugging of the main-loop. +- Zeek does not arbitrarily update ``network_time()`` to current time anymore. + When a packet source is providing a constant stream of packets, packets + drive network time. Previously, Zeek updated network time to the current + current time in various situations, disregarding timestamps of network packets. + Zeek will now update ``network_time()`` only when a packet source has been + inactive/idle for an interval of ``packet_source_inactivity_timeout`` + (default 100msec). When a worker process suddenly observes no packets, timer + expiration may initially be delayed by ``packet_source_inactivity_timeout``. + +- Calling ``suspend_processing()`` when reading traces does not update network + time to the current time anymore. Instead, Zeek keeps ``network_time()`` according + to the trace file. This causes scheduled events to not fire once ``suspend_processing()`` + is called. However, this appears more sensible behavior than arbitrarily setting + ``network_time()`` to the current time. Processing can still be continued from + broker events or input readers. + +- Previously, Zeek would process and dispatch events for the very first packet + in a trace file in order to initialize time, even if ``suspend_processing()`` + was called in a ``zeek_init()`` handler. This has been changed such that the + first packet will only be processed once ``continue_processing()`` has been + invoked again. Some background around the previous behaviour can be found + in GH-938. With the availability of ``network_time_init()``, this behavior + seems more reasonable. + +- If an event is scheduled with a 0.0sec timeout from a ``zeek_init()`` handler + that also executes a ``suspend_processing()``, the scheduled event will fire + immediately with ``network_time()`` still yielding ``0.0``. Previously, + ``network_time()`` was set to the current time. The new behavior is considered + more sensible with regards of determinism and in line with timers stopping + during a ``suspend_processing()``. + Removed Functionality ---------------------