Logger

I could have sworn I'd already done an episode on Ruby's standard logging library, but apparently not. Well, today I remedy that omission!

Even if you're just getting started programming, you've probably put some kind of logging in your programs. Who hasn't, at some point, inserted a puts line to verify that the program is doing what they think it's doing?

def average(numbers)
  sum = numbers.reduce(:+)
  puts sum
  sum / numbers.size
end

average([34, 56, 23, 18, 7, 85]) # => 37

# >> 223

This right here is logging code. It gives you some information about what was going on internally as the program was running. And for some programs, this may be all the logging you ever need.

But eventually, you may find that you have more advanced logging needs. Here are some potential reasons you might find yourself looking for something more than plain old puts:

• You may only want the logging to happen when you're debugging the program.
• You might want some log messages to be output all the time, while still disabling debugging output when not in a debugging context. In other words, you might want to have different priority levels for log messages.
• You might want to ensure that every log message contains a timestamp, so that you can understand the timeline of events when things go wrong.
• You might want to write logging information to a file, without redirecting STDIN and STDERR.
• You may want to limit the space that logfiles can use up, so as to avoid gradually filling up a server's drive space.
• You might want the log messages to be sent to a centralized logging server when the program is deployed to production.

For all these advanced needs and more, Ruby provides a standard library called Logger. We're not going to cover all of the use cases I just listed today; instead, I thought we could cover just enough to get you started with the library.

To use Logger, we first require the library. Then we create a Logger instance with Logger.new.

We have to provide an argument to this method, in order to tell the new Logger where to write its messages out to. Let's tell it to write to the global $stderr stream, which is a good default.

Now let's write a message to the logger. To do that, we send it the #info message along with a string.

When we execute this code, we see our message dumped to standard out, prefixed by a whole bunch of extra information.

require "logger"

log = Logger.new($stderr)
log.info "Hello, logging world!"

# !> I, [2015-08-06T15:20:42.430155 #29247]  INFO -- : Hello, logging world!

Before we talk about this extra info, let's add a few more lines of logging output.

require "logger"

log = Logger.new($stderr)
log.info "Hello, logging world!"
log.debug "This is a debug message"
log.error "This is an error message"

# !> I, [2015-08-06T15:31:27.400901 #29430]  INFO -- : Hello, logging world!
# !> D, [2015-08-06T15:31:27.400974 #29430] DEBUG -- : This is a debug message
# !> E, [2015-08-06T15:31:27.401007 #29430] ERROR -- : This is an error message

Now that we have a few different samples, let's talk about the format of the log lines, from left to right.

First off, we have a short, one-character indication of the message's severity level. We've seen three severity levels so far: info, debug, and error. We'll talk about the full list of severities in a moment. What we can see here is that the first letter in the log line corresponds to the first letter of the severity: I for INFO, D for DEBUG, E for ERROR.

After a comma, a space, and an open bracket, we can see what is clearly a date and time-stamp. Looking at the time side, we can see that it is specified all the way down to microsecond resolution.

Next there's a space, and then a pound sign followed by another number. This is the process ID of the program that emitted the logging message. If we re-run this code, we can see that the process ID changes each time.

Why might we want the process ID? If we were analyzing logs from multiple programs together, this is one way of telling them apart. It also helps us see if the program was killed and re-started between one message and another.

Next up, we see the full name of the logging severity level.

Then there's a space, a double dash, another space, and a colon. Technically there's another field here, currently invisible because it is blank. We'll talk about that field another time.

Finally, all the way at the end, we see the text that we sent to the logger.

So right off the bat we can see that Logger adds a great deal of metadata to each log message. The timestamps are probably the most immediately useful part of this metadata.

Now let's talk about severity levels. Logger defines five levels of severity.

DEBUG

Debug is the least severe, and it is normally used for extremely detailed information that is only of interest when debugging the program.

INFO

Info is for informational output. If you have something to log that's useful outside of a debugging context, but it doesn't represent a problem, use this level.

WARN

Warn is for warnings. These are problems that haven't graduated to the status of errors. For instance, if the user has specified a configuration value which is deprecated and may be removed in a future version of the program, a warning is probable in order.

ERROR

The error level is, not surprisingly, for errors. These are real problems which may be preventing the program from doing its job properly. These are issues that a user needs to know about. For instance, if a chat server loses its connection to a peer server and is unable to pass a message on as a result, that's an error.

FATAL

The fatal level is reserved for errors so bad that the program can't continue. These are often the result of bugs in the programs code. In another episode, we'll talk about how we might capture un-rescued exceptions and log them as fatal errors before exiting.

Technically, there is also a sixth severity level called UNKNOWN. But this level isn't commonly used.

Every logging severity level has a corresponding method. We've already seen these for DEBUG, INFO, and ERROR. The other levels have similar methods.

require "logger"

log = Logger.new($stderr)
log.debug "This is a debug message"
log.info "Hello, logging world!"
log.warn "This is a warning message"
log.error "This is an error message"
log.fatal "This is a fatal message"

# !> D, [2015-08-06T16:14:20.314303 #31233] DEBUG -- : This is a debug message
# !> I, [2015-08-06T16:14:20.314354 #31233]  INFO -- : Hello, logging world!
# !> W, [2015-08-06T16:14:20.314382 #31233]  WARN -- : This is a warning message
# !> E, [2015-08-06T16:14:20.314396 #31233] ERROR -- : This is an error message
# !> F, [2015-08-06T16:14:20.314409 #31233] FATAL -- : This is a fatal message

These logging levels don't just exist so we can filter the resulting log files by the severities we are interested in. We can also control what messages are written out, and which are ignored.

By default, as we can see here, all messages are written to the output stream. But we can change the level using the level attribute on the logger object. We have to pass once of the level constants defined inside the Logger class.

If we set the level to INFO and run this code again, we can see that the debug output vanishes. The logging level we set specifies the least severe level of output which will be logged. Anything less severe will be suppressed.

require "logger"

log = Logger.new($stderr)
log.level = Logger::INFO
log.debug "This is a debug message"
log.info "Hello, logging world!"
log.warn "This is a warning message"
log.error "This is an error message"
log.fatal "This is a fatal message"

# !> I, [2015-08-06T16:17:02.284007 #31299]  INFO -- : Hello, logging world!
# !> W, [2015-08-06T16:17:02.284083 #31299]  WARN -- : This is a warning message
# !> E, [2015-08-06T16:17:02.284133 #31299] ERROR -- : This is an error message
# !> F, [2015-08-06T16:17:02.284170 #31299] FATAL -- : This is a fatal message

So if we set the level to WARN, the INFO output disappears. If we set it to ERROR, the warning disappears. And so on.

require "logger"

log = Logger.new($stderr)
log.level = Logger::ERROR
log.debug "This is a debug message"
log.info "Hello, logging world!"
log.warn "This is a warning message"
log.error "This is an error message"
log.fatal "This is a fatal message"

# !> E, [2015-08-06T16:20:49.513895 #31382] ERROR -- : This is an error message
# !> F, [2015-08-06T16:20:49.513960 #31382] FATAL -- : This is a fatal message

Now, it's possible that what you're thinking right now is: "that's all lovely, Avdi, but what I was REALLY hoping you'd show me in this episode is how to log to a file!". So let's go ahead and end this introduction to Logger with how to log to a file instead of to output.

It turns out that this is extremely easy. If, instead of an output stream, we pass a string to the Logger initializer, it interprets this string as a filename.

require "logger"

log = Logger.new("rubytapas.log")
log.debug "This is a debug message"
log.info "Hello, logging world!"
log.warn "This is a warning message"
log.error "This is an error message"
log.fatal "This is a fatal message"

If we execute the code and then go looking for the file, we can see that it has been created and it contains all the log lines we just wrote.

# Logfile created on 2015-08-06 16:24:04 -0400 by logger.rb/44203
D, [2015-08-06T16:24:04.037189 #31445] DEBUG -- : This is a debug message
I, [2015-08-06T16:24:04.037223 #31445]  INFO -- : Hello, logging world!
W, [2015-08-06T16:24:04.037242 #31445]  WARN -- : This is a warning message
E, [2015-08-06T16:24:04.037258 #31445] ERROR -- : This is an error message
F, [2015-08-06T16:24:04.037275 #31445] FATAL -- : This is a fatal message

If we execute the code a couple more times and then take another look at the log file, we can see that rather than overwrite its contents, Logger appends new output to the end of the file. Which is exactly what we usually want to see in a log file, even if it does mean that the file will potentially grow without bounds.

# Logfile created on 2015-08-06 16:24:04 -0400 by logger.rb/44203
D, [2015-08-06T16:24:04.037189 #31445] DEBUG -- : This is a debug message
I, [2015-08-06T16:24:04.037223 #31445]  INFO -- : Hello, logging world!
W, [2015-08-06T16:24:04.037242 #31445]  WARN -- : This is a warning message
E, [2015-08-06T16:24:04.037258 #31445] ERROR -- : This is an error message
F, [2015-08-06T16:24:04.037275 #31445] FATAL -- : This is a fatal message
D, [2015-08-06T16:25:51.815994 #31488] DEBUG -- : This is a debug message
I, [2015-08-06T16:25:51.816057 #31488]  INFO -- : Hello, logging world!
W, [2015-08-06T16:25:51.816100 #31488]  WARN -- : This is a warning message
E, [2015-08-06T16:25:51.816129 #31488] ERROR -- : This is an error message
F, [2015-08-06T16:25:51.816180 #31488] FATAL -- : This is a fatal message
D, [2015-08-06T16:25:52.312465 #31500] DEBUG -- : This is a debug message
I, [2015-08-06T16:25:52.312559 #31500]  INFO -- : Hello, logging world!
W, [2015-08-06T16:25:52.312594 #31500]  WARN -- : This is a warning message
E, [2015-08-06T16:25:52.312623 #31500] ERROR -- : This is an error message
F, [2015-08-06T16:25:52.312664 #31500] FATAL -- : This is a fatal message

There is a great deal more to be learned about logging, and there are even other kinds of loggers with similar interfaces but very different behaviors. Hopefully, though, what we've seen today is enough to get you comfortable with the basics of logging in Ruby. As a general rule, the more a program logs about itself, the easier it is to debug problems with that program. So if you've been putting off using logging in your programs because of unfamiliarity with the tools, now is a great time to change that habit. Happy hacking!