Writing a Slog Handler Part 1: The Wrapper

An introduction to Go's log/slog package. Writing a wrapper for a slog.Handler that we can use in GitHub Actions.

Go 1.21 adds log/slog to the standard library. Its primary feature is structured logging similar to zap or logrus. It also adds log levels so you don't need a separate debug logger anymore.

I happened to be working on a GitHub action when the go1.21rc2 announcement prompted me to explore slog. I wanted to make it output logs formatted for GitHub Actions. Specifically, This meant emitting workflow commands for each log level, so that log.Info() appears as a notice, log.Warn() as a warning, and so on. It should also link logs to the line that produced them.

I ended up writing both a wrapper that will decorate any handler's output as a workflow command and a handler that formats log entries in human-readable format. Neither one necessarily requires the other, but they work well together if you want human-readable output in your GitHub Actions.

The Wrapper

See the final result on go.pkg.dev.

I started with a wrapper around another handler. It doesn't worry about formatting, it just takes the output of the wrapped handler and decorates it as a workflow command. The wrapper is itself a Handler, so you use it like any other.

This screenshot captures the essence of the wrapper in action. It shows a pull request with a source code annotation containing the output from slog.TextHandler.

At first this seemed trivially easy. The Handle method was less than 30 lines of straight-forward code:

type Wrapper struct {
	handler slog.Handler
	writer  io.Writer
}

func (w *Wrapper) Handle(ctx context.Context, record slog.Record) error {
	line := "::debug"
	switch {
	case record.Level >= slog.LevelError:
		line = "::error"
	case record.Level >= slog.LevelWarn:
		line = "::warning"
	case record.Level >= slog.LevelInfo:
		line = "::notice"
	}
	if record.PC != 0 {
		frames := runtime.CallersFrames([]uintptr{record.PC})
		frame, _ := frames.Next()
		line += " file=" + frame.File + ",line=" + strconv.Itoa(frame.Line)
	}
	line += "::"
	_, err := io.WriteString(w.writer, line)
	if err != nil {
		return err
	}
	err = w.handler.Handle(ctx, record)
	if err != nil {
		return err
	}
	_, err = w.writer.Write([]byte{'\n'})
	return err
}

This concise code lasted until I wrote a test for concurrent writes. The attentive reader probably already sees the problem. There are three different writes for each line, and concurrent writes will interleave the output.

The obvious solution to this is to use a mutex to guard against concurrent writes. That would work until handler.WithAttrs() or handler.WithGroup() is called, but then you end up with multiple handlers writing to the same writer that will have concurrency issues.

I ended up adding a pointer to root wrapper so that all wrappers created with the With*() methods can share the same mutex. I also added a buf field that the wrapped handler writes to instead of writing directly to the output allowing it to be written with a single Write().

Now Handle() looks like this:

type Wrapper struct {
	handler     slog.Handler
	writer      io.Writer
	linkSource  bool
	mu          sync.Mutex
	buf         *[]byte
	rootWrapper *Wrapper
}

func (w *Wrapper) root() *Wrapper {
	if w.rootWrapper == nil {
		return w
	}
	return w.rootWrapper
}

func (w *Wrapper) Handle(ctx context.Context, record slog.Record) error {
	// ... build line same as before ...
    
	root := w.root()
	root.mu.Lock()
	defer root.mu.Unlock()
	if root.buf == nil {
		b := make([]byte, 0, 1024)
		root.buf = &b
	}
	*root.buf = (*root.buf)[:0]
	*root.buf = append(*root.buf, line...)
	err := w.handler.Handle(ctx, record)
	if err != nil {
		return err
	}
	*root.buf = append(*root.buf, '\n')
	_, err = w.writer.Write(*root.buf)
	return err
}

The rest of the methods are pretty simple:

func (w *Wrapper) Enabled(ctx context.Context, level slog.Level) bool {
	return w.handler.Enabled(ctx, level)
}

func (w *Wrapper) WithAttrs(attrs []slog.Attr) slog.Handler {
	return &Wrapper{
		handler:     w.handler.WithAttrs(attrs),
		writer:      w.writer,
		linkSource:  w.linkSource,
		rootWrapper: w.root(),
	}
}

func (w *Wrapper) WithGroup(name string) slog.Handler {
	return &Wrapper{
		handler:     w.handler.WithGroup(name),
		writer:      w.writer,
		linkSource:  w.linkSource,
		rootWrapper: w.root(),
	}
}

Now we have a working wrapper. I spared you some of the trivial implementation details, but this is essentially the same as actionslog.Wrapper.

Part 2 - The Handler continues exploring "log/slog" by writing a human-readable handler.