slog HandlersThis document is maintained by Jonathan Amsterdam jba@google.com.
The standard library’s log/slog package has a two-part design. A “frontend,” implemented by the Logger type, gathers stuctured log information like a message, level, and attributes, and passes them to a “backend,” an implementation of the Handler interface. The package comes with two built-in handlers that usually should be adequate. But you may need to write your own handler, and that is not always straightforward. This guide is here to help.
Writing a handler requires an understanding of how the Logger and Handler types work together.
Each logger contains a handler. Certain Logger methods do some preliminary work, such as gathering key-value pairs into Attrs, and then call one or more Handler methods. These Logger methods are With, WithGroup, and the output methods.
An output method fulfills the main role of a logger: producing log output. Here is an example call to an output method:
logger.Info("hello", "key", value)
There are two general output methods, Log, and LogAttrs. For convenience, there is an output method for each of four common levels (Debug, Info, Warn and Error), and corresponding methods that take a context (DebugContext, InfoContext, WarnContext and ErrorContext).
Each Logger output method first calls its handler‘s Enabled method. If that call returns true, the method constructs a Record from its arguments and calls the handler’s Handle method.
As a convenience and an optimization, attributes can be added to Logger by calling the With method:
logger = logger.With("k", v)
This call creates a new Logger value with the argument attributes; the original remains unchanged. All subsequent output from logger will include those attributes. A logger‘s With method calls its handler’s WithAttrs method.
The WithGroup method is used to avoid avoid key collisions in large programs by establishing separate namespaces.
This call creates a new Logger value with a group named “g”:
logger = logger.WithGroup("g")
All subsequent keys for logger will be qualified by the group name “g”. Exactly what “qualified” means depends on how the logger's handler formats the output. The built-in TextHandler treats the group as a prefix to the key, separated by a dot: g.k for a key k, for example. The built-in JSONHandler uses the group as a key for a nested JSON object:
{"g": {"k": v}}
A logger‘s WithGroup method calls its handler’s WithGroup method.
Handler methodsWe can now talk about the four Handler methods in detail. Along the way, we will write a handler that formats logs using a format reminsicent of YAML. It will display this log output call:
logger.Info("hello", "key", 23)
something like this:
time: 2023-05-15T16:29:00 level: INFO message: "hello" key: 23 ---
Although this particular output is valid YAML, our implementation doesn‘t consider the subtleties of YAML syntax, so it will sometimes produce invalid YAML. For example, it doesn’t quote keys that have colons in them. We'll call it IndentHandler to forestall disappointment.
We begin with the IndentHandler type and the New function that constructs it from an io.Writer and options:
type IndentHandler struct {
opts Options
// TODO: state for WithGroup and WithAttrs
mu *sync.Mutex
out io.Writer
}
type Options struct {
// Level reports the minimum level to log.
// Levels with lower levels are discarded.
// If nil, the Handler uses [slog.LevelInfo].
Level slog.Leveler
}
func New(out io.Writer, opts *Options) *IndentHandler {
h := &IndentHandler{out: out, mu: &sync.Mutex{}}
if opts != nil {
h.opts = *opts
}
if h.opts.Level == nil {
h.opts.Level = slog.LevelInfo
}
return h
}
We'll support only one option, the ability to set a minimum level in order to supress detailed log output. Handlers should always use the slog.Leveler type for this option. Leveler is implemented by both Level and LevelVar. A Level value is easy for the user to provide, but changing the level of multiple handlers requires tracking them all. If the user instead passes a LevelVar, then a single change to that LevelVar will change the behavior of all handlers that contain it. Changes to LevelVars are goroutine-safe.
The mutex will be used to ensure that writes to the io.Writer happen atomically. Unusually, IndentHandler holds a pointer to a sync.Mutex rather than holding a sync.Mutex directly. There is a good reason for that, which we'll explain later.
TODO(jba): add link to that later explanation.
Our handler will need additional state to track calls to WithGroup and WithAttrs. We will describe that state when we get to those methods.
Enabled methodThe Enabled method is an optimization that can avoid unnecessary work. A Logger output method will call Enabled before it processes any of its arguments, to see if it should proceed.
The signature is
Enabled(context.Context, Level) bool
The context is available to allow decisions based on contextual information. For example, a custom HTTP request header could specify a minimum level, which the server adds to the context used for processing that request. A handler's Enabled method could report whether the argument level is greater than or equal to the context value, allowing the verbosity of the work done by each request to be controlled independently.
TODO(jba): include Enabled example
Handle methodThe Handle method is passed a Record containing all the information to be logged for a single call to a Logger output method. The Handle method should deal with it in some way. One way is to output the Record in some format, as TextHandler and JSONHandler do. But other options are to modify the Record and pass it on to another handler, enqueue the Record for later processing, or ignore it.
The signature of Handle is
Handle(context.Context, Record) error
The context is provided to support applications that provide logging information along the call chain. In a break with usual Go practice, the Handle method should not treat a canceled context as a signal to stop work.
If Handle processes its Record, it should follow the rules in the documentation. For example, a zero Time field should be ignored, as should zero Attrs.
A Handle method that is going to produce output should carry out the following steps:
Allocate a buffer, typically a []byte, to hold the output. It's best to construct the output in memory first, then write it with a single call to io.Writer.Write, to minimize interleaving with other goroutines using the same writer.
Format the special fields: time, level, message, and source location (PC). As a general rule, these fields should appear first and are not nested in groups established by WithGroup.
Format the result of WithGroup and WithAttrs calls.
Format the attributes in the Record.
Output the buffer.
That is how our IndentHandler's Handle method is structured:
func (h *IndentHandler) Handle(ctx context.Context, r slog.Record) error {
buf := make([]byte, 0, 1024)
if !r.Time.IsZero() {
buf = h.appendAttr(buf, slog.Time(slog.TimeKey, r.Time), 0)
}
buf = h.appendAttr(buf, slog.Any(slog.LevelKey, r.Level), 0)
if r.PC != 0 {
fs := runtime.CallersFrames([]uintptr{r.PC})
f, _ := fs.Next()
buf = h.appendAttr(buf, slog.String(slog.SourceKey, fmt.Sprintf("%s:%d", f.File, f.Line)), 0)
}
buf = h.appendAttr(buf, slog.String(slog.MessageKey, r.Message), 0)
indentLevel := 0
// TODO: output the Attrs and groups from WithAttrs and WithGroup.
r.Attrs(func(a slog.Attr) bool {
buf = h.appendAttr(buf, a, indentLevel)
return true
})
buf = append(buf, "---\n"...)
h.mu.Lock()
defer h.mu.Unlock()
_, err := h.out.Write(buf)
return err
}
The first line allocates a []byte that should be large enough for most log output. Allocating a buffer with some initial, fairly large capacity is a simple but significant optimization: it avoids the repeated copying and allocation that happen when the initial slice is empty or small. We'll return to this line in the section on speed and show how we can do even better.
The next part of our Handle method formats the special attributes, observing the rules to ignore a zero time and a zero PC.
Next, the method processes the result of WithAttrs and WithGroup calls. We'll skip that for now.
Then it's time to process the attributes in the argument record. We use the Record.Attrs method to iterate over the attributes in the order the user passed them to the Logger output method. Handlers are free to reorder or de-duplicate the attributes, but ours does not.
Lastly, after adding the line “---” to the output to separate log records, our handler makes a single call to h.out.Write with the buffer we've accumulated. We hold the lock for this write to make it atomic with respect to other goroutines that may be calling Handle at the same time.
TODO(jba): talk about appendAttr
WithAttrs methodOne of slog's performance optimizations is support for pre-formatting attributes. The Logger.With method converts key-value pairs into Attrs and then calls Handler.WithAttrs. The handler may store the attributes for later consumption by the Handle method, or it may take the opportunity to format the attributes now, once, rather than doing so repeatedly on each call to Handle.
The signature of the WithAttrs method is
WithAttrs(attrs []Attr) Handler
The attributes are the processed key-value pairs passed to Logger.With. The return value should be a new instance of your handler that contains the attributes, possibly pre-formatted.
WithAttrs must return a new handler with the additional attributes, leaving the original handler (its receiver) unchanged. For example, this call:
logger2 := logger1.With("k", v)
creates a new logger, logger2, with an additional attribute, but has no effect on logger1.
We will show an example implementation of WithAttrs below, when we discuss WithGroup.
WithGroup methodLogger.WithGroup calls Handler.WithGroup directly, with the same argument, the group name. A handler should remember the name so it can use it to qualify all subsequent attributes.
The signature of WithGroup is:
WithGroup(name string) Handler
Like WithAttrs, the WithGroup method should return a new handler, not modify the receiver.
The implementations of WithGroup and WithAttrs are intertwined. Consider this statement:
logger = logger.WithGroup("g1").With("k1", 1).WithGroup("g2").With("k2", 2)
Subsequent logger output should qualify key “k1” with group “g1”, and key “k2” with groups “g1” and “g2”. The order of the Logger.WithGroup and Logger.With calls must be respected by the implementations of Handler.WithGroup and Handler.WithAttrs.
We will look at two implementations of WithGroup and WithAttrs, one that pre-formats and one that doesn't.
TODO(jba): add IndentHandler examples
To verify that your handler follows these rules and generally produces proper output, use the testing/slogtest package.
TODO(jba): show the test function.
TODO(jba): reintroduce the material on Record.Clone that used to be here.
A handler must work properly when a single Logger is shared among several goroutines. That means that mutable state must be protected with a lock or some other mechanism. In practice, this is not hard to achieve, because many handlers won't have any mutable state.
The Enabled method typically consults only its arguments and a configured level. The level is often either set once initially, or is held in a LevelVar, which is already concurrency-safe.
The WithAttrs and WithGroup methods should not modify the receiver, for reasons discussed above.
The Handle method typically works only with its arguments and stored fields.
Calls to output methods like io.Writer.Write should be synchronized unless it can be verified that no locking is needed. Beware of facile claims like “Unix writes are atomic”; the situation is a lot more nuanced than that.
Some handlers have legitimate reasons for keeping state. For example, a handler might support a SetLevel method to change its configured level dynamically. Or it might output the time between sucessive calls to Handle, which requires a mutable field holding the last output time. Synchronize all accesses to such fields, both reads and writes.
The built-in handlers have no directly mutable state. They use a mutex only to sequence calls to their contained io.Writer.
Logging is often the debugging technique of last resort. When it is difficult or impossible to inspect a system, as is typically the case with a production server, logs provide the most detailed way to understand its behavior. Therefore, your handler should be robust to bad input.
For example, the usual advice when when a function discovers a problem, like an invalid argument, is to panic or return an error. The built-in handlers do not follow that advice. Few things are more frustrating than being unable to debug a problem that causes logging to fail; our feeling is that it is better to produce some output, however imperfect, than to produce none at all. That is why methods like Logger.Info convert programming bugs in their list of key-value pairs, like missing values or malformed keys, into Attrs that contain as much information as possible.
One place to avoid panics is in processing attribute values. A handler that wants to format a value will probably switch on the value's kind:
switch attr.Value.Kind() {
case KindString: ...
case KindTime: ...
// all other Kinds
default: ...
}
What should happen in the default case, when the handler encounters a Kind that it doesn‘t know about? The built-in handlers try to muddle through by using the result of the value’s String method. They do not panic or return an error. Your own handlers might in addition want to report the problem through your production monitoring or error-tracking telemetry system. The most likely explanation for the issue is that a newer version of the slog package added a new Kind—a backwards-compatible change under the Go 1 Compatibility Promise—and the handler wasn‘t updated. That is certainly a problem, but it shouldn’t deprive readers of the logs from seeing the rest of the output.
There is one circumstance where returning an error from Handler.Handle is appropriate. If the output operation itself fails, the best course of action is to report this failure by returning the error. For instance, the last two lines of the built-in Handle methods are
_, err := h.w.Write(*state.buf) return err
Although the output methods of Logger ignore the error, one could write a handler that does something with it, perhaps falling back to writing to standard error.
TODO(jba): discuss
TODO(jba): show how to pool a []byte.