Writing Concise and Informative Logs

Observability when working with lambdas is important, with so many getting spun up at different times and serving different requests it is good to have as much information as possible about what exactly is going on. When I wish to debug code my code or pull metrics I always use the json formatting. I do this because it is easily greppable by Cloudwatch and can hold some very valuable information, json is also an amazing format to work with. For anyone who doesn't know how to query Cloudwatch I would recommend checking this out. The most important thing is to put as much useful information into the log as possible, whilst preventing any unwanted information from slipping in.

Let us build up an informative log line

Here are the steps I follow when deciding what to add to a log line.

Let's say the following event has happened;

user has been updated

This is a vague statement but it is a good place to begin asking question and working out what information is needed. First question that springs to mind is which user has been updated?

Better add in a unique identifier for that user.

{
    msg: "a user has been updated",
    user_id: 1234,
}

What has been updated on the user? Some could argue that this information may be unnecessary but it all comes down to observability.

{
    level: "info"
    msg: "a user has been updated",
    user: {
        id: 1234,
        username: "JohnnMackk",
        email: "john.mackenzie91@yahoo.co.uk"
    },
}

At what time did this happen? This is cheating since Logrus gives this to us for free but let us build it up.

{
    level: "info"
    msg: "a user has been updated",
    user: {
        id: 1234,
        username: "JohnnMackk",
        email: "john.mackenzie91@yahoo.co.uk"
    },
    time: "05-11-2018 12:12:12",
}

Who actually updated this user? why not add their id? You could add the user as an object with their username ect but let's keep this log as small as possible

{
    level: "info"
    msg: "a user has been updated",
    logger_in_user: 1,
    user: {
        id: 1234,
        username: "JohnnMackk",
        email: "john.mackenzie91@yahoo.co.uk"
    },
    time: "05-11-2018 12:12:12",
}

Finally let's say that something went wrong sometime during this request? How do we know what happened just before the error. Let us add a unique identifier into this log so that we can follow it as a stack trace;

{
    level: "info"
    run_id: "n70zqPXBaxA9RdJ4",
    msg: "a user has been updated",
    logger_in_user: 1,
    user: {
        id: 1234,
        username: "JohnnMackk",
        email: "john.mackenzie91@yahoo.co.uk"
    },
    time: "05-11-2018 12:12:12",
}

Ok one last thing msg "a user has been updated" seems kind of redundant it was good for a starting point but now we have built up more of a picture around it, but we do need some kind of identifier to distinguish all logs of an "update" kind of nature.

Why don't we rename msg to type

{
    level: "info"
    run_id: "n70zqPXBaxA9RdJ4",
    type: "User Update",
    logger_in_user: 1,
    user: {
        id: 1234,
        username: "JohnnMackk",
        email: "john.mackenzie91@yahoo.co.uk"
    },
    time: "05-11-2018 12:12:12",
}

And done, from a user has been updated we how have a clear descriptive log with no redundant data.

Observability

Now for the reason we did the above, to view our logs, and read exactly what our system is doing.

Querying these logs via cloudwatch

I have recently been working with Golang lambdas running on AWS so I was using Cloudwatch to view these logs. Fortunately Cloudwatch has a really cool query language for this very job. Using the above as an example.

I can now begin to query Cloudwatch and pull back all these events via;

{ $.type = "User Update" }"

If i wanted to get all the updated done by a certain user I can;

{ $.type = "User Update" && $.logger_in_user = 1 }

And if something went wrong during the request I can create myself a stack trace via;

{ $.run_id = "n70zqPXBaxA9RdJ4" }

Viewing on the commandline

When viewing from the command line I use jq. Essentially this tool is a grepper, and a json formatter all in one.

The simplest

tail -f some-json-log-file.log | |jq '.'