diff --git a/README.md b/README.md index cff6853..bf3202f 100644 --- a/README.md +++ b/README.md @@ -113,11 +113,32 @@ vaultik version ### global flags * `--config `: Path to config file (default: `$VAULTIK_CONFIG`, then platform config dir, then `/etc/vaultik/config.yml`) -* `--verbose`, `-v`: Enable verbose output -* `--debug`: Enable debug output +* `--verbose`, `-v`: Enable verbose output (on stderr — see below) +* `--debug`: Enable debug output (on stderr — see below) * `--quiet`, `-q`: Suppress non-error output (also suppresses startup banner) * `--skip-errors`: Continue past per-file errors instead of aborting (applies to `snapshot create` and `restore`) +### stdout and stderr + +Log output — everything from `--verbose` and `--debug`, and every +warning and error the logger emits — goes to **stderr**. stdout carries +the output you asked for: tables, and the documents produced by `--json`. + +This means `vaultik snapshot list --verbose > out.txt` captures the +listing and leaves the diagnostics on your terminal. To capture both, +redirect stderr as well (`> out.txt 2> log.txt`, or `> out.txt 2>&1` to +interleave them). + +The split is what makes `--json` usable from a script. Warnings and +errors are never suppressed — not by `--quiet`, not by `--cron` — so a +logger on stdout would eventually land a log line inside a JSON +document and break the parse. A config file with group- or +world-readable permissions is enough to trigger it. + +Format follows the stream: when stderr is a terminal the records are +colorized one-liners, and when it is redirected or piped they are +JSON, one object per line. + ### environment variables * `VAULTIK_AGE_SECRET_KEY`: Age private key for decryption (required for `snapshot restore` and `snapshot verify --deep`) @@ -208,8 +229,9 @@ local index alone, and still exits zero. (whether the snapshot is in the local index), `remote_key` (the full 64-character storage key), and `remote_present` (whether it was seen on the destination store, or `null` if the destination could not be - listed). The warning about an unlistable destination goes to stderr - so stdout stays a single parseable document. + listed). Warnings about an unlistable destination, unreadable + manifests, and a truncated listing all go to stderr through the + logger, so stdout stays a single parseable document. **`snapshot verify`**: Verify snapshot integrity. * Default (shallow): checks that all blobs referenced in the manifest exist in storage @@ -504,6 +526,10 @@ All user-facing output goes through helpers in `internal/ui` and conforms to a uniform style. Color is enabled when stdout is a TTY and the `NO_COLOR` environment variable is unset (https://no-color.org/). +`internal/ui` writes to stdout; it is the output the user asked for. +Structured log records are a different thing and go through +`internal/log`, which writes to stderr (see "stdout and stderr" above). + Message classes: | Class | Marker | Alignment | Use for | diff --git a/TODO.md b/TODO.md index b258764..8d05580 100644 --- a/TODO.md +++ b/TODO.md @@ -25,6 +25,45 @@ release" is exactly the contradiction # Completed Steps +- 2026-08-09: Moved the logger to stderr and fixed `TTYHandler`'s + discarded attributes + ([issue #82](https://git.eeqj.de/sneak/vaultik/issues/82), + [issue #97](https://git.eeqj.de/sneak/vaultik/issues/97)). Two defects + in `internal/log`, fixed together because both live in the handler + construction path. The first: both handlers were built over + `os.Stdout`, and `WARN`/`ERROR` are never suppressed, so a config file + with group- or world-readable permissions was enough to put a log + record inside a `--json` document and break `jq`. Diagnostics now go + to stderr, and the TTY/JSON format choice follows stderr rather than + stdout — testing the wrong stream would colorize records on a + redirected stderr whenever stdout happened to be a terminal. This is + user-visible: `--verbose` and `--debug` output moves to stderr too, + which is documented in `README.md` under "stdout and stderr". It also + let the local workaround in `internal/vaultik/snapshot_list.go` go: + `warnWhileListing` had been hand-rolling structured-log formatting to + reach a non-stdout writer, and the `jsonOutput` parameter threaded + through the remote-listing helpers existed only to choose between the + two writers. The collect-then-emit machinery around `listingWarning` + stays, but on its remaining merit — warnings emitted in key order + after `group.Wait()` are deterministic run to run, where emitting from + the fetch workers would order them by network timing. The second + defect: `TTYHandler.WithAttrs` and `WithGroup` discarded their + arguments and returned the receiver while their doc comments claimed + otherwise, so `log.With` attributes vanished on a terminal and + appeared correctly in CI — failing precisely when someone is debugging + interactively. Both now return a new handler (the receiver is never + written to, since `slog` permits concurrent derivation), attributes + persist across records, and grouping is implemented as dotted key + prefixes, which is the only honest rendering for a format with nowhere + to nest. New tests cover both, including one that feeds the same + derivation chain to the TTY and JSON handlers and compares the + attribute sets, so the two paths cannot drift apart again. Found and + filed while verifying: the startup banner is written to stdout and + `--json` does not suppress it + ([issue #106](https://git.eeqj.de/sneak/vaultik/issues/106)), which is + a separate writer on a separate path and the remaining source of + stdout contamination. + - 2026-08-09: Made the tagged-release path actually work on Gitea ([issue #65](https://git.eeqj.de/sneak/vaultik/issues/65)). Three independent blockers, one of which was the whole diff --git a/internal/log/log.go b/internal/log/log.go index 2806017..fa60687 100644 --- a/internal/log/log.go +++ b/internal/log/log.go @@ -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 diff --git a/internal/log/tty_handler.go b/internal/log/tty_handler.go index cfdf4f9..7691e98 100644 --- a/internal/log/tty_handler.go +++ b/internal/log/tty_handler.go @@ -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 diff --git a/internal/log/tty_handler_test.go b/internal/log/tty_handler_test.go new file mode 100644 index 0000000..a54fa60 --- /dev/null +++ b/internal/log/tty_handler_test.go @@ -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, " =") +} diff --git a/internal/log/with_test.go b/internal/log/with_test.go new file mode 100644 index 0000000..2783545 --- /dev/null +++ b/internal/log/with_test.go @@ -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")) +} diff --git a/internal/vaultik/snapshot_list.go b/internal/vaultik/snapshot_list.go index f4fcc8c..e35055b 100644 --- a/internal/vaultik/snapshot_list.go +++ b/internal/vaultik/snapshot_list.go @@ -87,7 +87,7 @@ func (v *Vaultik) ListSnapshots(jsonOutput bool) error { snapshots = append(snapshots, info) } - listing, remoteErr := v.collectRemoteSnapshots(localKeys, jsonOutput) + listing, remoteErr := v.collectRemoteSnapshots(localKeys) if remoteErr != nil { v.warnRemoteListingFailed(remoteErr, jsonOutput) } else { @@ -131,23 +131,23 @@ func (v *Vaultik) ListSnapshots(jsonOutput bool) error { // still worth printing, and `snapshot list` exiting non-zero because a // volume is unmounted would be worse than useless. // -// In --json mode the warning goes to stderr rather than through the -// logger or the UI writer, both of which emit on stdout — the JSON -// document has to be the only thing on stdout for `snapshot list --json -// | jq` to work. The failure is also representable in the document -// itself: every row's remote_present is null when the destination could -// not be listed. +// The two output modes report it through different channels. Table mode +// uses the UI writer, whose prose and color match the table it sits +// under. The UI writer emits on stdout, though, so --json mode uses the +// logger instead: stdout has to hold nothing but the JSON document for +// `snapshot list --json | jq` to work. Both channels are chosen once, +// never both, so the user is not told the same thing twice. +// +// The failure is also representable in the document itself: every row's +// remote_present is null when the destination could not be listed. func (v *Vaultik) warnRemoteListingFailed(err error, jsonOutput bool) { if jsonOutput { - _, _ = fmt.Fprintf(v.Stderr, - "Warning: could not list backup destination store: %v. "+ - "Showing snapshots from the local index only.\n", err) + log.Warn("Could not list backup destination store; "+ + "showing snapshots from the local index only", "error", err) return } - // Once only: the logger also writes to stdout, so emitting through - // both it and the UI would print the same sentence to the user twice. v.UI.Warningf("Could not list backup destination store: %v.", err) v.UI.Infof("Showing snapshots from the local index only.") } @@ -156,69 +156,29 @@ func (v *Vaultik) warnRemoteListingFailed(err error, jsonOutput bool) { // is about to read is incomplete: manifests that could not be read, and // remote-only snapshots dropped by the maxRemoteOnlyRows cap. // -// Table mode reports both below the table (see reportListDrift). In -// --json mode they cannot go on stdout — the document has to be the -// only thing there for `snapshot list --json | jq` to work — and the -// document's shape is deliberately left alone so existing consumers -// keep parsing. So they go to stderr, the same place the -// unreachable-destination warning already goes. A consumer that must -// react to truncation can treat any output on this stream as "this -// listing is not the whole picture"; silent truncation of a listing -// whose whole purpose is disaster recovery is the worse failure. +// Table mode reports both below the table (see reportListDrift) through +// the UI writer, which emits on stdout. In --json mode stdout has to +// hold nothing but the document for `snapshot list --json | jq` to +// work, and the document's shape is deliberately left alone so existing +// consumers keep parsing — so these go to the logger, which writes to +// stderr. A consumer that must react to truncation can treat any output +// on that stream as "this listing is not the whole picture"; silent +// truncation of a listing whose whole purpose is disaster recovery is +// the worse failure. func (v *Vaultik) reportJSONListingLimits(listing *remoteSnapshotListing) { if listing.unreadable > 0 { - _, _ = fmt.Fprintf(v.Stderr, - "Warning: %d remote snapshot(s) could not be described: "+ - "manifest missing or unreadable. They are missing from "+ - "this listing.\n", listing.unreadable) + log.Warn("Some remote snapshot(s) could not be described: "+ + "manifest missing or unreadable; they are missing from "+ + "this listing", "unreadable", listing.unreadable) } if listing.omitted > 0 { - _, _ = fmt.Fprintf(v.Stderr, - "Warning: listing truncated: %d further remote-only "+ - "snapshot(s) not shown (limit %d per listing).\n", - listing.omitted, maxRemoteOnlyRows) + log.Warn("Listing truncated: further remote-only snapshot(s) "+ + "not shown", "omitted", listing.omitted, + "limit", maxRemoteOnlyRows) } } -// kvPairSize is the number of variadic arguments that make up one -// structured logging key/value pair. -const kvPairSize = 2 - -// warnWhileListing reports a per-snapshot problem found while -// describing the destination store, through a writer that is safe for -// the current output mode. -// -// In --json mode it writes to v.Stderr rather than calling log.Warn, -// for the same reason warnRemoteListingFailed does: internal/log builds -// its logger over os.Stdout and defaults to level Warn, so one warning -// there would put a log line on stdout ahead of the JSON document and -// break `snapshot list --json | jq`. A single corrupt manifest is -// precisely the degradation this listing is built to survive, so it -// must not be the thing that corrupts the output. -// -// This is a local workaround. Remove it, and the branch in -// warnRemoteListingFailed, once issue #82 makes the logger's sink -// configurable. -func (v *Vaultik) warnWhileListing(jsonOutput bool, msg string, args ...any) { - if !jsonOutput { - log.Warn(msg, args...) - - return - } - - var line strings.Builder - - _, _ = fmt.Fprintf(&line, "Warning: %s", msg) - - for i := 0; i+kvPairSize <= len(args); i += kvPairSize { - pair := args[i : i+kvPairSize] - _, _ = fmt.Fprintf(&line, " %v=%v", pair[0], pair[1]) - } - - _, _ = fmt.Fprintln(v.Stderr, line.String()) -} - // remoteSnapshotListing is the result of one pass over the destination // store's metadata/ prefix. type remoteSnapshotListing struct { @@ -247,11 +207,8 @@ type remoteSnapshotListing struct { // Manifest reads scale only with the number of snapshots the local // index does not already know about, and are capped at // maxRemoteOnlyRows. -// -// jsonOutput only selects where per-snapshot warnings are written; see -// warnWhileListing. func (v *Vaultik) collectRemoteSnapshots( - localKeys map[string]bool, jsonOutput bool, + localKeys map[string]bool, ) (*remoteSnapshotListing, error) { keys, err := v.listAllRemoteSnapshotKeys() if err != nil { @@ -282,17 +239,22 @@ func (v *Vaultik) collectRemoteSnapshots( } listing.remoteOnly, listing.unreadable = v.describeRemoteOnlySnapshots( - unknown, jsonOutput) + unknown) return listing, nil } // listingWarning is a problem found with one remote snapshot, recorded -// rather than emitted on the spot. Manifest reads run concurrently and -// the writer chosen by warnWhileListing is not guaranteed to be safe -// for concurrent use, so warnings are held until every read has -// finished and then emitted in key order from a single goroutine. That -// also makes the warning order deterministic run to run. +// rather than emitted on the spot. Manifest reads run concurrently, so +// emitting from the worker that found the problem would order the +// warnings by fetch completion — which varies run to run with network +// timing and tells the reader nothing. Holding them and emitting in key +// order from a single goroutine after every read has finished makes two +// runs over the same damaged store produce the same diagnostics in the +// same order. +// +// Concurrency safety is no longer part of the reason: these are emitted +// through log.Warn, and slog handlers are safe for concurrent use. type listingWarning struct { msg string args []any @@ -306,7 +268,7 @@ type listingWarning struct { // failing the listing: one bad snapshot directory must not hide every // other snapshot the user has. func (v *Vaultik) describeRemoteOnlySnapshots( - keys []string, jsonOutput bool, + keys []string, ) ([]SnapshotInfo, int) { found := make([]SnapshotInfo, len(keys)) ok := make([]bool, len(keys)) @@ -349,7 +311,7 @@ func (v *Vaultik) describeRemoteOnlySnapshots( for i := range keys { if warnings[i] != nil { - v.warnWhileListing(jsonOutput, warnings[i].msg, warnings[i].args...) + log.Warn(warnings[i].msg, warnings[i].args...) } if !ok[i] { diff --git a/internal/vaultik/snapshot_list_test.go b/internal/vaultik/snapshot_list_test.go index 3547e77..2bb0e4a 100644 --- a/internal/vaultik/snapshot_list_test.go +++ b/internal/vaultik/snapshot_list_test.go @@ -521,16 +521,16 @@ func TestListSnapshots_JSONMergedView(t *testing.T) { // TestListSnapshots_JSONUnreachableRemote checks that a failed listing // does not corrupt the JSON document with warning text, and that // "unknown" is reported as null rather than as absence. +// +//nolint:paralleltest // captureProcessStderr replaces os.Stderr func TestListSnapshots_JSONUnreachableRemote(t *testing.T) { - log.Initialize(log.Config{}) - t.Parallel() - env := newListEnv(t) env.addLocal(t, listLocalID, time.Date(2026, 3, 1, 10, 0, 0, 0, time.UTC)) env.store.listErr = errRemoteUnreachable - err := env.v.ListSnapshots(true) - require.NoError(t, err) + stderr := captureProcessStderr(t, func() { + require.NoError(t, env.v.ListSnapshots(true)) + }) // stdout must be nothing but the JSON document, so the warning has // to go to stderr. @@ -542,9 +542,8 @@ func TestListSnapshots_JSONUnreachableRemote(t *testing.T) { assert.Nil(t, rows[0].RemotePresent, "remote state is unknown when the destination cannot be listed") - assert.Contains(t, env.stderr.String(), - "could not list backup destination store") - assert.Contains(t, env.stderr.String(), "permission denied") + assert.Contains(t, stderr, "Could not list backup destination store") + assert.Contains(t, stderr, "permission denied") } // useNonUTCLocalZone points time.Local at a fixed non-UTC zone for the @@ -635,10 +634,9 @@ func TestListSnapshots_TimestampsAreUTCOnNonUTCHost(t *testing.T) { // machine consumer would otherwise see no difference between "that // snapshot is not on the destination" and "that snapshot could not be // read". +// +//nolint:paralleltest // captureProcessStderr replaces os.Stderr func TestListSnapshots_JSONReportsUnreadableManifests(t *testing.T) { - log.Initialize(log.Config{}) - t.Parallel() - env := newListEnv(t) goodKey := env.addRemote(t, listRemoteID, @@ -650,16 +648,18 @@ func TestListSnapshots_JSONReportsUnreadableManifests(t *testing.T) { strings.NewReader("this is not a zstd stream")) require.NoError(t, err) - err = env.v.ListSnapshots(true) - require.NoError(t, err) + stderr := captureProcessStderr(t, func() { + require.NoError(t, env.v.ListSnapshots(true)) + }) rows := decodeListJSON(t, env.stdout.String()) require.Len(t, rows, 1) assert.Equal(t, goodKey, rows[0].RemoteKey) - assert.Contains(t, env.stderr.String(), - "1 remote snapshot(s) could not be described", + assert.Contains(t, stderr, "could not be described", "a row dropped from the JSON document must be announced somewhere") + assert.Contains(t, stderr, `"unreadable":1`, + "the count of dropped rows must be reported, not just the fact") } // maxRemoteOnlyRowsForTest mirrors the maxRemoteOnlyRows cap in the @@ -671,10 +671,9 @@ const maxRemoteOnlyRowsForTest = 1000 // truncation of a listing whose whole purpose is disaster recovery is // the wrong failure mode: the consumer least able to notice is exactly // the one reading JSON. +// +//nolint:paralleltest // captureProcessStderr replaces os.Stderr func TestListSnapshots_JSONReportsTruncation(t *testing.T) { - log.Initialize(log.Config{}) - t.Parallel() - env := newListEnv(t) timestamp := time.Date(2026, 3, 2, 11, 22, 33, 0, time.UTC) @@ -684,25 +683,30 @@ func TestListSnapshots_JSONReportsTruncation(t *testing.T) { env.addRemote(t, fmt.Sprintf("otherhost_bulk_%04d", i), timestamp) } - err := env.v.ListSnapshots(true) - require.NoError(t, err) + stderr := captureProcessStderr(t, func() { + require.NoError(t, env.v.ListSnapshots(true)) + }) rows := decodeListJSON(t, env.stdout.String()) assert.Len(t, rows, maxRemoteOnlyRowsForTest) - assert.Contains(t, env.stderr.String(), "listing truncated") - assert.Contains(t, env.stderr.String(), "1 further remote-only") + assert.Contains(t, stderr, "Listing truncated") + assert.Contains(t, stderr, `"omitted":1`) + assert.Contains(t, stderr, + fmt.Sprintf(`"limit":%d`, maxRemoteOnlyRowsForTest)) } // captureProcessStdout redirects the process's own stdout to a pipe, -// rebuilds the global logger over it, runs fn, and returns everything -// written. +// rebuilds the global logger, runs fn, and returns everything written to +// the pipe. // -// internal/log builds its logger over os.Stdout at construction time and -// offers no injectable sink (issue #82), so a warning logged during a -// --json listing lands on the process's real stdout, not on any writer a -// test can inject. Capturing the file descriptor is therefore the only -// way a test can see what `snapshot list --json | jq` would see. +// The logger is rebuilt on purpose even though it is supposed to write +// to stderr: that is exactly what makes this a regression guard. If the +// logger ever goes back to os.Stdout, Initialize picks up the pipe and +// the log record shows up in the capture, breaking the JSON parse here +// the same way it would break `snapshot list --json | jq` in the field. +// Without the rebuild, a regressed logger would write to the real stdout +// the test process was started with and go unnoticed. // // Not parallel-safe: os.Stdout and the logger are process-global. func captureProcessStdout(t *testing.T, fn func(stdout io.Writer)) string { @@ -714,8 +718,6 @@ func captureProcessStdout(t *testing.T, fn func(stdout io.Writer)) string { previous := os.Stdout os.Stdout = writer - // Rebuild the logger so it writes to the pipe rather than to the - // real stdout the test process was started with. log.Initialize(log.Config{}) drained := make(chan string, 1) @@ -738,7 +740,57 @@ func captureProcessStdout(t *testing.T, fn func(stdout io.Writer)) string { require.NoError(t, reader.Close()) - // Put the logger back on the restored stdout. + // Put the logger back on the restored streams. + log.Initialize(log.Config{}) + + return captured +} + +// captureProcessStderr redirects the process's own stderr to a pipe, +// rebuilds the global logger over it, runs fn, and returns everything +// written. +// +// internal/log writes every diagnostic to os.Stderr and captures that +// file at Initialize time, so a warning logged during a listing lands on +// the process's real stderr, not on any writer a test can inject. +// Capturing the file descriptor is therefore the only way a test can see +// what the operator would see. The captured stream is a pipe rather than +// a terminal, so the records are JSON — the same form a redirected +// stderr gets in production. +// +// Not parallel-safe: os.Stderr and the logger are process-global. +func captureProcessStderr(t *testing.T, fn func()) string { + t.Helper() + + reader, writer, err := os.Pipe() + require.NoError(t, err) + + previous := os.Stderr + os.Stderr = writer + + log.Initialize(log.Config{}) + + drained := make(chan string, 1) + + go func() { + var buf bytes.Buffer + + _, _ = io.Copy(&buf, reader) + + drained <- buf.String() + }() + + fn() + + os.Stderr = previous + + require.NoError(t, writer.Close()) + + captured := <-drained + + require.NoError(t, reader.Close()) + + // Put the logger back on the restored streams. log.Initialize(log.Config{}) return captured @@ -747,13 +799,18 @@ func captureProcessStdout(t *testing.T, fn func(stdout io.Writer)) string { // TestListSnapshots_JSONStdoutIsOnlyTheDocument is the regression guard // for `snapshot list --json | jq` surviving a damaged destination store. // -// Every stdout writer the command has — the JSON encoder, the UI, and -// the global logger — is pointed at one pipe here, exactly as they are -// pointed at one file descriptor in production. A single log line about -// a corrupt manifest ahead of the array is enough to break the parse, -// and that is what this asserts cannot happen. +// Every stdout writer the command has — the JSON encoder and the UI — +// is pointed at one pipe here, exactly as they are pointed at one file +// descriptor in production, and the logger is rebuilt over that same +// pipe's process-level stdout so that a logger which regressed back to +// stdout would land in the capture. A single log line about a corrupt +// manifest ahead of the array is enough to break the parse, and that is +// what this asserts cannot happen. // -//nolint:paralleltest // replaces os.Stdout and the global logger +// The two warnings are asserted on the separately captured stderr: they +// must be emitted, just not there. +// +//nolint:paralleltest // replaces os.Stdout, os.Stderr and the logger func TestListSnapshots_JSONStdoutIsOnlyTheDocument(t *testing.T) { env := newListEnv(t) @@ -772,11 +829,15 @@ func TestListSnapshots_JSONStdoutIsOnlyTheDocument(t *testing.T) { oddKey := env.addRemoteRawTimestamp(t, "testhost_odd_2026-03-04T00:00:00Z", "the day before yesterday") - captured := captureProcessStdout(t, func(stdout io.Writer) { - env.v.Stdout = stdout - env.v.UI = ui.NewWithColor(stdout, false) + var captured string - require.NoError(t, env.v.ListSnapshots(true)) + stderr := captureProcessStderr(t, func() { + captured = captureProcessStdout(t, func(stdout io.Writer) { + env.v.Stdout = stdout + env.v.UI = ui.NewWithColor(stdout, false) + + require.NoError(t, env.v.ListSnapshots(true)) + }) }) rows := decodeListJSON(t, captured) @@ -794,8 +855,8 @@ func TestListSnapshots_JSONStdoutIsOnlyTheDocument(t *testing.T) { // Both warnings were emitted, on the stream that cannot corrupt the // document. - stderr := env.stderr.String() assert.Contains(t, stderr, "Could not describe remote snapshot") assert.Contains(t, stderr, "Remote manifest has an unparseable timestamp") - assert.Contains(t, stderr, "1 remote snapshot(s) could not be described") + assert.Contains(t, stderr, "could not be described") + assert.Contains(t, stderr, `"unreadable":1`) } diff --git a/internal/vaultik/vaultik.go b/internal/vaultik/vaultik.go index e1ffe2a..a6a2630 100644 --- a/internal/vaultik/vaultik.go +++ b/internal/vaultik/vaultik.go @@ -43,7 +43,11 @@ type Vaultik struct { ctx context.Context //nolint:containedctx // ctx bound at construction by design cancel context.CancelFunc - // IO + // IO. Stdout carries the output the user asked for and nothing else, + // so that `--json | jq` works. Stderr completes the standard triple + // for anything a command needs to write there directly; diagnostics + // are not that — they go through internal/log, which writes to the + // process's stderr. Stdout io.Writer Stderr io.Writer Stdin io.Reader