Context- and Structure-friendly logging in Ruby

output

Project here:
     https://github.com/jordansissel/ruby-cabin

% ruby examples/sample.rb
I, [2011-10-11T01:45:04.011360 #1441]  INFO -- : {"timestamp":"2011-10-11T01:45:04.010614-0700","program":"sample program","foo":"Hello","example":100,"message":"bar bar bar!","level":"info"}
I, [2011-10-11T01:45:05.173034 #1441]  INFO -- : {"timestamp":"2011-10-11T01:45:05.172846-0700","program":"sample program","foo":"Hello","example":100,"message":"Timing bar","duration":1.162167376}
I, [2011-10-11T01:45:05.173392 #1441]  INFO -- : {"timestamp":"2011-10-11T01:45:05.173322-0700","program":"sample program","foo":"Hello","example":100,"message":"bar bar bar!","level":"info"}
I, [2011-10-11T01:45:05.740390 #1441]  INFO -- : {"timestamp":"2011-10-11T01:45:05.740275-0700","program":"sample program","foo":"Hello","example":100,"message":"Another bar timer","duration":0.566953405}
I, [2011-10-11T01:45:05.740577 #1441]  INFO -- : {"timestamp":"2011-10-11T01:45:05.740530-0700","program":"sample program","message":"All done.","level":"info"}

sample.rb

require "rubygems"
require "cabin"
require "logger"

# Cabin is something I'm implementing and experimenting with.
# https://github.com/jordansissel/ruby-cabin (or gem install cabin)
@logger = Cabin::Channel.new

# A logging channel can have any number of subscribers.
# Any subscriber is simply expected to respond to '<<' and take a single
# argument (the event)
# Special case of stdlib Logger instances that are wrapped smartly to 
# log JSON and call the right Logger method (Logger#info, etc).
@logger.subscribe(Logger.new(STDOUT))

# You can store arbitrary key-value pairs in the logging channel. 
# These are emitted with every event.
@logger[:program] = "sample program"

def foo(val)
  # A context is something that lets you modify key-value pieces in the
  # logging channel and gives you a trivial way to undo the changes later.
  context = @logger.context()
  context[:foo] = val
  context[:example] = 100

  # The point of the context above is to save context so that the bar() method 
  # and it's logging efforts can include said context.
  timer = @logger.time("Timing bar")
  bar()
  timer.stop   # logs the result.

  @logger.time("Another bar timer") do
    bar()
  end

  # Clearing this context will exactly undo the changes made to the logger by
  # this context.
  context.clear()
end

def bar
  @logger.info("bar bar bar!")
  sleep(rand * 2)
end

foo("Hello")
@logger.info("All done.")