Merge remote-tracking branch 'origin/topic/awelzel/zeekctl-multiple-loggers'

* origin/topic/awelzel/zeekctl-multiple-loggers:
  NEWS: Add entry for ZeekControl and multi-loggers
  Bump zeekctl to multi-logger version
  logging: Support rotation_postprocessor_command_env

CHANGES

@@ -1,3 +1,13 @@
+6.0.0-dev.449 | 2023-04-27 12:16:46 +0200
+
+  * Bump zeekctl to multi-logger version (Arne Welzel, Corelight)
+
+  * logging: Support rotation_postprocessor_command_env (Arne Welzel, Corelight)
+
+    This new table provides a mechanism to add environment variables to the
+    postprocessor execution. Use case is from ZeekControl to inject a suffix
+    to be used when running with multiple logger.
+
 6.0.0-dev.445 | 2023-04-27 09:08:45 +0200
 
   * Update ZeekJS submodule to 0.9.0 (Arne Welzel, Corelight)

NEWS

@@ -112,6 +112,21 @@ New Functionality
   Loading the new policy scripts and using the external zeek-community-id
   plugin at the same time is unsupported.
 
+- ZeekControl is now multi-logger aware. When multiple logger nodes are configured
+  in ZeekControl's node.cfg, by default the log archival logic adds a logger's name
+  as suffix to the rotated file name:
+
+	stats.11:18:57-11:19:00-logger-1.log.gz
+	stats.11:18:57-11:19:00-logger-2.log.gz
+
+  Previously, in a multi-logger setup, individual logger processes would overwrite
+  each others log files during rotation, causing data loss.
+
+  For setups with a single logger, there's no change in behavior. The naming
+  of the final logs can be customized by providing an alternative
+  ``make-archive-name`` script and using the new ``ZEEK_ARG_LOG_SUFFIX``
+  environment variable.
+
 - Introduce a new command-line option ``-V`` / ``--build-info``. It produces
   verbose output in JSON format about the repository state and any included
   plugins.
@@ -199,6 +214,9 @@ New Functionality
 - Add packet analzyers for LLC, SNAP, and Novell 802.3, called from the Ethernet
   and VLAN analyzers by default.
 
+- Environment variables for the execution of log rotation postprocessors can
+  be set via ``Log::default_rotation_postprocessor_cmd_env``.
+
 Changed Functionality
 ---------------------
 

VERSION

@@ -1 +1 @@
-6.0.0-dev.445
+6.0.0-dev.449

auxil/zeekctl

@@ -1 +1 @@
-Subproject commit 633b4b3aafebde91cc1ded20b2841113681aa60a
+Subproject commit 7178d15edb4c737a5d6c28d100c0e457b7afed58

scripts/base/frameworks/logging/main.zeek

@@ -172,6 +172,14 @@ export {
 	## Default shell command to run on rotated files. Empty for none.
 	const default_rotation_postprocessor_cmd = "" &redef;
 
+	## This table contains environment variables to be used for the
+	## :zeek:see:`Log::default_rotation_postprocessor_cmd` command
+	## when executed via :zeek:see:`Log::run_rotation_postprocessor_cmd`.
+	##
+	## The entries in this table will be prepended with ``ZEEK_ARG_``
+	## as done by :zeek:see:`system_env`.
+	option default_rotation_postprocessor_cmd_env: table[string] of string = {};
+
 	## Specifies the default postprocessor function per writer type.
 	## Entries in this table are initialized by each writer type.
 	const default_rotation_postprocessors: table[Writer] of function(info: RotationInfo) : bool &redef;
@@ -578,6 +586,7 @@ export {
 	##          to postprocess a rotated log file.
 	##
 	## .. zeek:see:: Log::default_rotation_date_format
+	##    Log::default_rotation_postprocessor_cmd_env
 	##    Log::default_rotation_postprocessor_cmd
 	##    Log::default_rotation_postprocessors
 	global run_rotation_postprocessor_cmd: function(info: RotationInfo, npath: string) : bool;
@@ -654,8 +663,7 @@ function default_path_func(id: ID, path: string, rec: any) : string
 		return to_lower(id_str);
 	}
 
-# Run post-processor on file. If there isn't any postprocessor defined,
+# Run post-processor on file.
-# we move the file to a nicer name.
 function run_rotation_postprocessor_cmd(info: RotationInfo, npath: string) : bool
 	{
 	local pp_cmd = default_rotation_postprocessor_cmd;
@@ -668,11 +676,15 @@ function run_rotation_postprocessor_cmd(info: RotationInfo, npath: string) : boo
 
 	# The date format is hard-coded here to provide a standardized
 	# script interface.
-	system(fmt("%s %s %s %s %s %d %s",
+	#
-               pp_cmd, safe_shell_quote(npath), safe_shell_quote(info$path),
+	# Note that system_env() does not clear the environment, it only
-               strftime("%y-%m-%d_%H.%M.%S", info$open),
+	# adds entries from the given table. Unusual, but useful here.
-               strftime("%y-%m-%d_%H.%M.%S", info$close),
+	system_env(fmt("%s %s %s %s %s %d %s",
-               info$terminating, writer));
+	               pp_cmd, safe_shell_quote(npath), safe_shell_quote(info$path),
+	               strftime("%y-%m-%d_%H.%M.%S", info$open),
+	               strftime("%y-%m-%d_%H.%M.%S", info$close),
+	               info$terminating, writer),
+	           Log::default_rotation_postprocessor_cmd_env);
 
 	return T;
 	}

testing/btest/Baseline/plugins.hooks/output

@@ -558,6 +558,7 @@
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (Input::default_reader, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (KRB::ignored_errors, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (Log::default_rotation_dir, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
+0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (Log::default_rotation_postprocessor_cmd_env, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (MQTT::max_payload_size, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (NetControl::default_priority, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Option::set_change_handler, <frame>, (Notice::alarmed_types, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)) -> <no result>
@@ -2176,6 +2177,7 @@
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (Input::default_reader, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (KRB::ignored_errors, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (Log::default_rotation_dir, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
+0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (Log::default_rotation_postprocessor_cmd_env, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (MQTT::max_payload_size, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (NetControl::default_priority, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
 0.000000   MetaHookPre   CallFunction(Option::set_change_handler, <frame>, (Notice::alarmed_types, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100))
@@ -3793,6 +3795,7 @@
 0.000000 | HookCallFunction Option::set_change_handler(Input::default_reader, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(KRB::ignored_errors, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(Log::default_rotation_dir, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)
+0.000000 | HookCallFunction Option::set_change_handler(Log::default_rotation_postprocessor_cmd_env, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(MQTT::max_payload_size, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(NetControl::default_priority, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)
 0.000000 | HookCallFunction Option::set_change_handler(Notice::alarmed_types, Config::config_option_changed{ if (<skip-config-log> == Config::location) return (Config::new_value)Config::log = Config::Info($ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value))if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, to_any_coerceConfig::log)return (Config::new_value)}, -100)

testing/btest/Baseline/scripts.base.frameworks.logging.rotate-pp-env/out

@@ -0,0 +1,31 @@
+### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63.
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef
+ZEEK_ARG_EXTERNAL=external
+ZEEK_ARG_INIT=zeek_init
+ZEEK_ARG_REDEF=redef

testing/btest/scripts/base/frameworks/logging/rotate-pp-env.zeek

@@ -0,0 +1,32 @@
+# @TEST-DOC: Using a custom environment for the postprocessor command.
+# @TEST-EXEC: ZEEK_ARG_EXTERNAL=external zeek -b -r ${TRACES}/rotation.trace %INPUT >out 2>&1
+# @TEST-EXEC: btest-diff out
+
+module Test;
+
+export {
+	redef enum Log::ID += { LOG };
+
+	type Log: record {
+		t: time;
+		id: conn_id;
+	} &log;
+}
+
+redef Log::default_rotation_interval = 1hr;
+redef Log::default_rotation_postprocessor_cmd = "env | grep ZEEK_ARG | sort; true ";
+
+redef Log::default_rotation_postprocessor_cmd_env += {
+	["REDEF"] = "redef",
+};
+
+event zeek_init()
+	{
+	Log::create_stream(Test::LOG, [$columns=Log]);
+	Log::default_rotation_postprocessor_cmd_env["INIT"] = "zeek_init";
+	}
+
+event new_connection(c: connection)
+	{
+	Log::write(Test::LOG, [$t=network_time(), $id=c$id]);
+	}