Tags: #go #logs
Simple TEXT implementation:
var logger = slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
AddSource: true,
ReplaceAttr: func(g []string, a slog.Attr) slog.Attr {
// Ensure time is always logged in UTC.
if len(g) == 0 && a.Key == slog.TimeKey {
a.Value = slog.TimeValue(a.Value.Time().UTC())
}
// Remove the directory from the source's filename.
if a.Key == slog.SourceKey {
source := a.Value.Any().(*slog.Source)
source.File = filepath.Base(source.File)
}
return a
},
}))
Simple JSON implementation that shows how to switch log level at runtime:
package main
import (
"context"
"fmt"
"log/slog"
"os"
)
var Level = new(slog.LevelVar)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: Level}))
ctx := context.Background()
logger.LogAttrs(ctx, slog.LevelInfo, "info_one") // printed
logger.LogAttrs(ctx, slog.LevelDebug, "debug_one") // not printed
logger.Debug("debug_two", "foo", "bar") // not printed
fmt.Println("---")
Level.Set(slog.LevelDebug)
logger.LogAttrs(ctx, slog.LevelInfo, "info_one") // printed
logger.LogAttrs(ctx, slog.LevelDebug, "debug_one") // printed
logger.Debug("debug_two", "foo", "bar", slog.Bool("whatever", true)) // printed
}
https://play.golang.com/p/yvbOC1lXRGI
Here is an example that demonstrates how groups work and how they can be nested:
package main
import (
"context"
"log/slog"
"os"
)
func main() {
logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo}))
ctx := context.Background()
logger.LogAttrs(ctx, slog.LevelInfo, "one", slog.String("foo", "bar"))
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"one","foo":"bar"}
logger = logger.WithGroup("mirror")
logger.LogAttrs(ctx, slog.LevelInfo, "two", slog.String("beep", "boop"))
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"two","mirror":{"beep":"boop"}}
attrs := []any{
slog.String("method", "GET"),
}
logger = logger.With(slog.Group("origin_req", attrs...))
logger.LogAttrs(ctx, slog.LevelInfo, "two", slog.String("whatever", "wherever"))
// {"time":"2009-11-10T23:00:00Z","level":"INFO","msg":"two","mirror":{"origin_req":{"method":"GET"},"whatever":"wherever"}}
}
https://play.golang.com/p/F3lBGUhfVkM
[!IMPORTANT] Notice
logger.WithGroup("mirror")is left “open”.
There are no attributes pass like withlogger.With(slog.Group("origin_req", attrs...)).
This meansslog.String("beep", "boop")is logged within the"mirror"group.
This is a working example as used by Domainr
https://go.dev/play/p/TH_HdwDaUiN
Here is a text version that’s slightly different in setup (more flexible as it doesn’t constrain via an interface): https://go.dev/play/p/1TPwtbQB_Oy
package main
import (
"context"
"fmt"
"log/slog"
"os"
"play.ground/logging"
)
func main() {
ctx := context.Background()
logger := logging.NewLogger()
logger.LogAttrs(ctx, slog.LevelDebug, "some_event", slog.String("foo", "bar"))
logger.LogAttrs(ctx, slog.LevelInfo, "some_event", slog.String("foo", "bar"))
logger.LogAttrs(ctx, slog.LevelWarn, "some_event", slog.String("foo", "bar"))
logger.LogAttrs(ctx, slog.LevelError, "some_event", slog.String("foo", "bar"))
fmt.Println("NOTICE NO DEBUG LOG ABOVE, BUT THERE IS BELOW (AFTER CHANGING LOG LEVEL)")
logging.Level.Set(slog.LevelDebug)
logger.LogAttrs(ctx, slog.LevelDebug, "some_event", slog.String("foo", "bar"))
logger = logging.NewLoggerWithOutputLevel(os.Stdout, logging.Level)
logger.LogAttrs(ctx, slog.LevelDebug, "some_event", slog.String("foo", "bar"))
logger.LogAttrs(ctx, slog.LevelInfo, "some_event", slog.String("foo", "bar"))
logger.LogAttrs(ctx, slog.LevelWarn, "some_event", slog.String("foo", "bar"))
logger.LogAttrs(ctx, slog.LevelError, "some_event", slog.String("foo", "bar"))
}
-- go.mod --
module play.ground
-- logging/logging.go --
package logging
import (
"context"
"io"
"log"
"log/slog"
"os"
"path/filepath"
"strconv"
"strings"
)
// Level allows dynamically changing the output level via .Set() method.
// Defaults to [slog.LevelInfo].
var Level = new(slog.LevelVar)
// Logger describes the set of features we want to expose from log/slog.
//
// NOTE: Don't confuse our custom With() signature with (*slog.Logger).With
// We return a Logger type where the standard library returns a *slog.Logger
type Logger interface {
Enabled(ctx context.Context, level slog.Level) bool
LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr)
With(args ...any) Logger
_private()
}
// NewLogger returns a logging.Logger configured for stderr.
func NewLogger() Logger {
return NewLoggerWithOutputLevel(os.Stdout, Level)
}
// NewLoggerWithOutput returns a [Logger] configured with an output writer.
func NewLoggerWithOutput(w io.Writer) Logger {
return (*logger)(slog.New(slog.NewJSONHandler(w, defaultOptions()).WithAttrs(defaultAttrs())))
}
// NewLoggerWithOutputLevel returns a [Logger] configured with an output writer and Level.
func NewLoggerWithOutputLevel(w io.Writer, l slog.Leveler) Logger {
opts := defaultOptions()
opts.Level = l
return (*logger)(slog.New(slog.NewJSONHandler(w, opts).WithAttrs(defaultAttrs())))
}
// NewBareLoggerWithOutputLevel returns a [Logger] configured with an output location and [slog.Leveler].
// It does not include any additional attributes.
func NewBareLoggerWithOutputLevel(w io.Writer, l slog.Leveler) Logger {
opts := defaultOptions()
opts.Level = l
return (*logger)(slog.New(slog.NewJSONHandler(w, opts)))
}
// nolint:revive
//
//lint:ignore U1000 Prevents any other package from implementing this interface
type private struct{} //nolint:unused
// IMPORTANT: logger is an alias to slog.Logger to avoid a double-pointer deference.
// All methods off the type will need to type-cast a *logger to *slog.Logger.
// With() must additionally type-cast back to a Logger compatible type.
type logger slog.Logger
func (*logger) _private() {}
func (l *logger) Enabled(ctx context.Context, level slog.Level) bool {
return (*slog.Logger)(l).Enabled(ctx, level)
}
func (l *logger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) {
(*slog.Logger)(l).LogAttrs(ctx, level, msg, attrs...)
}
func (l *logger) With(args ...any) Logger {
return (*logger)((*slog.Logger)(l).With(args...))
}
// Adapt returns a [log.Logger] for use with packages that are not yet compatible with
// [log/slog].
func Adapt(l Logger, level slog.Level) *log.Logger {
// _private() ensures this type assertion cannot panic.
slogger := (*slog.Logger)(l.(*logger)) //nolint:revive,forcetypeassert
return slog.NewLogLogger(slogger.Handler(), level)
}
func defaultOptions() *slog.HandlerOptions {
return &slog.HandlerOptions{
AddSource: true,
ReplaceAttr: slogReplaceAttr,
Level: Level,
}
}
func defaultAttrs() []slog.Attr {
return []slog.Attr{slog.Group("app",
slog.String("name", "my app name"),
slog.String("version", "my app version"),
)}
}
// NullLogger discards logs.
func NullLogger() Logger {
// NOTE: We pass a level not currently defined to reduce operational overhead.
// The intent, unlike passing nil for the opts argument, is for the logger to
// not even bother generating a message that will just be discarded.
// An additional gap of 4 was used as it aligns with Go's original design.
// https://github.com/golang/go/blob/1e95fc7/src/log/slog/level.go#L34-L42
return (*logger)(slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelError + 4}))) //nolint:gomnd
}
// slogReplaceAttr adjusts the log output.
//
// - Restricts these changes to top-level keys (not keys within groups)
// - Changes default time field value to UTC time zone
// - Replaces msg key with event
// - Omits event field if empty
// - Omits error field if when nil
// - Truncates source's filename to domainr-api directory
//
// - Formats duration and delay values in microseconds as xxxxµs
//
// See https://pkg.go.dev/log/slog#HandlerOptions.ReplaceAttr
// N.B: TextHandler manages quoting attribute values as necessary.
func slogReplaceAttr(groups []string, a slog.Attr) slog.Attr {
// Limit application of these rules only to top-level keys
if len(groups) == 0 {
// Set time zone to UTC
if a.Key == slog.TimeKey {
a.Value = slog.TimeValue(a.Value.Time().UTC())
return a
}
// Use event as the default MessageKey, remove if empty
if a.Key == slog.MessageKey {
a.Key = "event"
if a.Value.String() == "" {
return slog.Attr{}
}
return a
}
// Display a 'partial' path.
// Avoids ambiguity when multiple files have the same name across packages.
// e.g. billing.go appears under 'global', 'billing' and 'server' packages.
if a.Key == slog.SourceKey {
if source, ok := a.Value.Any().(*slog.Source); ok {
a.Key = "caller"
if _, after, ok := strings.Cut(source.File, "domainr-api"+string(filepath.Separator)); ok {
source.File = after
}
}
return a
}
}
// Remove error key=value when error is nil
if a.Equal(slog.Any("error", error(nil))) {
return slog.Attr{}
}
// Present durations and delays as xxxxµs
switch a.Key {
case "dur", "delay", "p95", "previous_p95", "remaining", "max_wait":
a.Value = slog.StringValue(strconv.FormatInt(a.Value.Duration().Microseconds(), 10) + "µs")
}
return a
}
// https://go.dev/play/p/dgMult9xaao
//
// Code copied verbatim from https://github.com/veqryn/slog-dedup
package main
import (
"context"
"fmt"
"log/slog"
"os"
"modernc.org/b/v2" // Package b implements the B+tree flavor of a BTree.
)
func main() {
slogger := slog.New(NewOverwriteHandler(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
Level: slog.LevelDebug,
})))
FuncA(slogger, "foo")
}
func FuncA(l *slog.Logger, someAttr string) {
l = l.With(slog.String("foo", someAttr))
l.Debug("FuncA")
FuncB(l, "foo") // "foo":"foo"
}
func FuncB(l *slog.Logger, someAttr string) {
l = l.With(slog.String("foo", someAttr))
l.Debug("FuncB")
FuncC(l, someAttr) // "foo":"foo","foo":"foo"
}
func FuncC(l *slog.Logger, someAttr string) {
l = l.With(slog.String("foo", someAttr))
l.Debug("FuncC") // "foo":"foo","foo":"foo","foo":"foo"
}
// NewOverwriteHandler creates an OverwriteHandler slog.Handler middleware that will deduplicate all attributes and
// groups by overwriting any older attributes or groups with the same string key.
// It passes the final record and attributes off to the next handler when finished.
func NewOverwriteHandler(next slog.Handler) *OverwriteHandler {
return &OverwriteHandler{
next: next,
keyCompare: CaseSensitiveCmp,
getKey: getKeyClosure(IncrementIfBuiltinKeyConflict),
}
}
// OverwriteHandler is a slog.Handler middleware that will deduplicate all attributes and
// groups by overwriting any older attributes or groups with the same string key.
// It passes the final record and attributes off to the next handler when finished.
type OverwriteHandler struct {
next slog.Handler
goa *groupOrAttrs
keyCompare func(a, b string) int
getKey func(key string, depth int) (string, bool)
}
// Enabled reports whether the next handler handles records at the given level.
// The handler ignores records whose level is lower.
func (h *OverwriteHandler) Enabled(ctx context.Context, level slog.Level) bool {
return h.next.Enabled(ctx, level)
}
// Handle de-duplicates all attributes and groups, then passes the new set of attributes to the next handler.
func (h *OverwriteHandler) Handle(ctx context.Context, r slog.Record) error {
// The final set of attributes on the record, is basically the same as a final With-Attributes groupOrAttrs.
// So collect all final attributes and turn them into a groupOrAttrs so that it can be handled the same.
finalAttrs := make([]slog.Attr, 0, r.NumAttrs())
r.Attrs(func(a slog.Attr) bool {
finalAttrs = append(finalAttrs, a)
return true
})
goas := collectGroupOrAttrs(h.goa, &groupOrAttrs{attrs: finalAttrs})
// Resolve groups and with-attributes
uniq := b.TreeNew[string, any](h.keyCompare)
h.createAttrTree(uniq, goas, 0)
// Add all attributes to new record (because old record has all the old attributes)
newR := &slog.Record{
Time: r.Time,
Level: r.Level,
Message: r.Message,
PC: r.PC,
}
// Add deduplicated attributes back in
newR.AddAttrs(buildAttrs(uniq)...)
return h.next.Handle(ctx, *newR)
}
// WithGroup returns a new OverwriteHandler that still has h's attributes,
// but any future attributes added will be namespaced.
func (h *OverwriteHandler) WithGroup(name string) slog.Handler {
h2 := *h
h2.goa = h2.goa.WithGroup(name)
return &h2
}
// WithAttrs returns a new OverwriteHandler whose attributes consists of h's attributes followed by attrs.
func (h *OverwriteHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
h2 := *h
h2.goa = h2.goa.WithAttrs(attrs)
return &h2
}
// createAttrTree recursively goes through all groupOrAttrs, resolving their attributes and creating subtrees as
// necessary, adding the results to the map
func (h *OverwriteHandler) createAttrTree(uniq *b.Tree[string, any], goas []*groupOrAttrs, depth int) {
if len(goas) == 0 {
return
}
// If a group is encountered, create a subtree for that group and all groupOrAttrs after it
if goas[0].group != "" {
if key, ok := h.getKey(goas[0].group, depth); ok {
uniqGroup := b.TreeNew[string, any](h.keyCompare)
h.createAttrTree(uniqGroup, goas[1:], depth+1)
// Ignore empty groups, otherwise put subtree into the map
if uniqGroup.Len() > 0 {
uniq.Set(key, uniqGroup)
}
return
}
}
// Otherwise, set all attributes for this groupOrAttrs, and then call again for remaining groupOrAttrs's
h.resolveValues(uniq, goas[0].attrs, depth)
h.createAttrTree(uniq, goas[1:], depth)
}
// resolveValues iterates through the attributes, resolving them and putting them into the map.
// If a group is encountered (as an attribute), it will be separately resolved and added as a subtree.
// Since attributes are ordered from oldest to newest, it overwrites keys as it goes.
func (h *OverwriteHandler) resolveValues(uniq *b.Tree[string, any], attrs []slog.Attr, depth int) {
var ok bool
for _, a := range attrs {
a.Value = a.Value.Resolve()
if a.Equal(slog.Attr{}) {
continue // Ignore empty attributes, and keep iterating
}
// Default situation: resolve the key and put it into the map
a.Key, ok = h.getKey(a.Key, depth)
if !ok {
continue
}
if a.Value.Kind() != slog.KindGroup {
uniq.Set(a.Key, a)
continue
}
// Groups with empty keys are inlined
if a.Key == "" {
h.resolveValues(uniq, a.Value.Group(), depth)
continue
}
// Create a subtree for this group
uniqGroup := b.TreeNew[string, any](h.keyCompare)
h.resolveValues(uniqGroup, a.Value.Group(), depth+1)
// Ignore empty groups, otherwise put subtree into the map
if uniqGroup.Len() > 0 {
uniq.Set(a.Key, uniqGroup)
}
}
}
// buildAttrs converts the deduplicated map back into an attribute array,
// with any subtrees converted into slog.Group's
func buildAttrs(uniq *b.Tree[string, any]) []slog.Attr {
en, emptyErr := uniq.SeekFirst()
if emptyErr != nil {
return nil // Empty (btree only returns an error when empty)
}
defer en.Close()
// Iterate through all values in the map, add to slice
attrs := make([]slog.Attr, 0, uniq.Len())
for k, i, err := en.Next(); err == nil; k, i, err = en.Next() {
// Values will either be an attribute, a subtree, or a specially appended slice of the former two
switch v := i.(type) {
case slog.Attr:
attrs = append(attrs, v)
case *b.Tree[string, any]:
// Convert subtree into a group
attrs = append(attrs, slog.Attr{Key: k, Value: slog.GroupValue(buildAttrs(v)...)})
case appended:
// This case only happens in the AppendHandler
anys := make([]any, 0, len(v))
for _, sliceVal := range v {
switch sliceV := sliceVal.(type) {
case slog.Attr:
anys = append(anys, sliceV.Value.Any())
case *b.Tree[string, any]:
// Convert subtree into a map (because having a Group Attribute within a slice doesn't render)
anys = append(anys, buildGroupMap(buildAttrs(sliceV)))
default:
panic("unexpected type in attribute map")
}
}
attrs = append(attrs, slog.Any(k, anys))
default:
panic("unexpected type in attribute map")
}
}
return attrs
}
// appended is a type that exists to allow us to differentiate between a log attribute that is a slice or any's ([]any),
// versus when we are appending to the key so that it becomes a slice. Only used with the AppendHandler.
type appended []any
// buildGroupMap takes a slice of attributes (the attributes within a group), and turns them into a map of string keys
// to a non-attribute resolved value (any).
// This function exists solely to deal with groups that are inside appended-slices (for the AppendHandler),
// because slog does not have a "slice" kind, which means that those groups and their values do not render at all.
func buildGroupMap(attrs []slog.Attr) map[string]any {
group := map[string]any{}
for _, attr := range attrs {
if attr.Value.Kind() != slog.KindGroup {
group[attr.Key] = attr.Value.Any()
} else {
group[attr.Key] = buildGroupMap(attr.Value.Group())
}
}
return group
}
// groupOrAttrs holds either a group name or a list of slog.Attrs.
// It also holds a reference/link to its parent groupOrAttrs, forming a linked list.
type groupOrAttrs struct {
group string // group name if non-empty
attrs []slog.Attr // attrs if non-empty
next *groupOrAttrs // parent
}
// WithGroup returns a new groupOrAttrs that includes the given group, and links to the old groupOrAttrs.
// Safe to call on a nil groupOrAttrs.
func (g *groupOrAttrs) WithGroup(name string) *groupOrAttrs {
// Empty-name groups are inlined as if they didn't exist
if name == "" {
return g
}
return &groupOrAttrs{
group: name,
next: g,
}
}
// WithAttrs returns a new groupOrAttrs that includes the given attrs, and links to the old groupOrAttrs.
// Safe to call on a nil groupOrAttrs.
func (g *groupOrAttrs) WithAttrs(attrs []slog.Attr) *groupOrAttrs {
if len(attrs) == 0 {
return g
}
return &groupOrAttrs{
attrs: attrs,
next: g,
}
}
// collectGroupOrAttrs unrolls all individual groupOrAttrs and collects them into a slice, ordered from oldest to newest
func collectGroupOrAttrs(gs ...*groupOrAttrs) []*groupOrAttrs {
// Get a total count of all groups in the group linked-list chain
n := 0
for _, g := range gs {
for ga := g; ga != nil; ga = ga.next {
n++
}
}
// The groupOrAttrs on the handler is a linked list starting from the newest to the oldest set of attributes/groups.
// Within each groupOrAttrs, all attributes are in a slice that is ordered from oldest to newest.
// To make things consistent we will reverse the order of the groupOrAttrs, so that it goes from oldest to newest,
// thereby matching the order of the attributes.
res := make([]*groupOrAttrs, n)
j := 0
for i := len(gs) - 1; i >= 0; i-- {
for ga := gs[i]; ga != nil; ga = ga.next {
res[len(res)-j-1] = ga
j++
}
}
return res
}
// CaseSensitiveCmp is a case-sensitive comparison and ordering function that orders by byte values
func CaseSensitiveCmp(a, b string) int {
if a == b {
return 0
}
if a > b {
return 1
}
return -1
}
// IncrementIfBuiltinKeyConflict will, if there is a conflict/duplication at the root level (not in a group) with one of
// the built-in keys, add "#01" to the end of the key
func IncrementIfBuiltinKeyConflict(key string) (string, bool) {
if DoesBuiltinKeyConflict(key) {
return IncrementKeyName(key, 1), true // Don't overwrite the built-in attribute keys
}
return key, true
}
// DoesBuiltinKeyConflict returns true if the key conflicts with the builtin keys.
// This will only be called on all root level (not in a group) attribute keys.
func DoesBuiltinKeyConflict(key string) bool {
if key == slog.TimeKey || key == slog.LevelKey || key == slog.MessageKey || key == slog.SourceKey {
return true
}
return false
}
// IncrementKeyName adds a count onto the key name after the first seen.
// Example: keyname, keyname#01, keyname#02, keyname#03
func IncrementKeyName(key string, index int) string {
if index == 0 {
return key
}
return fmt.Sprintf("%s#%02d", key, index)
}
// getKeyClosure returns a function to be used to resolve a key at the root level, determining its behavior when it
// would otherwise conflict/duplicate the 4 built-in attribute keys (time, level, msg, source).
func getKeyClosure(resolveBuiltinKeyConflict func(k string) (string, bool)) func(key string, depth int) (string, bool) {
return func(key string, depth int) (string, bool) {
if depth == 0 {
return resolveBuiltinKeyConflict(key)
}
return key, true
}
}
package logging
import (
"context"
"fmt"
"io"
"log/slog"
"os"
"path/filepath"
"strings"
"github.com/domainr/mustang/internal/version"
)
// Logger describes the set of features we want to expose from log/slog.
type Logger interface {
Enabled(ctx context.Context, level slog.Level) bool
LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr)
With(args ...any) *slog.Logger
}
// Level allows dynamically changing the log level via .Set() method.
var Level = new(slog.LevelVar)
// NewLogger returns a logging.Logger configured for stderr.
func NewLogger() Logger {
return NewLoggerWithOutput(os.Stderr)
}
// NewLoggerWithOutput returns a logging.Logger configured with a specific
// output location.
func NewLoggerWithOutput(w io.Writer) Logger {
opts, attrs := loggerDefaults()
return slog.New(slog.NewTextHandler(w, opts).WithAttrs(attrs))
}
// NewLoggerWithOutputLevel returns a logging.Logger configured with a specific
// output location and Level.
func NewLoggerWithOutputLevel(w io.Writer, l slog.Leveler) Logger {
opts, attrs := loggerDefaults()
opts.Level = l
return slog.New(slog.NewTextHandler(w, opts).WithAttrs(attrs))
}
func loggerDefaults() (*slog.HandlerOptions, []slog.Attr) {
appName := strings.Replace(os.Getenv("HEROKU_APP_NAME"), "mustang", "heroku", 1)
if appName == "" {
appName = os.Getenv("USER")
}
opts := &slog.HandlerOptions{
AddSource: true,
ReplaceAttr: slogReplaceAttr,
Level: Level,
}
attrs := []slog.Attr{
slog.Group("mustang",
slog.String("name", appName),
slog.String("version", version.Version()),
),
}
return opts, attrs
}
// NullLogger discards logs.
func NullLogger() Logger {
// NOTE: We pass a level not currently defined to reduce operational overhead.
// The intent, unlike passing nil for the opts argument, is for the logger to
// not even bother generating a message that will just be discarded.
// An additional gap of 4 was used as it aligns with Go's original design.
// https://github.com/golang/go/blob/1e95fc7/src/log/slog/level.go#L34-L42
return slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelError + 4}))
}
// slogReplaceAttr adjusts the output format of some attributes:
// - changes timestamps to UTC time zone
// - shortens source.File by removing path
// - elides error=<nil>
// - formats dur values in microseconds as NNNµs
// See https://pkg.go.dev/log/slog#HandlerOptions.ReplaceAttr
// N.B: TextHandler manages quoting attribute values as necessary.
func slogReplaceAttr(groups []string, a slog.Attr) slog.Attr {
// Limit application of these rules only to top-level keys
if len(groups) == 0 {
// Set time zone to UTC
if a.Key == slog.TimeKey {
a.Value = slog.TimeValue(a.Value.Time().UTC())
return a
}
// Remove empty msg=""
if a.Equal(slog.String(slog.MessageKey, "")) {
return slog.Attr{}
}
// Remove error key=value when error is nil
if a.Equal(slog.Any("error", error(nil))) {
return slog.Attr{}
}
// Display a 'partial' path.
// Avoids ambiguity when multiple files have the same name across packages.
// e.g. billing.go appears under 'global', 'billing' and 'server' packages.
if a.Key == slog.SourceKey {
if source, ok := a.Value.Any().(*slog.Source); ok {
a.Key = "caller"
if _, after, ok := strings.Cut(source.File, "mustang"+string(filepath.Separator)); ok {
source.File = after
}
return a
}
}
}
// Present durations and delays as xxxxµs
switch a.Key {
case "dur", "delay", "p95", "previous_p95", "remaining", "max_wait":
a.Value = slog.StringValue(fmt.Sprintf("%dµs", a.Value.Duration().Microseconds()))
}
return a
}
package logging
import (
"bytes"
"context"
"fmt"
"log/slog"
"path/filepath"
"strings"
"testing"
"time"
)
func TestLogger(t *testing.T) {
buf := new(bytes.Buffer)
l := NewLoggerWithOutput(buf)
t.Run("has expected fields", func(t *testing.T) {
dumpLogs(t, buf)
l.LogAttrs(context.Background(), slog.LevelInfo, "test message")
out := buf.String()
for _, field := range []string{
"time",
"level",
"caller",
"mustang.name",
"mustang.version",
} {
if !strings.Contains(out, field+"=") {
t.Errorf("missing field %q:", field)
}
}
})
t.Run("adds non-default levels", func(t *testing.T) {
dumpLogs(t, buf)
ctx := context.Background()
tests := []struct {
level slog.Level
enabled bool
want string
}{
{slog.LevelDebug, false, ""},
{slog.LevelInfo, true, "level=INFO"},
{slog.LevelWarn, true, "level=WARN"},
{slog.LevelError, true, "level=ERROR"},
{slog.Level(12), true, "level=ERROR+4"},
}
for _, tt := range tests {
l.LogAttrs(ctx, tt.level, "")
// WARNING: strings.Contains can return true on a "" substr.
// For example: LevelInfo with "" would pass, which is misleading.
// Because the test would suggest that `level=INFO` shouldn't appear in the output.
if tt.enabled && !strings.Contains(buf.String(), tt.want) {
t.Errorf("missing level=%s", tt.level)
}
if got := l.Enabled(ctx, tt.level); tt.enabled != got {
t.Errorf("enabled = %t at level=%s", got, tt.level)
}
}
})
t.Run("adds debug at LevelDebug", func(t *testing.T) {
dumpLogs(t, buf)
ctx := context.Background()
l = NewLoggerWithOutputLevel(buf, slog.LevelDebug)
l.LogAttrs(ctx, slog.LevelDebug, "")
out := buf.String()
if !strings.Contains(out, "level=DEBUG") {
t.Errorf("missing level=DEBUG")
}
})
t.Run("elides empty message", func(t *testing.T) {
dumpLogs(t, buf)
l.LogAttrs(context.Background(), slog.LevelInfo, "")
out := buf.String()
if s := "msg="; strings.Contains(out, s) {
t.Errorf("log should not contain %q:", s)
}
})
t.Run("elides empty error", func(t *testing.T) {
dumpLogs(t, buf)
l.LogAttrs(context.Background(), slog.LevelInfo, "test message", slog.Any("error", nil))
out := buf.String()
if s := "error="; strings.Contains(out, s) {
t.Errorf("log should not contain %q:", s)
}
})
t.Run("uses UTC time zone", func(t *testing.T) {
dumpLogs(t, buf)
l.LogAttrs(context.Background(), slog.LevelInfo, "UTC")
out := buf.String()
ts := logFieldValue(out, "time")
p, err := time.Parse(time.RFC3339, ts)
if err != nil {
t.Fatalf("time field failed to parse: %s", err)
}
if z, _ := p.Zone(); z != time.UTC.String() {
t.Errorf("expected time in UTC zone, got %s", z)
}
})
t.Run("uses short source location", func(t *testing.T) {
dumpLogs(t, buf)
l.LogAttrs(context.Background(), slog.LevelInfo, "source loc")
out := buf.String()
source := logFieldValue(out, "source")
if strings.HasPrefix(source, string(filepath.Separator)) {
t.Errorf("source includes full path: %s", source)
}
})
t.Run("displays microseconds", func(t *testing.T) {
dumpLogs(t, buf)
const ts = 1234567890
l.LogAttrs(context.Background(), slog.LevelInfo, "",
slog.Duration("dur", ts),
slog.Duration("delay", ts),
slog.Duration("p95", ts),
slog.Duration("previous_p95", ts),
slog.Duration("remaining", ts),
slog.Duration("max_wait", ts),
)
out := buf.String()
for _, field := range []string{
"dur",
"delay",
"p95",
"previous_p95",
"remaining",
"max_wait",
} {
want := fmt.Sprintf("%s=%d%s", field, 1234567, "µs")
if !strings.Contains(out, want) {
t.Errorf("log should contain: %s", want)
}
}
})
}
func logFieldValue(s, field string) string {
prefix := field + "="
i := strings.Index(s, prefix)
if i == -1 {
return s
}
i += len(prefix)
return s[i : i+strings.Index(s[i:], " ")]
}
func dumpLogs(t *testing.T, buf *bytes.Buffer) {
t.Helper()
t.Cleanup(func() {
t.Helper()
if t.Failed() || testing.Verbose() {
t.Log("Logs:\n", buf.String())
}
buf.Reset()
})
}
// Reference:
// https://betterstack.com/community/guides/logging/logging-in-go/
//
// Playground Example:
// https://goplay.tools/snippet/Ty_22SjTQ1j
package main
import (
"context"
"errors"
"fmt"
"log/slog"
"os"
"path/filepath"
"strings"
)
func main() {
logLevelHandler := new(slog.LevelVar)
opts := &slog.HandlerOptions{
AddSource: true,
ReplaceAttr: slogReplaceAttr,
Level: logLevelHandler, // LevelVar allows for dynamic changing of the log level at runtime!
}
attrs := []slog.Attr{
slog.String("my_field", "is_this"),
slog.Group("fastly",
slog.String("example", os.Getenv("SOME_EXAMPLE")),
),
}
logger := slog.New(slog.NewTextHandler(os.Stderr, opts).WithAttrs(attrs)) // alternatively use slog.NewJSONHandler()
logger.Debug("Debug message 1") // not displayed
logger.Info("Info message")
logger.Warn("Warning message")
logger.Error("Error message")
logLevelHandler.Set(slog.LevelDebug) // dynamically switch the log level
logger.Debug("Debug message 2") // is displayed
// MUCH MORE PEFORMANT!
logger.LogAttrs(context.Background(), slog.LevelInfo, "xxxxxxxxxxxxxxxxxx",
slog.String("foo", "bar"),
)
var e error = ErrFoo{Code: 123, Err: errors.New("whoops")}
logger.LogAttrs(context.Background(), slog.LevelError, "",
slog.String("error", e.Error()),
)
logger.LogAttrs(context.Background(), slog.LevelError, "",
slog.Any("error", e),
)
newLogger := logger.With(slog.Group("some_group", slog.String("foo", "bar")))
newLogger.Info("with group")
newLoggerWithDuplicateGroup := newLogger.With(slog.Group("some_group", slog.String("inside_duplicate_group", "whatever"))) // the duplicated group isn't replaced, the attrs are appended to the original group
newLoggerWithDuplicateGroup.Info("with duplicate group")
newLoggerWithDuplicateGroup.LogAttrs(context.Background(), slog.LevelInfo, "does an inline group append to existing group on the logger?",
slog.Group("some_group", slog.String("a_new_inline_group_key", "with some value")), // the inlined group is appended to the original group
)
newLoggerWithEmptyGroup := newLogger.With(slog.Group("some_empty_group")) // Groups will be omitted if no attributes found
newLoggerWithEmptyGroup.Info("with empty group")
logger.LogAttrs(context.Background(), slog.LevelError, "inline group",
slog.Group("some_group", slog.String("foo", "bar")), // inline a slog.Group with other slog.Attr
)
logger.LogAttrs(context.Background(), slog.LevelError, "inline group will be omitted",
slog.Group("some_group"),
)
loggerWithDuplicateField := logger.With(slog.String("my_field", "is_now_overridden")) // NOPE! It's duplicated! so you'll have to fix that in slogReplaceAttr
loggerWithDuplicateField.Info("my message to see if my_field is overridden")
attribute := slog.Any("some_array", []string{"x", "y", "z"})
logger.Info("what does a slice look like", attribute)
thing := Foo
logger.LogAttrs(context.Background(), slog.LevelError, "what does a custom iota type look like",
slog.Any("my_thing", thing),
)
st := StructThing{"foo here", 123, true}
slog.LogAttrs(context.Background(), slog.LevelInfo, "message text", slog.Any("", st)) // no field == foo="foo here" bar=123 baz=true
slog.LogAttrs(context.Background(), slog.LevelInfo, "message text", slog.Any("agent", st)) // field specified == agent.foo="foo here" agent.bar=123 agent.baz=true
}
type StructThing struct {
Foo string
Bar int
Baz bool
}
func (st StructThing) LogValue() slog.Value {
return slog.GroupValue(
slog.String("foo", st.Foo),
slog.Int("bar", st.Bar),
slog.Bool("baz", st.Baz),
)
}
type Thing uint32
const (
Unknown Thing = iota
Foo Thing = 1 << (iota - 1)
Bar
Baz
)
// slogReplaceAttr adjusts the output format of some attributes:
// - changes timestamps to UTC time zone
// - shortens source.File by removing path
// - elides error=<nil>
// - formats dur values in microseconds as NNNµs
// See https://pkg.go.dev/log/slog#HandlerOptions.ReplaceAttr
// N.B: TextHandler manages quoting attribute values as necessary.
func slogReplaceAttr(groups []string, a slog.Attr) slog.Attr {
// Limit application of these rules only to top-level keys
if len(groups) == 0 {
// Set time zone to UTC
if a.Key == slog.TimeKey {
a.Value = slog.TimeValue(a.Value.Time().UTC())
return a
}
// Remove empty msg=""
if a.Equal(slog.String(slog.MessageKey, "")) {
return slog.Attr{}
}
// Remove error key=value when error is nil
if a.Equal(slog.Any("error", error(nil))) {
return slog.Attr{}
}
// Display a 'partial' path.
// This avoids ambiguity when you have multiple files called 'example.go' across different packages.
//
// NOTE: It's implemented based on my own application "mustang" (hence that reference in the path lookup)
/*
if a.Key == slog.SourceKey {
source, _ := a.Value.Any().(*slog.Source)
segs := strings.Split(source.File, string(filepath.Separator))
idx := slices.Index(segs, "mustang")
path := strings.Join(segs[idx+1:], string(filepath.Separator))
source.File = path
return a
}
*/
// Rewritten + change the key from `source` to `caller`.
if a.Key == slog.SourceKey {
if source, ok := a.Value.Any().(*slog.Source); ok {
a.Key = "caller"
if _, after, ok := strings.Cut(source.File, "mustang"+string(filepath.Separator)); ok {
source.File = after
}
return a
}
}
}
// Present durations and delays as xxxxµs
switch a.Key {
case "dur", "delay", "p95", "previous_p95", "remaining", "max_wait":
a.Value = slog.StringValue(fmt.Sprintf("%dµs", a.Value.Duration().Microseconds()))
}
return a
}
type ErrFoo struct {
Code int // let's pretend we don't want this printed by normal Error() message
Err error
}
func (ef ErrFoo) Error() string {
return fmt.Sprintf("%d: %s", ef.Code, ef.Err)
}
// This method allows us to tell slog to ignore the Code field and just print the Err as a string.
// https://betterstack.com/community/guides/logging/logging-in-go/#hiding-sensitive-fields-with-the-logvaluer-interface
func (ef ErrFoo) LogValue() slog.Value {
return slog.StringValue(ef.Err.Error())
}
// There are issues with LogAttrs when it wraps slog.Logger's LogAttrs.
// So we must implement wrapping as described in
// https://pkg.go.dev/log/slog#hdr-Wrapping_output_methods
// Which helps to preserve the correct source location.
// Package logging wraps the features we want to expose from log/slog and
// provides standard constructors for loggers.
package logging
import (
"context"
"io"
"log"
"log/slog"
"os"
"path/filepath"
"runtime"
"strconv"
"strings"
"time"
"github.com/domainr/mustang/internal/version"
)
// Level allows dynamically changing the output level via .Set() method.
// Defaults to [slog.LevelInfo].
var Level = new(slog.LevelVar)
// Logger describes the set of features we want to expose from log/slog.
//
// NOTE: Don't confuse our custom With() signature with (*slog.Logger).With
// We return a Logger type where the standard library returns a *slog.Logger
type Logger interface {
Enabled(ctx context.Context, level slog.Level) bool
LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr)
With(args ...any) Logger
_private(private) // prevents any other package from implementing this interface
}
// NewLogger returns a logging.Logger configured for stderr.
func NewLogger() Logger {
return NewLoggerWithOutputLevel(os.Stderr, Level)
}
// NewLoggerWithOutputLevel returns a [Logger] configured with an output writer and Level.
func NewLoggerWithOutputLevel(w io.Writer, l slog.Leveler) Logger {
opts := defaultOptions()
opts.Level = l
return (*logger)(slog.New(slog.NewTextHandler(w, opts).WithAttrs(defaultAttrs())))
}
// NewBareLoggerWithOutputLevel returns a [Logger] configured with an output location and [slog.Leveler].
// It does not include any additional attributes.
func NewBareLoggerWithOutputLevel(w io.Writer, l slog.Leveler) Logger {
opts := defaultOptions()
opts.Level = l
return (*logger)(slog.New(slog.NewTextHandler(w, opts)))
}
type private struct{}
// IMPORTANT: logger is an alias to slog.Logger to avoid a double-pointer deference.
// All methods off the type will need to type-cast a *logger to *slog.Logger.
// With() must additionally type-cast back to a Logger compatible type.
type logger slog.Logger
func (*logger) _private(private) {}
func (l *logger) Enabled(ctx context.Context, level slog.Level) bool {
return (*slog.Logger)(l).Enabled(ctx, level)
}
// LogAttrs effectively wraps slog.Logger's LogAttrs, so we must implement wrapping as described
// in https://pkg.go.dev/log/slog#hdr-Wrapping_output_methods to preserve the correct source location.
func (l *logger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) {
if !l.Enabled(context.Background(), level) {
return
}
var pcs [1]uintptr
runtime.Callers(2, pcs[:]) // skip 2 [Callers, LogAttrs]
r := slog.NewRecord(time.Now(), level, msg, pcs[0])
r.AddAttrs(attrs...)
(*slog.Logger)(l).Handler().Handle(ctx, r)
}
func (l *logger) With(args ...any) Logger {
return (*logger)((*slog.Logger)(l).With(args...))
}
// Adapt returns a [log.Logger] for use with packages that are not yet compatible with
// [log/slog].
func Adapt(l Logger, level slog.Level) *log.Logger {
// _private() ensures this type assertion cannot panic.
slogger := (*slog.Logger)(l.(*logger)) //nolint:revive,forcetypeassert
return slog.NewLogLogger(slogger.Handler(), level)
}
func defaultOptions() *slog.HandlerOptions {
return &slog.HandlerOptions{
AddSource: true,
ReplaceAttr: slogReplaceAttr,
Level: Level,
}
}
func defaultAttrs() []slog.Attr {
appName := strings.Replace(os.Getenv("HEROKU_APP_NAME"), "mustang", "heroku", 1)
if appName == "" {
appName = os.Getenv("USER")
}
return []slog.Attr{slog.Group("mustang",
slog.String("name", appName),
slog.String("version", version.Version()),
)}
}
// NullLogger discards logs.
func NullLogger() Logger {
// NOTE: We pass a level not currently defined to reduce operational overhead.
// The intent, unlike passing nil for the opts argument, is for the logger to
// not even bother generating a message that will just be discarded.
// An additional gap of 4 was used as it aligns with Go's original design.
// https://github.com/golang/go/blob/1e95fc7/src/log/slog/level.go#L34-L42
return (*logger)(slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{Level: slog.LevelError + 4}))) //nolint:gomnd
}
// slogReplaceAttr adjusts the log output.
//
// - Restricts these changes to top-level keys (not keys within groups)
// - Changes default time field value to UTC time zone
// - Replaces msg key with event
// - Omits event field if empty
// - Omits error field if when nil
// - Truncates source's filename to mustang directory
//
// - Formats duration and delay values in microseconds as xxxxµs
//
// See https://pkg.go.dev/log/slog#HandlerOptions.ReplaceAttr
// N.B: TextHandler manages quoting attribute values as necessary.
func slogReplaceAttr(groups []string, a slog.Attr) slog.Attr {
// Limit application of these rules only to top-level keys
if len(groups) == 0 {
// Set time zone to UTC
if a.Key == slog.TimeKey {
a.Value = slog.TimeValue(a.Value.Time().UTC())
return a
}
// Use event as the default MessageKey, remove if empty
if a.Key == slog.MessageKey {
a.Key = "event"
if a.Value.String() == "" {
return slog.Attr{}
}
return a
}
// Display a 'partial' path.
// Avoids ambiguity when multiple files have the same name across packages.
// e.g. billing.go appears under 'global', 'billing' and 'server' packages.
if a.Key == slog.SourceKey {
if source, ok := a.Value.Any().(*slog.Source); ok {
a.Key = "caller"
if _, after, ok := strings.Cut(source.File, "mustang"+string(filepath.Separator)); ok {
source.File = after
}
}
return a
}
}
// Remove error key=value when error is nil
if a.Equal(slog.Any("error", error(nil))) {
return slog.Attr{}
}
// Present durations and delays as xxxxµs
switch a.Key {
case "dur", "delay", "p95", "previous_p95", "remaining", "max_wait":
a.Value = slog.StringValue(strconv.FormatInt(a.Value.Duration().Microseconds(), 10) + "µs")
}
return a
}