Logging with context in Go
Logging is an important part of your application. Understanding what your system is doing helps finding problems, understanding your logic or even reverse engineering what the application is doing. Logging can be quite tricky when dealing with distributed/concurrent applications. In these cases it is crucial to understand the context of what the logger is doing.
As an example imagine logging in Cloud Functions. Scaling is achieved by creating new instances of your functions. Each of these instances can only handle one request at a time. So large spikes in request volume might result in creating many instances. Cloud Functions can be triggered by messages published to Pub/Sub. As an example look at the following cloud function.
This cloud function gets a TestRequestID from the message attributes and logs it using the log standard library from go. The output is something like this:
The main problem with this approach is that you have to set the TestRequestID as a context for all logs in the cloud function. Like can be seen from the previous example if someOtherFunction fails it will log an error. If we don’t add the TestRequestID to the log statement then in a parallel/concurrent system it is difficult to know which request failed. For instance in the following example 3 requests out of 4 failed. Now which one failed?
However which one failed is difficult to figure out from this example. An easy way to solve this is to add the TestRequestID to all the log calls. However this doesn’t scale and it is extremely error prone.
A good way to solve this is to use log libraries like klogr. Whit klogr you can use the function call WithValues to set context for the next calls.
Now if we run the with 4 parallel requests. We can see the following logging:
From this logging we can see TestRequestID is always logged. Giving context to the logging. We can also see that 4 request have been triggered and only TestRequestID 2510b79b-0ebb-4c01-b0af-950b932939c4 failed.
However if you would like to log with context with other functions you should always inject the logger to the functions that require logging. Just like in the next example:
You can then get always a context in the logging. Just like described bellow.
Another possible approach is to use the context from golang. Package context defines the Context type, which carries deadlines, cancellation signals, and other request-scoped values across API boundaries and between processes.
The first function (WithValues) checks if a the key is a valid key. This is a nice to have if you want to keep consistency over logs. Otherwise typos or other keys constructed with different names are common. The function that allows you to create a new logger is called NewLoggerFromContext. This functions allows you to get a context and translate that context to a set of key value pair into the logger using the withValues function from the logger package.
Using this approach you achieve separation of concerns, since the logger will use what is in the context. Another indirect benefit of this approach is that most of the times a context is already needed. So instead of injecting a logger and a context you can use only the context.
