Playing With Slog, the Proposed Structured Logging Package for the Go Standard Library

For a while now I’ve been keeping a close eye on the structure logging proposal making its way through Go’s language proposal process. Last month an experimental version of the proposal was released under the golang.org/x/exp package (see documentation here) and I decided to experiment with it and decided to summarise my learnings in a blog for others to learn more about this proposed addition to the Go standard library.

What is the Structured Logging Proposal?

From a high level (see the proposal itself for a more in-depth look) the proposal aims to address the current gap that exists in Go’s standard library by adding structured logging with levels, residing in a new package with the import path log/slog.

First, what is Structured Logging?

Logs have traditionally been aimed at being human readable. These days it’s common to want to index them to enable better filtering and searching. This can be performed by formatting the log output in a way that makes them machine-readable. This process is called structured logging.

For example, if you’ve used Go’s existing log package then the following code would output a log that looks like the output below:

log.Printf("processed %d items in %s", 23, time.Since(time.Now()))

// Not structured, boo :(
2022/11/10 02:53:02 processed 23 items in 83ns

Its lack of structure makes parsing the output difficult and potentially costly. A better, structured alternative would be the following which adds keys and associated values to the output making parsing it programmatically far easier and more reliable.

// Structured!
time=2022/11/10 02:53:02 msg="processed item" size=23 duration=83ns level=info

Now the logs have a structure associated with them, it’s much easier to encode them as other data formats such as JSON:

{"time":"2022-11-13T03:38:37.737821Z","level":"INFO","msg":"processed items","size":23,"duration":83}

Providing a general interface for logging in Go

A wide variety of structured logging packages exist within the Go ecosystem (Logrus, Zap and Zerolog to name a few), however this diverse API landscape can make supporting logging in a provider agnostic way challenging, often requiring abstractions to avoid coupling your implementation to any given logging package. This proposal would help alleviate this pain by providing a common interface in the standard library that service owners of package authors alike could depend on.

That’s enough talk for now, let’s take a look at the proposed package in a bit more depth.

Logging via the slog package

A Bare Bones Example

Following on from the items processed logging theme above (which is common through examples in the proposal) the slog proposal aims to introduce the following API. We’ll focus on the setup at first and dive into the log writing part later.

package main

import (
     "os"
     "time"

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

func main() {
    logger := slog.New(slog.NewTextHandler(os.Stdout))
    logger.Info("processed items",
        "size", 23,
        "duration", time.Since(time.Now()))
}

// time=2022-11-10T03:56:11.768Z level=INFO msg="processed items" size=23 duration=42ns

As demonstrated, upon creating a new instance of the slog logger you can pass a type of Handler; an interface whose responsibility is to handle log records produced by a Logger struct type (returned when calling slog.New(...)). The Handler interface is a key piece of the extensibility enabled by the slog package and one we’ll touch towards the end of this post.

In this instance we’ve used the TextHandler for writing the log output as structured text, but a JSONHandler also exists for formatting your structured logs to JSON.

...

logger := slog.New(slog.NewJSONHandler(os.Stdout))
logger.Info("processed items",
    "size", 23,
    "duration", time.Since(time.Now()))
    
// {"time":"2022-11-13T04:08:19.805393Z","level":"INFO","msg":"processed items","size":23,"duration":84}

At this point it’s also valuable to highlight that you can set the logger as the default logger via the SetDefault method call. This will do two things, set the logger as the default when using the slog package. For instance, both of these would output the same log statements:

...

func main() {
    logger := slog.New(&LogrusHandler{
        logger: logrus.StandardLogger(),
    })
    slog.SetDefault(logger)

    logger.Error("something went wrong", net.ErrClosed,
        "status", http.StatusInternalServerError)
    slog.Error("something went wrong", net.ErrClosed,
        "status", http.StatusInternalServerError)
}

// {"err":"use of closed network connection","level":"error","msg":"something went wrong","status":500,"time":"2022-11-24T22:31:06Z"}

Secondly, using slog.SetDefault() will also set the logger as the default logger for the log package. So function calls such as the following will log the expected output:

...
func main() {
    logger := slog.New(&LogrusHandler{
        logger: logrus.StandardLogger(),
    })
    slog.SetDefault(logger)

    log.Print("something went wrong")
    log.Fatalln("something went wrong")
}

//{"level":"info","msg":"something went wrong","time":"2022-11-24T22:33:57Z"}
// {"level":"info","msg":"something went wrong","time":"2022-11-24T22:33:57Z"}
// exit status 1

Logging

Logging via the slog package can be performed in one of two ways, either via the loosely typed API seen above (designed for brevity at the sacrifice of additional allocations), or via a strongly typed but more performance focused alternative seen below, both approaches output the log in the same format.

...

// designed for brevity at the sacrifice of additional allocations
logger.Info("processed items",
    "size", 23,
    "duration", time.Since(time.Now()),

// designed for performance
logger.LogAttrs(slog.InfoLevel, "processed items",
    slog.Int("size", 23),
    slog.Duration("duration", time.Since(time.Now())),

Storing and fetching via context.Context

The slog logger also provides an API to enable you to store and fetch the logger via a context. Note that on the below example, FromContext will actually return a default logger if none exists within the context.

...

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

    ctx := context.Background()
    
    // save logger to context.Context
    ctx = slog.NewContext(ctx, logger)
    
    // retrieve logger from context after propagating it throughout your API,
    // If no logger exists then a default logger is returned
    logger = slog.FromContext(ctx)
    logger.Info("processed items",
        "size", 23,
        "duration", time.Since(time.Now()),
    )
}

Whilst propagating objects via a context is somewhat of a contentious point amongst Go developers (and one questioned and discussed on the initial proposal), scoping a logger to a request is a common pattern when logging and as one user commented, advocated within the OTEL (OpenTelemetry) specification, so personally I don’t have an issue with it in this case.

It becomes especially powerful when using the With function (see docs) to attach request level attributes to the returned logger before propagating it further down the call stack like so:

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout))
    http.HandleFunc("/hello", func(w http.ResponseWriter, r *http.Request) {
        // subsequent log entries within this context will contain these fields
        l := logger.
            With("path", r.URL.Path).
            With("user-agent", r.UserAgent())

        // propagate the logger with the above fields via the request context
        ctx := slog.NewContext(r.Context(), l)

        handleRequest(w, r.WithContext(ctx))
    })

    http.ListenAndServe(":8080", nil)
}

func handleRequest(w http.ResponseWriter, r *http.Request) {
    l := slog.FromContext(r.Context())

    l.Info("handling request",
    "status", http.StatusOK)
    
    w.Write([]byte("Hello World"))
}

The above example prints the following log output, allowing you to attach the necessary fields to all log lines. This could include a request/trace ID or any other vital request level information.

{
    "time":"2022-11-16T00:48:43.169545Z",
    "level":"INFO",
    "msg":"handling request",
    "path":"/hello",
    "user-agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36",
    "status":200
}

Log Handler

At the beginning of this post we looked at how the logger takes an initial dependency on a slog.Handler, for instance when creating a new TextHandler. Let’s spend some time looking at what a handler is and how it provides extensibility to the slog logger.

The Handler is an interface with four methods:

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

Other than the Enabled(Level) method (which is used to report whether the logger supports the expected log level), the to most interesting method is Handle(Record), which gets invoked every time a log entry is written to the logger and receives an instance of Record as an argument, which provides all the relevant information of the particular log entry.

By implementing this interface we can create a logger that performs tasks such as batching log entries to send over HTTP, or create an adapter to integrate an existing logger package with slog, so we can make our application or package logging library agnostic.

Building a Logrus adapter for the slog logger

Let’s take a look at what that might look like as we create a slog handler that integrates with Logrus, a popular open source logging library. It’s not production ready but hopefully it gives you an idea of what a custom handler implementation would look like:

type LogrusHandler struct {
    logger logrus.Logger
}

func (h *LogrusHandler) Enabled(_ slog.Level) bool {
    // support all logging levels
    return true
}

func (h *LogrusHandler) Handle(rec slog.Record) error {
    fields := make(map[string]interface{}, rec.NumAttrs())

    rec.Attrs(func(a slog.Attr) {
        fields[a.Key] = a.Value.Any()
    })

    entry := h.logger.WithFields(fields)

    switch rec.Level {
        case slog.DebugLevel:
            entry.Debug(rec.Message)
        case slog.InfoLevel.Level():
            entry.Info(rec.Message)
        case slog.WarnLevel:
            entry.Warn(rec.Message)
        case slog.ErrorLevel:
            entry.Error(rec.Message)
    }

    return nil
}

func (h *LogrusHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
    // not implemented for brevity
    return h
}

func (h *LogrusHandler) WithGroup(name string) slog.Handler {
    // not implemented for brevity
    return h
}

And to use the slog handler we can do something like the following:

package main

import (
    "net"
    "net/http"
    "os"

    "github.com/sirupsen/logrus"
    "golang.org/x/exp/slog"
)

func init() {
    // set up logrus
    logrus.SetFormatter(&logrus.JSONFormatter{})
    logrus.SetOutput(os.Stdout)
    logrus.SetLevel(logrus.DebugLevel)
}

func main() {
    // integrate Logrus with the slog logger
    logger := slog.New(&LogrusHandler{
        logger: logrus.StandardLogger(),
    })

    // start logging via the slog API
    slog.Error("something went wrong", net.ErrClosed,
        "status", http.StatusInternalServerError)
}

Now, whenever we log via the slog logger, our log records will still be handled via Logrus but we’ll no longer need to depend on the Logrus API in our library and we’ll see the following output:

{"err":"use of closed network connection","level":"error","msg":"something went wrong","status":500,"time":"2022-11-19T00:07:51Z"}

Conclusion

Hopefully this post has given you some insight into the slog package proposal, its goals and its potentially. Personally I’m hoping the proposal gets accepted as it’d be great to have structured logging as a first-class citizen in the standard library, but only time will tell.

If you’re interested in learning more then be sure to take a look at the proposal over here and the further discussions here.