An Ultimate Guide for Structured Logging in Go with Slog

Whether you're already using structured logging or you're new to it, this guide will go over the concepts for everyone.

Good news! Go 1.21 introduced the slog package, the official take on structured logging. Before slog came out, developers might have come across several libraries, such as zerolog, zap, and logrus. Each one had its own way of dealing with logging.

So, what exactly is structured logging and how to implement structured logging with Golang Slog? Let's explore here!

>> Read more about Golang coding:

• Building A Powerful Golang HTTP Client With net/http
• What Are New Features in Golang sync.Once?
• Understanding Golang Ordered Map with Code Examples
• Instruction For Using Golang Generics With Code Examples

What is Structured Logging in Go?

Structured logging is about organizing your log data in a way that systems can easily read, like in JSON format or as key-value pairs. This isn’t just for show, it’s really practical since it lets you sift through and make sense of your logs with much less hassle.

Take a look at this structured log:

{
  "level": "info",
  "message": "User signed in",
  "user_id": 123,
  "ip": "14.241.254.36"
}

I get it, this might not look the most interesting at first look. But trust me, this is far more effective than traditional text logs for finding specific information. If you want to find out everything a specific user did, you can do a search similar to this one:

# query all logs with level info and user_id 123
level:info AND user_id:123

# query all error happened with user_id 123 in the last 24 hours
level:error AND user_id:123 timestamp:[now-24h TO now]

The exact way you run these queries can vary depending on the logging system you're using, but the main point is, most systems can work with structured logs to help you filter and search efficiently.

In this story, we'll discuss how to use the slog package to create structured logs in Go language in a simple and efficient way. This should be a comprehensive guide to cover all the aspects of slog package (I hope).

How to Use Golang Slog?

This is going to be a quick demo to give you a taste of how slog works, and we'll get into the details shortly.

First things first, we'll need to make sure our Go is updated to version 1.21 or later, let's get our hands dirty and start with an easy example:

package main

import (
	"log/slog"
)

func main() {
	slog.Info("This is a test message", "user_id", 123, "user_name", "John Doe")
}

And there you have it, we just logged a message that's neatly structured:

2024/03/27 19:51:24 INFO This is a test message user_id=123 user_name="John Doe"

slog.Info is the function that logs a message with:

• An "Info" level, which is used for general informational messages.
• The "This is a test message" part is the primary message we're logging,
• The pieces like ("user_id", 123) and ("user_name", "John Doe") are specific details we're recording alongside the main message.

We should notice the timestamp 2024/03/27 19:51:24 in the log, that's automatically included to timestamp the event, which is super useful for tracking when something happened.

"Interesting, but why doesn't it match the format we discussed earlier?”

The format you're seeing is what comes standard with the slog package and it's designed to be easy to read. If you prefer, we can switch it to JSON or a different format that suits your needs.

"So, if we stick with this format, are we still able to search and filter the logs as before?”

Yes, you can. While it's not in JSON, which is commonly used for its structured data, many logging systems are quite capable of interpreting various formats and can extract the necessary information for searching and filtering.

Let’s talk about the 4 key concepts in the slog package:

1. Logger: The Logger is the component you interact with when you write log statements in your code. It's responsible for assembling your messages and sending them to the handlers.
2. Handler: The Handler is the component that takes log messages from the logger and writes them to whatever destination you've configured, such as a console, file, or logging service.
3. Fields (or Records): These are the additional contextual information you attach to your log messages, formatted as key-value pairs. They help to provide more detail and make your logs easier to understand and query.
4. Level: The log level indicates the severity or importance of the log message, common levels are debug, info, warn, error.

Logging Levels

In the log/slog package that we work with, we'll find 4 main levels of logging: DEBUG, INFO, WARN, and ERROR. Each of these levels is associated with a specific number.

If we peek into the source code, we can see how these are defined:

const (
	LevelDebug Level = -4
	LevelInfo  Level = 0
	LevelWarn  Level = 4
	LevelError Level = 8
)

Now, these numbers aren't just randomly chosen, they're spaced out deliberately.

This spacing is really practical because it gives us the flexibility to add new levels in between the existing ones if we need to, without having to rearrange everything we've already set up:

• DEBUG (-4): DEBUG is the least severe level, it's meant for detailed and potentially verbose information that can help developers during the debugging process.
• INFO (0): This is default level. It's used for routine messages that confirm the program is functioning correctly and useful for tracking the flow of the application.
• WARN (4): WARN indicates a level of logging more serious than INFO but not as critical as ERROR. It's not an error, but it could be a potential problem or a sign that you might need to take a closer look at something
• ERROR (8): Use it to log when bad things happen, such as an exception being thrown that might affect the program's operation and require immediate attention.

The message with different loggings is unchanged, but the level is different:

slog.Debug("withdraw function called")
slog.Info("withdraw successful")
slog.Warn("withdraw failed")
slog.Error("withdraw failed: database shutdown")

When we look at what the log produces, it would look something like this:

2024/03/27 20:21:48 INFO withdraw successful
2024/03/27 20:21:48 WARN withdraw failed: the system is running out of memory
2024/03/27 20:21:48 ERROR withdraw failed: database shutdown

One thing to point out here is the missing DEBUG message in the output. This happens because the standard log level is set to INFO, which means that any level below INFO (0), like DEBUG (-4), isn't going to show up in our log.

Now, if we want those DEBUG messages to appear, we simply need to change the default log level setting. We can do that with a function like slog.SetLogLoggerLevel(slog.LevelDebug).

When we set the level to DEBUG, what happens is that all the messages, from DEBUG and upwards, will be visible:

func main() {
    slog.SetLogLoggerLevel(slog.LevelDebug)

    slog.Debug("Debug message") // Now this will show up
    slog.Info("Info message")
    slog.Warn("Warning message")
    slog.Error("Error message")
}

This should fix our issue, but we should configure the log level according to the environment. For example, a production environment might not need DEBUG messages, but a development or testing environment might.

Data Fields

The slog package uses fields to log structured data. Fields or records are key-value pairs that you can attach to a log message, so when we look at the message, we have more information than just the message itself.

The power of fields really shines when we switch our log output to a format like JSON. We don't need to dive into the details of handlers or loggers just yet, that's something we'll cover in the next section.

For now, think of it as a tool that helps us log information:

func main() {
    handler := slog.NewJSONHandler(os.Stdout, nil)
    logger := slog.New(handler)

    logger.Info("This is a test message", "user_id", 123, "user_name", "John Doe")
}

Here, we've set up a new logger with a JSON handler, which formats our log messages as JSON objects. And the result is a neatly formatted JSON object:

{
  "level": "info",
  "message": "This is a test message",
  "user_id": 123,
  "user_name": "John Doe"
}

// Before
// 2024/03/27 19:51:24 INFO This is a test message user_id=123 user_name="John Doe"

There are a couple of strategies for how we can include these key-value pairs in our logs, which we refer to as implicit and explicit.

The implicit way is pretty straightforward: We just list out our keys and values right after our message, pair by pair:

logger.Info("This is a test message", "user_id", 123, "user_name", "John Doe")

Then there's the explicit way, where we use certain functions that the slog package provides to create what we call Attr objects for each key-value pair:

logger.Info("This is a test message", slog.Int("user_id", 123), slog.String("user_name", "John Doe"))

We can also go with a mixed solution, combining both implicit and explicit in the same log statement:

logger.Info("This is a test message", "user_id", 123, slog.String("user_name", "John Doe"))

Helpers like slog.Int and slog.String are there to help us create an slog.Attr object, which represents a key-value pair. Creating this Attr is simply a way to get our data ready for logging.

So, which one to use?

Error-prone and Performance

The first method is pretty simple but it can be less efficient and easier to make mistakes this way.

For instance, if you leave out a value after a key, the slog package isn't going to know what you intended to put there.Here’s what happens if you forget a value:

logger.Info("This is a test message", "user_id", 123, "user_name")

// Output:
{"time":"2024-03-31T18:55:10.778394+07:00","level":"INFO","msg":"This is a test message","user_id":123,"!BADKEY":"user_name"}

In this case, slog assumes "user_name" is the value that's missing its key, and so it flags the issue with a "!BADKEY" label.

On the other hand, when you use the second method (slog.Int, slog.String, etc) we're explicitly creating slog.Attr objects, so they help to eliminate the risk of ending up with mismatched key-value pairs and reduce the risk of errors.

"How about the performance?”

The implicit method can be less efficient and lead to memory use issues. But when we explicit solution, slog.String, for example, it forms an Attr which has a Key and a Value:

type Attr struct {
	Key   string
	Value Value
}

The Value type in slog is designed for efficiency, it can hold different Go values, similar to interface{}, but optimized for common types like integers and strings to avoid extra memory allocations.

The slog package has support for a range of Attr types, including Int, Int64, Float64, String, Time, Duration, and even an Any type for when you need it.

Now, for the best possible performance, slog has the slog.LogAttrs function which is designed to keep memory allocations as low as possible:

slog.LogAttrs(
    context.Background(), slog.LevelInfo,
    slog.Int("user_id", 123),
    slog.String("user_name", "John Doe"),
)

This solution is definitely focused on performance, but it's more verbose, you need to spell out the logging context, log level.

Grouping Records

As the complexity of logging increases and we're adding numerous fields, the slog.Group function can be incredibly useful.

It lets us gather related fields under a single key and we just pick a name for our group, then stack the attributes that fit within that group:

logger.Info("a test message", 
    slog.Group("user",
        slog.Int("user_id", 123),
        slog.String("user_name", "John Doe"),
    ),
    slog.Group("account",
        "money", 1000000,
        slog.String("type", "premium"),
    ),
)

Now, our log output becomes a neatly structured JSON object, the groups "user" and "account" are represented as keys, with the related fields neatly tucked inside as values:

{
  "time":"2024-03-31T20:25:15.723681+07:00",
  "level": "info",
  "msg": "a test message",
  "user": {
    "user_id": 123,
    "user_name": "John Doe"
  },
  "account": {
    "money": 1000000,
    "type": "premium"
  }
}

If you look at the second group, you can see that we've combined implicit and explicit fields: For the "account" group, the "money" field is inputted implicitly, while the "type" field is included explicitly with the help of slog.String.

(This mixed way in the example is really just to demonstrate what's possible, but for clarity and consistency, sticking to one style is generally the better practice.)

LogValuer Interface

So let's talk about what happens when you put a struct into the log:

user := User {
  ID: 123,
  Name: "John Doe",
  Password: "123456"
}

logger.Info("checkout", "user", user)

Now, check out the log output and we'll notice the "user" key is always there, and the user's details are represented by the field name:

{
    "time": "2024-03-31T21:03:36.536996+07:00",
    "level": "INFO",
    "msg": "checkout",
    "user":{
        "ID":123,
        "Name": "John Doe",
        "Password": "123456"
    }
}

But here's the thing: when all the fields are logged like this, it could accidentally show stuff we want to keep private, like passwords or other personal info. Also, it can make the log really messy with too much info.

If we want to log things in a special way, we use what's called the LogValuer interface from the slog package. If a type implements this interface, you can decide exactly how it gets logged:

type LogValuer interface {
	LogValue() Value
}

Next, we're going to fix up our User struct by taking out the Name field and hiding the Password field:

func (u User) LogValue() slog.Value {
	return slog.GroupValue(
		slog.Int("id", u.ID),
        slog.String("password", "******"),
	)
}

logger.Info("checkout", "user", User{ID: 123, Name: "John Doe", Password: "123456"})

You may notice that instead of slog.Group like previous grouping section, we use slog.GroupValue which is required Attr instead of implicit key-value pairs.

Now the output is more secure and concise:

{
  "time": "2024-03-31T21:11:11+07:00",
  "level": "INFO",
  "msg": "checkout",
  "user": {
    "id": 123,
    "password": "******"
  }
}

So, by utilizing the LogValuer interface, we get a lot more say in what info shows up in our logs.

Binding Records to Logger

If you're logging the same thing over and over, there's a smart way to make things more efficient.

Let's say you've got a "user_id" that shows up multiple times like this:

logger.Info("checkout", "user_id", 123, "checkout_from", "Brazil")

logger.Info("confirm checkout", "user_id", 123, "money", 1000000)

logger.Info("receive checkout", "user_id", 123)

Instead of typing out "user_id" and its value every single time, you can attach them to your logger once. After you do that, they'll show up automatically in every log message this logger sends out.

Here's how you set it up using slog.With to create a new logger that remembers certain details:

logger = logger.With("user_id", 123)

logger.Info("checkout", "checkout_from", "Brazil")
logger.Info("confirm checkout", "money", 1000000)
logger.Info("receive checkout")

Your log output will look just like it did before, but now it's cleaner and easier to work with.

This logger.With() grabs the pieces of information you want to keep reusing and gives you back a new logger that includes them. So any time you make a log with this new logger, the "user_id" will be there, without you having to add it every time.

It's now time to learn more about Loggers and Handlers.

Logger and Handler

Let's take a step back and look at the bigger picture, we've got these three main parts: Logger, Handler, and Fields.

• The Logger is the frontend of the logging system. It's what you interact with when you're logging messages.
• The Handler is the backend which is responsible for taking those messages and doing something with them, like writing them to a file or sending them to a server.

We've been using the Logger in our examples so far, but we might not have realized it. Whenever we call slog.Info, we're using the default Logger that's provided by the package:

func Info(msg string, args ...any) {
	Default().log(context.Background(), LevelInfo, msg, args...)
}

The Default() function gives us the default Logger, which has a default Handler hooked up to it. But you can create a new Logger with a different Handler if you need to.

func main() {
    handler := slog.NewTextHandler(os.Stdout, nil)
    logger := slog.New(handler)
    logger.Info("This is a test message", "user_id", 123, "user_name", "John Doe")
}

In this case, we're creating a new Logger and choosing a TextHandler that will output our logs to the standard output, os.Stdout.

The results you get will look the same as they did when using the default setup.

"But why do we need to create a new logger? The default logger is good enough”

Sometimes we need to customize, maybe we want to add a new XML handler, or redact all fields that contain the key "password." Also, we've seen how we can customize the log level in a handler from INFO to DEBUG, right?

The slog package gives us two really strong built-in handlers to work with.

Built-in Handlers

We've got two types of built-in handlers that handle your logs in different ways:

• TextHandler: This handler writes logs in a human-readable format.
• JSONHandler: This handler writes logs in JSON format.

Here's how you can use the JSON handler, which we already did in the previous section:

func main() {
    handler := slog.NewJSONHandler(os.Stdout, nil)
    logger := slog.New(handler)
    logger.Info("This is a test message", "user_id", 123, "user_name", "John Doe")
}

This will give you a log in JSON format:

{
  "level": "info",
  "message": "This is a test message",
  "user_id": 123,
  "user_name": "John Doe"
}

Even with these built-in handlers, you still get a lot of room to make changes, with 3 settings you can adjust:

type HandlerOptions struct {
  AddSource   bool
  Level       Leveler
  ReplaceAttr func(groups []string, a Attr) Attr
}

• AddSource: This setting lets the handler add details about where in your code the log was created.
• Level: This controls which levels of messages the handler will pay attention to. For instance, setting it to INFO means it will ignore the DEBUG messages.
• ReplaceAttr: This gives you control over the data in your logs. You can use it to hide private information by swapping out real data for something like "***"

Let's give the AddSource option a go:

opts := &slog.HandlerOptions{
    AddSource: true,
}
logger := slog.New(slog.NewJSONHandler(os.Stdout, opts))
logger.Info("This is a test message", "user_id", 123, "user_name", "John Doe")

Now, the output you get will be all on one line, but I've made it easier to read here by spreading it out:

{
  "time": "2024-03-29T21:51:53.920183+07:00",
  "level": "INFO",
  "source": {
    "function": "main.main",
    "file": "/Users/phuong/articles/slog/main.go",
    "line": 13
  },
  "msg": "This is a test message",
  "user_id": 123,
  "user_name": "John Doe"
}

Our log now includes the source field, it's not just a simple string but it's an object with three fields: function, file, and line. This detail can be really helpful when you need to quickly figure out where a message or an issue is coming from in your code.

"But every time I use a custom logger, do I have to create it or pass it around?”

We don't have to keep making new loggers or pass them around every time.

There's a way to avoid that, by setting a global logger right in the slog package, we don't need to create our own package just for that:

func main() {
    handler := slog.NewJSONHandler(os.Stdout, nil)
    logger := slog.New(handler)

    slog.SetDefault(logger)

    slog.Info("This is a test message", "user_id", 123, "user_name", "John Doe")
}

Once you set the default logger, you can use slog.Info straight away without having to create a new logger every time. But there's something interesting here, the change also impacts the standard log package:

log.Println("This is a test message")

// Output: {"time":"2024-03-31T10:06:10.945147+07:00","level":"INFO","msg":"This is a test message"}

This happens because we usually want just one format for logging in our application to keep things clean and consistent.

But there's a small detail to pay attention to, when you use log.Println, it doesn't work with slog.LogValuer, which we talked about earlier.

Understand the Handler

The two built-in handlers we've talked about are usually all you need. But if you ever want to make your own handler to work with the slog logger, this section is what you need to know.

Now, if you're already using zap, which is a well-known logging tool made by Uber, there's a way to connect its logging system with slog (it's an experimental feature).

If you want to give this a try, we'll need to install a couple of packages first:

go get go.uber.org/zap
go get go.uber.org/zap/exp/zapslog

And this is how we inject the zap backend into the slog logger:

func main() {
	zLogger, _ := zap.NewProduction()
	defer zLogger.Sync()
	logger := slog.New(zapslog.NewHandler(zLogger.Core(), nil))

	logger.Info("This is a test message", "user_id", 123, "user_name", "John Doe")
}

zapslog.NewHandler is a function that takes the core of the zap logger and turns it into a handler that slog can use. This way, you can write your logs with slog, and zap will take care of them behind the scenes.

The slog package is really flexible, and that's a big part of its strength. Because there are so many structured logging packages out there, slog can act like a bridge between the standard lib and other packages.

Let's go through the Handler interface piece by piece:

type Handler interface {
	Enabled(context.Context, Level) bool
	Handle(context.Context, Record) error
	WithAttrs(attrs []Attr) Handler
	WithGroup(name string) Handler
}

Here is the explanation of each part:

• Enabled: This is a function that decides if a log should be printed out. It checks the message's log level, like Info, Debug, Error, and it might look at the context that you provide.
• Handle: After a log record passes the Enabled check, the Handle function is what actually takes care of the log. This is where the log gets its format, where it's sent to (like a file, the screen, or over a network), or when it's given to another system.
• WithAttrs: This function gives you a new handler that's pretty much the same as the original, but with some extra details added. It's like the logger.With function we looked at before.
• WithGroup: This lets you group related log details under one name, as we already discussed in the previous section.

Making your own log handler is a bit of a complex job, but you can learn a lot from checking out the code for the JSON and Text handlers that come with slog.

By looking at these, you'll see how a handler should work and deal with logs. When you're building your own handler, you'll have to decide how you want to format logs, where they should go, and what to do if something goes wrong while logging.

>> You may consider about SOLID principles in Golang:

• Practical SOLID in Golang: Single Responsibility Principle
• Mastering the Open/Closed Principle in Golang
• Mastering the Liskov Substitution Principle in Golang
• Mastering The Interface Segregation Principle in Golang
• Best Practices For Dependency Inversion in Golang

Conclusion

In a nutshell, Golang's slog package brings structured logging to the standard library. It lets you ditch the cryptic text logs and move to a more readable format, like JSON or key-value pairs. This makes searching and filtering your logs a breeze. Slog offers a powerful and flexible API, with features like log levels, custom fields, and grouping. So, if you're looking to upgrade your logging game in Go, slog is definitely worth checking out!