Debugging Ruby code for non-rubyists

Suppose you program in Python, PHP, or some other popular language. But suddenly, you end up maintaining a Linux distribution package of a program written in Ruby. Or inherit a project that contains hacky Ruby scripts glued together by even more hacky shell scripts. Or you have to fix a Chef cookbook. And now you’re supposed to track down a bug or understand a patch.

Here are some things that might come in handy for observing and debugging Ruby code - we’ll be discussing methods that can help you in inspecting objects, logging, exploring execution context and looking up definitions of methods.

Output

The following methods help with inspecting objects and data structures and putting them on the screen.

p

p is your best friend. It inspects an object. In other words, it calls object’s inspect method, which returns its string representation. It then stdouts whatever it finds, be it a number - like 10, a list or an array, like 1, 2, 3, 4 or a hash (dictionary) of key-value pairs like 'foo' : 'bar' and 'bar' : 'baz':

p number
=> 10

p list
=> [1, 2, 3, 4]

p hash
=> {:foo=>:bar, :bar=>:baz}

p also accepts multiple arguments and each of those will be inspected in turn:

p number, list
=> 10
   [1, 2, 3, 4]

To send info to stderr, you can use the warn method. warn is useful as the stream representing the standard error is not buffered. However, unlike p, it does not call inspect automatically, so you need to call it explicitly.

warn hash.inspect
=> {:foo=>:bar, :bar=>:baz}

(Tip: unbufferred writes to standard output can be enabled by setting STDOUT.sync = true)

JSON.pretty_generate

When viewing nested hashes or complex data structures, the output of p can be hard to read. JSON to the rescue! It pretty-prints the representation of any object that can be converted to JSON format.

First, require the JSON library:

require 'json'

Then:

puts JSON.pretty_generate(hash)
=> {
  "foo": "bar",
  "bar": "baz"
}

Logger

Using real logging instead of p or warn is handy when debugging existing applications. The ruby Logger has a simple interface. To log a message with certain log level, simply call an appropriate method:

log.fatal("Oh no, it crashed.")
log.error("This is an error.")
log.warn("This is a warning.")
log.info("Just wanted to say hi.")
log.debug("Too many details here!")

Frameworks like Rails often expose a logger that extends or at least has the same interface as the one from the Ruby standard library:

Rails.logger.info("Logging info about a web request").

but of course, you can create your own logger:

require 'logger'
log = Logger.new("debug.log")

Useful trick, especially when there are many messages already being logged, can be to add a ‘tag’ to the message body

log.debug("FOO This is important debug information.")

that can be easily grepped for:

$ tail -f debug.log | grep FOO
D, [2014-06-22T01:24:27.611669 #3814] DEBUG -- : FOO This is important debug information.

or to simply raise the minimal log level, so only messages above this level are actually written into the logfile:

log.level = Logger::WARN

State and context

Current time with microsecond precision

Sometimes a precise time stamp can reveal relative ordering of execution, or helps spotting slow parts of the program

Time.now.to_f
=> 1402595441.01877

returns the current time as a UNIX time stamp with microseconds.

Current process info

The process pid and the (real) uid and gid are, somewhat unsurprisingly, accessible via Process.pid, Process.uid and Process.gid.

Current values of instance variables

In Ruby, it is possible to get current values of object instance variables in a very simple way:

instance_variables.each { |name| puts "#{name}=#{instance_variable_get(name)}" }

Caller

Where is this method called from? caller to the rescue! It is an array that contains the current backtrace. caller[0] is the current method’s caller, caller[1] the caller’s caller, etc…

caller
=> ["/home/bkutil/.gem/ruby/2.1.0/gems/pry-0.9.12.6/lib/pry/pry_instance.rb:328:in `eval'",
"/home/bkutil/.gem/ruby/2.1.0/gems/pry-0.9.12.6/lib/pry/pry_instance.rb:328:in `evaluate_ruby'",
"/home/bkutil/.gem/ruby/2.1.0/gems/pry-0.9.12.6/lib/pry/pry_instance.rb:278:in `re'",
"/home/bkutil/.gem/ruby/2.1.0/gems/pry-0.9.12.6/lib/pry/pry_instance.rb:254:in `rep'",
"/home/bkutil/.gem/ruby/2.1.0/gems/pry-0.9.12.6/lib/pry/pry_instance.rb:234:in `block (3 levels) in repl'",

Sources

Current file and line

For logging the current file and line, Ruby provides two constants __FILE__ and __LINE__. A simple ruby script test.rb:

#!/usr/bin/env ruby
warn "I'm in #{__FILE__} on line #{__LINE__}"

will output I'm in ./test.rb on line 2.

Source location

source_location is super useful when you’re digging into code of a library or an existing app - it shows where a certain method is defined.

Suppose you have code that creates a ftp connection via Net::FTP.new and logs in using login method.

require 'net/ftp'
ftp = Net::FTP.new("ftp://example.com")
ftp.login

and for some reason or other, you’re interested in getting at the sources of the login method.

First, you’ll need to get an object representing the method. Calling method on the ftp is the way to go:

m   = ftp.method(:login)
=> #<Method: Net::FTP#login>

then, m.source_location will reveal the file and line, where the method is defined:

m.source_location
=> ["/home/bkutil/.rubies/ruby-2.1.0/lib/ruby/2.1.0/net/ftp.rb", 453]

and indeed, there it is:

 453     def login(user = "anonymous", passwd = nil, acct = nil)
 454       if user == "anonymous" and passwd == nil
 455         passwd = "anonymous@"
 456       end
 567     ...

Similarly, given a class (which is also an object in ruby), one can look up the sources of one of its class methods (aka static methods). Here is an example with Net::HTTP get method:

require 'net/http'
Net::HTTP.method(:get).source_location
=> ["/home/bkutil/.rubies/ruby-2.1.0/lib/ruby/2.1.0/net/http.rb", 454]

There are three small gotchas:

First, this approach above won’t work for instance methods defined in a Ruby module. A module in Ruby cannot be instantiated, so instead of using method, instance_method is needed to get the method object:

require 'forwardable'

Forwardable.method(:delegate)
=> NameError: undefined method `delegate' for class `Module'

Forwardable.instance_method(:delegate).source_location
=> ["/home/bkutil/.rubies/ruby-2.1.0/lib/ruby/2.1.0/forwardable.rb", 132]

Second, native methods (those optimized in C for speed) will return nil, for example the empty? check of the String class:

String.new.method(:empty?).source_location
=> nil

And finally, evaled code (this also applies for other *_eval methods you will encounter) won’t have its source location defined properly, unless the file and line are explicitly passed as a parameter.

!/usr/bin/env ruby

eval("class FooPrinter; def test; puts 'foo'; end; end")

x = FooPrinter.new
p x.method(:test).source_location

without extra params outputs

["(eval)", 1]

A simple grep for eval, class_eval or instance_eval might help in this case.

Conclusion

These are just a couple of tricks that I found useful while debugging. Here is cheat sheet in text, html and pdf with the snippets above for printing out or future reference.

Most of these methods are incorporated into advanced REPLs like pry, which also integrates documentation and has a shell-like syntax that is easy to grasp to non-rubyists. I really recommend taking a look at it as well.

Found these tricks useful? Have your own? Or do you have a question? Send me an email (balazs at kutilovi dot cz) or a tweet - I’d love to hear what you think and/or help you out!

P.S: Big thanks to @dmajda and @pepareidinger for proofreading and their insightful comments.