!header dev-utils/debug main h1. Debugging Aids !toc h2. Introduction Ruby offers several aids to debugging. @dev-utils/debug@ offers more. With @dev-utils/debug@ you can: * Escape to an IRB session from a running program. 
  breakpoint
  breakpoint 'Person#name'           # Identify it when it happens.
  breakpoint { @name }               # Default return value.
* Access a no-config logfile for debugging. 
  debug 'Database connection established'   # Look in ./debug.log
* Trace expressions in that logfile. 
  trace 'x + y'
  trace 'Process.pid'
  trace 'names', :pp                 # Pretty-print.
  trace 'page_structure', :yaml      # YAML representation.
* %(planned)Find the difference between complex objects (planned).% These are discussed in detail below. h2. Escape to an IRB Session Ruby's debugger allows you to step through code and find the value of local variables, but setting breakpoints can be difficult, code stepping can be flaky, and running a complex program through the debugger is slow. A partial solution to these problems is to escape from a running program to an open IRB session containing the current environment. This simulates the setting of breakpoints, even allowing for conditions. Those "breakpoints" remain in place between program runs as well, until you remove the relevant line of code. The program runs normally, not through the debugger, so there are no speed issues. During the IRB session, you can interact with the program: get and set local (or other) variables, call methods, and so on. When you finish with IRB, end the session with @CTRL-D@ and the program will continue running. p. @dev-utils/debug@ defines two convenient *aliases* for you: *iv* for @instance_variables@ and *lv* for @local_variables@. Note that IRB will load your @$HOME/.irbrc@ file, even though it's being run from within your program. This means you can define other aliases and helpful methods there. h3. Breakpoint Example The following code comes from @examples/breakpoint-example.rb@ in the distribution: 
  require 'dev-utils/debug'
  
  class Person
    def initialize(name, age)
      @name, @age = name, age
      breakpoint 'Person#initialize'
    end
  
    attr_reader :age
    def name
      breakpoint('Person#name') { @name }
    end
  end
  
  person = Person.new('John Smith', 23)
  puts "Name: #{person.name}"
In English: we have a @Person@ class containing a name and age. When a Person object is initialized, we have a breakpoint. When a Person's name is queried (via @Person#name@) we have another breakpoint. This one uses the default return value feature, which means we can force a different return value when that method is called. After the class is defined, a Person object is created, and its name is printed, meaning both breakpoints will be triggered. To demonstrate the behaviour of this short program, we will run it three times and muck about with IRB. In the console output below, @^D@ represents the keystroke _CTRL-D_, which terminates the breakpoint session. Be careful not to type @exit@, as that will terminate the whole program. In the first run, we will simply exit IRB each time, allowing the program to proceed as intended. 
  Executing breakpoint "Person#initialize" at breakpoint-example.rb:19 in 'initialize'
  >> ^D
  Executing breakpoint "Person#name" at breakpoint-example.rb:24 in 'name'
  >> ^D
  Name: John Smith
In the second run, we inspect the @age@ local variable while the object is being initialized, and set the @@name@ instance variable to something different. We skip the next breakpoint. When the name is printed out, we can see that changing the instance variable has been effective. (By the way, we don't demonstrate it here, but changing _local_ variables is effective as well.) 
  Executing breakpoint "Person#initialize" at breakpoint-example.rb:19 in 'initialize'
  >> lv
  => ["name", "age", "_"]
  >> age
  => 23
  >> name
  => "John Smith"
  >> @name = "Mary Jones"
  => "Mary Jones"
  >> ^D
  Executing breakpoint "Person#name" at breakpoint-example.rb:24 in 'name'
  >> ^D
  Name: Mary Jones
In the thirs and final run, we skip the first breakpoint. When the second one is triggered, during @Person#name@, we call the @age@ method, inspect the @@name@ instance variable, and then force the method to return a different value. Again, we see the effectiveness of this when the name is printed after we exit the breakpoint. 
  Executing breakpoint "Person#initialize" at breakpoint-example.rb:19 in 'initialize'
  >> ^D
  Executing breakpoint "Person#name" at breakpoint-example.rb:24 in 'name'
  >> age                  # This is calling a method...
  => 23
  >> self.age()           # ...this method, in fact.
  => 23
  >> @name
  => "John Smith"
  >> throw :debug_return, 'Maybellene Maconachie'
  Name: Maybellene Maconachie
Note that we haven't changed the value of @@name@ in the above example, only forced a bogus return value from @Person#name@. If the program were to print the person's name again, it would print "John Smith". h3. Breakpoint Caveats There are two things to note with this breakpoint functionality: * It sets the interrupt handler so that IRB can deal with it. If there's some way to reset this to whatever was in place beforehand, I'd like to know. In practice, this shouldn't be a problem, because you only use breakpoints while debugging, and you're not likely to care about interrupts at that time. * The IRB prompt is set to @--simple-prompt@, no matter what's in your config file. This is a matter of convenience, as you don't really need a fancy prompt in this situation. However, I might try to make this more flexible in a future version. h2. Zero-conf Logfile for Debugging and Tracing Logging is a very useful general tool, and there are two excellent logging packages for Ruby: @logger@ (in the standard library) and the more powerful @log4r@. But if all you want to do is record a few pieces of debugging information, then configuring a logger can seem like too much hassle. Throwing output to @STDERR@ is often a reasonable solution, but that can interfere with the output of your program. It also interferes with a unit test display, if that's running in the console. So @dev-utils/debug@ offers a no-frills log file for capturing any debugging information you want to generate. You use it like this: 
  debug 'Database connection established'
The log file will be @debug.log@ in the current directory when you run the program. You can see an example of logging and tracing below. h3. Tracing Expressions This is an extra convenience to go with the zero-conf debug logger described above. "Tracing" means recording the value of an exression, typically a single variable. But that usually means a statement like this: @puts "x = #{x}"@. The simple alternative offered here is this: 
  trace 'x'
Of course, the @'x'@ can be any exression, like 
  trace 'x + y - avg(a,b,c)'
  trace 'Process.pid'
If these two trace statements are executed, then something like the following lines will appear in your debugging log file: 
  D, [#244] DEBUG : x = 5
  D, [#244] DEBUG : x + y - avg(a,b,c) = 42
You can see an example of logging and tracing below. h3. Tailoring the Output Format By default, the values emitted by @trace@ are formatted with @inspect@. This works well for numbers, strings, and short arrays. However, for hashes, long arrays, arrays of hashes, custom objects with many attributes, etc., other formats are likely to be more suitable. The following examples show how you can select a different format conveniently, using @ENV@, which will typically contain a large number of elements. See the "API Documentation":api/classes/DevUtils/Debug.html#M000005 for more detail. 
  trace ENV, :p               # inspect (default)
  trace ENV, :s               # to_s
  trace ENV, :pp              # pretty print
  trace ENV, :yaml            # YAML
h3. Using Rake to View the Log If you use "Rake":http://rake.rubyforge.org to run your program or unit tests, then the working directory when the program starts will be the directory containing the @Rakefile@. That means that the log file will be @debug.log@ in that directory. The great thing about Rake is that you can run it from anywhere; well, any _subdirectory_ in your project. Rake will keep looking in parent directories until it finds a Rakefile. It will then @chdir@ accordingly. So it doesn't matter from where you _run_ Rake; the log file will live in a predictable location. This means you can easily create a Rake task to view the log file: 
  task :log do
    puts File.read('debug.log')
  end
If you have a @test@ task to run your unit tests, and they write to the debug logfile, you can now do this: 
  $ rake test
  ...
  $ rake log
  ...
Or: 
  $ rake test && rake log
h3. Planned Features Configure the logfile with a statement like one of the following: 
  Debug.logger = nil
  Debug.logger = STDERR
  Debug.logger = Logger.new(...)
  Debug.logfile = '/var/log/projX/debug.log'
The logger used is always a @Logger@ object (see @logger@ in the standard library). So you can control it to the extent that it allows. The default logger used has a bare minimum of extraneous output, and if you use @Debug.logfile=@, then that maxim is maintained. There are also some improvements that can be made to the output: * Show milliseconds instead of process ID at the start of each line. * Less crap at the start of each line. * Nice formatting of long lines. Finally, making available an advanced @.irbrc@ file with @ri@ integration and more would be a good addition to the project.
h3. Different Kinds of "Debugging" Information Just a note of clarification. In many systems, especially long-running ones, it is a good practice to keep logfiles, so that you can see what's going on, monitor activity, measure performance, and so on. If you include some debugging information, you can get some information on the internal state of the system just before a crash. This kind of "debugging" information is part of an overall logging strategy. The "debugging" information that @dev-utils/debug@ is concerned with, however, is _not_ part of any strategy. It is simply for when you have a bug you need to track down, and want some temporary output (especially tracing; see next section) to aid that cause. That is why there's a simple default filename that keeps getting overwritten; we simply don't need numbered backups or daily rolling logfiles for this throwaway information. h3. Logging and Tracing Example The following code comes from @examples/log-trace-example.rb@ in the distribution: 
  require 'dev-utils/debug'
  require 'extensions/enumerable'  # dev-utils depends on extensions anyway.
  
  debug "Running sanity check of dev-utils/debug logging and tracing."
  
  x, y = 5, 10
  trace 'x + y'
  trace 'Process.pid'
  
  debug "Now we test the various output formatters."
  
  words = %w(wren fibonnaci smelt bovine smeglicious craptacular
             inoccidental myrmidon boondoggle)
  word_lengths = words.build_hash { |word| [word, word.length] }
  
  [:p, :s, :pp, :y].each_with_index do |symbol, idx|
    debug ''
    debug "#{idx+1}. #{symbol.inspect} format"
    trace 'words', symbol
    debug ''
    trace 'word_lengths', symbol
  end
When run, it produces the following output (snipped): 
  D, [#2168] DEBUG : Running sanity check of dev-utils/debug logging and tracing.
  D, [#2168] DEBUG : x + y = 15
  D, [#2168] DEBUG : Process.pid = 2168
  D, [#2168] DEBUG : Now we test the various output formatters.
  D, [#2168] DEBUG :
  D, [#2168] DEBUG : 1. :p format
  D, [#2168] DEBUG : words = ["wren", "fibonnaci", "smelt", "bovine", "smeglicious
  ", "craptacular", "inoccidental", "myrmidon", "boondoggle"]
  D, [#2168] DEBUG :
  D, [#2168] DEBUG : word_lengths = {"craptacular"=>11, "smelt"=>5, "boondoggle"=>
  10, "myrmidon"=>8, "bovine"=>6, "fibonnaci"=>9, "smeglicious"=>11, "wren"=>4, "i
  noccidental"=>12}
  ...
  ...
  D, [#2168] DEBUG : 4. :y format
  D, [#2168] DEBUG : words = ---
  D, [#2168] DEBUG :    - wren
  D, [#2168] DEBUG :    - fibonnaci
  D, [#2168] DEBUG :    - smelt
  D, [#2168] DEBUG :    - bovine
  D, [#2168] DEBUG :    - smeglicious
  D, [#2168] DEBUG :    - craptacular
  D, [#2168] DEBUG :    - inoccidental
  D, [#2168] DEBUG :    - myrmidon
  D, [#2168] DEBUG :    - boondoggle
  D, [#2168] DEBUG :
  D, [#2168] DEBUG : word_lengths = ---
  D, [#2168] DEBUG :    craptacular: 11
  D, [#2168] DEBUG :    smelt: 5
  D, [#2168] DEBUG :    boondoggle: 10
  D, [#2168] DEBUG :    myrmidon: 8
  D, [#2168] DEBUG :    bovine: 6
  D, [#2168] DEBUG :    fibonnaci: 9
  D, [#2168] DEBUG :    smeglicious: 11
  D, [#2168] DEBUG :    wren: 4
  D, [#2168] DEBUG :    inoccidental: 12
h3. Vim Mappings The following Vim shortcuts are useful for creating debug and trace lines. Put them, or a preferred variant, in your @$HOME/.vim/ftplugin/ruby_yourname.vim@ file (change @.vim@ to @vimfiles@ on Windows). p. @,D@ and @,T@ in _insert_ mode add a debug or trace statement after the cursor. You'll want to use them on a blank line, usually after hitting ENTER, or 'o' or 'O' in normal mode. In _normal_ mode, those key sequences create a line _above_ the current one, and put their statement there. In all cases, the cursor is left between the quotes. 
  imap ,D debug ""i
  nmap ,D O,D
  imap ,T trace ''i
  nmap ,T O,T
If you translate these into your editor of choice, let me know and I'll include them here.
h2. Finding Differences Between Complex Objects (Planned) It is common when unit testing to compare objects, especially with a method call like @assert_equal(expected, actual)@. But if you are comparing two _complex_ objects (i.e. with many and possibly nested composed objects), and find that they are _not_ equal, but when you pretty-print them you find that they _look_ equal, then finding the difference can be a pain. Enter @Debug.diff@. You give it two objects, and it recurses their composed objects, evaluating them until it finds a difference, and it returns it. @diff@ is really intended for use in IRB. You can ask for the nth difference, all the differences, or the number of differences. For example: 
  ... irb session ...
h2. Conclusion p. @dev-utils/debug@ offers several very useful debugging aids that are designed to work well with unit testing and with Rake. There are plans for more, and suggestions are most welcome.