8.2 Logging

The `caller` method

You'd have observed how when your code produces an error, Ruby prints a stack trace - the method and line number which had the offending statement, the method that called this, and so on.

This stack trace is useful when you are inside a method within a deep context and want to inspect it. This is provided by the caller method which if needed can be used to debug our code as well. An example:

Example Code:

Output Window

The caller method returns the stack trace as an array which is pretty convenient if you want to programmatically introspect it.

Logging

There will be occasions when you need to continuously keep track of what your application is doing so that when something goes wrong, you have a detailed trace. This is called 'Logging' - it is most useful when there is a time gap when the error could occur and when you try debugging it. Ruby ships with the Logger class that you can use for logging.

An example:

Example Code:

Output Window

Before you can use the Logger class, you have to require it explicitly by using the
require 'logger' statement. When initializing, you have to tell it where to log it - this can be the name of a file, a File object or any IO object to which it can write. In our examples, we pass it the $stdout object which prints to the standard output.

The Logger class exposes multiple methods - all of which logs the message, but in the following order of severity: debug < info < warn < error < fatal < unknown. So, if the logging level is set to say WARN, then only levels that have same or higher severity than WARN are printed - which includes WARN, ERROR, FATAL and UNKNOWN. The highest state of logging is DEBUG, which will print everything.

You can set the severity level of logging by assigning the level like so:
logger.level = Logger::INFO

An example:

Example Code:

Output Window

In the above example, when the severity was set to UNKNOWN, only messages with that severity was logged. This was because all other severity levels are lesser than UNKNOWN, and hence ignored.

However, when the severity was changed to INFO, all messages that were either UNKNOWN, ERROR or WARN were printed. The messages with severity DEBUG were ignored because DEBUG has lesser severity than INFO.

All these messages lack an important context: the time when they were logged. Let us fix that:

Example Code:

Output Window

The formatter attribute takes in a lambda to which the parameters given in the example are passed in order. The lambda can make use of the parameters and format the log output the way you need it.

You might have noticed that we were initializing Logger with STDOUT. You can replace STDOUT with a File object so that all logs go into a file. This is typically how logging is used. Logger only cares that the parameter is a stream to which it can write. Instances of File, IO and STDOUT/STDERR are all objects that can be used here.

We'll end this lesson with an exercise. I've implemented an Order class that procures, packs and ships an order. You have to instrument the order so that during each step, an appropriate log is produced. Each log should contain the new state of the order and any new information passed to it during that step. You should use info as your severity level for normal logs. For exceptions, use error.

Hint

Use the Logger instance for the duration of the object's lifecycle. Instance variables to the rescue!

Output Window

Congratulations, guest!


% of the book completed

or

This lesson is Copyright © 2011-2014 by Jasim A Basheer