Logger – simple, yet powerful Rails debugging tool

I don’t know about You, but logs are for me most powerful debugging tool. Placing many logger.debug or logger.info can quickly provide info what is happening inside Rails application.

This approach is especially useful when something wrong is happening and trigger is unknown. Placing many logging directives can provide data for analysis what could be a reason.

Default Rails logger has one serious flaw which makes logs on production sites almost useless – messages are not grouped in calls. If You have many processes of Rails running and logging to single file, some requests will be processed in parallel and You have log entries mixed. With default log format there is no way to say which entry is from which process.

Since Rails 2.0 we have ActiveSupport::BufferedLogger, but it solves other problem – number of disk writes and file locks – You can set after how many entries log will be flushed to disk.

AnnotatedLogger

Here comes AnnotatedLogger for a rescue. The idea is to take each message and prefix it with PID of Rails process. As long You don’t run Rails in multithread mode, this is unique ID which will make log entry distinguishable.

class AnnotatedLogger < Logger
  
  def initialize *args
    super *args

    [:info, :debug, :warn, :error, :fatal].each {|m|
      AnnotatedLogger.class_eval %Q|
      def #{m} arg=nil, &block
        pid = "%.5d:" % $$
        if block_given?
          arg = yield
        end
        super "%s %s" % [pid, arg.gsub(/\n/,"\n%s" % pid)]
      end
      |

    }
  end
end

Now in Rails::Initializer.run do |config| section of config/environment.rb define AnnotatedLogger as default Rails logger:

 config.logger = AnnotatedLogger.new "log/#{RAILS_ENV}.log"

Of course You can add other data to log entries (timestamp?). Here is an example of log entries:

24551:Processing SearchController#processing (for [FILTERED] at 2009-09-15 15:11:24) [GET]
24551:   Session ID: df260892836fc619ec666f894e7d8e88
24551:   Parameters: {[FILTERED]}
24542:   Airport Load (0.216460)   SELECT * FROM [FILTERED]
24542: Completed in 0.24903 (4 reqs/sec) | Rendering: 0.01298 (5%) | DB: 0.22554 (90%) | 200 OK [FILTERED]
24551:   Search Columns (0.004711)   SHOW FIELDS FROM [FILTERED]
24551: Rendering template within layouts/blank
24551: Rendering search/processing

Without PIDs You would expect that Airport Load entry is part of SearchController#processing for session with ID df260892836fc619ec666f894e7d8e88. In reality this is output from processing different request.

What else?

This how I do deal with logs from Rails application. Do You have other ideas how to make logging more usable not only in development environment?

PS
I have just other idea – probably You could use BufferedLogger with disabled auto flushing and patch ActionController to flush manually all entries after request was processed – then all messages would be dumped in single block.