Structured logging is vital for all production deployments. It’s one of the few windows of insight you have into an app that isn’t running on your local machine. But what makes structured logging different from a call to log.Println()
, and why does it matter?
Structured logs conform to a uniform format or share a specific structure, usually consisting of a collection of key-value pairs. The opposite of structured logging is free-form logging, with no consistent layout imposed on the log statements. Here’s an example:
// free form
"Error while running function"
// structured log
"message: 'Error while running function' level:'ERROR' time: '2023-09-17:09:52'"
So why do you need structured logs? Programs find it easier to process structured logs than free-form logs, which is a crucial advantage when you have many statements to comb through while looking for the reason for an error because it lets you perform operations like filtering and searching.
In this article, you’ll learn how to add structured logging to your applications with the slog
package, which was added to the standard library in Go 1.21. To follow along, you’ll need:
- Go 1.21 or later installed on your machine
- A working knowledge of Go
That’s it!
The basics of slog
To begin with slog, you only need to understand three concepts: loggers, records, and handlers. Let’s start with loggers. The logger
type is the front end of slog. It's the type that owns the methods you call when you want to log something. When you call one of those methods, the logger
creates an instance of another type called a record
, whose only job is to store the necessary information to create a log.
Finally, the logger
passes the record
to an instance of the handler
type. The handler
type is an interface, and it’s slog’s “backend”. The code that’s responsible for actually creating the log (writing it to stdout
, for example) lives in the handler
.
To recap, here’s a diagram illustrating the relationship between logger
s, record
s, and handler
s:
Let’s look at some code. Assume you’re calling a function that returns an error, and if the error isn’t nil
, you want to log it:
err := doSomething()
if err != nil {
// log the error
}
First, you need a logger
. Slog
provides a default logger that you can use by calling one of these top-level methods:
slog.Debug()
slog.Info()
slog.Warn()
slog.Error()
These methods all have the same function signature and produce the same output: a log statement whose severity matches the method's name. The Debug
method has the lowest severity, and the Error
method has the highest. Take a look at the signature of slog.Error()
:
func Error(msg string, args ...any) {
}
It takes a string as its first argument and then an arbitrary list of key-value pairs. The keys must be strings, but the values can be any type. Calling Error()
usually looks like this:
err := doSomething()
if err != nil {
// log the error
slog.Error("doSomething returned an error", "error", err)
}
Here, "error"
and err
form the key-value pair. This code would produce output like this:
2023/09/30 17:41:57 ERROR doSomething returned an error error="random error"
The timestamp was generated automatically by the default logger and is a part of every log record. What happens if you omit the key in the key-value pairs? This code:
slog.Error("doSomething returned an error", err, 5)
Generates this output:
2023/09/30 17:51:32 ERROR doSomething returned an error !BADKEY="random error" !BADKEY=5
Slog
will still output the log in a structured, key-value format, but it will prefix all values without a key with a key called !BADKEY
, so you must be careful you don’t omit any keys from your key-value pairs.
Slog also offers a more rigid way to create a log that removes the possibility of a !BADKEY
error: the Attr
type. A value of type Attr
represents a single key-value pair, and slog offers you several convenient methods to create an Attr
. There’s a method for each basic data type in Go, as well as a slog.Any
method that will allow you to use a value of any type to create an Attr
. To put this into context, this means that we can replace this method call:
slog.Error("doSomething returned an error", "error", err, 5)
with an Attr
version:
slog.Error("doSomething returned an error", slog.String("error", err), slog.Int("id", 5)
The convenience method you should use depends on the type of the value on the key-value pair you want to turn into an Attr
. If you stick to Attr
s instead of the alternating value style, you’re less likely to omit a key from your log statement. Ultimately, the top-level methods place no restrictions on you - you’re free to use alternating keys and values, Attr
s, or to mix both, so it’s up to you to be careful with your log statements.
So far, we’ve focused on the default logger, but if want more control over the output format, you need a create a custom logger. Slog
provides the slog.New
function for this. slog.New
takes a value that satisfies the handler
interface and returns a logger
that uses the handler you provided to it. Slog provides two types of handlers for you: a text handler and a JSON handler. You can create new loggers like this:
textLogger := slog.New(slog.NewTextHandler(os.Stdout, nil))
// or
jsonLogger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
The NewTextHandler
and NewJSONHandler
methods take an io.Writer
and a configuration struct as arguments, and return values that satisfy the handler
interface. These loggers have the same methods as the default logger, but because they use different handlers, the output they produce is different. Both loggers produce structured, key-value output, but the specific format is different. textLogger
will produce a string of regular text, but jsonLogger
will produce JSON output. Here’s an example. This code:
textLogger.Error("an error occurred", "error", err)
jsonLogger.Error("an error occurred", "error", err)
Produces this output:
// text handler output
time=2023-10-02T08:12:43.634+01:00 level=ERROR msg="doSomething returned an error" error="random error"
// JSON handler output
{"time":"2023-10-02T08:12:43.634180321+01:00","level":"ERROR","msg":"doSomething returned an error","error":"random error"}
Slog allows you to replace the default package logger with a custom logger. Calling slog.SetDefault(jsonLogger)
, for example, will cause the top-level methods like slog.Info()
to use the jsonLogger
instead of the default logger.
Customizing loggers
Slog gives you some options to change the behavior of your loggers. For example, if you have a key-value pair you want to include in all your logs like a user ID, you can use logger.With()
to create a new logger that will always include that pair in your log messages. Here’s an example:
authLogger := jsonLogger.With("userId", 1)
authLogger.Error("user action failed", "error", err)
authLogger.Info("user logged in!")
And here’s the output:
{"time":"2023-10-02T11:04:40.852885792+01:00","level":"ERROR","msg":"user action failed","userId":1,"error":"random error"}
{"time":"2023-10-02T11:04:40.852935987+01:00","level":"INFO","msg":"user logged in!","userId":1}
Note how both logs contain the userId:1
pair, even though it wasn’t added to the calls to either Error
or Info
.
Slog allows you to group key-value pairs using the slog.Group
function. This lets you create one value that represents multiple key-value pairs so you can save space when you want to use the group of pairs. To create a group, you need to pass a group name and one or more key-value pairs to slog.Group
. Here’s an example:
userInfo := slog.Group("user-info",
"id", 5,
"ip-address", "180.80.80.5")
This code creates a group named user-info
, with the pairs id:5, ip-address: "180.80.80.5"
. You can then use the group like this:
jsonLogger.Error("user action failed", userInfo, "error", err)
To get this result:
{"time":"2023-10-02T11:41:31.521075924+01:00","level":"ERROR","msg":"user action failed","user-info":{"id":5,"ip-address":"180.80.80.5"},"error":"random error"}
You can also pass a group as an argument to logger.With
:
authLogger := jsonLogger.With(userInfo)
authLogger.Error("user action failed", "error", err)
To get this result:
{"time":"2023-10-02T11:48:10.436603233+01:00","level":"ERROR","msg":"user action failed","user-info":{"id":5,"ip-address":"180.80.80.5"},"error":"random error"}
Finally, you can use the logger.WithGroup()
method to prefix all key-value pairs the logger will output with a group name. This is useful in cases where other parts of your codebase might create log statements that have the same keys as the ones you’re using. The prefix allows you to identify which part of the code produced a particular log statement, even when the code uses the same keys. Here’s how it works. This code:
authLogger := jsonLogger.WithGroup("auth")
authLogger.Error("user action failed", "error", err)
Produces this output:
{"time":"2023-10-02T14:42:41.186099512+01:00","level":"ERROR","msg":"user action failed","auth":{"error":"random error"}}
Customizing handlers
Another way to control the output of your log statements is by customizing your handlers. With the handlers slog gives you, that’s done by passing them a HandlerOptions
struct. This is the type definition of HandlerOptions
:
type HandlerOptions struct {
AddSource bool
Level Leveler
ReplaceAttr func(groups []string, a Attr) Attr
}
A HandlerOptions
where AddSource
is true will make the log include a source
key whose value is the filename, function, and line number from which the log originated. Here’s an example:
jsonLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{AddSource: true}))
jsonLogger.Error("doSomething returned an error", "error", err)
And the output:
{"time":"2023-10-02T15:04:59.905411319+01:00","level":"ERROR","source":{"function":"main.main","file":"/home/Documents/dev/slog-sandbox/main.go","line":21},"msg":"doSomething returned an error","error":"random error"}
A note on enabling AddSource: If you have AddSource
enabled and you wrap your log statement in another function, it will cause the location reported by AddSource
to be off. Here’s an example:
package main
import (
"errors"
"log/slog"
"os"
)
var logger *slog.Logger
var err error
func wrapper(msg string, err error) {
logger.Error(msg, err)
}
func main() {
logger = slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{AddSource: true}))
err = errors.New("random error")
wrapper("an error occurred", err)
}
This code returns this output:
{"time":"2023-10-02T17:41:40.031790944+01:00","level":"ERROR","source":{"function":"main.wrapper","file":"/home/Documents/dev/slog-sandbox/main.go","line":13},"msg":"an error occurred","error":"random error"}
And you can see the location of the log is reported as inside wrapper
when we want the location where wrapper
was called inside main
. So what’s the fix? You have to create a record yourself with the correct source information using the runtime
package. The documentation provides an example of such a function.
The Level
field governs the minimum severity of the logs the Handler will accept. Any log statements with a severity less than the Level
field will be ignored by the handler and not logged. But what’s up with the Leveler
type? Leveler
is an interface with this definition:
type Leveler interface {
Level() Level
}
And this is the definition of type level:
type Level int
The higher the value of the Level
, the more severe it is. The Level
field is a Leveler
type to allow you to provide a value that can change the Level
it returns - you can read about that in the docs, but if you don’t need that, the Level
type also satisfies the Leveler
interface, so you can pass a static Level
instead. Like so:
jsonLogger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{AddSource: true, Level: slog.Level(4)}))
These are the values for slog’s levels:
const (
LevelDebug Level = -4
LevelInfo Level = 0
LevelWarn Level = 4
LevelError Level = 8
)
Which means that jsonLogger
will now log only Warn
and Error
statements, and ignore Info
and Debug
. Here's a demonstration:
jsonLogger.Debug("doSomething returned an error", "error", err)
jsonLogger.Info("doSomething returned an error", "error", err)
jsonLogger.Warn("doSomething returned an error", "error", err)
jsonLogger.Error("doSomething returned an error", "error", err)
Will output:
{"time":"2023-10-02T17:21:58.740882837+01:00","level":"WARN","source":{"function":"main.main","file":"/home/Documents/dev/slog-sandbox/main.go","line":23},"msg":"doSomething returned an error","error":"random error"}
{"time":"2023-10-02T17:21:58.740946987+01:00","level":"ERROR","source":{"function":"main.main","file":"/home/Documents/dev/slog-sandbox/main.go","line":24},"msg":"doSomething returned an error","error":"random error"}
We won’t delve into the ReplaceAttr
function, but its purpose is to allow you to transform both the keys and values of every key-value pair. You can use ReplaceAttr
to remove key-value pairs, change the key names, or modify the value in any way you desire.
Optimizing for performance
If you do a quick Google search, you’ll see the primary culprit for performance issues when logging in Golang is something called allocation. Allocation is the process of reserving computer memory for your program’s use. That memory can be reserved from the stack or the heap. Allocating memory on the stack is straightforward, but allocating memory on the heap is much more complicated, and thus consumes more computational power and time.
So when people say allocations are making a server slower, they mean that executing some log statements is forcing the program to do a lot of heap allocation, and thus slowing it down. Now that you understand what allocation is and why it’s bad for performance, how can you minimize allocations while using slog?
The first thing you should do is use Attrs
in all your log statements. Creating an Attr
allows your log statement to avoid an allocation when executing for that key-value pair. Taking it one step further, slog provides the Logger.LogAttrs()
method. The fact that it accepts only Attrs
means that it can avoid allocations even further. According to the documentation,
The call
logger.LogAttrs(ctx, slog.LevelInfo, "hello", slog.Int("count", 3))
is the most efficient way to achieve the same output asslog.Info("hello", "count", 3)
logAttrs
requires a context as its first argument, which is a value that contains information about the code’s environment that can be passed between functions. Its other arguments are a Level
for the log statement, a string, and then an arbitrarily long list of Attrs
. You can find a list of other performance considerations in the documentation.
Extending slog
Because slog is split into a front end and a back end, it’s possible to further customize slog while keeping its interface the same, by changing the back end. While slog only provides two built-in handlers, because handler
is an interface, you can write a custom implementation to have complete control over the output.
A guide covering how to write custom handlers is out of scope for this post, but you can find one such guide written by the author of slog here. Thankfully, you don’t need to write a handler from scratch to use one. There are several community-contributed handlers, including handlers that allow you to output colored logs, and a handler that lets you implement sampling. You can find a full list here.
Context in slog
Sometimes, handler
s may need access to the context
of the function where the log statement was called, so slog provides methods that allow you to pass that context as part of the log statement.
The Logger.LogAttr()
method takes a context as the first parameter, and all the log statements have alternate versions that let you provide a context. That means that there’s a logger.{Level}Context
method for each of slog’s built-in severity levels.
Slog vs Zap vs ZeroLog
To help you decide whether you’d want to use slog in your next project, here’s a table comparing slog to some of the most popular alternatives for structured logging.
Slog (with built-in handlers) | Zap | ZeroLog | |
---|---|---|---|
Community and Support | Part of Go’s stdlib | Owned by Uber | No org. backing it |
Performance | Slower than Zap | Slower than ZeroLog | Fatest |
Extensibility | Most extensible | Decently extensible | Least extensible |
Output Format | Plain text or JSON | JSON | JSON or CBOR only |
You can find benchmarks for slog, zap, and zeroLog here.
Conclusion
Structured logging is a feature all production applications should have, to provide the developer as much insight into the running of the application as possible. Slog is a new addition to the Golang standard library that provides convenient, efficient, and easily extensible structured logging.
Slog can meet the most common use cases for structured logging with its built-in handlers, but if you need more control or have a niche requirement, it allows you to use third-party handlers, or write your own. I hope you enjoyed the article, and happy coding!
Top comments (0)