Double Shot #1511

Summer camp season is upon us – see y’all in a couple of weeks, most likely.

An Introduction to Swift for Ruby Developers – Now you can avoid Objective-C when you want to move to iOS, which is good.
InfraRuby 3.7 Released – Static ruby compiler, su…

I am a puts debuggerer

February 5, 2016

I love puts debugging

I am a puts debuggerer. I don’t say this to disparage people that use a Real Debugger. I think Real Debuggers are great, I’ve just never taken the time to learn one well. Every time I try to lean one, I end up not using it for a while and have to re-learn how to use it. Anyway, I want to share some tricks I use for puts debugging with you. I use these tricks whenever I don’t understand how something works and I want to know more. Most of the stuff below is definitely not a “best practice” and you should never leave this code around when you’re done with a debugging session. However, I think it’s important to say that when you’re debugging anything goes. I mean anything. Global variables, redefining methods, adding conditionals, manipulating the load path, monkey patching, printing the call stack, anything.

I’ve tried to stick to real world examples in this post. However, many of these examples came from when I was trying to debug security issues in Rails, so please reuse the techniques I’m showing here but not the target code. The target code I’m trying to debug is broken, and I don’t want you to use it.

I’ve tried to organize each section in to a headline with the problem I have, and the body as the solution I used.

Also, I gave up on using a consistent voice because this is a blog post and I don’t care.

I know where I am but not how I got here

Sometimes I’ll be debugging an issue and know where the problem is, but not how I got there. For those times I’ll just do puts caller to get the callstack.

For example I have this code:

  LOOKUP           = Hash.new { |h, k| h[k] = Type.new(k) unless k.blank? }

But I need to know how the default block is getting called, I do this:

  LOOKUP           = Hash.new { |h, k|
    puts "#" * 90
    puts caller
    puts "#" * 90
    h[k] = Type.new(k) unless k.blank?
  }

The above code will print out 90 hash tags, then the call stack, then 90 more hash tags. I print out the hash tags so that if it gets called multiple times, I can easily differentiate the call stacks. Note that I am calling them “hash tags” in order to annoy you.

I do this pretty frequently, so I have a Vim shortcut to do it:

" puts the caller
nnoremap <leader>wtf oputs "#" * 90<c-m>puts caller<c-m>puts "#" * 90<esc>

That lets me do <leader>wtf and inserts those three lines below the line that I’m on.

I only want to print the call stack once

Just use exit! after printing the callstack, or call raise. raise will show an exception so you see the stack anyway.

I only want to see the stack in certain cases

This is debugging code, so you can do whatever you want. Lets say I just want to see the stack when adding something to the hash. Just do this:

  LOOKUP           = Hash.new { |h, k|
    unless k.blank?
      puts "#" * 90
      puts caller
      puts "#" * 90
      h[k] = Type.new(k)
    end
  }

Since I’m going to throw this code away anyway, I’m free to add any kind of weird conditionals I’d like!

I’m calling a method, but I don’t know where it goes

In the case where I’m calling a method, but I don’t know where that method is implemented, I’ll use the method method along with the source_location method. For example, I have an action in a controller that calls render and I want to find that method:

def show
  render params[:id]
end

I’ll change the above code to this:

def index
  p method(:render).source_location
  render params[:id]
end

Run this:

$ curl http://localhost:3000/users/xxxx

Then in the logs I see this:

Processing by UsersController#show as */*
  Parameters: {"id"=>"xxxx"}
["/Users/aaron/git/rails/actionpack/lib/action_controller/metal/instrumentation.rb", 40]
Completed 500 Internal Server Error in 35ms (ActiveRecord: 0.0ms)

Now I know that the render method is in instrumentation.rb on line 40.

I’m calling `super` but I don’t know where that goes

Here I can see that render calls super, but I don’t know where that is implemented. In that case, I use super_method on the return value of method.

So I change this:

def index
  p method(:render).source_location
  render params[:id]
end

To this:

def index
  p method(:render).super_method.source_location
  render params[:id]
end

Run the same request through, and I get this for the output:

Processing by UsersController#show as */*
  Parameters: {"id"=>"xxxx"}
["/Users/aaron/git/rails/actionpack/lib/action_controller/metal/rendering.rb", 34]
Completed 500 Internal Server Error in 34ms (ActiveRecord: 0.0ms)

Now I see that super goes here. That method also calls super, but I can just rinse and repeat the above process (or use a loop!) to find the method I actually care about.

What if the thing implements the `method` method?

Sometimes the method trick doesn’t work because the object I want to know about implements it’s own version of method. For example, I am trying to find where the headers method is implemented on the request object with this code:

def index
  p request.method(:headers).source_location
  @users = User.all
end

When I run a request, I get this error:

ArgumentError (wrong number of arguments (given 1, expected 0)):
  app/controllers/users_controller.rb:5:in `index'

This is because the request object implements it’s own method called method. To figure out where the headers method is, I will unbind the method from Kernel, rebind it to the request, then execute it like this:

def index
  method = Kernel.instance_method(:method)
  p method.bind(request).call(:headers).source_location
  @users = User.all
end

Running the request again, I get this for the output:

Processing by UsersController#index as */*
["/Users/aaron/git/rails/actionpack/lib/action_dispatch/http/request.rb", 201]

Now I know the headers method is implemented here.

I can even find the implementation of the method method like this:

def index
  method = Kernel.instance_method(:method)
  p method.bind(request).call(:method).source_location
  @users = User.all
end

I’m calling something but I don’t know where it goes (again)

Sometimes the immediate method isn’t the method I actually care about, so using the method trick to figure out where I’m going won’t help. In that case, I’ll use a larger hammer which is TracePoint. We can redo the render example to get a list of all methods that are called from render. The methods we’ll see listed may not be called directly from render but from somewhere.

  # GET /users
  # GET /users.json
  def index
    @users = User.all
    tp = TracePoint.new(:call) do |x|
      p x
    end
    tp.enable
    render 'index'
  ensure
    tp.disable
  end

The TracePoint allocated here will fire on every “call” event and the block will print out the method name and location of the call. A “call” even it when a Ruby method gets called (not a C method). If you want to see C methods as well, use :c_call. This example will produce a ton of output. I really only use this technique when the number of methods being called is fairly small, or I don’t even know where to begin looking.

I know an exception is getting raised, but I don’t know where

Sometimes an exception gets raised, but I don’t know where the exception actually got raised. This example uses Rails 3.0.0 (we’ve since fixed this issue), but say you have this code:

ActiveRecord::Base.logger = Logger.new $stdout

User.connection.execute "oh no!"

I know this SQL won’t work, and there will be an exception. But lets see what the exception actually looks like:

  SQL (0.1ms)  oh no!
SQLite3::SQLException: near "oh": syntax error: oh no!
activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:202:in `rescue in log': SQLite3::SQLException: near "oh": syntax error: oh no! (ActiveRecord::StatementInvalid)
	from activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:194:in `log'
	from activerecord-3.0.0/lib/active_record/connection_adapters/sqlite_adapter.rb:135:in `execute'
	from test.rb:6:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `eval'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands.rb:39:in `require'
	from railties-3.0.0/lib/rails/commands.rb:39:in `<top (required)>'
	from script/rails:6:in `require'
	from script/rails:6:in `<main>'

If you read this backtrace, it looks like the exception came from abstract_adapter.rb line 202. However, what you’ll quickly notice is that this code is rescuing an exception, and then re-raising. So where did the real exception get raised? To find it, we could add some puts statements, or use the -d flag on Ruby like this:

[aaron@TC okokok (master)]$ bundle exec ruby -d script/rails runner test.rb

The -d flag will enable warnings and also print out every line where an exception was raised. Yes, this definitely prints a bunch of stuff, but if you look at the output near the end it will look something like this:

Exception `NameError' at activesupport-3.0.0/lib/active_support/core_ext/module/remove_method.rb:3 - method `_validators' not defined in Class
Exception `SQLite3::SQLException' at sqlite3-1.3.11/lib/sqlite3/database.rb:91 - near "oh": syntax error
Exception `SQLite3::SQLException' at activesupport-3.0.0/lib/active_support/notifications/instrumenter.rb:24 - near "oh": syntax error
  SQL (0.1ms)  oh no!
SQLite3::SQLException: near "oh": syntax error: oh no!
Exception `ActiveRecord::StatementInvalid' at activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:202 - SQLite3::SQLException: near "oh": syntax error: oh no!
Exception `ActiveRecord::StatementInvalid' at railties-3.0.0/lib/rails/commands/runner.rb:48 - SQLite3::SQLException: near "oh": syntax error: oh no!
activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:202:in `rescue in log': SQLite3::SQLException: near "oh": syntax error: oh no! (ActiveRecord::StatementInvalid)
	from activerecord-3.0.0/lib/active_record/connection_adapters/abstract_adapter.rb:194:in `log'
	from activerecord-3.0.0/lib/active_record/connection_adapters/sqlite_adapter.rb:135:in `execute'
	from test.rb:6:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `eval'
	from railties-3.0.0/lib/rails/commands/runner.rb:48:in `<top (required)>'
	from railties-3.0.0/lib/rails/commands.rb:39:in `require'
	from railties-3.0.0/lib/rails/commands.rb:39:in `<top (required)>'
	from script/rails:6:in `require'
	from script/rails:6:in `<main>'

You’ll see the original exception happened here:

Exception `SQLite3::SQLException' at sqlite3-1.3.11/lib/sqlite3/database.rb:91 - near "oh": syntax error

And it was re-raised here:

Exception `SQLite3::SQLException' at activesupport-3.0.0/lib/active_support/notifications/instrumenter.rb:24 - near "oh": syntax error

Cases where exceptions are getting wrapped and re-raised should expose the originating backtrace. So this is a bug, but it has been fixed, and we can cover how to fix that another day.

I want to run a command line tool with `-d`

Say you want to use the above technique to run your RSpec tests with the -d flag, you can do this:

$ ruby -d -S rspec

I want to use the `-d` flag but I don’t know how to run the process

The default Rake test task will run your tests in a sub process. This means that running ruby -d -S rake will not set the debug flag in the sub-process that runs your tests. In this case I use the RUBYOPT environment variable like this:

[aaron@TC okokok (master)]$ RUBYOPT=-d bundle exec rake test

The RUBYOPT environment variable will get applied to every Ruby program that is executed in this shell, even sub shells executed by rake. This means the rspec command above could be rewritten as:

$ RUBYOPT=-d rspec

I need to find where this object came from

Usually printing the callstack will tell me where an object came from. But sometimes the object is allocated outside of the stack, so it’s difficult to figure out where it came from. Take this code for example:

def foo
  x = baz
  bar x
end

def bar x
  puts "#" * 90
  puts caller
  puts "#" * 90
  p x
end

def baz; zot;        end
def zot; Object.new; end

foo

I used the “wtf" technique from "I know where I am but not how I got here", and printed out the value of `x`. From that, I learned that I really care how that `x` value was allocated, but if I trace back up the stack to the `foo` method, I can see that it calls `baz` to get the value. In large code bases, it can be very tricky to follow all the calls and logic through a sibling tree (if you think about the code as a graph, then the `foo` method has two children, `baz` and `bar`, so you can think of `baz` as being a sibling to `bar`). I am lazy and I don't want to go chasing through all the methods to find how this object came to be, so I like to use Ruby's object allocation tracer. Ruby's allocation tracer has been available since Ruby 2.1 (don't quote me on that). When I use it, I require and enable it as soon as possible. Then I print out the allocation location at the place I care about, like this:

require 'objspace'
ObjectSpace.trace_object_allocations_start

def foo
  x = baz
  bar x
end

def bar x
  p ObjectSpace.allocation_sourcefile(x) => ObjectSpace.allocation_sourceline(x)
end

def baz; zot;        end
def zot; Object.new; end

foo

When I run the program, the output is like this:

[aaron@TC tlm.com (master)]$ ruby x.rb 
{"x.rb"=>14}
[aaron@TC tlm.com (master)]$

I see that the object is allocated on line 14 in x.rb. So I go to that line and that method, then repeat the “wtf" trick or this trick until I figure out what is wrong with the program.

I usually start object tracing ASAP because I don’t know where my object will be allocated. The tracing slows down the program, but not enough to really matter while I’m debugging.

I need to require something really, really early

The above technique will only give you allocation information for objects that have been allocated after trace_object_allocations_start has been called. Lets say the object is being allocated at file require time, but you don’t know what file or where. In this case, I want to execute some code way before anything in the framework gets required. To do that, I’ll use the -r flag and write a script.

Say there’s a script where we’re trying to find the allocation location of User::BLACKLISTED_CLASS_METHODS.

require 'active_record'

ActiveRecord::Base.establish_connection adapter: 'sqlite3', database: ':memory:'

ActiveRecord::Base.connection.instance_eval do
  create_table :users
end

class User < ActiveRecord::Base; end
p ObjectSpace.allocation_sourcefile(User::BLACKLISTED_CLASS_METHODS) =>
    ObjectSpace.allocation_sourceline(User::BLACKLISTED_CLASS_METHODS)

But we don’t know which file allocates that constant, and don’t want to figure it out (yes this is slightly contrived). I will write a file, in this case named y.rb that looks like this:

require 'objspace'
ObjectSpace.trace_object_allocations_start

Then I’ll use the command line arguments to Ruby to require this file and execute my program:

[aaron@TC tlm.com (master)]$ ruby -I. -ry x.rb
{"/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/activerecord-5.0.0.beta1/lib/active_record/attribute_methods.rb"=>35}
[aaron@TC tlm.com (master)]$

If we break down the arguments to Ruby, the -I. says “add . to the load path”, -ry is the same as require 'y', then run x.rb. So . is added to the load path, and y.rb is required before Ruby even starts running x.rb. Then we see that the BLACKLISTED_CLASS_METHODS was allocated in attribute_methods.rb line 35. You can combine this technique with the RUBYOPT technique in case you code is run in a sub process like this:

$ RUBYOPT='-I. -ry' rake test

An object is being mutated, but I don’t know where

Sometimes I run in to an object that I know is being mutated, but I don’t know where the mutation is happening. In that case, I will call freeze on the object, run my test, and then see where an exception occurs. As an example, I needed to figure out where this variable is being mutated. I knew it was being mutated, I could see in the code it’s being mutated, but I didn’t know where that was happening first. So I changed the code to be like this:

def initialize
  super()

  @cv = new_cond

  @sharing = Hash.new(0)
  @sharing.freeze
  @waiting = {}
  @exclusive_thread = nil
  @exclusive_depth = 0
end

Booting the server gave me a exception with stack trace:

active_support/concurrency/share_lock.rb:151:in `delete': can't modify frozen Hash (RuntimeError)
	from active_support/concurrency/share_lock.rb:151:in `yield_shares'
	from active_support/concurrency/share_lock.rb:79:in `block in stop_exclusive'

Now I know where the first mutation happened. If that’s not the one I care about, I can remove the freeze I added earlier, and add it after this mutation.

I have a deadlock, but I don’t know where

When I’m having issues with threads and I don’t know where it is, I’ll add some code to inspect the live threads. For example, I was debugging this issue. The application server was hanging, but I didn’t know where. To find where the threads were hanging, I wrote a file called x.rb with code like this:

trap(:INFO) {
  Thread.list.each do |t|
    puts "#" * 90
    p t
    puts t.backtrace
    puts "#" * 90
  end
}

Then booted the app server like this:

$ ruby -I. -rx bin/rails s

Now when the app server hangs, I hit Ctrl-T (sorry, this only works on OS X, you’ll need to use kill on Linux), and I’ll see a stack trace for every thread:

##########################################################################################
#<Thread:0x007f90bc07cb38 run>
omglolwut/x.rb:7:in `backtrace'
omglolwut/x.rb:7:in `block (2 levels) in <top (required)>'
omglolwut/x.rb:4:in `each'
omglolwut/x.rb:4:in `block in <top (required)>'
gems/puma-2.16.0/lib/rack/handler/puma.rb:43:in `join'
gems/puma-2.16.0/lib/rack/handler/puma.rb:43:in `run'
gems/rack-2.0.0.alpha/lib/rack/server.rb:296:in `start'
rails/commands/server.rb:78:in `start'
rails/commands/commands_tasks.rb:90:in `block in server'
rails/commands/commands_tasks.rb:85:in `tap'
rails/commands/commands_tasks.rb:85:in `server'
rails/commands/commands_tasks.rb:49:in `run_command!'
rails/command.rb:20:in `run'
rails/commands.rb:19:in `<top (required)>'
bin/rails:4:in `require'
bin/rails:4:in `<main>'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b668@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/reactor.rb:136 sleep>
lib/puma/reactor.rb:29:in `select'
lib/puma/reactor.rb:29:in `run_internal'
lib/puma/reactor.rb:138:in `block in run_in_thread'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b500@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:216 sleep>
lib/puma/thread_pool.rb:219:in `sleep'
lib/puma/thread_pool.rb:219:in `block in start!'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b3c0@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:187 sleep>
lib/puma/thread_pool.rb:190:in `sleep'
lib/puma/thread_pool.rb:190:in `block in start!'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bef3b258@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/server.rb:296 sleep>
lib/puma/server.rb:322:in `select'
lib/puma/server.rb:322:in `handle_servers'
lib/puma/server.rb:296:in `block in run'
##########################################################################################
##########################################################################################
#<Thread:0x007f90c1ef9a08@/Users/aaron/.rbenv/versions/ruby-trunk/lib/ruby/gems/2.4.0/gems/puma-2.16.0/lib/puma/thread_pool.rb:61 sleep>
lib/ruby/2.4.0/monitor.rb:111:in `sleep'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:132:in `wait_until'
action_dispatch/http/response.rb:170:in `block in await_commit'
lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
action_dispatch/http/response.rb:169:in `await_commit'
action_controller/metal/live.rb:270:in `process'
action_controller/metal.rb:193:in `dispatch'
action_controller/metal.rb:265:in `dispatch'
action_dispatch/routing/route_set.rb:50:in `dispatch'
action_dispatch/routing/route_set.rb:32:in `serve'
##########################################################################################
##########################################################################################
#<Thread:0x007f90bd1d5f38@/Users/aaron/git/rails/actionpack/lib/action_controller/metal/live.rb:279 sleep>
lib/ruby/2.4.0/monitor.rb:111:in `sleep'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:111:in `wait'
lib/ruby/2.4.0/monitor.rb:123:in `wait_while'
active_support/concurrency/share_lock.rb:57:in `block (2 levels) in start_exclusive'
active_support/concurrency/share_lock.rb:154:in `yield_shares'
active_support/concurrency/share_lock.rb:56:in `block in start_exclusive'
lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
active_support/concurrency/share_lock.rb:51:in `start_exclusive'
active_support/concurrency/share_lock.rb:113:in `exclusive'
active_support/dependencies/interlock.rb:12:in `loading'
active_support/dependencies.rb:37:in `load_interlock'
active_support/dependencies.rb:369:in `require_or_load'
active_support/dependencies.rb:529:in `load_missing_constant'
active_support/dependencies.rb:212:in `const_missing'
active_support/dependencies.rb:561:in `load_missing_constant'
active_support/dependencies.rb:212:in `const_missing'
app/controllers/users_controller.rb:9:in `index'
##########################################################################################

I’ve trimmed the output a bit to make it easier to read, but you can now see what each thread is doing, and it’s clear which two threads are deadlocking (it’s the last two).

I want to know when a method is executed, but only at a certain time

Sometimes I want to know when a method is executed, but I want to do it after a certain time. For example, I want to know when start_exclusive is called, but after the application boots up. In these cases, I’ll mix global variables along with the trap trick I showed earlier.

First I modify start_exclusive to look like this:

def start_exclusive(purpose: nil, compatible: [], no_wait: false)
  if $foo
    puts "#" * 90
    puts caller
    puts "#" * 90
  end
  # ..
end

Then I write an x.rb file like this:

trap(:INFO) {
  puts "turning on debugging!"
  $foo = true
}

Then I boot the app server, and once everything has warmed up, I hit Ctrl-T and now my global variable is set to true and I start seeing logging messages.

END

This is everything I can think of right now. You should also check out Richard’s post on puts debugging. Have a good day. The End.

[…]

The Ruby Rails Aggregator