In Progress
Unit 1, Lesson 21
In Progress

Log Formatting

Video transcript & code

Lately we've been learning how to use Ruby's Logger class. Today I thought we might talk a little about log formatting.

It's no secret that the default output format for the Logger class is pretty verbose. Sometimes the various metadata fields making up log lines can take up more space than the log message itself.

require "logger"
logger = Logger.new($stderr)
logger.info "Hello, world"

# !> I, [2015-09-06T16:18:59.832974 #17789]  INFO -- : Hello, world

If we want, we can customize the logger format. The formatter attribute can be set to a call-able object, such as a lambda, which will then receive four arguments for each message: the severity level, the date and time of the event, the program name (we'll talk about that one more in an upcoming episode), and the actual log message.

Let's make this a minimalist formatter that only emits the severity and the message.

When we try it out, we can see that our log lines are a lot less cluttered.

require "logger"
logger = Logger.new($stderr)
logger.formatter = ->(severity, datetime, progname, message) {
  "#{severity}: #{message}\n"
}

logger.info "Ready for launch"
logger.warn "These readings look weird"
logger.fatal "Aborting launch"

# !> INFO: Ready for launch
# !> WARN: These readings look weird
# !> FATAL: Aborting launch

Custom formatters can be a great way to clean up logging output, particularly in situations where logging is user-visible. For instance, if we have a command-line program that logs to standard error. They can also help us to make our logging consistent with some pre-existing, established log format standard in an organization.

Another interesting use for a custom formatter might be to use it to do some basic structured logging. We may talk more about structured logging in a future episode, but just for a quick example here's how we might output each message as a JSON object. We map each incoming argument to keys in a hash, and then convert the hash to JSON format.

require "logger"
logger = Logger.new($stderr)
logger.formatter = ->(severity, datetime, progname, message) {
  {
    severity: severity,
    time: datetime,
    program: progname,
    message: message
  }.to_json + "\n"
}

logger.info "Ready for launch"
logger.warn "These readings look weird"
logger.fatal "Aborting launch"

# !> {"severity":"INFO","time":"2015-09-07 13:37:47 -0400","program":null,"me...
# !> {"severity":"WARN","time":"2015-09-07 13:37:47 -0400","program":null,"me...
# !> {"severity":"FATAL","time":"2015-09-07 13:37:47 -0400","program":null,"m...

One thing to keep in mind when implementing a formatter is that Logger will not insert newlines between messages for us. We have to remember to add a newline to the end of each line.

There's one other way we can modify the format of logs. Maybe we don't mind the overall layout; we just want more readable dates and times. In that case, we can specify a new #datetime_format. Let's specify %c, which is a shortcut for a fairly human-oriented format.

require "logger"
logger = Logger.new($stderr)
logger.datetime_format = "%c"

logger.info "Ready for launch"
logger.warn "These readings look weird"
logger.fatal "Aborting launch"

# !> I, [Mon Sep  7 13:54:34 2015#26647]  INFO -- : Ready for launch
# !> W, [Mon Sep  7 13:54:34 2015#26647]  WARN -- : These readings look weird
# !> F, [Mon Sep  7 13:54:34 2015#26647] FATAL -- : Aborting launch

As you can see, the date and timestamp portion of the logs is now in a very different style.

The string we pass to datetime_format can accept any of the codes that are valid for the Time#strftime method. You can find a list of these specifiers in the #strftime documentation.

All that said, I'd advise you to think carefully before modifying any part of the log output format, and especially before changing the date/time format. The logging metadata that seems like "noise" most of the time can turn out to be essential when diagnosing problems on production servers. And the standard ISO8601 date/time format is universally recognized, unambiguous, and easy to parse programmatically.

And with that warning, we're done for today. Happy hacking!

Responses