Recently I had a fun problem where my log messages in Ruby on Rails were not outputting at all. This included ActiveRecord/internal Rails messages as well as messages I defined. Particularly, I was receiving header information, but not the message itself, which should have been a pretty big clue. Messages looked something like this:

INFO Tue Feb 06 04:42:22 -0800 2007 (1539)
 
DEBUG Tue Feb 06 04:42:22 -0800 2007 (1539)
 
DEBUG Tue Feb 06 04:42:22 -0800 2007 (1539)
 
INFO Tue Feb 06 04:42:22 -0800 2007 (1539)

If I had any brains, I would have remembered that the default logging behavior does not include a snazzy header with detailed information like the above. This means that I had overridden the message format. I had the following code in my environment.rb file:

class Logger
  def format_message(severity, timestamp, msg, progname)
    "#{severity} #{timestamp} (#{$$})\n #{msg}\n"
  end
end

To troubleshoot, I tried using the formats presented at two other web sites. Eventually I happened onto a description of how Ruby 1.8.3 had transposed the msg and progname arguments in the format_message method. Bingo!

Now I have a format_message definition that aligns better with the one posted to the Ruby on Rails Wiki:

class Logger
  def format_message(severity, timestamp, progname, msg)
    "#{severity} #{timestamp} (#{$$})\n #{msg}\n"
  end
end

Why did my log messages work and then stop working? Well, I first noticed this problem locally when I moved to my MacBook as a development environment. Naturally, I thought the OS X environment was to blame. Well, with the change I also moved to the newest version of Ruby, where the transposition happened. My host, Dreamhost, also moved to the newest version of Ruby around that time, making log messages stop working there. This lent a general thought that I had messed up my app when in fact I just hadn’t adapted to the changes in Ruby 1.8.3.

I have not uncovered more information on why the parameters for format_message where transposed. Accident? Intentional (perhaps there is new method overloading in place)?

Feb 20, 2007 · Subscribe · Archive · Projects · Twitter · GitHub · Flickr