Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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
Labels
Milestone

Comments

@ivoanjo
Copy link
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
Copy link
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 as completed in 7cdf0a8 Aug 8, 2016
@enebo
Copy link
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
Copy link
Contributor Author

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
Copy link
Contributor Author

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
Copy link
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.

enebo added a commit that referenced this issue Dec 22, 2017
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 #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
Labels
Projects
None yet
Development

No branches or pull requests

2 participants