Standard lib structured logging in Go 1.21

Aug 8, 2023 1124 words 6 minutes

Contents

Go 1.21 includes structured logging (with levels) as a standard library package.
In this post we look at the log/slog package, and what it provides.

TL;DR - here’s a package to make using log/slog easier: github.com/zknill/slogmw

Levels

log/slog comes with 4 levels:

1
2
3
4
slog.Debug("hello world")
slog.Info("hello world")
slog.Warn("hello world")
slog.Error("hello world")

The functions providing each level come with the same pair of exported method calls.

Here’s the example for Info:

1
2
func Info(msg string, args ...any)
func InfoContext(msg string, args ...any)

We will come back to the InfoContext function, but for now, let’s focus on the Info function.

Structured arguments

The basic calls to log/slog level functions are like this:

1
slog.Info("hello world", "user", 5)

By default, this log call produces the output:

1
2023/08/09 09:31:24 INFO hello world user=5

This is the default because the package level functions that we’ve seen (like Info, etc) use the “default” slog.Logger. We can change the format of the default logger to use a JSONHandler, which writes the log events as json objects.

1
2
3
4
5
6
7
logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
slog.SetDefault(logger)

slog.Info("hello world", "user", 5)

// Output
{"time":"2023-08-09T09:39:05.234745912+01:00","level":"INFO","msg":"hello world","user":5}

Using HandlerOptions

HandlerOptions provides the main hooks we can use to modify the built in TextHander and JSONHandler. The Handlers provide the formatting, and decide which events should be printed based on the log level.

Setting the log level

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
opts := &slog.HandlerOptions{
    Level: slog.LevelWarn,
}

logger := slog.New(slog.NewTextHandler(os.Stdout, opts))
slog.SetDefault(logger)

// Info log event is not printed
slog.Info("hello world", "user", 5)
slog.Warn("only this is printed")

// Output with modified time format:
// time=2023-08-09T11:04:08.527+01:00 level=WARN msg="only this is printed"

Set the time format

But the time format has changed in the JSON message, to change the time format:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
opts := &slog.HandlerOptions{
    // Use the ReplaceAttr function on the handler options
    // to be able to replace any single attribute in the log output
    ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
         // check that we are handling the time key
         if a.Key != slog.TimeKey {
         	return a
         }
         
         t := a.Value.Time()
         
         // change the value from a time.Time to a String
         // where the string has the correct time format.
         a.Value = slog.StringValue(t.Format(time.DateTime))
         
         return a
    },
}

logger := slog.New(slog.NewJSONHandler(os.Stdout, opts))
slog.SetDefault(logger)

slog.Info("hello world", "user", 5)

// Output with modified time format
{"time":"2023-08-09 09:54:46","level":"INFO","msg":"hello world","user":5}

Change the event keys

We can use the same ReplaceAttr pattern to change the keys in the log message:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
opts := &slog.HandlerOptions{
    ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
    	if a.Key != slog.MessageKey {
    		return a
    	}
    
    	// change the key from "msg" to "message"
    	a.Key = "message"
    
    	return a
    },
}

logger := slog.New(slog.NewTextHandler(os.Stdout, opts))
slog.SetDefault(logger)

slog.Info("hello world", "user", 5)

// Output
time=2023-08-09T10:57:59.213+01:00 level=INFO message="hello world" user=5

Using nested log objects

log/slog provides a level of nesting of log fields with the slog.Group() method.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
textLog := slog.New(slog.NewTextHandler(os.Stdout, nil))
jsonLog := slog.New(slog.NewJSONHandler(os.Stdout, nil))

slog.SetDefault(textLog)

slog.Info("outside the group",
	// The Group method takes the outer key, then kv pairs
	slog.Group("request",
		"method", "GET",
		"url", "http://zknill.io",
	),
)

slog.SetDefault(jsonLog)

slog.Info("outside the group",
  slog.Group("request",
  	"method", "GET",
  	"url", "http://zknill.io",
  ),
)

Output from text logger

1
time=... level=INFO msg="outside the group" request.method=GET request.url=http://zknill.io

Output from json logger

1
{"time":"...","level":"INFO","msg":"outside the group","request":{"method":"GET","url":"http://zknill.io"}}

The JSON logger will render the group as a child object of the request key. The text logger will concat the keys with a . separator; like request.method=GET

Carrying log context

I mentioned that we would return to the InfoContext(...) method. This method, and the other level context methods accept a context, which means the logger can have access to the context objects and extract app specific information to add to the log events.

But to access the context, we will need to create our own handler. So far we’ve been using the built in handlers: slog.TextHander and slog.JSONHandler. Both of these handlers ignore the context.

Handler interface

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
type Handler interface {
  // Enabled reports if the specific log event should 
  // be printed for this Handler and the given log level.
  // We can also choose to use info from the Context that
  // we passed in the InfoContext(...) call. If we used
  // Info(...) not InfoContext(...) then the context will 
  // be context.Background().
  Enabled(context.Context, slog.Level) bool

  // Handle takes the log record and prints it. The handle
  // function has access to the context, so we can extract
  // request specific info that we want to include in our
  // log event here.
  Handle(context.Context, Record) error

  // WithAttrs are the key value pairs that we're including in the structured logging
  // e.g. user=5
  WithAttrs(attrs []Attr) Handler

  // WithGroup is a sub-handler, with the group/object name
  WithGroup(name string) Handler
}

Defining a custom JSON handler that includes extra context:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
package main

import (
    "context"
    "log/slog"
    "os"
)

func main() {
    // make the default json handler
    jsonHandler := slog.NewJSONHandler(os.Stdout, nil)

    // wrap the default json handler in a handler that logs context
    myHandler := &myHandler{JSONHandler: jsonHandler}
    

    logger := slog.New(myHandler)
    slog.SetDefault(logger)
    
    // add our context fields 
    ctx := context.Background()
    ctx = context.WithValue(ctx, userIDKey, "5")
    
    // call the context log method
    slog.InfoContext(ctx, "hello world")
}

// myHandler embeds the anonymous struct member
// *slog.JSONHandler. This gives us method overriding
// where all methods of the handler interface we don't
// implement will be dispatched to the built in handler
type myHandler struct {
    *slog.JSONHandler
}

type contextKey string

const userIDKey contextKey = "userid"

// Handle passes the userID key and value as an extra
// attribute to the standard json handler then calls handle.
func (h *myHandler) Handle(ctx context.Context, r slog.Record) error {
    userID := ctx.Value(userIDKey).(string)
    
    return h.
    	JSONHandler.
    	WithAttrs([]slog.Attr{slog.String("userID", userID)}).
    	Handle(ctx, r)
}

`slogmw` package

Most of us are going to want to modify or change elements of the log/slog package output, so here is a set of middleware that captures the patterns above into a more usable interface.

github.com/zknill/slogmw