Forum: Ruby on Rails [ANN] Rails plugin to improve log format

Announcement (2017-05-07): www.ruby-forum.com is now read-only since I unfortunately do not have the time to support and maintain the forum any more. Please see rubyonrails.org/community and ruby-lang.org/en/community for other Rails- und Ruby-related community platforms.
95d0a2aeedab6a6d90b147613224b90f?d=identicon&s=25 Paul Dowman (pdowman)
on 2009-04-15 17:22
(Received via mailing list)
I have created a Rails plugin to improve the log file format. (It also
adds an optional “Exception” parameter to the warn() and error()
methods to print a stack trace automatically.)

It's available here:
http://github.com/pauldowman/better_logging


___Improved log format___

It adds severity level (with colour, if
ActiveRecord::Base.colorize_logging == true), hostname and process ID
to each log line, and it and adds warn() and exception() methods that
take an exception as an argument and print the stack trace.

For example, here’s how the default format looks:

Session ID: 7eeb00aa62b395698a28bf033e56b7c5
Parameters: {"action"=>"show", "id"=>"1", "controller"=>"people"}
User Load (0.4ms)   SELECT * FROM `users` WHERE (id = '1') LIMIT 1
User Columns (2.1ms)   SHOW FIELDS FROM `users`
Rendering template within layouts/application
Rendering people/show
Rendered layouts/_head (3.1ms)
Rendered layouts/_navigation (2.2ms)
Adding Cache-Control header
Completed in 164ms (View: 116, DB: 21) | 200 OK [http://localhost/
people/1]

Here’s how the same thing would look with the better_logging plugin
installed in development mode (it looks best with a proportional
font). Note that the severity (INFO, WARN, ERROR, etc), is printed in
colour (if colour is enabled for the log, which it is by default in
development mode).

INFO   Session ID: 7eeb00aa62b395698a28bf033e56b7c5
INFO   Parameters: {"action"=>"show", "id"=>"1",
"controller"=>"people"}
DEBUG  User Load (0.4ms)   SELECT * FROM `users` WHERE (id = '1')
LIMIT 1
DEBUG  User Columns (2.1ms)   SHOW FIELDS FROM `users`
INFO   Rendering template within layouts/application
INFO   Rendering people/show
DEBUG  Rendered layouts/_head (3.1ms)
DEBUG  Rendered layouts/_navigation (2.2ms)
INFO   Adding Cache-Control header
INFO   Completed in 164ms (View: 116, DB: 21) | 200 OK [http://
localhost/people/1]

And here’s how it would look with the better_logging plugin installed
in production mode, on a host named “akash”, with process id 27471:

akash.27471   13:27:04  INFO   Session ID:
7eeb00aa62b395698a28bf033e56b7c5
akash.27471   13:27:04  INFO   Parameters: {"action"=>"show",
"id"=>"1", "controller"=>"people"}
akash.27471   13:27:04  INFO   Rendering template within layouts/
application
akash.27471   13:27:04  INFO   Rendering people/show
akash.27471   13:27:04  INFO   Adding Cache-Control header
akash.27471   13:27:04  INFO   Completed in 164ms (View: 116, DB: 21)
| 200 OK [http://localhost/people/1]

And here’s how it would look in production mode on a host with a long
name. This host name is “myreallybigserver-7.mydomain.com”.

igserver-7.27471   13:27:04  INFO   Session ID:
7eeb00aa62b395698a28bf033e56b7c5
igserver-7.27471   13:27:04  INFO   Parameters: {"action"=>"show",
"id"=>"1", "controller"=>"people"}
igserver-7.27471   13:27:04  INFO   Rendering template within layouts/
application
igserver-7.27471   13:27:04  INFO   Rendering people/show
igserver-7.27471   13:27:04  INFO   Adding Cache-Control header
igserver-7.27471   13:27:04  INFO   Completed in 164ms (View: 116, DB:
21) | 200 OK [http://localhost/people/1]

Note that the hostname & process ID is added to the beginning of each
line of a multi-line log statement. So even if you call logger.error()
with a string that has newlines in it, the host & process ID will be
added to each line, not only the first.

This is so that you can filter your log with a regular expression
like /^igserver-7\.27471/ and not miss lines.
Improved warn() and error() methods

The warn() and error() methods now allow an Exception object to be
given as an optional second parameter. If the exception is given, then
the stack trace will be automatically logged.

For example:

  begin
    # do something that raises an exception
  rescue Exception => e
    log.error "Oops", e
  end

The above code will log “Oops”, and then log the stack trace.


___Why?___

Adding severity:
All lines printed to the log have a “severity” level, this can be
“DEBUG”, “WARN”, “ERROR”, etc. Normally this isn’t included in the log
output, so it’s impossible to search a log file for warnings or
errors, or filter based on severity, and it’s just a useful thing to
see.
Adding hostname and process ID

Normally, when not in development mode, a Rails app consists of more
than one Rails process responding to requests at the same time. Those
processes may be printing lines to the log at the same time, and it’s
hard to know which process printed a certain line.

Also, it’s common to have multiple servers working in parallel, and a
user’s session might involve requests to multiple servers. If the log
files are combined it’s useful to know which process on which server
printed a given line.

This makes it possible to filter a Rails log to show output from one
process only, and to combine the log files from multiple servers.

The hostname is truncated (by default to 10 characters but this is
configurable). The end of the hostname is printed, rather than the
beginning, because often the end of the hostname is more unique.

Adding a timestamp:
This should be pretty obvious, but the log file isn’t too useful for
debugging errors if you don’t know what time anything happened. The
first line printed by each Rails action does include a timestamp, but
it’s common to have other processes that aren’t responding to web
requests, and these are likely printing to your Rails log also (e.g. a
background queue, etc).


___Why not log to syslog?___

It’s a single point of failure, and it will become a scalability
bottleneck. There are good arguments for using a common syslog server,
but I prefer to just log locally on each server and combine them via
post-processing.


___Installation___

./script/plugin install git://github.com/pauldowman/better_logging.git


___Configuration___

By default it behaves differently in development mode, it doesn’t log
the time, process ID or hostname. If RAILS_ENV is not “development”
those will be logged.

There are two options that can be set, add these lines to an
initializer:
PaulDowman::RailsPlugins::BetterLogging.verbose = false

    * This suppresses printing of the hostname, process ID and
timestamp. This defaults to false in development mode, true otherwise.

PaulDowman::RailsPlugins::BetterLogging.hostname_maxlen = 15

    * This sets the maximum number of characters of the hostname that
will be printed. The beginning of the hostname is truncated, rather
than the end, because often the end of the hostname is more unique
than the beginning. The default is 10.

For more info see:
http://github.com/pauldowman/better_logging
This topic is locked and can not be replied to.