GH-210: improve call stack tracking

Adds tracking of arguments

CHANGES

@@ -1,4 +1,8 @@
 
+2.6-108 | 2019-01-28 14:11:19 -0600
+
+  * GH-210: improve call stack tracking w/ argument info (Jon Siwek, Corelight)
+
 2.6-106 | 2019-01-24 17:53:03 -0600
 
   * Fix building with LibreSSL again (Jon Siwek, Corelight)

VERSION

@@ -1 +1 @@
-2.6-106
+2.6-108

src/Expr.cc

@@ -4839,28 +4839,17 @@ Val* CallExpr::Eval(Frame* f) const
 		{
 		const ::Func* func = func_val->AsFunc();
 		const CallExpr* current_call = f ? f->GetCall() : 0;
-		call_stack.emplace_back(CallInfo{this, func});
 
 		if ( f )
 			f->SetCall(this);
 
-		try
-			{
-			ret = func->Call(v, f);
-			}
-		catch ( ... )
-			{
-			call_stack.pop_back();
-			throw;
-			}
+		ret = func->Call(v, f);
 
 		if ( f )
 			f->SetCall(current_call);
 
 		// Don't Unref() the arguments, as Func::Call already did that.
 		delete v;
-
-		call_stack.pop_back();
 		}
 	else
 		delete_vals(v);

src/Func.cc

@@ -70,9 +70,32 @@ std::string render_call_stack()
 			rval += " | ";
 
 		auto& ci = *it;
-		auto loc = ci.call->GetLocationInfo();
 		auto name = ci.func->Name();
-		rval += fmt("#%d %s() at %s:%d", lvl, name, loc->filename, loc->first_line);
+		std::string arg_desc;
+
+		if ( ci.args )
+			{
+			loop_over_list(*ci.args, i)
+				{
+				ODesc d;
+				d.SetShort();
+				(*ci.args)[i]->Describe(&d);
+
+				if ( ! arg_desc.empty() )
+					arg_desc += ", ";
+
+				arg_desc += d.Description();
+				}
+			}
+
+		rval += fmt("#%d %s(%s)", lvl, name, arg_desc.data());
+
+		if ( ci.call )
+			{
+			auto loc = ci.call->GetLocationInfo();
+			rval += fmt(" at %s:%d", loc->filename, loc->first_line);
+			}
+
 		++lvl;
 		}
 
@@ -399,6 +422,8 @@ Val* BroFunc::Call(val_list* args, Frame* parent) const
 		}
 
 	g_frame_stack.push_back(f);	// used for backtracing
+	const CallExpr* call_expr = parent ? parent->GetCall() : nullptr;
+	call_stack.emplace_back(CallInfo{call_expr, this, args});
 
 	if ( g_trace_state.DoTrace() )
 		{
@@ -470,6 +495,8 @@ Val* BroFunc::Call(val_list* args, Frame* parent) const
 			}
 		}
 
+	call_stack.pop_back();
+
 	// We have an extra Ref for each argument (so that they don't get
 	// deleted between bodies), release that.
 	loop_over_list(*args, k)
@@ -625,7 +652,11 @@ Val* BuiltinFunc::Call(val_list* args, Frame* parent) const
 		g_trace_state.LogTrace("\tBuiltin Function called: %s\n", d.Description());
 		}
 
+	const CallExpr* call_expr = parent ? parent->GetCall() : nullptr;
+	call_stack.emplace_back(CallInfo{call_expr, this, args});
 	Val* result = func(parent, args);
+	call_stack.pop_back();
+
 	loop_over_list(*args, i)
 		Unref((*args)[i]);
 
@@ -663,9 +694,18 @@ bool BuiltinFunc::DoUnserialize(UnserialInfo* info)
 
 void builtin_error(const char* msg, BroObj* arg)
 	{
+	auto emit = [=](const CallExpr* ce)
+		{
+		if ( ce )
+			ce->Error(msg, arg);
+		else
+			reporter->Error(msg, arg);
+		};
+
+
 	if ( call_stack.empty() )
 		{
-		reporter->Error(msg, arg);
+		emit(nullptr);
 		return;
 		}
 
@@ -674,13 +714,12 @@ void builtin_error(const char* msg, BroObj* arg)
 	if ( call_stack.size() < 2 )
 		{
 		// Don't need to check for wrapper function like "<module>::__<func>"
-		last_call.call->Error(msg, arg);
+		emit(last_call.call);
 		return;
 		}
 
 	auto starts_with_double_underscore = [](const std::string& name) -> bool
 		{ return name.size() > 2 && name[0] == '_' && name[1] == '_'; };
-	auto last_loc = last_call.call->GetLocationInfo();
 	std::string last_func = last_call.func->Name();
 
 	auto pos = last_func.find_first_of("::");
@@ -690,7 +729,7 @@ void builtin_error(const char* msg, BroObj* arg)
 		{
 		if ( ! starts_with_double_underscore(last_func) )
 			{
-			last_call.call->Error(msg, arg);
+			emit(last_call.call);
 			return;
 			}
 
@@ -703,7 +742,7 @@ void builtin_error(const char* msg, BroObj* arg)
 
 		if ( ! starts_with_double_underscore(func_name) )
 			{
-			last_call.call->Error(msg, arg);
+			emit(last_call.call);
 			return;
 			}
 
@@ -714,9 +753,9 @@ void builtin_error(const char* msg, BroObj* arg)
 	auto parent_func = parent_call.func->Name();
 
 	if ( wrapper_func == parent_func )
-		parent_call.call->Error(msg, arg);
+		emit(parent_call.call);
 	else
-		last_call.call->Error(msg, arg);
+		emit(last_call.call);
 	}
 
 #include "bro.bif.func_h"

src/Func.h

@@ -143,6 +143,7 @@ extern bool check_built_in_call(BuiltinFunc* f, CallExpr* call);
 struct CallInfo {
 	const CallExpr* call;
 	const Func* func;
+	const val_list* args;
 };
 
 extern vector<CallInfo> call_stack;

testing/btest/Baseline/language.index-assignment-invalid/out

@@ -1,5 +1,5 @@
-internal error in /Users/jon/projects/bro/bro/scripts/base/utils/queue.bro, line 152: vector index assignment failed for invalid type 'myrec', value: [a=T, b=hi, c=<uninitialized>] (Queue::ret[Queue::j]), call stack: 
- #0 Queue::get_vector() at /Users/jon/projects/bro/bro/testing/btest/.tmp/language.index-assignment-invalid/index-assignment-invalid.bro:19 
- #1 bar() at /Users/jon/projects/bro/bro/testing/btest/.tmp/language.index-assignment-invalid/index-assignment-invalid.bro:27 
- #2 foo() at /Users/jon/projects/bro/bro/testing/btest/.tmp/language.index-assignment-invalid/index-assignment-invalid.bro:39 
-
+internal error in /home/jon/pro/zeek/zeek/scripts/base/utils/queue.bro, line 152: vector index assignment failed for invalid type 'myrec', value: [a=T, b=hi, c=<uninitialized>] (Queue::ret[Queue::j]), call stack: 
+ #0 Queue::get_vector([initialized=T, vals={[2] = test,[6] = jkl;,[4] = asdf,[1] = goodbye,[5] = 3,[0] = hello,[3] = [a=T, b=hi, c=<uninitialized>]}, settings=[max_len=<uninitialized>], top=7, bottom=0, size=0], [hello, goodbye, test]) at /home/jon/pro/zeek/zeek/testing/btest/.tmp/language.index-assignment-invalid/index-assignment-invalid.bro:19 
+ #1 bar(55) at /home/jon/pro/zeek/zeek/testing/btest/.tmp/language.index-assignment-invalid/index-assignment-invalid.bro:27 
+ #2 foo(hi, 13) at /home/jon/pro/zeek/zeek/testing/btest/.tmp/language.index-assignment-invalid/index-assignment-invalid.bro:39 
+ #3 bro_init() 

testing/btest/language/index-assignment-invalid.bro

@@ -13,7 +13,7 @@ type myrec: record {
 	c: string &optional;
 };
 
-function bar()
+function bar(c: count)
 	{
 	local rval: vector of string = vector();
 	Queue::get_vector(q, rval);
@@ -22,9 +22,9 @@ function bar()
 	print rval;
 	}
 
-function foo()
+function foo(s: string, c: count)
 	{
-	bar();
+	bar(c + 42);
 	}
 
 event bro_init()
@@ -36,5 +36,5 @@ event bro_init()
 	Queue::put(q, "asdf");
 	Queue::put(q, 3);
 	Queue::put(q, "jkl;");
-	foo();
+	foo("hi", 13);
 	}