diff --git a/CHANGES b/CHANGES index 2d872fcb11..7a87c22fca 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,15 @@ +7.1.0-dev.738 | 2024-12-10 18:26:31 +0100 + + * Introduce get_packet_lag() (Jan Grashoefer, Corelight) + + * Add btest for get_current_packet_ts() (Jan Grashoefer, Corelight) + + * Introduce get_current_packet_ts to fix packet lag (Jan Grashoefer, Corelight) + + 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. + 7.1.0-dev.734 | 2024-12-10 09:56:46 +0100 * DNS/dns_binds_rr: Fix complte to complete typo, switch to count (Arne Welzel, Corelight) diff --git a/VERSION b/VERSION index e9c819020b..c422f2731b 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -7.1.0-dev.734 +7.1.0-dev.738 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 c324a728be..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; @@ -214,7 +215,7 @@ event check_stats(then: time, last_ns: NetStats, last_cs: ConnStats, last_ps: Pr if ( reading_live_traffic() ) { - info$pkt_lag = current_time() - nettime; + 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 fbcf322c44..cc2321408e 100644 --- a/src/zeek.bif +++ b/src/zeek.bif @@ -3854,6 +3854,31 @@ function get_current_packet_header%(%) : raw_pkt_hdr return std::move(hdr); %} +## 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 network_time +## +## .. note:: +## +## 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; + 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. 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()); + } diff --git a/testing/external/commit-hash.zeek-testing b/testing/external/commit-hash.zeek-testing index 9805198913..0c933fa673 100644 --- a/testing/external/commit-hash.zeek-testing +++ b/testing/external/commit-hash.zeek-testing @@ -1 +1 @@ -2a63b457f24133a845c2020a321b7cbc05262291 +4359bd2c0e776dce08f7eca30d3d34cfe3e1d98b