Navigation
Voterbox
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:
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:
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:
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:
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:
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:
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:
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:
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:
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/