diff --git a/CHANGES b/CHANGES index dc3b2bfee9..c7eb3f6f70 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,59 @@ +6.0.0-dev.266 | 2023-03-23 13:35:28 +0100 + + * iosource: Remove non-existing ManagerBase friend (Arne Welzel, Corelight) + + * broker::Manager: use_realtime_false when allow_network_time_forward=F (Arne Welzel, Corelight) + + 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. + + * A set of tests around network time handling (Arne Welzel, Corelight) + + * broker::Manager: No more network_time forwarding (Arne Welzel, Corelight) + + 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. + + * TimerMgr: No network_time updates in Process() (Arne Welzel, Corelight) + + 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. + + * Event: No more network_time updates (Arne Welzel, Corelight) + + 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). + + * RunState: Implement forward_network_time_if_applicable() (Arne Welzel, Corelight) + + 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. + + * PktSrc: Add HasBeenIdleFor() method (Arne Welzel, Corelight) + + 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). + + * PktSrc: Move termination pseduo_realtime special case to RunState (Arne Welzel, Corelight) + + 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. + + * Bump zeekctl and doc submodule for updates regarding Site::local_nets (Christian Kreibich, Corelight) + + * Update doc submodule [nomail] [skip ci] (zeek-bot) + 6.0.0-dev.250 | 2023-03-21 19:17:36 +0100 * Expr: Factor out type tag extraction (Arne Welzel, Corelight) 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 --------------------- diff --git a/VERSION b/VERSION index 79b802bf75..d139a5e0a6 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -6.0.0-dev.250 +6.0.0-dev.266 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/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() diff --git a/src/RunState.cc b/src/RunState.cc index 67041cc915..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(); @@ -352,17 +390,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/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, diff --git a/src/broker/Manager.cc b/src/broker/Manager.cc index e35ece26e2..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"); @@ -1140,11 +1146,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 +1222,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()); + } } } 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/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.cc b/src/iosource/PktSrc.cc index a7940250df..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,13 +201,19 @@ bool PktSrc::ExtractNextPacketInternal() } else { - had_packet = false; - } + // 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); + } - if ( run_state::pseudo_realtime && ! IsOpen() ) - { - if ( broker_mgr->Active() ) - iosource_mgr->Terminate(); + had_packet = false; } return false; diff --git a/src/iosource/PktSrc.h b/src/iosource/PktSrc.h index d93b5d60bc..6b2a007039 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. @@ -207,7 +225,6 @@ public: protected: friend class Manager; - friend class ManagerBase; // Methods to use by derived classes. @@ -365,6 +382,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; 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()); 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/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/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/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/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"; + } 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(); - } 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(); + } 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"; + }