Here at Zetetic we do a lot of logging, and a lot of looking at logs. In particular, we have a couple of daemon processes implemented in Rails for PingMe that handle our message queueing and parsing of incoming messages (when you reply to your pings or create new ones by remote). If you have any experience with message queueing systems, you’ll recall that these are not easy things to maintain, and require access to really good diagnostics. And if you are familiar with Rails you’ll recall that there are no time-stamps prepended to the log messages, making it very difficult sometimes to track down what happened when.
I did a quick bit of poking around and came across this fantastic article with a number of tips in terms of logging. Their solution for the issue of formatting the messages (so that you can have timestamps) is to subclass Logger, and instantiate that.
However, we have our own Loggers all over the place, in our daemons, they use the Logger class which has been patched by Rails to have that timestamp-less format. What we do from there is replace the Rails logger instance with our own (there are a few reasons for this, having to do with forking processes, resources, and the nature of daemons that I don’t want to get into), which works beautifully:
logger = Logger.new("#{config[:log_dir]}/#{config[:name]}.log", 'daily')
unless config[:log_level].blank?
begin
logger.level = Logger.const_get(config[:log_level])
rescue StandardError => e
logger.level = Logger::INFO
logger.error "An exception occurred while setting log level to #{config[:log_level]}, setting to INFO. Exception: #{e.message}"
end
else
logger.level = Logger::INFO
end
logger.info "Initialized log @ #{Time.now.utc} with log_level #{logger.level.to_s}"
logger.info "Starting up Dispatcher #{config[:name]}..."
# over-ride the active record logger (which would be closed now)
ActiveRecord::Base.logger = logger
ActionMailer::Base.logger = logger
I really don’t feel like subclassing Logger, I just want to adjust the default behavior, since we’re using the same loggers everywhere. So I opened up config/environment.rb, and at the bottom of it, added this:
# re-patch logger to restore format patched out by Rails
class Logger
def format_message(severity, timestamp, program, message)
"#{timestamp.to_formatted_s(:db)} #{program}: [#{severity}] #{message}\n"
end
end
Works fantastic! Thanks to Maintainable Software for their post.