Send diagnostics to stderr and stop dropping log attributes (closes #82)
All checks were successful
check / check (pull_request) Successful in 2m34s

Two defects in internal/log, fixed together because both live in the
handler construction path.

Logger on stdout (#82). Initialize built both handlers over os.Stdout.
Every --json subcommand writes its document to that same stream, and
WARN/ERROR are never suppressed by any flag, so a log record could land
inside a JSON document and break the parse. This was not theoretical: a
config file with group- or world-readable permissions triggers a WARN
during startup, which was enough to make `snapshot list --json | jq`
fail. Diagnostics now go to stderr, and the TTY/JSON format choice
follows stderr's TTY-ness rather than stdout's -- testing the wrong
stream would colorize records on a redirected stderr whenever stdout
happened to be a terminal, and emit JSON to a terminal in the reverse
case.

This is user-visible: --verbose and --debug output moves to stderr as
well, so `vaultik snapshot list -v > out.txt` no longer captures the
diagnostics. README.md documents the split under a new "stdout and
stderr" section. --quiet and --cron semantics are untouched: level
selection is unchanged, and warnings and errors are still emitted in
both modes.

It also retires the local workaround in internal/vaultik/snapshot_list.go.
warnWhileListing had been hand-rolling structured-log formatting to reach
a writer that was not stdout, and the jsonOutput parameter threaded
through the remote-listing helpers existed only to choose between the two
writers; both are gone, and those warnings go through log.Warn in every
mode. The collect-then-emit machinery around listingWarning stays, on
its remaining merit rather than its original one: slog handlers are safe
for concurrent use, but emitting from the manifest-fetch workers would
order warnings by network timing, where collecting and emitting in key
order after group.Wait makes two runs over the same damaged store
produce the same diagnostics in the same order.

TTYHandler dropped attributes (#97). WithAttrs and WithGroup discarded
their arguments and returned the receiver, while their doc comments
claimed the opposite. Because the handler is chosen by TTY-ness, this
failed only on a terminal and worked correctly in CI -- so it broke
exactly when someone was debugging interactively. Both now return a new
handler: the receiver is never written to, since slog permits a handler
to be shared and derived from concurrently, and the derived handler
copies its slices rather than reslicing so two concurrent derivations
cannot overwrite each other's attributes. The mutex became a pointer so
handlers sharing a stream keep sharing one lock. Attributes persist
across every subsequent record, and grouping is implemented as dotted
key prefixes, which is the only honest rendering for a format with
nowhere to nest.

Tests: an attribute attached through the exported log.With reaches
TTYHandler output; attributes persist across records; groups qualify
keys; deriving does not leak between siblings or back to the parent;
sixteen goroutines derive from and write through one handler under
-race; and the TTY and JSON handlers are fed identical derivation chains
and compared attribute set by attribute set, which is the test that
would have caught the original defect and the one that stops the two
paths drifting again. All of these fail against the unfixed handler.

The existing snapshot-list tests that asserted these warnings on an
injected writer now capture the process's real stderr, which is where
they go; the assertions are otherwise unchanged.
This commit is contained in:
2026-08-09 16:25:50 +00:00
parent e3f407b440
commit b7aee81fa5
9 changed files with 841 additions and 162 deletions

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