Structured Logging in Rails and Go with JSON and current.sh

by on

Structured logging is a modern take on log messages. Instead of plain text with a timestamp, structured logs have key value pairs. Sticking to common keys and formatted values, you can do some pretty powerful querying on your log data. In this post, we explore the basics of structured logging in Rails and Go with JSON, as well as the benefits of using a structure-aware logging system like current.sh.

Structured Logging Basics

At its very core, structured logging means that instead of a log message as a string of text written for a human:

05/Apr/2016:13:00:00 -0400 production database timing out

The log messages are written in a machine friendly format with key value pairs:

timestamp=2016-04-04T08:55:57-04:00 event=timeout database=production

While this doesn’t quite read as well for the human, it lets you perform powerful queries to dig through the log. So instead of searching for "production database" you can search for database=production.

That’s a pretty simple example, so think about looking for “get or post requests to any session controller actions for users with github accounts”. With structured logging, that query could look like:

(method=GET OR method=POST) controller=sessions account=github

Pretty cool, huh?

JSON Logging

You can do k=v style structured logging, but JSON logging makes structured logging even more powerful. When you use JSON, you’re required to make everything key value pairs or it’s not valid JSON. It also means you’ll be using JSON’s basic types, so your logger can tell if something is a string or a number or a boolean. It also means you can do some basic logging work locally.

The other great thing about JSON is that it’s a really well supported format, so no matter what language or framework you’re using, you can log in JSON.

For example, at MeetSpace, we’re using Go, and it was really easy to use Go’s standard library JSON encoder to print log messages in JSON. This is the base of our JSON logging code:

// Entry is a structured log message
type Entry map[string]interface{}

// LogLevel logs an Entry at the given level as JSON
func LogLevel(e Entry, level string) {
	e["@timestamp"] = time.Now().Format(time.RFC3339)
	e["@severity"] = level
	out, err := json.Marshal(e)
	if err != nil {
                ReportError(err)
		return
	}
	fmt.Println(string(out))
}

You can also use the excellent logrus logger in JSON mode to generate JSON logs.

Now, when we log messages, they look like this:

{"@severity":"info","@timestamp":"2016-04-04T09:54:44-04:00","action":"socket","id":"1","message":{"type":"hello","to":"2","from":"1","data":""}}
{"@severity":"info","@timestamp":"2016-04-04T09:54:44-04:00","event":"broadcast","id":"2","message":{"type":"hello","to":"2","from":"1","data":""},"room":"foo"}
{"@severity":"info","@timestamp":"2016-04-04T09:54:44-04:00","action":"socket","id":"2","message":{"type":"secret","to":"3","from":"2","data":""}}
{"@severity":"info","@timestamp":"2016-04-04T09:54:44-04:00","action":"socket","id":"2","message":{"type":"hi","to":"1","from":"2","data":""}}
{"@severity":"info","@timestamp":"2016-04-04T09:54:44-04:00","event":"broadcast","id":"1","message":{"type":"hi","to":"1","from":"2","data":""},"room":"foo"}

If you scroll that to the end of the line, you can see that the message value is a JSON object! You can nest objects within objects and it’s pretty powerful when it comes to debugging and querying.

You’ll also notice the syntax highlighting helps a lot for readability. It’s highlighted here by highlight.js, but when I’m on my terminal I will do this:

meetspaced | jq -c .

jq is a JSON querying CLI tool. By piping my output to jq -c . it will render the top level elements syntax highlighted in compact form for my terminal. Nice!

You can even perform some pretty powerful operations with jq. For example, this is how you ask for message when id is "2":

meetspaced | jq -c 'select(.id == "2") | .message' 
{"type":"hello","to":"2","from":"1","data":""}
{"type":"secret","to":"3","from":"2","data":""}
{"type":"hi","to":"1","from":"2","data":""}

It’s great that since we’re working with JSON there are so many awesome tools to use along with it.

Structured Logging in Rails

current.sh provides a currentsh gem to use with Rails. Once it’s set up, your Rails logs will log to current automatically. I wanted to check it out in development, so I set config.currentsh.enabled = true in config/environments/development.rb. Then, When I looked at my logs, I got this:

$ rails s
=> Booting Puma
=> Rails 5.0.0.beta3 application starting in development on http://localhost:3000
=> Run `rails server -h` for more startup options
=> Ctrl-C to shutdown server
@current: {"type":"boot","application":"Blurg::Application"}
Puma starting in single mode...
* Version 3.2.0 (ruby 2.3.0-p0), codename: Spring Is A Heliocentric Viewpoint
* Min threads: 5, max threads: 5
* Environment: development
* Listening on tcp://localhost:3000
Use Ctrl-C to stop

It’s the normal Rails logs, plus some lines have @current: at the beginning with some JSON data attached. I went a little further and grepped these lines, trimmed the prefix, and piped it to jq and I got some pure JSON logs:

$ rails s | grep "^@current" | sed -u "s/^@current: //" | jq -c .
{"type":"boot","application":"Blurg::Application"}
{"type":"action","transaction":"c9884b8d8e7bb02b1f0d","controller":"Rails::WelcomeController","action":"index","params":{"internal":true,"controller":"rails/welcome","action":"index"},"format":"html","method":"GET","path":"/","status":200,"view_runtime":7.86834100017586,"db_runtime":0}
{"type":"request","transaction":"c9884b8d8e7bb02b1f0d","method":"GET","path":"/","elapse":0.060579123}

Of course, you don’t have to do all that! You can just use regular logs in development and then use a logging system to view them in all their structured goodness.

Extended Features

What’s the point of all this? It’s all about machine readability empowering awesome features! The reason I keep mentioning current.sh is because without a structured logging system, structured logging isn’t that useful. It’s when you use a service like current.sh or a tool like jq that is aware of structure that all the fun stuff happens.

At MeetSpace, we really like being able to tag our log messages with current’s special @tags awareness to make certain kinds of logs really easy to find. Also, because the structure is parseable, it means that when you’re debugging you can not only query for keys and values, but you can see them very well visualized. Here’s a screenshot of an expanded log entry:

Log entry in current.sh

What’s really cool about this is how it was able to parse types like the timestamp, and also dig into the nested message object. That means I can perform queries like message.type=join. When your logging system is aware of your log message structure, it opens a lot of doors.

— Nick Gauthier

Frustrated with video conferencing?

MeetSpace has the best audio quality and reliability around, and is built for distributed teams.

Start Your Free Trial