ruby-on-railsrubydevisewarden

How to view the call stack when an object is thrown in Ruby


The warden gem uses throw and catch functions to handle control flow. This makes it super hard to debug authentication systems, especially in devise where the gem throws the :warden symbol and the warden gem catches it.

I my program, I have a function that (indirectly) throws a :warden symbol, but I don't know what is the exact call site of thethrow function. Is there a way to find it?

It seems that we cannot use the TracePoint class because it only supports raise events.


Solution

  • I was able to get something working using TracePoint and the fact that throw is a c language routine by trapping c_call:

    TracePoint.new(:c_call) do |trace|
      if trace.method_id == :throw
        p [trace.path, trace.lineno]
      end
    end
    

    This will only get you where the call to throw was actually made, not a full stack trace of everything called up to that point, though you could play around with catching :call as well, and put something together that captures more information. As a quick example:

    TracePoint.new(:call, :c_call) do |trace|
      if trace.event == :call || trace.method_id == :throw
        p [trace.method_id, trace.path, trace.lineno]
      end
    
      trace.disable if trace.method_id == :throw
    end
    

    Full example:

    # might_throw_cont.rb
    def might_throw_second
      throw :warden if rand(100) < 10
    
      might_throw_third
    end
    
    def might_throw_third
      throw :warden if rand(100) < 10
    
      might_throw_final
    end
    
    # example.rb
    require './might_throw_cont'
    
    def might_throw_first
      throw :warden if rand(100) < 10
    
      might_throw_second
    end
    
    def might_throw_final
      throw :warden if rand(100) < 10
    
      will_throw
    end
    
    def will_throw
      throw :warden
    end
    
    TracePoint.new(:call, :c_call) do |trace|
      if trace.event == :call || trace.method_id == :throw
        p [trace.method_id, trace.path, trace.lineno]
      end
    
      trace.disable if trace.method_id == :throw
    end.enable do
      catch :warden do
        might_throw_first
      end
    
      puts "done"
    end
    

    Obviously, going to be hard to tell which method actually threw the symbol in this example. But running the example, a couple times I'll be able to see in the output (2 example runs):

    # run 1
    [:might_throw_first, "example.rb", 3]
    [:might_throw_second, "/Users/simplelime/Documents/Ruby/might_throw_cont.rb", 1]
    [:might_throw_third, "/Users/simplelime/Documents/Ruby/might_throw_cont.rb", 7]
    [:might_throw_final, "example.rb", 9]
    [:will_throw, "example.rb", 15]
    [:throw, "example.rb", 16] # < only line you'll see if you trace only :c_call
    done
    
    # run 2
    [:might_throw_first, "example.rb", 3]
    [:throw, "example.rb", 4] # < only line you'll see if you trace only :c_call
    done