jruby -rtracer doesn't trace

The problem here is that JRuby doesn't normally support set_trace_func unless you pass --debug, because of the extra overhead that repeatedly checking for trace functions adds to the system. Normally, we warn if set_trace_func is called without being in "full trace mode", but in this case tracer.rb sets verbose to false, disabling all warnings.

Passing --debug along with -rtracer causes it to work just fine:

~/projects/jruby ➔ ruby --debug -rtracer -e "puts 1; puts 2"
#0:-e:1::-: puts 1; puts 2
#0:-e:1:Kernel:>: puts 1; puts 2
#0:-e:1:Fixnum:>: puts 1; puts 2
#0:-e:1:Fixnum:<: puts 1; puts 2
#0:-e:1:IO:>: puts 1; puts 2
1#0:-e:1:IO:<: puts 1; puts 2
#0:-e:1:IO:>: puts 1; puts 2

#0:-e:1:IO:<: puts 1; puts 2
#0:-e:1:Kernel:<: puts 1; puts 2
#0:-e:1::-: puts 1; puts 2
#0:-e:1:Kernel:>: puts 1; puts 2
#0:-e:1:Fixnum:>: puts 1; puts 2
#0:-e:1:Fixnum:<: puts 1; puts 2
#0:-e:1:IO:>: puts 1; puts 2
2#0:-e:1:IO:<: puts 1; puts 2
#0:-e:1:IO:>: puts 1; puts 2

#0:-e:1:IO:<: puts 1; puts 2
#0:-e:1:Kernel:<: puts 1; puts 2

I'm going to either modify tracer.rb to not turn verbose off or modify set_trace_func to log regardless of verbosity (or raise).

Ok, this actually appears to be a behavioral difference with Kernel#caller. At the toplevel of a required script (from -r) we have a two-deep caller(0) trace. The logic at the bottom of tracer.rb only enables tracing if caller(0) is one-deep at toplevel.

This is obviously a rather fragile way to know when to turn on tracing, but I have a one-character fix for caller backtrace generation that may be good enough.

And yes, I realized my example above was still running MRI...

I fixed this in 5f3de42 by modifying how we prepare the toplevel binding. Previously, we pushed the frames necessary for toplevel very early, so that TOPLEVEL_BINDING could be constructed. This caused there to be an extra frame already on the stack when doing requires, and so caller(0) had an extra element, and so tracer did not enable itself (or display the tracing warning). The modification in 5f3de42 was to push the context needed for TOPLEVEL_BINDING but then remove them while doing requires, and finally re-init the toplevel context with what it should be for normal execution.

My previous attempt to fix this-removing an element from all caller(0) traces-caused caller(0) to be incorrect when called from a non -r source, so it was not the right way to go. This fix appears to match MRI a bit better.

This seemed to cause no end of problems, so I'm reopening it. I reverted the fix in 93b1257 and added a temporary hack to tracer.rb in ecb74ae. We'll need to revisit this for 1.6.

JRUBY-4636 should be confirmed with any fix for this bug.

Noncritical...moving to 1.7.

This appears to not work even with --debug these days.

jruby --debug -rtracer xxx.rb (no tracing output)

jruby 1.7.0.dev (ruby-1.8.7-p357) (2012-04-09 3391966) (Java HotSpot(TM) Client VM 1.6.0_26) [Windows 7-x86-java]

Should be fixed by these commits:

commit daed10cb5d4b2a02edbb670553fbc5c1e314e82a
Author: Charles Oliver Nutter <headius@headius.com>
Date:   Thu Apr 12 10:33:36 2012 -0500

    Deprecate now-unused ThreadContext.setFile

commit 0b167802678933b8c7346a043287a6210d9bab41
Author: Charles Oliver Nutter <headius@headius.com>
Date:   Wed Apr 11 17:32:10 2012 -0500

    Fix root-level backtrace mangling caused by old-style logic.
    
    Backtraces are not managed by file and line fields in ThreadContext
    anymore; instead, a new backtrace element should be pushed in each
    case (updating a preallocated stack of BacktraceElement objects).
    The old logic was still being used to set TC.file and TC.line
    before pushing a Frame...a relic from when backtrace data lived on
    Frame and pulled file/line info from the "current" values in TC.
    The continued use of these methods meant that backtrace elements
    were being updated in-place rather than pushed/popped for
    top-level backtraces, mangling them and destroying the proper
    values (ending up showing the last-set filename for toplevel).
    
    This commit removes all uses of setFile/setLine that are not
    performed against a backtrace element owned by the calling
    context.

sweet works now.
thanks!
roger