Structured Logging with slog in Go

Table of Contents

Introduction

When debugging our applications, having information about its status is very important. One way to achieve this is through the use of logs, which allow us to store information related to a request or event in our system.

In article, we will learn how to use the slog package from the Go standard library, which was previously an experimental package but will be officially available in the upcoming version 1.21.

No time to read this post? no problem, here is the link to the repository 🧑🏽‍💻.

What is structured logging?

Let’s start by defining what structured logging is. It refers to the process of generating logs in a well-defined format (typically JSON) that adds a level of organization and consistency, making them easier to process and analyze.

These logs usually have a key/value format (typical of JSON objects) that captures relevant contextual information about the event being logged, information such as:

• Severity level (INFO, ERROR, WARNING)
• Timestamp
• User ID
• Request ID
• Any other relevant information

What options/packages do we currently have?

• Zap
• Logrus
• Zero log
• Go’s native log
• A ton of other options

log package

Before we learn how to use the slog package, let’s take a look at the log package of the Go standard library. Which provides a simple way to write records to a file, the console, or any type that implements the io.Writer interface.

package main

import (
	"log"
	"os"
)

func main() {
	defaultLogger := log.Default()
	defaultLogger.SetOutput(os.Stdout)
	log.Println("Hello from the std-log package!")
	logger := log.New(
		os.Stderr,
		"Go application: ",
		log.Ldate|log.Ltime|log.Lmicroseconds|log.LUTC|log.Lshortfile,
	)

	logger.Println("Hello from the custom logger!")
	logger.Printf("username=%s user_id=%s request_id:%s", "John Doe", "123", "abc123")
}

Run it on the playground

The output contains a timestamp with the local time zone and the specified message. Here we are adding the application name, file name, and line number to each record. Also the microseconds to the timestamp, and the date of the record in UTC instead of local time.

2023/08/12 12:33:07 Hello from the std-log package!
Go application: 2023/08/12 18:33:07.205115 main.go:20: Hello from the custom logger!
Go application: 2023/08/12 18:33:07.205164 main.go:21: username=John Doe user_id=123 request_id:abc123

Limitations of the log package

• Lack of records by level
• Does not support structured logging
• Limited configuration
• It is difficult to maintain consistency in the format of the records

slog package

Let’s start by defining the architecture intended for this package:

• Logger: This is the “Frontend” for the logs produced with slog. It provides the level methods Info() and Error().
• Record: represents each self-contained record created by a Logger.
• Handler: This is the backend of the slog package. It is an interface that, once implemented, determines the format and destination of each record. It includes two handlers:
  • TextHandler
  • JSONHandler

TextHandler

package main

import (
	"os"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewTextHandler(os.Stdout, nil))
	logger.Debug("Debug message example")
	logger.Info("Info message example")
	logger.Warn("Warning message example")
	logger.Error("Error message example")
}

Run it on the playground

Output

time=2023-08-12T12:51:20.001-06:00 level=INFO msg="Info message example"
time=2023-08-12T12:51:20.001-06:00 level=WARN msg="Warning message example"
time=2023-08-12T12:51:20.001-06:00 level=ERROR msg="Error message example"

JSONHandler

package main

import (
	"os"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Debug("Debug message example")
	logger.Info("Info message example")
	logger.Warn("Warning message example")
	logger.Error("Error message example")
}

Run it on the playground

Output

{"time":"2023-08-12T12:51:43.832022-06:00","level":"INFO","msg":"Info message example"}
{"time":"2023-08-12T12:51:43.83216-06:00","level":"WARN","msg":"Warning message example"}
{"time":"2023-08-12T12:51:43.832162-06:00","level":"ERROR","msg":"Error message example"}

Contextual logging with slog

Structured records offer an important advantage over plain text in that they allow the inclusion of arbitrary attributes in the key-value format.

These attributes allow us to provide additional context of the logged event, which can be valuable for tasks such as resolving issues, generating metrics, and many other purposes.

package main

import (
	"os"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info(
		"incoming request",
		"method", "GET",
		"time_taken_ms", 158,
		"file_path", "/path/to/file.txt",
		"status", 200,
	)
}

Run it on the playground

Output

{
  "time": "2023-08-12T16:51:15.273168-06:00",
  "level": "INFO",
  "msg": "incoming request",
  "method": "GET",
  "time_taken_ms": 158,
  "file_path": "/path/to/file.txt",
  "status": 200
}

All methods (such as Info(), Debug(), etc) accept a message as their first argument and an unlimited number of values in weakly-typed key-value format.

However, due to this weak typing, it can lead to unexpected errors if not enough care is taken when creating our records. Unbalanced key/value pairs will produce problematic output.

package main

import (
	"os"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info(
		"incoming request",
		"method", "GET",
		"file_path", // this key has no value
	)
}

Run it on the playground

Output

{
  "time": "2023-08-12T12:57:07.929177-06:00",
  "level": "INFO",
  "msg": "incoming request",
  "method": "GET",
  "!BADKEY": "file_path"
}

As you can see in the output of this log, slog uses the !BADKEY key for those keys that do not have a corresponding value, this can be problematic when troubleshooting or viewing our logs. It may even happen that we are not aware of it until we review the records.

Part of the proposal to solve this is to add this validation as part of the go vet command to detect possible keys without their respective value; Another recommendation is to be very careful when doing code reviews in our projects.

To prevent these errors, it is better to use strongly-typed contextual attributes.

package main

import (
	"os"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.Info(
		"incoming request",
		slog.String("method", "GET"),
		slog.Int("time_taken_ms", 158),
		slog.String("file_path", "/path/to/file.txt"),
		slog.Int("status", 200),
		slog.String(
			"shipping_address",
			"123 Main St, City, Country",
		),
	)
}

Run it on the playground

Output

{
  "time": "2023-08-12T16:52:28.473112-06:00",
  "level": "INFO",
  "msg": "incoming request",
  "method": {
    "Key": "time_taken_ms",
    "Value": {}
  },
  "file_path": "/path/to/file.txt",
  "status": 200,
  "shipping_address": "123 Main St, City, Country"
}

While this is a better alternative to using weakly typed contextual slogging, this solution is also not foolproof as nothing prevents us from mixing weakly typed records with strongly typed ones.

So… How could we achieve strongly typed records and at the same time add context to them?

In order to achieve this we have to use the LogAttrs() method:

package main

import (
	"context"
	"os"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.LogAttrs(
		context.Background(),
		slog.LevelInfo,
		"incoming request",
		slog.String("method", "GET"),
		slog.Int("time_taken_ms", 158),
		slog.String("file_path", "/path/to/file.txt"),
		slog.Int("status", 200),
		slog.String(
			"shipping_address",
			"123 Main St, City, Country",
		),
	)
}

Run it on the playground

Output

{
  "time": "2023-08-12T16:54:08.576372-06:00",
  "level": "INFO",
  "msg": "incoming request",
  "method": "GET",
  "time_taken_ms": 158,
  "file_path": "/path/to/file.txt",
  "status": 200,
  "shipping_address": "123 Main St, City, Country"
}

This method only accepts values in key-value format of type slog.Attr, which is what we need to avoid records with missing values.

Grouping contextual attributes

Slog also provides a way to group multiple attributes using a single key.

package main

import (
	"context"
	"os"
	"time"

	"log/slog"
)

func main() {
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
	logger.LogAttrs(
		context.Background(),
		slog.LevelInfo,
		"order created",
		slog.Int("id", 23123),
		slog.Group("order",
			slog.Time("order_date", time.Now()),
			slog.String("shipping_address", "123 Main St, City, Country"),
			slog.String("payment_method", "Credit Card"),
			slog.Float64("total_amount", 49.99),
		),
	)
}

Run it on the playground

Output

{
  "time": "2023-08-12T16:54:54.213995-06:00",
  "level": "INFO",
  "msg": "order created",
  "id": 23123,
  "order": {
    "order_date": "2023-08-12T16:54:54.213897-06:00",
    "shipping_address": "123 Main St, City, Country",
    "payment_method": "Credit Card",
    "total_amount": 49.99
  }
}

The way the record is displayed depends on the handler we use, if it is the TextHandler each record is prefixed with the group name.

Using child loggers

Another feature that is quite useful is to include the same attributes in our records, this can help us not to forget about them and not repeat the same attributes in each record.

In the slog package we can create child loggers that inherit the context of the parent logger using the Logger.With() method. Which accepts one or more values in key-value format and returns a new Logger that includes the specified attributes.

package main

import (
	"os"
	"runtime/debug"

	"log/slog"
)

func main() {
	handler := slog.NewJSONHandler(os.Stdout, nil)
	buildInfo, _ := debug.ReadBuildInfo()

	logger := slog.New(handler)

	child := logger.With(
		slog.Group("program_info",
			slog.Int("pid", os.Getpid()),
			slog.String("go_version", buildInfo.GoVersion),
		),
	)

	child.Info("image upload successful", slog.String("image_id", "39ud88"))
	child.Warn(
		"storage is 90% full",
		slog.String("available_space", "90.1 mb"),
	)
}

Run it on the playground

Output

{
  "time": "2023-08-12T16:55:40.656021-06:00",
  "level": "INFO",
  "msg": "image upload successful",
  "program_info": {
    "pid": 30773,
    "go_version": "go1.21rc2"
  },
  "image_id": "39ud88"
}
{
  "time": "2023-08-12T16:55:40.656381-06:00",
  "level": "WARN",
  "msg": "storage is 90% full",
  "program_info": {
    "pid": 30773,
    "go_version": "go1.21rc2"
  },
  "available_space": "90.1 mb"
}

Customize handlers

So far we have only used the default configuration that comes with the JSONHandler and TextHandler handlers, but this configuration can be changed with the HandlerOptions type.

package main

import (
	"os"

	"log/slog"
)

func main() {
	opts := slog.HandlerOptions{
		AddSource: true,
		Level:     slog.LevelDebug,
	}

	handler := slog.NewJSONHandler(os.Stdout, &opts)

	logger := slog.New(handler)

	logger.Debug("Debug message example")
	logger.Info("Info message example")
	logger.Warn("Warning message example")
	logger.Error("Error message example")
}

Run it on the playground

Output

{
  "time":"2009-11-10T23:00:00Z",
  "level":"DEBUG",
  "source": {
    "function":"main.main",
    "file":"/tmp/sandbox1831383992/prog.go",
    "line":19
  },
  "msg":"Debug message example"
}
{
  "time":"2009-11-10T23:00:00Z",
  "level":"INFO",
  "source": {
    "function":"main.main",
    "file":"/tmp/sandbox1831383992/prog.go",
    "line":20
  },
  "msg":"Info message example"
}
{
  "time":"2009-11-10T23:00:00Z",
  "level":"WARN",
  "source": {
    "function":"main.main",
    "file":"/tmp/sandbox1831383992/prog.go",
    "line":21
  },
  "msg":"Warning message example"
}
{
  "time":"2009-11-10T23:00:00Z",
  "level":"ERROR",
  "source": {
    "function":"main.main",
    "file":"/tmp/sandbox1831383992/prog.go",
    "line":22
  },
  "msg":"Error message example"
}

Hiding sensitive information with the LogValuer interface

The LogValuer interface allows us to determine what output will be logged for a custom type.

package main

import (
	"os"

	"log/slog"
)

type User struct {
	ID        string `json:"id"`
	FirstName string `json:"first_name"`
	LastName  string `json:"last_name"`
	Email     string `json:"email"`
	Password  string `json:"password"`
}

// This allows us to hide the password field, and only log the user ID.
func (u *User) LogValue() slog.Value {
	return slog.StringValue(u.ID)
}

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

	u := &User{
		ID:        "user-12234",
		FirstName: "Jan",
		LastName:  "Doe",
		Email:     "jan@example.com",
		Password:  "pass-12334",
	}

	logger.Info("info", "user", u)
}

Run it on the playground

Output

{
  "time": "2023-08-12T13:00:20.827022-06:00",
  "level": "INFO",
  "msg": "info",
  "user": "user-12234"
}

We can also use the GroupValue function to log multiple values at once.

package main

import (
	"os"

	"log/slog"
)

type User struct {
	ID        string `json:"id"`
	FirstName string `json:"first_name"`
	LastName  string `json:"last_name"`
	Email     string `json:"email"`
	Password  string `json:"password"`
}

// This allows us to hide the password field, and concatenate the first and last name fields.
func (u *User) LogValue() slog.Value {
	return slog.GroupValue(
		slog.String("id", u.ID),
		slog.String("name", u.FirstName+" "+u.LastName),
	)
}

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

	u := &User{
		ID:        "user-12234",
		FirstName: "Jan",
		LastName:  "Doe",
		Email:     "jan@example.com",
		Password:  "pass-12334",
	}

	logger.Info("info", "user", u)
}

Run it on the playground

Output

{
  "time": "2023-08-12T13:01:34.688525-06:00",
  "level": "INFO",
  "msg": "info",
  "user": {
    "id": "user-12234",
    "name": "Jan Doe"
  }
}

Conclusion

I hope this article helped you to understand the Go slog package that is already available in the Go version 1.21.

Happy coding!