From a1c19840ce440736d2268651de0916e2be2301e6 Mon Sep 17 00:00:00 2001 From: Jon Siwek Date: Thu, 2 Jul 2020 15:15:52 -0700 Subject: [PATCH] Add backtrace() and print_backtrace() --- scripts/base/init-bare.zeek | 23 +++++- scripts/base/init-default.zeek | 1 + scripts/base/utils/backtrace.zeek | 78 +++++++++++++++++++ src/EventHandler.cc | 28 +------ src/ZeekArgs.cc | 37 +++++++++ src/ZeekArgs.h | 13 +++- src/zeek.bif | 40 ++++++++++ testing/btest/Baseline/bifs.backtrace/out | 13 ++++ .../canonified_loaded_scripts.log | 5 +- testing/btest/Baseline/plugins.hooks/output | 17 ++-- testing/btest/bifs/backtrace.zeek | 28 +++++++ 11 files changed, 242 insertions(+), 41 deletions(-) create mode 100644 scripts/base/utils/backtrace.zeek create mode 100644 testing/btest/Baseline/bifs.backtrace/out create mode 100644 testing/btest/bifs/backtrace.zeek diff --git a/scripts/base/init-bare.zeek b/scripts/base/init-bare.zeek index a02a676df9..edef9350a8 100644 --- a/scripts/base/init-bare.zeek +++ b/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? # diff --git a/scripts/base/init-default.zeek b/scripts/base/init-default.zeek index 52fe7dca8a..b7d1b01b99 100644 --- a/scripts/base/init-default.zeek +++ b/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 diff --git a/scripts/base/utils/backtrace.zeek b/scripts/base/utils/backtrace.zeek new file mode 100644 index 0000000000..b1ac24a921 --- /dev/null +++ b/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]; + } + } diff --git a/src/EventHandler.cc b/src/EventHandler.cc index 830a031f0e..ba834d4d68 100644 --- a/src/EventHandler.cc +++ b/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(); - static auto call_argument_vector = zeek::id::find_type("call_argument_vector"); - auto vargs = zeek::make_intrusive(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("call_argument"); - auto rec = zeek::make_intrusive(call_argument); - rec->Assign(0, zeek::make_intrusive(fname)); - - ODesc d; - d.SetShort(); - ftype->Describe(&d); - rec->Assign(1, zeek::make_intrusive(d.Description())); - - if ( fdefault ) - rec->Assign(2, std::move(fdefault)); - - if ( i < static_cast(vl->size()) && (*vl)[i] ) - rec->Assign(3, (*vl)[i]); - - vargs->Assign(i, std::move(rec)); - } + auto vargs = zeek::MakeCallArgumentVector(*vl, GetType()->Params()); Event* ev = new Event(new_event, { zeek::make_intrusive(name), diff --git a/src/ZeekArgs.cc b/src/ZeekArgs.cc index 3f480427ef..397a707c29 100644 --- a/src/ZeekArgs.cc +++ b/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("call_argument_vector"); + + auto rval = make_intrusive(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("call_argument"); + auto rec = make_intrusive(call_argument); + rec->Assign(0, make_intrusive(fname)); + + ODesc d; + d.SetShort(); + ftype->Describe(&d); + rec->Assign(1, make_intrusive(d.Description())); + + if ( fdefault ) + rec->Assign(2, std::move(fdefault)); + + if ( i < static_cast(vals.size()) && vals[i] ) + rec->Assign(3, vals[i]); + + rval->Assign(i, std::move(rec)); + } + + return rval; + } diff --git a/src/ZeekArgs.h b/src/ZeekArgs.h index 6c54947de8..9abc9e3d36 100644 --- a/src/ZeekArgs.h +++ b/src/ZeekArgs.h @@ -5,12 +5,17 @@ #include #include "BroList.h" -ZEEK_FORWARD_DECLARE_NAMESPACED(Val, zeek); - namespace zeek { +class VectorVal; +class RecordType; template class IntrusivePtr; -using Args = std::vector>; + +using ValPtr = IntrusivePtr; +using VectorValPtr = IntrusivePtr; +using RecordTypePtr = IntrusivePtr; + +using Args = std::vector; /** * Converts a legacy-style argument list for use in modern Zeek function @@ -22,4 +27,6 @@ using Args = std::vector>; */ Args val_list_to_args(const val_list& vl); +VectorValPtr MakeCallArgumentVector(const Args& vals, const RecordTypePtr& types); + } // namespace zeek diff --git a/src/zeek.bif b/src/zeek.bif index a390bae068..79ded154ba 100644 --- a/src/zeek.bif +++ b/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("Backtrace"); + static auto elem_type = id::find_type("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(backtrace_type); + + for ( auto it = call_stack.rbegin(); it != call_stack.rend(); ++it ) + { + auto elem = make_intrusive(elem_type); + const auto& ci = *it; + + const auto& params = ci.func->GetType()->Params(); + auto args = MakeCallArgumentVector(ci.args, params); + + elem->Assign(function_name_idx, ci.func->Name()); + elem->Assign(function_args_idx, std::move(args)); + + if ( ci.call ) + { + auto loc = ci.call->GetLocationInfo(); + elem->Assign(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; + %} # =========================================================================== # diff --git a/testing/btest/Baseline/bifs.backtrace/out b/testing/btest/Baseline/bifs.backtrace/out new file mode 100644 index 0000000000..7ec7423519 --- /dev/null +++ b/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() diff --git a/testing/btest/Baseline/coverage.default-load-baseline/canonified_loaded_scripts.log b/testing/btest/Baseline/coverage.default-load-baseline/canonified_loaded_scripts.log index 5d9fbfde6d..e7ea377396 100644 --- a/testing/btest/Baseline/coverage.default-load-baseline/canonified_loaded_scripts.log +++ b/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 diff --git a/testing/btest/Baseline/plugins.hooks/output b/testing/btest/Baseline/plugins.hooks/output index c1e94ae6b1..fa53153c0c 100644 --- a/testing/btest/Baseline/plugins.hooks/output +++ b/testing/btest/Baseline/plugins.hooks/output @@ -282,7 +282,7 @@ 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> 0.000000 MetaHookPost CallFunction(Log::__create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> -0.000000 MetaHookPost CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])) -> +0.000000 MetaHookPost CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Broker::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Cluster::LOG)) -> 0.000000 MetaHookPost CallFunction(Log::add_default_filter, , (Config::LOG)) -> @@ -463,7 +463,7 @@ 0.000000 MetaHookPost CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) -> 0.000000 MetaHookPost CallFunction(Log::create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) -> 0.000000 MetaHookPost CallFunction(Log::create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -> -0.000000 MetaHookPost CallFunction(Log::write, , (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])) -> +0.000000 MetaHookPost CallFunction(Log::write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) -> 0.000000 MetaHookPost CallFunction(NetControl::check_plugins, , ()) -> 0.000000 MetaHookPost CallFunction(NetControl::init, , ()) -> 0.000000 MetaHookPost CallFunction(Notice::want_pp, , ()) -> @@ -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, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) 0.000000 MetaHookPre CallFunction(Log::__create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -0.000000 MetaHookPre CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])) +0.000000 MetaHookPre CallFunction(Log::__write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Broker::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Cluster::LOG)) 0.000000 MetaHookPre CallFunction(Log::add_default_filter, , (Config::LOG)) @@ -1384,7 +1385,7 @@ 0.000000 MetaHookPre CallFunction(Log::create_stream, , (Weird::LOG, [columns=Weird::Info, ev=Weird::log_weird, path=weird])) 0.000000 MetaHookPre CallFunction(Log::create_stream, , (X509::LOG, [columns=X509::Info, ev=X509::log_x509, path=x509])) 0.000000 MetaHookPre CallFunction(Log::create_stream, , (mysql::LOG, [columns=MySQL::Info, ev=MySQL::log_mysql, path=mysql])) -0.000000 MetaHookPre CallFunction(Log::write, , (PacketFilter::LOG, [ts=1591143698.178012, node=zeek, filter=ip or not ip, init=T, success=T])) +0.000000 MetaHookPre CallFunction(Log::write, , (PacketFilter::LOG, [ts=1593810429.768109, node=zeek, filter=ip or not ip, init=T, success=T])) 0.000000 MetaHookPre CallFunction(NetControl::check_plugins, , ()) 0.000000 MetaHookPre CallFunction(NetControl::init, , ()) 0.000000 MetaHookPre CallFunction(Notice::want_pp, , ()) @@ -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() diff --git a/testing/btest/bifs/backtrace.zeek b/testing/btest/bifs/backtrace.zeek new file mode 100644 index 0000000000..0647e35d96 --- /dev/null +++ b/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); + }