Files
vaultik/internal/log/tty_handler.go
clawbot 4de3e419b9
All checks were successful
check / check (pull_request) Successful in 2m46s
Suppress the startup banner under --json (closes #106)
Entry writes the banner to stdout before cobra parses anything, and the
scan that decides whether to write it knew --quiet, -q and --cron but
not --json. Every --json document therefore arrived behind two lines of
prose and a blank line, and `vaultik snapshot list --json | jq` failed.
Passing opts.JSON as extraQuiet could not help: that reaches UI.SetQuiet
through an fx OnStart hook, long after the banner is already written.
With the logger moved to stderr in #82, this was the last writer that
could put something on stdout the caller did not ask for.

The design question the issue raised is answered in favour of extending
the raw-argv scan rather than moving the banner after parsing. The
banner is printed first deliberately, so that it still appears when
cobra rejects the arguments and on --help; after parsing there is no
single place that covers those paths, so "after parsing" means either
reimplementing the banner in several handlers or losing it exactly where
a human most wants to know which build just ran. The objection to the
scan is that --json is a subcommand flag matched anywhere in the vector,
but --cron is already in the list and is also a subcommand flag: it
exists only on `snapshot create`. So this adds another instance of an
imprecision the code already accepts, not a new kind of one. The two
error directions are not symmetric either — a false positive loses a
decorative banner, a false negative corrupts a document — so the scan
errs toward suppression, and --json=false suppresses it exactly as
--quiet=false already does.

Three tests at the CLI layer, where internal/vaultik's existing guard
cannot reach. TestEntryJSONStdoutIsExactlyOneDocument runs Entry itself
over the process's real stdout descriptor, through cobra and the fx
graph to the document, and asserts the capture decodes as one JSON value
with nothing after it; it is hermetic because file:// storage needs no
credentials and `snapshot list` treats a destination store with no
metadata/ as an empty list rather than a failure. A second covers the
argument vectors of all five --json commands plus the pre-subcommand and
--json=true forms. A third asserts the banner is still printed without a
suppressing flag, so the first cannot be satisfied by deleting it.

AGENTS.md policy 9 still keyed the structured-log format on stdout's
TTY-ness after #82 moved that decision to stderr; it now names the log
stream. A rules file that misdescribes the code misleads exactly the
readers who trust it most.

Two smaller findings from the same review. bytesAttrKey's human-readable
byte formatting stopped applying under an open group, because the key
reaching the comparison is group-qualified: "bytes" logged under a group
arrives as "transfer.bytes" and fell back to a bare number. The match is
now made on the final dot-separated segment, tested both grouped and
ungrouped. And listEnv.stderr in snapshot_list_test.go, assigned but
never read since those tests began capturing the process's stderr, is
removed. Vaultik.Stderr is kept — nothing writes to it today, which its
comment now says outright rather than leaving the next reader to hunt
for a writer that does not exist.

`prune --json` still does not survive jq, for an unrelated reason found
while verifying this: pruneLocalSnapshots writes three lines of prose to
stdout with no --json awareness, on main and after this change alike,
and -q never suppressed them either. Filed as #108 rather than fixed
here, being a different writer on a different code path.
2026-08-09 17:08:54 +00:00

297 lines
8.0 KiB
Go

package log //nolint:revive,nolintlint // stdlib log unused here; see #76
import (
"context"
"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. Keys reaching
// writeAttr are group-qualified, so the match is made against the final
// dot-separated segment: without that, a "bytes" attribute logged under
// an open group would arrive as "transfer.bytes" and silently lose its
// formatting.
const bytesAttrKey = "bytes"
// isBytesAttr reports whether a group-qualified attribute key names the
// byte-count attribute, i.e. whether its last segment is bytesAttrKey.
func isBytesAttr(key string) bool {
if idx := strings.LastIndex(key, groupSeparator); idx >= 0 {
key = key[idx+len(groupSeparator):]
}
return key == bytesAttrKey
}
// ANSI color codes
const (
colorReset = "\033[0m"
colorRed = "\033[31m"
colorYellow = "\033[33m"
colorBlue = "\033[34m"
colorGray = "\033[90m"
colorGreen = "\033[32m"
colorCyan = "\033[36m"
colorBold = "\033[1m"
)
// 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
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.
func NewTTYHandler(out io.Writer, opts *slog.HandlerOptions) *TTYHandler {
if opts == nil {
opts = &slog.HandlerOptions{}
}
return &TTYHandler{
out: out,
opts: *opts,
mu: &sync.Mutex{},
}
}
// Enabled reports whether the handler handles records at the given level.
func (h *TTYHandler) Enabled(_ context.Context, level slog.Level) bool {
return level >= h.opts.Level.Level()
}
// Handle writes the log record to the output with color formatting.
func (h *TTYHandler) Handle(_ context.Context, r slog.Record) error {
h.mu.Lock()
defer h.mu.Unlock()
// Format timestamp
timestamp := r.Time.Format("15:04:05")
// Level and color
level := r.Level.String()
var levelColor string
switch r.Level {
case slog.LevelDebug:
levelColor = colorGray
level = "DEBUG"
case slog.LevelInfo:
levelColor = colorGreen
level = "INFO "
case slog.LevelWarn:
levelColor = colorYellow
level = "WARN "
case slog.LevelError:
levelColor = colorRed
level = "ERROR"
default:
levelColor = colorReset
}
// Print main message
_, _ = fmt.Fprintf(h.out, "%s%s%s %s%s%s %s%s%s",
colorGray, timestamp, colorReset,
levelColor, level, colorReset,
colorBold, r.Message, colorReset)
// 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)
}
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
})
_, _ = fmt.Fprintln(h.out)
return nil
}
// 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
}
// 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 isBytesAttr(a.Key) {
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
func formatDuration(d time.Duration) string {
switch {
case d < time.Millisecond:
return fmt.Sprintf("%dµs", d.Microseconds())
case d < time.Second:
return fmt.Sprintf("%dms", d.Milliseconds())
case d < time.Minute:
return fmt.Sprintf("%.1fs", d.Seconds())
default:
return d.String()
}
}
// formatBytes formats bytes in a human-readable way
func formatBytes(b int64) string {
const unit = 1024
if b < unit {
return fmt.Sprintf("%d B", b)
}
div, exp := int64(unit), 0
for n := b / unit; n >= unit; n /= unit {
div *= unit
exp++
}
return fmt.Sprintf("%.1f %cB", float64(b)/float64(div), "KMGTPE"[exp])
}