From 513ea7e04f4f6a7895c25b36722ad81875dbb491 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 29 Jun 2022 12:59:06 +0200 Subject: [PATCH 1/4] logging/ascii: Fix .shadow paths when using LogAscii::logdir With the introduction of LogAscii::logdir, log filenames can now include parent directories rather than being plain basenames. Enabling log rotation, leftover log rotation and setting LogAscii::logdir broke due to not handling this situation. This change ensures that .shadow files are placed within the directory where the respective .log file is created. Previously, the .shadow. (or .tmp.shadow.) prefix was simply prepended, yielding non-sensical paths such as .tmp.shadow.foo/bar/packet_filter.log for a logdir of foo/bar. Additionally, respect LogAscii::logdir when searching for leftover log files rather than defaulting to the current working directory. The following quirk exist around LogAscii::logdir, but will be addressed in a follow-up. * By default, logs are currently rotated into the working directory of the process, rather than staying confined within LogAscii::logdir. One of the added tests shows this behavior. --- src/logging/writers/ascii/Ascii.cc | 83 ++++++----- .../logs.cat | 3 + .../out | 4 + .../out | 1 + .../out | 131 ++++++++++++++++++ .../logs.cat | 3 + .../out | 4 + ...ir-leftover-log-rotation-shadow-files.zeek | 34 +++++ ...tover-log-rotation-stale-shadow-files.zeek | 23 +++ ...te-ascii-logdir-leftover-log-rotation.zeek | 35 +++++ ...te-leftover-log-rotation-shadow-files.zeek | 49 +++++++ 11 files changed, 335 insertions(+), 35 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/logs.cat create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/out create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/logs.cat create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/out create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-shadow-files.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-leftover-log-rotation-shadow-files.zeek diff --git a/src/logging/writers/ascii/Ascii.cc b/src/logging/writers/ascii/Ascii.cc index 7df607a115..82b9bd5bdd 100644 --- a/src/logging/writers/ascii/Ascii.cc +++ b/src/logging/writers/ascii/Ascii.cc @@ -15,11 +15,13 @@ #include #include +#include "zeek/3rdparty/doctest.h" #include "zeek/Func.h" #include "zeek/RunState.h" #include "zeek/logging/Manager.h" #include "zeek/logging/writers/ascii/ascii.bif.h" #include "zeek/threading/SerialTypes.h" +#include "zeek/util.h" using namespace std; using zeek::threading::Field; @@ -38,7 +40,7 @@ namespace zeek::logging::writer::detail struct LeftoverLog { /* - * Name of leftover log, relative to working dir. + * Name of leftover log. */ std::string filename; @@ -83,9 +85,9 @@ struct LeftoverLog /** * Return the "path" (logging framework parlance) of the log without the - * file extension. E.g. the "path" of "conn.log" is just "conn". + * directory or file extension. E.g. the "path" of "logs/conn.log" is just "conn". */ - std::string Path() const { return filename.substr(0, filename.size() - extension.size()); } + std::string Path() const { return zeek::filesystem::path(filename).stem(); } /** * Deletes the shadow file and returns whether it succeeded. @@ -93,9 +95,31 @@ struct LeftoverLog bool DeleteShadow() const { return unlink(shadow_filename.data()) == 0; } }; +/** + * Prefix the basename part of the given path with prefix. + * + * prefix_basename_with("logs/conn.log", ".shadow") -> logs/.shadow.conn.log" + */ +static std::string prefix_basename_with(const std::string& path, const std::string& prefix) + { + auto fspath = zeek::filesystem::path(path); + auto new_filename = prefix + fspath.filename().string(); + return (fspath.parent_path() / new_filename).string(); + } + +TEST_CASE("writers.ascii prefix_basename_with") + { + CHECK(prefix_basename_with("", ".shadow.") == ".shadow."); + CHECK(prefix_basename_with("conn.log", ".shadow.") == ".shadow.conn.log"); + CHECK(prefix_basename_with("/conn.log", ".shadow.") == "/.shadow.conn.log"); + CHECK(prefix_basename_with("a/conn.log", ".shadow.") == "a/.shadow.conn.log"); + CHECK(prefix_basename_with("/a/conn.log", ".shadow.") == "/a/.shadow.conn.log"); + CHECK(prefix_basename_with("a/b/conn.log", ".shadow.") == "a/b/.shadow.conn.log"); + } + static std::optional parse_shadow_log(const std::string& fname) { - auto sfname = shadow_file_prefix + fname; + auto sfname = prefix_basename_with(fname, shadow_file_prefix); LeftoverLog rval; rval.filename = fname; @@ -457,17 +481,7 @@ bool Ascii::DoInit(const WriterInfo& info, int num_fields, const threading::Fiel } if ( fname.front() != '/' && ! logdir.empty() ) - { - string path = logdir; - std::size_t last = path.find_last_not_of('/'); - - if ( last == string::npos ) // Nothing but slashes -- weird but ok... - path = "/"; - else - path.erase(last + 1); - - fname = path + "/" + fname; - } + fname = zeek::filesystem::path(logdir) / fname; fname += ext; @@ -476,8 +490,8 @@ bool Ascii::DoInit(const WriterInfo& info, int num_fields, const threading::Fiel if ( use_shadow ) { - auto sfname = shadow_file_prefix + fname; - auto tmp_sfname = ".tmp" + sfname; + auto sfname = prefix_basename_with(fname, shadow_file_prefix); + auto tmp_sfname = prefix_basename_with(sfname, ".tmp"); auto sfd = open(tmp_sfname.data(), O_WRONLY | O_CREAT | O_TRUNC, 0666); if ( sfd < 0 ) @@ -698,7 +712,7 @@ bool Ascii::DoRotate(const char* rotated_path, double open, double close, bool t if ( use_shadow ) { - auto sfname = shadow_file_prefix + fname; + auto sfname = prefix_basename_with(fname, shadow_file_prefix); if ( unlink(sfname.data()) != 0 ) { @@ -735,21 +749,19 @@ static std::vector find_leftover_logs() std::vector stale_shadow_files; auto prefix_len = strlen(shadow_file_prefix); - auto d = opendir("."); + // Find any .shadow files within LogAscii::logdir if set or + // otherwise search in the current working directory. + auto logdir = zeek::filesystem::current_path(); + if ( BifConst::LogAscii::logdir->Len() > 0 ) + logdir = zeek::filesystem::absolute(BifConst::LogAscii::logdir->ToStdString()); + + auto d = opendir(logdir.c_str()); struct dirent* dp; if ( ! d ) { - char cwd[PATH_MAX]; - - if ( ! getcwd(cwd, sizeof(cwd)) ) - { - cwd[0] = '.'; - cwd[1] = '\0'; - } - - reporter->Error("failed to open directory '%s' in search of leftover logs: %s", cwd, - strerror(errno)); + reporter->Error("failed to open directory '%s' in search of leftover logs: %s", + logdir.c_str(), strerror(errno)); return rval; } @@ -758,27 +770,28 @@ static std::vector find_leftover_logs() if ( strncmp(dp->d_name, shadow_file_prefix, prefix_len) != 0 ) continue; - std::string log_name = dp->d_name + prefix_len; + std::string shadow_fname = logdir / dp->d_name; + std::string log_fname = logdir / (dp->d_name + prefix_len); - if ( util::is_file(log_name) ) + if ( util::is_file(log_fname) ) { - if ( auto ll = parse_shadow_log(log_name) ) + if ( auto ll = parse_shadow_log(log_fname) ) { if ( ll->error.empty() ) rval.emplace_back(std::move(*ll)); else - reporter->Error("failed to process leftover log '%s': %s", log_name.data(), + reporter->Error("failed to process leftover log '%s': %s", log_fname.data(), ll->error.data()); } } else // There was a log here. It's gone now. - stale_shadow_files.emplace_back(dp->d_name); + stale_shadow_files.emplace_back(shadow_fname); } for ( const auto& f : stale_shadow_files ) if ( unlink(f.data()) != 0 ) - reporter->Error("cannot unlink %s: %s", f.data(), strerror(errno)); + reporter->Error("cannot unlink stale %s: %s", f.data(), strerror(errno)); closedir(d); return rval; diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/logs.cat b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/logs.cat new file mode 100644 index 0000000000..05dd1c9670 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/logs.cat @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +leftover conn log +leftover dns log diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/out new file mode 100644 index 0000000000..823cec2fc1 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-shadow-files/out @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +### NOTE: This file has been sorted with diff-sort. +running my rotation postprocessor for path 'conn' +running my rotation postprocessor for path 'dns' diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out new file mode 100644 index 0000000000..2a19abcf36 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out @@ -0,0 +1,131 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +test.2011-03-07-03-00-05.log test 11-03-07_03.00.05 11-03-07_04.00.05 0 ascii +test.2011-03-07-04-00-05.log test 11-03-07_04.00.05 11-03-07_05.00.05 0 ascii +test.2011-03-07-05-00-05.log test 11-03-07_05.00.05 11-03-07_06.00.05 0 ascii +test.2011-03-07-06-00-05.log test 11-03-07_06.00.05 11-03-07_07.00.05 0 ascii +test.2011-03-07-07-00-05.log test 11-03-07_07.00.05 11-03-07_08.00.05 0 ascii +test.2011-03-07-08-00-05.log test 11-03-07_08.00.05 11-03-07_09.00.05 0 ascii +test.2011-03-07-09-00-05.log test 11-03-07_09.00.05 11-03-07_10.00.05 0 ascii +test.2011-03-07-10-00-05.log test 11-03-07_10.00.05 11-03-07_11.00.05 0 ascii +test.2011-03-07-11-00-05.log test 11-03-07_11.00.05 11-03-07_12.00.05 0 ascii +test.2011-03-07-12-00-05.log test 11-03-07_12.00.05 11-03-07_12.59.55 1 ascii +> test.2011-03-07-03-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1024 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 0 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-04-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1025 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 1 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-05-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1026 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 2 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-06-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1027 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 3 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-07-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1028 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 4 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-08-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1029 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 5 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-09-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1030 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 6 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-10-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1031 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 7 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-11-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1032 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 8 +#close XXXX-XX-XX-XX-XX-XX +> test.2011-03-07-12-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1033 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 9 +#close XXXX-XX-XX-XX-XX-XX diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/logs.cat b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/logs.cat new file mode 100644 index 0000000000..05dd1c9670 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/logs.cat @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +leftover conn log +leftover dns log diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/out new file mode 100644 index 0000000000..823cec2fc1 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-leftover-log-rotation-shadow-files/out @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +### NOTE: This file has been sorted with diff-sort. +running my rotation postprocessor for path 'conn' +running my rotation postprocessor for path 'dns' diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-shadow-files.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-shadow-files.zeek new file mode 100644 index 0000000000..9c15dba571 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-shadow-files.zeek @@ -0,0 +1,34 @@ +# @TEST-DOC: Test that .shadow files are picked up from LogAscii::logdir. +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: echo ".log" >> logs/.shadow.conn.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> logs/.shadow.conn.log +# @TEST-EXEC: echo "leftover conn log" > logs/conn.log +# @TEST-EXEC: echo ".log" >> logs/.shadow.dns.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> logs/.shadow.dns.log +# @TEST-EXEC: echo "leftover dns log" > logs/dns.log + +# @TEST-EXEC: zeek -b %INPUT > out + +# @TEST-EXEC: ! test -f logs/.shadow.conn.log +# @TEST-EXEC: ! test -f logs/conn.log +# @TEST-EXEC: ! test -f logs/.shadow.dns.log +# @TEST-EXEC: ! test -f logs/dns.log + +# Ensure rotated logs ends-up in the current working directory: This may change in the future. +# @TEST-EXEC: cat ./conn-*.log ./dns-*.log > logs.cat + +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-sort btest-diff out +# @TEST-EXEC: btest-diff logs.cat + +module GLOBAL; + +function my_rotation_postprocessor(info: Log::RotationInfo) : bool + { + print fmt("running my rotation postprocessor for path '%s'", info$path); + return T; + } + +redef LogAscii::logdir = "./logs"; +redef LogAscii::enable_leftover_log_rotation = T; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek new file mode 100644 index 0000000000..3871849bd9 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek @@ -0,0 +1,23 @@ +# @TEST-DOC: Test that stale .shadow files are removed from LogAscii::logdir. +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: echo ".log" >> logs/.shadow.conn.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> logs/.shadow.conn.log + +# @TEST-EXEC: zeek -b %INPUT > out 2>&1 + +# @TEST-EXEC: ! test -f logs/.shadow.conn.log + +# @TEST-EXEC: btest-diff out + +module GLOBAL; + +function my_rotation_postprocessor(info: Log::RotationInfo) : bool + { + print fmt("running my rotation postprocessor for path '%s'", info$path); + return T; + } + +redef LogAscii::logdir = "./logs"; +redef LogAscii::enable_leftover_log_rotation = T; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek new file mode 100644 index 0000000000..dfdf31d723 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek @@ -0,0 +1,35 @@ +# @TEST-DOC: Enable leftover log rotation and logdir. Note, files are rotated into the cwd. +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: zeek -b -r ${TRACES}/rotation.trace %INPUT >zeek.out 2>&1 +# @TEST-EXEC: grep "test" zeek.out | sort >out +# @TEST-EXEC: for i in `ls test.*.log | sort`; do printf '> %s\n' $i; cat $i; done >>out +# @TEST-EXEC: btest-diff out + +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; +} + +redef LogAscii::logdir = "./logs"; +redef LogAscii::enable_leftover_log_rotation = T; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; + +event zeek_init() + { + Log::create_stream(Test::LOG, [$columns=Log]); + } + +event new_connection(c: connection) + { + Log::write(Test::LOG, [$t=network_time(), $id=c$id]); + } diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-leftover-log-rotation-shadow-files.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-leftover-log-rotation-shadow-files.zeek new file mode 100644 index 0000000000..7024752284 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-leftover-log-rotation-shadow-files.zeek @@ -0,0 +1,49 @@ +# @TEST-DOC: Enable leftover log rotation, put shadow files for conn and dns in the cwd and ensure rotation happens during startup. +# @TEST-EXEC: echo ".log" >> .shadow.conn.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> .shadow.conn.log +# @TEST-EXEC: echo "leftover conn log" > conn.log + +# @TEST-EXEC: echo ".log" >> .shadow.dns.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> .shadow.dns.log +# @TEST-EXEC: echo "leftover dns log" > dns.log + +# @TEST-EXEC: zeek -b %INPUT > out + +# Ensure leftover files were removed. +# @TEST-EXEC: ! test -f .shadow.conn.log +# @TEST-EXEC: ! test -f conn.log +# @TEST-EXEC: ! test -f .shadow.dns.log +# @TEST-EXEC: ! test -f dns.log + +# Ensure the rotated conn log ends-up in the current working directory. +# @TEST-EXEC: ls ./conn-*.log +# @TEST-EXEC: cat ./conn-*.log ./dns-*.log > logs.cat + +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-sort btest-diff out +# @TEST-EXEC: btest-diff logs.cat + +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; +} + +module GLOBAL; + +function my_rotation_postprocessor(info: Log::RotationInfo) : bool + { + print fmt("running my rotation postprocessor for path '%s'", info$path); + return T; + } + +redef LogAscii::enable_leftover_log_rotation = T; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; From aaa47a709cdf4b6182c6472cc1a6c178f7063977 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Thu, 30 Jun 2022 16:07:04 +0200 Subject: [PATCH 2/4] logging: Introduce Log::default_logdir deprecate LogAscii::logdir and per writer logdir Also modify FormatRotationPath to keep rotated logs within Log::default_logdir unless the rotation function explicitly set dir, e.g. by when the user redef'ed default_rotation_interval. --- scripts/base/frameworks/logging/main.zeek | 7 + .../frameworks/logging/writers/ascii.zeek | 5 +- src/logging/Manager.cc | 7 + src/logging/writers/ascii/Ascii.cc | 22 ++- .../out | 1 + .../out | 1 + .../logs.cat | 3 + .../out | 4 + .../out | 1 + .../out | 131 ++++++++++++++++++ ...tover-log-rotation-stale-shadow-files.zeek | 2 +- ...te-ascii-logdir-leftover-log-rotation.zeek | 2 +- ...ir-leftover-log-rotation-shadow-files.zeek | 34 +++++ ...tover-log-rotation-stale-shadow-files.zeek | 23 +++ .../logging/rotate-default-logdir.zeek | 34 +++++ 15 files changed, 272 insertions(+), 5 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/logs.cat create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/out create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-stale-shadow-files/out create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir/out create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-shadow-files.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-stale-shadow-files.zeek create mode 100644 testing/btest/scripts/base/frameworks/logging/rotate-default-logdir.zeek diff --git a/scripts/base/frameworks/logging/main.zeek b/scripts/base/frameworks/logging/main.zeek index 1e611b5d75..43cb2beefe 100644 --- a/scripts/base/frameworks/logging/main.zeek +++ b/scripts/base/frameworks/logging/main.zeek @@ -26,6 +26,13 @@ export { ## Default writer to use if a filter does not specify anything else. const default_writer = WRITER_ASCII &redef; + ## Default logging directory. An empty string implies using the + ## current working directory. + ## This directory is also used for rotated logs in cases where + ## :zeek:see:`Log::rotation_format_func` returns a record with + ## an empty or unset ``dir`` field. + const default_logdir = "" &redef; + ## Default separator to use between fields. ## Individual writers can use a different value. const separator = "\t" &redef; diff --git a/scripts/base/frameworks/logging/writers/ascii.zeek b/scripts/base/frameworks/logging/writers/ascii.zeek index bbeb94c172..32ec65c31f 100644 --- a/scripts/base/frameworks/logging/writers/ascii.zeek +++ b/scripts/base/frameworks/logging/writers/ascii.zeek @@ -57,7 +57,10 @@ export { ## Define the default logging directory. If empty, logs are written ## to the current working directory. ## - const logdir = "" &redef; + ## This setting is superseeded by :zeek:see:`Log::default_logdir`. The + ## latter applies to all file writers and also interacts better with + ## log rotation. + const logdir = "" &redef &deprecated="Remove in v6.1. Use 'Log::default_logdir'."; ## Format of timestamps when writing out JSON. By default, the JSON ## formatter will use double values for timestamps which represent the diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index 9db7235da7..4b1fb07b59 100644 --- a/src/logging/Manager.cc +++ b/src/logging/Manager.cc @@ -1529,6 +1529,13 @@ std::string Manager::FormatRotationPath(EnumValPtr writer, std::string_view path auto prefix = rp_val->GetFieldAs(1)->CheckString(); auto dir = dir_val->AsString()->CheckString(); + // If rotation_format_func returned an empty dir in RotationPath + // and Log::default_logdir is set, use it so that rotation is + // confined within it. + auto default_logdir = zeek::id::find_const("Log::default_logdir")->ToStdString(); + if ( util::streq(dir, "") && ! default_logdir.empty() ) + dir = default_logdir.c_str(); + if ( ! util::streq(dir, "") && ! util::detail::ensure_intermediate_dirs(dir) ) { reporter->Error("Failed to create dir '%s' returned by " diff --git a/src/logging/writers/ascii/Ascii.cc b/src/logging/writers/ascii/Ascii.cc index 82b9bd5bdd..8a703331e2 100644 --- a/src/logging/writers/ascii/Ascii.cc +++ b/src/logging/writers/ascii/Ascii.cc @@ -19,6 +19,7 @@ #include "zeek/Func.h" #include "zeek/RunState.h" #include "zeek/logging/Manager.h" +#include "zeek/logging/logging.bif.h" #include "zeek/logging/writers/ascii/ascii.bif.h" #include "zeek/threading/SerialTypes.h" #include "zeek/util.h" @@ -262,8 +263,13 @@ void Ascii::InitConfigOptions() gzip_file_extension.assign((const char*)BifConst::LogAscii::gzip_file_extension->Bytes(), BifConst::LogAscii::gzip_file_extension->Len()); + // Remove in v6.1: LogAscii::logdir should be gone in favor + // of using Log::default_logdir. logdir.assign((const char*)BifConst::LogAscii::logdir->Bytes(), BifConst::LogAscii::logdir->Len()); + + if ( logdir.empty() ) + logdir = zeek::id::find_const("Log::default_logdir")->ToStdString(); } bool Ascii::InitFilterOptions() @@ -374,7 +380,13 @@ bool Ascii::InitFilterOptions() gzip_file_extension.assign(i->second); else if ( strcmp(i->first, "logdir") == 0 ) + { + // This doesn't play nice with leftover log rotation + // and log rotation in general. There's no documentation + // or a test for this specifically, so deprecate it. + reporter->Warning("Remove in v6.1. Per writer logdir is deprecated."); logdir.assign(i->second); + } } if ( ! InitFormatter() ) @@ -748,10 +760,16 @@ static std::vector find_leftover_logs() std::vector rval; std::vector stale_shadow_files; auto prefix_len = strlen(shadow_file_prefix); + auto default_logdir = zeek::id::find_const("Log::default_logdir")->ToStdString(); - // Find any .shadow files within LogAscii::logdir if set or - // otherwise search in the current working directory. + // Find any .shadow files within LogAscii::logdir, Log::default_logdir + // or otherwise search in the current working directory. auto logdir = zeek::filesystem::current_path(); + + if ( ! default_logdir.empty() ) + logdir = zeek::filesystem::absolute(default_logdir); + + // Remove LogAscii::logdir fallback in v6.1. if ( BifConst::LogAscii::logdir->Len() > 0 ) logdir = zeek::filesystem::absolute(BifConst::LogAscii::logdir->ToStdString()); diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out index 49d861c74c..0f3aae8c56 100644 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files/out @@ -1 +1,2 @@ ### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +warning in <...>/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek, line 20: deprecated (LogAscii::logdir): Remove in v6.1. Use 'Log::default_logdir'. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out index 2a19abcf36..21ba63d2f4 100644 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-ascii-logdir-leftover-log-rotation/out @@ -9,6 +9,7 @@ test.2011-03-07-09-00-05.log test 11-03-07_09.00.05 11-03-07_10.00.05 0 ascii test.2011-03-07-10-00-05.log test 11-03-07_10.00.05 11-03-07_11.00.05 0 ascii test.2011-03-07-11-00-05.log test 11-03-07_11.00.05 11-03-07_12.00.05 0 ascii test.2011-03-07-12-00-05.log test 11-03-07_12.00.05 11-03-07_12.59.55 1 ascii +warning in <...>/rotate-ascii-logdir-leftover-log-rotation.zeek, line 22: deprecated (LogAscii::logdir): Remove in v6.1. Use 'Log::default_logdir'. > test.2011-03-07-03-00-05.log #separator \x09 #set_separator , diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/logs.cat b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/logs.cat new file mode 100644 index 0000000000..05dd1c9670 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/logs.cat @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +leftover conn log +leftover dns log diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/out new file mode 100644 index 0000000000..823cec2fc1 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-shadow-files/out @@ -0,0 +1,4 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +### NOTE: This file has been sorted with diff-sort. +running my rotation postprocessor for path 'conn' +running my rotation postprocessor for path 'dns' diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-stale-shadow-files/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-stale-shadow-files/out new file mode 100644 index 0000000000..49d861c74c --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir-leftover-log-rotation-stale-shadow-files/out @@ -0,0 +1 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir/out b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir/out new file mode 100644 index 0000000000..f12f4edf0b --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.rotate-default-logdir/out @@ -0,0 +1,131 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +./logs/test.2011-03-07-03-00-05.log test 11-03-07_03.00.05 11-03-07_04.00.05 0 ascii +./logs/test.2011-03-07-04-00-05.log test 11-03-07_04.00.05 11-03-07_05.00.05 0 ascii +./logs/test.2011-03-07-05-00-05.log test 11-03-07_05.00.05 11-03-07_06.00.05 0 ascii +./logs/test.2011-03-07-06-00-05.log test 11-03-07_06.00.05 11-03-07_07.00.05 0 ascii +./logs/test.2011-03-07-07-00-05.log test 11-03-07_07.00.05 11-03-07_08.00.05 0 ascii +./logs/test.2011-03-07-08-00-05.log test 11-03-07_08.00.05 11-03-07_09.00.05 0 ascii +./logs/test.2011-03-07-09-00-05.log test 11-03-07_09.00.05 11-03-07_10.00.05 0 ascii +./logs/test.2011-03-07-10-00-05.log test 11-03-07_10.00.05 11-03-07_11.00.05 0 ascii +./logs/test.2011-03-07-11-00-05.log test 11-03-07_11.00.05 11-03-07_12.00.05 0 ascii +./logs/test.2011-03-07-12-00-05.log test 11-03-07_12.00.05 11-03-07_12.59.55 1 ascii +> ./logs/test.2011-03-07-03-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1024 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 0 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-04-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1025 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 1 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-05-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1026 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 2 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-06-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1027 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 3 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-07-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1028 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 4 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-08-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1029 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 5 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-09-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1030 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 6 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-10-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1031 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 7 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-11-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1032 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 8 +#close XXXX-XX-XX-XX-XX-XX +> ./logs/test.2011-03-07-12-00-05.log +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path test +#open XXXX-XX-XX-XX-XX-XX +#fields t id.orig_h id.orig_p id.resp_h id.resp_p +#types time addr port addr port +XXXXXXXXXX.XXXXXX 10.0.0.1 20 10.0.0.2 1033 +XXXXXXXXXX.XXXXXX 10.0.0.2 20 10.0.0.3 9 +#close XXXX-XX-XX-XX-XX-XX diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek index 3871849bd9..af1f5a6d37 100644 --- a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek +++ b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation-stale-shadow-files.zeek @@ -7,7 +7,7 @@ # @TEST-EXEC: ! test -f logs/.shadow.conn.log -# @TEST-EXEC: btest-diff out +# @TEST-EXEC: TEST_DIFF_CANONIFIER='$SCRIPTS/diff-remove-abspath | $SCRIPTS/diff-remove-timestamps' btest-diff out module GLOBAL; diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek index dfdf31d723..7fdba2c9fa 100644 --- a/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek +++ b/testing/btest/scripts/base/frameworks/logging/rotate-ascii-logdir-leftover-log-rotation.zeek @@ -3,7 +3,7 @@ # @TEST-EXEC: zeek -b -r ${TRACES}/rotation.trace %INPUT >zeek.out 2>&1 # @TEST-EXEC: grep "test" zeek.out | sort >out # @TEST-EXEC: for i in `ls test.*.log | sort`; do printf '> %s\n' $i; cat $i; done >>out -# @TEST-EXEC: btest-diff out +# @TEST-EXEC: TEST_DIFF_CANONIFIER='$SCRIPTS/diff-remove-abspath | $SCRIPTS/diff-remove-timestamps' btest-diff out module Test; diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-shadow-files.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-shadow-files.zeek new file mode 100644 index 0000000000..41ca5a1ef0 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-shadow-files.zeek @@ -0,0 +1,34 @@ +# @TEST-DOC: Test that .shadow files are picked up from Log::default_logdir. +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: echo ".log" >> logs/.shadow.conn.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> logs/.shadow.conn.log +# @TEST-EXEC: echo "leftover conn log" > logs/conn.log +# @TEST-EXEC: echo ".log" >> logs/.shadow.dns.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> logs/.shadow.dns.log +# @TEST-EXEC: echo "leftover dns log" > logs/dns.log + +# @TEST-EXEC: zeek -b %INPUT > out + +# @TEST-EXEC: ! test -f logs/.shadow.conn.log +# @TEST-EXEC: ! test -f logs/conn.log +# @TEST-EXEC: ! test -f logs/.shadow.dns.log +# @TEST-EXEC: ! test -f logs/dns.log + +# Ensure rotated logs ends-up in the ./logs directory. +# @TEST-EXEC: cat ./logs/conn-*.log ./logs/dns-*.log > logs.cat + +# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-sort btest-diff out +# @TEST-EXEC: btest-diff logs.cat + +module GLOBAL; + +function my_rotation_postprocessor(info: Log::RotationInfo) : bool + { + print fmt("running my rotation postprocessor for path '%s'", info$path); + return T; + } + +redef LogAscii::enable_leftover_log_rotation = T; +redef Log::default_logdir = "./logs"; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-stale-shadow-files.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-stale-shadow-files.zeek new file mode 100644 index 0000000000..cdc919aa99 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir-leftover-log-rotation-stale-shadow-files.zeek @@ -0,0 +1,23 @@ +# @TEST-DOC: Test that stale .shadow files are removed from ::default_logdir +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: echo ".log" >> logs/.shadow.conn.log +# @TEST-EXEC: echo "my_rotation_postprocessor" >> logs/.shadow.conn.log + +# @TEST-EXEC: zeek -b %INPUT > out 2>&1 + +# @TEST-EXEC: ! test -f logs/.shadow.conn.log + +# @TEST-EXEC: TEST_DIFF_CANONIFIER='$SCRIPTS/diff-remove-abspath | $SCRIPTS/diff-remove-timestamps' btest-diff out + +module GLOBAL; + +function my_rotation_postprocessor(info: Log::RotationInfo) : bool + { + print fmt("running my rotation postprocessor for path '%s'", info$path); + return T; + } + +redef Log::default_logdir = "./logs"; +redef LogAscii::enable_leftover_log_rotation = T; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; diff --git a/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir.zeek b/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir.zeek new file mode 100644 index 0000000000..6300a4e9b3 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/rotate-default-logdir.zeek @@ -0,0 +1,34 @@ +# @TEST-DOC: Set Log::default_logdir to ./logs. Ensure logs stay within ./logs. +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: zeek -b -r ${TRACES}/rotation.trace %INPUT >zeek.out 2>&1 +# @TEST-EXEC: grep "test" zeek.out | sort >out +# @TEST-EXEC: for i in `ls ./logs/test.*.log | sort`; do printf '> %s\n' $i; cat $i; done >>out +# @TEST-EXEC: btest-diff out + +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; +} + +redef Log::default_logdir = "./logs"; +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; + +event zeek_init() + { + Log::create_stream(Test::LOG, [$columns=Log]); + } + +event new_connection(c: connection) + { + Log::write(Test::LOG, [$t=network_time(), $id=c$id]); + } From 93584c7c7f4981881349bb5b33de1a7d66ded9a9 Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 6 Jul 2022 12:13:32 +0200 Subject: [PATCH 3/4] logging/sqlite: Recognize Log::default_logdir and place files there if set --- src/logging/writers/sqlite/SQLite.cc | 8 +++- .../ls.logs | 3 ++ .../test.select | 21 +++++++++ .../zeek.out | 2 + .../logging/sqlite/default-logdir.zeek | 46 +++++++++++++++++++ 5 files changed, 78 insertions(+), 2 deletions(-) create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/test.select create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/zeek.out create mode 100644 testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek diff --git a/src/logging/writers/sqlite/SQLite.cc b/src/logging/writers/sqlite/SQLite.cc index 4fd2e54e90..95bf5d4a6a 100644 --- a/src/logging/writers/sqlite/SQLite.cc +++ b/src/logging/writers/sqlite/SQLite.cc @@ -10,6 +10,7 @@ #include "zeek/logging/writers/sqlite/sqlite.bif.h" #include "zeek/threading/SerialTypes.h" +#include "zeek/util.h" using namespace std; using zeek::threading::Field; @@ -128,8 +129,11 @@ bool SQLite::DoInit(const WriterInfo& info, int arg_num_fields, const Field* con num_fields = arg_num_fields; fields = arg_fields; - string fullpath(info.path); - fullpath.append(".sqlite"); + auto fullpath = zeek::filesystem::path( + zeek::id::find_const("Log::default_logdir")->ToStdString()); + + fullpath /= info.path; + fullpath += ".sqlite"; string tablename; WriterInfo::config_map::const_iterator it = info.config.find("tablename"); diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs new file mode 100644 index 0000000000..d31d0d2566 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs @@ -0,0 +1,3 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +./logs/reporter.sqlite +./logs/test.sqlite diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/test.select b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/test.select new file mode 100644 index 0000000000..63564a8c79 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/test.select @@ -0,0 +1,21 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +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 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/zeek.out b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/zeek.out new file mode 100644 index 0000000000..1d37b57d25 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/zeek.out @@ -0,0 +1,2 @@ +### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. +XXXXXXXXXX.XXXXXX test/Log::WRITER_SQLITE: tablename configuration option not found. Defaulting to path test diff --git a/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek b/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek new file mode 100644 index 0000000000..0dd5023ce8 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek @@ -0,0 +1,46 @@ +# +# @TEST-REQUIRES: which sqlite3 +# @TEST-REQUIRES: has-writer Zeek::SQLiteWriter +# @TEST-GROUP: sqlite +# +# @TEST-EXEC: mkdir logs +# @TEST-EXEC: zeek -b -r ${TRACES}/rotation.trace %INPUT >zeek.out 2>&1 +# @TEST-EXEC: ls ./logs/* > ls.logs +# @TEST-EXEC: sqlite3 ./logs/test.sqlite 'select * from test' > test.select +# @TEST-EXEC: btest-diff test.select +# @TEST-EXEC: btest-diff ls.logs +# @TEST-EXEC: btest-diff zeek.out +# +# @TEST-DOC: Configure Log::default_writer, Log::default_logdir and ensure the test.sqlite database is in ./logs + +redef Log::default_writer = Log::WRITER_SQLITE; +redef Log::default_logdir = "./logs"; + +# Also enable log-rotation, but it has no effect on sqlite. +redef Log::default_rotation_interval = 1hr; +redef Log::default_rotation_postprocessor_cmd = "echo"; + +redef LogSQLite::unset_field = "(unset)"; + +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; +} +event zeek_init() + { + Log::create_stream(Test::LOG, [$columns=Log]); + } + +event new_connection(c: connection) + { + Log::write(Test::LOG, [$t=network_time(), $id=c$id]); + } From a2bcb1bf285d694c1c035d64f7b9a4252fff684a Mon Sep 17 00:00:00 2001 From: Arne Welzel Date: Wed, 6 Jul 2022 22:52:48 +0200 Subject: [PATCH 4/4] sqlite default-logdir test: Remove ls ./logs baseline Observed .sqlite-journal files and missing reporter.sqlite files in CI runs. Subsequently reading the ./test.sqlite file is more reliable and should be good enough. --- .../ls.logs | 3 --- .../scripts/base/frameworks/logging/sqlite/default-logdir.zeek | 2 -- 2 files changed, 5 deletions(-) delete mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs b/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs deleted file mode 100644 index d31d0d2566..0000000000 --- a/testing/btest/Baseline/scripts.base.frameworks.logging.sqlite.default-logdir/ls.logs +++ /dev/null @@ -1,3 +0,0 @@ -### BTest baseline data generated by btest-diff. Do not edit. Use "btest -U/-u" to update. Requires BTest >= 0.63. -./logs/reporter.sqlite -./logs/test.sqlite diff --git a/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek b/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek index 0dd5023ce8..127943fb6a 100644 --- a/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek +++ b/testing/btest/scripts/base/frameworks/logging/sqlite/default-logdir.zeek @@ -5,10 +5,8 @@ # # @TEST-EXEC: mkdir logs # @TEST-EXEC: zeek -b -r ${TRACES}/rotation.trace %INPUT >zeek.out 2>&1 -# @TEST-EXEC: ls ./logs/* > ls.logs # @TEST-EXEC: sqlite3 ./logs/test.sqlite 'select * from test' > test.select # @TEST-EXEC: btest-diff test.select -# @TEST-EXEC: btest-diff ls.logs # @TEST-EXEC: btest-diff zeek.out # # @TEST-DOC: Configure Log::default_writer, Log::default_logdir and ensure the test.sqlite database is in ./logs