The Books are Wrong About Logger

Posted over 2 years ago in The Standard Library.

I've read several books that introduced the standard Logger library and they all agree on one thing: you can't customize the output. That's so last version in thinking! Behold...

Here's a trivial Logger script, showing basic functionality:

#!/usr/bin/env ruby -w

require "logger"

def expensive_error_report
  sleep 3  # Heavy Computation Simulation (patent pending)
  "YOU BROKE IT!"
end

log       = Logger.new(STDOUT)
log.level = Logger::INFO  # set out output level above the DEBUG default

log.debug("We're not in the verbose debug mode.")
log.info("We do see informative logs though.")
if log.error?  # check that this will be printed, before waste time
  log.error(expensive_error_report)
end

If you run that you will see:

I, [2006-07-08T11:17:19.531943 #340]  INFO -- : We do see informative logs though.
E, [2006-07-08T11:17:22.532424 #340] ERROR -- : YOU BROKE IT!

Now everyone has always known you can format the date and time display using a strftime() compatible pattern:

#!/usr/bin/env ruby -w

require "logger"

def expensive_error_report
  sleep 3
  "YOU BROKE IT!"
end

log                 = Logger.new(STDOUT)
log.level           = Logger::INFO
log.datetime_format = "%Y-%m-%d %H:%M "  # simplify time output

log.debug("We're not in the verbose debug mode.")
log.info("We do see informative logs though.")
if log.error?
  log.error(expensive_error_report)
end

Which gives us the slightly easier to read:

I, [2006-07-08 11:23 #384]  INFO -- : We do see informative logs though.
E, [2006-07-08 11:23 #384] ERROR -- : YOU BROKE IT!

All books I've read to date though tell you that's the end of the customization line. But, if you are using Ruby 1.8.4 or higher, it's no longer true:

#!/usr/bin/env ruby -w

require "logger"

# Build a Logger::Formatter subclass.
class PrettyErrors < Logger::Formatter
  # Provide a call() method that returns the formatted message.
  def call(severity, time, program_name, message)
    if severity == "ERROR"
      datetime      = time.strftime("%Y-%m-%d %H:%M")
      print_message = "!!! #{String(message)} (#{datetime}) !!!"
      border        = "!" * print_message.length
      [border, print_message, border].join("\n") + "\n"
    else
      super
    end
  end
end

def expensive_error_report
  sleep 3
  "YOU BROKE IT!"
end

log           = Logger.new(STDOUT)
log.level     = Logger::INFO
log.formatter = PrettyErrors.new  # Install custom formatter!

log.debug("We're not in the verbose debug mode.")
log.info("We do see informative logs though.")
if log.error?
  log.error(expensive_error_report)
end

Here's what that code produces:

I, [2006-07-08T12:20:31.325112 #521]  INFO -- : We do see informative logs though.
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!! YOU BROKE IT! (2006-07-08 12:20) !!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

Don't believe everything you read.

Jeff added about 2 hours later:

Thanks for this post. I've just started learning about the Ruby logger, so this was good timing for me.

Leonard Richardson added 2 days later:

I just checked the Ruby Cookbook and it mentions call(), though your technique of using a subclass is better than my technique of just overriding call().

Justin added 2 days later:

James, thanks for that! Too bad they didn't allow for custom logging levels. I just hacked it, but my solution is just that, a quick hack.

Neville added 5 months later:

AFAIK, the following example can be simplified using loggers block parameter, whereby the block is not "yielded" to unless the level is active ... ie:

if log.error?
  log.error(expensive_error_report)
end

becomes:

log.error {expensive_error_report}

(Note the curly braces)

James Edward Gray II added 5 months later:

Thanks for showing that Neville. I was unaware of that feature.

Add Your Thoughts

You can use Markdown in the body of your comment to format text and make links.

Note that I reserve the right to edit any content you post here. I typically exercise this right to fix formatting issues. All posts must be approved so spam will never been seen on these pages.

Author:
URL or Email (optional):
Body: