The standard Ruby distribution contains the Logger class, a very nice piece of work written by Hiroshi Nakamura, that allows you to add logging to your Ruby code with very little effort. Very little effort appeals strongly to the lazy-programmer streak in me. Contrary to what you may have heard, being a lazy programmer is a very good quality. Laziness is the first of the three virtues of a programmer (the others being Impatience and Hubris). Laziness is about doing as much as possible with the least effort, which lets you get more done.

However, sometimes I am even too lazy to use Logger. I feel like I have to do too much work. I don’t want to expend much more effort on logging than creating a log message. If it takes more work than that then I’m just not going to be inclined to put logging into my code. I take facilitating such laziness as a true challenge - I’ll work hard to be lazy.

One of my personal principles of programming is

the best infrastructures are invisible.

What I mean by this is: if you have to think more than a little about how to use something supplied by an infrastructure - if its use isn’t so transparent that it borders on complete invisibility - you’ll somehow misuse it. It has to be simple. Trivial. Invisible. If you’re designing infrastructure and you don’t believe in this principle, turn in your badge and go do something else. We’ll all thank you for that.

So, being driven to activity in order to increase my overall opportunity to be even lazier than I already am, I began the task of making logging as invisible as possible.

The Standard Ruby Logger Class

Nakamura created a great logging facility. Logger does what it should do very well. I’ve used many logging packages in many different environments and his stands out as one that works and contains all the functionality that one would need to create good logs.

Creating Logs - When a Logger instance is created, an IO Stream is given as the destination of messages. If a String is given, it is interpreted as a filename and a file is opened as the IO Stream to receive the messages. If a File is given, it is written to as an IO Stream. Loggers can also be created that roll over by age or size.

Logging Messages - Logger messages are associated with one of five levels of increasing severity: debug, info, warn, error and fatal. These names double as the methods used to create such logging messages, and when appended with a question mark, indicate whether or not the current threshold would pass the message.

Thresholding Messages - Logger instances each have a threshold which only passes along messages of that severity or higher to be written. This threshold is dynamic, so that under different conditions the threshold can be raised or lowered. Anomalies can be logged more deeply if they can be detected early enough.

Formatting Messages - There is a standard format for log messages, but this may be changed if desired. Each Logger instance has a formatter, and it may be dynamically reassigned during processing. While the interface that calls the formatter is not accessible, there is nothing to prevent the message being a more complex object than a string - something that could be expanded by the formatter into a more robust log entry.

Ease of Use - The Logger distribution comes with an Logger::Application convenience class that can be inherited to admit simplified logging. For small applications this can significantly reduce the effort required to log messages.

But for all this, there is still some pain for me. I need a variation of logging that gives me:

More Succinct Formatting - I need to know when something happened in sub-second resolution, the severity of the entry, the message, and perhaps the class of the object logging the message, in that order. I don’t want anything fancier than that (at least for baseline logging functionality) but it should be as easy to read and decipher as possible, and should lead me to any problem situations as quickly as possible. The standard Logger framework’s formatter needs to be jazzed up a little.

Ubiquity over Objects - Logger instances are nice, but I don’t want to manage or refer to them every time I want to write to the log. I don’t want to lose any versatility I get with using the objects - I should be able to use them when I need to - however I want my logging statements to be as sparse as possible. For the most basic, simple logging, I don’t want to have to pass around logging objects and call their methods. The Logger I’m using needs to be tucked away and out of sight, at least in these simple situations. Logging should be more ubiquitous and seem to just become a global-level extension of the Ruby language.

Even More Ease of Use - Along the same lines as the ubiquity and aside from simple calls to start logging and log messages, there should be no need for additional information. Details should be hidden from the logging facility’s users and kept as invisible as possible. Logger::Application is not a bad solution, but it does force an application to be derived from this class to get the ease of use. I don’t want my applications to be Loggers; there’s typically a lot more going on than just logging messages.

Easy Logging

What evolved from this pain are EasyLog, EasyLogger and EasyLogFormatter. These objects address the issues I had with using just the standard Logger and my desire for a higher degree of invisibility. Using the Easy Logging framework is virtually painless, oriented to the demands of even the laziest Ruby programmers.

EasyLogFormatter

I’ll discuss the EasyLogFormatter class first since besides being simple, it can also be used with the existing Logger. The intention of this class is to capture what I need when writing applications, making entries that are written to logs a little more succinct.

The creation of an EasyLogFormatter and its assignment to a Logger is simple. Given a Logger instance logger,

logger.formatter = EasyLogFormatter.new

By default the instance formats messages written to logs as a date-time stamp, a severity and a message:

05/27/08 13:38:02.695 INFO   loading preferences

This format, while being quite succinct, still contains just the information needed to track activity at a high level. Additional information can be easily added to the message.

The difference between this and the standard Logger::Formatter is that there is no mention of the Program, and the notion of sub-second precision is added. This difference supports the distribution of information across a set of logs, something I call distributed logging.

In distributed logging, I throw out the Program specification and write the messages to a separate log for each instance of an application, not together to a single log for a whole set of applications. For me, the log of an entire system is really the set of individual logs - one for the application coordinator, and the others subordinate to it. When a set of interacting applications is logging to the same IO Stream, I’ve found that a coordinating log contains just the highest-level messages, and constituent application instances write their messages to a separate log for a particular application instance. Besides making these logs of specific functionality shorter and more understandable, it reduces cross-functionality cross-talk, which is important since Logger has known bugs with regard to write-locking (it doesn’t.) The chances of entries getting garbled through contention is significantly reduced.

From this perspective, sub-second precision becomes very important - the standard Logger::Formatter resolves to seconds which is not good enough for most distributed logging - precision must be high enough to reconstruct the precise sequence of events across multiple logs. To support this, when creating an EasyLogFormatter the caller can specify the sub-second precision of the date-time stamp - but this is optional. If left unspecified, the system statistically determines the clock precision itself, and uses this value when writing messages.

The principle benefit of distributed logging is that entries from a subset of logfiles may be combined after the fact and sorted precisely by time to provide an accurate record of subsystem interaction. By combining logfiles during viewing rather than during recording, it becomes much easier to see the trees in the forest - the certain trees that matter - and to more easily observe how their branches intertwine. In absence of a sophisticated viewer with such features, this provides an accessible mechanism for understanding what a system has done.

# easylog.rb  (the EasyLogFormatter class)
class EasyLogFormatter < Logger::Formatter
  def initialize(subsecond_precision = nil)
    super()
    @AppLogFormat = "%s %-5s  %s\n"
    self.datetime_format = "%m/%d/%y %H:%M:%S."
    @usecs = subsecond_precision || Time.subsecond_precision
  end

  def format_datetime(time)
    time.strftime(datetime_format) << ("%06d" % time.usec)[0,@usecs]
  end

  def call(severity, time, progname, msg)
    @AppLogFormat % [format_datetime(time), severity, msg2str(msg)]
  end
end

The code consists of three methods that override the ones in its Logger::Formatter ancestor. The initialize method replaces the entry format and date-time stamp format and captures the sub-second precision either from what was given or from the value determined by the Time class. (Time’s subsecond_precision method is added by the eymiha rubygem.) The format_datetime method adds microseconds to the datetime stamp based on the instance’s subsecond_precision value. The call method formats and returns the log entry as a string.

EasyLogger

The EasyLogger class derives from Logger, fundamentally doing what a Logger does but adds the notion of a class-level default EasyLogger instance. At first glance this seems superfluous, but it frees the user from passing the instance down through the methods in the system. Since the class owns the instance, it is available wherever the class has been made available.

Creating a new EasyLogger is straightforward. Somewhere in an application prior to logging, an EasyLogger is initialized:

EasyLogger.new 'logfile'

If no default exists, the EasyLogger instance becomes the default. Things are put into place so the default is used to make simple logging ubiquitous rather than requiring EasyLogger objects to be passed within the execution call-stack.

A Logger instance has five methods used to write messages to the log they manage: default, info, warn, error and fatal. These are all available directly in an EasyLogger instance, but class methods with these names are also built when the class is loaded, each taking a message and an array of Loggers that will receive the message. These class methods call the instance methods on the EasyLoggers in the array. Besides providing a simple mechanism for logging the same message in multiple EasyLogger instances, which may be important in some applications, it has special functionality when the array is empty: it sends the message to the default EasyLogger.

What this means is that to log a message to the default EasyLogger instance, all that needs to be done is to call the EasyLogger class method with the correct severity:

EasyLogger.error "something terrible is going on"

To manage the default Logger instance, a few more bits of plumbing are needed. Class methods are provided to get the default, change the default, and finish using the default. The last is present to set up for the assignment of a new default upon the creation of a new EasyLogger.

# easylog.rb  (the EasyLogger class)
class EasyLogger < Logger
  class_attr_reader :default_logger
  attr_accessor :classify

  def initialize(logdev, shift_age = 'weekly', shift_size = 1048576,
                 subsecond_precision = nil)
    super(logdev, shift_age, shift_size)
    @formatter = EasyLogFormatter.new(subsecond_precision)
    @classify = true
    @@default_logger = self unless @@default_logger
  end

  def self.change_logger(new)
    old, @@default_logger = @@default_logger, new
  end

  def self.finish_logging
    change_logger nil
  end

  private

  def self.build_loggers
    (0..4).collect { |i| Logger::SEV_LABEL[i].downcase }.each do |severity|
      EasyLogger.class_eval <<EOF
def self.#{severity}(message, *loggers)
  loggers = [@@default_logger] if loggers.length == 0
  loggers.compact.each { |logger| logger.#{severity}(message) }
end
EOF
    end
  end

  self.build_loggers
end

The first thing to notice in the code is that default_logger method is defined through the a class_attr_reader method. This has the same purpose as the attr_reader method does for instance methods (it is added by the eymiha rubygem). The initialize method builds the instance upon a Logger, creates a new EasyLogFormatter for formatting messages, and assigns itself as the default_logger if one has not yet been assigned. The change_logger class method swaps in the new EasyLogger for the old default and the finish_logging method sets the default to nil.

The code also contains a classify attribute. This is present to support the EasyLog module, the final piece of the Easy Logging framework.

EasyLog

Ease of use is made complete through the EasyLog module. Not only does it further increase the ubiquity of logging, but it also makes the establishment of logging virtually invisible.

On high, somewhere before logging starts, instead of creating an EasyLogger as I did in the previous section, I would just require the code and start logging to a file:

require 'eymiha/util/easylog'
start_logging 'logfile'

Then, in some method in other code file, without needing to do another require, a message can be logged:

log_debug "the value of foo is '#{foo}'"

And that’s it. The module has built the log_debug, log_info, log_warn, log_error and log_fatal methods that take a message (and optionally an array of EasyLoggers, as do the class methods of EasyLogger) and call the corresponding EasyLogger class methods that use the default_logger. And what’s more, it has included them into all of the objects in the system. Once a single require of the Easy Logging framework has been done somewhere in the system, logging is available everywhere for free!

Analogous to the EasyLogger, methods are available in EasyLog that get the default EasyLogger, change the default EasyLogger, and finish using the default EasyLogger.

The classify instance variable in EasyLogger that we alluded to earlier still needs an explanation. It is a switch that when true appends the class name of the object logging the message parenthetically to the end of the message. It’s tucked away in the EasyLogger instance so that some logs can have the the class names appended while others need not. This is simply a convenience for log file consumers who need that level of detail.

easylogger.classify = false

is all that’s needed to turn this off.

#easylog.rb  (the EasyLog module)
module EasyLog
  def start_logging(logdev, shift_age = 'weekly', shift_size = 1048576, subsecond_precision = nil)
    EasyLogger.finish_logging
    EasyLogger.new(logdev, shift_age, shift_size, subsecond_precision)
  end

  def easylogger
    EasyLogger.default_logger
  end

  def change_easylogger(easylogger)
    EasyLogger.change_logger(easylogger)
  end

  def finish_logging
    EasyLogger.finish_logging
  end

  private

  def classify_log_message(message,easylogger)
    ((easylogger != nil) ? easylogger.classify : false) ?
      "#{message} (#{class_name})" : message
  end

  def self.build_loggers
    (0..4).collect { |i| Logger::SEV_LABEL[i].downcase }.each do |severity|
      EasyLog.module_eval <<EOF
def log_#{severity}(message,*easyloggers)
  easyloggers = [easylogger] if easyloggers.size == 0
  easyloggers.compact.each { |easylogger|
    EasyLogger.#{severity}(classify_log_message(message,easylogger),easylogger)
  }
end
EOF
    end
  end

  self.build_loggers
end

include EasyLog

The code is remarkably simple. The start_logging method finishes logging with the current EasyLogger instance and creates a new default EasyLogger. The easy_logger method returns EasyLogger’s default EasyLogger instance. The change_easylogger swaps in the new EasyLogger as the default. The finish_logging method sets the default to nil. Finally, the EasyLog module is included into Ruby to integrate it into all objects.

A Little More Convenience

After releasing the initial Easy Logging functionality, it became clear to me that there were a few additional features to add that would make using it even easier to use, namely interrogating and setting thresholds, and emitting blank lines.

Thresholds

Message thresholding is fully developed in Logger, but nothing was done in EasyLogging to make it more accessible. The idea is that given Logger’s overall message severity relationship

DEBUG < INFO < WARN < ERROR < FATAL

setting a threshold at one of these values would only log messages with a level at or above the threshold value. For instance, if the threshold was set to WARN, only warning, error and fatal error messages would be logged. To set this within the EasyLog, an explicit assignment is needed:

easylogger.level = Logger::WARN if easylogger

This is terribly un-lazy. The access to the easylogger must be exposed and qualified, and an assignment to a value in Logger must be exposed, all counter to the EasyLogging lazy philosophy. Thresholding access and modification can be done much more conveniently if a few methods are added.

# easylog.rb  (support for thresholding)

class EasyLogger
  def self.level
    @@default_logger ? @@default_logger.level : nil
  end

  def self.build_loggers
    (0..4).collect { |i| Logger::SEV_LABEL[i].downcase }.each do |severity|
      EasyLogger.class_eval <<EOF
def self.#{severity}(message,*loggers)
  loggers = [@@default_logger] if loggers.length == 0
  loggers.compact.each { |logger| logger.#{severity}(message) }
end

def self.#{severity}?
  @@default_logger && @@default_logger.#{severity}?
end

def self.level_#{severity}
  @@default_logger.level=Logger::#{severity.upcase} if @@default_logger
end
EOF
    end
  end
end

module EasyLog
  def log_level
    EasyLogger.level
  end

  def self.build_loggers
    (0..4).collect { |i| Logger::SEV_LABEL[i].downcase }.each do |severity|
      EasyLog.module_eval <<EOF
def log_#{severity}(message,*easyloggers)
  easyloggers = [easylogger] if easyloggers.size == 0
  easyloggers.compact.each { |easylogger|
    EasyLogger.#{severity}(classify_log_message(message,easylogger),easylogger)
  }
end

def log_#{severity}?
  EasyLogger.#{severity}?
end

def log_level_#{severity}
  EasyLogger.level_#{severity}
end
EOF
      end
    end
  end

Eleven matching methods are now in EasyLogger and EasyLog. The first ones report the current threshold, the second set interrogate the threshold with respect to a level, and the third set assign the threshold level:

This hides the references to the Logger values and the access and qualification of the default EasyLogger, as well as holding to the EasyLogging style.

Blank Lines

When logging is well-sprinkled into a program, significant information can be conveyed to a reader. If that reader is a program that processes logs, the information can be sorted and organized so that the activity is easily understood. In absence of such a program, I am at a loss when faced with many pages of logs. Everything runs together, my eyes gloss over, and I must expend far too much effort to see what happened. And since the logging I’m doing is in plain text, I can’t use features such as color and font to help. All I potentially have at my disposal are blank lines and indentation.

First off, indentation is hard. In order to do it right, it has to be nested - that means some sort of indentation stack is needed. When you enter a region you’d like to be more indented, you push an indent onto the indentation stack, and when leaving, you pop the stack to get back to the original indent. While this seems simple, it can be very painful. Missing a push or a pop throws everything off. Of course, the Ruby way would be to do this in a block, something like

log_indent("  ") { some_code_that_may_do_logging }

but that means that logging is elevated to the level of a principal activity, failing me in the same way as the Logger-as-the-superclass did. In light of this, I’m casting off indentation as a feature that is just too painful to use to include in EasyLogging.

Blank lines are another story. A blank line represents grouping - interesting that a line absent of information can add information; it just does it on another cognitive level. By judiciously using blank lines, I can segregate different parts of the log, which is just what I’m looking for. Judiciously is a loaded word, of course - too many blank lines can be as much of an impediment to understanding as too few - but when used well, grouping is a very powerful feature.

To handle logging blank lines, we add to two methods, and also metacode:

# easylog.rb  (blank line support)

class EasyLogFormatter
  def call(severity, time, progname, msg)
    (msg == "") ?
      "\n" :
      (@AppLogFormat % [format_datetime(time), severity, msg2str(msg)])
  end
end

class EasyLogger
  def self.build_loggers
    (0..4).collect { |i| Logger::SEV_LABEL[i].downcase }.each do |severity|
      EasyLogger.class_eval <<EOF
def self.#{severity}(message="",*loggers)
  loggers = [@@default_logger] if loggers.length == 0
  loggers.compact.each { |logger| logger.#{severity}(message) }
end

def self.#{severity}?
  @@default_logger && @@default_logger.#{severity}?
end

def self.level_#{severity}
  @@default_logger.level=Logger::#{severity.upcase} if @@default_logger
end
EOF
    end
  end

end

module EasyLog
  def classify_log_message(message,easylogger)
    ((easylogger != nil) ?
     (easylogger.classify and message != "" and message != " ") : false) ?
      "#{message} (#{class_name})" : message
  end

  def self.build_loggers
    (0..4).collect { |i| Logger::SEV_LABEL[i].downcase }.each do |severity|
      EasyLog.module_eval <<EOF
def log_#{severity}(message="",*easyloggers)
  easyloggers = [easylogger] if easyloggers.size == 0
  easyloggers.compact.each { |easylogger|
    EasyLogger.#{severity}(classify_log_message(message,easylogger),easylogger)
  }
end

def log_#{severity}?
  EasyLogger.#{severity}?
end

def log_level_#{severity}
  EasyLogger.level_#{severity}
end
EOF
    end
  end
end

The call method in EasyLogFormatter is modified so that when the given message is empty, only a newline is logged. We also adjust the metacode so that when logging if no message is given, the message is defaulted to be empty to make the result a blank line. The classify_log_message method in EasyLog is also modified to keep any parenthesized class names off of the blank lines. Since blank lines are logged with an inherent severity, they are subject to thresholding to keep extra blank lines out of the log.

But looking closely at classify_log_message, there’s one more trick to see. The parenthesized class name is not only not added when the message is empty - it is also not added when the message contains just a single space. Whenever the message to log is just a single space, the EasyLogFormatter will still add the time and severity - but the rest of the line will be blank. This gives me two options - a blank line with nothing on it and a line with just a blank message. I get a cheap two-level nesting of blank lines virtually for free.

Laziness Revisited

A single one-line require, a single one-line start_logging call, and logging is available everywhere in an application. This is just about as lazy as a programmer can be. And about as productive as a programmer that needs to include logging can be as well.

The code is available in the eymiha_util rubygem, available at rubygems.org.