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.
This commit is contained in:
Arne Welzel 2022-06-29 12:59:06 +02:00
parent 8ba44c656a
commit 513ea7e04f
11 changed files with 335 additions and 35 deletions

View file

@ -15,11 +15,13 @@
#include <string>
#include <vector>
#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<LeftoverLog> 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<LeftoverLog> find_leftover_logs()
std::vector<std::string> 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<LeftoverLog> 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;

View file

@ -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

View file

@ -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'

View file

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

View file

@ -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

View file

@ -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

View file

@ -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'

View file

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

View file

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

View file

@ -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]);
}

View file

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