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.