Add backtrace() and print_backtrace()

scripts/base/init-bare.zeek

@@ -771,7 +771,7 @@ type record_field_table: table[string] of record_field;
 
 ## Meta-information about a parameter to a function/event.
 ##
-## .. zeek:see:: call_argument_vector new_event
+## .. zeek:see:: call_argument_vector new_event backtrace print_backtrace
 type call_argument: record {
 	name: string;	##< The name of the parameter.
 	type_name: string;	##< The name of the parameters's type.
@@ -785,9 +785,28 @@ type call_argument: record {
 
 ## Vector type used to capture parameters of a function/event call.
 ##
-## .. zeek:see:: call_argument new_event
+## .. zeek:see:: call_argument new_event backtrace print_backtrace
 type call_argument_vector: vector of call_argument;
 
+## A representation of an element in a Zeek script's call stack.
+##
+## .. zeek:see:: backtrace print_backtrace
+type BacktraceElement: record {
+	## The name of the function being called at this point in the call stack.
+	function_name: string;
+	## The arguments passed to the function being called.
+	function_args: call_argument_vector;
+	## The file in which the function call is being made.
+	file_location: string &optional;
+	## The line number at which the function call is being made.
+	line_location: count &optional;
+};
+
+## A representation of a Zeek script's call stack.
+##
+## .. zeek:see:: backtrace print_backtrace
+type Backtrace: vector of BacktraceElement;
+
 # todo:: Do we still need these here? Can they move into the packet filter
 # framework?
 #

scripts/base/init-default.zeek

@@ -7,6 +7,7 @@
 @load base/utils/site
 @load base/utils/active-http
 @load base/utils/addrs
+@load base/utils/backtrace
 @load base/utils/conn-ids
 @load base/utils/dir
 @load base/utils/directions-and-hosts

scripts/base/utils/backtrace.zeek

@@ -0,0 +1,78 @@
+## Prints a Zeek function call stack.
+##
+## show_args: whether to print function argument names/types/values.
+##
+## one_line: whether to print the stack in a single line or multiple.
+##
+## one_line_delim: delimiter between stack elements if printing to one line.
+##
+## skip: the number of call stack elements to skip past, starting from zero,
+##       with that being the call to this function.
+##
+## to_file: the file to which the call stack will be printed.
+##
+## .. zeek:see:: backtrace
+function print_backtrace(show_args: bool &default=F,
+                         one_line: bool &default=F,
+                         one_line_delim: string &default="|",
+                         skip: count &default=1,
+                         to_file: file &default=open("/dev/stdout"))
+	{
+	local bt = backtrace();
+	local vs: vector of string = vector();
+	local orig_skip = skip;
+
+	for ( i in bt )
+		{
+		if ( skip > 0 )
+			{
+			--skip;
+			next;
+			}
+
+		local bte = bt[i];
+
+		local info = fmt("%s(", bte$function_name);
+
+		if ( show_args )
+			for ( ai in bte$function_args )
+				{
+				local arg = bte$function_args[ai];
+
+				if ( ai > 0 )
+					info += ", ";
+
+				info += fmt("%s: %s", arg$name, arg$type_name);
+
+				if ( arg?$value )
+					info += fmt(" = %s", arg$value);
+				}
+
+		info += ")";
+
+		if ( bte?$file_location )
+			info += fmt(" at %s:%s", bte$file_location, bte$line_location);
+
+		vs += fmt("#%s: %s", i - orig_skip, info);
+		}
+
+	if ( one_line )
+		{
+		local line = "";
+
+		for ( vsi in vs )
+			{
+			line += one_line_delim + " " + vs[vsi] + " ";
+
+			if ( vsi == |vs| - 1 )
+				line += one_line_delim;
+			}
+
+		print to_file, line;
+		}
+	else
+		{
+		for ( vsi in vs )
+			print to_file, vs[vsi];
+		}
+	}

src/EventHandler.cc

@@ -116,33 +116,7 @@ void EventHandler::NewEvent(zeek::Args* vl)
 		// new_event() is the one event we don't want to report.
 		return;
 
-	const auto& args = GetType()->Params();
+	auto vargs = zeek::MakeCallArgumentVector(*vl, GetType()->Params());
-	static auto call_argument_vector = zeek::id::find_type<zeek::VectorType>("call_argument_vector");
-	auto vargs = zeek::make_intrusive<zeek::VectorVal>(call_argument_vector);
-
-	for ( int i = 0; i < args->NumFields(); i++ )
-		{
-		const char* fname = args->FieldName(i);
-		const auto& ftype = args->GetFieldType(i);
-		auto fdefault = args->FieldDefault(i);
-
-		static auto call_argument = zeek::id::find_type<zeek::RecordType>("call_argument");
-		auto rec = zeek::make_intrusive<zeek::RecordVal>(call_argument);
-		rec->Assign(0, zeek::make_intrusive<zeek::StringVal>(fname));
-
-		ODesc d;
-		d.SetShort();
-		ftype->Describe(&d);
-		rec->Assign(1, zeek::make_intrusive<zeek::StringVal>(d.Description()));
-
-		if ( fdefault )
-			rec->Assign(2, std::move(fdefault));
-
-		if ( i < static_cast<int>(vl->size()) && (*vl)[i] )
-			rec->Assign(3, (*vl)[i]);
-
-		vargs->Assign(i, std::move(rec));
-		}
 
 	Event* ev = new Event(new_event, {
 			zeek::make_intrusive<zeek::StringVal>(name),

src/ZeekArgs.cc

@@ -1,5 +1,8 @@
 #include "ZeekArgs.h"
 #include "Val.h"
+#include "Type.h"
+#include "ID.h"
+#include "Desc.h"
 
 zeek::Args zeek::val_list_to_args(const val_list& vl)
 	{
@@ -11,3 +14,37 @@ zeek::Args zeek::val_list_to_args(const val_list& vl)
 
 	return rval;
 	}
+
+zeek::VectorValPtr zeek::MakeCallArgumentVector(const Args& vals,
+                                                const RecordTypePtr& types)
+    {
+	static auto call_argument_vector = zeek::id::find_type<zeek::VectorType>("call_argument_vector");
+
+	auto rval = make_intrusive<VectorVal>(call_argument_vector);
+
+	for ( int i = 0; i < types->NumFields(); i++ )
+		{
+		const char* fname = types->FieldName(i);
+		const auto& ftype = types->GetFieldType(i);
+		auto fdefault = types->FieldDefault(i);
+
+		static auto call_argument = zeek::id::find_type<zeek::RecordType>("call_argument");
+		auto rec = make_intrusive<RecordVal>(call_argument);
+		rec->Assign(0, make_intrusive<StringVal>(fname));
+
+		ODesc d;
+		d.SetShort();
+		ftype->Describe(&d);
+		rec->Assign(1, make_intrusive<StringVal>(d.Description()));
+
+		if ( fdefault )
+			rec->Assign(2, std::move(fdefault));
+
+		if ( i < static_cast<int>(vals.size()) && vals[i] )
+			rec->Assign(3, vals[i]);
+
+		rval->Assign(i, std::move(rec));
+		}
+
+	return rval;
+    }

src/ZeekArgs.h

@@ -5,12 +5,17 @@
 #include <vector>
 #include "BroList.h"
 
-ZEEK_FORWARD_DECLARE_NAMESPACED(Val, zeek);
-
 namespace zeek {
 
+class VectorVal;
+class RecordType;
 template <class T> class IntrusivePtr;
-using Args = std::vector<zeek::IntrusivePtr<zeek::Val>>;
+
+using ValPtr = IntrusivePtr<Val>;
+using VectorValPtr = IntrusivePtr<VectorVal>;
+using RecordTypePtr = IntrusivePtr<RecordType>;
+
+using Args = std::vector<ValPtr>;
 
 /**
  * Converts a legacy-style argument list for use in modern Zeek function
@@ -22,4 +27,6 @@ using Args = std::vector<zeek::IntrusivePtr<zeek::Val>>;
  */
 Args val_list_to_args(const val_list& vl);
 
+VectorValPtr MakeCallArgumentVector(const Args& vals, const RecordTypePtr& types);
+
 } // namespace zeek

src/zeek.bif

@@ -2172,6 +2172,46 @@ function is_v6_subnet%(s: subnet%): bool
 		return zeek::val_mgr->False();
 	%}
 
+## Returns a representation of the call stack as a vector of call stack
+## elements, each containing call location information.
+##
+## Returns: the call stack information, including function, file, and line
+##          location information.
+function backtrace%(%): Backtrace
+	%{
+	using zeek::detail::call_stack;
+	static auto backtrace_type = id::find_type<VectorType>("Backtrace");
+	static auto elem_type = id::find_type<RecordType>("BacktraceElement");
+	static auto function_name_idx = elem_type->FieldOffset("function_name");
+	static auto function_args_idx = elem_type->FieldOffset("function_args");
+	static auto file_location_idx = elem_type->FieldOffset("file_location");
+	static auto line_location_idx = elem_type->FieldOffset("line_location");
+
+	auto rval = make_intrusive<VectorVal>(backtrace_type);
+
+	for ( auto it = call_stack.rbegin(); it != call_stack.rend(); ++it )
+		{
+		auto elem = make_intrusive<RecordVal>(elem_type);
+		const auto& ci = *it;
+
+		const auto& params = ci.func->GetType()->Params();
+		auto args = MakeCallArgumentVector(ci.args, params);
+
+		elem->Assign<StringVal>(function_name_idx, ci.func->Name());
+		elem->Assign(function_args_idx, std::move(args));
+
+		if ( ci.call )
+			{
+			auto loc = ci.call->GetLocationInfo();
+			elem->Assign<StringVal>(file_location_idx, loc->filename);
+			elem->Assign(line_location_idx, val_mgr->Count(loc->first_line));
+			}
+
+		rval->Assign(rval->Size(), std::move(elem));
+		}
+
+	return rval;
+	%}
 
 # ===========================================================================
 #

testing/btest/Baseline/bifs.backtrace/out

@@ -0,0 +1,13 @@
+
+--- Backtrace ---
+#0: print_bt() at /home/jon/pro/zeek/zeek/testing/btest/.tmp/bifs.backtrace/backtrace.zeek:26
+#1: zeek_init()
+
+--- Backtrace ---
+| #0: print_bt() at /home/jon/pro/zeek/zeek/testing/btest/.tmp/bifs.backtrace/backtrace.zeek:20 | #1: bar() at /home/jon/pro/zeek/zeek/testing/btest/.tmp/bifs.backtrace/backtrace.zeek:27 | #2: zeek_init() |
+
+--- Backtrace ---
+#0: print_bt(show_args: bool = T, one_line: bool = F) at /home/jon/pro/zeek/zeek/testing/btest/.tmp/bifs.backtrace/backtrace.zeek:15
+#1: foo(c: count = 444) at /home/jon/pro/zeek/zeek/testing/btest/.tmp/bifs.backtrace/backtrace.zeek:21
+#2: bar(a: string = asdf, b: bool = T) at /home/jon/pro/zeek/zeek/testing/btest/.tmp/bifs.backtrace/backtrace.zeek:27
+#3: zeek_init()

testing/btest/Baseline/coverage.default-load-baseline/canonified_loaded_scripts.log

@@ -3,7 +3,7 @@
 #empty_field	(empty)
 #unset_field	-
 #path	loaded_scripts
-#open	2019-10-15-01-48-24
+#open	2020-07-03-21-08-52
 #fields	name
 #types	string
 scripts/base/init-bare.zeek
@@ -189,6 +189,7 @@ scripts/base/init-default.zeek
   scripts/base/utils/active-http.zeek
     scripts/base/utils/exec.zeek
   scripts/base/utils/addrs.zeek
+  scripts/base/utils/backtrace.zeek
   scripts/base/utils/conn-ids.zeek
   scripts/base/utils/dir.zeek
     scripts/base/frameworks/reporter/__load__.zeek
@@ -381,4 +382,4 @@ scripts/base/init-default.zeek
   scripts/base/misc/find-filtered-trace.zeek
   scripts/base/misc/version.zeek
 scripts/policy/misc/loaded-scripts.zeek
-#close	2019-10-15-01-48-25
+#close	2020-07-03-21-08-52

testing/btest/Baseline/plugins.hooks/output

@@ -282,7 +282,7 @@
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::__create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> <no result>
-0.000000   MetaHookPost  CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
+0.000000   MetaHookPost  CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Broker::LOG)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Cluster::LOG)) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::add_default_filter, <frame>, (Config::LOG)) -> <no result>
@@ -463,7 +463,7 @@
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> <no result>
 0.000000   MetaHookPost  CallFunction(Log::create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> <no result>
-0.000000   MetaHookPost  CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
+0.000000   MetaHookPost  CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) -> <no result>
 0.000000   MetaHookPost  CallFunction(NetControl::check_plugins, <frame>, ()) -> <no result>
 0.000000   MetaHookPost  CallFunction(NetControl::init, <null>, ()) -> <no result>
 0.000000   MetaHookPost  CallFunction(Notice::want_pp, <frame>, ()) -> <no result>
@@ -808,6 +808,7 @@
 0.000000   MetaHookPost  LoadFile(0, base<...>/analyzer) -> -1
 0.000000   MetaHookPost  LoadFile(0, base<...>/analyzer.bif.zeek) -> -1
 0.000000   MetaHookPost  LoadFile(0, base<...>/api.zeek) -> -1
+0.000000   MetaHookPost  LoadFile(0, base<...>/backtrace.zeek) -> -1
 0.000000   MetaHookPost  LoadFile(0, base<...>/bif) -> -1
 0.000000   MetaHookPost  LoadFile(0, base<...>/broker) -> -1
 0.000000   MetaHookPost  LoadFile(0, base<...>/cluster) -> -1
@@ -1203,7 +1204,7 @@
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]))
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]))
 0.000000   MetaHookPre   CallFunction(Log::__create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]))
-0.000000   MetaHookPre   CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T]))
+0.000000   MetaHookPre   CallFunction(Log::__write, <frame>, (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T]))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Broker::LOG))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Cluster::LOG))
 0.000000   MetaHookPre   CallFunction(Log::add_default_filter, <frame>, (Config::LOG))
@@ -1384,7 +1385,7 @@
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird]))
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509]))
 0.000000   MetaHookPre   CallFunction(Log::create_stream, <frame>, (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql]))
-0.000000   MetaHookPre   CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T]))
+0.000000   MetaHookPre   CallFunction(Log::write, <frame>, (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T]))
 0.000000   MetaHookPre   CallFunction(NetControl::check_plugins, <frame>, ())
 0.000000   MetaHookPre   CallFunction(NetControl::init, <null>, ())
 0.000000   MetaHookPre   CallFunction(Notice::want_pp, <frame>, ())
@@ -1729,6 +1730,7 @@
 0.000000   MetaHookPre   LoadFile(0, base<...>/analyzer)
 0.000000   MetaHookPre   LoadFile(0, base<...>/analyzer.bif.zeek)
 0.000000   MetaHookPre   LoadFile(0, base<...>/api.zeek)
+0.000000   MetaHookPre   LoadFile(0, base<...>/backtrace.zeek)
 0.000000   MetaHookPre   LoadFile(0, base<...>/bif)
 0.000000   MetaHookPre   LoadFile(0, base<...>/broker)
 0.000000   MetaHookPre   LoadFile(0, base<...>/cluster)
@@ -2123,7 +2125,7 @@
 0.000000 | HookCallFunction Log::__create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])
 0.000000 | HookCallFunction Log::__create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])
 0.000000 | HookCallFunction Log::__create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])
-0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])
+0.000000 | HookCallFunction Log::__write(PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])
 0.000000 | HookCallFunction Log::add_default_filter(Broker::LOG)
 0.000000 | HookCallFunction Log::add_default_filter(Cluster::LOG)
 0.000000 | HookCallFunction Log::add_default_filter(Config::LOG)
@@ -2304,7 +2306,7 @@
 0.000000 | HookCallFunction Log::create_stream(Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])
 0.000000 | HookCallFunction Log::create_stream(X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])
 0.000000 | HookCallFunction Log::create_stream(mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])
-0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])
+0.000000 | HookCallFunction Log::write(PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])
 0.000000 | HookCallFunction NetControl::check_plugins()
 0.000000 | HookCallFunction NetControl::init()
 0.000000 | HookCallFunction Notice::want_pp()
@@ -2661,6 +2663,7 @@
 0.000000 | HookLoadFile  base<...>/analyzer
 0.000000 | HookLoadFile  base<...>/analyzer.bif.zeek
 0.000000 | HookLoadFile  base<...>/api.zeek
+0.000000 | HookLoadFile  base<...>/backtrace.zeek
 0.000000 | HookLoadFile  base<...>/bif
 0.000000 | HookLoadFile  base<...>/broker
 0.000000 | HookLoadFile  base<...>/cluster
@@ -2756,7 +2759,7 @@
 0.000000 | HookLoadFile  base<...>/xmpp
 0.000000 | HookLoadFile  base<...>/zeek.bif.zeek
 0.000000 | HookLogInit   packet_filter 1/1 {ts (time), node (string), filter (string), init (bool), success (bool)}
-0.000000 | HookLogWrite  packet_filter [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T]
+0.000000 | HookLogWrite  packet_filter [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T]
 0.000000 | HookQueueEvent NetControl::init()
 0.000000 | HookQueueEvent filter_change_tracking()
 0.000000 | HookQueueEvent zeek_init()

testing/btest/bifs/backtrace.zeek

@@ -0,0 +1,28 @@
+# @TEST-EXEC: zeek -b %INPUT >out
+# @TEST-EXEC: TEST_DIFF_CANONIFIER=$SCRIPTS/diff-remove-abspath btest-diff out
+
+@load base/utils/backtrace
+
+function print_bt(show_args: bool, one_line: bool)
+	{
+	print "";
+	print "--- Backtrace ---";
+	print_backtrace(show_args, one_line, "|", 2);
+	}
+
+function foo(c: count)
+	{
+	print_bt(T, F);
+	}
+
+function bar(a: string, b: bool)
+	{
+	print_bt(F, T);
+	foo(444);
+	}
+
+event zeek_init()
+	{
+	print_bt(F, F);
+	bar("asdf", T);
+	}