slog: Golang's official structured logging package

Since its inception, Go has had the log package built into its standard library as a standard component of Go source output logging, and this package is widely used in the Go standard library itself and in Go community projects.

However, for the Go standard library log package, the Go community has always demanded improvements, and the mainstream voice focuses on the following points.

log packages are designed to be easily human readable and do not support structured logs that are easy to parse by machine such as outputting logs in json format like zap.
No support for log levels (log level).
The log package uses a proprietary log output format and does not provide a common logger interface type for the Go community to follow, resulting in a variety of log output formats used by Go community projects, which are difficult to be compatible with each other.

The Go community has tried to work together to improve the standard library log package and wrote the first draft of the Proposal design, but it was not accepted by the Go core team for various reasons.

In late August 2022, Jonathan Amsterdam of the Go team initiated a discussion with the community about adding structured, log-level support for logging packages to the Go standard library, and formed a consensus proposal.

Jonathan Amsterdam has named the structured logging package slog and plans to put it under log/slog. He also gave the initial implementation of slog under golang.org/x/exp, and the Proposal is officially in review these days. It is not known when it will be officially implemented in the official version of Go.

In this article, we’ll take a brief look at slog’s proposal and its initial implementation.

1. slog’s design introduction

The design of slog started with a detailed research of some widely used log packages in the community, such as uber zap, zerolog and so on. The design of slog is therefore “standing on the shoulders of those who have gone before”, especially uber zap.

Jonathan Amsterdam set the following goals for the slog design (taken from the slog proposal).

Ease of use

A survey of existing logging packages revealed that programmers want a simple and easy to understand logging API. in this proposal, we will use the most popular way to express key-value pairs today, i.e., alternate passing in keys and values.
High Performance

The log API will be designed to minimize memory allocation and locking. It provides a way to alternate input keys and values, which is slightly more tedious but faster.
Can be integrated with runtime tracing

The Go team is working on an improved runtime tracing system. The logs from this package will be seamlessly integrated into this tracing system, allowing developers to relate their program behavior to the runtime behavior.

A diagram of the structure of slog is drawn here based on the source code of slog proposal and golang.org/x/exp/slog.

A brief explanation of the diagram.

slog is logically divided into front-end (front) and back-end (backend).

The slog frontend is the API that slog provides to the user, but, unfortunately, slog still does not extract the Logger interface like log, but defines a Logger structure and provides those methods as in the diagram, which means that we still cannot unify the frontend API throughout the Go community.

With the front-end methods, slog encapsulates the log content and related property information into an instance of the slog.Record type, which is then passed to the slog backend.

If you are using the front-end methods of a third-party logging package from the Go community, such as zap, to use the slog back-end, you will likewise need to wrap zap, etc., so that it outputs slog.Record and passes it to the slog back-end (no examples of this are available yet).

slog abstracts the back end as the slog.Handler interface, with the following interface.

//
// Any of the Handler's methods may be called concurrently with itself
// or with other methods. It is the responsibility of the Handler to
// manage this concurrency.
type Handler interface {
    // Enabled reports whether the handler handles records at the given level.
    // The handler ignores records whose level is lower.
    // Enabled is called early, before any arguments are processed,
    // to save effort if the log event should be discarded.
    Enabled(Level) bool

    // Handle handles the Record.
    // It will only be called if Enabled returns true.
    // Handle methods that produce output should observe the following rules:
    //   - If r.Time is the zero time, ignore the time.
    //   - If an Attr's key is the empty string, ignore the Attr.
    Handle(r Record) error

    // WithAttrs returns a new Handler whose attributes consist of
    // both the receiver's attributes and the arguments.
    // The Handler owns the slice: it may retain, modify or discard it.
    WithAttrs(attrs []Attr) Handler

    // WithGroup returns a new Handler with the given group appended to
    // the receiver's existing groups.
    // The keys of all subsequent attributes, whether added by With or in a
    // Record, should be qualified by the sequence of group names.
    //
    // How this qualification happens is up to the Handler, so long as
    // this Handler's attribute keys differ from those of another Handler
    // with a different sequence of group names.
    //
    // A Handler should treat WithGroup as starting a Group of Attrs that ends
    // at the end of the log event. That is,
    //
    //     logger.WithGroup("s").LogAttrs(slog.Int("a", 1), slog.Int("b", 2))
    //
    // should behave like
    //
    //     logger.LogAttrs(slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))
    WithGroup(name string) Handler
}

The existence of interface types makes slog’s backend more extensible. In addition to using the two built-in Handler implementations provided by slog: TextHandler and JSONHandler, we can also define or completely customize the backend Handler implementation based on third-party log packages.

slog built-in two of the most commonly used Handler: TextHandler and JSONHandler. textHandler, as the name implies, like the standard library log package will be output as a line of text; and JSONHandler is to JSON format output log content and various attributes, we look at the author gave the example.

// github.com/bigwhite/experiments/tree/master/slog-examples/demo1/main.go
package main

import (
    "net"

    "golang.org/x/exp/slog"
)

func main() {
    slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr)))
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}

This is an example of using the built-in TextHandler, let’s run it and see the result.

1
2
3

time=2022-10-23T18:41:35.074+08:00 level=INFO msg=hello name=Al
time=2022-10-23T18:41:35.074+08:00 level=ERROR msg=oops status=500 err="use of closed network connection"
time=2022-10-23T18:41:35.074+08:00 level=ERROR msg=oops status=500 err="use of closed network connection"

We see that the output log is presented in the form of “key1=value1 key2=value2 … keyN=valueN”, the two keys time and level are mandatory, and the key err is also mandatory when calling the Error method. of.

Next, we will replace the TextHandler with JSONHandler.

slog.SetDefault(slog.New(slog.NewTextHandler(os.Stderr)))

// Replace with:

slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stderr)))

Running the modified program, we get:

1
2
3

{"time":"2022-10-23T18:45:26.2131+08:00","level":"INFO","msg":"hello","name":"Al"}
{"time":"2022-10-23T18:45:26.213287+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T18:45:26.21331+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}

We see that each log is presented as a json record, which makes the structured logs ideal for machine parsing.

If we remove the SetDefault line of code above, let’s run the program again.

1
2
3

2022/10/23 18:47:51 INFO hello name=Al
2022/10/23 18:47:51 ERROR oops status=500 err="use of closed network connection"
2022/10/23 18:47:51 ERROR oops status=500 err="use of closed network connection"

We get a different logging style than TextHandler and JSONHandler, but this logging style looks very familiar! Isn’t this the same output style as the log package! Yes, if the newly created Logger is not explicitly set as the default Logger, slog will use defaultHandler, and the output function of defaultHandler is log.Output.

// slog project

// logger.go
var defaultLogger atomic.Value

func init() {
    defaultLogger.Store(Logger{
        handler: newDefaultHandler(log.Output), // The log.Output is used directly here
    })
} 

// handler.go

type defaultHandler struct {
    ch *commonHandler
    // log.Output, except for testing
    output func(calldepth int, message string) error
}

func newDefaultHandler(output func(int, string) error) *defaultHandler {
    return &defaultHandler{
        ch:     &commonHandler{json: false},
        output: output,
    }
}

The front end of slog is “fixed format”, so there is nothing to customize. But the back end has a lot to play with, so let’s focus on the back end.

2. Handler Options (HandlerOptions)

slog provides the HandlerOptions structure.

// handler.go

// HandlerOptions are options for a TextHandler or JSONHandler.
// A zero HandlerOptions consists entirely of default values.
type HandlerOptions struct {
    // Add a "source" attribute to the output whose value is of the form
    // "file:line".
    // This is false by default, because there is a cost to extracting this
    // information.
    AddSource bool

    // Ignore records with levels below Level.Level().
    // The default is InfoLevel.
    Level Leveler

    // If set, ReplaceAttr is called on each attribute of the message,
    // and the returned value is used instead of the original. If the returned
    // key is empty, the attribute is omitted from the output.
    //
    // The built-in attributes with keys "time", "level", "source", and "msg"
    // are passed to this function first, except that time and level are omitted
    // if zero, and source is omitted if AddSourceLine is false.
    //
    // ReplaceAttr can be used to change the default keys of the built-in
    // attributes, convert types (for example, to replace a `time.Time` with the
    // integer seconds since the Unix epoch), sanitize personal information, or
    // remove attributes from the output.
    ReplaceAttr func(a Attr) Attr
}

With this structure, we can add source information to the output log, i.e., the file name and line number of the output log, as shown in the following example.

// github.com/bigwhite/experiments/tree/master/slog-examples/demo2/main.go
package main

import (
    "net"
    "os"

    "golang.org/x/exp/slog"
)

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

    slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stderr)))
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))
}

Running the above program, we will get.

1
2
3

{"time":"2022-10-23T21:46:25.718112+08:00","level":"INFO","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:16","msg":"hello","name":"Al"}
{"time":"2022-10-23T21:46:25.718324+08:00","level":"ERROR","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:17","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:46:25.718352+08:00","level":"ERROR","source":"/Users/tonybai/go/src/github.com/bigwhite/experiments/slog-examples/demo2/main.go:18","msg":"oops","status":500,"err":"use of closed network connection"}

We can also implement dynamic setting of logging levels through HandlerOptions, such as the following example.

// github.com/bigwhite/experiments/tree/master/slog-examples/demo3/main.go
func main() {
    var lvl = &slog.AtomicLevel{}
    lvl.Set(slog.DebugLevel)
    opts := slog.HandlerOptions{
        Level: lvl,
    }
    slog.SetDefault(slog.New(opts.NewJSONHandler(os.Stderr)))

    slog.Info("before resetting log level:")

    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

    slog.Info("after resetting log level to error level:")
    lvl.Set(slog.ErrorLevel)
    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

}

The field Level of slog.HandlerOptions is an interface type variable with the type slog.Leveler.

1
2
3

type Leveler interface {
    Level() Level
}

The types that implement the Level method can be assigned to the Level field of HandlerOptions. slog provides AtomicLevel that supports concurrent access for us to use directly, the above demo3 uses AtomicLevel, the initial setting is DebugLevel, so the first call to Info, Error and other API output logs will be output. After that, the log level will be reset to ErrorLevel, so that the log output from Info API will not be rendered, and the following is the result of demo3 program.

{"time":"2022-10-23T21:58:48.467666+08:00","level":"INFO","msg":"before resetting log level:"}
{"time":"2022-10-23T21:58:48.467818+08:00","level":"INFO","msg":"hello","name":"Al"}
{"time":"2022-10-23T21:58:48.467825+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467842+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467846+08:00","level":"INFO","msg":"after resetting log level to error level:"}
{"time":"2022-10-23T21:58:48.46785+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}
{"time":"2022-10-23T21:58:48.467854+08:00","level":"ERROR","msg":"oops","status":500,"err":"use of closed network connection"}

What the third field of HandlerOptions, ReplaceAttr, does is left to your own exploration.

In addition to using HandleOptions to do some customization, we can also fully customize the implementation of the Handler interface, which we will illustrate with an example below.

3. Custom Handler interface implementation

Let’s define a new Handler: ChanHandler, which implements the behavior of writing logs to a channel (used to simulate logs to kafka), and let’s build the ChanHandler.

// github.com/bigwhite/experiments/tree/master/slog-examples/demo4/main.go
type ChanHandler struct {
    slog.Handler
    ch  chan []byte
    buf *bytes.Buffer
}

func (h *ChanHandler) Enabled(level slog.Level) bool {
    return h.Handler.Enabled(level)
}

func (h *ChanHandler) Handle(r slog.Record) error {
    err := h.Handler.Handle(r)
    if err != nil {
        return err
    }
    var nb = make([]byte, h.buf.Len())
    copy(nb, h.buf.Bytes())
    h.ch <- nb
    h.buf.Reset()
    return nil
}

func (h *ChanHandler) WithAttrs(as []slog.Attr) slog.Handler {
    return &ChanHandler{
        buf:     h.buf,
        ch:      h.ch,
        Handler: h.Handler.WithAttrs(as),
    }
}

func (h *ChanHandler) WithGroup(name string) slog.Handler {
    return &ChanHandler{
        buf:     h.buf,
        ch:      h.ch,
        Handler: h.Handler.WithGroup(name),
    }
}

func NewChanHandler(ch chan []byte) *ChanHandler {
    var b = make([]byte, 256)
    h := &ChanHandler{
        buf: bytes.NewBuffer(b),
        ch:  ch,
    }

    h.Handler = slog.NewJSONHandler(h.buf)

    return h
}

We see that ChanHandler has a slog.JSONHandler embedded in it, and the implementation of the slog.Handler interface is mostly done by the embedded JSONHandler, the only difference is the Handle method, where the logs processed by the JSONHandler are copied out and sent to the channel. Here is the main function of the demo.

// github.com/bigwhite/experiments/tree/master/slog-examples/demo4/main.go

func main() {
    var ch = make(chan []byte, 100)
    attrs := []slog.Attr{
        {Key: "field1", Value: slog.StringValue("value1")},
        {Key: "field2", Value: slog.StringValue("value2")},
    }
    slog.SetDefault(slog.New(NewChanHandler(ch).WithAttrs(attrs)))
    go func() { // Simulates the consumer of a channel, used to consume logs
        for {
            b := <-ch
            fmt.Println(string(b))
        }
    }()

    slog.Info("hello", "name", "Al")
    slog.Error("oops", net.ErrClosed, "status", 500)
    slog.LogAttrs(slog.ErrorLevel, "oops",
        slog.Int("status", 500), slog.Any("err", net.ErrClosed))

    time.Sleep(3 * time.Second)
}

Running the above program, we will get the following output.

{"time":"2022-10-23T23:09:01.358702+08:00","level":"INFO","msg":"hello","field1":"value1","field2":"value2","name":"Al"}

{"time":"2022-10-23T23:09:01.358836+08:00","level":"ERROR","msg":"oops","field1":"value1","field2":"value2","status":500,"err":"use of closed network connection"}

{"time":"2022-10-23T23:09:01.358856+08:00","level":"ERROR","msg":"oops","field1":"value1","field2":"value2","status":500,"err":"use of closed network connection"}

4. slog’s performance

Let’s take a look at the performance of slog again. We directly used the performance comparison data with zap that comes with the slog source code, and used the benchstat tool to view the comparison results as follows.

$ benchstat zapbenchmarks/zap.bench slog.bench
name                              old time/op    new time/op    delta
Attrs/async_discard/5_args-8         348ns ± 2%      88ns ± 2%   -74.77%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8        570ns ± 2%     280ns ± 2%   -50.94%  (p=0.008 n=5+5)
Attrs/async_discard/40_args-8       1.84µs ± 2%    0.91µs ± 3%   -50.37%  (p=0.008 n=5+5)
Attrs/fastText_discard/5_args-8      476ns ± 2%     200ns ±45%   -57.92%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8     822ns ± 7%     524ns ± 2%   -36.27%  (p=0.008 n=5+5)
Attrs/fastText_discard/40_args-8    2.70µs ± 3%    2.01µs ± 3%   -25.76%  (p=0.008 n=5+5)

name                              old alloc/op   new alloc/op   delta
Attrs/async_discard/5_args-8          320B ± 0%        0B       -100.00%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8         640B ± 0%      208B ± 0%   -67.50%  (p=0.008 n=5+5)
Attrs/async_discard/40_args-8       2.69kB ± 0%    1.41kB ± 0%   -47.64%  (p=0.008 n=5+5)
Attrs/fastText_discard/5_args-8       320B ± 0%        0B       -100.00%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8      641B ± 0%      208B ± 0%   -67.55%  (p=0.008 n=5+5)
Attrs/fastText_discard/40_args-8    2.70kB ± 0%    1.41kB ± 0%   -47.63%  (p=0.029 n=4+4)

name                              old allocs/op  new allocs/op  delta
Attrs/async_discard/5_args-8          1.00 ± 0%      0.00       -100.00%  (p=0.008 n=5+5)
Attrs/async_discard/10_args-8         1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/async_discard/40_args-8         1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/fastText_discard/5_args-8       1.00 ± 0%      0.00       -100.00%  (p=0.008 n=5+5)
Attrs/fastText_discard/10_args-8      1.00 ± 0%      1.00 ± 0%      ~     (all equal)
Attrs/fastText_discard/40_args-8      1.00 ± 0%      1.00 ± 0%      ~     (all equal)

We see that the performance of slog is much better than zap, which is already known for its high performance, and memory allocation is much reduced.

5. Summary

Through the initial exploration of slog, I feel that slog as a whole has borrowed the design of third-party logging packages such as zap, both using the strategy of front-end and back-end separation, but it seems to be better understood than zap.

The previous example mentions the easy-to-use front-end API, and talks about the high performance of slog. slog’s design goal of integrating with runtime tracing is not mentioned much in the proposal, but more about its integration with context.Context (through slog.WithContext and slog.FromContext, etc.), perhaps this is the basis for integration with runtime tracing.

Jonathan Amsterdam has also mentioned in the proposal that each third-party log package has its own characteristics, and that slog is not expected to replace all third-party log packages, but only to interact fully with third-party log packages to achieve a common “backend” for each application. An application with many dependencies may find that it already has many log packages connected. If all packages supported the Handler interface proposed by slog, then the application could create a single Handler and install it once for each logging library to get consistent logging across all its dependencies.

Personal opinion: When slog is added to the standard library, slog is recommended for new projects.

The sample code covered in this article can be downloaded here.

6. References

Proposal: Structured Logging review - https://go-review.googlesource.com/c/proposal/+/444415/3/design/56345-structured-logging.md
discussion: structured, leveled logging - https://github.com/golang/go/discussions/54763
proposal: log/slog: structured, leveled logging - https://github.com/golang/go/issues/56345
Experimental implementation of slog - https://github.com/golang/exp/tree/master/slog
logr - https://github.com/go-logr/logr
Go Logging Design Proposal - Ross Light - https://docs.google.com/document/d/1nFRxQ5SJVPpIBWTFHV-q5lBYiwGrfCMkESFGNzsrvBU/edit
Standardization around logging and related concerns - https://groups.google.com/g/golang-dev/c/F3l9Iz1JX4g/m/t0J0loRaDQAJ

7. Ref

https://tonybai.com/2022/10/30/first-exploration-of-slog/

Table of Contents