Ruby on Rails | Screencasts | Download | Documentation | Weblog | Community | Source

Ruby on Rails
HowtoConfigureLogging (Version #69)

Home Page | All Pages | Recently Revised | Feed

This howto shows how to modify some of the defaults in rails’ logging configuration. For background about what the logger is and how to use it, see logger.

Basics

You can control some aspects of the logger through the config object in config/environment.rb for a change in all environments

Log Level

The available log levels are: :debug, :info, :warn, :error, :fatal. The ruby Logger class normally also accepts :any, but that doesn’t seem to work with rails.

config.log_level = :debug

Log Path

The log file path is relative to the RAILS_ROOT directory. Make sure that the file exists and has permissions that allow writing for the user that rails will run under.

config.log_path = 'log/debug.log'

Per-environment logging configs

Setting config.log_level in a per environment file (such a development.rb) appears to no longer work. the solution appears to be:

RAILS_DEFAULT_LOGGER.level = Logger::INFO if defined? RAILS_DEFAULT_LOGGER

The rest of this document is if you want more fine-level control over the logger or want to use something other than the default Logger object.

Using different loggers for different parts of rails

This does not seem to happen in environment.rb as stated.
environment.rb defines the loggers used by the components of rails. First it defines the default logger for the application :

begin
  RAILS_DEFAULT_LOGGER = Logger.new("#{RAILS_ROOT}/log/#{RAILS_ENV}.log")
rescue StandardError
  RAILS_DEFAULT_LOGGER = Logger.new(STDERR)
  RAILS_DEFAULT_LOGGER.level = Logger::WARN
  RAILS_DEFAULT_LOGGER.warn(
    "Rails Error: Unable to access log file. Please ensure that log/#{RAILS_ENV}.log exists and is chmod 0666. " +
    "The log level has been raised to WARN and the output directed to STDERR until the problem is fixed." 
  )
end

Then it assigns this logger to its friends :

[ActiveRecord, ActionController, ActionMailer].each { |mod| mod::Base.logger ||= RAILS_DEFAULT_LOGGER }

Say you want Active record to log in database.log instead of the default #{RAILS_ENV}.log file. You can add the following to the end of your #{RAILS_ROOT}/config/#{RAILS_ENV}.rb file (for example to developement.rb):

ActiveRecord::Base.logger = Logger.new("#{RAILS_ROOT}/log/#{RAILS_ENV}_database.log")

Setting a different log severity for different environments

Say you want Active record to only log warnings when your application is running in production mode. You can add the following to the end of your #{RAILS_ROOT}/config/production.rb file:

config.log_level = :warn

The above method is for

Getting monochrome log messages

Removing the colour escape sequences that are used by default is quite simple. Simply set colorize_logging to false:

ActiveRecord::Base.colorize_logging = false

Note that the colorize_logging method doesn’t appear in ActionController (why?[because the only module in rails that adds color to the logs is ActiveRecord -jean]).

Changing the log format

As said in the logger.rb source file:
> There is currently no supported way to change the overall format, but you may
> have some luck hacking the Format constant.

This, when added to the end of environment.rb, puts the timestamp and PID in the log.

class Logger
  def format_message(severity, timestamp, progname, msg)
    "#{timestamp} (#{$$}) #{msg}\n" 
  end
end

Why doesn’t Logger behave the way the Ruby library docs say it should under rails?

(Note that the Rails 2.0 default logger has been changed from Ruby’s own logger with the clean_logger extensions described below to ActiveSupport::BufferedLogger. From the CHANGELOG: “You can change it back with config.logger = Logger.new(”/path/to/log”, level)”. Rails::Initializer.initialize_logger() documentation also indicates you can set RAILS_DEFAULT_LOGGER.)

Look at the source to what Rails 1.2 does to mung the standard Logger object to do what it wants. Can you see anything wrong with this picture? If Rails wants a Logger object that behaves this way, it should subclass Logger, or inject its own Logger::Formatter into the picture rather than this mess.

What this accomplishes is utterly evil. If you’re adding things to a rails app that expect Logger to behave as documented, you’ll configure your logging date formats all day long and never have any impact. Worse, the code is flagged :nodoc:, so after screwing around with expected behavior, we’re left with no indication as to why a Logger instance created from the Rails console will behave different than a Logger created from IRB.

Mixins are a great feature of Ruby, but a mixin that irrevocably alters a core library class just to avoid the minor pain of creating a proper subclass where it it obviously necessary is just plain wrong, no matter how $!#^$% pragmatic you’re claiming to be.

This code added to environment.rb will restore the default logger behavior under 1.8.4, Rails 1.2:

class Logger
  def format_message(severity, timestamp, progname, msg)
    if <a href="mailto:!@formatter.nil">!@formatter.nil</a>? 
      @formatter.call(severity, timestamp, progname, msg)
    else
      @default_formatter.call(severity, timestamp, progname, msg)
    end
  end
end

class RailsFormatter < Logger::Formatter
  def call(severity, timestamp, progname, msg)
    "#{msg}\n" 
  end
end

RAILS_DEFAULT_LOGGER.formatter = RailsFormatter.new

Need Advanced Logging?

If you need something similar to log4j , then you should take a look at the log4r project It allows more advanced logging than the standard logger.

However, log4r doesn’t work with the current version of Rails because of incompatibilities between the benchmarking module and log4r. See ticket 3512 for more information.

As of 2/20/07, log4r has been idle for several years. It looks like no-one has been able to contact the original developer for some time, and a replacement project, http://logging.rubyforge.org has been created that solves the above mentioned problem.

Logging Permission Errors

I ran into problems with logging on Apache 2 with Fcgi resulting in a “could not access {RAILS_ENV}/log/development.log” message in the Apache Error log and suggesting I made sure the log file existed and was chmodded 0666. Changine permissions on the files had no effect but setting a 777 permission on the /log directory fixed it.

Question:

Thank you for these useful informations. However I’d like to know if it’s possible to display the logs in the console rather than using the ”debug.log” file .

Answer #1:
You can tail the log in the console. For example:
cd /railsapp/log
tail -f development.log

Adding Color to your own logs

The ActiveRecord #format_log_entry method looks like this:

        def format_log_entry(message, dump = nil)
          if ActiveRecord::Base.colorize_logging
            if @@row_even
              @@row_even = false
              message_color, dump_color = "4;36;1", "0;1" 
            else
              @@row_even = true
              message_color, dump_color = "4;35;1", "0" 
            end

            log_entry = "  \e[#{message_color}m#{message}\e[0m   " 
            log_entry << "\e[#{dump_color}m%#{String === dump ? 's' : 'p'}\e[0m" % dump if dump
            log_entry
          else
            "%s  %s" % [message, dump]
          end
        end

it’s actually found in active_record/connection_adapters/abstract_adapter.rb


Question: I am running Rails 1.2.3 with Mongrel and Ruby 1.8.6 on Windows. No matter what I set the value of log_level in environment.rb or environments/development.rb, my logfile always contains the same output. How do I begin to track down why its doing so?


Answer: config.log_level = :info will not work if you are setting config.logger. In that case, you will want to set config.logger.log_level = (Logger::INFO or whatever). I have also seen cases where ./script/server will setup one logger and RAILS_DEFAULT_LOGGER will not get reset. You can assert this by keeping a global reference to the logger you setup in environment.rb, and later on doing a `throw “Lame” unless $my_logger == RAILS_DEFAULT_LOGGER`

Pretty logs for rails 1.2.x and 2.0
I use for creating pretty logggs on rails
next patches

config/environment.rb

  require 'logger_core_ext'

file app/lib/logger_core_ext.rb

class Logger
  # Used for rails 1.2.x
  alias format_message old_format_message
  class Formatter
    def call(severity, time, progname, msg)
      "[%s|#%5d|%s] %s: %s\n" % [severity[0..3], $$, time.to_s(:db), progname, msg2str(msg)]
    end
  end
end

module ActiveSupport
  # Used for rails 2.0
  class BufferedLogger
    module Severity
      def level_to_s(level)
        case level
        when 0
          'DEBUG'
        when 1
          'INFO'
        when 2
          'WARN'
        when 3  
          'ERROR'
        when 4
          'FATAL'
        when 5 
          'UNKNOWN'
        end
      end
    end

    def add(severity, message = nil, progname = nil, &block)
      return if @level > severity
     # message = (message || (block && block.call) || progname).to_s
     message = (message || (block && block.call) || progname).to_s
      # If a newline is necessary then create a new message ending with a newline.
      # Ensures that the original message is not mutated.
      message = "#{message}\n" unless message[-1] == ?\n
      message = "[%s|#%5d|%s] %s: %s" % [level_to_s(severity)[0..3], $$, Time.now.to_s(:db), progname, message]
      @buffer << message
      auto_flush
      message
    end
  end
end

source posr for rails loggining patch

This howto shows how to modify some of the defaults in rails’ logging configuration. For background about what the logger is and how to use it, see logger.

Basics

You can control some aspects of the logger through the config object in config/environment.rb for a change in all environments

Log Level

The available log levels are: :debug, :info, :warn, :error, :fatal. The ruby Logger class normally also accepts :any, but that doesn’t seem to work with rails.

config.log_level = :debug

Log Path

The log file path is relative to the RAILS_ROOT directory. Make sure that the file exists and has permissions that allow writing for the user that rails will run under.

config.log_path = 'log/debug.log'

Per-environment logging configs

Setting config.log_level in a per environment file (such a development.rb) appears to no longer work. the solution appears to be:

RAILS_DEFAULT_LOGGER.level = Logger::INFO if defined? RAILS_DEFAULT_LOGGER

The rest of this document is if you want more fine-level control over the logger or want to use something other than the default Logger object.

Using different loggers for different parts of rails

This does not seem to happen in environment.rb as stated.
environment.rb defines the loggers used by the components of rails. First it defines the default logger for the application :

begin
  RAILS_DEFAULT_LOGGER = Logger.new("#{RAILS_ROOT}/log/#{RAILS_ENV}.log")
rescue StandardError
  RAILS_DEFAULT_LOGGER = Logger.new(STDERR)
  RAILS_DEFAULT_LOGGER.level = Logger::WARN
  RAILS_DEFAULT_LOGGER.warn(
    "Rails Error: Unable to access log file. Please ensure that log/#{RAILS_ENV}.log exists and is chmod 0666. " +
    "The log level has been raised to WARN and the output directed to STDERR until the problem is fixed." 
  )
end

Then it assigns this logger to its friends :

[ActiveRecord, ActionController, ActionMailer].each { |mod| mod::Base.logger ||= RAILS_DEFAULT_LOGGER }

Say you want Active record to log in database.log instead of the default #{RAILS_ENV}.log file. You can add the following to the end of your #{RAILS_ROOT}/config/#{RAILS_ENV}.rb file (for example to developement.rb):

ActiveRecord::Base.logger = Logger.new("#{RAILS_ROOT}/log/#{RAILS_ENV}_database.log")

Setting a different log severity for different environments

Say you want Active record to only log warnings when your application is running in production mode. You can add the following to the end of your #{RAILS_ROOT}/config/production.rb file:

config.log_level = :warn

The above method is for

Getting monochrome log messages

Removing the colour escape sequences that are used by default is quite simple. Simply set colorize_logging to false:

ActiveRecord::Base.colorize_logging = false

Note that the colorize_logging method doesn’t appear in ActionController (why?[because the only module in rails that adds color to the logs is ActiveRecord -jean]).

Changing the log format

As said in the logger.rb source file:
> There is currently no supported way to change the overall format, but you may
> have some luck hacking the Format constant.

This, when added to the end of environment.rb, puts the timestamp and PID in the log.

class Logger
  def format_message(severity, timestamp, progname, msg)
    "#{timestamp} (#{$$}) #{msg}\n" 
  end
end

Why doesn’t Logger behave the way the Ruby library docs say it should under rails?

(Note that the Rails 2.0 default logger has been changed from Ruby’s own logger with the clean_logger extensions described below to ActiveSupport::BufferedLogger. From the CHANGELOG: “You can change it back with config.logger = Logger.new(”/path/to/log”, level)”. Rails::Initializer.initialize_logger() documentation also indicates you can set RAILS_DEFAULT_LOGGER.)

Look at the source to what Rails 1.2 does to mung the standard Logger object to do what it wants. Can you see anything wrong with this picture? If Rails wants a Logger object that behaves this way, it should subclass Logger, or inject its own Logger::Formatter into the picture rather than this mess.

What this accomplishes is utterly evil. If you’re adding things to a rails app that expect Logger to behave as documented, you’ll configure your logging date formats all day long and never have any impact. Worse, the code is flagged :nodoc:, so after screwing around with expected behavior, we’re left with no indication as to why a Logger instance created from the Rails console will behave different than a Logger created from IRB.

Mixins are a great feature of Ruby, but a mixin that irrevocably alters a core library class just to avoid the minor pain of creating a proper subclass where it it obviously necessary is just plain wrong, no matter how $!#^$% pragmatic you’re claiming to be.

This code added to environment.rb will restore the default logger behavior under 1.8.4, Rails 1.2:

class Logger
  def format_message(severity, timestamp, progname, msg)
    if <a href="mailto:!@formatter.nil">!@formatter.nil</a>? 
      @formatter.call(severity, timestamp, progname, msg)
    else
      @default_formatter.call(severity, timestamp, progname, msg)
    end
  end
end

class RailsFormatter < Logger::Formatter
  def call(severity, timestamp, progname, msg)
    "#{msg}\n" 
  end
end

RAILS_DEFAULT_LOGGER.formatter = RailsFormatter.new

Need Advanced Logging?

If you need something similar to log4j , then you should take a look at the log4r project It allows more advanced logging than the standard logger.

However, log4r doesn’t work with the current version of Rails because of incompatibilities between the benchmarking module and log4r. See ticket 3512 for more information.

As of 2/20/07, log4r has been idle for several years. It looks like no-one has been able to contact the original developer for some time, and a replacement project, http://logging.rubyforge.org has been created that solves the above mentioned problem.

Logging Permission Errors

I ran into problems with logging on Apache 2 with Fcgi resulting in a “could not access {RAILS_ENV}/log/development.log” message in the Apache Error log and suggesting I made sure the log file existed and was chmodded 0666. Changine permissions on the files had no effect but setting a 777 permission on the /log directory fixed it.

Question:

Thank you for these useful informations. However I’d like to know if it’s possible to display the logs in the console rather than using the ”debug.log” file .

Answer #1:
You can tail the log in the console. For example:
cd /railsapp/log
tail -f development.log

Adding Color to your own logs

The ActiveRecord #format_log_entry method looks like this:

        def format_log_entry(message, dump = nil)
          if ActiveRecord::Base.colorize_logging
            if @@row_even
              @@row_even = false
              message_color, dump_color = "4;36;1", "0;1" 
            else
              @@row_even = true
              message_color, dump_color = "4;35;1", "0" 
            end

            log_entry = "  \e[#{message_color}m#{message}\e[0m   " 
            log_entry << "\e[#{dump_color}m%#{String === dump ? 's' : 'p'}\e[0m" % dump if dump
            log_entry
          else
            "%s  %s" % [message, dump]
          end
        end

it’s actually found in active_record/connection_adapters/abstract_adapter.rb


Question: I am running Rails 1.2.3 with Mongrel and Ruby 1.8.6 on Windows. No matter what I set the value of log_level in environment.rb or environments/development.rb, my logfile always contains the same output. How do I begin to track down why its doing so?


Answer: config.log_level = :info will not work if you are setting config.logger. In that case, you will want to set config.logger.log_level = (Logger::INFO or whatever). I have also seen cases where ./script/server will setup one logger and RAILS_DEFAULT_LOGGER will not get reset. You can assert this by keeping a global reference to the logger you setup in environment.rb, and later on doing a `throw “Lame” unless $my_logger == RAILS_DEFAULT_LOGGER`

Pretty logs for rails 1.2.x and 2.0
I use for creating pretty logggs on rails
next patches

config/environment.rb

  require 'logger_core_ext'

file app/lib/logger_core_ext.rb

class Logger
  # Used for rails 1.2.x
  alias format_message old_format_message
  class Formatter
    def call(severity, time, progname, msg)
      "[%s|#%5d|%s] %s: %s\n" % [severity[0..3], $$, time.to_s(:db), progname, msg2str(msg)]
    end
  end
end

module ActiveSupport
  # Used for rails 2.0
  class BufferedLogger
    module Severity
      def level_to_s(level)
        case level
        when 0
          'DEBUG'
        when 1
          'INFO'
        when 2
          'WARN'
        when 3  
          'ERROR'
        when 4
          'FATAL'
        when 5 
          'UNKNOWN'
        end
      end
    end

    def add(severity, message = nil, progname = nil, &block)
      return if @level > severity
     # message = (message || (block && block.call) || progname).to_s
     message = (message || (block && block.call) || progname).to_s
      # If a newline is necessary then create a new message ending with a newline.
      # Ensures that the original message is not mutated.
      message = "#{message}\n" unless message[-1] == ?\n
      message = "[%s|#%5d|%s] %s: %s" % [level_to_s(severity)[0..3], $$, Time.now.to_s(:db), progname, message]
      @buffer << message
      auto_flush
      message
    end
  end
end

source posr for rails loggining patch

i2 on Rails