Structured Logging — Part 3: Practical Application for Ruby

Originally published at blog.current.sh on October 21, 2015 by @evanphx.

This is Part 3, start with Part 1.

Congrats! You’ve made the wise decision to use structured logging, and I know you won’t be sorry.

Now you need to actually start applying these techniques to your code base so that the logs start off structured with all the right formatting. Let’s jump right in.

Ruby

I recommend people create a small log class and singleton instance that they funnel log requests through. This gives them a single inflection point to add features and smooth out the data as they see fit.

This is a really simple skeleton to start with. You can add methods on SLogger for different event types, etc. The point is it’s code that lives per project and can evolve to keep logging clean.

I prefer to keep this file as lib/<project>/log.rb and require it when needed.

Rails

First, we start with the Ruby methodology, then we tie into the Rails logging system.

That gives you structured logging in your normal Rails logs. I think that’s the best way to start and once you have a handle on it, you can decide if you’d rather the logs be sent somewhere else.

Because rails apps are typically standalone projects, I prefer to put this into lib/log.rb and then require it when needed.

Another source of information is Rails itself. All that model/view/controller logging is rich with information about what and how your app is working.

The best general purpose gem to use to tame Rails into doing structured logging is lograge. It will modify your installation to emit controller information in a structured way. The format is controlled by lograge itself. I generally recommend people use the JSON emitter it includes.

So you’d have something like this in your config/environments/production.rb:

config.lograge.enabled = true config.lograge.formatter = Lograge::Formatters::Json.new

Lograge will transform your logs from:

Started GET "/api/v1/user" for ::1 at 2015-10-20 12:56:47 -0700 Completed 200 OK in 244ms (Views: 81.2ms | ActiveRecord: 126.5ms)

Into:

{"method":"GET","path":"/api/v1/user","format":"*/*","controller":"api/v1/users","action":"show","status":200,"duration":102.32,"view":64.84,"db":8.33}

One downside of lograge is that it does not handle any ActiveRecord logs right now, even when the log level would emit them (that log level is debug, by the by).

Over here at Current, we’re in the process of putting together a gem that integrates with our service but also provides general structured logging facilities to all of Rail’s subsystems. So if you’d like to log ActiveRecord access in a structured manner, we’ll have that out for you soon.

Development vs Production

Generally folks want to emit structured logs in production only. This is because they’re generally harder to read than traditional logs that have been formatted with a direct human reader in mind.

For that reason, we’ve directed you to enable lograge only in production. If you’d like to enable it in development, simply add the config values to config/environments/development.rb as well. Additionally, you could leave off setting the formatter in development. lograge will use a human readable format in that case, making the logs easier to read.

Multiple Mechanisms

You’ll no doubt notice that if you follow the Rails path above, you’ll have 2 different mechanisms for creating structured logs in your Rails app. This is on purpose. lograge is good to tie into the Rails stack, but it’s not as easy to use for logging that you’d want to do within your app itself.

For instance, in your login controller, perhaps you’d want to add:

SLog.info "user login", user:, user.name, last_login:, user.last_login

Now you have login information in your logs to track and correlate along with other activities the user might do. Doing this via SLog is much easier than trying to tie into lograge each time.

If you decide you’d like to have the SLog calls be routed to lograge, great! The lograge docs will direct you in doing that.

Conclusion

The overall goal is to keep the code that emits structured data as simple and clean as possible. This promotes heavy use of structured logs and allows for centralized control over formatting and emission.