Introducing YetiLogger

In this blog post I’m going to introduce the yeti_logger gem. This is Yesware’s shared logging mechanism for our Ruby code. You might be wondering why such a need exists. Ruby has pretty decent logging via the Logger class and Rails builds upon that. So why another layer? For us it came down to a few reasons:

  • abstraction
  • efficiency
  • format

Keep reading for some background on each of these reasons and a high level overview of how to use it, or feel free to jump straight to the GitHub repo (https://github.com/Yesware/yeti_logger) to check out the Readme.

More on the why?

As with all things software, we tend to change our minds on things here at Yesware. Logging is not necessarily one of them, but it’s something we’ve toyed with in the past. We wanted to be sure that all of the great logging we were adding to the product wouldn’t result in a refactoring nightmare if we switched from using Rails.logger to something else. Also, to make things more complicated, we have some non-Rails applications that use Logger directly, and a very few places that even use puts (most of our production apps run on Heroku, where our logs are sent to stdout anyway, so this isn’t as bad as it sounds). Having a nice abstraction layer over whichever logger we wanted to use seemed like a good idea.

Another aspect of abstraction is the idea that it should be very easy to log (and to stop logging). By making YetiLogger a mixin module, you get methods you can call directly on your class or class instance, such as log_info("hello"). By having these methods live on your class/module/instance, it makes it much easier to replace YetiLogger, or just bypass it by defining a method on your class/module/instance with the same signature of those from YetiLogger. For example to temporarily bypass all calls to YetiLogger#log_info, define a dummy method on your class that does what you like with it:

def log_info(message)
  # Code to stick message wherever you like, such as a database, queueing system, or nowhere!
end

We also wanted more control over the performance impact of our logging. Fortunately we’re not in a position that we’ve been able to point to our logging as a major source of performance drain on our application. That said, we didn’t want to get ourselves into such a predicament. The formatting of a string to emit to a log is generally fast, but sometimes we want to compute or fetch additional information to help with later debugging. Additionally there were some efforts to remove log statements from the code that were set to log at levels below where we typically ran. While this was fine and all, we really wanted to have the freedom to leave some poor-performing code in and be assured that unless we needed to turn it on, it would remain off. As you can see below, we accomplish that with Ruby blocks being passed to YetiLogger methods. Since the block’s evaluation is deferred, we can optionally check whether or not we need to even evaluate it (and thus even build the string to log) based on the logging level. Unfortunately, Ruby doesn’t have the notion of lazy evaluated method parameters, so we couldn’t rely on that. Blocks gave us what we were looking for. We can now fill calls to YetiLogger with inefficient blocks that lookup all the information we’d want to debug something knowing that unless we crank up the log level they’ll safely not impact performance.

The last, and probably biggest reason for YetiLogger is one of consistent formatting. We’ve tried out several logging tools and are currently big fans of SumoLogic. It’s great for consolidating all of our production system logs and giving us a nifty way to search through them. One thing that quickly came up after we began using our logs more was that the formatting of log messages was all over the place. Parsing structured data is much easier than extracting information from plain text. Take these two log messages for example:

user_id=37 email=yeti@yesware.com msg=login

and

"user 37 (yeti@yesware.com) logged in"

Now, extracting the user id and email from either of these is not terribly hard. In fact it’s arguably not hard at all. The problem isn’t with one such format, but when every log statement has a slightly different way of formatting things, it’s a problem of scale. At some point, the code to extract all the possible ways a user id is specified is huge. And that’s just one field. The key=value formatting that we prefer to use however, is much easier for a machine to read. It makes writing parsers to extract attributes much more cookie cutter, rather than each one looking slightly different. While YetiLogger does support unstructured log messages, by far the preferred way to use it is to take advantage of the key=value style format.

That’s a little about how we got to where we are with YetiLogger. Now let’s take a look at how to use it.

How it works

To start with, install it via RubyGems:

gem install yeti_logger

YetiLogger is a wrapper around a Logger-like class, so before you can you it, you must configure it. The only required configuration is to specify a logger class to use for the actual logging.

require 'yeti_logger'
 
YetiLogger.configure do |config|
  config.logger = Rails.logger
end

The logger can be any Logger-like class that YetiLogger will defer to for actual logging. It also relies on the underlying logger for configuration such as log levels.

Once you have a configured YetiLogger, you can begin mixing it into your classes and modules. Adding it to a class will give you both class-level methods as well as instance-level methods such as log_info, log_warn, etc.

class MyClass
  include YetiLogger
 
  def test_logging
    log_info("hello!")
  end
end
 
MyClass.new.test_logging

The above will output a log line that looks like this:

2016-04-05T10:23:29.135-04:00 pid=90811 [INFO] - MyClass: hello!

The bits at the beginning of the line are all specified via the underlying Logger format configuration. The last bits of the line (MyClass: hello!) all come from YetiLogger. In general, the format for a log message is <Class name>: <log message>. The signature for each of the log_* methods looks like this:

log_info(obj = nil, exception = nil, &amp;block)

Yes, everything is optional, but that’s to give you the most flexibility. Let’s drill into each of the arguments separately.

The first arg is obj. This can be any object, but it really gets boiled down to one of three types: a hash, an exception, and everything else. See the next paragraph if obj is an exception. If it is not an exception, nor a hash, then we simply call #to_s on it and log that. If obj is a Hash, though, then we convert it into a key=value key=value string of the hash’s values. Remember that one of the reasons for YetiLogger was formatting? We found that key value formatting of log messages helps us write tools that look through logs for information. It’s much easier to find all activity associated with a user by searching for user_id=1234, rather than having to remember what format to keep things in so you don’t wind up matching all versions of logging user id: user_id:1234, user_id(1234), or the worst 1234.

The second argument is exception. This argument, if present, should be a Ruby Exception. YetiLogger will print the message, class and backtrace of the exception. If the first argument (obj) is a Hash, the exception details will be added to it and equivalently logged as key=value pairs.

The last argument, a block, is the preferred way to call YetiLogger for logging messages below the level you specify for logging. For instance, if you’ve configured the Logger to log at the info level, then all debug-level log statements should use the block form of calling. The block form of calling YetiLogger defers evaluation of the block until after the log level is checked. This allows you to leave in log statements that may be very expensive to compute (lookup additional data from a database for instance) and be assured that they won’t slow down your app, until you crank up the log level so they are evaluated. The value returned from the block follows similar rules above for the obj parameter. For instance:

log_info(user_id: user.id, msg: "logging in")

is equivalent to

log_info do
  {
    user_id: user.id,
    msg: "logging in"
  }
end

We routinely run with our logging levels set at info, but we still use the block form frequently as it’s also a convenient way to encapsulate all the logic associated with forming a log message. For instance:

log_info do
  msg = if user.first_login?
    "first login"
  else
    "login"
  end
  {
    user_id: user.id,
    msg: msg
  }
end

Continue reading more about YetiLogger here, including test support and the internal message formatters that you may find useful outside of a logging context.

Conclusion

I hope you liked reading about YetiLogger and that you find some use for it in your projects. As always, let us know via issues or pull requests against the repository about any questions or improvements you may want to see. We’ve been using YetiLogger pretty much untouched for a few years now and have been quite happy with it. It’s been a huge time saver in terms of instilling conventions that we find useful for debugging issues via logs, and hope you do too.

https://github.com/Yesware/yeti_logger

Leave a Reply

Your email address will not be published. Required fields are marked *