Rails logs are not flushed automatically (in Rake tasks)

Updated . Posted . Visible to the public.

The Rails logger will store its content in a buffer and write it into the file system every 1000 lines. This will come back to bite you when using Rails.logger.info to write log output during Rake tasks or on a production console.

You often won't notice this because for the development and test environments auto_flushing Show archive.org snapshot is set to write after each line. On production environments the Rails logger writes only every 1000 lines -- and not upon shell or script termination as you might expect -- so Rake tasks can lose up to 999 lines of log entries if they don't flush the logger themselves (which will happen).

For the "regular" workflow Rails seems to do something smart like flushing after each request but for Rake tasks you need to do such a thing yourself. You could set the auto_flushing to 1 but that would have a somewhat strong performance impact since your application would need to acquire a write lock on the file and add its line for every log entry.

Instead, patch the task method definition to have your Rails logs written to disk after a Rake task is complete (you can do this in your project.rake file):

Rake::DSL.module_eval do
  def task_with_logger_flushing(*args, &block)
    flushing_block = lambda do |*block_args|
      begin
        block.call(*block_args) if block
      ensure
        Rails.logger.flush if defined?(Rails) and Rails.logger
      end
    end
    task_without_logger_flushing(*args, &flushing_block)
  end
  alias_method :task_without_logger_flushing, :task
  alias_method :task, :task_with_logger_flushing
end

The above patch should work safely on pure Rake so you can apply it even if you have rake tasks that run without Rails.

When you work on a production Rails console, you can call Rails.logger.flush to write log output.

Arne Hartherz
Last edit
License
Source code in this card is licensed under the MIT License.
Posted by Arne Hartherz to makandra dev (2011-10-19 14:58)