6.6. Logging
Both this and the previous chapter mentioned that you could see the executed queries, errors, and other details about the requests in a log file. Depending on the environment you are in, Rails will log a certain amount of information in logdevelopment.log, log est.log, or logproduction.log. The log folder will also contain a server.log file for the Web server (for example, Mongrel).
When you look at the development.log file after having visited the front page of the blog, you see an entry similar to the following:
Processing ArticlesController#index (for 127.0.0.1 at 2009-01-28 11:28:11) [GET] [4;36;1mArticle Load (0.0ms)[0m [0;1mSELECT * FROM "articles" WHERE (published = 't' AND published_at <= '2009-01-28 16:28:11') ORDER BY published_at DESC LIMIT 1 OFFSET 0[0m
[4;35;1mSQL (0.0ms)[0m [0mSELECT count(*) AS count_all FROM "articles" WHERE
(published = 't' AND published_at <= '2009-01-28 16:28:11') [0m
Rendering template within layouts/articles
Rendering articles/index
[4;36;1mSQL (0.0ms)[0m [0;1mSELECT count(*) AS count_all FROM "comments" WHERE
("comments".article_id = 2) [0m
Rendered articles/_article (10.0ms)
Completed in 29ms (View: 18, DB: 0) | 200 OK [http://localhost/]This tells you a whole lot of information: the type of request received, the IP it came from and the timestamp, which controller and action executed your request, the rendered templates, and the queries that were executed behind the scenes. It also tells you the time that it took to execute each of these, and how much time was spent processing the view, versus database access. For example, in the preceding output, the request took 0.029 seconds with no significant time spent querying the database. Finally, you have the HTTP response code and the URL that were sent back to the client.
Analyzing the log files can be an extremely useful way to perform preliminary troubleshooting, spot performance problems, and identify unexpected behavior.
Developers operating on non-Microsoft operating systems often use the following command to display the last lines of their current development log: tail -f log/development.log. On Windows simply use the output of ruby script/server or a POSIX emulation layer like Cygwin.
As the logs grow, there are times when you might want to clear all of your .log files in log. Rather than doing this manually, you can use a provided Rake task:
rake log:clear
6.6.1. Using Logger
Though Rails logs a good deal of information for you (particularly when in development and test mode), it is incredibly beneficial to be able to log your own messages.
Rails 2.x takes advantage of the ActiveSupport::BufferedLogger class to log messages and it provides you with the identifier logger, which references the Rails logger instance. In contexts where this is not defined, you can directly reference RAILS_DEFAULT_LOGGER, which is a constant that's globally available.
To verify all this, try running the following session:
C:projectslog> ruby script/console
Loading development environment (Rails 2.2.2)
>> logger
NameError: undefined local variable or method 'logger' for #<Object:0x27bf9ec>
from (irb):1
>> Rails.logger
=> #<ActiveSupport::BufferedLogger:0x51dade4 @no_block=false, @level=0, @log=#<F
ile:C:/projects/blog/log/development.log>, @auto_flushing=1, @buffer=[]>
>> RAILS_DEFAULT_LOGGER
=> #<ActiveSupport::BufferedLogger:0x51dade4 @no_block=false, @level=0, @log=#<F
ile:C:/projects/blog/log/development.log>, @auto_flushing=1, @buffer=[]>6.6.1.1. Levels of Severity
logger exposes several methods that are used to indicate the level of severity of the information being logged. Ordered by severity, these methods/levels are debug, info, warn, error, and fatal.
Whether you execute logger.debug "a custom message!" or logger.warn "a custom message!" in your code, the same message gets stored in the log file. Why do you need five methods then?
The existence of these methods representing various levels of severity is justified by the fact that each environment in Rails will only log messages that have been passed to methods above a certain threshold. This threshold for development and testing is debug, which means that any logging messages will be added to the log. In production mode, only info or more severe methods are logged (that is, warn, error, and fatal). This is how, for example, Rails manages to log all the SQL queries when in development and test mode, but not when in production. This occurs because those SQL queries that you saw before are logged using the debug method.
To see the log in production mode, run the following preliminary steps:
rake db:migrate RAILS_ENV=production ruby script/server -e production
Once the Web server is running, load the front page of the blog. Within the production log, you should obtain something along the lines of:
Processing ArticlesController#index (for 127.0.0.1 at 2009-01-28 12:05:40) [GET] Rendering template within layouts/articles Rendering articles/index Completed in 6ms (View: 2, DB: 1) | 200 OK [http://localhost/]
Only messages logged with info (or above) are shown, so there are no SQL queries in there.
When you log your own messages, try to stick to this rule of thumb:
Use debug when the information you want to log is there purely to provide aid in case of troubleshooting at a later stage
info when the behavior is expected and the information captured is important enough to be published in the production log
warn when you'd like to keep track of any unexpected behavior that doesn't break your application, but that still needs to be addressed
error when in the presence of an actual error that breaks a part of the application, but doesn't warrant taking the server offline
fatal for those occasions when the error is something so serious that the application needs to be manually restarted (and of course, the idea is to fix the cause of the problem as well)
6.6.1.2. Reducing the Production Log
Writing many messages in production can impact the server performance (I/O is expensive). With this in mind, some people like to increase the level that's required before anything is logged in their production log file. To do this you can add the following line to your configenvironmentsproduction.rb:
config.log_level = :warn
In this way, any warning, error, or fatal message is still logged, but simple information isn't. This means that when you go to apply this change and visit the front page again, no entries will be added to the logproduction.log, unless an error/warning occurred.
Similarly, you can define a different file for the log messages that are to be saved, by adding config.log_path = 'log/my_log.log'.
Keep in mind that this can be viewed as a case of premature optimization and it is not recommended that you do it right away. Having knowledge and insight of what your server does is usually much more valuable than trying to squeeze performances from the get-go. Should the need arise though, you know how to do it.
You could also modify the way the controller logs errors for common exceptions that do not warrant any changes to the code, by monkey patching the log_error method. When the issue at hand is the sheer size of the log rather than the row performance impact, setting up log rotation with one of the many tools available for most operating systems can be a good idea.
6.6.2. Redirecting Logging to the Console
Instead of trying out snippets in the console and then checking out the SQL queries that are executed by looking into the log file, it is convenient in such instances to simply redirect the logging performed by ActiveRecord to the standard output. To do this, first start the console and then run the highlighted lines:
C:projectslog> ruby script/console
Loading development environment (Rails 2.2.2)
>> ActiveRecord::Base.logger = ActiveSupport::BufferedLogger.new(STDOUT)
=> #<ActiveSupport::BufferedLogger:0x6031d34 @auto_flushing=1, @level=0, @buffer
={}, @log=#<IO:0x44b6af0>, @guard=#<Mutex:0x6031cf8>>>> Article.find(4).comments
?[4;36;1mArticle Load (0.001000)?[0m ?[0;1mSELECT * FROM "articles" WHERE ("
articles"."id" = 4) ?[0m
?[4;35;1mComment Load (0.000000)?[0m ?[0mSELECT * FROM "comments" WHERE ("co
mments".article_id = 4) ?[0m
=> [#<Comment id: 3, article_id: 4, name: "Fabio", email: "[email protected]", b
ody: "I like your blog. Keep it up! :)", created_at: "2008-07-27 23:04:53", upda
ted_at: "2008-07-27 23:07:59">]
>>Notice how you create a new instance of ActiveSupport::BufferedLogger, indicating that the standard output should be used as the target for the logger. Then when you run Article.find(4).comments the queries are printed to the console, before you obtain the actual array of comments (in this case, a single comment).
6.6.3. Filtering Data
Logging is a powerful tool and Rails makes it very easy to use and customize this feature to suit your needs. There are, however, certain pieces of information that you may not want to log. Passwords and credit card numbers come to mind. In production mode the queries are not logged, but this sensitive data may still show up in the log. So how can you log the request parameters without showing certain types of sensitive data, in plain text within your logs?
Once again, Rails really strives to make your life as easy as possible and provides you with a filter_parameter_logging method. This method accepts one, or a list, of comma-separated symbols, and instructs the controller not to log any parameters containing that word (or those words). So if you were to uncomment the following line in the ApplicationController:
filter_parameter_logging :password
the logs would show [FILTERED] for any parameter matching the regular expression /password/i (for example, :password => [FILTERED]).