From 19eea409c38fdefae7cd9113b23f9d7c6fc46285 Mon Sep 17 00:00:00 2001 From: Robin Sommer Date: Thu, 21 Jun 2012 17:42:33 -0700 Subject: [PATCH] Extending the log writer DoInit() API. We now pass in a Info struct that contains: - the path name (as before) - the rotation interval - the log_rotate_base_time in seconds - a table of key/value pairs with further configuration options. To fill the table, log filters have a new field "config: table[string] of strings". This gives a way to pass arbitrary values from script-land to writers. Interpretation is left up to the writer. Also splits calc_next_rotate() into two functions, one of which is thread-safe and can be used with the log_rotate_base_time value from DoInit(). Includes also updates to the None writer: - It gets its own script writers/none.bro. - New bool option LogNone::debug to enable debug output. It then prints out all the values passed to DoInit(). That's used by a btest test to ensure the new DoInit() values are right. - Fixed a bug that prevented Bro from terminating.. (scripts.base.frameworks.logging.rotate-custom currently fails. Haven't yet investigated why.) --- scripts/base/frameworks/logging/__load__.bro | 1 + scripts/base/frameworks/logging/main.bro | 6 +++ .../base/frameworks/logging/writers/none.bro | 17 ++++++++ src/File.cc | 3 +- src/Val.cc | 1 + src/bro.bif | 4 +- src/logging.bif | 6 +++ src/logging/Manager.cc | 36 +++++++++++++++-- src/logging/WriterBackend.cc | 40 ++++++++++++++++++- src/logging/WriterBackend.h | 18 +++++++++ src/logging/writers/None.cc | 27 +++++++++++++ src/logging/writers/None.h | 4 +- src/util.cc | 25 +++++++----- src/util.h | 17 +++++++- .../output | 12 ++++++ .../base/frameworks/logging/none-debug.bro | 37 +++++++++++++++++ 16 files changed, 231 insertions(+), 23 deletions(-) create mode 100644 scripts/base/frameworks/logging/writers/none.bro create mode 100644 testing/btest/Baseline/scripts.base.frameworks.logging.none-debug/output create mode 100644 testing/btest/scripts/base/frameworks/logging/none-debug.bro diff --git a/scripts/base/frameworks/logging/__load__.bro b/scripts/base/frameworks/logging/__load__.bro index 17e03e2ef7..be44a7e34f 100644 --- a/scripts/base/frameworks/logging/__load__.bro +++ b/scripts/base/frameworks/logging/__load__.bro @@ -2,3 +2,4 @@ @load ./postprocessors @load ./writers/ascii @load ./writers/dataseries +@load ./writers/none diff --git a/scripts/base/frameworks/logging/main.bro b/scripts/base/frameworks/logging/main.bro index bec5f31dc6..9936ae44b1 100644 --- a/scripts/base/frameworks/logging/main.bro +++ b/scripts/base/frameworks/logging/main.bro @@ -138,6 +138,10 @@ export { ## Callback function to trigger for rotated files. If not set, the ## default comes out of :bro:id:`Log::default_rotation_postprocessors`. postprocessor: function(info: RotationInfo) : bool &optional; + + ## A key/value table that will be passed on the writer. + ## Interpretation of the values is left to the writer. + config: table[string] of string &default=table(); }; ## Sentinel value for indicating that a filter was not found when looked up. @@ -327,6 +331,8 @@ function __default_rotation_postprocessor(info: RotationInfo) : bool { if ( info$writer in default_rotation_postprocessors ) return default_rotation_postprocessors[info$writer](info); + + return F; } function default_path_func(id: ID, path: string, rec: any) : string diff --git a/scripts/base/frameworks/logging/writers/none.bro b/scripts/base/frameworks/logging/writers/none.bro new file mode 100644 index 0000000000..22d83bd8ec --- /dev/null +++ b/scripts/base/frameworks/logging/writers/none.bro @@ -0,0 +1,17 @@ +##! Interface for the None log writer. Thiis writer is mainly for debugging. + +module LogNone; + +export { + ## If true, output some debugging output that can be useful for unit + ##testing the logging framework. + const debug = F &redef; +} + +function default_rotation_postprocessor_func(info: Log::RotationInfo) : bool + { + return T; + } + +redef Log::default_rotation_postprocessors += { [Log::WRITER_NONE] = default_rotation_postprocessor_func }; + diff --git a/src/File.cc b/src/File.cc index 8b432f4428..20e845c09f 100644 --- a/src/File.cc +++ b/src/File.cc @@ -572,8 +572,9 @@ void BroFile::InstallRotateTimer() const char* base_time = log_rotate_base_time ? log_rotate_base_time->AsString()->CheckString() : 0; + double base = parse_rotate_base_time(base_time); double delta_t = - calc_next_rotate(rotate_interval, base_time); + calc_next_rotate(network_time, rotate_interval, base); rotate_timer = new RotateTimer(network_time + delta_t, this, true); } diff --git a/src/Val.cc b/src/Val.cc index 32a3c367bb..8a8c2b18c0 100644 --- a/src/Val.cc +++ b/src/Val.cc @@ -1651,6 +1651,7 @@ int TableVal::RemoveFrom(Val* val) const while ( (v = tbl->NextEntry(k, c)) ) { Val* index = RecoverIndex(k); + Unref(index); Unref(t->Delete(k)); delete k; diff --git a/src/bro.bif b/src/bro.bif index 1feccb8639..b1f33c9c46 100644 --- a/src/bro.bif +++ b/src/bro.bif @@ -4814,7 +4814,9 @@ function calc_next_rotate%(i: interval%) : interval %{ const char* base_time = log_rotate_base_time ? log_rotate_base_time->AsString()->CheckString() : 0; - return new Val(calc_next_rotate(i, base_time), TYPE_INTERVAL); + + double base = parse_rotate_base_time(base_time); + return new Val(calc_next_rotate(network_time, i, base), TYPE_INTERVAL); %} ## Returns the size of a given file. diff --git a/src/logging.bif b/src/logging.bif index efc6ed0b4b..d25e89c33c 100644 --- a/src/logging.bif +++ b/src/logging.bif @@ -81,3 +81,9 @@ const extent_size: count; const dump_schema: bool; const use_integer_for_time: bool; const num_threads: count; + +# Options for the None writer. + +module LogNone; + +const debug: bool; diff --git a/src/logging/Manager.cc b/src/logging/Manager.cc index b30ee26534..23b6f070a1 100644 --- a/src/logging/Manager.cc +++ b/src/logging/Manager.cc @@ -51,6 +51,7 @@ struct Manager::Filter { string path; Val* path_val; EnumVal* writer; + TableVal* config; bool local; bool remote; double interval; @@ -519,6 +520,7 @@ bool Manager::AddFilter(EnumVal* id, RecordVal* fval) Val* log_remote = fval->LookupWithDefault(rtype->FieldOffset("log_remote")); Val* interv = fval->LookupWithDefault(rtype->FieldOffset("interv")); Val* postprocessor = fval->LookupWithDefault(rtype->FieldOffset("postprocessor")); + Val* config = fval->LookupWithDefault(rtype->FieldOffset("config")); Filter* filter = new Filter; filter->name = name->AsString()->CheckString(); @@ -530,6 +532,7 @@ bool Manager::AddFilter(EnumVal* id, RecordVal* fval) filter->remote = log_remote->AsBool(); filter->interval = interv->AsInterval(); filter->postprocessor = postprocessor ? postprocessor->AsFunc() : 0; + filter->config = config->Ref()->AsTableVal(); Unref(name); Unref(pred); @@ -538,6 +541,7 @@ bool Manager::AddFilter(EnumVal* id, RecordVal* fval) Unref(log_remote); Unref(interv); Unref(postprocessor); + Unref(config); // Build the list of fields that the filter wants included, including // potentially rolling out fields. @@ -768,6 +772,22 @@ bool Manager::Write(EnumVal* id, RecordVal* columns) WriterBackend::WriterInfo info; info.path = path; + HashKey* k; + IterCookie* c = filter->config->AsTable()->InitForIteration(); + + TableEntryVal* v; + while ( (v = filter->config->AsTable()->NextEntry(k, c)) ) + { + ListVal* index = filter->config->RecoverIndex(k); + string key = index->Index(0)->AsString()->CheckString(); + string value = v->Value()->AsString()->CheckString(); + info.config.insert(std::make_pair(key, value)); + Unref(index); + delete k; + } + + // CreateWriter() will set the other fields in info. + writer = CreateWriter(stream->id, filter->writer, info, filter->num_fields, arg_fields, filter->local, filter->remote); @@ -777,7 +797,6 @@ bool Manager::Write(EnumVal* id, RecordVal* columns) Unref(columns); return false; } - } // Alright, can do the write now. @@ -977,8 +996,6 @@ WriterFrontend* Manager::CreateWriter(EnumVal* id, EnumVal* writer, const Writer WriterFrontend* writer_obj = new WriterFrontend(id, writer, local, remote); assert(writer_obj); - writer_obj->Init(info, num_fields, fields); - WriterInfo* winfo = new WriterInfo; winfo->type = writer->Ref()->AsEnumVal(); winfo->writer = writer_obj; @@ -1020,6 +1037,16 @@ WriterFrontend* Manager::CreateWriter(EnumVal* id, EnumVal* writer, const Writer Stream::WriterMap::value_type(Stream::WriterPathPair(writer->AsEnum(), info.path), winfo)); + // Still need to set the WriterInfo's rotation parameters, which we + // computed above. + const char* base_time = log_rotate_base_time ? + log_rotate_base_time->AsString()->CheckString() : 0; + + winfo->info.rotation_interval = winfo->interval; + winfo->info.rotation_base = parse_rotate_base_time(base_time); + + writer_obj->Init(winfo->info, num_fields, fields); + return writer_obj; } @@ -1223,8 +1250,9 @@ void Manager::InstallRotationTimer(WriterInfo* winfo) const char* base_time = log_rotate_base_time ? log_rotate_base_time->AsString()->CheckString() : 0; + double base = parse_rotate_base_time(base_time); double delta_t = - calc_next_rotate(rotation_interval, base_time); + calc_next_rotate(network_time, rotation_interval, base); winfo->rotation_timer = new RotationTimer(network_time + delta_t, winfo, true); diff --git a/src/logging/WriterBackend.cc b/src/logging/WriterBackend.cc index 35bb27d27b..a31b0ebc0f 100644 --- a/src/logging/WriterBackend.cc +++ b/src/logging/WriterBackend.cc @@ -63,12 +63,48 @@ using namespace logging; bool WriterBackend::WriterInfo::Read(SerializationFormat* fmt) { - return fmt->Read(&path, "path"); + int size; + + if ( ! (fmt->Read(&path, "path") && + fmt->Read(&rotation_base, "rotation_base") && + fmt->Read(&rotation_interval, "rotation_interval") && + fmt->Read(&size, "config_size")) ) + return false; + + config.clear(); + + while ( size ) + { + string value; + string key; + + if ( ! (fmt->Read(&value, "config-value") && fmt->Read(&value, "config-key")) ) + return false; + + config.insert(std::make_pair(value, key)); + } + + return true; } + bool WriterBackend::WriterInfo::Write(SerializationFormat* fmt) const { - return fmt->Write(path, "path"); + int size = config.size(); + + if ( ! (fmt->Write(path, "path") && + fmt->Write(rotation_base, "rotation_base") && + fmt->Write(rotation_interval, "rotation_interval") && + fmt->Write(size, "config_size")) ) + return false; + + for ( config_map::const_iterator i = config.begin(); i != config.end(); ++i ) + { + if ( ! (fmt->Write(i->first, "config-value") && fmt->Write(i->second, "config-key")) ) + return false; + } + + return true; } WriterBackend::WriterBackend(WriterFrontend* arg_frontend) : MsgThread() diff --git a/src/logging/WriterBackend.h b/src/logging/WriterBackend.h index 30e1995430..84c43818a6 100644 --- a/src/logging/WriterBackend.h +++ b/src/logging/WriterBackend.h @@ -48,6 +48,8 @@ public: */ struct WriterInfo { + typedef std::map config_map; + /** * A string left to the interpretation of the writer * implementation; it corresponds to the value configured on @@ -55,6 +57,22 @@ public: */ string path; + /** + * The rotation interval as configured for this writer. + */ + double rotation_interval; + + /** + * The parsed value of log_rotate_base_time in seconds. + */ + double rotation_base; + + /** + * A map of key/value pairs corresponding to the relevant + * filter's "config" table. + */ + std::map config; + private: friend class ::RemoteSerializer; diff --git a/src/logging/writers/None.cc b/src/logging/writers/None.cc index e133394722..acf9355cf7 100644 --- a/src/logging/writers/None.cc +++ b/src/logging/writers/None.cc @@ -1,9 +1,36 @@ #include "None.h" +#include "NetVar.h" using namespace logging; using namespace writer; +bool None::DoInit(const WriterInfo& info, int num_fields, + const threading::Field* const * fields) + { + if ( BifConst::LogNone::debug ) + { + std::cout << "[logging::writer::None]" << std::endl; + std::cout << " path=" << info.path << std::endl; + std::cout << " rotation_interval=" << info.rotation_interval << std::endl; + std::cout << " rotation_base=" << info.rotation_base << std::endl; + + for ( std::map::const_iterator i = info.config.begin(); i != info.config.end(); i++ ) + std::cout << " config[" << i->first << "] = " << i->second << std::endl; + + for ( int i = 0; i < num_fields; i++ ) + { + const threading::Field* field = fields[i]; + std::cout << " field " << field->name << ": " + << type_name(field->type) << std::endl; + } + + std::cout << std::endl; + } + + return true; + } + bool None::DoRotate(string rotated_path, double open, double close, bool terminating) { if ( ! FinishedRotation(string("/dev/null"), Info().path, open, close, terminating)) diff --git a/src/logging/writers/None.h b/src/logging/writers/None.h index 89ba690e09..7e2e4ef4eb 100644 --- a/src/logging/writers/None.h +++ b/src/logging/writers/None.h @@ -19,7 +19,7 @@ public: protected: virtual bool DoInit(const WriterInfo& info, int num_fields, - const threading::Field* const * fields) { return true; } + const threading::Field* const * fields); virtual bool DoWrite(int num_fields, const threading::Field* const* fields, threading::Value** vals) { return true; } @@ -27,7 +27,7 @@ protected: virtual bool DoRotate(string rotated_path, double open, double close, bool terminating); virtual bool DoFlush() { return true; } - virtual bool DoFinish() { return true; } + virtual bool DoFinish() { WriterBackend::DoFinish(); return true; } }; } diff --git a/src/util.cc b/src/util.cc index 798be400d1..16df52b987 100644 --- a/src/util.cc +++ b/src/util.cc @@ -1082,18 +1082,8 @@ const char* log_file_name(const char* tag) return fmt("%s.%s", tag, (env ? env : "log")); } -double calc_next_rotate(double interval, const char* rotate_base_time) +double parse_rotate_base_time(const char* rotate_base_time) { - double current = network_time; - - // Calculate start of day. - time_t teatime = time_t(current); - - struct tm t; - t = *localtime(&teatime); - t.tm_hour = t.tm_min = t.tm_sec = 0; - double startofday = mktime(&t); - double base = -1; if ( rotate_base_time && rotate_base_time[0] != '\0' ) @@ -1105,6 +1095,19 @@ double calc_next_rotate(double interval, const char* rotate_base_time) base = t.tm_min * 60 + t.tm_hour * 60 * 60; } + return base; + } + +double calc_next_rotate(double current, double interval, double base) + { + // Calculate start of day. + time_t teatime = time_t(current); + + struct tm t; + t = *localtime_r(&teatime, &t); + t.tm_hour = t.tm_min = t.tm_sec = 0; + double startofday = mktime(&t); + if ( base < 0 ) // No base time given. To get nice timestamps, we round // the time up to the next multiple of the rotation interval. diff --git a/src/util.h b/src/util.h index 6b237edfd8..6ca584900c 100644 --- a/src/util.h +++ b/src/util.h @@ -193,9 +193,22 @@ extern FILE* rotate_file(const char* name, RecordVal* rotate_info); // This mimics the script-level function with the same name. const char* log_file_name(const char* tag); +// Parse a time string of the form "HH:MM" (as used for the rotation base +// time) into a double representing the number of seconds. Returns -1 if the +// string cannot be parsed. The function's result is intended to be used with +// calc_next_rotate(). +// +// This function is not thread-safe. +double parse_rotate_base_time(const char* rotate_base_time); + // Calculate the duration until the next time a file is to be rotated, based -// on the given rotate_interval and rotate_base_time. -double calc_next_rotate(double rotate_interval, const char* rotate_base_time); +// on the given rotate_interval and rotate_base_time. 'current' the the +// current time to be used as base, 'rotate_interval' the rotation interval, +// and 'base' the value returned by parse_rotate_base_time(). For the latter, +// if the function returned -1, that's fine, calc_next_rotate() handles that. +// +// This function is thread-safe. +double calc_next_rotate(double current, double rotate_interval, double base); // Terminates processing gracefully, similar to pressing CTRL-C. void terminate_processing(); diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.none-debug/output b/testing/btest/Baseline/scripts.base.frameworks.logging.none-debug/output new file mode 100644 index 0000000000..b2a8921c38 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.none-debug/output @@ -0,0 +1,12 @@ +[logging::writer::None] + path=ssh + rotation_interval=3600 + rotation_base=300 + config[foo] = bar + config[foo2] = bar2 + field id.orig_p: port + field id.resp_h: addr + field id.resp_p: port + field status: string + field country: string + diff --git a/testing/btest/scripts/base/frameworks/logging/none-debug.bro b/testing/btest/scripts/base/frameworks/logging/none-debug.bro new file mode 100644 index 0000000000..5d2e98323a --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/none-debug.bro @@ -0,0 +1,37 @@ +# +# @TEST-EXEC: bro -b %INPUT >output +# @TEST-EXEC: btest-diff output + +redef Log::default_writer = Log::WRITER_NONE; +redef LogNone::debug = T; +redef Log::default_rotation_interval= 1hr; +redef log_rotate_base_time = "00:05"; + +module SSH; + +export { + redef enum Log::ID += { LOG }; + + type Log: record { + t: time; + id: conn_id; # Will be rolled out into individual columns. + status: string &optional; + country: string &default="unknown"; + } &log; +} + +event bro_init() +{ + local config: table[string] of string; + config["foo"]="bar"; + config["foo2"]="bar2"; + + local cid = [$orig_h=1.2.3.4, $orig_p=1234/tcp, $resp_h=2.3.4.5, $resp_p=80/tcp]; + + Log::create_stream(SSH::LOG, [$columns=Log]); + + Log::remove_default_filter(SSH::LOG); + Log::add_filter(SSH::LOG, [$name="f1", $exclude=set("t", "id.orig_h"), $config=config]); + Log::write(SSH::LOG, [$t=network_time(), $id=cid, $status="success"]); +} +