Merge remote-tracking branch 'origin/topic/awelzel/2572-event-handler-stats'

* origin/topic/awelzel/2572-event-handler-stats:
  Bump external baselines
  external/testing-setup: Less telemetry.log volume
  EventHandler: Use telemetry framework for EventHandler.call_count

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)

VERSION

@@ -1 +1 @@
-6.0.0-dev.82
+6.0.0-dev.87

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);

src/EventHandler.h

@@ -2,12 +2,14 @@
 
 #pragma once
 
+#include <optional>
 #include <string>
 #include <unordered_set>
 
 #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<zeek::telemetry::IntCounter> call_count;
 
 	std::unordered_set<std::string> auto_publish;
 	};

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

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;
+		}
+	}

testing/external/commit-hash.zeek-testing

@@ -1 +1 @@
-6373f271d1ad02f88004465766d40c5d3e50e464
+fae5bc9cfa6d57c9bcfed4dea6d0cd5c4a15932d

testing/external/commit-hash.zeek-testing-private

@@ -1 +1 @@
-ecadd8772e54199ed47c0a97398a39e3abd5b5c7
+0520a9854fb0591916bb88f68e98ed5750f1b7e6

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