34
README.md
34
README.md
@@ -113,11 +113,32 @@ vaultik version
|
||||
### global flags
|
||||
|
||||
* `--config <path>`: 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 |
|
||||
|
||||
39
TODO.md
39
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
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
377
internal/log/tty_handler_test.go
Normal file
377
internal/log/tty_handler_test.go
Normal 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
64
internal/log/with_test.go
Normal 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"))
|
||||
}
|
||||
@@ -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] {
|
||||
|
||||
@@ -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`)
|
||||
}
|
||||
|
||||
@@ -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
|
||||
|
||||
Reference in New Issue
Block a user