2271 - bugfix: traces cross-contaminating errors

There were several places where we push a call on to a routine without
incrementing call-stack depth, which was used to compute the depth at
which to trace an instruction. So sometimes you ended up one depth lower
than you started a call with. Do this enough times and instructions that
should be traced at level 100 end up at level 0 and pop up as errors.

Solution: since call-stack depth is only used for tracing, include it in
the trace stream and make sure we reset it along with the trace stream.
Then catch all places where we forget to increment call-stack depth and
make sure we catch such places in the future.

When I first ran into this with Caleb I thought there must be some way
that we're writing some output into the warnings result. I didn't
recognize that the spurious output as part of the trace, just at the
wrong level.

9 files changed, 62 insertions, 17 deletions

diff --git a/003trace.cc b/003trace.cc
index 0193fa4f..2eab9017 100644
--- a/003trace.cc
+++ b/003trace.cc
@@ -108,9 +108,10 @@ struct trace_stream {
   ostringstream* curr_stream;
   string curr_label;
   int curr_depth;
+  int callstack_depth;
   int collect_depth;
   ofstream null_stream;  // never opens a file, so writes silently fail
-  trace_stream() :curr_stream(NULL), curr_depth(0), collect_depth(Max_depth) {}
+  trace_stream() :curr_stream(NULL), curr_depth(Max_depth), callstack_depth(0), collect_depth(Max_depth) {}
   ~trace_stream() { if (curr_stream) delete curr_stream; }
 
   ostream& stream(string label) {
@@ -147,9 +148,7 @@ struct trace_stream {
     label = trim(label);
     for (vector<trace_line>::iterator p = past_lines.begin(); p != past_lines.end(); ++p)
       if (label.empty() || label == p->label) {
-        if (p->depth)
-          output << std::setw(4) << p->depth << ' ';
-        output << p->label << ": " << p->contents << '\n';
+        output << std::setw(4) << p->depth << ' ' << p->label << ": " << p->contents << '\n';
       }
     return output.str();
   }
@@ -359,15 +358,12 @@ using std::ofstream;
 :(before "End Globals")
 //: In future layers we'll use the depth field as follows:
 //:
-//: Mu 'applications' will be able to use depths 1-100 as they like.
+//: Errors will be depth 0.
+//: Warnings will be depth 1.
+//: Mu 'applications' will be able to use depths 2-100 as they like.
 //: Primitive statements will occupy 101-9998
 const int Initial_callstack_depth = 101;
 const int Max_callstack_depth = 9998;
-//: (ignore this until the call layer)
-:(before "End Globals")
-int Callstack_depth = 0;
-:(before "End Setup")
-Callstack_depth = 0;
 //: Finally, details of primitive mu statements will occupy depth 9999 (more on that later as well)
 :(before "End Globals")
 const int Primitive_recipe_depth = 9999;
diff --git a/020run.cc b/020run.cc
index c08049a0..8f471b56 100644
--- a/020run.cc
+++ b/020run.cc
@@ -62,7 +62,7 @@ void run_current_routine()
     // Running One Instruction
 //?     Instructions_running[current_recipe_name()]++;
     if (current_instruction().is_label) { ++current_step_index(); continue; }
-    trace(Initial_callstack_depth+Callstack_depth, "run") << current_instruction().to_string() << end();
+    trace(Initial_callstack_depth + Trace_stream->callstack_depth, "run") << current_instruction().to_string() << end();
     if (Memory[0] != 0) {
       raise_error << "something wrote to location 0; this should never happen\n" << end();
       Memory[0] = 0;
diff --git a/029tools.cc b/029tools.cc
index 48e62466..8c22ad44 100644
--- a/029tools.cc
+++ b/029tools.cc
@@ -162,7 +162,7 @@ case _CLEAR_TRACE: {
 }
 :(before "End Primitive Recipe Implementations")
 case _CLEAR_TRACE: {
-  CLEAR_TRACE;
+  if (Trace_stream) Trace_stream->past_lines.clear();
   break;
 }
 
diff --git a/034call.cc b/034call.cc
index ebfb9534..11dc326e 100644
--- a/034call.cc
+++ b/034call.cc
@@ -55,6 +55,11 @@ struct routine {
 };
 :(code)
 routine::routine(recipe_ordinal r) {
+  if (Trace_stream) {
+    ++Trace_stream->callstack_depth;
+    trace("trace") << "new routine; incrementing callstack depth to " << Trace_stream->callstack_depth << end();
+    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   calls.push_front(call(r));
   // End routine Constructor
 }
@@ -91,10 +96,13 @@ default: {
     continue;
   }
   // not a primitive; look up the book of recipes
+  if (Trace_stream) {
+    ++Trace_stream->callstack_depth;
+    trace("trace") << "incrementing callstack depth to " << Trace_stream->callstack_depth << end();
+    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   Current_routine->calls.push_front(call(current_instruction().operation));
   call_housekeeping:
-  ++Callstack_depth;
-  assert(Callstack_depth < 9000);  // 9998-101 plus cushion
   continue;  // not done with caller; don't increment current_step_index()
 }
 
@@ -129,7 +137,11 @@ inline const vector<instruction>& routine::steps() const {
 // it, and the one below that, and so on
 while (current_step_index() >= SIZE(Current_routine->steps())) {
   // Falling Through End Of Recipe
-  --Callstack_depth;
+  if (Trace_stream) {
+    trace("trace") << "fall-through: exiting " << current_recipe_name() << "; decrementing callstack depth from " << Trace_stream->callstack_depth << end();
+    --Trace_stream->callstack_depth;
+    assert(Trace_stream->callstack_depth >= 0);
+  }
   Current_routine->calls.pop_front();
   if (Current_routine->calls.empty()) return;
   // Complete Call Fallthrough
diff --git a/036call_reply.cc b/036call_reply.cc
index ccf18a2f..e2e34c06 100644
--- a/036call_reply.cc
+++ b/036call_reply.cc
@@ -25,7 +25,11 @@ case REPLY: {
   // Starting Reply
   const instruction& reply_inst = current_instruction();  // save pointer into recipe before pop
   const string& callee = current_recipe_name();
-  --Callstack_depth;
+  if (Trace_stream) {
+    trace("trace") << "reply: decrementing callstack depth from " << Trace_stream->callstack_depth << end();
+    --Trace_stream->callstack_depth;
+    assert(Trace_stream->callstack_depth >= 0);
+  }
   Current_routine->calls.pop_front();
   // just in case 'main' returns a value, drop it for now
   if (Current_routine->calls.empty()) goto stop_running_current_routine;
diff --git a/037recipe.cc b/037recipe.cc
index 55522bd9..2c5d7d81 100644
--- a/037recipe.cc
+++ b/037recipe.cc
@@ -55,6 +55,11 @@ case CALL: {
 :(before "End Primitive Recipe Implementations")
 case CALL: {
   // Begin Call
+  if (Trace_stream) {
+    ++Trace_stream->callstack_depth;
+    trace("trace") << "indirect 'call': incrementing callstack depth to " << Trace_stream->callstack_depth << end();
+    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   Current_routine->calls.push_front(call(ingredients.at(0).at(0)));
   ingredients.erase(ingredients.begin());  // drop the callee
   goto call_housekeeping;
diff --git a/050scenario.cc b/050scenario.cc
index 6dbd9f56..bf3b75e7 100644
--- a/050scenario.cc
+++ b/050scenario.cc
@@ -200,6 +200,11 @@ case RUN: {
   vector<recipe_ordinal> tmp_recipe = load(tmp.str());
   bind_special_scenario_names(tmp_recipe.at(0));
   transform_all();
+  if (Trace_stream) {
+    ++Trace_stream->callstack_depth;
+    trace("trace") << "run: incrementing callstack depth to " << Trace_stream->callstack_depth << end();
+    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   Current_routine->calls.push_front(call(tmp_recipe.at(0)));
   continue;  // not done with caller; don't increment current_step_index()
 }
diff --git a/053continuation.cc b/053continuation.cc
index 9ccd6311..8de32f0f 100644
--- a/053continuation.cc
+++ b/053continuation.cc
@@ -53,6 +53,11 @@ case CONTINUE_FROM: {
 :(before "End Primitive Recipe Implementations")
 case CONTINUE_FROM: {
   long long int c = ingredients.at(0).at(0);
+  if (Trace_stream) {
+    Trace_stream->callstack_depth += SIZE(Continuation[c]);
+    trace("trace") << "continuation; growing callstack depth to " << Trace_stream->callstack_depth << end();
+    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   Current_routine->calls = Continuation[c];  // deep copy; calls have no pointers
   continue;  // skip rest of this instruction
 }
@@ -186,6 +191,11 @@ case CREATE_DELIMITED_CONTINUATION: {
 }
 :(before "End Primitive Recipe Implementations")
 case CREATE_DELIMITED_CONTINUATION: {
+  if (Trace_stream) {
+    ++Trace_stream->callstack_depth;
+    trace("trace") << "delimited continuation; incrementing callstack depth to " << Trace_stream->callstack_depth << end();
+    assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   Current_routine->calls.front().is_reset = true;
   Current_routine->calls.push_front(call(Recipe_ordinal[current_instruction().ingredients.at(0).name]));
   ingredients.erase(ingredients.begin());  // drop the callee
@@ -225,7 +235,10 @@ case REPLY_DELIMITED_CONTINUATION: {
   }
   Delimited_continuation[Next_delimited_continuation_id] = call_stack(Current_routine->calls.begin(), reset);
   while (Current_routine->calls.begin() != reset) {
-    --Callstack_depth;
+    if (Trace_stream) {
+      --Trace_stream->callstack_depth;
+      assert(Trace_stream->callstack_depth >= 0);
+    }
     Current_routine->calls.pop_front();
   }
   // return it as the result of the 'reset' call
@@ -255,6 +268,11 @@ call_stack::iterator find_reset(call_stack& c) {
     const call_stack& new_calls = Delimited_continuation[ingredients.at(0).at(0)];
     for (call_stack::const_reverse_iterator p = new_calls.rbegin(); p != new_calls.rend(); ++p)
       Current_routine->calls.push_front(*p);
+    if (Trace_stream) {
+      Trace_stream->callstack_depth += SIZE(new_calls);
+      trace("trace") << "calling delimited continuation; growing callstack depth to " << Trace_stream->callstack_depth << end();
+      assert(Trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+    }
     ++current_step_index();  // skip past the reply-delimited-continuation
     ingredients.erase(ingredients.begin());  // drop the callee
     goto call_housekeeping;
diff --git a/081run_interactive.cc b/081run_interactive.cc
index dc46cf1f..ced4f763 100644
--- a/081run_interactive.cc
+++ b/081run_interactive.cc
@@ -98,6 +98,11 @@ bool run_interactive(long long int address) {
   if (trace_count("error") > 0) return false;
   // now call 'sandbox' which will run 'interactive' in a separate routine,
   // and wait for it
+  if (Save_trace_stream) {
+    ++Save_trace_stream->callstack_depth;
+    trace("trace") << "run-interactive: incrementing callstack depth to " << Save_trace_stream->callstack_depth << end();
+    assert(Save_trace_stream->callstack_depth < 9000);  // 9998-101 plus cushion
+  }
   Current_routine->calls.push_front(call(Recipe_ordinal["sandbox"]));
   return true;
 }