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";