Logging for Production

Now we know how to use logs to debug locally let's talk a little bit more about how to instrument our Go apps for production debugging. Today we're going to talk about structured logging and particularly we're going to talk about a package called slog or slog and we're going to talk about log levels a little bit too.

So firstly let's talk a little bit about structured logging. The easiest way to understand what it is is to see an example. So I've got some really basic code here that I'm going to run. From the output here you can see the difference between the two different logs. The first one I've used the format.println that we talked about previously and the second example I've constructed a logger using this slog package and I've used logger.info.

We'll talk about that a little bit more shortly but from the output you can see that the structured log has a bunch of key value pairs which has in this instance a time, a log level, message and then some meta information that I added. So effectively we'll just logging as JSON.

What may be interesting to you to find out is that structured logging was only very recently added to the Go language and previously we had to either use third-party libraries or depend on the original log package or the format.println function. And the easiest way to understand why it's added is actually to go to the Go GitHub and look at the issue that was opened in the discussion that was had that led to structured logging being introduced.

So in theory, one can produce structured logs with any logging package. And here's an example using the initial log. In practice, this is tedious and error-prone. So structured logging package provides an API for expressing key-value pairs. This draft proposal contains such an API. So effectively, the whole goal of the slog package was just to make it easier to do what was already possible. And I would say generally that's the goal of structured logging.

The advantages of structured logging firstly if we go back to the example here you can see that it's in JSON format and what that means is it's easier to parse and easy to query we'll see some examples of that shortly logs have a consistent format this is really important for ingesting it into other systems so that we can do analysis on it you can add richer texts so in the example here I've made a meta info tag but you can also add different key value pairs which we'll see in a second and the additional context can help you debugging. As you can see we get a lot more information inside this one than we did in the previous one so this is particularly helpful for debugging.

Structured logging could probably be an entire course in itself so we're not going to go into detail of every single function that the slog package provides or go into some of the more advanced patterns but what we are going to cover off is the basics and talk about log levels a bit too.

So I'm going to start by just quickly showing the slog.log documentation over on go.dev and you can see that it has these attribute functions slog.any, bool, duration, flow, group, int string, etc. What this means in reality is if I look at this basic log that we already wrote, hello world and meta information, maybe I want to add some extra information here that we can add to our log.

So let's do that now. So I'm going to add slog.int and maybe it's an account id and I'm going to just make up number to put in here. If we run that again, we'll see that now we've got an account ID in our structured logs. This is really powerful. And what we could probably do is make sure we attach this to all of our logs as we pass it through our API handlers or something like that.

You can also do things like add errors to it. So I think the slog package doesn't actually provide a slog.error but it does supply the slog.any. So let's try and use that one. So if I should Errors.new, just click some error and I can do slog.anyError and then I can pass the error in here too and let's log that again and you can see that it can accept errors as well in here.

So far you may have noticed that I've used logger.info and also inside my level it says info. So what does that mean? So slog and generally other packages include things called log levels. Log levels are a means to make it easy for you to distinguish between important errors. Log levels can be useful as they allow you to instrument your code with some extra meta information and ease log management.

So here's how to make logs different levels in Go. So I'm literally just going to copy this this and I'm just going to do logger.error and if I run this and you can see now the log level has changed and not much else has changed for us which might seem strange.

The reason we use different log levels is for log management. So let's imagine an application that has tens of thousands of requests every second, and we're logging every single request ID with some meta information about the user. It might be overwhelming for our system to send all of those logs to our logging infrastructure, and it also might make it harder to debug because we get information overload.

So what we might want to do is set our application by default to only log error logs, and then we have the ability to turn on info or debug logs when we're trying to debug a specific issue we need to capture some extra information and this is actually what I would recommend doing I would recommend having two log levels whenever you are working with an application you have info or debug and then you have error and then what we can do inside of our code is we can actually set a log level.

The second argument to this function here is actually a set of options so what we can do here is we can set a log level and we go and slog.level like this we build some options and slog.anlerOptions so that level to be log level. So this is exactly what we saw before, so it's logging info and it's logging error. But what we can also do is we can update this to be a different log level. So we can do dot slog dot level error.

If I run this again, you'll notice that we don't actually get the first log anymore. So this is really powerful. We've set our log level to be set to error, but what we might also want to do is we could potentially read in from an environment variable and switch on this and the case where this is debug we could then do log level equals log dot level info.

You may want to add more case statements if you want to have more log levels, even though my suggestion is to only have two. And what this means is that if we did set this environment variable to be something else, we'd be able to increase our log level and we would get this info line. This is really powerful to be able to switch on and off logs without having to keep adding them and removing them from your production applications. So I see this pattern a lot.

So so far we've seen various log levels enabled and we've had a bit of a messy console output. But we haven't seen the biggest benefit yet, which is where we're going to take all these logs and put them into some other tool. We're going to ingest them into another tool where we can visualize it. So let's have a look at how we could do that.