From 56a8b999650b6517215fae631dadbe8f81015c90 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 15 Feb 2023 18:04:21 +0100 Subject: [PATCH 1/3] EventHandler: Use telemetry framework for EventHandler.call_count Put the IntCounter into a std::optional rather than initializing it at EventHandler construction time as that will currently expose a time series per event handler through the Prometheus API. --- src/EventHandler.cc | 12 ++++++++++- src/EventHandler.h | 8 +++++-- .../out | 4 ++++ .../telemetry/event-handler-invocations.zeek | 21 +++++++++++++++++++ 4 files changed, 42 insertions(+), 3 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.telemetry.event-handler-invocations/out create mode 100644 testing/btest/scripts/base/frameworks/telemetry/event-handler-invocations.zeek diff --git a/src/EventHandler.cc b/src/EventHandler.cc index 154bc7615f..e15234d750 100644 --- a/src/EventHandler.cc +++ b/src/EventHandler.cc @@ -9,6 +9,7 @@ #include "zeek/Var.h" #include "zeek/broker/Data.h" #include "zeek/broker/Manager.h" +#include "zeek/telemetry/Manager.h" namespace zeek { @@ -53,7 +54,16 @@ void EventHandler::SetFunc(FuncPtr f) void EventHandler::Call(Args* vl, bool no_remote) { - call_count++; + if ( ! call_count ) + { + static auto eh_invocations_family = telemetry_mgr->CounterFamily( + "zeek", "event-handler-invocations", {"name"}, + "Number of times the given event handler was called", "1", true); + + call_count = eh_invocations_family.GetOrAdd({{"name", name}}); + } + + call_count->Inc(); if ( new_event ) NewEvent(vl); diff --git a/src/EventHandler.h b/src/EventHandler.h index e7c9458971..258682adfc 100644 --- a/src/EventHandler.h +++ b/src/EventHandler.h @@ -2,12 +2,14 @@ #pragma once +#include #include #include #include "zeek/Type.h" #include "zeek/ZeekArgs.h" #include "zeek/ZeekList.h" +#include "zeek/telemetry/Counter.h" namespace zeek { @@ -55,7 +57,7 @@ public: } bool GenerateAlways() const { return generate_always; } - uint64_t CallCount() const { return call_count; } + uint64_t CallCount() const { return call_count ? call_count->Value() : 0; } private: void NewEvent(zeek::Args* vl); // Raise new_event() meta event. @@ -67,7 +69,9 @@ private: bool enabled; bool error_handler; // this handler reports error messages. bool generate_always; - uint64_t call_count = 0; + + // Initialize this lazy, so we don't expose metrics for 0 values. + std::optional call_count; std::unordered_set auto_publish; }; diff --git a/testing/btest/Baseline/scripts.base.frameworks.telemetry.event-handler-invocations/out b/testing/btest/Baseline/scripts.base.frameworks.telemetry.event-handler-invocations/out new file mode 100644 index 0000000000..bc1ab6859b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.telemetry.event-handler-invocations/out @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +zeek, event-handler-invocations, [zeek_init], 1 +zeek, event-handler-invocations, [connection_state_remove], 500 +zeek, event-handler-invocations, [zeek_done], 1 diff --git a/testing/btest/scripts/base/frameworks/telemetry/event-handler-invocations.zeek b/testing/btest/scripts/base/frameworks/telemetry/event-handler-invocations.zeek new file mode 100644 index 0000000000..e1a52792f5 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/telemetry/event-handler-invocations.zeek @@ -0,0 +1,21 @@ +# @TEST-DOC: Query for zeek event-handler-invocations metrics counting number of times handlers were called. + +# Note compilable to C++ due to globals being initialized to a record that +# has an opaque type as a field. +# @TEST-REQUIRES: test "${ZEEK_USE_CPP}" != "1" +# @TEST-EXEC: zcat <$TRACES/echo-connections.pcap.gz | zeek -b -Cr - %INPUT > out +# @TEST-EXEC: btest-diff out +# @TEST-EXEC-FAIL: test -f reporter.log + +@load base/frameworks/telemetry + + +event zeek_done() &priority=-100 + { + local ms = Telemetry::collect_metrics("zeek", "event-handler-invocations"); + for ( _, m in ms ) + { + if ( /zeek_.*|connection_.*/ in cat(m$labels)) + print m$opts$prefix, m$opts$name, m$labels, m$count_value; + } + } From d9e5cc30787017f677dad651247fe83e53d789b8 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Tue, 7 Feb 2023 10:53:17 +0100 Subject: [PATCH 2/3] external/testing-setup: Less telemetry.log volume For traces spanning a long time period, don't produce immense amounts of logs. Also filter down the event handler invocation entries to connection related events in telemetry.log. --- testing/external/scripts/testing-setup.zeek | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/testing/external/scripts/testing-setup.zeek b/testing/external/scripts/testing-setup.zeek index b80e31e1c1..9285a23c6c 100644 --- a/testing/external/scripts/testing-setup.zeek +++ b/testing/external/scripts/testing-setup.zeek @@ -16,6 +16,10 @@ # Exclude process metrics, they are non-deterministic. redef Telemetry::log_prefixes -= { "process" }; +# Increase default telemetry.log 30x to reduce log size +# for traces spanning a long time period. +redef Telemetry::log_interval = 1800sec; + # Prevent the version_info metric from being logged as it's not deterministic. hook Telemetry::log_policy(rec: Telemetry::Info, id: Log::ID, filter: Log::Filter) { @@ -23,6 +27,19 @@ hook Telemetry::log_policy(rec: Telemetry::Info, id: Log::ID, filter: Log::Filte break; } +# Filter out veto metrics and also loaded_script logs and telemetry logs due +# depending on the configuration (heavily). +hook Telemetry::log_policy(rec: Telemetry::Info, id: Log::ID, filter: Log::Filter) + { + if ( rec$prefix != "zeek" ) + return; + + # Filter all event-handler-invocations entries from telemetry.log + # except those having something to do with connections. + if ( rec$name == "event-handler-invocations" && /connection_.*/ !in cat(rec$label_values) ) + break; + } + # The IMAP analyzer includes absolute filenames in its error messages, # exclude it for now from analyzer.log. # https://github.com/zeek/zeek/issues/2659 From bf693aaaa550a796e1fd46d6ad8f66971c5a6e91 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 22 Feb 2023 12:10:34 +0100 Subject: [PATCH 3/3] Bump external baselines --- testing/external/commit-hash.zeek-testing | 2 +- testing/external/commit-hash.zeek-testing-private | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/testing/external/commit-hash.zeek-testing b/testing/external/commit-hash.zeek-testing index affb8b0230..93ec8be2d1 100644 --- a/testing/external/commit-hash.zeek-testing +++ b/testing/external/commit-hash.zeek-testing @@ -1 +1 @@ -6373f271d1ad02f88004465766d40c5d3e50e464 +e61bff14b4789b20c0fc71eca18b0618c2609b16 diff --git a/testing/external/commit-hash.zeek-testing-private b/testing/external/commit-hash.zeek-testing-private index a60dfa3909..c82cbfe79e 100644 --- a/testing/external/commit-hash.zeek-testing-private +++ b/testing/external/commit-hash.zeek-testing-private @@ -1 +1 @@ -ecadd8772e54199ed47c0a97398a39e3abd5b5c7 +e4a5af38c31a94a2f74af4c3754c9b40313df5b4