From e20aa66eae3087cd46759e399777511c5257297a Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Fri, 4 Oct 2024 11:34:02 +0200 Subject: [PATCH] misc/stats: Add zeek_net_timestamp_seconds Adding a metric for the network time value itself should make it possible to observe it stopping or growing slowly as compared to realtime when Zeek isn't able to keep up. Also, modify the telemetry/log.zeek test to include misc/stats and log at a higher frequency with a more interesting pcap. --- scripts/policy/misc/stats.zeek | 15 +++- .../telemetry.log.filtered | 76 +++++++++++++++++-- .../telemetry_histogram.log.filtered | 9 ++- .../policy/frameworks/telemetry/log.zeek | 10 ++- 4 files changed, 96 insertions(+), 14 deletions(-) diff --git a/scripts/policy/misc/stats.zeek b/scripts/policy/misc/stats.zeek index cf5bb1cbd0..c324a728be 100644 --- a/scripts/policy/misc/stats.zeek +++ b/scripts/policy/misc/stats.zeek @@ -130,9 +130,20 @@ global packet_lag_gf = Telemetry::register_gauge_family([ $help_text="Difference of network time and wallclock time in seconds.", ]); +# Gauge as motivated by: +# https://www.robustperception.io/are-increasing-timestamps-counters-or-gauges/ +global network_time_cf = Telemetry::register_gauge_family([ + $prefix="zeek", + $name="net-timestamp", + $unit="seconds", + $help_text="The current network time.", +]); + global no_labels: vector of string; -hook Telemetry::sync() { +hook Telemetry::sync() + { + Telemetry::gauge_family_set(network_time_cf, no_labels, time_to_double(network_time())); local net_stats = get_net_stats(); Telemetry::counter_family_set(bytes_received_cf, no_labels, net_stats$bytes_recvd); Telemetry::counter_family_set(packets_received_cf, no_labels, net_stats$pkts_recvd); @@ -148,7 +159,7 @@ hook Telemetry::sync() { Telemetry::gauge_family_set(packet_lag_gf, no_labels, interval_to_double(current_time() - network_time())); } -} + } event zeek_init() &priority=5 { diff --git a/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry.log.filtered b/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry.log.filtered index b5c04c3f44..27fe96a750 100644 --- a/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry.log.filtered +++ b/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry.log.filtered @@ -1,7 +1,71 @@ ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. -XXXXXXXXXX.XXXXXX zeek counter zeek_ended_sessions_total reason inactivity 0.0 -XXXXXXXXXX.XXXXXX zeek counter zeek_total_sessions_total protocol tcp 1.0 -XXXXXXXXXX.XXXXXX zeek gauge zeek_active_sessions protocol tcp 1.0 -XXXXXXXXXX.XXXXXX zeek counter zeek_ended_sessions_total reason inactivity 0.0 -XXXXXXXXXX.XXXXXX zeek counter zeek_total_sessions_total protocol tcp 500.0 -XXXXXXXXXX.XXXXXX zeek gauge zeek_active_sessions protocol tcp 500.0 +1300475167.096535 zeek counter zeek_net_received_bytes_total (empty) (empty) 87.0 +1300475167.096535 zeek counter zeek_net_received_packets_total (empty) (empty) 1.0 +1300475167.096535 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475167.096535 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475167.096535 zeek counter zeek_total_sessions_total protocol udp 1.0 +1300475167.096535 zeek counter zeek_total_sessions_total protocol tcp 0.0 +1300475167.096535 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475167.096535 +1300475167.096535 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475167.096535 zeek gauge zeek_active_sessions protocol udp 1.0 +1300475167.096535 zeek gauge zeek_active_sessions protocol tcp 0.0 +1300475168.652003 zeek counter zeek_net_received_bytes_total (empty) (empty) 1142.0 +1300475168.652003 zeek counter zeek_net_received_packets_total (empty) (empty) 6.0 +1300475168.652003 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475168.652003 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475168.652003 zeek counter zeek_total_sessions_total protocol udp 3.0 +1300475168.652003 zeek counter zeek_total_sessions_total protocol tcp 1.0 +1300475168.652003 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475168.652003 +1300475168.652003 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475168.652003 zeek gauge zeek_active_sessions protocol udp 3.0 +1300475168.652003 zeek gauge zeek_active_sessions protocol tcp 1.0 +1300475169.780331 zeek counter zeek_net_received_bytes_total (empty) (empty) 23385.0 +1300475169.780331 zeek counter zeek_net_received_packets_total (empty) (empty) 113.0 +1300475169.780331 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475169.780331 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475169.780331 zeek counter zeek_total_sessions_total protocol udp 17.0 +1300475169.780331 zeek counter zeek_total_sessions_total protocol tcp 10.0 +1300475169.780331 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475169.780331 +1300475169.780331 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475169.780331 zeek gauge zeek_active_sessions protocol udp 17.0 +1300475169.780331 zeek gauge zeek_active_sessions protocol tcp 10.0 +1300475170.811500 zeek counter zeek_net_received_bytes_total (empty) (empty) 23604.0 +1300475170.811500 zeek counter zeek_net_received_packets_total (empty) (empty) 116.0 +1300475170.811500 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475170.811500 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475170.811500 zeek counter zeek_total_sessions_total protocol udp 18.0 +1300475170.811500 zeek counter zeek_total_sessions_total protocol tcp 10.0 +1300475170.811500 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475170.8115 +1300475170.811500 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475170.811500 zeek gauge zeek_active_sessions protocol udp 18.0 +1300475170.811500 zeek gauge zeek_active_sessions protocol tcp 10.0 +1300475171.886280 zeek counter zeek_net_received_bytes_total (empty) (empty) 24248.0 +1300475171.886280 zeek counter zeek_net_received_packets_total (empty) (empty) 124.0 +1300475171.886280 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475171.886280 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475171.886280 zeek counter zeek_total_sessions_total protocol udp 21.0 +1300475171.886280 zeek counter zeek_total_sessions_total protocol tcp 10.0 +1300475171.886280 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475171.88628 +1300475171.886280 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475171.886280 zeek gauge zeek_active_sessions protocol udp 21.0 +1300475171.886280 zeek gauge zeek_active_sessions protocol tcp 10.0 +1300475173.116749 zeek counter zeek_net_received_bytes_total (empty) (empty) 24679.0 +1300475173.116749 zeek counter zeek_net_received_packets_total (empty) (empty) 129.0 +1300475173.116749 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475173.116749 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475173.116749 zeek counter zeek_total_sessions_total protocol udp 22.0 +1300475173.116749 zeek counter zeek_total_sessions_total protocol tcp 10.0 +1300475173.116749 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475173.116749 +1300475173.116749 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475173.116749 zeek gauge zeek_active_sessions protocol udp 22.0 +1300475173.116749 zeek gauge zeek_active_sessions protocol tcp 10.0 +1300475173.475401 zeek counter zeek_net_received_bytes_total (empty) (empty) 25260.0 +1300475173.475401 zeek counter zeek_net_received_packets_total (empty) (empty) 136.0 +1300475173.475401 zeek counter zeek_ended_sessions_total reason inactivity 0.0 +1300475173.475401 zeek counter zeek_total_sessions_total protocol icmp 0.0 +1300475173.475401 zeek counter zeek_total_sessions_total protocol udp 24.0 +1300475173.475401 zeek counter zeek_total_sessions_total protocol tcp 10.0 +1300475173.475401 zeek gauge zeek_net_timestamp_seconds (empty) (empty) 1300475173.475401 +1300475173.475401 zeek gauge zeek_active_sessions protocol icmp 0.0 +1300475173.475401 zeek gauge zeek_active_sessions protocol udp 24.0 +1300475173.475401 zeek gauge zeek_active_sessions protocol tcp 9.0 diff --git a/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry_histogram.log.filtered b/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry_histogram.log.filtered index d47ba69d07..28672af18d 100644 --- a/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry_histogram.log.filtered +++ b/testing/btest/Baseline/scripts.policy.frameworks.telemetry.log/telemetry_histogram.log.filtered @@ -1,3 +1,8 @@ ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. -XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 2.0,3.0,4.0,5.0,6.0,10.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 -XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 2.0,3.0,4.0,5.0,6.0,10.0,inf 0.0,322.0,90.0,5.0,76.0,7.0,0.0 1650.264644 500.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0,0.0 0.0 0.0 +XXXXXXXXXX.XXXXXX zeek zeek_connection_duration_seconds (empty) (empty) 0.0001,0.001,0.01,0.1,0.5,1.0,5.0,10.0,30.0,60.0,inf 6.0,14.0,0.0,3.0,10.0,0.0,1.0,0.0,0.0,0.0,0.0 4.651298 34.0 diff --git a/testing/btest/scripts/policy/frameworks/telemetry/log.zeek b/testing/btest/scripts/policy/frameworks/telemetry/log.zeek index ab74478913..1faff83719 100644 --- a/testing/btest/scripts/policy/frameworks/telemetry/log.zeek +++ b/testing/btest/scripts/policy/frameworks/telemetry/log.zeek @@ -1,20 +1,22 @@ # @TEST-DOC: Test loading of telemetry/log and smoke check the telemetry.log file -# @TEST-EXEC: zcat <$TRACES/echo-connections.pcap.gz | zeek -b -Cr - %INPUT > out -# @TEST-EXEC: grep 'zeek.*sessions' telemetry.log > telemetry.log.filtered +# @TEST-EXEC: zeek -b -Cr $TRACES/wikipedia.trace %INPUT > out +# @TEST-EXEC: grep -E 'zeek_(net|.*sessions)' telemetry.log > telemetry.log.filtered # @TEST-EXEC: grep 'zeek.*connection_duration' telemetry_histogram.log > telemetry_histogram.log.filtered -# @TEST-EXEC: btest-diff telemetry.log.filtered +# @TEST-EXEC: TEST_DIFF_CANONIFIER= btest-diff telemetry.log.filtered # @TEST-EXEC: btest-diff telemetry_histogram.log.filtered +@load misc/stats @load frameworks/telemetry/log +redef Telemetry::log_interval = 1sec; global connection_duration_hf = Telemetry::register_histogram_family([ $prefix="zeek", $name="connection_duration", $unit="seconds", $help_text="Monitored connection duration", - $bounds=vector(2.0, 3.0, 4.0, 5.0, 6.0, 10.0) + $bounds=vector(0.0001, 0.001, 0.01, 0.1, 0.5, 1.0, 5.0, 10.0, 30.0, 60.0) ]); global connection_duration_h = Telemetry::histogram_with(connection_duration_hf);