Smart logging hacks in ruby
Posted Fri, 12 Nov 2010
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 = LogStash::Logger.new(STDOUT)
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 => "1.2.3.4" }])
W, [2010-11-12T15:21:04.639404 #18782] WARN -- irb: ["rejecting bad client", {:client=>"1.2.3.4"}]
>> 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.