Tracking Rails Application Behavior and Errors with the Ruby Logger

by Mike Zazaian at 2009-09-21 17:23:40 UTC in rails

a quick overview on the utility of the Ruby Logger class, how it's implemented in Rails, and how to create a custom log to track only specific actions in your app

2 comments 2 links

Paul Bunyan was a bastard

The word Logger for me evokes an image of of Paul Bunyan in that 1950's-era Disney cartoon, where he and Babe the Blue Ox are trouncing through some massive wilderness, felling redwoods by the dozens, deforesting at a superhuman rate for no apparent reason besides wanton competition and personal glory.

Fortunately Ruby has a vastly more useful, humble, and environmentally-friendly Logger built right into it, and you won't even have to displace entire species of woodland creatures to implement it.

Ruby was (and is) not a bastard

Indeed, the Ruby Logger class is a really handy way to keep track of all of the happenings in any code or applications that you might want to keep an eye on:

$ irb
>> require 'logger'
=> true

>> logger = Logger.new STDOUT
=> #<Logger:0xb6d047e0 @level=0, @progname=nil, @logdev=#<Logger::LogDevice:0xb6d0477c @shift_age=nil, @filename=nil, @mutex=#<Logger::LogDevice::LogDeviceMutex:0xb6d04754 @mon_waiting_queue=[], @mon_entering_queue=[], @mon_count=0, @mon_owner=nil>, @dev=#<IO:0xb7c95574>, @shift_size=nil>, @formatter=nil, @default_formatter=#<Logger::Formatter:0xb6d047a4 @datetime_format=nil>>

>> logger.info "I'm really happy something happened inside of my application.  Seriously."
=> I, [2009-09-20T10:56:36.874923 #7362]  INFO -- : I'm really happy something happened inside of my application.  Seriously.

neither is Rails

Nifty, huh? Luckily for us, Rails already keeps an instance of the logger class accessible for use as the variable logger from any of the standard Rails MVC classes in order to print messages directly to the appropriate log file in your RAILS_ROOT/log directory. For example, if you're running the production environment of your application, the following line will output to /log/production.log:

#!/app/models/bee.rb

class Bee << ActiveRecord::Base
  ...
  logger.info "I am terrified of bees.  Why did I create a class for them?"
  ...
end

That poor choice of classes aside, you get the idea. You can also (not that you'd need to) pass a message to the logger inside a block, like this:

logger.info { "This is just getting out of hand." }

the gamut

info, however, is just one of the methods that you can call from an object of class Logger. For shits and/or giggles, here's the entire hierarchy of methods available to the logger, in order:

debug

>> l.debug "this really shouldn't have happened"
D, [2009-09-20T12:15:24.872484 #7362] DEBUG -- : this really shouldn't have happened
=> true

useful for tracking when various methods are fired (or mis-fired) within an application to enforce the expected functionality

info

>> l.info "I've yet to understand what this feature does"
I, [2009-09-20T12:16:05.183239 #7362]  INFO -- : I've yet to understand what this feature does
=> true

enables you to enter basic notations about application functionality in the log, or to enter other bits of relevant data such as benchmarks or timestamps, or anything that might be useful for analysis

warn

>> logger.warn "a storm's a'brewin'"
W, [2009-09-20T12:14:05.276635 #7362]  WARN -- : a storm's a'brewin'
=> true

useful for tracking potential security threats or more substantial malfunctions in an application, such as instances in which flash notices appear in the wrong circumstances, or when users access areas of the site which they weren't explicitly allowed to

error

>> l.error "Err...that really, really shouldn't have happened."
E, [2009-09-20T12:16:44.778900 #7362] ERROR -- : Err...that really, really shouldn't have happened.
=> true

used for tracking bugs that severely hamper the performance or function of your application, but do not require your server to be restarted

fatal

>> l.fatal "ABANDON SHIP!!! WE'RE ALL GOING TO DIE!!!!!!!!!!!!!!!!!!!!"
F, [2009-09-20T12:17:17.661242 #7362] FATAL -- : ABANDON SHIP!!! WE'RE ALL GOING TO DIE!!!!!!!!!!!!!!!!!!!!
=> true

used for tracking MASSIVE bugs and issues such as methods falling into infinite loops and other issues that might crash your server, overload it's resources, and/or force you to restart it

That's pretty much all you'll need to know for effectively writing messages to the log in your Rails app. No, there isn't any particular utility to any of these messages besides distinguishing the type of message being output, and the severity of said message, but it's still useful to classify logger messages as such to allow you to more easily identify issues that arise.

creating a custom logger

So what if you want to get fancy and, say, create a custom log for every time a user accesses an article in your nifty, loggified Rails app? Well, as you've seen, there aren't too many visible complexities to the Ruby logging system, and the creation of custom loggers is no exception. Observe:

#!/app/controllers/some_controller.rb

require 'logger'
logfile = File.open("#{RAILS_ROOT}/log/article_views.log", "a")
custom_logger = Logger.new(logfile)
custom_logger.info "Happy people are viewing articles.  Happy..."

It's really that simple. First we tell File.open write to the end of the /log/article_views.log if it exists, or to create a new file if it doesn't (This is what "a" denotes. Check out the Ruby IO Rdoc file for more info).

Once that's done we create a new instance of the Logger class, and instead of storing those messages in STDOUT as we did before, we just save them in a file at the logfile path. Neato.

aging custom logfiles

One issue that pops up with the creation of custom logfiles is that they're not cleared or aged according to the specifications of the rest of your Rail's app's logs, meaning they can get big and bloated and nasty and hard to read and/or open.

This is easy enough to negotiate, however, as the Logger class allows you pass in a couple of arguments upon instantiation that allow you determine when and how a log is aged.

Say, for example, that you wanted a new version of your custom log file to be created every time it hits one megabyte. Say also that you want the last ten iterations of that logfile to be kept on record for later reference. You'd just pass those maximum file size and iteration values into the Logger.new method like this, assuming, that is, that your logfile variable is still in tact from earlier:

custom_logger = Logger.new(logfile, 10, 1000000)

Cool, huh? You can even set your logger to age along more standard time intervals to prevent your logfiles from becoming too massive, like this:

custom_logger = Logger.new(logfile, 'daily')
custom_logger = Logger.new(logfile, 'weekly')
custom_logger = Logger.new(logfile, 'monthly')

As you'd imagine, both of these techniques are enormously useful if you plan log large amounts of data in your custom log, and/or if your site has a great deal of traffic.

fin

So that's the word. I won't bore you with any more of the specifics of custom logs or the nuances thereof, except to say that there are methods available for formatting the output of your logger messages, and a host of other methods available for the Logger class, too. But as these are covered in the Logger rdoc in the Ruby Standard Library Documentation, so you're not being wholly left in the woods on this one.

Either way, hopefully you've learned some helpful hints on using and creating logs in Ruby/Rails apps, and that Paul Bunyan was an evil opportunist who until now has never been properly reprimanded for his misdeeds.

Damn you, Paul Bunyan. Damn you.

2 comments

shaun at 2009-10-08 17:47:13 UTC

Hey Mike,

Great post, I didn't know you could "age" log files like that, very cool! I wonder.. is there a way to age normal log files, like production.log? So they will rotate every month or when they reach a certain file size, etc.?

Thanks, Shaun

Mike Zazaian at 2009-10-11 18:47:32 UTC

Hey Shaun -- yeah, it's a nice little feature built in to the ruby logger. To answer your question, there's a really nice linux server app called logrotate that can handle the rotation and compression (everything, really) of the default Rails development/production logs. I've actually already written an article on this, and will be posting it tomorrow morning after a quick edit. Bueno?

Comments closed

latest links

Help.GitHub - Multiple SSH keys The article from github help mirroring this process
ones zeros majors and minors ones zeros majors and minors: esoteric adventures in solipsism, by chris wanstrath
ActiveScaffold A Ruby on Rails plugin for dynamic, AJAX CRUD interfaces

login

register activate reset

feeds

articles/rss

topics

staff

editor

about

doblock focuses on ruby, rails, and all things that can help ruby and/or rails programmers hone their skills.

Techniques, tutorials, news, and even free open-source applications, doblock seeks to fill in the cracks of the ruby/rails blogosphere.

doblock v. 0.10.1 powered by Rails