Ruby Dual Output / Logging

Summary:

Logging in Ruby is a fairly straight forward process, however I came across an interesting issue. I found that I was constantly doing both a 'log' statement, as well as a 'puts' statement to output to console. Well, this clutters code especially once your script turns into a multi-layered application. Additionally, most of the time what I am logging is the same thing I want to output to console.

In walks Log4r.

Log4r is a comprehensive and flexible logging library written in Ruby for use in Ruby programs. It features a hierarchical logging system of any number of levels, custom level names, logger inheritance, multiple output destinations, execution tracing, custom formatting, thread safteyness, XML and YAML configuration, and more."

Logging to Console:

The most generally place you want to see output from a script is to the console. Our first setup is going to configure Log4r to log to console:

sample.rb:

#!/usr/bin/env/ruby
 
require('rubygems')
require('log4r')
include Logr4
 
log = Logger.new 'sample application'
format = PatternFormatter.new(:pattern => "%l:\t %m")
log.add Log4r::StdoutOutputter.new('console', :formatter=>format)
 
log.info 'sample application logging to console'

You can see that we have configured out 'log' object, and then added a 'format' to it with the 'log.add' method. Here you can specify any format pattern that you want. I generally like to keep the log level in the output for clarity ('%l').

Our output looks like:

wdierkes$ ruby sample.rb 
INFO:    sample application logging to console

Logging to a file:

Now, say we didn't want to log to console, we only want to log to a file. This is a perfectly legit scenario. We would simply change our logger around:

#!/usr/bin/env/ruby
 
require('rubygems')
require('log4r')
include Log4r
 
log_file = './sample.log'
 
log = Logger.new 'sample application'
format = PatternFormatter.new(:pattern => "[ %d ] %l\t %m")
log.add FileOutputter.new('fileOutputter', :filename => log_file, :trunc => false, :formatter=>format)
 
puts "logging to #{log_file}"
log.info 'sample application logging to console'

Only a few changes... we are now adding a bit more to the format pattern as do most log files. We are also now using the FileOutputter class.

Lets see the new output:

wdierkes$ ruby sample.rb 
logging to ./sample.log
 
wdierkes$ cat sample.log 
[ 2007-09-03 15:51:04 ] INFO     sample application logging to console

Perfect!

Combining Console And Logfile Output in One Logger:

Here we arrive at my original dilemma. I constantly want to log the same thing to console, and the log file.. however keeping two separate formatter patterns for each. This turned out to be a lot easier than I had anticipated.

sample.rb:

#!/usr/bin/env/ruby
 
require('rubygems')
require('log4r')
include Log4r
 
log_file = './sample.log'
 
log = Logger.new 'sample application'
console_format = PatternFormatter.new(:pattern => "%l:\t %m")
log.add Log4r::StdoutOutputter.new('console', :formatter=>console_format)
 
file_format = PatternFormatter.new(:pattern => "[ %d ] %l\t %m")
log.add FileOutputter.new('fileOutputter', :filename => log_file, :trunc => false, :formatter=>file_format)
 
log.info 'sample application logging to console'

All we need to do is add both Outputters to our log object, and that is it. Lets check this bad boy out:

wdierkes$ ruby sample.rb 
INFO:    Im logging to both console and ./sample.log now
 
wdierkes$ cat sample.log 
[ 2007-09-03 15:51:04 ] INFO     sample application logging to console
[ 2007-09-03 15:56:05 ] INFO     Im logging to both console and ./sample.log now

Looking nice... real nice.

Toggle Debug

Most of my scripts have a '--debug' flag that will set the global $debug to 'true'. If not set, then $debug should be 'nil'. We can easily add the following to our logger to enable debug:

if($debug)
    log.level = DEBUG
else
    log.level = INFO
end

There are 5 default levels when you create your Logger object:

DEBUG < INFO < WARN < ERROR < FATAL

I usually only toggle between INFO and DEBUG since all other levels will be displayed in 'INFO' mode.

One Logger for all my classes?:

Being that our main goal is world domination, with limited lines of code why not combine all of your classes to use one logger? In most cases, multiple classes are working together to accomplish a single task. In generally, you might want to break up your logs if you are running: multiple daemons, multiple threads, etc.

The following lays out a standard way of accessing the same log object with multiple classes. The concept is to have a 'base' or 'core' class that is passed between the other classes. In this example, the 'base' class is used to maintain common methods that all other classes will likely access.

sample.rb:

#!/usr/bin/env/ruby
 
require('rubygems')
require('log4r')
include Log4r
 
$debug = true
 
module Sample
    class Base
         def initialize(log_file)
              @log = Logger.new 'sample application'
              console_format = PatternFormatter.new(:pattern => "%l:\t %m")
              self.log.add Log4r::StdoutOutputter.new('console', :formatter=>console_format)
              file_format = PatternFormatter.new(:pattern => "[ %d ] %l\t %m")
              self.log.add FileOutputter.new('fileOutputter', :filename => log_file, :trunc => false, :formatter=>file_format)
 
              if($debug)
                  self.log.level = DEBUG
              else
                  self.log.level = INFO
              end
        end
 
        def log=(log_obj)
            @log = log_obj
        end
 
        def log()
            @log
        end
    end
 
    class ClassA
        def initialize(base)
             @base = base  
        end
 
        def base=(base_obj)
            @base = base_obj
        end
 
        def base()
            @base
        end
    end
 
    class ClassB
        def initialize(base)
            @base = base  
        end
 
        def base=(base_obj)
            @base = base_obj
        end
 
        def base()
            @base
         end
    end
end
 
log_file = './sample.log'
base = Sample::Base.new(log_file)
base.log.info 'accessing the logger from the base object'
 
objA = Sample::ClassA.new(base)
objA.base.log.info 'accessing the logger from ClassA (same object)'
 
objB = Sample::ClassB.new(base)
objB.base.log.debug 'accessing the logger from ClassB (same obj)'

Note that the base, objA, and objB are all logging to the Logger established in the Sample::Base class. Lets see what we have:

wdierkes$ ruby sample.rb 
INFO:    accessing the logger from the base object
INFO:    accessing the logger from ClassA (same object)
DEBUG:   accessing the logger from ClassB (same obj)
 
 
wdierkes$ cat sample.log 
[ 2007-09-03 16:15:40 ] INFO     accessing the logger from the base object
[ 2007-09-03 16:15:40 ] INFO     accessing the logger from ClassA (same object)
[ 2007-09-03 16:15:40 ] DEBUG    accessing the logger from ClassB (same obj)

You like?

Reference:

Log4r: http://log4r.sourceforge.net/