sneak
b21996844f
check / check (push) In progress
The TTY log handler always wrote ANSI color, unlike internal/ui, which disables color when NO_COLOR is set. Add a color flag to TTYHandler, set from NO_COLOR with the same test internal/ui uses, and route every color code through a paint helper that returns plain text when color is off. The README's color sentence now covers log lines too. Model: deepseek-v4-pro
465 lines
13 KiB
Go
465 lines
13 KiB
Go
package log_test
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"encoding/json"
|
|
"fmt"
|
|
"log/slog"
|
|
"math"
|
|
"regexp"
|
|
"sort"
|
|
"strconv"
|
|
"strings"
|
|
"sync"
|
|
"testing"
|
|
|
|
"github.com/stretchr/testify/assert"
|
|
"github.com/stretchr/testify/require"
|
|
"sneak.berlin/go/vaultik/internal/log"
|
|
)
|
|
|
|
// ansiEscape matches the SGR sequences TTYHandler wraps every field in.
|
|
// Stripping them is what lets a test compare TTYHandler's rendering with
|
|
// slog.JSONHandler's.
|
|
var ansiEscape = regexp.MustCompile(`\x1b\[[0-9;]*m`)
|
|
|
|
// countKey is an attribute key reused across the comparison cases.
|
|
const countKey = "count"
|
|
|
|
// debugHandlerOptions enables every level, so a test never has to reason
|
|
// about the default level while reasoning about attributes.
|
|
func debugHandlerOptions() *slog.HandlerOptions {
|
|
return &slog.HandlerOptions{Level: slog.LevelDebug}
|
|
}
|
|
|
|
// ttyAttrs renders one record through a TTYHandler and returns its
|
|
// attributes as key -> value, with color stripped.
|
|
//
|
|
// TTYHandler emits " key=value" per attribute after the message, and the
|
|
// message itself is the last thing before the first attribute, so
|
|
// splitting on spaces and keeping the tokens containing "=" recovers the
|
|
// attribute set. Test values below therefore avoid spaces and "=".
|
|
func ttyAttrs(t *testing.T, derive func(*slog.Logger) *slog.Logger,
|
|
msg string, args ...any,
|
|
) map[string]string {
|
|
t.Helper()
|
|
|
|
var buf bytes.Buffer
|
|
|
|
logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
|
|
derive(logger).Info(msg, args...)
|
|
|
|
line := ansiEscape.ReplaceAllString(buf.String(), "")
|
|
attrs := make(map[string]string)
|
|
|
|
for token := range strings.FieldsSeq(line) {
|
|
key, value, found := strings.Cut(token, "=")
|
|
if !found {
|
|
continue
|
|
}
|
|
|
|
attrs[key] = value
|
|
}
|
|
|
|
return attrs
|
|
}
|
|
|
|
// jsonAttrs renders one record through slog.JSONHandler and returns its
|
|
// attributes flattened to the same dotted-key form TTYHandler uses, so
|
|
// the two are directly comparable. The built-in time/level/msg fields
|
|
// are dropped: they are the record, not its attributes.
|
|
func jsonAttrs(t *testing.T, derive func(*slog.Logger) *slog.Logger,
|
|
msg string, args ...any,
|
|
) map[string]string {
|
|
t.Helper()
|
|
|
|
var buf bytes.Buffer
|
|
|
|
logger := slog.New(slog.NewJSONHandler(&buf, debugHandlerOptions()))
|
|
derive(logger).Info(msg, args...)
|
|
|
|
var decoded map[string]any
|
|
|
|
require.NoError(t, json.Unmarshal(buf.Bytes(), &decoded))
|
|
|
|
delete(decoded, slog.TimeKey)
|
|
delete(decoded, slog.LevelKey)
|
|
delete(decoded, slog.MessageKey)
|
|
|
|
attrs := make(map[string]string)
|
|
flattenJSON(attrs, "", decoded)
|
|
|
|
return attrs
|
|
}
|
|
|
|
// flattenJSON turns JSONHandler's nested group objects into the dotted
|
|
// keys TTYHandler writes.
|
|
func flattenJSON(dst map[string]string, prefix string, src map[string]any) {
|
|
for key, value := range src {
|
|
full := key
|
|
if prefix != "" {
|
|
full = prefix + "." + key
|
|
}
|
|
|
|
nested, ok := value.(map[string]any)
|
|
if ok {
|
|
flattenJSON(dst, full, nested)
|
|
|
|
continue
|
|
}
|
|
|
|
dst[full] = valueString(value)
|
|
}
|
|
}
|
|
|
|
// valueString renders a decoded JSON scalar the way slog.Value.String
|
|
// renders the corresponding Go value, so the two handlers' outputs can
|
|
// be compared as strings. encoding/json decodes every number as
|
|
// float64, so an integral one is rendered back as an integer — which is
|
|
// what the Go value that produced it was.
|
|
func valueString(v any) string {
|
|
switch typed := v.(type) {
|
|
case string:
|
|
return typed
|
|
case bool:
|
|
return strconv.FormatBool(typed)
|
|
case float64:
|
|
if typed == math.Trunc(typed) {
|
|
return strconv.FormatInt(int64(typed), 10)
|
|
}
|
|
|
|
return strconv.FormatFloat(typed, 'g', -1, 64)
|
|
default:
|
|
return fmt.Sprint(v)
|
|
}
|
|
}
|
|
|
|
// TestTTYHandlerWithAttrsEmitsAttributes is the direct regression test
|
|
// for the reported defect: WithAttrs discarded its argument, so an
|
|
// attribute attached to a logger never reached the output.
|
|
func TestTTYHandlerWithAttrsEmitsAttributes(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
attrs := ttyAttrs(t, func(l *slog.Logger) *slog.Logger {
|
|
return l.With("key", "value")
|
|
}, "hello")
|
|
|
|
assert.Equal(t, "value", attrs["key"],
|
|
"an attribute attached with With must appear on every record")
|
|
}
|
|
|
|
// TestTTYHandlerWithAttrsPersistsAcrossRecords checks that the
|
|
// attributes are retained rather than emitted once. A handler that
|
|
// stored them but consumed them would pass the test above.
|
|
func TestTTYHandlerWithAttrsPersistsAcrossRecords(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
var buf bytes.Buffer
|
|
|
|
logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions())).
|
|
With("request", "abc123")
|
|
|
|
logger.Info("first")
|
|
logger.Info("second")
|
|
|
|
plain := ansiEscape.ReplaceAllString(buf.String(), "")
|
|
lines := strings.Split(strings.TrimSuffix(plain, "\n"), "\n")
|
|
|
|
require.Len(t, lines, 2)
|
|
|
|
for _, line := range lines {
|
|
assert.Contains(t, line, "request=abc123")
|
|
}
|
|
}
|
|
|
|
// TestTTYHandlerWithGroupQualifiesKeys checks that WithGroup does
|
|
// something real rather than being discarded. This format has no
|
|
// nesting, so grouping shows up as a dotted key prefix.
|
|
func TestTTYHandlerWithGroupQualifiesKeys(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
attrs := ttyAttrs(t, func(l *slog.Logger) *slog.Logger {
|
|
return l.WithGroup("db").With("rows", 3)
|
|
}, "queried", "table", "chunks")
|
|
|
|
assert.Equal(t, "3", attrs["db.rows"],
|
|
"an attribute added under a group must be qualified by it")
|
|
assert.Equal(t, "chunks", attrs["db.table"],
|
|
"a record attribute must also be qualified by the open group")
|
|
assert.NotContains(t, attrs, "rows")
|
|
}
|
|
|
|
// TestTTYHandlerByteFormattingSurvivesGrouping guards the interaction
|
|
// between the two features. The human-readable rendering of a "bytes"
|
|
// attribute is selected by comparing the key, and keys reaching that
|
|
// comparison are group-qualified, so a "bytes" attribute logged under an
|
|
// open group arrived as "transfer.bytes" and fell back to a bare number.
|
|
// No caller groups a byte count today, which is exactly why this needs a
|
|
// test rather than a bug report.
|
|
func TestTTYHandlerByteFormattingSurvivesGrouping(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
// Printed as "1.0 MB", in powers of 1000 like every other byte count.
|
|
const oneMegabyte = 1_000_000
|
|
|
|
for name, testCase := range map[string]struct {
|
|
derive func(*slog.Logger) *slog.Logger
|
|
key string
|
|
}{
|
|
"ungrouped": {
|
|
derive: func(l *slog.Logger) *slog.Logger { return l },
|
|
key: "bytes",
|
|
},
|
|
"grouped": {
|
|
derive: func(l *slog.Logger) *slog.Logger {
|
|
return l.WithGroup("transfer")
|
|
},
|
|
key: "transfer.bytes",
|
|
},
|
|
} {
|
|
t.Run(name, func(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
var buf bytes.Buffer
|
|
|
|
logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
|
|
testCase.derive(logger).Info("uploaded", "bytes", oneMegabyte)
|
|
|
|
line := ansiEscape.ReplaceAllString(buf.String(), "")
|
|
|
|
assert.Contains(t, line, testCase.key+"=1.0 MB",
|
|
"a byte count must be human-readable however it is qualified")
|
|
assert.NotContains(t, line, strconv.Itoa(oneMegabyte),
|
|
"the raw number must not survive the formatting")
|
|
})
|
|
}
|
|
}
|
|
|
|
// TestTTYHandlerMatchesJSONHandlerAttributes is the drift guard. The
|
|
// handler is chosen by TTY-ness, so a difference between these two is
|
|
// invisible in whichever environment the developer is not in — which is
|
|
// how the original defect survived: attributes vanished on a terminal
|
|
// and were correct in CI.
|
|
func TestTTYHandlerMatchesJSONHandlerAttributes(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
cases := []struct {
|
|
name string
|
|
derive func(*slog.Logger) *slog.Logger
|
|
args []any
|
|
}{
|
|
{
|
|
name: "record attributes only",
|
|
derive: func(l *slog.Logger) *slog.Logger { return l },
|
|
args: []any{"path", "/etc/vaultik", countKey, 7},
|
|
},
|
|
{
|
|
name: "handler attributes",
|
|
derive: func(l *slog.Logger) *slog.Logger {
|
|
return l.With("host", "alpha")
|
|
},
|
|
args: []any{countKey, 7},
|
|
},
|
|
{
|
|
name: "handler attributes accumulate",
|
|
derive: func(l *slog.Logger) *slog.Logger {
|
|
return l.With("host", "alpha").With("snapshot", "s1")
|
|
},
|
|
args: []any{countKey, 7},
|
|
},
|
|
{
|
|
name: "group qualifies later attributes",
|
|
derive: func(l *slog.Logger) *slog.Logger {
|
|
return l.WithGroup("db").With("rows", 3)
|
|
},
|
|
args: []any{"table", "chunks"},
|
|
},
|
|
{
|
|
name: "nested groups",
|
|
derive: func(l *slog.Logger) *slog.Logger {
|
|
return l.WithGroup("outer").WithGroup("inner").
|
|
With("leaf", "v")
|
|
},
|
|
args: []any{"other", "w"},
|
|
},
|
|
{
|
|
name: "attributes before and after a group",
|
|
derive: func(l *slog.Logger) *slog.Logger {
|
|
return l.With("top", "t").WithGroup("g").With("in", "i")
|
|
},
|
|
args: []any{"rec", "r"},
|
|
},
|
|
{
|
|
name: "inline group value on the record",
|
|
derive: func(l *slog.Logger) *slog.Logger { return l },
|
|
args: []any{slog.Group("net",
|
|
slog.String("proto", "s3"), slog.Int("retries", 2))},
|
|
},
|
|
}
|
|
|
|
for _, testCase := range cases {
|
|
t.Run(testCase.name, func(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
tty := ttyAttrs(t, testCase.derive, "message", testCase.args...)
|
|
js := jsonAttrs(t, testCase.derive, "message", testCase.args...)
|
|
|
|
assert.Equal(t, sortedKeys(js), sortedKeys(tty),
|
|
"TTY and JSON handlers must emit the same attribute keys")
|
|
assert.Equal(t, js, tty,
|
|
"TTY and JSON handlers must emit the same attribute values")
|
|
})
|
|
}
|
|
}
|
|
|
|
// sortedKeys returns m's keys in order, for a stable comparison message.
|
|
func sortedKeys(m map[string]string) []string {
|
|
keys := make([]string, 0, len(m))
|
|
for key := range m {
|
|
keys = append(keys, key)
|
|
}
|
|
|
|
sort.Strings(keys)
|
|
|
|
return keys
|
|
}
|
|
|
|
// TestTTYHandlerWithAttrsDoesNotMutateReceiver checks that deriving does
|
|
// not write through to the parent or to a sibling. slog permits a
|
|
// handler to be shared, so a WithAttrs that appended into the receiver's
|
|
// state would leak attributes between unrelated loggers.
|
|
func TestTTYHandlerWithAttrsDoesNotMutateReceiver(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
var buf bytes.Buffer
|
|
|
|
base := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
|
|
first := base.With("branch", "one")
|
|
second := base.With("branch", "two")
|
|
|
|
base.Info("base")
|
|
first.Info("first")
|
|
second.Info("second")
|
|
|
|
plain := ansiEscape.ReplaceAllString(buf.String(), "")
|
|
lines := strings.Split(strings.TrimSuffix(plain, "\n"), "\n")
|
|
|
|
require.Len(t, lines, 3)
|
|
|
|
assert.NotContains(t, lines[0], "branch=",
|
|
"deriving must not add attributes to the handler derived from")
|
|
assert.Contains(t, lines[1], "branch=one")
|
|
assert.NotContains(t, lines[1], "branch=two")
|
|
assert.Contains(t, lines[2], "branch=two")
|
|
assert.NotContains(t, lines[2], "branch=one")
|
|
}
|
|
|
|
// TestTTYHandlerConcurrentDerivation exercises the same handler being
|
|
// derived from and written through by several goroutines at once, which
|
|
// is what slog permits and what a mutating WithAttrs would make a data
|
|
// race. Run under -race by script/test.
|
|
func TestTTYHandlerConcurrentDerivation(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
const workers = 16
|
|
|
|
var buf bytes.Buffer
|
|
|
|
base := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions())).
|
|
With("shared", "yes")
|
|
|
|
var group sync.WaitGroup
|
|
|
|
group.Add(workers)
|
|
|
|
for worker := range workers {
|
|
go func() {
|
|
defer group.Done()
|
|
|
|
base.With("worker", worker).
|
|
WithGroup("g").
|
|
With("nested", worker).
|
|
Info("concurrent")
|
|
}()
|
|
}
|
|
|
|
group.Wait()
|
|
|
|
plain := ansiEscape.ReplaceAllString(buf.String(), "")
|
|
lines := strings.Split(strings.TrimSuffix(plain, "\n"), "\n")
|
|
|
|
require.Len(t, lines, workers)
|
|
|
|
for _, line := range lines {
|
|
assert.Contains(t, line, "shared=yes")
|
|
assert.Contains(t, line, "worker=")
|
|
assert.Contains(t, line, "g.nested=")
|
|
}
|
|
}
|
|
|
|
// TestTTYHandlerEmptyGroupAndAttrsAreNoOps covers the slog.Handler
|
|
// contract corners: WithGroup("") and WithAttrs(nil) change nothing, and
|
|
// an empty Attr is dropped rather than rendered as "=".
|
|
func TestTTYHandlerEmptyGroupAndAttrsAreNoOps(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
var buf bytes.Buffer
|
|
|
|
handler := log.NewTTYHandler(&buf, debugHandlerOptions())
|
|
|
|
assert.Same(t, handler, handler.WithGroup(""),
|
|
"an empty group name must not open a group")
|
|
assert.Same(t, handler, handler.WithAttrs(nil),
|
|
"deriving with no attributes must not allocate a handler")
|
|
|
|
slog.New(handler).LogAttrs(context.Background(), slog.LevelInfo, "msg",
|
|
slog.Attr{}, slog.String("kept", "yes"))
|
|
|
|
plain := ansiEscape.ReplaceAllString(buf.String(), "")
|
|
|
|
assert.Contains(t, plain, "kept=yes")
|
|
assert.NotContains(t, plain, " =")
|
|
}
|
|
|
|
// TestTTYHandlerRespectsNoColor checks that only a non-empty NO_COLOR
|
|
// turns color off, matching internal/ui's shouldColor test. The handler
|
|
// is only ever chosen for a terminal, so this is the one remaining
|
|
// condition that can still leave color in log output.
|
|
func TestTTYHandlerRespectsNoColor(t *testing.T) {
|
|
cases := []struct {
|
|
name string
|
|
noColor string
|
|
colored bool
|
|
}{
|
|
{
|
|
name: "NO_COLOR turns color off",
|
|
noColor: "1",
|
|
},
|
|
{
|
|
name: "empty NO_COLOR keeps color on",
|
|
noColor: "",
|
|
colored: true,
|
|
},
|
|
}
|
|
|
|
for _, testCase := range cases {
|
|
t.Run(testCase.name, func(t *testing.T) {
|
|
t.Setenv("NO_COLOR", testCase.noColor)
|
|
|
|
var buf bytes.Buffer
|
|
|
|
logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
|
|
logger.Info("hello", "key", "value")
|
|
|
|
if testCase.colored {
|
|
assert.Contains(t, buf.String(), "\x1b[",
|
|
"an empty NO_COLOR must leave ANSI color in log output")
|
|
} else {
|
|
assert.NotContains(t, buf.String(), "\x1b[",
|
|
"NO_COLOR must suppress every ANSI escape in log output")
|
|
}
|
|
})
|
|
}
|
|
}
|