Configure logging

To get the best results out of request-log-analyzer, we offer some tips on how to configure logging in your Rails application. The single most important issue is making sure that every process or thread writes to its own log file, so messages do not get mixed up.

The problem of mixed log files

In its default configuration, Rails will write its log messages to a single log file: log/<environment>.log. In most production environments, multiple processes will be active to handle incoming requests. If there are more processes writing to the same log file at once, the messages can get mixed up. This is a problem when request-log-analyzer parses a log file. An example:

Processing Controller1#action1 ...
Processing Controller2#action2 ...
Completed in 100ms...
Completed in 567ms...

In this example, what action was completed in 100ms, and what action in 567 ms? We can never be sure.

Request-log-analyzer’s detection mechanism

Request-log-analyzer tries to detect this situation. If such a situation is detected, a warning will be issued to inform you about the situation. Moreover, request-log-analyzer will discard both request, as it cannot be sure what information belongs to what request. This will prevent invalid data creeping into the reports for a large part, but it will not always work. In some edge cases this detection mechanism will discard too little information, in some cases it will discard too much. In any case, it is best to fix the logging configuration to prevent this from happening.

There is a command line flag that alters the method r-l-a uses when it detects these ordering problems:

--assume-correct-order: Setting this flag will make RLA assume that any detected log order problems are caused by other causes than separate processes writing to the same log file. Set this option if you are sure you correctly setup your logging, as more request information will be retained.

As of version 1.12.1 the assume-correct-order flag has been deprecated. Now please use
$ --parse-strategy <strategy> Legal values are 'assume-correct' or 'cautious'.

Solution for Mongrel: one log file per port

Add the following code to your config/environments/production.rb file to create a separate log file for every port on which mongrel is active:

# Use a different logger for distributed setups
ObjectSpace.each_object(Mongrel::HttpServer) { |i| @port = i.port } rescue nil

# Need to be able to run this code during migrations or console
if @port and @port.to_i > 0
  config.logger = Logger.new("#{RAILS_ROOT}/log/#{RAILS_ENV}.#{@port}.log", 'monthly')
else
  puts "Port could not be introspected; we must not be running Mongrel in this instance."
end

You can simply invoke request-log-analyzer on all the files by using a wildcard:
$ request-log-analyzer --assume-correct-order log/production.*.log

As of version 1.12.1 the assume-correct-order flag has been deprecated. Now please use
$ request-log-analyzer --parse-strategy assume-correct log/production.*.log

Solution for multiple machines: Syslogger

If you are running a multiple machine stack, you could also take a look at the syslogger gem here: http://github.com/cpowell/sysloglogger or here: http://seattlerb.rubyforge.org/SyslogLogger .

SyslogLogger is a Logger replacement that logs to syslog. It is almost drop-in with a few caveats. You can add SyslogLogger to your Rails production environment to aggregate logs between multiple machines. A nice benefit of using the Syslogger is that it automatically groups each request and even adds the PID of the mongrel to the log file.

Tweaking default Rails logging

A Rails application in production will log the basic data.
RLA can work with this minimal set just fine, but if you want some more information, the best you can do is tweak Rails a little.
For example: I want to see fragment caching in production.

If you have rails frozen in vendor, you just open the following file:

vendor/rails/actionpack/lib/action_controller/caching/fragments.rb

Look for the read_fragment function and replace
self.class.benchmark "Cached fragment hit: #{key}" do

with

self.class.benchmark("Cached fragment hit: #{key}", Logger::INFO) do

to enable it during production.

If you do not have rails frozen, make a copy of the fragments.rb file and put it in your config/initializers/folder. Apply any tweaks to this mixin.

Continuous log analysis

If you want to do continuous analysis, you should take a look at http://github.com/barttenbrinke/munin-plugins-rails/ which leverages request-log-analyzer to power munin.