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
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:
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.
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.
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.
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.
What evolved from this pain are
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.
I’ll discuss the
EasyLogFormatter class first since besides being simple, it can also be used with the existing
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.
By default the instance formats messages written to logs as a date-time stamp, a severity and a message:
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.
The code consists of three methods that override the ones in its
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
subsecond_precision method is added by the
format_datetime method adds microseconds to the
datetime stamp based on the instance’s
call method formats and returns the log entry as a string.
EasyLogger class derives from
Logger, fundamentally doing what a Logger does but adds the notion of a class-level default
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:
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.
Logger instance has five methods used to write messages to the log they manage:
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
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:
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
The first thing to notice in the code is that default_logger method is defined through the a
This has the same purpose as the
attr_reader method does for instance methods (it is added by 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.
change_logger class method swaps in the new
EasyLogger for the old default and the
finish_logging method sets the default to
The code also contains a
This is present to support the
EasyLog module, the final piece of the Easy Logging framework.
Ease of use is made complete through the
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:
Then, in some method in other code file, without needing to do another
require, a message can be logged:
And that’s it.
The module has built the
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
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
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.
is all that’s needed to turn this off.
The code is remarkably simple.
start_logging method finishes logging with the current
EasyLogger instance and creates a new default
easy_logger method returns
change_easylogger swaps in the new
EasyLogger as the default.
finish_logging method sets the default to
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.
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
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:
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.
Eleven matching methods are now in
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:
|EasyLogger class method||EasyLog method||Action|
|level||log_level||returns the current threshold of the default
|debug?||log_debug?||returns true if debug messages will be logged by the default
|info?||log_info?||returns true if informational messages will be logged by the default
|warn?||log_warn?||returns true if warning messages will be logged by the default
|error?||log_error?||returns true if error messages will be logged by the default
|fatal?||log_fatal?||returns true if fatal error messages will be logged by the default
|level_debug||log_level_debug||sets the threshold of the default
|level_info||log_level_info||sets the threshold of the default
|level_warn||log_level_warn||sets the threshold of the default
|level_error||log_level_error||sets the threshold of the default
|level_fatal||log_level_fatal||sets the threshold of the default
This hides the references to the
Logger values and the access and qualification of the default
EasyLogger, as well as holding to the
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
but that means that logging is elevated to the level of a principal activity, failing me in the same way as the
In light of this, I’m casting off indentation as a feature that is just too painful to use to include in
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:
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.
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.
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.