Creating and Understanding Tracebacks
Problem
You are debugging a program, and need to understand the stack traces that come with Ruby exceptions. Or you need to see which path the Ruby interpreter took to get to a certain line of code.
Solution
You can call the Kernel#caller method at any time to look at the Ruby interpreter’s current call stack. The call stack is represented as a list of strings.
This Ruby program simulates a company with a top-down management style: one method delegates to another, which calls yet another. The method at the bottom can use caller to look upwards and see the methods that called it:
1 #!/usr/bin/ruby -w
2 # delegation.rb
3 class CEO
4 def CEO.new_vision
5 Manager.implement_vision
6 end
7 end
8
9 class Manager
10 def Manager.implement_vision
11 Engineer.do_work
12 end
13 end
14
15 class Engineer
16 def Engineer.do_work
17 puts 'How did I get here?'
18 first = true
19 caller.each do |c|
20 puts %{#{(first ? 'I' : ' which')} was called by "#{c}"}
21 first = false
22 end
23 end
24 end
25
26 CEO.new_vision
Running this program illustrates the path the interpreter takes to Engineer.do_work:
$ ./delegation.rb How did I get here? I was called by "delegation.rb:11:in 'implement_vision'" which was called by "delegation.rb:5:in 'new_vision'" which was called by "delegation.rb:26"
Discussion
Each string in a traceback shows which line of Ruby code made some method call. The first bit of the traceback given above shows that Engineer.do_work was called by Manager.implement_vision on line 11 of the program. The second line shows how Manager.implement_vision was called, and so on.
Remember the stack trace displayed when a Ruby script raises an exception? It’s the same one you can get any time by calling Kernel#caller. In fact, if you rescue an exception and assign it to a variable, you can get its traceback as an array of strings the equivalent of calling caller on the line that triggered the exception:
def raise_exception
raise Exception, 'You wanted me to raise an exception, so…'
end
begin
raise_exception
rescue Exception => e
puts "Backtrace of the exception:\n #{e.backtrace.join("\n ")}"
end
# Backtrace of the exception:
# (irb):2:in 'raise_exception'
# (irb):5:in 'irb_binding'
# /usr/lib/ruby/1.8/irb/workspace.rb:52:in 'irb_binding'
# :0
Note the slight differences between a backtrace generated from a Ruby script and one generated during an irb session.
If you’ve used languages like Python, you might long for “real” backtrace objects. About the best you can do is to parse the strings of a Ruby backtrace with a regular expression. The parse_caller method below extracts the files, lines, and method names from a Ruby backtrace. It works in both Ruby programs and irb sessions.
CALLER_RE = /(.*):([0-9]+)(:in \’(.*)’)?/
def parse_caller(l)
l.collect do |c|
captures = CALLER_RE.match(c)
[captures[1], captures[2], captures[4]]
end
end
begin
raise_exception
rescue Exception => e
puts “Exception history:”
first = true
parse_caller(e.backtrace).each do |file, line, method|
puts %{ #{first ? “L” : “because l”}ine #{line} in “#{file}”} +
%{ called “#{method}” }
first = false
end
end
# Exception history:
# Line 2 in “(irb)” called “raise_exception”
# because line 24 in “(irb)” called “irb_binding”
# because line 52 in “/usr/lib/ruby/1.8/irb/workspace.rb”
called "irb_binding" # because line 0 in "" called ""
Adding Logging to Your Application
Problem
You want to make your application log events or diagnostic data to a file or stream. You want verbose logging when your application is in development, and more taciturn logging when in production.
Solution
Use the logger library in the Ruby standard library. Use its Logger class to send logging data to a file or other output stream.
In most cases, you’ll share a single Logger object throughout your application, as a global variable or module constant:
require ' logger’ $LOG = Logger.new($stderr)
You can then call the instance methods of Logger to send messages to the log at various levels of severity. From least to most severe, the instance methods are Logger#debug, Logger#info, Logger#warn, Logger#error, and Logger#fatal.
This code uses the application’s logger to print a debugging message, and (at a higher severity) as part of error-handling code.
def divide(numerator, denominator)
$LOG.debug("Numerator: #{numerator}, denominator #{denominator}")
begin
result = numerator / denominator
rescue Exception => e
$LOG.error "Error in division!: #{e}"
result = nil
end
return result
end
divide(10, 2)
# D, [2006-03-31T19:35:01.043938 #18088] DEBUG —
: Numerator: 10, denominator 2 # => 5 divide(10, 0) # D, [2006-03-31T19:35:01.045230 #18088] DEBUG —
: Numerator: 10, denominator 0 # E, [2006-03-31T19:35:01.045495 #18088] ERROR –
: Error in division!: divided by 0 # => nil
To change the log level, simply assign the appropriate constant to level:
$LOG.level = Logger::ERROR
Now our logger will ignore all log messages except those with severity ERROR or FATAL:
divide(10, 2) # => 5 divide(10, 0) # E, [2006-03-31T19:35:01.047861 #18088] ERROR —
: Error in division!: divided by 0 # => nil
Discussion
Ruby’s standard logging system works like Java’s oft-imitated Log4J. The Logger object centralizes all the decisions about whether a particular message is important enough to be written to the log. When you write code, you simply assume that all the messages will be logged. At runtime, you can get a more or a less verbose log by changing the log level. A production application usually has a log level of Logger::INFO or Logger::WARN.
The DEBUG log level is useful for step-by-step diagnostics of a complex task. The ERROR level is often used when handling exceptions: if the program can’t solve a problem, it logs the exception rather than crash and expects a human administrator to deal with it. The FATAL level should only be used when the program cannot recover from a problem, and is about to crash or exit.
If your log is being stored in a file, you can have Logger rotate or replace the log file when it get too big, or once a certain amount of time has elapsed:
# Keep data for the current month only
Logger.new('this_month.log', 'monthly')
# Keep data for today and the past 20 days.
Logger.new('application.log', 20, 'daily')
# Start the log over whenever the log exceeds 100 megabytes in size.
Logger.new('application.log', 0, 100 * 1024 * 1024)
If the default log entries are too verbose for you, you have a couple of options. The simplest is to set datetime_format to a more concise date format. This code gets rid of the milliseconds:
$LOG.datetime_format = '%Y-%m-%d %H:%M:%S'
$LOG.error('This is a little shorter.')
# E, [2006-03-31T19:35:01#17339] ERROR — : This is a little shorter.
If that’s not enough for you, you can replace the call method that formats a message for the log:
class Logger class Formatter Format = "%s [%s] %s %s\n” def call(severity, time, progname, msg) Format % [severity, format_datetime(time), progname, msg] end end end $LOG.error(’This is much shorter.’) # ERROR [2006-03-31T19:35:01.058646 ] This is much shorter.