From a06ef66edc00a4a7c99c3fe7871beb3bf6bbda70 Mon Sep 17 00:00:00 2001 From: Jon Siwek Date: Sat, 27 Jun 2020 22:43:37 -0700 Subject: [PATCH] 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). --- .../base/frameworks/cluster/nodes/logger.zeek | 20 +++- .../frameworks/cluster/nodes/manager.zeek | 2 + .../base/frameworks/cluster/nodes/proxy.zeek | 2 + .../base/frameworks/cluster/nodes/worker.zeek | 2 + scripts/base/frameworks/logging/main.zeek | 88 +++++++++++++++ .../frameworks/logging/writers/ascii.zeek | 24 ----- src/logging/Manager.cc | 89 ++++++++++++--- src/logging/Manager.h | 32 +++--- src/logging/logging.bif | 1 + src/logging/writers/ascii/Ascii.cc | 89 ++++++++------- src/zeek-setup.cc | 1 + testing/btest/Baseline/plugins.hooks/output | 17 +-- .../.stderr | 0 .../out | 90 ++++++++++++++++ .../test.custom-dir.log | 1 + .../test.default.log | 1 + .../test.zip-in-flight-custom-ext.log | 1 + .../test.zip-in-flight.log | 1 + .../logging/rotate-custom-fmt-func.zeek | 49 +++++++++ .../config-cluster-leftover-log-archival.zeek | 16 +-- .../config-cluster-log-archival.zeek | 102 ++++++++++++++++++ 21 files changed, 510 insertions(+), 118 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/.stderr create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/out create mode 100644 testing/btest/Baseline/supervisor.config-cluster-log-archival/test.custom-dir.log create mode 100644 testing/btest/Baseline/supervisor.config-cluster-log-archival/test.default.log create mode 100644 testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight-custom-ext.log create mode 100644 testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight.log create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-custom-fmt-func.zeek create mode 100644 testing/btest/supervisor/config-cluster-log-archival.zeek diff --git a/scripts/base/frameworks/cluster/nodes/logger.zeek b/scripts/base/frameworks/cluster/nodes/logger.zeek index a56d4a4d66..baaa9666eb 100644 --- a/scripts/base/frameworks/cluster/nodes/logger.zeek +++ b/scripts/base/frameworks/cluster/nodes/logger.zeek @@ -22,8 +22,24 @@ redef Log::default_rotation_interval = 1 hrs; ## Alarm summary mail interval. redef Log::default_mail_alarms_interval = 24 hrs; -## Use the cluster's archive logging script. +@if ( Supervisor::is_supervised() ) -@if ( ! Supervisor::is_supervised() ) +redef Log::default_rotation_dir = "log-queue"; + +function supervisor_rotation_format_func(ri: Log::RotationFmtInfo): Log::RotationPath + { + local open_str = strftime(Log::default_rotation_date_format, ri$open); + local close_str = strftime(Log::default_rotation_date_format, ri$open); + local prefix = fmt("%s__%s__%s__", ri$path, open_str, close_str); + local rval = Log::RotationPath($file_prefix=prefix); + return rval; + } + +redef Log::rotation_format_func = supervisor_rotation_format_func; + +@else + +## Use the cluster's archive logging script. redef Log::default_rotation_postprocessor_cmd = "archive-log"; + @endif diff --git a/scripts/base/frameworks/cluster/nodes/manager.zeek b/scripts/base/frameworks/cluster/nodes/manager.zeek index 945d952f31..53e3e52298 100644 --- a/scripts/base/frameworks/cluster/nodes/manager.zeek +++ b/scripts/base/frameworks/cluster/nodes/manager.zeek @@ -19,5 +19,7 @@ redef Log::enable_remote_logging = T; ## Log rotation interval. redef Log::default_rotation_interval = 24 hrs; +@if ( ! Supervisor::is_supervised() ) ## Use the cluster's delete-log script. redef Log::default_rotation_postprocessor_cmd = "delete-log"; +@endif diff --git a/scripts/base/frameworks/cluster/nodes/proxy.zeek b/scripts/base/frameworks/cluster/nodes/proxy.zeek index dec0d69f6b..1e01a865c8 100644 --- a/scripts/base/frameworks/cluster/nodes/proxy.zeek +++ b/scripts/base/frameworks/cluster/nodes/proxy.zeek @@ -13,6 +13,8 @@ redef Log::enable_remote_logging = T; redef Log::default_rotation_interval = 24hrs; +@if ( ! Supervisor::is_supervised() ) ## Use the cluster's delete-log script. redef Log::default_rotation_postprocessor_cmd = "delete-log"; +@endif diff --git a/scripts/base/frameworks/cluster/nodes/worker.zeek b/scripts/base/frameworks/cluster/nodes/worker.zeek index 02c22fb127..73c1edfb6d 100644 --- a/scripts/base/frameworks/cluster/nodes/worker.zeek +++ b/scripts/base/frameworks/cluster/nodes/worker.zeek @@ -12,8 +12,10 @@ redef Log::enable_remote_logging = T; redef Log::default_rotation_interval = 24hrs; +@if ( ! Supervisor::is_supervised() ) ## Use the cluster's delete-log script. redef Log::default_rotation_postprocessor_cmd = "delete-log"; +@endif @load misc/trim-trace-file ## Record all packets into trace file. diff --git a/scripts/base/frameworks/logging/main.zeek b/scripts/base/frameworks/logging/main.zeek index 924fecd498..7b9f1b493f 100644 --- a/scripts/base/frameworks/logging/main.zeek +++ b/scripts/base/frameworks/logging/main.zeek @@ -119,6 +119,21 @@ export { terminating: bool; ##< True if rotation occured due to Zeek shutting down. }; + ## The function type for log rotation post processors. + type RotationPostProcessorFunc: function(info: Log::RotationInfo): bool; + + ## Information passed into rotation format callback function given by + ## :zeek:see:`Log::rotation_format_func`. + type RotationFmtInfo: record { + writer: Writer; ##< The log writer being used. + path: string; ##< Original path value. + open: time; ##< Time when opened. + close: time; ##< Time when closed. + terminating: bool; ##< True if rotation occurred due to Zeek shutting down. + ## The postprocessor function that will be called after rotation. + postprocessor: RotationPostProcessorFunc &optional; + }; + ## Default rotation interval to use for filters that do not specify ## an interval. Zero disables rotation. ## @@ -126,6 +141,40 @@ export { ## option. const default_rotation_interval = 0secs &redef; + ## Default rotation directory to use for the *dir* field of + ## :zeek:see:`Log::RotationPath` during calls to + ## :zeek:see:`Log::rotation_format_func`. An empty string implies + ## using the current working directory; + option default_rotation_dir = ""; + + ## A log file rotation path specification that's returned by the + ## user-customizable :zeek:see:`Log::rotation_format_func`. + type RotationPath: record { + ## A directory to rotate the log to. This directory is created + ## just-in-time, as the log rotation is about to happen. If it + ## cannot be created, an error is emitted and the rotation process + ## tries to proceed with rotation inside the working directory. When + ## setting this field, beware that renaming files across systems will + ## generally fail. + dir: string &default = default_rotation_dir; + + ## A prefix to use for the the rotated log. Log writers may later + ## append a file extension of their choosing to this user-chosen + ## prefix (e.g. if using the default ASCII writer and you want + ## rotated files of the format "foo-.log", then this prefix + ## can be set to "foo-" and the ".log" is added later (there's + ## also generally means of customizing the file extension, too, + ## like the ``ZEEK_LOG_SUFFIX`` environment variable or + ## writer-dependent configuration options. + file_prefix: string; + }; + + ## A function that one may use to customize log file rotation paths. + ## Note that the "fname" field of the *ri* argument is always an + ## empty string for the purpose of this function call (i.e. the full + ## file name is not determined yet). + const rotation_format_func: function(ri: RotationFmtInfo): RotationPath &redef; + ## Default naming format for timestamps embedded into filenames. ## Uses a ``strftime()`` style. const default_rotation_date_format = "%Y-%m-%d-%H-%M-%S" &redef; @@ -556,6 +605,45 @@ function run_rotation_postprocessor_cmd(info: RotationInfo, npath: string) : boo return T; } +# Default function to postprocess a rotated ASCII log file. It simply +# runs the writer's default postprocessor command on it. +function default_ascii_rotation_postprocessor_func(info: Log::RotationInfo): bool + { + # Run default postprocessor. + return Log::run_rotation_postprocessor_cmd(info, info$fname); + } + +redef Log::default_rotation_postprocessors += { + [Log::WRITER_ASCII] = default_ascii_rotation_postprocessor_func +}; + +function Log::rotation_format_func(ri: Log::RotationFmtInfo): Log::RotationPath + { + local rval: Log::RotationPath; + local open_str: string; + + # The reason for branching here is historical: + # the default format path before the intro of Log::rotation_format_func + # always separated the path from open-time using a '-', but ASCII's + # default postprocessor chose to rename using a '.' separaor. It also + # chose a different date format. + if ( ri$postprocessor == __default_rotation_postprocessor && + ri$writer == WRITER_ASCII && + ri$writer in default_rotation_postprocessors && + default_rotation_postprocessors[WRITER_ASCII] == default_ascii_rotation_postprocessor_func) + { + open_str = strftime(Log::default_rotation_date_format, ri$open); + rval = RotationPath($file_prefix=fmt("%s.%s", ri$path, open_str)); + } + else + { + open_str = strftime("%y-%m-%d_%H.%M.%S", ri$open); + rval = RotationPath($file_prefix=fmt("%s-%s", ri$path, open_str)); + } + + return rval; + } + function create_stream(id: ID, stream: Stream) : bool { if ( ! __create_stream(id, stream) ) diff --git a/scripts/base/frameworks/logging/writers/ascii.zeek b/scripts/base/frameworks/logging/writers/ascii.zeek index b9d89eb2a2..789d6d59af 100644 --- a/scripts/base/frameworks/logging/writers/ascii.zeek +++ b/scripts/base/frameworks/logging/writers/ascii.zeek @@ -86,27 +86,3 @@ export { ## This option is also available as a per-filter ``$config`` option. const unset_field = Log::unset_field &redef; } - -# Default function to postprocess a rotated ASCII log file. It moves the rotated -# file to a new name that includes a timestamp with the opening time, and then -# runs the writer's default postprocessor command on it. -function default_rotation_postprocessor_func(info: Log::RotationInfo) : bool - { - # If the filename has a ".gz" extension, then keep it. - local gz = info$fname[-3:] == ".gz" ? ".gz" : ""; - local bls = getenv("ZEEK_LOG_SUFFIX"); - - if ( bls == "" ) - bls = "log"; - - # Move file to name including both opening and closing time. - local dst = fmt("%s.%s.%s%s", info$path, - strftime(Log::default_rotation_date_format, info$open), bls, gz); - - system(fmt("/bin/mv %s %s", info$fname, dst)); - - # Run default postprocessor. - return Log::run_rotation_postprocessor_cmd(info, dst); - } - -redef Log::default_rotation_postprocessors += { [Log::WRITER_ASCII] = default_rotation_postprocessor_func }; diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index 4321672d8b..d5f57ddf7d 100644 --- a/src/logging/Manager.cc +++ b/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(path.size()), path.data(), rot_str.data()); + auto ri = zeek::make_intrusive(zeek::BifType::Record::Log::RotationFmtInfo); + ri->Assign(0, std::move(writer)); + ri->Assign(2, open); + ri->Assign(1, path.size(), path.data()); + ri->Assign(3, close); + ri->Assign(4, zeek::val_mgr->Bool(terminating)); + ri->Assign(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(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(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(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::BifType::Record::Log::RotationInfo); info->Assign(0, {zeek::NewRef{}, winfo->type}); info->Assign(1, zeek::make_intrusive(new_name)); @@ -1543,13 +1603,12 @@ bool Manager::FinishedRotation(WriterFrontend* writer, const char* new_name, con info->Assign(4, zeek::make_intrusive(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); diff --git a/src/logging/Manager.h b/src/logging/Manager.h index 99d2105ecc..cc796069d6 100644 --- a/src/logging/Manager.h +++ b/src/logging/Manager.h @@ -4,7 +4,6 @@ #pragma once -#include #include #include "../Val.h" @@ -30,18 +29,6 @@ class RotationFinishedMessage; class Manager : public plugin::ComponentManager { 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 streams; // Indexed by stream enum. int rotations_pending; // Number of rotations not yet finished. + zeek::FuncPtr rotation_format_func; }; } diff --git a/src/logging/logging.bif b/src/logging/logging.bif index 07a701e6e4..eb2d8c6efc 100644 --- a/src/logging/logging.bif +++ b/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, diff --git a/src/logging/writers/ascii/Ascii.cc b/src/logging/writers/ascii/Ascii.cc index 94d6e7490d..de3c89f6be 100644 --- a/src/logging/writers/ascii/Ascii.cc +++ b/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("Log::RotationInfo"); + static auto writer_type = zeek::id::find_type("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(rot_info_type); + rot_info->Assign(0, writer_val); + rot_info->Assign(1, rotation_path); + rot_info->Assign(2, ll.Name()); + rot_info->Assign(3, ll.open_time); + rot_info->Assign(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("Log::RotationInfo"); - static auto writer_type = zeek::id::find_type("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(rt); - info->Assign(0, writer_val); - info->Assign(1, make_intrusive(ll.RotationPath())); - info->Assign(2, make_intrusive(ll.Name())); - info->Assign(3, make_intrusive(ll.open_time)); - info->Assign(4, make_intrusive(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()); } } } diff --git a/src/zeek-setup.cc b/src/zeek-setup.cc index 3198bf3180..7000f2c859 100644 --- a/src/zeek-setup.cc +++ b/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(); diff --git a/testing/btest/Baseline/plugins.hooks/output b/testing/btest/Baseline/plugins.hooks/output index fa53153c0c..61769c9574 100644 --- a/testing/btest/Baseline/plugins.hooks/output +++ b/testing/btest/Baseline/plugins.hooks/output @@ -282,7 +282,7 @@ 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> -0.000000 MetaHookPost CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) -> +0.000000 MetaHookPost CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T])) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Broker::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Cluster::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Config::LOG)) -> @@ -463,7 +463,7 @@ 0.000000 MetaHookPost CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> 0.000000 MetaHookPost CallFunction(Log::create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> 0.000000 MetaHookPost CallFunction(Log::create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> -0.000000 MetaHookPost CallFunction(Log::write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) -> +0.000000 MetaHookPost CallFunction(Log::write, , (PacketFilter::LOG, [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T])) -> 0.000000 MetaHookPost CallFunction(NetControl::check_plugins, , ()) -> 0.000000 MetaHookPost CallFunction(NetControl::init, , ()) -> 0.000000 MetaHookPost CallFunction(Notice::want_pp, , ()) -> @@ -499,6 +499,7 @@ 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (Input::default_mode, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (Input::default_reader, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (KRB::ignored_errors, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> +0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (Log::default_rotation_dir, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (MQTT::max_payload_size, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (NetControl::default_priority, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> 0.000000 MetaHookPost CallFunction(Option::set_change_handler, , (Notice::alarmed_types, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) -> @@ -1204,7 +1205,7 @@ 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -0.000000 MetaHookPre CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) +0.000000 MetaHookPre CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T])) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Broker::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Cluster::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Config::LOG)) @@ -1385,7 +1386,7 @@ 0.000000 MetaHookPre CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) 0.000000 MetaHookPre CallFunction(Log::create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) 0.000000 MetaHookPre CallFunction(Log::create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -0.000000 MetaHookPre CallFunction(Log::write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) +0.000000 MetaHookPre CallFunction(Log::write, , (PacketFilter::LOG, [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T])) 0.000000 MetaHookPre CallFunction(NetControl::check_plugins, , ()) 0.000000 MetaHookPre CallFunction(NetControl::init, , ()) 0.000000 MetaHookPre CallFunction(Notice::want_pp, , ()) @@ -1421,6 +1422,7 @@ 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (Input::default_mode, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (Input::default_reader, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (KRB::ignored_errors, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) +0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (Log::default_rotation_dir, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (MQTT::max_payload_size, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (NetControl::default_priority, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) 0.000000 MetaHookPre CallFunction(Option::set_change_handler, , (Notice::alarmed_types, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100)) @@ -2125,7 +2127,7 @@ 0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]) 0.000000 | HookCallFunction Log::__create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]) 0.000000 | HookCallFunction Log::__create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]) -0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T]) +0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T]) 0.000000 | HookCallFunction Log::add_default_filter(Broker::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Cluster::LOG) 0.000000 | HookCallFunction Log::add_default_filter(Config::LOG) @@ -2306,7 +2308,7 @@ 0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]) 0.000000 | HookCallFunction Log::create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]) 0.000000 | HookCallFunction Log::create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]) -0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T]) +0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T]) 0.000000 | HookCallFunction NetControl::check_plugins() 0.000000 | HookCallFunction NetControl::init() 0.000000 | HookCallFunction Notice::want_pp() @@ -2342,6 +2344,7 @@ 0.000000 | HookCallFunction Option::set_change_handler(Input::default_mode, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) 0.000000 | HookCallFunction Option::set_change_handler(Input::default_reader, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) 0.000000 | HookCallFunction Option::set_change_handler(KRB::ignored_errors, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) +0.000000 | HookCallFunction Option::set_change_handler(Log::default_rotation_dir, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) 0.000000 | HookCallFunction Option::set_change_handler(MQTT::max_payload_size, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) 0.000000 | HookCallFunction Option::set_change_handler(NetControl::default_priority, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) 0.000000 | HookCallFunction Option::set_change_handler(Notice::alarmed_types, Config::config_option_changed{ Config::log = (coerce [$ts=network_time(), $id=Config::ID, $old_value=Config::format_value(lookup_ID(Config::ID)), $new_value=Config::format_value(Config::new_value)] to Config::Info)if ( != Config::location) Config::log$location = Config::locationLog::write(Config::LOG, Config::log)return (Config::new_value)}, -100) @@ -2759,7 +2762,7 @@ 0.000000 | HookLoadFile base<...>/xmpp 0.000000 | HookLoadFile base<...>/zeek.bif.zeek 0.000000 | HookLogInit packet_filter 1/1 {ts (time), node (string), filter (string), init (bool), success (bool)} -0.000000 | HookLogWrite packet_filter [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T] +0.000000 | HookLogWrite packet_filter [ts=1594172474.563824, node=zeek, filter=ip or not ip, init=T, success=T] 0.000000 | HookQueueEvent NetControl::init() 0.000000 | HookQueueEvent filter_change_tracking() 0.000000 | HookQueueEvent zeek_init() diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/.stderr b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/.stderr new file mode 100644 index 0000000000..e69de29bb2 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/out new file mode 100644 index 0000000000..5df962dda3 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-custom-fmt-func/out @@ -0,0 +1,90 @@ +1st test__2011-03-07-03-00-05__2011-03-07-03-00-05__.log test 11-03-07_03.00.05 11-03-07_04.00.05 0 ascii +1st test__2011-03-07-04-00-05__2011-03-07-04-00-05__.log test 11-03-07_04.00.05 11-03-07_05.00.05 0 ascii +1st test__2011-03-07-05-00-05__2011-03-07-05-00-05__.log test 11-03-07_05.00.05 11-03-07_06.00.05 0 ascii +1st test__2011-03-07-06-00-05__2011-03-07-06-00-05__.log test 11-03-07_06.00.05 11-03-07_07.00.05 0 ascii +1st test__2011-03-07-07-00-05__2011-03-07-07-00-05__.log test 11-03-07_07.00.05 11-03-07_08.00.05 0 ascii +1st test__2011-03-07-08-00-05__2011-03-07-08-00-05__.log test 11-03-07_08.00.05 11-03-07_09.00.05 0 ascii +1st test__2011-03-07-09-00-05__2011-03-07-09-00-05__.log test 11-03-07_09.00.05 11-03-07_10.00.05 0 ascii +1st test__2011-03-07-10-00-05__2011-03-07-10-00-05__.log test 11-03-07_10.00.05 11-03-07_11.00.05 0 ascii +1st test__2011-03-07-11-00-05__2011-03-07-11-00-05__.log test 11-03-07_11.00.05 11-03-07_12.00.05 0 ascii +1st test__2011-03-07-12-00-05__2011-03-07-12-00-05__.log test 11-03-07_12.00.05 11-03-07_12.59.55 1 ascii +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-03-00-05__2011-03-07-03-00-05__.log, path=test2, open=1299466805.0, close=1299470395.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-03-59-55__2011-03-07-03-59-55__.log, path=test2, open=1299470395.0, close=1299470405.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-04-00-05__2011-03-07-04-00-05__.log, path=test2, open=1299470405.0, close=1299473995.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-04-59-55__2011-03-07-04-59-55__.log, path=test2, open=1299473995.0, close=1299474005.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-05-00-05__2011-03-07-05-00-05__.log, path=test2, open=1299474005.0, close=1299477595.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-05-59-55__2011-03-07-05-59-55__.log, path=test2, open=1299477595.0, close=1299477605.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-06-00-05__2011-03-07-06-00-05__.log, path=test2, open=1299477605.0, close=1299481195.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-06-59-55__2011-03-07-06-59-55__.log, path=test2, open=1299481195.0, close=1299481205.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-07-00-05__2011-03-07-07-00-05__.log, path=test2, open=1299481205.0, close=1299484795.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-07-59-55__2011-03-07-07-59-55__.log, path=test2, open=1299484795.0, close=1299484805.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-08-00-05__2011-03-07-08-00-05__.log, path=test2, open=1299484805.0, close=1299488395.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-08-59-55__2011-03-07-08-59-55__.log, path=test2, open=1299488395.0, close=1299488405.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-09-00-05__2011-03-07-09-00-05__.log, path=test2, open=1299488405.0, close=1299491995.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-09-59-55__2011-03-07-09-59-55__.log, path=test2, open=1299491995.0, close=1299492005.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-10-00-05__2011-03-07-10-00-05__.log, path=test2, open=1299492005.0, close=1299495595.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-10-59-55__2011-03-07-10-59-55__.log, path=test2, open=1299495595.0, close=1299495605.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-11-00-05__2011-03-07-11-00-05__.log, path=test2, open=1299495605.0, close=1299499195.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-11-59-55__2011-03-07-11-59-55__.log, path=test2, open=1299499195.0, close=1299499205.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-12-00-05__2011-03-07-12-00-05__.log, path=test2, open=1299499205.0, close=1299502795.0, terminating=F] +custom rotate, [writer=Log::WRITER_ASCII, fname=test2__2011-03-07-12-59-55__2011-03-07-12-59-55__.log, path=test2, open=1299502795.0, close=1299502795.0, terminating=T] +#close XXXX-XX-XX-XX-XX-XX +#empty_field (empty) +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#open XXXX-XX-XX-XX-XX-XX +#path test +#path test2 +#separator \x09 +#set_separator , +#types time addr port addr port +#unset_field - +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1024 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 0 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1025 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 1 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1026 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 2 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1027 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 3 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1028 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 4 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1029 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 5 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1030 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 6 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1031 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 7 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1032 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 8 +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1033 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 9 +> test2__2011-03-07-03-00-05__2011-03-07-03-00-05__.log +> test2__2011-03-07-03-59-55__2011-03-07-03-59-55__.log +> test2__2011-03-07-04-00-05__2011-03-07-04-00-05__.log +> test2__2011-03-07-04-59-55__2011-03-07-04-59-55__.log +> test2__2011-03-07-05-00-05__2011-03-07-05-00-05__.log +> test2__2011-03-07-05-59-55__2011-03-07-05-59-55__.log +> test2__2011-03-07-06-00-05__2011-03-07-06-00-05__.log +> test2__2011-03-07-06-59-55__2011-03-07-06-59-55__.log +> test2__2011-03-07-07-00-05__2011-03-07-07-00-05__.log +> test2__2011-03-07-07-59-55__2011-03-07-07-59-55__.log +> test2__2011-03-07-08-00-05__2011-03-07-08-00-05__.log +> test2__2011-03-07-08-59-55__2011-03-07-08-59-55__.log +> test2__2011-03-07-09-00-05__2011-03-07-09-00-05__.log +> test2__2011-03-07-09-59-55__2011-03-07-09-59-55__.log +> test2__2011-03-07-10-00-05__2011-03-07-10-00-05__.log +> test2__2011-03-07-10-59-55__2011-03-07-10-59-55__.log +> test2__2011-03-07-11-00-05__2011-03-07-11-00-05__.log +> test2__2011-03-07-11-59-55__2011-03-07-11-59-55__.log +> test2__2011-03-07-12-00-05__2011-03-07-12-00-05__.log +> test2__2011-03-07-12-59-55__2011-03-07-12-59-55__.log +> test__2011-03-07-03-00-05__2011-03-07-03-00-05__.log +> test__2011-03-07-04-00-05__2011-03-07-04-00-05__.log +> test__2011-03-07-05-00-05__2011-03-07-05-00-05__.log +> test__2011-03-07-06-00-05__2011-03-07-06-00-05__.log +> test__2011-03-07-07-00-05__2011-03-07-07-00-05__.log +> test__2011-03-07-08-00-05__2011-03-07-08-00-05__.log +> test__2011-03-07-09-00-05__2011-03-07-09-00-05__.log +> test__2011-03-07-10-00-05__2011-03-07-10-00-05__.log +> test__2011-03-07-11-00-05__2011-03-07-11-00-05__.log +> test__2011-03-07-12-00-05__2011-03-07-12-00-05__.log diff --git a/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.custom-dir.log b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.custom-dir.log new file mode 100644 index 0000000000..de2fed6998 --- /dev/null +++ b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.custom-dir.log @@ -0,0 +1 @@ +{"s":"test"} diff --git a/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.default.log b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.default.log new file mode 100644 index 0000000000..de2fed6998 --- /dev/null +++ b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.default.log @@ -0,0 +1 @@ +{"s":"test"} diff --git a/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight-custom-ext.log b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight-custom-ext.log new file mode 100644 index 0000000000..de2fed6998 --- /dev/null +++ b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight-custom-ext.log @@ -0,0 +1 @@ +{"s":"test"} diff --git a/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight.log b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight.log new file mode 100644 index 0000000000..de2fed6998 --- /dev/null +++ b/testing/btest/Baseline/supervisor.config-cluster-log-archival/test.zip-in-flight.log @@ -0,0 +1 @@ +{"s":"test"} diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-custom-fmt-func.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-custom-fmt-func.zeek new file mode 100644 index 0000000000..3c1831c562 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-custom-fmt-func.zeek @@ -0,0 +1,49 @@ +# @TEST-EXEC: zeek -b -r ${TRACES}/rotation.trace %INPUT | egrep "test|test2" | sort >out.tmp +# @TEST-EXEC: cat out.tmp pp.log | sort >out +# @TEST-EXEC: for i in `ls test*.log | sort`; do printf '> %s\n' $i; cat $i; done | sort | $SCRIPTS/diff-remove-timestamps | uniq >>out +# @TEST-EXEC: btest-diff out +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-sort btest-diff .stderr + +module Test; + +export { + # Create a new ID for our log stream + redef enum Log::ID += { LOG }; + + # Define a record with all the columns the log file can have. + # (I'm using a subset of fields from ssh-ext for demonstration.) + type Log: record { + t: time; + id: conn_id; # Will be rolled out into individual columns. + } &log; +} + +function my_rotation_format_func(ri: Log::RotationFmtInfo): Log::RotationPath + { + local open_str = strftime(Log::default_rotation_date_format, ri$open); + local close_str = strftime(Log::default_rotation_date_format, ri$open); + local prefix =fmt("%s__%s__%s__", ri$path, open_str, close_str); + local rval = Log::RotationPath($file_prefix=prefix); + return rval; + } + +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo 1st >>pp.log"; +redef Log::rotation_format_func = my_rotation_format_func; + +function custom_rotate(info: Log::RotationInfo) : bool + { + print "custom rotate", info; + return T; + } + +event zeek_init() + { + Log::create_stream(Test::LOG, [$columns=Log]); + Log::add_filter(Test::LOG, [$name="2nd", $path="test2", $interv=30mins, $postprocessor=custom_rotate]); + } + +event new_connection(c: connection) + { + Log::write(Test::LOG, [$t=network_time(), $id=c$id]); + } diff --git a/testing/btest/supervisor/config-cluster-leftover-log-archival.zeek b/testing/btest/supervisor/config-cluster-leftover-log-archival.zeek index 900bb2cd9f..1616899c92 100644 --- a/testing/btest/supervisor/config-cluster-leftover-log-archival.zeek +++ b/testing/btest/supervisor/config-cluster-leftover-log-archival.zeek @@ -4,16 +4,14 @@ # Test default leftover log rotation/archival behavior # @TEST-EXEC: btest-bg-run zeek zeek -j -b %INPUT # @TEST-EXEC: btest-bg-wait 45 - -# @TEST-EXEC: cp zeek/logger-1/test*.log test.default.log +# @TEST-EXEC: cp zeek/logger-1/log-queue/test*.log test.default.log # @TEST-EXEC: btest-diff test.default.log # @TEST-EXEC: rm -rf ./zeek # Test leftover log rotation/archival behavior with custom postprocessor func # @TEST-EXEC: btest-bg-run zeek zeek -j -b %INPUT use_custom_postproc=T # @TEST-EXEC: btest-bg-wait 45 - -# @TEST-EXEC: cp zeek/logger-1/test*.log test.postproc.log +# @TEST-EXEC: cp zeek/logger-1/log-queue/test*.log test.postproc.log # @TEST-EXEC: btest-diff test.postproc.log # @TEST-EXEC: btest-diff zeek/logger-1/postproc.out # @TEST-EXEC: rm -rf ./zeek @@ -37,17 +35,13 @@ export { } module GLOBAL; -module LogAscii; -export { function my_rotation_postprocessor(info: Log::RotationInfo) : bool { local f = open("postproc.out"); print f, "running my rotation postprocessor"; close(f); - return LogAscii::default_rotation_postprocessor_func(info); + return T; } -} -module GLOBAL; event zeek_init() { @@ -56,7 +50,7 @@ event zeek_init() if ( use_custom_postproc ) { local df = Log::get_filter(Test::LOG, "default"); - df$postprocessor = LogAscii::my_rotation_postprocessor; + df$postprocessor = my_rotation_postprocessor; Log::add_filter(Test::LOG, df); } @@ -86,7 +80,7 @@ event zeek_init() print sf, ".log"; if ( use_custom_postproc ) - print sf, "LogAscii::my_rotation_postprocessor"; + print sf, "my_rotation_postprocessor"; else print sf, ""; diff --git a/testing/btest/supervisor/config-cluster-log-archival.zeek b/testing/btest/supervisor/config-cluster-log-archival.zeek new file mode 100644 index 0000000000..290e58d930 --- /dev/null +++ b/testing/btest/supervisor/config-cluster-log-archival.zeek @@ -0,0 +1,102 @@ + +# @TEST-PORT: SUPERVISOR_PORT +# @TEST-PORT: LOGGER_PORT + +# Test default log rotation/archival behavior (rotate into log-queue dir) +# @TEST-EXEC: btest-bg-run zeek zeek -j -b %INPUT +# @TEST-EXEC: btest-bg-wait 45 +# @TEST-EXEC: cp zeek/logger-1/log-queue/test*.log test.default.log +# @TEST-EXEC: btest-diff test.default.log +# @TEST-EXEC: rm -rf ./zeek + +# Test rotation/archival behavior with in-flight compression +# @TEST-EXEC: btest-bg-run zeek zeek -j -b LogAscii::gzip_level=1 %INPUT +# @TEST-EXEC: btest-bg-wait 45 +# @TEST-EXEC: gunzip -c zeek/logger-1/log-queue/test*.log.gz > test.zip-in-flight.log +# @TEST-EXEC: btest-diff test.zip-in-flight.log +# @TEST-EXEC: rm -rf ./zeek + +# Test rotation/archival behavior with in-flight compression + custom file extension +# @TEST-EXEC: btest-bg-run zeek zeek -j -b LogAscii::gzip_level=1 LogAscii::gzip_file_extension="mygz" %INPUT +# @TEST-EXEC: btest-bg-wait 45 +# @TEST-EXEC: cp zeek/logger-1/log-queue/test*.log.mygz test.log.gz +# @TEST-EXEC: gunzip -c test.log.gz > test.zip-in-flight-custom-ext.log +# @TEST-EXEC: btest-diff test.zip-in-flight-custom-ext.log +# @TEST-EXEC: rm -rf ./zeek + +# Test rotation/archival behavior with a custom rotation dir +# @TEST-EXEC: btest-bg-run zeek zeek -j -b %INPUT Log::default_rotation_dir=my-logs +# @TEST-EXEC: btest-bg-wait 45 +# @TEST-EXEC: cp zeek/logger-1/my-logs/test*.log test.custom-dir.log +# @TEST-EXEC: btest-diff test.custom-dir.log +# @TEST-EXEC: rm -rf ./zeek + +@load base/frameworks/cluster + +# JSON for log file brevity. +redef LogAscii::use_json=T; + +global topic = "test-topic"; + +module Test; +export { + redef enum Log::ID += { LOG }; + + type Log: record { + s: string; + } &log; +} +module GLOBAL; + +event pong() + { + terminate(); + } + +event ping() + { + Log::write(Test::LOG, [$s="test"]); + Broker::publish(topic, pong); + } + +event zeek_init() + { + Log::create_stream(Test::LOG, [$columns=Test::Log]); + + if ( Supervisor::is_supervisor() ) + { + Broker::subscribe(topic); + Broker::listen("127.0.0.1", to_port(getenv("SUPERVISOR_PORT"))); + Broker::peer("127.0.0.1", to_port(getenv("LOGGER_PORT"))); + + local cluster: table[string] of Supervisor::ClusterEndpoint; + cluster["logger-1"] = [$role=Supervisor::LOGGER, $host=127.0.0.1, + $p=to_port(getenv("LOGGER_PORT"))]; + + for ( n, ep in cluster ) + { + local sn = Supervisor::NodeConfig($name = n); + sn$cluster = cluster; + sn$directory = n; + local res = Supervisor::create(sn); + + if ( res != "" ) + print fmt("failed to create node %s: %s", n, res); + } + } + else + { + Broker::subscribe(topic); + Broker::peer("127.0.0.1", to_port(getenv("SUPERVISOR_PORT"))); + } + } + +event Broker::peer_added(endpoint: Broker::EndpointInfo, msg: string) + { + if ( Supervisor::is_supervisor() ) + Broker::publish(topic, ping); + } + +event Broker::peer_lost(endpoint: Broker::EndpointInfo, msg: string) + { + }