diff --git a/CHANGES b/CHANGES index a4b3c05649..b072eccb82 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,17 @@ +6.0.0-dev.87 | 2023-02-22 12:58:05 +0100 + + * external/testing-setup: Less telemetry.log volume (Arne Welzel, Corelight) + + 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. + + * EventHandler: Use telemetry framework for EventHandler.call_count (Arne Welzel, Corelight) + + 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. + 6.0.0-dev.82 | 2023-02-21 16:48:03 -0700 * parse.y: Improve error reporting of type redef (Arne Welzel, Corelight) diff --git a/VERSION b/VERSION index c9e6a64992..8e616e4045 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -6.0.0-dev.82 +6.0.0-dev.87 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; + } + } diff --git a/testing/external/commit-hash.zeek-testing b/testing/external/commit-hash.zeek-testing index affb8b0230..26eccf6560 100644 --- a/testing/external/commit-hash.zeek-testing +++ b/testing/external/commit-hash.zeek-testing @@ -1 +1 @@ -6373f271d1ad02f88004465766d40c5d3e50e464 +fae5bc9cfa6d57c9bcfed4dea6d0cd5c4a15932d diff --git a/testing/external/commit-hash.zeek-testing-private b/testing/external/commit-hash.zeek-testing-private index a60dfa3909..8d49cce761 100644 --- a/testing/external/commit-hash.zeek-testing-private +++ b/testing/external/commit-hash.zeek-testing-private @@ -1 +1 @@ -ecadd8772e54199ed47c0a97398a39e3abd5b5c7 +0520a9854fb0591916bb88f68e98ed5750f1b7e6 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