Structured, Queryable Logging With Postgres and Bunyan

We at the Guardian Mobile Innovation Lab have been running a series of experiments using push notifications as a means of delivering news to readers in new and inventive ways. It’s been fascinating, but we’ve repeatedly run up against the same problem: data. What do we record? How do we record it? When?

For any normal project this is an easily solved problem: sit down, work out your requirements and create a database. For us it’s a little more tricky: The experimental nature of what we do means we change projects often and aren’t entirely sure what will happen (and so, what we’ll want to record). Also the time pressures we work under — our Brexit notifications were put together in under a week — mean we often don’t have a lot of time to plan out what we’ll want to capture.

But we have been recording data. Lots and lots of it. In our server logs. But there are two problems with that:

• Our log messages are all text, making it difficult to filter and extract information
• The individual log messages are difficult to place in context — we know a request failed, but which user was attempting to subscribe to our notifications at the time? Did they try again afterwards or give up?

So I got to thinking — can we structure our logging in a way that will allow us to also use our logs as a data store for queries?

Logging with objects, not strings

The first stop was a Node module named Bunyan. It’s a logging library that allows you to pass JavaScript objects into your log. Like so:

log.info({action: "server-start", port: 3000}, "Server started.")

By default it looks like this in the CLI:

Certainly nicer than a normal output, but still not a giant leap forward. But Bunyan has the ability to add additional streams to your logger, to send messages to whatever destination you choose. Where to store structured, JSON-safe logging information? A NoSQL database like MongoDB? Maybe. But the query language is more than a little confusing, and we want to be able to easily grab data back out of our logs. What about Postgres? Since version 9.4 it has a new datatype, JSONB, which lets us store and query structured JSON data. (I’m not saying that SQL isn’t a confusing query language, but at least more people know it.)

Just because you can go crazy with JSON doesn’t mean you should. We put together a table schema that allows us to extract the common elements every log message has into normal, defined columns, and only once we’ve extracted them, dump the custom keys into “data”:

Then create a custom Node stream to use with Bunyan, using the Node pg library. Adding the stream to Bunyan is as simple as:

log.addStream({
 level: 'debug',
 stream: new DbStream(),
 type: 'raw'
});

Grouping and merging

So far so good. You may have noticed that the schema above contains an extra field that wasn’t mentioned before: req_id. This comes from the Node module Restify, which allows us to create REST APIs. It uses Bunyan as its internal logging library, and creates a custom log instance for every request, with a pre-populated unique ID for each request. So, if we use this log instance, every message we log is automatically tied together by this ID.

When we don’t have to worry about context it’s a lot easier to throw logging into our code. So in this overly contrived example:

The trySubscribeAction() function doesn’t have to worry about logging the device ID or whether it’s firing a subscription or unsubscription action, because the subscribe() function already has. So what? Well, this is where Postgres’ customizability really shines. The JSONB datatype has a concatenate operator, so you can run:

SELECT '{"a":1}'::jsonb || '{"b":2}'::jsonb

and it’ll return

{"a":1,"b":2}

With a little tweaking, we can create a custom aggregator in our database that lets us aggregate a whole collection of JSON objects together:

CREATE AGGREGATE jsonb_merge(jsonb) (
    SFUNC = jsonb_concat(jsonb, jsonb),
    STYPE = jsonb,
    INITCOND = '{}'
)

Which means we can run queries like this:

select jsonb_merge(data) from log_entries group by req_id

Which will return all of our contextual logging data for a single request, rolled into one object:

{“id”: “kGchgQ:APA91bGX3CA…”, “result”: “<subscription ID>”, “action”: “subscribe”}
{“id”: “kGchgQ:APA91bGX3CA…”, “error”: “Timeout”, “action”: “subscribe”}

That’s not the most readable format, but the real power is when we can use SQL to query it. With the creation of a quick view, all we need to do in order to fetch the number of unique subscribers in the last day is:

SELECT count(DISTINCT data->>'id')
FROM log_entries_grouped
WHERE data->>'action' = 'subscribe'
AND time between (NOW() - INTERVAL '1 day') AND NOW()
GROUP BY data->>'id'

And to find out how many subscribed and unsubscribed in the same day:

SELECT count(DISTINCT data->>'id')
FROM log_entries_grouped
WHERE data->>'action' = 'subscribe'
AND (
 SELECT count(*)
 FROM log_entries_grouped as inner_log
 WHERE inner_log.data->>'id' = log_entries_grouped.data->>'id'
 AND inner_log.data->>'action' = 'unsubscribed'
) > 0
AND time between (NOW() - INTERVAL '1 day') AND NOW()

It’s not pretty, but it is very powerful. We’ll be taking the idea for a spin in our next experiment and seeing how it works in practice.