Rails 3 logs with severity and PIDs

better_logger.rb

# You must require this file in application.rb, above the Application
# definition, for this to work. For example:
#
#   # Syslog-like Rails logs
#   if Rails.env.production?
#     require File.expand_path('../../lib/better_logger', __FILE__)
#   end
#
#   module MyApp
#     class Application < Rails::Application

require 'active_support/buffered_logger'

class BetterLogger < ActiveSupport::BufferedLogger

  SEVERITIES = Severity.constants.sort_by{|c| Severity.const_get(c) }

  def add(severity, message = nil, progname = nil, &block)
    return if @level > severity
    message = (message || (block && block.call) || progname).to_s
    # Prepend pid and severity to the written message
    log = "[%s] %-5.5s %s" % [$$, SEVERITIES[severity], message.gsub(/^\n+/, '')]
    # If a newline is necessary then create a new message ending with a newline.
    log << "\n" unless log[-1] == ?\n
    buffer << log
    auto_flush
    message
  end

  class Railtie < ::Rails::Railtie
    # overwrite Rails' initializer to set up our own instead
    initializer :initialize_logger do |app|
      Rails.logger = begin
        logger = BetterLogger.new(app.config.paths.log.to_a.first)
        level_name = app.config.log_level.to_s.upcase
        logger.level = ActiveSupport::BufferedLogger.const_get(level_name)
        logger.auto_flushing = false if Rails.env.production?
        logger
      end
      ActiveSupport::Dependencies.logger = Rails.logger

      # cache has no callback of its own, but is set before this callback
      ActiveSupport.on_load(:before_initialize) do
        Rails.cache.logger = Rails.logger
      end
      ActiveSupport.on_load(:active_record) do
        ActiveRecord::Base.logger = Rails.logger
      end
      ActiveSupport.on_load(:action_controller) do
        ActionController::Base.logger = Rails.logger
      end
      ActiveSupport.on_load(:action_mailer) do
        ActionMailer::Base.logger = Rails.logger
      end
    end

  end

end

Why do you need the Railtie when you can just set config.logger in either application.rb or the different envs?

I tried that first, but it didn't seem to work for all the other loggers in the Railtie. Maybe I was doing it wrong?

Well, I doubt the great Arko is doing something wrong, but sounds like you might want to patch Rails ;)

winning

Hi Andre,

I've used the PidLogger, but I ran into a problem with the log_level.

"Rails.logger = PidLogger.new(Rails.application.config.paths.log.first)" doesn't copy the current config.log_level setting.

"Rails.logger = PidLogger.new(Rails.application.config.paths.log.first, Rails.logger.level)" should do the trick

Cheers,

Ben

Good catch, thanks!

Benoist's fork correctly outputs empty lines.

That's deliberate on my part. Rails sometimes sends things to the logger that start with newlines, and it creates weird-looking logs.

I find it unreadable when you skip empty lines. That makes it very hard to see where a new request begins. Instead of scanning for an empty line I have to scan for the line containing the request URI.

Well when you've got a lot of traffic running in debug or info mode, the logs aren't readable anyway, with or without newlines. But in case of debug mode in development when you've got separate requests in your log, it's really hard to read without the new lines...

Ahh, that makes sense. I've updated to include a newline before the PID if the logged message starts with a newline. :)

Couldnt you eliminate a bunch of the code by just overriding the add() method in an initializer?

Something like:

class Railtie < ::Rails::Railtie
    initializer "swap in PidLogger" do
      module ActiveSupport
         class BufferedLogger
            def add(severity, message = nil, progname = nil, &block)
               return if @level > severity
               message = (message || (block && block.call) || progname).to_s
               # Insert a newline before the log line if there was one in the first place.
               log = (message[0] == ?\n) ? "\n" : ""
               # Prepend pid and severity to the written message
               log << "[#{$$}] #{SEVERITIES[severity]} #{message.gsub(/^\n+/, '')}"
               # If a newline is necessary then end with a newline.
               log << "\n" unless log[-1] == ?\n
               buffer << log
              auto_flush
              log
            end
        end
    end
 end

Probably, but I wasn't comfortable monkeypatching BufferedLogger.

Hi man,

I forked your code, but instead of recreating everything that is done in the method and the initializer I just extend the actual logger object.
Pretty neat solution.