Merge remote-tracking branch 'origin/topic/dev/print-to-log'

Adjustments during merge:

- kept the UNKNOWN Log::ID as placeholder value
- changed the coverage.find-bro-logs test to check for arbitrary $path
  field values instead of just string literals
- don't force EnumVal to unsigned integer since the relevant union member
  is the signed integer and added the relevant enum values/types to
  .bif files for easier access
- compare FILE* versus file name to check for stdout equality (don't
  think it matters much, just a bit more efficient)
- minor whitespace/style tweaks

* origin/topic/dev/print-to-log:
  Added a non boolean configuration and other changes as suggested by Jon
  Allow Print Statements to be redirected to a Log# This is a combination of 3 commits.

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

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

VERSION

@@ -1 +1 @@
-3.1.0-dev.286
+3.1.0-dev.292

doc

@@ -1 +1 @@
-Subproject commit 39bd2dc06feaf7dd8923d2e634506182c8c0ad29
+Subproject commit e66c76bf7410144504bdeda787674b786821e3ff

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

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.

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<EnumVal> 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<EnumVal> 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<RecordVal>(internal_type("Log::PrintLogInfo")->AsRecordType());
+	auto vec = make_intrusive<VectorVal>(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<BifEnum::Log::PrintLogType>(
+	        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() )

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());

testing/btest/Baseline/coverage.find-bro-logs/out

@@ -38,6 +38,7 @@ ocsp
 openflow
 packet_filter
 pe
+print_log_path
 radius
 rdp
 reporter

testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/anotherfile

@@ -0,0 +1 @@
+from event, [ts=1574278151.973419, vals=[2, T]]

testing/btest/Baseline/scripts.base.frameworks.logging.print-log-stdout/otherfile

@@ -0,0 +1,2 @@
+hello world ,
+2, T

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

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

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;
+    }

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

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);
+	}

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);
+	}