Gray Soft / The Standard Library / The Books are Wrong About Logger

8

JUL
2006

The Books are Wrong About Logger

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.

In: The Standard Library | Tags: Hidden Features | 7 Comments

Comments (7)

Jeff July 8th, 2006 Reply Link

Thanks for this post. I've just started learning about the Ruby Logger, so this was good timing for me.
1. Reply (using GitHub Flavored Markdown)
  
  Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
  
  Or login with:
  Name * Email URL Comment *
Leonard Richardson July 10th, 2006 Reply Link

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().
1. Reply (using GitHub Flavored Markdown)
  
  Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
  
  Or login with:
  Name * Email URL Comment *
Justin July 11th, 2006 Reply Link

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.
1. Reply (using GitHub Flavored Markdown)
  
  Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
  
  Or login with:
  Name * Email URL Comment *
Neville December 13th, 2006 Reply Link
AFAIK, the following example can be simplified using Logger's 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)
1. Reply (using GitHub Flavored Markdown)
  
  Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
  
  Or login with:
  Name * Email URL Comment *
2. James Edward Gray II December 13th, 2006 Reply Link
  
  Thanks for showing that Neville. I was unaware of that feature.
  1. Reply (using GitHub Flavored Markdown)
    
    Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
    
    Or login with:
    Name * Email URL Comment *
Joe Martin March 18th, 2010 Reply Link
You can even simplify this a bit more by redefining Logger::Formatter's call method via module_eval:
```
Logger::Formatter.module_eval(
  %q{ def call(severity, time, progname, msg)} +
  %q{ "#{severity} -- #{format_datetime(time)}  #{progname}:: #{msg2str(msg)}" end}
)
```
Adding this to your script will overwrite the call method in Formatter. I much prefer to manually editing the core Ruby library files, and is more efficient than creating a new subclass.
1. Reply (using GitHub Flavored Markdown)
  
  Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
  
  Or login with:
  Name * Email URL Comment *
2. James Edward Gray II March 18th, 2010 Reply Link
  
  That works too, but I prefer to stick to the public interface the library defines for adjusting the format. My hope that it will stay supported even if the call() method is no longer used internally.
  1. Reply (using GitHub Flavored Markdown)
    
    Comments on this blog are moderated. Spam is removed, formatting is fixed, and there's a zero tolerance policy on intolerance.
    
    Or login with:
    Name * Email URL Comment *