Writing a Slog Handler Part 2: The Handler
Continuing the introduction to Go's log/slog by writing a slog.Handler that outputs human-readable logs.
We finished Part 1 with a wrapper that decorates another handler's output as a GitHub Actions workflow command. After that, I still wanted to have a go at writing a full handler. I decided on a handler that would log in a human-readable format. Yes, I know that a big reason for structure logging is to make it easier to parse by machines, but I'm a human and I want to read my logs too. This should be a good companion to the GitHub Actions wrapper because there aren't many use cases for parsing GitHub Actions logs.
Before we set out, we should decide what a human readable structured log looks like. I decided on a multi-line format putting the message at the beginning and following it with attributes in yaml format.
It looks like this:
greetings from your human-readable slog handler
time: 2023-07-11T13:04:13.319-05:00
level: INFO
foo: bar
config:
baz: qux
I think it's a bit easier on the eyes than the slog.TextHandler equivalent:
time=2023-07-11T14:06:14.160-05:00 level=INFO msg="greetings from your human-readable slog handler" foo=bar config=map[baz:qux]
Even if you think a human-readable handler is a terrible idea, please indulge me because this is about the journey, not the destination.
The Handler
See the final result on go.pkg.dev.
Now that we're fully implementing a Handler, let's take a closer look at the interface:
slog.Handler
// A Handler handles log records produced by a Logger..
//
// A typical handler may print log records to standard error,
// or write them to a file or database, or perhaps augment them
// with additional attributes and pass them on to another handler.
//
// 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.
//
// Users of the slog package should not invoke Handler methods directly.
// They should use the methods of [Logger] instead.
type Handler interface {
// Enabled reports whether the handler handles records at the given level.
// The handler ignores records whose level is lower.
// It is called early, before any arguments are processed,
// to save effort if the log event should be discarded.
// If called from a Logger method, the first argument is the context
// passed to that method, or context.Background() if nil was passed
// or the method does not take a context.
// The context is passed so Enabled can use its values
// to make a decision.
Enabled(context.Context, Level) bool
// Handle handles the Record.
// It will only be called when Enabled returns true.
// The Context argument is as for Enabled.
// It is present solely to provide Handlers access to the context's values.
// Canceling the context should not affect record processing.
// (Among other things, log messages may be necessary to debug a
// cancellation-related problem.)
//
// Handle methods that produce output should observe the following rules:
// - If r.Time is the zero time, ignore the time.
// - If r.PC is zero, ignore it.
// - Attr's values should be resolved.
// - If an Attr's key and value are both the zero value, ignore the Attr.
// This can be tested with attr.Equal(Attr{}).
// - If a group's key is empty, inline the group's Attrs.
// - If a group has no Attrs (even if it has a non-empty key),
// ignore it.
Handle(context.Context, 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(level, msg, slog.Int("a", 1), slog.Int("b", 2))
//
// should behave like
//
// logger.LogAttrs(level, msg, slog.Group("s", slog.Int("a", 1), slog.Int("b", 2)))
//
// If the name is empty, WithGroup returns the receiver.
WithGroup(name string) Handler
}
Got all that? Me neither. There is a lot to take in, but I appreciate how
thorough it is. The list of rules for Handle() is especially helpful.
The primary question before us is how to handle the groups and attributes we
gather along the way using WithGroup() and WithAttrs().
Two approaches come to mind:
- The Attr Collector - Store all the attributes and groups in the handler and use them to build log entries.
- The Incremental Builder - Keep the yaml portion of the log entry on the handler
and append it from
WithAttrs().
I explored both approaches and landed on the latter, but first lets look at the former.
The Attr Collector
We want to store the slog.Attr values
we get from WithAttrs() on the handler. It took me a bit to realize this, but
a group is itself a kind of Attr. Also, the spec for Handle() says that groups
with empty keys should be inlined. Together, this means we can represent the
whole hierarchy of groups and attributes as a single Attr field.
Implementing this quickly presented the question of how WithAttrs() will find
the correct place in the hierarchy to add the new attributes. We could keep a
pointer to the current group, or we could keep track of our current depth in
the hierarchy. The group written by WithGroup() will always be the
last attribute on the slice; so, the depth is all we need to navigate to the
current group. It ends up looking like this:
type Handler struct {
output io.Writer
root slog.Attr
level slog.Level
depth int
}
// resolveGroup returns a clone of root and a pointer to
// the current group.
func (h *Handler) resolveGroup() (slog.Attr, *slog.Attr) {
root := slog.Group("", slog.GroupValue(h.root.Value.Group()...))
group := &root
for i := 0; i < h.depth; i++ {
j := len(group.Value.Group()) - 1
attrs := append(
[]slog.Attr{},
append(
group.Value.Group()[:j],
group.Value.Group()[j].Value.Group()...,
)...,
)
*group = slog.Group(group.Key, attrs)
}
return root, group
}
func (h *Handler) Enabled(_ context.Context, level slog.Level) bool {
return level >= h.level
}
func (h *Handler) WithGroup(name string) slog.Handler {
if name == "" {
return h
}
root, group := h.resolveGroup()
group.Value = slog.GroupValue(append(
group.Value.Group(),
slog.Group(name))...,
)
return &Handler{
output: h.output,
root: root,
depth: h.depth + 1,
level: h.level,
}
}
func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler {
root, group := h.resolveGroup()
group.Value = slog.GroupValue(append(group.Value.Group(), attrs...)...)
return &Handler{
output: h.output,
root: root,
depth: h.depth,
level: h.level,
}
}
The most expedient way to incorporate the record's attributes is by
using WithAttrs() to create a new handler with the record's attributes. This
new handler then builds the yaml part of the log entry.
func (h *Handler) Handle(_ context.Context, record slog.Record) error {
// Get the record attrs that should be at the root level.
// We will place these upfront for readability.
frontAttrs := []slog.Attr{slog.String("level", record.Level.String())}
if !record.Time.IsZero() {
frontAttrs = append(frontAttrs, slog.Time("time", record.Time))
}
if record.PC != 0 {
frame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next()
frontAttrs = append(frontAttrs, slog.String(
"source",
frame.File+":"+strconv.Itoa(frame.Line),
))
}
// Get record attrs that belong in the current group.
recordAttrs := make([]slog.Attr, 0, record.NumAttrs())
record.Attrs(func(attr slog.Attr) bool {
recordAttrs = append(recordAttrs, attr)
return true
})
// Create handler for this log entry.
h2 := h.WithAttrs(recordAttrs).(*Handler)
// Marshal the yaml for the log entry.
attrs := append(frontAttrs, h2.root.Value.Group()...)
y, err := marshalYamlAttrs(attrs, " ")
if err != nil {
y = []byte("!ERROR building log entry: " + err.Error())
}
// Write the entry.
entry := append([]byte(record.Message + "\n"), y...)
_, err = h2.output.Write(entry)
return err
}
This approach works, but it does a lot of memory allocations on Handle(),
which is typically in the hot path. We could make this more efficient by
using sync.Pool for byte slices and []slog.Attr values, but we still
end up re-marshaling the handler's Attrs for each log entry. I left
out marshalYamlAttrs() for brevity, but suffice it to say it ends up
calling yaml.Marshal() on the Attrs which is responsible for most of the
allocations.
If I were just writing a handler for GitHub actions, I would probably stop here. It works fine for the volume of logs even the most verbose GitHub action would emit. But this is also a learning exercise. I want to end up with a handler that performs about as well as the handlers provided by "log/slog".
I ran some benchmarks to double-check my intuition because I've learned my intuition on performance is often wrong. It turns out it was correct this time.
Part 3 - The Handler Revisited reimplements our handler using the incremental builder approach. It is more efficient and gets the performance in line with slog's provided handlers.