Rails

The rails_semantic_logger gem replaces the default Rails logger with Semantic Logger. It also reduces Rails logging output in production to almost a single line for every Controller-Action call.

Rails Support

Installation

Add the following lines to Gemfile

gem 'awesome_print'
gem 'rails_semantic_logger'

The gem awesome_print is optional, but is recommended to get colorized output of semantic data (Hash output).

Install required gems with bundler

bundle install

This will automatically replace the standard Rails logger with Semantic Logger which will write all log data to the configured Rails log file.

Process Forking

See Process Forking if you use Unicorn or Puma.

Configuration

The configuration can be set in either config/application.rb or the environment specific file in config/environments.

Standard Rails log output for a single page request

Rails Default

Rails log output for the same single page request after adding the rails_semantic_logger gem:

Rails Single Line

Re-enable Started, Processing, and Rendered messages

config.rails_semantic_logger.started    = true
config.rails_semantic_logger.processing = true
config.rails_semantic_logger.rendered   = true

Semantic

Original Rails messages with semantic logger formatting

config.rails_semantic_logger.semantic   = false
config.rails_semantic_logger.started    = true
config.rails_semantic_logger.processing = true
config.rails_semantic_logger.rendered   = true

Semantic Disabled

Include the file name and line number in the source code where the message originated

config.semantic_logger.backtrace_level = :info

with_source

The above output shows 3 web requests where the source file name was log_subscriber.rb and line number 11.

Log Level

To change the log level:

# Set to the log level to :trace, :debug, :info, :warn, :error, or :fatal
config.log_level = :debug

Named Tags

Named tags can be added to every log message on a per web request basis, by overriding the Rails built-in config.log_tags with a hash value.

For example, add the following to application.rb, or replace the existing config.log_tags entry:

  config.log_tags = {
    request_id: :request_id,
    ip:         :remote_ip,
    user:       -> request { request.cookie_jar['login'] }
  }

Note:

To turn off named tags in development, add the following to config/environments/development.rb

config.log_tags        = nil

Quiet asset logging

Rails logs asset retrievals at the debug level. These log entries can quickly clutter the log output:

Rack -- Started -- {:ip => "127.0.0.1", :method => "GET", :path => "/assets/rocket_job_mission_control/rocket-icon-64x64.png"}

To turn off the asset logging:

config.rails_semantic_logger.quiet_assets = true

Colorize Logging

If the Rails colorized logging is enabled, then the colorized formatter will be used by default. To disable colorized logging in both Rails and Semantic Logger:

config.colorize_logging = false

Semantic log output

By default Action Controller and Active Record text messages are converted to semantic data (Hash):

Rack -- Started -- { :ip => "127.0.0.1", :method => "GET", :path => "/users" }
UserController -- Completed #index -- { :action => "index", :db_runtime => 54.64, :format => "HTML", :method => "GET", :mongo_runtime => 0.0, :path => "/users", :status => 200, :status_message => "OK", :view_runtime => 709.88 }

To disable semantic message conversion:

config.rails_semantic_logger.semantic = false

Started message

By default the Started message is logged at the debug level so that it does not appear in production.

Rack -- Started -- { :ip => "127.0.0.1", :method => "GET", :path => "/users" }

To show Rack started messages in production:

config.rails_semantic_logger.started = true

Processing message

By default the Controller Processing message is logged at the debug level so that it does not appear in production.

UserController -- Processing #index

To show the Controller Processing message in production:

config.rails_semantic_logger.processing = true

View Rendering messages

By default the Action View rendering messages are logged at the debug level so that they do not appear in production.

ActionView::Base --   Rendered data/search/_user.html.haml (46.7ms)

To show the Action View rendering messages in production:

config.rails_semantic_logger.rendered = true

Awesome Print Options

The default Awesome Print options can be changed by supplying any valid Awesome Print options:

config.rails_semantic_logger.ap_options = {multiline: false}

The defaults can also changed be creating a ~/.aprc file. See the Awesome Print Options Documentation

Notes:

Additional appenders

Example, also log to a JSON log file, for consumption by ELK, Splunk, etc.:

config.semantic_logger.add_appender(file_name: "log/#{Rails.env}.json", formatter: :json)

Example, also log to a local Syslog:

config.semantic_logger.add_appender(appender: syslog)

Example, also log to a local Syslog such as syslog-ng over TCP:

config.semantic_logger.add_appender(appender: syslog, url: 'tcp://myloghost:514')

Example, also log to elasticsearch:

config.semantic_logger.add_appender(appender: :elasticsearch, url: 'http://localhost:9200')

Example, also log to BugSnag:

config.semantic_logger.add_appender(appender: :bugsnag)

See Appenders for the complete list of available appenders.

Output Format

The Rails log file and Rails Server standard out logging can be modified directly with the format config option.

  config.rails_semantic_logger.format = :default

Valid options:

Note:

JSON Example, in application.rb:

  config.rails_semantic_logger.format = :json

Custom Example, create app/lib/my_formatter.rb:

  # My Custom colorized formatter
  class MyFormatter < SemanticLogger::Formatters::Color
    # Return the complete log level name in uppercase
    def level
      "#{color}log.level.upcase#{color_map.clear}"
    end
  end

In application.rb:

  config.rails_semantic_logger.format = MyFormatter.new

See SemanticLogger::Formatters::Color for the other methods that can be overridden.

To modify and use a different base formatter choose from the complete list of formatters.

Disable default Rails file logging

When running in an environment where local file logging is not available, or to completely replace the file logger, disable the default rails file logging by setting:

config.rails_semantic_logger.add_file_appender = false

After disabling the default file logging another appender needs to be added before any logging will be sent anywhere. For example to create a JSON only log file:

config.semantic_logger.add_appender(file_name: 'log/json.log', formatter: :json)

Notes:

Adding custom data to the Rails Completed log message

During Controller-action processing custom data can be added to the Rails Completed message.

Add a method called append_info_to_payload to the controller to modify the payload that is logged:

class ThingController
  private

  def append_info_to_payload(payload)
    super
    payload[:user_id] = 42
  end
end

Log file name and line number

In development to log the file and line number from which every log message originated:

# Log file name and line number for log messages at this level and above
config.semantic_logger.backtrace_level = :debug

By default backtraces are only captured for :error and :fatal levels since capturing a backtrace for every log message is expensive.

This feature can be used in production, but use care since setting the level too low will slow down the application.

Log Rotation

Since the log file is not re-opened with every call, when the log file needs to be rotated, use a copy-truncate operation over deleting the file.

Sample Log rotation file for Linux:

/var/www/rails/my_rails_app/shared/log/*.log {
        daily
        missingok
        copytruncate
        rotate 14
        compress
        delaycompress
        notifempty
}

Replacing Existing loggers

Rails Semantic Logger automatically replaces the default loggers for the following gems after they have been initialized:

Next: Centralized Logging ==>