diff --git a/CHANGES b/CHANGES index 494eca8301..b4c96ec840 100644 --- a/CHANGES +++ b/CHANGES @@ -1,3 +1,24 @@ +6.0.0-dev.148 | 2023-03-02 10:05:06 +0100 + + * logging/Manager: Remove unused variable (Arne Welzel, Corelight) + + * logging: Add telemetry for streams and log writers (Arne Welzel, Corelight) + + 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. + 6.0.0-dev.143 | 2023-03-01 10:40:36 +0000 * X.509: expose the signature type inside the tbs certificate (Johanna Amann, Corelight) diff --git a/NEWS b/NEWS index ab2f684d1c..cc6929540b 100644 --- a/NEWS +++ b/NEWS @@ -58,6 +58,9 @@ New Functionality - The X.509 certificate parser now exposes the signature type that is given inside the signed portion of the certificate. +- Add logging metrics for streams (``zeek-log-stream-writes``) and writers + (``zeek-log-writer-writes-total``). + Changed Functionality --------------------- diff --git a/VERSION b/VERSION index 5fd189c62d..bf95e5f05e 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -6.0.0-dev.143 +6.0.0-dev.148 diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index 733b62ba81..2b39aa4ff2 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); @@ -1148,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 ) @@ -1170,7 +1201,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; + } 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,