Logger
Video transcript & code
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
andSTDERR
. - 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!
Responses