From 69a98e2cbb113ae631a6061c7e753fb70b59f4eb Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 1 Feb 2023 17:16:11 +0100 Subject: [PATCH 1/3] logging: Add telemetry for streams and log writers This adds one metric per log stream and one metric per log writer (path based) to track the number of writes on a stream level as well as on a writer level. $ curl -sSf localhost:8181/metrics | grep Conn zeek_log_writer_writes_total{endpoint="",filter-name="default",module="HTTP",path="http",stream="HTTP::LOG",writer="Log::WRITER_SQLITE"} 1 1677497572770 zeek_log_stream_writes_total{endpoint="",module="HTTP",stream="HTTP::LOG"} 1 1677497572770 The initial version of this change also included metrics around log write vetoes, but given no log policies exist in the default configuration and they are mostly interesting for a few streams/writers only, skip this for now. These can always be added by the script writer, too. The difference between the stream level writes and concrete writers can be used to deduce the number of vetoes (or errors) as a starting point. --- NEWS | 3 ++ src/logging/Manager.cc | 47 ++++++++++++++++++- src/logging/Manager.h | 4 ++ .../telemetry.log | 16 +++++++ .../base/frameworks/logging/telemetry.zeek | 36 ++++++++++++++ 5 files changed, 104 insertions(+), 2 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.telemetry/telemetry.log create mode 100644 testing/btest/scripts/base/frameworks/logging/telemetry.zeek diff --git a/NEWS b/NEWS index a0b57d484c..5a137a2a6f 100644 --- a/NEWS +++ b/NEWS @@ -55,6 +55,9 @@ New Functionality verbose output in JSON format about the repository state and any included plugins. +- Add logging metrics for streams (``zeek-log-stream-writes``) and writers + (``zeek-log-writer-writes-total``). + Changed Functionality --------------------- diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index 733b62ba81..c9416c9eef 100644 --- a/src/logging/Manager.cc +++ b/src/logging/Manager.cc @@ -3,6 +3,7 @@ #include "zeek/logging/Manager.h" #include +#include #include #include "zeek/Desc.h" @@ -21,6 +22,7 @@ #include "zeek/logging/logging.bif.h" #include "zeek/plugin/Manager.h" #include "zeek/plugin/Plugin.h" +#include "zeek/telemetry/Manager.h" #include "zeek/threading/Manager.h" #include "zeek/threading/SerialTypes.h" @@ -73,6 +75,10 @@ struct Manager::WriterInfo bool from_remote = false; bool hook_initialized = false; string instantiating_filter; + + telemetry::IntCounter total_writes; + + WriterInfo(telemetry::IntCounter total_writes) : total_writes(total_writes) { } }; struct Manager::Stream @@ -92,6 +98,8 @@ struct Manager::Stream bool enable_remote = false; + std::optional total_writes; // Initialized on first write. + ~Stream(); }; @@ -132,7 +140,16 @@ Manager::Stream::~Stream() delete *f; } -Manager::Manager() : plugin::ComponentManager("Log", "Writer") +Manager::Manager() + : plugin::ComponentManager("Log", "Writer"), + total_log_stream_writes_family(telemetry_mgr->CounterFamily( + "zeek", "log-stream-writes", {"module", "stream"}, + "Total number of log writes for the given stream.", "1", true)), + total_log_writer_writes_family(telemetry_mgr->CounterFamily( + "zeek", "log-writer-writes", {"writer", "module", "stream", "filter-name", "path"}, + "Total number of log writes passed to a concrete log writer not vetoed by stream or " + "filter policies.", + "1", true)) { rotations_pending = 0; } @@ -734,6 +751,16 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) } } + if ( ! stream->total_writes ) + { + std::string module_name = detail::extract_module_name(stream->name.c_str()); + std::initializer_list labels{{"module", module_name}, + {"stream", stream->name}}; + stream->total_writes = total_log_stream_writes_family.GetOrAdd(labels); + } + + stream->total_writes->Inc(); + // Send to each of our filters. for ( list::iterator i = stream->filters.begin(); i != stream->filters.end(); ++i ) { @@ -905,6 +932,9 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) if ( ! writer ) return false; + + // Find the newly inserted WriterInfo record. + w = stream->writers.find(wpp); } // Alright, can do the write now. @@ -927,6 +957,9 @@ bool Manager::Write(EnumVal* id, RecordVal* columns_arg) return true; } + assert(w != stream->writers.end()); + w->second->total_writes.Inc(); + // Write takes ownership of vals. assert(writer); writer->Write(filter->num_fields, vals); @@ -1170,7 +1203,17 @@ WriterFrontend* Manager::CreateWriter(EnumVal* id, EnumVal* writer, WriterBacken return w->second->writer; } - WriterInfo* winfo = new WriterInfo; + // Initialize metric for this frontend. + std::string stream_module_name = detail::extract_module_name(stream->name.c_str()); + std::string writer_name = writer->GetType()->AsEnumType()->Lookup(writer->AsEnum()); + std::initializer_list labels{{"writer", writer_name}, + {"module", stream_module_name}, + {"stream", stream->name}, + {"filter-name", instantiating_filter}, + {"path", info->path}}; + + WriterInfo* winfo = new WriterInfo( + zeek::log_mgr->total_log_writer_writes_family.GetOrAdd(labels)); winfo->type = writer->Ref()->AsEnumVal(); winfo->writer = nullptr; winfo->open_time = run_state::network_time; diff --git a/src/logging/Manager.h b/src/logging/Manager.h index 739b6be7e9..6f926242f3 100644 --- a/src/logging/Manager.h +++ b/src/logging/Manager.h @@ -12,6 +12,7 @@ #include "zeek/logging/Component.h" #include "zeek/logging/WriterBackend.h" #include "zeek/plugin/ComponentManager.h" +#include "zeek/telemetry/Manager.h" namespace broker { @@ -305,6 +306,9 @@ private: int rotations_pending; // Number of rotations not yet finished. FuncPtr rotation_format_func; FuncPtr log_stream_policy_hook; + + telemetry::IntCounterFamily total_log_stream_writes_family; + telemetry::IntCounterFamily total_log_writer_writes_family; }; } // namespace logging; diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.telemetry/telemetry.log b/testing/btest/Baseline/scripts.base.frameworks.logging.telemetry/telemetry.log new file mode 100644 index 0000000000..16332e424f --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.telemetry/telemetry.log @@ -0,0 +1,16 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path telemetry +#open XXXX-XX-XX-XX-XX-XX +#fields ts peer metric_type prefix name unit labels label_values value +#types time string string string string string vector[string] vector[string] double +XXXXXXXXXX.XXXXXX zeek counter zeek log-stream-writes - module,stream HTTP,HTTP::LOG 14.0 +XXXXXXXXXX.XXXXXX zeek counter zeek log-stream-writes - module,stream DNS,DNS::LOG 34.0 +XXXXXXXXXX.XXXXXX zeek counter zeek log-stream-writes - module,stream Conn,Conn::LOG 34.0 +XXXXXXXXXX.XXXXXX zeek counter zeek log-writer-writes - filter-name,module,path,stream,writer default,HTTP,http,HTTP::LOG,Log::WRITER_ASCII 10.0 +XXXXXXXXXX.XXXXXX zeek counter zeek log-writer-writes - filter-name,module,path,stream,writer default,DNS,dns,DNS::LOG,Log::WRITER_ASCII 23.0 +XXXXXXXXXX.XXXXXX zeek counter zeek log-writer-writes - filter-name,module,path,stream,writer default,Conn,conn,Conn::LOG,Log::WRITER_ASCII 30.0 +#close XXXX-XX-XX-XX-XX-XX diff --git a/testing/btest/scripts/base/frameworks/logging/telemetry.zeek b/testing/btest/scripts/base/frameworks/logging/telemetry.zeek new file mode 100644 index 0000000000..4e7396d56d --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/telemetry.zeek @@ -0,0 +1,36 @@ +# @TEST-DOC: Check telemetry.log for log stream and log filter writes. +# @TEST-EXEC: zeek -b -r ${TRACES}/wikipedia.trace %INPUT +# @TEST-EXEC: btest-diff telemetry.log + +@load base/protocols/conn +@load base/protocols/dns +@load base/protocols/http + +@load policy/frameworks/telemetry/log + +global http_logs = 0; +hook HTTP::log_policy(rec: HTTP::Info, id: Log::ID, filter: Log::Filter) + { + if (++http_logs % 3 == 0) + break; + } + +global dns_logs = 0; +global conn_logs = 0; +hook Log::log_stream_policy(rec: any, id: Log::ID) + { + if (id == DNS::LOG && ++dns_logs % 3 == 0) + break; + + if (id == Conn::LOG && ++conn_logs % 7 == 0) + break; + } + +hook Telemetry::log_policy(rec: Telemetry::Info, id: Log::ID, filter: Log::Filter) + { + if ( rec$prefix != "zeek" || /^log-/ !in rec$name ) + break; + + if ( /HTTP|DNS|Conn/ !in cat(rec$label_values) ) + break; + } From 545b867ddd19441833dc839fc7691dc6480e7b68 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Mon, 27 Feb 2023 12:02:18 +0100 Subject: [PATCH 2/3] logging/Manager: Remove unused variable --- src/logging/Manager.cc | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index c9416c9eef..2b39aa4ff2 100644 --- a/src/logging/Manager.cc +++ b/src/logging/Manager.cc @@ -1181,8 +1181,6 @@ WriterFrontend* Manager::CreateWriter(EnumVal* id, EnumVal* writer, WriterBacken bool local, bool remote, bool from_remote, const string& instantiating_filter) { - WriterFrontend* result = nullptr; - Stream* stream = FindStream(id); if ( ! stream ) From bfc2374c8f4108ce55cf8c316ff4f7964ab6a44b Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Mon, 27 Feb 2023 13:04:40 +0100 Subject: [PATCH 3/3] Bump external test suites, filter some telemetry.log entries --- testing/external/commit-hash.zeek-testing | 2 +- testing/external/commit-hash.zeek-testing-private | 2 +- testing/external/scripts/testing-setup.zeek | 10 +++++++--- 3 files changed, 9 insertions(+), 5 deletions(-) diff --git a/testing/external/commit-hash.zeek-testing b/testing/external/commit-hash.zeek-testing index 26eccf6560..577208577f 100644 --- a/testing/external/commit-hash.zeek-testing +++ b/testing/external/commit-hash.zeek-testing @@ -1 +1 @@ -fae5bc9cfa6d57c9bcfed4dea6d0cd5c4a15932d +2adb32810742823cddea39d9a7ced7e45df67131 diff --git a/testing/external/commit-hash.zeek-testing-private b/testing/external/commit-hash.zeek-testing-private index 8d49cce761..496448b15b 100644 --- a/testing/external/commit-hash.zeek-testing-private +++ b/testing/external/commit-hash.zeek-testing-private @@ -1 +1 @@ -0520a9854fb0591916bb88f68e98ed5750f1b7e6 +41f6eb60c626316f0554548fcfa1ab07ddcf61a0 diff --git a/testing/external/scripts/testing-setup.zeek b/testing/external/scripts/testing-setup.zeek index 9285a23c6c..76656112c2 100644 --- a/testing/external/scripts/testing-setup.zeek +++ b/testing/external/scripts/testing-setup.zeek @@ -27,17 +27,21 @@ 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. + # except those having something to do with connection_* if ( rec$name == "event-handler-invocations" && /connection_.*/ !in cat(rec$label_values) ) break; + + # Filter out the LoadedScripts stream due to platform dependent + # difference in the scripts loaded, and also filter out Telemetry + # log counts. + if ( rec$name == /log-.*/ && /LoadedScripts::LOG|Telemetry::LOG/ in cat(rec$label_values) ) + break; } # The IMAP analyzer includes absolute filenames in its error messages,