Line numbers, error reporting and backtraces

The AST ruby creates when parsing your code doesn't contain that much information regarding its format. In particular, it only stores one line number per node. Why care? It turns out that this is what Ruby needs to generate meaningful backtrace info and report events to the trace_func and/or event_hook*1.

When you have chained method calls with multi-line blocks, the line numbers reported by Ruby will often be wrong:

class Object; def foo; caller end end

a = foo do     # line 3, this is where Ruby tells us the last #foo call
  #            # is being performed from
  #
end.foo do
  #
end.foo        # <--- when it's actually here (line 8)

p a
# >> ["-:3"]

I patched ruby to set the NODE line number to the last line (the one with the end block delimiter), which helps with chained calls, but might be a bit confusing regarding LINE events.

I used this program to show the events reported by Ruby to the trace_func and print the call stack at each point:

class Object
  def foo; 1 end
end
set_trace_func lambda { |event, file, line, id, binding, classname|
  puts "=" * 40
  puts "%8s :%-2d %5s %8s" % [event, line, id, classname]
  puts caller.map{|x| x.inspect}
}

foo do                   # line 11
 1
end.foo do               # line 13
 2
end

[ 
  1,                     # line 18
  2, 
  3 + 4.
  
  abs, 4
].foo                    # line 23

These are the events and backtrace information generated with the above script, for both the unpatched interpreter and the modified one, side by side:

 
            Normal                                  Patched 
 
 ======================================================================
     line :11          false                 line :13          false
 "test_nd_line.rb:11"                    "test_nd_line.rb:13"
 "test_nd_line.rb:11"                    "test_nd_line.rb:13"
 ======================================================================
     call :3    foo   Object                 call :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:11"                    "test_nd_line.rb:11"
 ======================================================================
     line :3    foo   Object                 line :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:11"                    "test_nd_line.rb:11"
 ======================================================================
   return :3    foo   Object               return :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:11"                    "test_nd_line.rb:11"
 ======================================================================
     call :3    foo   Object                 call :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:11"                    "test_nd_line.rb:13"              <--- THIS IS GOOD
 ======================================================================
     line :3    foo   Object                 line :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:11"                    "test_nd_line.rb:13"
 ======================================================================
   return :3    foo   Object               return :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:11"                    "test_nd_line.rb:13"
 ======================================================================
     line :18          false                 line :23          false
 "test_nd_line.rb:18"                    "test_nd_line.rb:23"
 "test_nd_line.rb:18"                    "test_nd_line.rb:23"
 ======================================================================
   c-call :20   abs   Fixnum               c-call :22   abs   Fixnum
 "test_nd_line.rb:20"                    "test_nd_line.rb:22"
 ======================================================================
 c-return :20   abs   Fixnum             c-return :22   abs   Fixnum
 "test_nd_line.rb:20"                    "test_nd_line.rb:22"
 ======================================================================
   c-call :22     +   Fixnum               c-call :22     +   Fixnum
 "test_nd_line.rb:22"                    "test_nd_line.rb:22"
 ======================================================================
 c-return :22     +   Fixnum             c-return :22     +   Fixnum
 "test_nd_line.rb:22"                    "test_nd_line.rb:22"
 ======================================================================
     call :3    foo   Object                 call :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:18"                    "test_nd_line.rb:23"
 ======================================================================
     line :3    foo   Object                 line :3    foo   Object
 "test_nd_line.rb:3:in `foo'"            "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:18"                    "test_nd_line.rb:23"
 ======================================================================
   return :3    foo   Object             return :3    foo   Object
 "test_nd_line.rb:3:in `foo'             "test_nd_line.rb:3:in `foo'"
 "test_nd_line.rb:18"                    "test_nd_line.rb:23"

Which one looks better to you? I think that, all in all, reporting chained calls correctly is probably more important than making LINE events look good: set_trace_func is rarely used, but we have to read the backtrace every time we leave an exception uncaught...

I'll probably submit this to ruby-core once matz's large commit is digested:

Index: parse.y
===================================================================
RCS file: /src/ruby/parse.y,v
retrieving revision 1.307.2.34
diff -p -u -r1.307.2.34 parse.y
--- parse.y	19 Apr 2006 04:57:55 -0000	1.307.2.34
+++ parse.y	14 Jun 2006 09:21:41 -0000
@@ -1800,13 +1800,15 @@ block_call	: command do_block
 			$$ = $2;
 		        fixpos($$, $1);
 		    }
-		| block_call '.' operation2 opt_paren_args
+		| block_call '.' operation2 {$<num>2 = ruby_sourceline; } opt_paren_args
 		    {
-			$$ = new_call($1, $3, $4);
+			$$ = new_call($1, $3, $5);
+			nd_set_line($$, $<num>2);
 		    }
-		| block_call tCOLON2 operation2 opt_paren_args
+		| block_call tCOLON2 operation2 {$<num>2 = ruby_sourceline; } opt_paren_args
 		    {
-			$$ = new_call($1, $3, $4);
+			$$ = new_call($1, $3, $5);
+			nd_set_line($$, $<num>2);
 		    }
 		;
 
@@ -1815,17 +1817,19 @@ method_call	: operation paren_args
 			$$ = new_fcall($1, $2);
 		        fixpos($$, $2);
 		    }
-		| primary_value '.' operation2 opt_paren_args
+		| primary_value '.' operation2 {$<num>2 = ruby_sourceline; } opt_paren_args
 		    {
-			$$ = new_call($1, $3, $4);
+			$$ = new_call($1, $3, $5);
 		        fixpos($$, $1);
+			nd_set_line($$, $<num>2);
 		    }
-		| primary_value tCOLON2 operation2 paren_args
+		| primary_value tCOLON2 operation2 {$<num>2 = ruby_sourceline; } paren_args
 		    {
-			$$ = new_call($1, $3, $4);
+			$$ = new_call($1, $3, $5);
 		        fixpos($$, $1);
+			nd_set_line($$, $<num>2);
 		    }
-		| primary_value tCOLON2 operation3
+		| primary_value tCOLON2 operation3 
 		    {
 			$$ = new_call($1, $3, 0);
 		    }

Trace Object? - Daniel Berger (2006-06-14 (Wed) 12:52:41)

If we're going to modify this, I vote we go all the way and provide StackTrace objects, instead of mucking around with string parsing.

- Dan

Chris 2006-06-14 (Wed) 13:23:03

And offsets, not just line numbers

mfp 2006-06-14 (Wed) 14:02:30

I posted something like that (trivially extensible to create such StackTrace objects) recently, see A better Kernel#caller.

This posting wasn't as much about Kernel#caller as about the information passed to the trace_func & exception backtraces being accurate --- i.e. I was talking about a change in the accuracy axis, StackTrace being along the "convenience/usability" one.

That said, I'm all for non-textual, usable, accurate/meaningful stack traces.