Search this site





Smart logging hacks in ruby

Ruby has Logger. It is good, but strings suck. In a world where more and more people are using log data for inputs and analysis, structured data is good. I want to log structured data.

This lead to me subclassing Logger and additionally providing my own logger format class. The code for this is in logstash, logging.rb.

What did I add? Two main goals: First, improve context. Second, log structured data (objects). This is achieved by style changes (log objects, not strings), adding awesome_print support, adding code context to each log (line/file/method), etc.

To support the first goal (context), if the loglevel is 'debug' I will inspect the call stack and include the file and line of code that is logging. I also set the 'progname' to the name of the program by default. To support the second goal, log objects and improve how objects are formatted into strings with Object#inspect (or awesome_inspect, if available).

Some examples:

>> logger =
I, [2010-11-12T15:19:48.388469 #18782]  INFO -- : ["Failed: require 'ap' (aka awesome_print); some logging features may be disabled", #<LoadError: no such file to load -- ap>]
# This is an example of what javascript folks call 'progressive enhancement'
# - we still function if awesome_print is not available.

>> logger.level = Logger::WARN
>> logger.warn("Hello")
W, [2010-11-12T15:20:05.465705 #18782]  WARN -- irb: Hello

>> logger.warn(["rejecting bad client", { :client => "" }])
W, [2010-11-12T15:21:04.639404 #18782]  WARN -- irb: ["rejecting bad client", {:client=>""}]

>> logger.level = Logger::DEBUG
>> logger.warn("Hello")
W, [2010-11-12T15:21:57.754874 #18782]  WARN -- (irb):12#irb_binding: Hello
# Notice the context (file, line, method)       ^^^^^^^^^^^^^^^^^^^^
# When DEBUG level is set only due to performance and verbosity concerns.
The main benefit personally is logging objects instead of strings, which you can do, today, with the standard Logger. However, standard logger doesn't make nice with awesome_print or add file/line/method context. Anyway, logging objects lets you later hook a smarter error handling tool up to your logging that can inspect the structured data rather than having to regex your way through a single string.

If you have awesome_print available, the object output by my formatter gets even more useful for human viewing:

Why log structured? Easier to parse and query later, like in a logstash query.