diff --git a/CHANGES b/CHANGES index 043fb0ba32..31f74285e1 100644 --- a/CHANGES +++ b/CHANGES @@ -1,4 +1,8 @@ +3.1.0-dev.292 | 2019-12-02 13:37:19 -0800 + + * GH-619: Allow "print" statements to be redirected to a Log (Dev Bali, Corelight) + 3.1.0-dev.286 | 2019-11-21 08:47:32 -0800 * GH-684: Fix parsing of RPC calls with non-AUTH_UNIX flavors diff --git a/NEWS b/NEWS index 9fd2b44cc9..b3e957f518 100644 --- a/NEWS +++ b/NEWS @@ -22,6 +22,10 @@ New Functionality - There is now a new ``tcp_options`` event that is raised for each TCP header that contains options. +- Added a new option, ``Log::print_to_log`` that can be set to automatically + redirect the output from "print" statements to a real log stream (e.g. + instead of writing to stdout). + Changed Functionality --------------------- diff --git a/VERSION b/VERSION index fa9526d31a..063cce3f01 100644 --- a/VERSION +++ b/VERSION @@ -1 +1 @@ -3.1.0-dev.286 +3.1.0-dev.292 diff --git a/doc b/doc index 39bd2dc06f..e66c76bf74 160000 --- a/doc +++ b/doc @@ -1 +1 @@ -Subproject commit 39bd2dc06feaf7dd8923d2e634506182c8c0ad29 +Subproject commit e66c76bf7410144504bdeda787674b786821e3ff diff --git a/scripts/base/frameworks/logging/main.zeek b/scripts/base/frameworks/logging/main.zeek index 3a83808369..b318cd0151 100644 --- a/scripts/base/frameworks/logging/main.zeek +++ b/scripts/base/frameworks/logging/main.zeek @@ -12,7 +12,9 @@ export { ## file. type Log::ID: enum { ## Dummy place-holder. - UNKNOWN + UNKNOWN, + ## Print statements that have been redirected to a log stream. + PRINTLOG }; ## If true, local logging is by default enabled for all filters. @@ -75,6 +77,36 @@ export { ## Returns: The path to be used for the filter. global default_path_func: function(id: ID, path: string, rec: any) : string &redef; + ## If :zeek:see:`Log::print_to_log` is set to redirect, ``print`` statements will + ## automatically populate log entries with the fields contained in this record. + type PrintLogInfo: record { + ## Current timestamp. + ts: time &log; + ## Set of strings passed to the print statement. + vals: string_vec &log; + }; + + ## Configurations for :zeek:see:`Log::print_to_log` + type PrintLogType: enum { + ## No redirection of ``print`` statements. + REDIRECT_NONE, + ## Redirection of those ``print`` statements that were being logged to stdout, + ## leaving behind those set to go to other specific files. + REDIRECT_STDOUT, + ## Redirection of all ``print`` statements. + REDIRECT_ALL + }; + + ## Event for accessing logged print records. + global log_print: event(rec: PrintLogInfo); + + ## Set configuration for ``print`` statements redirected to logs. + const print_to_log: PrintLogType = REDIRECT_NONE &redef; + + ## If :zeek:see:`Log::print_to_log` is enabled to write to a print log, + ## this is the path to which the print Log Stream writes to + const print_log_path = "print" &redef; + # Log rotation support. ## Information passed into rotation callback functions. @@ -643,3 +675,9 @@ function remove_default_filter(id: ID) : bool { return remove_filter(id, "default"); } + +event zeek_init() &priority=5 + { + if ( print_to_log != REDIRECT_NONE ) + Log::create_stream(PRINTLOG, [$columns=PrintLogInfo, $ev=log_print, $path=print_log_path]); + } diff --git a/src/File.h b/src/File.h index 530d5c7a07..6433cd7dfd 100644 --- a/src/File.h +++ b/src/File.h @@ -66,6 +66,9 @@ public: bool IsRawOutput() const { return raw_output; } protected: + + friend class PrintStmt; + BroFile() { Init(); } void Init(); @@ -80,7 +83,8 @@ protected: // Returns nil if the file is not active, was in error, etc. // (Protected because we do not want anyone to write directly - // to the file.) + // to the file, but the PrintStmt friend uses this to check whether + // it's really stdout.) FILE* File(); // Raises a file_opened event. diff --git a/src/Stmt.cc b/src/Stmt.cc index fca38a357a..d777e61b97 100644 --- a/src/Stmt.cc +++ b/src/Stmt.cc @@ -14,6 +14,9 @@ #include "Debug.h" #include "Traverse.h" #include "Trigger.h" +#include "IntrusivePtr.h" +#include "logging/Manager.h" +#include "logging/logging.bif.h" const char* stmt_name(BroStmtTag t) { @@ -184,6 +187,40 @@ TraversalCode ExprListStmt::Traverse(TraversalCallback* cb) const static BroFile* print_stdout = 0; +static IntrusivePtr lookup_enum_val(const char* module_name, const char* name) + { + ID* id = lookup_ID(name, module_name); + assert(id); + assert(id->IsEnumConst()); + + EnumType* et = id->Type()->AsEnumType(); + + int index = et->Lookup(module_name, name); + assert(index >= 0); + IntrusivePtr rval{et->GetVal(index), false}; + + return rval; + } + +static Val* print_log(val_list* vals) + { + auto plval = lookup_enum_val("Log", "PRINTLOG"); + auto record = make_intrusive(internal_type("Log::PrintLogInfo")->AsRecordType()); + auto vec = make_intrusive(internal_type("string_vec")->AsVectorType()); + + for ( const auto& val : *vals ) + { + ODesc d(DESC_READABLE); + val->Describe(&d); + vec->Assign(vec->Size(), new StringVal(d.Description())); + } + + record->Assign(0, new Val(current_time(), TYPE_TIME)); + record->Assign(1, vec.detach()); + log_mgr->Write(plval.get(), record.get()); + return nullptr; + } + Val* PrintStmt::DoExec(val_list* vals, stmt_flow_type& /* flow */) const { RegisterAccess(); @@ -203,6 +240,26 @@ Val* PrintStmt::DoExec(val_list* vals, stmt_flow_type& /* flow */) const ++offset; } + static auto print_log_type = static_cast( + internal_val("Log::print_to_log")->AsEnum()); + + switch ( print_log_type ) { + case BifEnum::Log::REDIRECT_NONE: + break; + case BifEnum::Log::REDIRECT_ALL: + return print_log(vals); + case BifEnum::Log::REDIRECT_STDOUT: + if ( f->File() == stdout ) + // Should catch even printing to a "manually opened" stdout file, + // like "/dev/stdout" or "-". + return print_log(vals); + break; + default: + reporter->InternalError("unknown Log::PrintLogType value: %d", + print_log_type); + break; + } + desc_style style = f->IsRawOutput() ? RAW_STYLE : STANDARD_STYLE; if ( f->IsRawOutput() ) diff --git a/src/logging/logging.bif b/src/logging/logging.bif index b960bc7471..fda6d36c5c 100644 --- a/src/logging/logging.bif +++ b/src/logging/logging.bif @@ -10,6 +10,12 @@ type Filter: record; type Stream: record; type RotationInfo: record; +enum PrintLogType %{ + REDIRECT_NONE, + REDIRECT_STDOUT, + REDIRECT_ALL, +%} + function Log::__create_stream%(id: Log::ID, stream: Log::Stream%) : bool %{ bool result = log_mgr->CreateStream(id->AsEnumVal(), stream->AsRecordVal()); diff --git a/testing/btest/Baseline/coverage.find-bro-logs/out b/testing/btest/Baseline/coverage.find-bro-logs/out index 55ef0c557e..c57889e881 100644 --- a/testing/btest/Baseline/coverage.find-bro-logs/out +++ b/testing/btest/Baseline/coverage.find-bro-logs/out @@ -38,6 +38,7 @@ ocsp openflow packet_filter pe +print_log_path radius rdp reporter diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/.stdout new file mode 100644 index 0000000000..e69de29bb2 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/anotherfile b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/anotherfile new file mode 100644 index 0000000000..0f26e071a1 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/anotherfile @@ -0,0 +1 @@ +from event, [ts=1574278151.973419, vals=[2, T]] diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/otherfile b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/otherfile new file mode 100644 index 0000000000..6a8799a20f --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/otherfile @@ -0,0 +1,2 @@ +hello world , +2, T diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/print.log b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/print.log new file mode 100644 index 0000000000..5452244963 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/print.log @@ -0,0 +1,11 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path print +#open 2019-11-18-15-32-20 +#fields ts vals +#types time vector[string] +1574119940.484001 hello world \x2c +1574119940.484104 2,T +#close 2019-11-18-15-32-20 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/.stdout b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/.stdout new file mode 100644 index 0000000000..e69de29bb2 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/otherfile b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/otherfile new file mode 100644 index 0000000000..e69de29bb2 diff --git a/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/print_statements.log b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/print_statements.log new file mode 100644 index 0000000000..9496a1eab9 --- /dev/null +++ b/testing/btest/Baseline/scripts.base.frameworks.logging.print-log/print_statements.log @@ -0,0 +1,13 @@ +#separator \x09 +#set_separator , +#empty_field (empty) +#unset_field - +#path print_statements +#open 2019-11-19-00-27-19 +#fields ts vals +#types time vector[string] +1574123239.274803 file "otherfile" of string,hello world \x2c +1574123239.275147 hello world \x2c +1574123239.275171 file "otherfile" of string,2,T +1574123239.275177 2,T +#close 2019-11-19-00-27-19 diff --git a/testing/btest/core/leaks/print-log.zeek b/testing/btest/core/leaks/print-log.zeek new file mode 100644 index 0000000000..3130625e50 --- /dev/null +++ b/testing/btest/core/leaks/print-log.zeek @@ -0,0 +1,14 @@ +# @TEST-GROUP: leaks +# +# @TEST-REQUIRES: zeek --help 2>&1 | grep -q mem-leaks +# +# @TEST-EXEC: HEAP_CHECK_DUMP_DIRECTORY=. HEAPCHECK=local btest-bg-run zeek zeek -m -b -r $TRACES/http/get.trace %INPUT +# @TEST-EXEC: btest-bg-wait 60 + +redef Log::print_to_log = Log::REDIRECT_ALL; + +event new_connection(c: connection) + { + print "hello world ,"; + print 2,T; + } \ No newline at end of file diff --git a/testing/btest/coverage/find-bro-logs.test b/testing/btest/coverage/find-bro-logs.test index 61d2b13ada..82b5df2445 100644 --- a/testing/btest/coverage/find-bro-logs.test +++ b/testing/btest/coverage/find-bro-logs.test @@ -19,6 +19,7 @@ python find_logs.py "${BROSCRIPTS}" | sort > out @TEST-START-FILE find_logs.py import os, sys +import re scriptdir = sys.argv[1] @@ -66,5 +67,6 @@ for fname in find_scripts(): # Print the value of the "$path" field. idx = line.find("$path") if idx > 0: - print("%s" % line[idx:].split('"')[1]) + m = re.match('.*\$path\s*=\s*"?(\w+)"?.*', line[idx:]) + print(m.group(1)) @TEST-END-FILE diff --git a/testing/btest/scripts/base/frameworks/logging/print-log-stdout.zeek b/testing/btest/scripts/base/frameworks/logging/print-log-stdout.zeek new file mode 100644 index 0000000000..e9288daa85 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/print-log-stdout.zeek @@ -0,0 +1,25 @@ +# +# @TEST-EXEC: zeek -b %INPUT +# @TEST-EXEC: btest-diff print.log +# @TEST-EXEC: btest-diff .stdout +# @TEST-EXEC: btest-diff otherfile +# @TEST-EXEC: btest-diff anotherfile + +redef Log::print_to_log = Log::REDIRECT_STDOUT; + +event zeek_init() + { + local f = open("otherfile"); + print f, "hello world ,"; + print "hello world ,"; + print f,2,T; + print 2,T; + close(f); + } + +event Log::log_print (rec: Log::PrintLogInfo) + { + local f = open("anotherfile"); + print f,"from event",rec; + close(f); + } diff --git a/testing/btest/scripts/base/frameworks/logging/print-log.zeek b/testing/btest/scripts/base/frameworks/logging/print-log.zeek new file mode 100644 index 0000000000..9c1bd30c73 --- /dev/null +++ b/testing/btest/scripts/base/frameworks/logging/print-log.zeek @@ -0,0 +1,18 @@ +# +# @TEST-EXEC: zeek -b %INPUT +# @TEST-EXEC: btest-diff print_statements.log +# @TEST-EXEC: btest-diff .stdout +# @TEST-EXEC: btest-diff otherfile + +redef Log::print_to_log = Log::REDIRECT_ALL; +redef Log::print_log_path = "print_statements"; + +event zeek_init() + { + local f = open("otherfile"); + print f, "hello world ,"; + print "hello world ,"; + print f,2,T; + print 2,T; + close(f); + } \ No newline at end of file