Balázs' blog

Printf debugging basics in Ruby

Sometimes, a printf is enough. Although IDEs usually integrate with a debugger and allow you to setup complex breakpoints, the power of printing out statements shouldn’t be underestimated. The learning curve is low and all the required tools are there. No need to install gems, or spend money on an IDE.

Let’s look at some printf style tools that’s good to have in your debugging toolbox. We’ll be going from the simplest ones for inspecting objects, logging, going through 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 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 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. Time also implements nsec for even greater precision.

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'",

In cases you’re fine with a jump or the program exiting, raise can do the same for you.

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. This works pretty well for your own code, but what if you want to know where a library method comes from?

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.

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!

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