From 08c5a9c66d5918d5fcc874680d400d1522729f50 Mon Sep 17 00:00:00 2001 From: Jan Grashoefer Date: Fri, 23 Aug 2024 19:14:55 +0200 Subject: [PATCH 1/3] Introduce get_current_packet_ts to fix packet lag Using network_time to calculate packet lag will produce wrong results when there is no packet available but network time does not (yet) fall back to wall clock. --- scripts/policy/misc/stats.zeek | 5 ++++- src/zeek.bif | 25 +++++++++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) diff --git a/scripts/policy/misc/stats.zeek b/scripts/policy/misc/stats.zeek index c324a728be..8449ccdb0d 100644 --- a/scripts/policy/misc/stats.zeek +++ b/scripts/policy/misc/stats.zeek @@ -166,6 +166,8 @@ event zeek_init() &priority=5 Log::create_stream(Stats::LOG, [$columns=Info, $ev=log_stats, $path="stats", $policy=log_policy]); } +const null_ts = double_to_time(0); + event check_stats(then: time, last_ns: NetStats, last_cs: ConnStats, last_ps: ProcStats, last_es: EventStats, last_rs: ReassemblerStats, last_ts: TimerStats, last_fs: FileAnalysisStats, last_ds: DNSStats) { local nettime = network_time(); @@ -214,7 +216,8 @@ event check_stats(then: time, last_ns: NetStats, last_cs: ConnStats, last_ps: Pr if ( reading_live_traffic() ) { - info$pkt_lag = current_time() - nettime; + local pkt_ts = get_current_packet_ts(); + info$pkt_lag = pkt_ts > null_ts ? current_time() - pkt_ts : 0 sec; info$pkts_dropped = ns$pkts_dropped - last_ns$pkts_dropped; info$pkts_link = ns$pkts_link - last_ns$pkts_link; diff --git a/src/zeek.bif b/src/zeek.bif index ee14c0ddce..d614bf27a0 100644 --- a/src/zeek.bif +++ b/src/zeek.bif @@ -3833,6 +3833,31 @@ function get_current_packet_header%(%) : raw_pkt_hdr return std::move(hdr); %} +## Returns the currently processed PCAP packet's timestamp. +## +## Returns: The currently processed packet's timestamp. +## +## .. zeek:see:: get_current_packet get_current_packet_header +## +## .. note:: +## +## For ``get_current_packet_ts()`` the same limitations as for +## :zeek:see:`get_current_packet` apply. In particular, the return value +## should be considered undefined when called within event handlers raised +## via :zeek:see:`event`, :zeek:see:`schedule` or by recipient of Broker +## messages. +function get_current_packet_ts%(%) : time + %{ + double ts = 0; + const Packet* p = nullptr; + zeek::iosource::PktSrc* pkt_src = zeek::run_state::detail::current_packet_source(); + + if ( pkt_src && pkt_src->GetCurrentPacket(&p) ) + ts = p->time; + + return zeek::make_intrusive(ts); + %} + ## Writes a given packet to a file. ## ## pkt: The PCAP packet. From 6977c07a2530fc658e159c49809c49059480176e Mon Sep 17 00:00:00 2001 From: Jan Grashoefer Date: Mon, 26 Aug 2024 12:43:14 +0200 Subject: [PATCH 2/3] Add btest for get_current_packet_ts() --- .../Baseline/core.network_time.packet_ts/output | 5 +++++ testing/btest/core/network_time/packet_ts.zeek | 17 +++++++++++++++++ 2 files changed, 22 insertions(+) create mode 100644 testing/btest/Baseline/core.network_time.packet_ts/output create mode 100644 testing/btest/core/network_time/packet_ts.zeek diff --git a/testing/btest/Baseline/core.network_time.packet_ts/output b/testing/btest/Baseline/core.network_time.packet_ts/output new file mode 100644 index 0000000000..cda26603e4 --- /dev/null +++ b/testing/btest/Baseline/core.network_time.packet_ts/output @@ -0,0 +1,5 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +network_time_init network time: 1362692526.869344 +network_time_init packet ts: 1362692526.869344 +conn_state_remove network time: 1362692527.080972 +conn_state_remove packet ts: 0.0 diff --git a/testing/btest/core/network_time/packet_ts.zeek b/testing/btest/core/network_time/packet_ts.zeek new file mode 100644 index 0000000000..602e668d64 --- /dev/null +++ b/testing/btest/core/network_time/packet_ts.zeek @@ -0,0 +1,17 @@ +# @TEST-DOC: Test get_current_packet_ts() in comparison with network_time(). +# @TEST-EXEC: zeek -b -r $TRACES/http/get.trace %INPUT > output +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff output + +event network_time_init() + { + print fmt("network_time_init network time: %s", network_time()); + print fmt("network_time_init packet ts: %s", get_current_packet_ts()); + } + +# Note: Gracefully closed connections will be actually removed after +# tcp_close_delay (default 5 secs). +event connection_state_remove(c: connection) + { + print fmt("conn_state_remove network time: %s", network_time()); + print fmt("conn_state_remove packet ts: %s", get_current_packet_ts()); + } From c2b17f9d308be603fbb78e6d48f27e995d726e1c Mon Sep 17 00:00:00 2001 From: Jan Grashoefer Date: Mon, 9 Dec 2024 19:19:29 +0100 Subject: [PATCH 3/3] Introduce get_packet_lag() --- scripts/base/utils/time.zeek | 20 ++++++++++++++++++++ scripts/policy/misc/stats.zeek | 6 ++---- src/zeek.bif | 14 +++++++------- 3 files changed, 29 insertions(+), 11 deletions(-) diff --git a/scripts/base/utils/time.zeek b/scripts/base/utils/time.zeek index c173c82878..c6f8cfe76b 100644 --- a/scripts/base/utils/time.zeek +++ b/scripts/base/utils/time.zeek @@ -1,3 +1,4 @@ +##! Time-related functions. ## Given an interval, returns a string representing the minutes and seconds ## in the interval (for example, "3m34s"). @@ -6,3 +7,22 @@ function duration_to_mins_secs(dur: interval): string local dur_count = double_to_count(interval_to_double(dur)); return fmt("%dm%ds", dur_count/60, dur_count%60); } + +## Time value representing the 0 timestamp. +const null_ts = double_to_time(0); + +## Calculate the packet lag, i.e. the difference between wall clock and the +## timestamp of the currently processed packet. If Zeek is not processing a +## packet, the function returns a 0 interval value. +function get_packet_lag(): interval + { + # We use get_current_packet_ts() instead of network_time() here, because + # network time does not immediately fall back to wall clock if there is + # no packet. Instead, network time remains set to the last seen packet's + # timestamp for ``packet_source_inactivity_timeout``. + local pkt_ts = get_current_packet_ts(); + if (pkt_ts == null_ts) + return 0 sec; + + return current_time() - pkt_ts; + } diff --git a/scripts/policy/misc/stats.zeek b/scripts/policy/misc/stats.zeek index 8449ccdb0d..cae9a3b16a 100644 --- a/scripts/policy/misc/stats.zeek +++ b/scripts/policy/misc/stats.zeek @@ -2,6 +2,7 @@ @load base/frameworks/notice @load base/frameworks/telemetry +@load base/utils/time module Stats; @@ -166,8 +167,6 @@ event zeek_init() &priority=5 Log::create_stream(Stats::LOG, [$columns=Info, $ev=log_stats, $path="stats", $policy=log_policy]); } -const null_ts = double_to_time(0); - event check_stats(then: time, last_ns: NetStats, last_cs: ConnStats, last_ps: ProcStats, last_es: EventStats, last_rs: ReassemblerStats, last_ts: TimerStats, last_fs: FileAnalysisStats, last_ds: DNSStats) { local nettime = network_time(); @@ -216,8 +215,7 @@ event check_stats(then: time, last_ns: NetStats, last_cs: ConnStats, last_ps: Pr if ( reading_live_traffic() ) { - local pkt_ts = get_current_packet_ts(); - info$pkt_lag = pkt_ts > null_ts ? current_time() - pkt_ts : 0 sec; + info$pkt_lag = get_packet_lag(); info$pkts_dropped = ns$pkts_dropped - last_ns$pkts_dropped; info$pkts_link = ns$pkts_link - last_ns$pkts_link; diff --git a/src/zeek.bif b/src/zeek.bif index d614bf27a0..84cc1e397a 100644 --- a/src/zeek.bif +++ b/src/zeek.bif @@ -3833,19 +3833,19 @@ function get_current_packet_header%(%) : raw_pkt_hdr return std::move(hdr); %} -## Returns the currently processed PCAP packet's timestamp. +## Returns the currently processed PCAP packet's timestamp or a 0 timestamp if +## there is no packet being processed at the moment. ## ## Returns: The currently processed packet's timestamp. ## -## .. zeek:see:: get_current_packet get_current_packet_header +## .. zeek:see:: get_current_packet get_current_packet_header network_time ## ## .. note:: ## -## For ``get_current_packet_ts()`` the same limitations as for -## :zeek:see:`get_current_packet` apply. In particular, the return value -## should be considered undefined when called within event handlers raised -## via :zeek:see:`event`, :zeek:see:`schedule` or by recipient of Broker -## messages. +## When there is no packet being processed, ``get_current_packet_ts()`` +## will return a 0 timestamp, while ``network_time()`` will return the +## timestamp of the last processed packet until it falls back to tracking +## wall clock after ``packet_source_inactivity_timeout``. function get_current_packet_ts%(%) : time %{ double ts = 0;