Log to stderr and stop discarding With attributes (closes #82)
All checks were successful
check / check (push) Successful in 4m20s

Closes #97.

internal/log attached both handlers to os.Stdout, so any record that was
not suppressed landed in the middle of a --json document. WARN and ERROR
are never suppressed, so this was not hypothetical: a config file with
permissions looser than 0600 was enough to break
`vaultik snapshot list --json | jq`.

Both handlers now write to os.Stderr, and the TTY-vs-JSON format choice
tests os.Stderr rather than os.Stdout - the format has to follow the
stream the records land on, or a redirected stderr gets colorized
whenever stdout happens to be a terminal.

User-visible: --verbose and --debug output moves to stderr too, so
`vaultik snapshot list -v > out.txt` no longer captures diagnostics.
--quiet and --cron semantics are unchanged.

TTYHandler.WithAttrs and WithGroup discarded their arguments and returned
the receiver, while their doc comments claimed otherwise, so attributes
passed through the exported log.With vanished. The effect was
environment-dependent in the worst direction: handler choice is by
TTY-ness, so attributes disappeared on a terminal - where a developer is
debugging - and appeared correctly in CI. Both now return a new handler
with copied state rather than mutating the receiver, since slog permits a
handler to be shared and derived from concurrently. A test asserts the
TTY and JSON handlers emit the same attribute set, which is the test that
would have caught the original defect.

The local workaround in snapshot_list.go is removed now that the logger
no longer writes to stdout. The collect-then-emit machinery is kept, but
for a different reason than it was added: emitting from the fetch workers
would order warnings by network timing, whereas key-order emission after
group.Wait() is deterministic run to run.

Not yet complete: --json stdout still carries the startup banner, which
internal/cli/entry.go writes before cobra parses and which
bannerSuppressedInArgs does not recognise --json for. That is the
remaining stdout contamination path and is tracked in #106.
This commit was merged in pull request #107.
This commit is contained in:
2026-08-09 18:43:55 +02:00
parent e3f407b440
commit c16ef476a9
9 changed files with 841 additions and 162 deletions

View File

@@ -1,5 +1,9 @@
// Package log provides the application-wide structured logger: slog
// with a colorized TTY handler on terminals and JSON output otherwise.
// writing to stderr, with a colorized TTY handler when stderr is a
// terminal and JSON output otherwise.
//
// Everything this package emits is a diagnostic, so it all goes to
// stderr. stdout belongs to the output the user asked for.
package log //nolint:revive,nolintlint // stdlib log unused here; see #76
import (
@@ -69,13 +73,27 @@ func Initialize(cfg Config) {
Level: level,
}
// Check if stdout is a TTY.
if term.IsTerminal(int(os.Stdout.Fd())) {
// Diagnostics go to stderr, never to stdout. stdout is reserved for
// the output the user asked for: every --json subcommand writes its
// document there, and WARN/ERROR are never suppressed, so a logger
// on stdout puts log records inside that document and makes it
// unparseable. A config file with group- or world-readable
// permissions is enough to trigger it (see internal/config), so this
// was not a theoretical collision.
//
// The format is chosen by the TTY-ness of the stream the records
// actually land on. AGENTS.md policy 9 says "if stdout is not a
// terminal, emit jsonl"; it says stdout because that is where logs
// used to go, and the property it is really asking for is that
// output nobody is watching be machine-readable. Testing stdout here
// would colorize records on a redirected stderr whenever stdout
// happened to be a terminal, and vice versa.
if term.IsTerminal(int(os.Stderr.Fd())) {
// Use colorized TTY handler
logger = slog.New(NewTTYHandler(os.Stdout, opts))
logger = slog.New(NewTTYHandler(os.Stderr, opts))
} else {
// Use JSON format for non-TTY output
logger = slog.New(slog.NewJSONHandler(os.Stdout, opts))
logger = slog.New(slog.NewJSONHandler(os.Stderr, opts))
}
// Set as default logger

View File

@@ -5,10 +5,20 @@ import (
"fmt"
"io"
"log/slog"
"strings"
"sync"
"time"
)
// groupSeparator joins an open group path to an attribute key. This
// format has no nesting, so a group becomes a dotted key prefix:
// slog.New(h).WithGroup("db").With("rows", 3) renders "db.rows=3".
const groupSeparator = "."
// bytesAttrKey is the attribute key whose int64 value is rendered as a
// human-readable byte count rather than a bare number.
const bytesAttrKey = "bytes"
// ANSI color codes
const (
colorReset = "\033[0m"
@@ -22,10 +32,26 @@ const (
)
// TTYHandler is a custom slog handler for TTY output with colors.
//
// A handler and the handlers derived from it via WithAttrs/WithGroup
// all write to the same stream, so they share one mutex; that is why mu
// is a pointer. A value mutex would give every derived handler its own
// lock and stop serializing writes to the stream they have in common.
type TTYHandler struct {
opts slog.HandlerOptions
mu sync.Mutex
mu *sync.Mutex
out io.Writer
// attrs are the attributes accumulated through WithAttrs, emitted
// ahead of each record's own attributes. Their keys already carry
// the group path that was open when they were added, so no
// qualification happens at write time.
attrs []slog.Attr
// groups is the group path opened by WithGroup, applied as a key
// prefix to attributes that arrive later — both on a record and
// through a further WithAttrs.
groups []string
}
// NewTTYHandler creates a new TTY handler with colored output.
@@ -37,6 +63,7 @@ func NewTTYHandler(out io.Writer, opts *slog.HandlerOptions) *TTYHandler {
return &TTYHandler{
out: out,
opts: *opts,
mu: &sync.Mutex{},
}
}
@@ -81,29 +108,19 @@ func (h *TTYHandler) Handle(_ context.Context, r slog.Record) error {
levelColor, level, colorReset,
colorBold, r.Message, colorReset)
// Print attributes
r.Attrs(func(a slog.Attr) bool {
value := a.Value.String()
// Special handling for certain attribute types
switch a.Value.Kind() {
case slog.KindDuration:
if d, ok := a.Value.Any().(time.Duration); ok {
value = formatDuration(d)
}
case slog.KindInt64:
if a.Key == "bytes" {
value = formatBytes(a.Value.Int64())
}
case slog.KindAny, slog.KindBool, slog.KindFloat64, slog.KindString,
slog.KindTime, slog.KindUint64, slog.KindGroup, slog.KindLogValuer:
// Plain string form above is already correct for these kinds.
default:
// Future kinds also use the plain string form.
}
// Attributes carried by the handler come first, then the record's
// own. Handler attributes were qualified when they were added; the
// record's are qualified now, against whatever group path is open.
for _, a := range h.attrs {
h.writeAttr(a)
}
_, _ = fmt.Fprintf(h.out, " %s%s%s=%s%s%s",
colorCyan, a.Key, colorReset,
colorBlue, value, colorReset)
prefix := strings.Join(h.groups, groupSeparator)
r.Attrs(func(a slog.Attr) bool {
for _, flat := range appendAttr(nil, prefix, a) {
h.writeAttr(flat)
}
return true
})
@@ -113,14 +130,125 @@ func (h *TTYHandler) Handle(_ context.Context, r slog.Record) error {
return nil
}
// WithAttrs returns a new handler with the given attributes.
func (h *TTYHandler) WithAttrs(_ []slog.Attr) slog.Handler {
return h // Simplified for now
// appendAttr flattens a into dst, folding prefix into its key and
// expanding group values into further dotted keys. Following the
// slog.Handler contract: an empty Attr is dropped, a group with no
// attributes is dropped, and a group with an empty key is inlined into
// its parent rather than contributing a level.
func appendAttr(dst []slog.Attr, prefix string, a slog.Attr) []slog.Attr {
a.Value = a.Value.Resolve()
if a.Equal(slog.Attr{}) {
return dst
}
key := a.Key
switch {
case prefix == "":
// key stands alone.
case key == "":
key = prefix
default:
key = prefix + groupSeparator + key
}
if a.Value.Kind() != slog.KindGroup {
return append(dst, slog.Attr{Key: key, Value: a.Value})
}
for _, member := range a.Value.Group() {
dst = appendAttr(dst, key, member)
}
return dst
}
// WithGroup returns a new handler with the given group name.
func (h *TTYHandler) WithGroup(_ string) slog.Handler {
return h // Simplified for now
// WithAttrs returns a new handler that emits attrs on every record it
// handles, in addition to whatever the handler already carried. Keys
// are qualified by the group path open at the time of the call, so
// WithGroup("db").WithAttrs(rows=3) later renders "db.rows=3".
//
// The receiver is not modified.
func (h *TTYHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
if len(attrs) == 0 {
return h
}
prefix := strings.Join(h.groups, groupSeparator)
next := h.clone()
for _, a := range attrs {
next.attrs = appendAttr(next.attrs, prefix, a)
}
return next
}
// WithGroup returns a new handler that qualifies every subsequent
// attribute key with name. This format is a single line with nowhere to
// nest, so grouping is rendered as a dotted key prefix: after
// WithGroup("db"), an attribute "rows" is emitted as "db.rows".
//
// An empty name returns the receiver unchanged, per the slog.Handler
// contract. The receiver is not modified.
func (h *TTYHandler) WithGroup(name string) slog.Handler {
if name == "" {
return h
}
next := h.clone()
next.groups = append(next.groups, name)
return next
}
// clone returns a copy of h that shares its output stream and mutex but
// owns its attribute and group slices.
//
// The slices are copied rather than resliced on purpose. slog permits
// one handler to be derived from concurrently, and two derivations that
// appended into a shared backing array would each overwrite the other's
// attribute — a data race with a silent wrong-output failure mode.
func (h *TTYHandler) clone() *TTYHandler {
next := &TTYHandler{
opts: h.opts,
mu: h.mu,
out: h.out,
attrs: make([]slog.Attr, len(h.attrs), len(h.attrs)+1),
groups: make([]string, len(h.groups), len(h.groups)+1),
}
copy(next.attrs, h.attrs)
copy(next.groups, h.groups)
return next
}
// writeAttr renders one already-flattened, already-qualified attribute
// as " key=value". Callers hold h.mu.
func (h *TTYHandler) writeAttr(a slog.Attr) {
value := a.Value.String()
// Special handling for certain attribute types
switch a.Value.Kind() {
case slog.KindDuration:
if d, ok := a.Value.Any().(time.Duration); ok {
value = formatDuration(d)
}
case slog.KindInt64:
if a.Key == bytesAttrKey {
value = formatBytes(a.Value.Int64())
}
case slog.KindAny, slog.KindBool, slog.KindFloat64, slog.KindString,
slog.KindTime, slog.KindUint64, slog.KindGroup, slog.KindLogValuer:
// Plain string form above is already correct for these kinds.
default:
// Future kinds also use the plain string form.
}
_, _ = fmt.Fprintf(h.out, " %s%s%s=%s%s%s",
colorCyan, a.Key, colorReset,
colorBlue, value, colorReset)
}
// formatDuration formats a duration in a human-readable way

View File

@@ -0,0 +1,377 @@
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")
}
// 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, " =")
}

64
internal/log/with_test.go Normal file
View File

@@ -0,0 +1,64 @@
//nolint:testpackage // needs the package logger; see TestWithAttributesReachTTYOutput
package log //nolint:revive,nolintlint // stdlib log unused here; see #76
import (
"bytes"
"log/slog"
"regexp"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
)
// withTestANSIEscape matches the SGR sequences TTYHandler emits.
var withTestANSIEscape = regexp.MustCompile(`\x1b\[[0-9;]*m`)
// TestWithAttributesReachTTYOutput exercises the exported package-level
// With through a TTYHandler, which is the path the reported defect was
// on: the handler is selected by TTY-ness, so on a terminal With's
// attributes were silently dropped while the same code printed them
// correctly in CI.
//
// This is an in-package test so it can point the package logger at a
// buffer. Building an slog.Logger over a TTYHandler by hand would test
// slog, not this package's With, and there is no injectable sink to
// reach it from outside. The package logger is process-global, so this
// test must not run in parallel.
//
//nolint:paralleltest // replaces the process-global package logger
func TestWithAttributesReachTTYOutput(t *testing.T) {
var buf bytes.Buffer
previous := logger
t.Cleanup(func() { logger = previous })
logger = slog.New(NewTTYHandler(&buf, &slog.HandlerOptions{
Level: slog.LevelDebug,
}))
With("key", "value").Info("hello")
plain := withTestANSIEscape.ReplaceAllString(buf.String(), "")
require.NotEmpty(t, plain)
assert.Contains(t, plain, "hello")
assert.Contains(t, plain, "key=value",
"log.With attributes must reach TTYHandler output")
}
// TestWithoutInitializedLoggerFallsBack pins the documented behavior of
// With before Initialize has run: it hands back the slog default rather
// than a nil logger that would panic at the call site.
//
//nolint:paralleltest // replaces the process-global package logger
func TestWithoutInitializedLoggerFallsBack(t *testing.T) {
previous := logger
t.Cleanup(func() { logger = previous })
logger = nil
assert.NotNil(t, With("key", "value"))
}