How can I keep track of my stack trace height for debugging purposes?

Question

I want my code to do the following:

def debug (message)
  puts message.rjust(message.length + (stack_trace-1 * 2)) # -1 for the call to debug
end

def a
  debug "in a"
  b
  debug "end a"
end

def b
  debug "in b"
  c
  debug "end b"
end

def c
  debug "in c"
  meaningful_work
  debug "end c"
end

Output:

in a
  in b
    in c
    end c
  end b
end a

I've done this before in PHP, like this:

function echon($string){
  $nest_level = count(debug_backtrace()) - 1; // minus one to ignore the call to *this* function
  echo str_repeat("  ", $nest_level) . $string . "\n";
}

As far as my google-fu can tell, there isn't a Ruby equivalent to debug_backtrace. I don't want to modify the calls of all the numerous methods in the code base I am working in to pass along a backtrace - that is needlessly cumbersome and hard to revert.

Is there some global I can use to keep track here?

score 3 · Answer 1 · answered Dec 15 '14 at 18:56

Simply use Kernel#caller with .length. caller(0).length will give you the current stack depth.

Example:

irb(main):001:0> caller(0)
=> ["(irb):1:in `irb_binding'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/workspace.rb:86:in `eval'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/workspace.rb:86:in `evaluate'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/context.rb:380:in `evaluate'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:492:in `block (2 levels) in eval_input'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:624:in `signal_status'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:489:in `block in eval_input'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/ruby-lex.rb:247:in `block (2 levels) in each_top_level_statement'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/ruby-lex.rb:233:in `loop'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/ruby-lex.rb:233:in `block in each_top_level_statement'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/ruby-lex.rb:232:in `catch'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb/ruby-lex.rb:232:in `each_top_level_statement'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:488:in `eval_input'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:397:in `block in start'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:396:in `catch'", "/System/Library/Frameworks/Ruby.framework/Versions/2.0/usr/lib/ruby/2.0.0/irb.rb:396:in `start'", "/usr/bin/irb:12:in `<main>'"]
irb(main):002:0> caller(0).length
=> 17

This works excellently! I subtracted about 45 from the length because the depth was so great, and it made my code very readable. Thanks. — Devon Parsons, Dec 15 '14 at 19:08
Although your solution was certainly worthy of accepting, CarySwoveland's answer goes above and beyond and provides a wealth of resource for future readers, so I'm changing to accept his. Sorry! — Devon Parsons, Dec 22 '14 at 14:51

Cary Swoveland · Accepted Answer · 2014-12-19T19:47:14.793

Here is one way to implement @nneonneo's excellent suggestion.

Code

INDENT = 2

def debug(msg=nil)
  @prev_arr_size ||= 1
  @arrived ||= false
  arr = caller(1)
  indent = ' '*(arr.size-2)*INDENT
  if msg
    puts indent + msg
    return
  end 
  meth, call_meth = method_str(arr[0]), method_str(arr[1])
  entering = (@prev_arr_size==arr.size) ? !@arrived : @prev_arr_size < arr.size
  msg1, msg2 = entering ? ["in ", "called from "] : ["end", "returning to"]
  puts indent  + "%s %s, %s %s" % [msg1, meth, msg2, call_meth]
  @prev_arr_size = arr.size
  @arrived = !@arrived
end

def method_str(str)
  file, _, meth = str.partition(/:.*?in\s+/)
  "#{meth[1..-2]} (#{file})"
end

Example

def a
  debug
  # frivolous work
  b
  debug
end

def b
  debug
  c
  x = 5
  debug "It seems that x is now #{x}"
  # more frivolous work
  c
  debug
end

def c
  debug
  # meaningful_work
  debug
end

a
#=> in  a (t.rb), called from  <main> (t.rb)
#     in  b (t.rb), called from  a (t.rb)
#       in  c (t.rb), called from  b (t.rb)
#       end c (t.rb), returning to b (t.rb)
#     It seems that x is now 5
#       in  c (t.rb), called from  b (t.rb)
#       end c (t.rb), returning to b (t.rb)
#     end b (t.rb), returning to a (t.rb)
#   end a (t.rb), returning to <main> (t.rb)

Phenomenal answer, if I could accept two I would. May I make a suggestion? Add an optional parameter to debug, a string that overrides the default debug string, so we can pass in things like `"temp user_id: #{user_id}"` and maintain our nice formatting — Devon Parsons, Dec 17 '14 at 14:45
Deven, I made the change you suggested, which was a good one. Sorry the the delay in replying. — Cary Swoveland, Dec 19 '14 at 19:47

How can I keep track of my stack trace height for debugging purposes?

2 Answers2