Add Log::rotation_format_func and Log::default_rotation_dir options

These may be redefined to customize log rotation path prefixes,
including use of a directory.  File extensions are still up to
individual log writers to add themselves during the actual rotation.

These new also allow for some simplication to the default
ASCII postprocessor function: it eliminates the need for it doing an
extra/awkward rename() operation that only changes the timestamp format.

This also teaches the supervisor framework to use these new options
to rotate ascii logs into a log-queue/ directory with a specific
file name format (intended for an external archiver process to
monitor separately).

src/logging/Manager.cc

@@ -142,6 +142,11 @@ Manager::~Manager()
 		delete *s;
 	}
 
+void Manager::InitPostScript()
+	{
+	rotation_format_func = zeek::id::find_func("Log::rotation_format_func");
+	}
+
 WriterBackend* Manager::CreateBackend(WriterFrontend* frontend, zeek::EnumVal* tag)
 	{
 	Component* c = Lookup(tag);
@@ -1483,7 +1488,7 @@ void Manager::InstallRotationTimer(WriterInfo* winfo)
 		}
 	}
 
-std::string Manager::FormatRotationTime(time_t t)
+static std::string format_rotation_time_fallback(time_t t)
 	{
 	struct tm tm;
 	char buf[128];
@@ -1493,11 +1498,55 @@ std::string Manager::FormatRotationTime(time_t t)
 	return buf;
 	}
 
-std::string Manager::FormatRotationPath(std::string_view path, time_t t)
+std::string Manager::FormatRotationPath(zeek::EnumValPtr writer,
+                                        std::string_view path, double open,
+                                        double close, bool terminating,
+                                        zeek::FuncPtr postprocessor)
 	{
-	auto rot_str = FormatRotationTime(t);
-	return fmt("%.*s-%s",
-	           static_cast<int>(path.size()), path.data(), rot_str.data());
+	auto ri = zeek::make_intrusive<zeek::RecordVal>(zeek::BifType::Record::Log::RotationFmtInfo);
+	ri->Assign(0, std::move(writer));
+	ri->Assign<zeek::TimeVal>(2, open);
+	ri->Assign<zeek::StringVal>(1, path.size(), path.data());
+	ri->Assign<zeek::TimeVal>(3, close);
+	ri->Assign(4, zeek::val_mgr->Bool(terminating));
+	ri->Assign<zeek::Val>(5, std::move(postprocessor));
+
+	std::string rval;
+
+	try
+		{
+		auto res = rotation_format_func->Invoke(ri);
+		auto rp_val = res->AsRecordVal();
+		auto dir_val = rp_val->GetFieldOrDefault(0);
+		auto prefix = rp_val->GetField(1)->AsString()->CheckString();
+		auto dir = dir_val->AsString()->CheckString();
+
+		if ( ! streq(dir, "") && ! ensure_intermediate_dirs(dir) )
+			{
+			reporter->Error("Failed to create dir '%s' returned by "
+			                "Log::rotation_format_func for path %.*s: %s",
+			                dir, static_cast<int>(path.size()), path.data(),
+			                strerror(errno));
+			dir = "";
+			}
+
+		if ( streq(dir, "") )
+			rval = prefix;
+		else
+			rval = fmt("%s/%s", dir, prefix);
+
+		}
+	catch ( InterpreterException& e )
+		{
+		auto rot_str = format_rotation_time_fallback((time_t)open);
+		rval = fmt("%.*s-%s", static_cast<int>(path.size()), path.data(),
+		           rot_str.data());
+		reporter->Error("Failed to call Log::rotation_format_func for path %.*s "
+		                "continuing with rotation to: ./%s",
+		                static_cast<int>(path.size()), path.data(), rval.data());
+		}
+
+	return rval;
 	}
 
 void Manager::Rotate(WriterInfo* winfo)
@@ -1505,10 +1554,22 @@ void Manager::Rotate(WriterInfo* winfo)
 	DBG_LOG(DBG_LOGGING, "Rotating %s at %.6f",
 		winfo->writer->Name(), network_time);
 
-	// Build a temporary path for the writer to move the file to.
-	auto tmp = FormatRotationPath(winfo->writer->Info().path,
-	                              (time_t)winfo->open_time);
-	winfo->writer->Rotate(tmp.data(), winfo->open_time, network_time, terminating);
+	static auto default_ppf = zeek::id::find_func("Log::__default_rotation_postprocessor");
+
+	zeek::FuncPtr ppf;
+
+	if ( winfo->postprocessor )
+		ppf = {zeek::NewRef{}, winfo->postprocessor};
+	else
+		ppf = default_ppf;
+
+	auto rotation_path = FormatRotationPath({zeek::NewRef{}, winfo->type},
+	                                        winfo->writer->Info().path,
+	                                        winfo->open_time, network_time,
+	                                        terminating,
+	                                        std::move(ppf));
+
+	winfo->writer->Rotate(rotation_path.data(), winfo->open_time, network_time, terminating);
 
 	++rotations_pending;
 	}
@@ -1534,7 +1595,6 @@ bool Manager::FinishedRotation(WriterFrontend* writer, const char* new_name, con
 	if ( ! winfo )
 		return true;
 
-	// Create the RotationInfo record.
 	auto info = zeek::make_intrusive<zeek::RecordVal>(zeek::BifType::Record::Log::RotationInfo);
 	info->Assign(0, {zeek::NewRef{}, winfo->type});
 	info->Assign(1, zeek::make_intrusive<zeek::StringVal>(new_name));
@@ -1543,13 +1603,12 @@ bool Manager::FinishedRotation(WriterFrontend* writer, const char* new_name, con
 	info->Assign(4, zeek::make_intrusive<zeek::TimeVal>(close));
 	info->Assign(5, zeek::val_mgr->Bool(terminating));
 
+	static auto default_ppf = zeek::id::find_func("Log::__default_rotation_postprocessor");
+
 	zeek::Func* func = winfo->postprocessor;
+
 	if ( ! func )
-		{
-		const auto& id = zeek::detail::global_scope()->Find("Log::__default_rotation_postprocessor");
-		assert(id);
-		func = id->GetVal()->AsFunc();
-		}
+		func = default_ppf.get();
 
 	assert(func);
 

src/logging/Manager.h

@@ -4,7 +4,6 @@
 
 #pragma once
 
-#include <ctime>
 #include <string_view>
 
 #include "../Val.h"
@@ -30,18 +29,6 @@ class RotationFinishedMessage;
 class Manager : public plugin::ComponentManager<Tag, Component> {
 public:
 
-	/**
-	 * Returns a formatted string representing the given time.  This
-	 * string is used in the log file rotation process.
-	 */
-	static std::string FormatRotationTime(time_t t);
-
-	/**
-	 * Returns a formatted string representing the file rotation path.  This
-	 * string is used in the log file rotation process.
-	 */
-	static std::string FormatRotationPath(std::string_view path, time_t t);
-
 	/**
 	 * Constructor.
 	 */
@@ -52,6 +39,24 @@ public:
 	 */
 	~Manager();
 
+	/**
+	 * Called after scripts are parsed; obtains values of customizable options.
+	 */
+	void InitPostScript();
+
+	/**
+	 * Calls the Log::rotation_format_func script function, tries to create
+	 * any directories (failure to falls back to using working dir for
+	 * rotation) and returns the formatted rotation path string that
+	 * will be sent along to writer threads to perform the actual rotation.
+	 * @param rotation_info  The fields of a Log::RotationFmtInfo record
+	 *                       to create and pass to Log::rotation_format_func.
+	 */
+	std::string FormatRotationPath(zeek::EnumValPtr writer,
+	                               std::string_view path, double open,
+	                               double close, bool terminating,
+	                               zeek::FuncPtr postprocesor);
+
 	/**
 	 * Creates a new log stream.
 	 *
@@ -290,6 +295,7 @@ private:
 
 	std::vector<Stream *> streams;	// Indexed by stream enum.
 	int rotations_pending;	// Number of rotations not yet finished.
+	zeek::FuncPtr rotation_format_func;
 };
 
 }

src/logging/logging.bif

@@ -9,6 +9,7 @@ module Log;
 type Filter: record;
 type Stream: record;
 type RotationInfo: record;
+type RotationFmtInfo: record;
 
 enum PrintLogType %{
 	REDIRECT_NONE,

src/logging/writers/ascii/Ascii.cc

@@ -88,20 +88,6 @@ struct LeftoverLog {
 	std::string Name() const
 		{ return filename.substr(0, filename.size() - extension.size()); }
 
-	/**
-	 * The path to which the log file should be rotated (before
-	 * calling any postprocessing function).
-	 */
-	std::string RotationPath() const
-		{ return log_mgr->FormatRotationPath(Name(), open_time) + extension; }
-
-	/**
-	 * Performs the rename() call to rotate the file and returns whether
-	 * it succeeded.
-	 */
-	bool Rename() const
-		{ return rename(filename.data(), RotationPath().data()) == 0; }
-
 	/**
 	 * Deletes the shadow file and returns whether it succeeded.
 	 */
@@ -753,50 +739,61 @@ void Ascii::RotateLeftoverLogs()
 
 	for ( const auto& ll : leftover_logs )
 		{
-		if ( ! ll.Rename() )
+		static auto rot_info_type = zeek::id::find_type<zeek::RecordType>("Log::RotationInfo");
+		static auto writer_type = zeek::id::find_type<zeek::EnumType>("Log::Writer");
+		static auto writer_idx = writer_type->Lookup("Log", "WRITER_ASCII");
+		static auto writer_val = writer_type->GetVal(writer_idx);
+		static auto default_ppf = zeek::id::find_func("Log::__default_rotation_postprocessor");
+		assert(default_ppf);
+
+		auto ppf = default_ppf;
+
+		if ( ! ll.post_proc_func.empty() )
+			{
+			auto func = zeek::id::find_func(ll.post_proc_func.data());
+
+			if ( func )
+				ppf = std::move(func);
+			else
+				reporter->Warning("Could no postprocess log '%s' with intended "
+								  "postprocessor function '%s', proceeding "
+								  " with the default function",
+								  ll.filename.data(), ll.post_proc_func.data());
+			}
+
+		auto rotation_path = log_mgr->FormatRotationPath(
+		        writer_val, ll.Name(), ll.open_time, ll.close_time, false, ppf);
+
+		rotation_path += ll.extension;
+
+		auto rot_info = zeek::make_intrusive<zeek::RecordVal>(rot_info_type);
+		rot_info->Assign(0, writer_val);
+		rot_info->Assign<zeek::StringVal>(1, rotation_path);
+		rot_info->Assign<zeek::StringVal>(2, ll.Name());
+		rot_info->Assign<zeek::TimeVal>(3, ll.open_time);
+		rot_info->Assign<zeek::TimeVal>(4, ll.close_time);
+		rot_info->Assign(5, zeek::val_mgr->False());
+
+		if ( rename(ll.filename.data(), rotation_path.data()) != 0 )
 			reporter->FatalError("Found leftover/unprocessed log '%s', but "
 								 "failed to rotate it: %s",
 								 ll.filename.data(), strerror(errno));
 
 		if ( ! ll.DeleteShadow() )
 			// Unusual failure to report, but not strictly fatal.
-			reporter->Error("Failed to unlink %s: %s",
-			                ll.shadow_filename.data(), strerror(errno));
-
-		static auto rt = zeek::id::find_type<zeek::RecordType>("Log::RotationInfo");
-		static auto writer_type = zeek::id::find_type<zeek::EnumType>("Log::Writer");
-		static auto writer_idx = writer_type->Lookup("Log", "WRITER_ASCII");
-		static auto writer_val = writer_type->GetVal(writer_idx);
-
-		auto info = make_intrusive<RecordVal>(rt);
-		info->Assign(0, writer_val);
-		info->Assign(1, make_intrusive<StringVal>(ll.RotationPath()));
-		info->Assign(2, make_intrusive<StringVal>(ll.Name()));
-		info->Assign(3, make_intrusive<TimeVal>(ll.open_time));
-		info->Assign(4, make_intrusive<TimeVal>(ll.close_time));
-		info->Assign(5, val_mgr->False());
-
-		auto ppf = ll.post_proc_func.empty() ? "Log::__default_rotation_postprocessor"
-		                                     : ll.post_proc_func.data();
-
-		auto func = zeek::id::find_func(ppf);
-
-		if ( ! func )
-			reporter->Error("Postprocessing log '%s' failed: "
-							"no such function: '%s'",
-							ll.filename.data(), ppf);
-
+			reporter->Warning("Failed to unlink %s: %s",
+			                  ll.shadow_filename.data(), strerror(errno));
 
 		try
 			{
-			func->Invoke(std::move(info));
-			reporter->Info("Rotated/postprocessed leftover log '%s'",
-			               ll.filename.data());
+			ppf->Invoke(std::move(rot_info));
+			reporter->Info("Rotated/postprocessed leftover log '%s' -> '%s' ",
+			               ll.filename.data(), rotation_path.data());
 			}
 		catch ( InterpreterException& e )
 			{
-			reporter->Info("Postprocess function '%s' failed for leftover log '%s'",
-			               ppf, ll.filename.data());
+			reporter->Warning("Postprocess function '%s' failed for leftover log '%s'",
+			                  ppf->Name(), ll.filename.data());
 			}
 		}
 	}

src/zeek-setup.cc

@@ -643,6 +643,7 @@ zeek::detail::SetupResult zeek::detail::setup(int argc, char** argv,
 		exit(1);
 
 	iosource_mgr->InitPostScript();
+	log_mgr->InitPostScript();
 	plugin_mgr->InitPostScript();
 	zeekygen_mgr->InitPostScript();
 	broker_mgr->InitPostScript();