Wrong line numbers in Kernel#caller inside set_trace_func (with code to reproduce) #4051

Closed
ivoanjo opened this Issue Aug 6, 2016 · 5 comments

Comments

Projects
None yet
2 participants
@ivoanjo
Contributor

ivoanjo commented Aug 6, 2016

I was trying to see if I could get pry-nav to work with JRuby. It doesn't have a lot of features, but it's a straightforward use of set_trace_func and I wanted to experiment with it a bit.

I hit some issues, and investigating them led me to discover that when running code inside set_trace_func and then calling Kernel#caller (such as when stepping) leads to line numbers being wrong in the stack trace, which confuses pry.

Environment

Running jruby 9.1.2.0 (2.3.0) 2016-05-26 7357c8f OpenJDK 64-Bit Server VM 25.91-b14 on 1.8.0_91-8u91-b14-3ubuntu1~15.10.1-b14 [linux-x86_64] on Ubuntu 15.10.

Expected Behavior

Example code:

def sum(arg1, arg2)
  arg1 + arg2
end

def crazy_sums
  sum(1, 2)
end

set_trace_func proc { |type, _, line, *stuff|
  unless ['c-return', 'c-call'].include? type
    puts "Event #{type} @ #{line}, caller: #{caller.first}"
  end
}

crazy_sums

Output in MRI 2.3.1:

Event line @ 15, caller: test.rb:15:in `<main>'
Event call @ 5, caller: test.rb:5:in `crazy_sums'
Event line @ 6, caller: test.rb:6:in `crazy_sums'
Event call @ 1, caller: test.rb:1:in `sum'
Event line @ 2, caller: test.rb:2:in `sum'
Event return @ 3, caller: test.rb:3:in `sum'
Event return @ 7, caller: test.rb:7:in `crazy_sums'

With MRI, caller.first matches the line we get in set_trace_func.

Actual Behavior

Output in JRuby:

Event line @ 15, caller: test.rb:9:in `<top>'
Event call @ 5, caller: test.rb:15:in `crazy_sums'
Event line @ 6, caller: test.rb:15:in `crazy_sums'
Event call @ 1, caller: test.rb:6:in `sum'
Event line @ 2, caller: test.rb:6:in `sum'
Event return @ 3, caller: test.rb:2:in `sum'
Event return @ 7, caller: test.rb:6:in `crazy_sums'

With JRuby, the line numbers don't match the line we get in set_trace_func.

There is also a minor difference where MRI calls the top-level <main> while JRuby uses <top>. This seems minor, but I can report it as a separate issue if needed.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Aug 8, 2016

Member

Commit 44a2aa6 fixes us reporting top vs main. Throwing it on this issue versus making a new one.

Member

enebo commented Aug 8, 2016

Commit 44a2aa6 fixes us reporting top vs main. Throwing it on this issue versus making a new one.

@enebo enebo closed this in 7cdf0a8 Aug 8, 2016

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Aug 8, 2016

Member

@ivoanjo heya. I think I fixed the rest of this. I can see two potential failure paths though:

  1. It is possible I am missing return for non-methods. This is less clear to be based on how these are emitted but if someone can find a test case I will fix it.
  2. Something is really screwy with our AST generation of statements which include keywords. I half expect to uncover some issues there. However, stuff like 'foo if true' is pretty rare and doubly rare for you to care about it in set_trace_func.

@ivoanjo If you can kick the tires it might be the best we can do for verifying this for the next JRuby release.

Member

enebo commented Aug 8, 2016

@ivoanjo heya. I think I fixed the rest of this. I can see two potential failure paths though:

  1. It is possible I am missing return for non-methods. This is less clear to be based on how these are emitted but if someone can find a test case I will fix it.
  2. Something is really screwy with our AST generation of statements which include keywords. I half expect to uncover some issues there. However, stuff like 'foo if true' is pretty rare and doubly rare for you to care about it in set_trace_func.

@ivoanjo If you can kick the tires it might be the best we can do for verifying this for the next JRuby release.

@enebo enebo added this to the JRuby 9.1.3.0 milestone Aug 8, 2016

@enebo enebo added the ir label Aug 8, 2016

@ivoanjo

This comment has been minimized.

Show comment
Hide comment
@ivoanjo

ivoanjo Aug 9, 2016

Contributor

Wow, nice to see you picked up the hard part after I did the easy one ;)

I'll try set_trace_func in a bigger codebase, see if I can spot any inconsistencies, and report back.

Contributor

ivoanjo commented Aug 9, 2016

Wow, nice to see you picked up the hard part after I did the easy one ;)

I'll try set_trace_func in a bigger codebase, see if I can spot any inconsistencies, and report back.

@ivoanjo

This comment has been minimized.

Show comment
Hide comment
@ivoanjo

ivoanjo Aug 9, 2016

Contributor

Ok so I did a few tests and it seems like the lines are correct between the backtrace and what set_trace_func gets and match with MRI outputs.

The exception I saw was end trace events, which are reported off-by-one between what caller and set_trace_func, but also in many cases neither value is correct when comparing with the file and MRI.

Contributor

ivoanjo commented Aug 9, 2016

Ok so I did a few tests and it seems like the lines are correct between the backtrace and what set_trace_func gets and match with MRI outputs.

The exception I saw was end trace events, which are reported off-by-one between what caller and set_trace_func, but also in many cases neither value is correct when comparing with the file and MRI.

@enebo

This comment has been minimized.

Show comment
Hide comment
@enebo

enebo Aug 9, 2016

Member

@ivoanjo If you can distill some snippets then I will try and knock these down. I did run into something where an extra keyword in a line can cause it to bump forward by one (which is super confusing output from the parser). Open them as new issues.

Member

enebo commented Aug 9, 2016

@ivoanjo If you can distill some snippets then I will try and knock these down. I did run into something where an extra keyword in a line can cause it to bump forward by one (which is super confusing output from the parser). Open them as new issues.

@nixme nixme referenced this issue in nixme/pry-nav Sep 16, 2016

Closed

Add instructions for JRuby in README #24

enebo added a commit that referenced this issue Dec 22, 2017

Fixes #4060. Wrong line numbers inside set_trace_func for end events.
Fixes #4051. Wrong line numbers in Kernel#caller inside set_trace_func (with code to reproduce)

#4051 was largely already fixed but the backtrace elements themselves had the
wrong line (which was why #4060 was opened).

The problem was mri changes their position of class/module/sclass from start
line to end line.  We just store start line.  They will also look at first
instr/node within the class/module for start line.  That solution is memory
efficient but then makes those nodes report wrong lines with -S ast.

Our solution was to just add an endLine field to those nodes.  The memory
increase from that is very small so I think it is ok.

The second part of this was that we build backtrace from setting line number
via a line number instr.  We had no end line so we couldn't emit one.  Now that
we have one we do....but only if --debug is supplied since the only instr after
this point is return and that cannot raise (so we cannot generate a backtrace).

enebo added a commit that referenced this issue Dec 22, 2017

Fixes #4060. Wrong line numbers inside set_trace_func for end events.
Fixes #4051. Wrong line numbers in Kernel#caller inside set_trace_func (with code to reproduce)

#4051 was largely already fixed but the backtrace elements themselves had the
wrong line (which was why #4060 was opened).

The problem was mri changes their position of class/module/sclass from start
line to end line.  We just store start line.  They will also look at first
instr/node within the class/module for start line.  That solution is memory
efficient but then makes those nodes report wrong lines with -S ast.

Our solution was to just add an endLine field to those nodes.  The memory
increase from that is very small so I think it is ok.

The second part of this was that we build backtrace from setting line number
via a line number instr.  We had no end line so we couldn't emit one.  Now that
we have one we do....but only if --debug is supplied since the only instr after
this point is return and that cannot raise (so we cannot generate a backtrace).
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment