Compare commits
4 Commits
ea3d702b1f
...
main
| Author | SHA1 | Date | |
|---|---|---|---|
| 696ed9ab4d | |||
| f21e7c9e70 | |||
| c16ef476a9 | |||
| e3f407b440 |
@@ -83,8 +83,8 @@ Version: 2025-06-08
|
||||
possible to mock or stub these side-effects in tests.
|
||||
|
||||
9. Always use structured logging. Log any relevant state/context with the
|
||||
messages (but do not log secrets). If stdout is not a terminal, output
|
||||
the structured logs in jsonl format.
|
||||
messages (but do not log secrets). If the log stream is not a terminal,
|
||||
output the structured logs in jsonl format.
|
||||
|
||||
10. Avoid using bare strings or numbers in code, especially if they appear
|
||||
anywhere more than once. Always define a constant (usually at the top
|
||||
|
||||
13
Makefile
13
Makefile
@@ -66,7 +66,18 @@ lint:
|
||||
lint-fix:
|
||||
@script/lint-fix
|
||||
|
||||
# Build binary.
|
||||
# Build binary. `build` is the name the org convention reaches for and
|
||||
# the one a caller checks the exit code of; `vaultik` is the file rule
|
||||
# that does the work, so an unchanged tree still short-circuits.
|
||||
#
|
||||
# This alias is not decorative. `build` was listed in .PHONY with no
|
||||
# rule, and a phony target with no prerequisites and no recipe is
|
||||
# already satisfied: `make build` printed "Nothing to be done" and
|
||||
# exited 0 without producing a binary (issue #110). Every name in
|
||||
# .PHONY needs a rule for that reason; TestPhonyTargetsAllHaveRules in
|
||||
# cmd/vaultik keeps it that way.
|
||||
build: vaultik
|
||||
|
||||
vaultik: internal/*/*.go cmd/vaultik/*.go
|
||||
go build -ldflags "$(LDFLAGS)" -o $@ ./cmd/vaultik
|
||||
|
||||
|
||||
42
README.md
42
README.md
@@ -113,11 +113,40 @@ 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.
|
||||
|
||||
Under `--json`, stdout holds the document and nothing else. The startup
|
||||
banner is suppressed, as `--quiet` and `--cron` suppress it, and the
|
||||
progress narration a command would otherwise print — such as the stale
|
||||
local records `prune` reconciles away — is suppressed too, so it cannot
|
||||
land ahead of the document. Every `--json` command therefore pipes on
|
||||
its own, with no additional flag: `vaultik snapshot list --json | jq .`
|
||||
and `vaultik prune --json | jq .` both work as written.
|
||||
|
||||
### environment variables
|
||||
|
||||
* `VAULTIK_AGE_SECRET_KEY`: Age private key for decryption (required for `snapshot restore` and `snapshot verify --deep`)
|
||||
@@ -208,8 +237,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 +534,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 |
|
||||
|
||||
133
TODO.md
133
TODO.md
@@ -25,6 +25,139 @@ release" is exactly the contradiction
|
||||
|
||||
# Completed Steps
|
||||
|
||||
- 2026-08-09: Finished the `--json` stdout contract and gave `make build`
|
||||
a rule ([issue #108](https://git.eeqj.de/sneak/vaultik/issues/108),
|
||||
[issue #110](https://git.eeqj.de/sneak/vaultik/issues/110)). Two
|
||||
unrelated defects of the same shape — a command reporting something it
|
||||
did not do — landed together because both are small.
|
||||
|
||||
`CleanupLocalSnapshots` wrote three prose lines to stdout with no
|
||||
`--json` awareness, covering every branch of the function, so no input
|
||||
avoided them and `vaultik prune --json | jq` failed even after
|
||||
[issue #106](https://git.eeqj.de/sneak/vaultik/issues/106) removed the
|
||||
banner. `-q` never helped either: `printlnStdout` and `stdoutf` write
|
||||
straight to `Vaultik.Stdout` and never consult `Vaultik.UI`, which is
|
||||
what `SetQuiet` affects. The issue offered three fixes and asked for a
|
||||
decision. Taken: thread `*PruneOptions` into the function and gate each
|
||||
write on `!opts.JSON`, matching `PruneBlobs` (its sibling phase, which
|
||||
already takes the same struct), `RemoveSnapshot` and `remote info`, so
|
||||
the package has one pattern rather than two. Rejected: moving the lines
|
||||
to `log.Info`, because the logger's default level is `slog.LevelWarn`,
|
||||
so that would not relocate them to stderr — it would delete them from a
|
||||
plain `vaultik prune`, and the removal of rows from the local index is
|
||||
not something to narrate only under `--verbose`. Also rejected: putting
|
||||
the stale-record count into `PruneBlobsResult`, whose every field is
|
||||
blob-scoped and which is produced by the later phase; a prune document
|
||||
covering both phases is a reasonable thing to want, but it is a schema
|
||||
design question and not a stream-hygiene fix. The narration is
|
||||
duplicated as `log.Info` records, which `PruneBlobs` already does
|
||||
alongside its own prints, so the events survive on stderr for anyone
|
||||
running `--verbose`.
|
||||
|
||||
`make build` printed "Nothing to be done for 'build'" and exited 0
|
||||
without producing a binary: `build` was listed in `.PHONY` with no
|
||||
`build:` rule anywhere, and declaring a name phony is exactly what
|
||||
converts make's "No rule to make target" error into a silent success.
|
||||
Fixed with `build: vaultik`, keeping `vaultik:` as the file rule. The
|
||||
audit the issue asked for covers all 19 `.PHONY` names; `build` was the
|
||||
only one without a rule, and `vaultik` is correctly absent from
|
||||
`.PHONY`, being a real file target.
|
||||
|
||||
Tests, each verified to fail with the fix reverted rather than assumed
|
||||
to: `CleanupLocalSnapshots` leaves stdout untouched under `--json` in
|
||||
all three branches (stale records, none, empty index) and still emits
|
||||
every line without it, so the guard cannot be satisfied by deleting the
|
||||
output; `prune --json` run end to end through `Entry`, cobra and fx
|
||||
over the process's real stdout descriptor against a `file://` store,
|
||||
asserting exactly one JSON document, in both the stale and non-stale
|
||||
branches; and a parse of the `Makefile` asserting every `.PHONY` name
|
||||
has a rule and that `build` reaches the rule that produces the binary,
|
||||
which keeps the audit true for names added later. That last one is a
|
||||
parse rather than an invocation of `make`, since `make test` is what
|
||||
runs it and shelling back into `make build` would nest a build inside
|
||||
the test run. The property a parse cannot establish — that the recipe
|
||||
still fails when the build fails — was verified by hand against a
|
||||
deliberately broken tree: `make build` exits 2 and produces nothing.
|
||||
`cmd/vaultik` gains its first test file, so `make test` now reports 16
|
||||
packages `ok` where it reported 15.
|
||||
|
||||
- 2026-08-09: Stopped the startup banner from contaminating `--json`
|
||||
documents ([issue #106](https://git.eeqj.de/sneak/vaultik/issues/106)).
|
||||
`Entry` writes the banner to stdout before cobra parses anything, and
|
||||
the flag scan that suppresses it knew `--quiet`, `-q` and `--cron` but
|
||||
not `--json`, so every `--json` document arrived behind two lines of
|
||||
prose and a blank line, and `vaultik snapshot list --json | jq` failed.
|
||||
With the logger already on stderr from
|
||||
[issue #82](https://git.eeqj.de/sneak/vaultik/issues/82), this was the
|
||||
last writer that could put something on stdout that the caller did not
|
||||
ask for. The design question the issue raised — extend the raw-argv
|
||||
scan, or move the banner after parsing — is answered in favour of the
|
||||
scan: the banner is printed first deliberately, so that it still
|
||||
appears when cobra rejects the arguments and on `--help`, and after
|
||||
parsing there is no single place that covers those paths. The stated
|
||||
cost of the scan, that `--json` is a subcommand flag matched anywhere
|
||||
in the vector, is a cost `--cron` already carries — it exists only on
|
||||
`snapshot create` — so this adds an instance of an accepted
|
||||
imprecision rather than a new kind, and the two error directions are
|
||||
not symmetric: a false positive loses a decorative banner, a false
|
||||
negative corrupts a document. Regression tests at the CLI layer, where
|
||||
`internal/vaultik`'s existing guard cannot reach: one runs `Entry`
|
||||
itself over the process's real stdout descriptor, through cobra and fx
|
||||
to the document, made hermetic by `file://` storage; a second covers
|
||||
the argument vectors of all five `--json` commands; a third asserts the
|
||||
banner is still printed without a suppressing flag, so the first
|
||||
cannot be satisfied by deleting the banner. Also corrected `AGENTS.md`
|
||||
policy 9, which still keyed the structured-log format on stdout's
|
||||
TTY-ness after #82 moved that decision to stderr — 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 silently stopped applying under an open
|
||||
group, because the key reaching the comparison is group-qualified
|
||||
(`transfer.bytes`), now matched on its final segment and tested both
|
||||
ways; 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.
|
||||
|
||||
- 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
|
||||
|
||||
169
cmd/vaultik/makefile_test.go
Normal file
169
cmd/vaultik/makefile_test.go
Normal file
@@ -0,0 +1,169 @@
|
||||
package main_test
|
||||
|
||||
import (
|
||||
"os"
|
||||
"path/filepath"
|
||||
"regexp"
|
||||
"slices"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
)
|
||||
|
||||
// This file guards the Makefile that builds this program, which is why
|
||||
// it lives beside it rather than in a package of its own.
|
||||
//
|
||||
// Issue #110: `build` was listed in .PHONY with no `build:` rule
|
||||
// anywhere in the file. That combination is silently successful — make
|
||||
// considers a phony target with no prerequisites and no recipe already
|
||||
// satisfied, so `rm -f vaultik && make build` printed "Nothing to be
|
||||
// done for 'build'" and exited 0 with no binary produced. Declaring the
|
||||
// name phony is precisely what converts the "No rule to make target"
|
||||
// error into a green.
|
||||
//
|
||||
// The guard is a parse of the Makefile rather than an invocation of
|
||||
// make. `make test` is what runs these tests, so shelling back into
|
||||
// `make build` here would nest a build inside the test run and drop a
|
||||
// binary into the tree as a side effect of testing. The one property a
|
||||
// parse cannot establish — that the recipe still fails when the build
|
||||
// fails — is not testable from inside the build either; it is verified
|
||||
// by hand against a deliberately broken tree.
|
||||
|
||||
// phonyDirective introduces the list of phony target names.
|
||||
const phonyDirective = ".PHONY:"
|
||||
|
||||
// ruleLine matches a rule's target list: a target starts in column
|
||||
// zero, so recipe lines (tab-indented) and the continuation lines of a
|
||||
// variable assignment (space-indented) are excluded by construction.
|
||||
//
|
||||
// The trailing (?:[^=]|$) rejects `:=` assignments such as
|
||||
// `VERSION := $(shell script/version)`, which are not rules. Directives
|
||||
// and function calls (`.PHONY:`, `ifeq`, `$(error ...)`) do not match
|
||||
// because a target here must begin with a letter, digit or underscore.
|
||||
var ruleLine = regexp.MustCompile(`^([A-Za-z0-9_][A-Za-z0-9_./ -]*):(?:[^=]|$)`)
|
||||
|
||||
// TestPhonyTargetsAllHaveRules fails on any name in .PHONY that has no
|
||||
// rule in the Makefile. Such a name is not a build target at all: it is
|
||||
// a command that reports success without doing anything, which is worse
|
||||
// than one that does not exist, because a caller checking the exit code
|
||||
// cannot tell the difference.
|
||||
func TestPhonyTargetsAllHaveRules(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
makefile := readMakefile(t)
|
||||
|
||||
phony := phonyTargets(makefile)
|
||||
require.NotEmpty(t, phony, "no .PHONY names found; the parser is broken")
|
||||
|
||||
rules := declaredRules(makefile)
|
||||
|
||||
// Sanity check on the rule parser before trusting its verdict: a
|
||||
// parser that found nothing would pass this test by accident.
|
||||
require.Contains(t, rules, "vaultik",
|
||||
"the file rule that builds the binary must be recognized")
|
||||
|
||||
for _, target := range phony {
|
||||
assert.Contains(t, rules, target,
|
||||
"`.PHONY` lists %q but the Makefile declares no %q rule, so "+
|
||||
"`make %s` exits 0 without doing anything", target, target, target)
|
||||
}
|
||||
}
|
||||
|
||||
// TestBuildTargetBuildsTheBinary pins the specific shape of issue #110:
|
||||
// `make build` has to reach the rule that produces the binary. The test
|
||||
// above would also pass if `build:` were given an empty recipe of its
|
||||
// own, which would be the same silent success under a different
|
||||
// spelling.
|
||||
func TestBuildTargetBuildsTheBinary(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
prerequisites := rulePrerequisites(readMakefile(t), "build")
|
||||
require.NotNil(t, prerequisites, "the Makefile declares no `build` rule")
|
||||
|
||||
assert.Contains(t, prerequisites, "vaultik",
|
||||
"`make build` must depend on the rule that builds the binary")
|
||||
}
|
||||
|
||||
// readMakefile returns the contents of the repository's Makefile. The
|
||||
// test binary runs with its package directory as the working directory,
|
||||
// so the root is found by walking up until the Makefile appears.
|
||||
func readMakefile(t *testing.T) string {
|
||||
t.Helper()
|
||||
|
||||
dir, err := os.Getwd()
|
||||
require.NoError(t, err)
|
||||
|
||||
for {
|
||||
//nolint:gosec // G304: the path is this test's own directory walk
|
||||
contents, err := os.ReadFile(filepath.Join(dir, "Makefile"))
|
||||
if err == nil {
|
||||
return string(contents)
|
||||
}
|
||||
|
||||
parent := filepath.Dir(dir)
|
||||
require.NotEqual(t, dir, parent,
|
||||
"walked to the filesystem root without finding a Makefile")
|
||||
|
||||
dir = parent
|
||||
}
|
||||
}
|
||||
|
||||
// phonyTargets returns every name declared phony, across all .PHONY
|
||||
// lines.
|
||||
func phonyTargets(makefile string) []string {
|
||||
var targets []string
|
||||
|
||||
for line := range strings.SplitSeq(makefile, "\n") {
|
||||
if !strings.HasPrefix(line, phonyDirective) {
|
||||
continue
|
||||
}
|
||||
|
||||
targets = append(targets,
|
||||
strings.Fields(strings.TrimPrefix(line, phonyDirective))...)
|
||||
}
|
||||
|
||||
return targets
|
||||
}
|
||||
|
||||
// declaredRules returns the set of target names that have a rule.
|
||||
func declaredRules(makefile string) map[string]bool {
|
||||
rules := make(map[string]bool)
|
||||
|
||||
for line := range strings.SplitSeq(makefile, "\n") {
|
||||
match := ruleLine.FindStringSubmatch(line)
|
||||
if match == nil {
|
||||
continue
|
||||
}
|
||||
|
||||
// One rule may name several targets: `a b: prereq`.
|
||||
for target := range strings.FieldsSeq(match[1]) {
|
||||
rules[target] = true
|
||||
}
|
||||
}
|
||||
|
||||
return rules
|
||||
}
|
||||
|
||||
// rulePrerequisites returns the prerequisites of the named rule, or nil
|
||||
// if no such rule exists. A rule with none returns an empty slice, so
|
||||
// "declared with nothing to do" is distinguishable from "not declared".
|
||||
func rulePrerequisites(makefile, target string) []string {
|
||||
for line := range strings.SplitSeq(makefile, "\n") {
|
||||
match := ruleLine.FindStringSubmatch(line)
|
||||
if match == nil {
|
||||
continue
|
||||
}
|
||||
|
||||
if !slices.Contains(strings.Fields(match[1]), target) {
|
||||
continue
|
||||
}
|
||||
|
||||
_, after, _ := strings.Cut(line, ":")
|
||||
|
||||
return append([]string{}, strings.Fields(after)...)
|
||||
}
|
||||
|
||||
return nil
|
||||
}
|
||||
@@ -1,6 +1,7 @@
|
||||
package cli
|
||||
|
||||
import (
|
||||
"io"
|
||||
"os"
|
||||
"strings"
|
||||
"time"
|
||||
@@ -14,18 +15,12 @@ import (
|
||||
const shortCommitLen = 12
|
||||
|
||||
// Entry is the main entry point for the CLI application.
|
||||
// It prints the startup banner (unless a quiet flag is present in os.Args),
|
||||
// executes the root cobra command, and routes any returned error through
|
||||
// the ui.Writer so the user sees a properly formatted "🛑 ERROR:" line.
|
||||
// It prints the startup banner to stdout (unless a banner-suppressing
|
||||
// flag is present in os.Args — see bannerSuppressedInArgs), executes the
|
||||
// root cobra command, and routes any returned error through the
|
||||
// ui.Writer so the user sees a properly formatted "🛑 ERROR:" line.
|
||||
func Entry() {
|
||||
if !bannerSuppressedInArgs(os.Args[1:]) {
|
||||
short := globals.Commit
|
||||
if len(short) > shortCommitLen {
|
||||
short = short[:shortCommitLen]
|
||||
}
|
||||
|
||||
writeStartupBanner(ui.New(os.Stdout), time.Now().UTC(), short)
|
||||
}
|
||||
emitStartupBanner(os.Args[1:], os.Stdout)
|
||||
|
||||
rootCmd := NewRootCommand()
|
||||
rootCmd.SilenceErrors = true
|
||||
@@ -37,6 +32,24 @@ func Entry() {
|
||||
}
|
||||
}
|
||||
|
||||
// emitStartupBanner writes the startup banner to w unless args (the
|
||||
// argument vector with the program name already stripped) contains a
|
||||
// flag that suppresses it. Split out of Entry so that the decision — the
|
||||
// only thing standing between a --json invocation and a parseable
|
||||
// stdout — is reachable from a test without running the whole CLI.
|
||||
func emitStartupBanner(args []string, w io.Writer) {
|
||||
if bannerSuppressedInArgs(args) {
|
||||
return
|
||||
}
|
||||
|
||||
short := globals.Commit
|
||||
if len(short) > shortCommitLen {
|
||||
short = short[:shortCommitLen]
|
||||
}
|
||||
|
||||
writeStartupBanner(ui.New(w), time.Now().UTC(), short)
|
||||
}
|
||||
|
||||
// ReportErrorf emits a user-facing error to stderr in the standard
|
||||
// 🛑 ERROR: format. Use it from goroutine error paths (where returning
|
||||
// an error to cobra isn't an option) and anywhere else a CLI command
|
||||
@@ -46,9 +59,20 @@ func ReportErrorf(format string, args ...any) {
|
||||
}
|
||||
|
||||
// bannerSuppressedInArgs reports whether any of args is a flag that
|
||||
// should suppress the startup banner (--quiet/-q/--cron). Stops at the
|
||||
// "--" argument terminator. Recognizes both long forms and short -q,
|
||||
// including combined short flags like "-qv".
|
||||
// should suppress the startup banner (--quiet/-q/--cron/--json). Stops
|
||||
// at the "--" argument terminator. Recognizes both long forms and short
|
||||
// -q, including combined short flags like "-qv".
|
||||
//
|
||||
// This scans the raw argument vector because the banner is printed
|
||||
// before cobra parses anything — deliberately, so that it still appears
|
||||
// when cobra rejects the arguments and on --help. The consequence is
|
||||
// that a flag is matched wherever it occurs in the vector, including
|
||||
// positions where the command it belongs to would not accept it.
|
||||
// --json is a subcommand flag rather than a persistent one, but so is
|
||||
// --cron (it exists only on `snapshot create`), so this adds no new
|
||||
// class of imprecision. The only cost of a false positive is a missing
|
||||
// decorative banner; the cost of a false negative is a corrupt document
|
||||
// on stdout, so the scan errs deliberately in that direction.
|
||||
func bannerSuppressedInArgs(args []string) bool {
|
||||
for _, a := range args {
|
||||
if a == "--" {
|
||||
@@ -56,11 +80,13 @@ func bannerSuppressedInArgs(args []string) bool {
|
||||
}
|
||||
|
||||
switch a {
|
||||
case "--quiet", "-q", "--cron":
|
||||
case "--quiet", "-q", "--cron", "--json":
|
||||
return true
|
||||
}
|
||||
|
||||
if strings.HasPrefix(a, "--quiet=") || strings.HasPrefix(a, "--cron=") {
|
||||
if strings.HasPrefix(a, "--quiet=") ||
|
||||
strings.HasPrefix(a, "--cron=") ||
|
||||
strings.HasPrefix(a, "--json=") {
|
||||
return true
|
||||
}
|
||||
// Combined short flags like -qv or -vq.
|
||||
|
||||
300
internal/cli/entry_banner_test.go
Normal file
300
internal/cli/entry_banner_test.go
Normal file
@@ -0,0 +1,300 @@
|
||||
package cli //nolint:testpackage // needs access to unexported emitStartupBanner
|
||||
|
||||
import (
|
||||
"bytes"
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"io"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"strings"
|
||||
"testing"
|
||||
|
||||
"github.com/adrg/xdg"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
)
|
||||
|
||||
// Command words and flags used to build argument vectors below. They are
|
||||
// constants rather than repeated literals so that a rename shows up as a
|
||||
// compile error in one place.
|
||||
const (
|
||||
cmdSnapshot = "snapshot"
|
||||
cmdList = "list"
|
||||
cmdCreate = "create"
|
||||
cmdVerify = "verify"
|
||||
cmdRemove = "remove"
|
||||
cmdPrune = "prune"
|
||||
cmdRemote = "remote"
|
||||
cmdInfo = "info"
|
||||
|
||||
flagJSON = "--json"
|
||||
flagQuiet = "--quiet"
|
||||
flagConfig = "--config"
|
||||
|
||||
// programName is argv[0] as the real process receives it. Entry
|
||||
// strips it before scanning, so it has to be present.
|
||||
programName = "vaultik"
|
||||
|
||||
// someSnapshotID is any snapshot identifier: these tests never run
|
||||
// the command, so it only has to occupy the positional argument.
|
||||
someSnapshotID = "host_2026-01-01T00:00:00Z"
|
||||
)
|
||||
|
||||
// placeholderJSONDocument stands in for whatever document a --json
|
||||
// command writes to stdout. `snapshot list --json` with no snapshots
|
||||
// prints exactly this; the other --json commands print an object rather
|
||||
// than an array, but this test is not about their shape. It is about
|
||||
// what is on stdout *before* them, which is the same for all of them
|
||||
// because Entry prints the banner before cobra has parsed anything and
|
||||
// therefore before it can know which command is running.
|
||||
const placeholderJSONDocument = "[]\n"
|
||||
|
||||
// jsonArgumentVectors are the argument vectors of every --json
|
||||
// invocation the CLI accepts, with the program name stripped exactly as
|
||||
// Entry strips it. Each one must leave stdout untouched by the banner.
|
||||
//
|
||||
//nolint:gochecknoglobals // read-only test fixture shared by two tests
|
||||
var jsonArgumentVectors = map[string][]string{
|
||||
"snapshot list": {cmdSnapshot, cmdList, flagJSON},
|
||||
"snapshot verify": {cmdSnapshot, cmdVerify, someSnapshotID, flagJSON},
|
||||
"snapshot remove": {cmdSnapshot, cmdRemove, someSnapshotID, flagJSON},
|
||||
"prune": {cmdPrune, flagJSON},
|
||||
"remote info": {cmdRemote, cmdInfo, flagJSON},
|
||||
|
||||
// --json before the subcommand, and with an explicit value: the
|
||||
// scan is positional, so both forms have to be recognized.
|
||||
"json first": {flagJSON, cmdSnapshot, cmdList},
|
||||
"json with value": {cmdSnapshot, cmdList, flagJSON + "=true"},
|
||||
|
||||
// A --json invocation that also carries a flag with a value, so the
|
||||
// scan cannot be fooled by an argument that consumes the next one.
|
||||
"json with config": {
|
||||
flagConfig, "/nonexistent/vaultik.yml", cmdSnapshot, cmdList, flagJSON,
|
||||
},
|
||||
}
|
||||
|
||||
// TestJSONInvocationStdoutIsExactlyOneDocument is the CLI-layer
|
||||
// regression guard for issue #106: `vaultik snapshot list --json | jq`
|
||||
// must work with no other flags.
|
||||
//
|
||||
// internal/vaultik's TestListSnapshots_JSONStdoutIsOnlyTheDocument
|
||||
// guards the same contract one layer down, but it calls the library
|
||||
// function directly and so cannot see Entry, which is where the
|
||||
// contamination was: the startup banner is written to stdout before
|
||||
// cobra parses anything, and the suppression scan did not know about
|
||||
// --json. The two banner lines and the blank line landed ahead of the
|
||||
// document and `jq` refused the result.
|
||||
//
|
||||
// The document is a constant here because this test is about the
|
||||
// argument vectors, one per --json command; the one that runs a real
|
||||
// command end to end is TestEntryJSONStdoutIsExactlyOneDocument below.
|
||||
func TestJSONInvocationStdoutIsExactlyOneDocument(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for name, argv := range jsonArgumentVectors {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var stdout bytes.Buffer
|
||||
|
||||
emitStartupBanner(argv, &stdout)
|
||||
|
||||
require.Empty(t, stdout.String(),
|
||||
"nothing may reach stdout ahead of a --json document")
|
||||
|
||||
_, err := stdout.WriteString(placeholderJSONDocument)
|
||||
require.NoError(t, err)
|
||||
|
||||
requireExactlyOneJSONDocument(t, stdout.String())
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestBannerStillPrintedWithoutSuppressingFlag pins the other half of
|
||||
// the contract. Without it, deleting the banner outright would satisfy
|
||||
// the test above, and the banner is wanted on interactive invocations.
|
||||
func TestBannerStillPrintedWithoutSuppressingFlag(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for name, argv := range map[string][]string{
|
||||
"no flags": {cmdSnapshot, cmdList},
|
||||
"verbose": {cmdSnapshot, cmdList, "--verbose"},
|
||||
"after the terminator": {
|
||||
cmdSnapshot, "restore", "--", flagJSON,
|
||||
},
|
||||
} {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var stdout bytes.Buffer
|
||||
|
||||
emitStartupBanner(argv, &stdout)
|
||||
|
||||
assert.Contains(t, stdout.String(), "starting up at",
|
||||
"the banner belongs on invocations that did not opt out")
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestBannerSuppressedInArgs covers the suppression scan directly,
|
||||
// including the flags that suppressed the banner before --json joined
|
||||
// them, so that adding --json cannot regress them.
|
||||
func TestBannerSuppressedInArgs(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
for name, testCase := range map[string]struct {
|
||||
args []string
|
||||
suppressed bool
|
||||
}{
|
||||
"quiet long": {[]string{cmdSnapshot, cmdCreate, flagQuiet}, true},
|
||||
"quiet short": {[]string{cmdSnapshot, cmdCreate, "-q"}, true},
|
||||
"quiet combined": {[]string{cmdSnapshot, cmdCreate, "-qv"}, true},
|
||||
"cron": {[]string{cmdSnapshot, cmdCreate, "--cron"}, true},
|
||||
"json": {[]string{cmdSnapshot, cmdList, flagJSON}, true},
|
||||
"nothing": {[]string{cmdSnapshot, cmdList}, false},
|
||||
"empty": {nil, false},
|
||||
"json after dashes": {
|
||||
[]string{cmdSnapshot, cmdList, "--", flagJSON}, false,
|
||||
},
|
||||
"quiet after dashes": {
|
||||
[]string{cmdSnapshot, cmdCreate, "--", "-q"}, false,
|
||||
},
|
||||
} {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
assert.Equal(t, testCase.suppressed,
|
||||
bannerSuppressedInArgs(testCase.args))
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// hermeticConfig is a complete, valid config that needs no network and
|
||||
// no credentials: file:// storage is exempt from the S3 credential
|
||||
// checks, and FileStorer over a directory that does not exist lists
|
||||
// zero objects without erroring. Chunk, blob and compression settings
|
||||
// are filled in by config.Load.
|
||||
const hermeticConfig = `age_recipients:
|
||||
- age1278m9q7dp3chsh2dcy82qk27v047zywyvtxwnj4cvt0z65jw6a7q5dqhfj
|
||||
snapshots:
|
||||
test:
|
||||
paths:
|
||||
- %s
|
||||
storage_url: file://%s
|
||||
index_path: %s
|
||||
hostname: test-host
|
||||
`
|
||||
|
||||
// TestEntryJSONStdoutIsExactlyOneDocument runs the real thing: Entry,
|
||||
// with a real argument vector, over the process's real stdout file
|
||||
// descriptor, all the way through cobra and the fx graph to the
|
||||
// document. It is the assertion the issue asks for — `vaultik snapshot
|
||||
// list --json | jq .` with no other flags — with the pipe replaced by a
|
||||
// decoder.
|
||||
//
|
||||
// `snapshot list` is the command chosen because it is the only --json
|
||||
// command that reaches its document without a populated destination
|
||||
// store: it reads the local index, streams `metadata/` (empty here),
|
||||
// and treats a barren destination as an empty list rather than a
|
||||
// failure.
|
||||
//
|
||||
// Not parallel: it replaces os.Args, os.Stdout and the xdg globals.
|
||||
func TestEntryJSONStdoutIsExactlyOneDocument(t *testing.T) {
|
||||
dir := t.TempDir()
|
||||
configPath := filepath.Join(dir, "config.yml")
|
||||
|
||||
contents := fmt.Sprintf(hermeticConfig,
|
||||
filepath.Join(dir, "source"),
|
||||
filepath.Join(dir, "store"),
|
||||
filepath.Join(dir, "index.sqlite"))
|
||||
|
||||
require.NoError(t,
|
||||
os.WriteFile(configPath, []byte(contents), configFileMode))
|
||||
|
||||
// The PID lock lives under xdg.DataHome, which xdg resolves at
|
||||
// package init; point it at the temp dir so the test neither
|
||||
// touches nor collides with the real one.
|
||||
t.Setenv("XDG_DATA_HOME", filepath.Join(dir, "data"))
|
||||
xdg.Reload()
|
||||
t.Cleanup(xdg.Reload)
|
||||
|
||||
previousArgs := os.Args
|
||||
|
||||
t.Cleanup(func() {
|
||||
os.Args = previousArgs
|
||||
rootFlags = RootFlags{}
|
||||
})
|
||||
|
||||
os.Args = []string{
|
||||
programName, flagConfig, configPath, cmdSnapshot, cmdList, flagJSON,
|
||||
}
|
||||
|
||||
stdout := captureProcessStdout(t, Entry)
|
||||
|
||||
requireExactlyOneJSONDocument(t, stdout)
|
||||
|
||||
var snapshots []any
|
||||
|
||||
require.NoError(t, json.Unmarshal([]byte(stdout), &snapshots))
|
||||
assert.Empty(t, snapshots,
|
||||
"a destination store with no snapshots lists none")
|
||||
}
|
||||
|
||||
// captureProcessStdout redirects the process's own stdout to a pipe for
|
||||
// the duration of fn and returns what was written to it. The redirection
|
||||
// has to be at the file-descriptor level rather than through an injected
|
||||
// writer, because the banner and the JSON encoder reach os.Stdout
|
||||
// independently and the point of the test is that both land in the same
|
||||
// place.
|
||||
//
|
||||
// Not parallel-safe: os.Stdout is process-global.
|
||||
func captureProcessStdout(t *testing.T, fn func()) string {
|
||||
t.Helper()
|
||||
|
||||
reader, writer, err := os.Pipe()
|
||||
require.NoError(t, err)
|
||||
|
||||
previous := os.Stdout
|
||||
os.Stdout = writer
|
||||
|
||||
captured := make(chan string, 1)
|
||||
|
||||
go func() {
|
||||
var buf bytes.Buffer
|
||||
|
||||
_, _ = io.Copy(&buf, reader)
|
||||
captured <- buf.String()
|
||||
}()
|
||||
|
||||
fn()
|
||||
|
||||
os.Stdout = previous
|
||||
|
||||
require.NoError(t, writer.Close())
|
||||
|
||||
out := <-captured
|
||||
|
||||
require.NoError(t, reader.Close())
|
||||
|
||||
return out
|
||||
}
|
||||
|
||||
// requireExactlyOneJSONDocument fails unless stdout decodes as a single
|
||||
// JSON value with nothing before or after it — the property that makes
|
||||
// `| jq` work.
|
||||
func requireExactlyOneJSONDocument(t *testing.T, stdout string) {
|
||||
t.Helper()
|
||||
|
||||
decoder := json.NewDecoder(strings.NewReader(stdout))
|
||||
|
||||
var document any
|
||||
|
||||
err := decoder.Decode(&document)
|
||||
require.NoError(t, err,
|
||||
"stdout must parse as JSON, got:\n%s", stdout)
|
||||
|
||||
_, err = decoder.Token()
|
||||
require.ErrorIs(t, err, io.EOF,
|
||||
"stdout must hold exactly one JSON document, got:\n%s", stdout)
|
||||
}
|
||||
165
internal/cli/entry_prune_json_test.go
Normal file
165
internal/cli/entry_prune_json_test.go
Normal file
@@ -0,0 +1,165 @@
|
||||
package cli //nolint:testpackage // shares hermeticConfig and the capture helpers
|
||||
|
||||
import (
|
||||
"context"
|
||||
"database/sql"
|
||||
"encoding/json"
|
||||
"fmt"
|
||||
"os"
|
||||
"path/filepath"
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/adrg/xdg"
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"sneak.berlin/go/vaultik/internal/database"
|
||||
"sneak.berlin/go/vaultik/internal/types"
|
||||
)
|
||||
|
||||
// pruneJSONDocument is the shape `prune --json` writes: the
|
||||
// PruneBlobsResult document, and nothing else.
|
||||
//
|
||||
//nolint:tagliatelle // snake_case is the established JSON output format
|
||||
type pruneJSONDocument struct {
|
||||
BlobsFound int `json:"blobs_found"`
|
||||
BlobsDeleted int `json:"blobs_deleted"`
|
||||
BytesFreed int64 `json:"bytes_freed"`
|
||||
}
|
||||
|
||||
// stalePruneSnapshotID is seeded into the local index with no manifest
|
||||
// on the destination store, which is exactly what makes it stale.
|
||||
const stalePruneSnapshotID = "test-host_test_2026-04-01T09:00:00Z"
|
||||
|
||||
// TestEntryPruneJSONStdoutIsExactlyOneDocument is the end-to-end
|
||||
// regression guard for issue #108: `vaultik prune --json | jq .` must
|
||||
// work with no other flags.
|
||||
//
|
||||
// It runs Entry over the process's real stdout descriptor, through
|
||||
// cobra and the fx graph, against a hermetic file:// destination store
|
||||
// — the same construction TestEntryJSONStdoutIsExactlyOneDocument uses
|
||||
// for `snapshot list`, with the pipe to jq replaced by a decoder.
|
||||
//
|
||||
// Both branches of the local-snapshot reconciliation are exercised
|
||||
// because the three stdout writes that broke this covered all of them:
|
||||
// one line per stale record and a summary when there were any, and a
|
||||
// "No stale local snapshots found." line when there were none. No input
|
||||
// avoided the contamination, so no single branch demonstrates the fix.
|
||||
//
|
||||
// Not parallel: it replaces os.Args, os.Stdout and the xdg globals.
|
||||
//
|
||||
//nolint:paralleltest // replaces os.Args, os.Stdout and the xdg globals
|
||||
func TestEntryPruneJSONStdoutIsExactlyOneDocument(t *testing.T) {
|
||||
for _, testCase := range []struct {
|
||||
name string
|
||||
seedStale bool
|
||||
description string
|
||||
}{
|
||||
{
|
||||
name: "no stale local records",
|
||||
seedStale: false,
|
||||
description: "the empty-index branch used to print a 'No stale' line",
|
||||
},
|
||||
{
|
||||
name: "stale local records present",
|
||||
seedStale: true,
|
||||
description: "the removal branch used to print a line per record " +
|
||||
"plus a summary",
|
||||
},
|
||||
} {
|
||||
t.Run(testCase.name, func(t *testing.T) {
|
||||
configPath := writeHermeticPruneConfig(t, testCase.seedStale)
|
||||
|
||||
previousArgs := os.Args
|
||||
|
||||
t.Cleanup(func() {
|
||||
os.Args = previousArgs
|
||||
rootFlags = RootFlags{}
|
||||
})
|
||||
|
||||
os.Args = []string{
|
||||
programName, flagConfig, configPath, cmdPrune, flagJSON,
|
||||
}
|
||||
|
||||
stdout := captureProcessStdout(t, Entry)
|
||||
|
||||
requireExactlyOneJSONDocument(t, stdout)
|
||||
|
||||
var document pruneJSONDocument
|
||||
|
||||
require.NoError(t, json.Unmarshal([]byte(stdout), &document),
|
||||
testCase.description)
|
||||
|
||||
// A destination store with no blobs has none to prune. The
|
||||
// assertion that matters is the one above; this one keeps the
|
||||
// test honest about which document it decoded.
|
||||
assert.Equal(t, 0, document.BlobsFound)
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// writeHermeticPruneConfig builds a config over a temp directory and, if
|
||||
// seedStale is set, creates the index database up front with one
|
||||
// snapshot record that has no counterpart on the destination store.
|
||||
// Returns the config path.
|
||||
func writeHermeticPruneConfig(t *testing.T, seedStale bool) string {
|
||||
t.Helper()
|
||||
|
||||
dir := t.TempDir()
|
||||
configPath := filepath.Join(dir, "config.yml")
|
||||
indexPath := filepath.Join(dir, "index.sqlite")
|
||||
|
||||
contents := fmt.Sprintf(hermeticConfig,
|
||||
filepath.Join(dir, "source"),
|
||||
filepath.Join(dir, "store"),
|
||||
indexPath)
|
||||
|
||||
require.NoError(t,
|
||||
os.WriteFile(configPath, []byte(contents), configFileMode))
|
||||
|
||||
// The PID lock lives under xdg.DataHome, which xdg resolves at
|
||||
// package init; point it at the temp dir so the test neither
|
||||
// touches nor collides with the real one.
|
||||
t.Setenv("XDG_DATA_HOME", filepath.Join(dir, "data"))
|
||||
xdg.Reload()
|
||||
t.Cleanup(xdg.Reload)
|
||||
|
||||
if seedStale {
|
||||
seedStaleSnapshotRecord(t, indexPath)
|
||||
}
|
||||
|
||||
return configPath
|
||||
}
|
||||
|
||||
// seedStaleSnapshotRecord creates the index database at path and
|
||||
// inserts one completed snapshot into it. Nothing is written to the
|
||||
// destination store, so `prune` finds the record stale and removes it —
|
||||
// the branch that printed a line per record.
|
||||
func seedStaleSnapshotRecord(t *testing.T, path string) {
|
||||
t.Helper()
|
||||
|
||||
ctx := context.Background()
|
||||
|
||||
db, err := database.New(ctx, path)
|
||||
require.NoError(t, err)
|
||||
|
||||
defer func() { require.NoError(t, db.Close()) }()
|
||||
|
||||
startedAt := time.Date(2026, 4, 1, 9, 0, 0, 0, time.UTC)
|
||||
completedAt := startedAt.Add(time.Minute)
|
||||
|
||||
snap := &database.Snapshot{
|
||||
ID: types.SnapshotID(stalePruneSnapshotID),
|
||||
Hostname: "test-host",
|
||||
VaultikVersion: "test",
|
||||
StartedAt: startedAt,
|
||||
CompletedAt: &completedAt,
|
||||
}
|
||||
|
||||
repos := database.NewRepositories(db)
|
||||
|
||||
err = repos.WithTx(ctx, func(ctx context.Context, tx *sql.Tx) error {
|
||||
return repos.Snapshots.Create(ctx, tx, snap)
|
||||
})
|
||||
require.NoError(t, err)
|
||||
}
|
||||
@@ -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,34 @@ 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. 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"
|
||||
@@ -22,10 +46,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 +77,7 @@ func NewTTYHandler(out io.Writer, opts *slog.HandlerOptions) *TTYHandler {
|
||||
return &TTYHandler{
|
||||
out: out,
|
||||
opts: *opts,
|
||||
mu: &sync.Mutex{},
|
||||
}
|
||||
}
|
||||
|
||||
@@ -81,29 +122,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 +144,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 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
|
||||
|
||||
422
internal/log/tty_handler_test.go
Normal file
422
internal/log/tty_handler_test.go
Normal file
@@ -0,0 +1,422 @@
|
||||
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")
|
||||
}
|
||||
|
||||
// TestTTYHandlerByteFormattingSurvivesGrouping guards the interaction
|
||||
// between the two features. The human-readable rendering of a "bytes"
|
||||
// attribute is selected by comparing the key, and keys reaching that
|
||||
// comparison are group-qualified, so a "bytes" attribute logged under an
|
||||
// open group arrived as "transfer.bytes" and fell back to a bare number.
|
||||
// No caller groups a byte count today, which is exactly why this needs a
|
||||
// test rather than a bug report.
|
||||
func TestTTYHandlerByteFormattingSurvivesGrouping(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
const oneAndAHalfKiB = 1536
|
||||
|
||||
for name, testCase := range map[string]struct {
|
||||
derive func(*slog.Logger) *slog.Logger
|
||||
key string
|
||||
}{
|
||||
"ungrouped": {
|
||||
derive: func(l *slog.Logger) *slog.Logger { return l },
|
||||
key: "bytes",
|
||||
},
|
||||
"grouped": {
|
||||
derive: func(l *slog.Logger) *slog.Logger {
|
||||
return l.WithGroup("transfer")
|
||||
},
|
||||
key: "transfer.bytes",
|
||||
},
|
||||
} {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
var buf bytes.Buffer
|
||||
|
||||
logger := slog.New(log.NewTTYHandler(&buf, debugHandlerOptions()))
|
||||
testCase.derive(logger).Info("uploaded", "bytes", oneAndAHalfKiB)
|
||||
|
||||
line := ansiEscape.ReplaceAllString(buf.String(), "")
|
||||
|
||||
assert.Contains(t, line, testCase.key+"=1.5 KB",
|
||||
"a byte count must be human-readable however it is qualified")
|
||||
assert.NotContains(t, line, strconv.Itoa(oneAndAHalfKiB),
|
||||
"the raw number must not survive the formatting")
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// 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"))
|
||||
}
|
||||
@@ -79,7 +79,7 @@ func (v *Vaultik) Prune(opts *PruneOptions) error {
|
||||
// store is treated as gone. This used to be the separate 'snapshot
|
||||
// cleanup' command and is now folded in so a single 'vaultik prune'
|
||||
// gets the local index fully back in sync with the destination.
|
||||
err = v.CleanupLocalSnapshots()
|
||||
err = v.CleanupLocalSnapshots(opts)
|
||||
if err != nil {
|
||||
return fmt.Errorf("reconciling local snapshots with remote: %w", err)
|
||||
}
|
||||
|
||||
134
internal/vaultik/prune_cleanup_test.go
Normal file
134
internal/vaultik/prune_cleanup_test.go
Normal file
@@ -0,0 +1,134 @@
|
||||
package vaultik_test
|
||||
|
||||
import (
|
||||
"testing"
|
||||
"time"
|
||||
|
||||
"github.com/stretchr/testify/assert"
|
||||
"github.com/stretchr/testify/require"
|
||||
"sneak.berlin/go/vaultik/internal/log"
|
||||
"sneak.berlin/go/vaultik/internal/vaultik"
|
||||
)
|
||||
|
||||
// cleanupStaleID is a local snapshot record with no remote manifest —
|
||||
// the record CleanupLocalSnapshots exists to remove.
|
||||
const cleanupStaleID = "testhost_home_2026-04-01T09:00:00Z"
|
||||
|
||||
// remainingSnapshotLimit bounds the post-cleanup listing. ListRecent
|
||||
// takes a SQL LIMIT, so it must be positive; the fixtures never exceed
|
||||
// a handful of rows.
|
||||
const remainingSnapshotLimit = 100
|
||||
|
||||
// cleanupStart is the fixture snapshot's start time. Its exact value is
|
||||
// irrelevant; only presence in the index matters here.
|
||||
//
|
||||
//nolint:gochecknoglobals // read-only fixture shared by the tests below
|
||||
var cleanupStart = time.Date(2026, 4, 1, 9, 0, 0, 0, time.UTC)
|
||||
|
||||
// TestCleanupLocalSnapshots_JSONWritesNothingToStdout is the regression
|
||||
// guard for issue #108: `vaultik prune --json | jq` failed because this
|
||||
// function wrote prose to stdout on every branch, ahead of the
|
||||
// PruneBlobsResult document, with no --json awareness at all.
|
||||
//
|
||||
// Both branches are covered because the three writes between them left
|
||||
// no input that avoided the contamination: with stale records there was
|
||||
// a line per record plus a summary, and with none there was still the
|
||||
// "No stale local snapshots found." line.
|
||||
func TestCleanupLocalSnapshots_JSONWritesNothingToStdout(t *testing.T) {
|
||||
log.Initialize(log.Config{})
|
||||
t.Parallel()
|
||||
|
||||
for name, seed := range map[string]func(*listEnv){
|
||||
"no stale records": func(env *listEnv) {
|
||||
// A snapshot present both locally and remotely: nothing to
|
||||
// remove, which used to print the "No stale" line.
|
||||
env.addLocal(t, listLocalID, cleanupStart)
|
||||
env.addRemote(t, listLocalID, cleanupStart)
|
||||
},
|
||||
"stale records present": func(env *listEnv) {
|
||||
env.addLocal(t, cleanupStaleID, cleanupStart)
|
||||
},
|
||||
"nothing at all": func(_ *listEnv) {},
|
||||
} {
|
||||
t.Run(name, func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
env := newListEnv(t)
|
||||
seed(env)
|
||||
|
||||
err := env.v.CleanupLocalSnapshots(&vaultik.PruneOptions{JSON: true})
|
||||
require.NoError(t, err)
|
||||
|
||||
assert.Empty(t, env.stdout.String(),
|
||||
"stdout carries the --json document and nothing else")
|
||||
})
|
||||
}
|
||||
}
|
||||
|
||||
// TestCleanupLocalSnapshots_HumanOutputRetained pins the other half of
|
||||
// the contract. Without it the test above would be satisfied by
|
||||
// deleting the three lines outright, and a `vaultik prune` with no
|
||||
// flags must still say that it removed records from the local index —
|
||||
// that is the deletion of local state, not decoration.
|
||||
func TestCleanupLocalSnapshots_HumanOutputRetained(t *testing.T) {
|
||||
log.Initialize(log.Config{})
|
||||
t.Parallel()
|
||||
|
||||
t.Run("stale records present", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
env := newListEnv(t)
|
||||
env.addLocal(t, cleanupStaleID, cleanupStart)
|
||||
|
||||
err := env.v.CleanupLocalSnapshots(&vaultik.PruneOptions{})
|
||||
require.NoError(t, err)
|
||||
|
||||
out := env.stdout.String()
|
||||
|
||||
assert.Contains(t, out, "Removing stale local record: "+cleanupStaleID)
|
||||
assert.Contains(t, out, "Removed 1 stale local snapshot record(s).")
|
||||
})
|
||||
|
||||
t.Run("no stale records", func(t *testing.T) {
|
||||
t.Parallel()
|
||||
|
||||
env := newListEnv(t)
|
||||
env.addLocal(t, listLocalID, cleanupStart)
|
||||
env.addRemote(t, listLocalID, cleanupStart)
|
||||
|
||||
err := env.v.CleanupLocalSnapshots(&vaultik.PruneOptions{})
|
||||
require.NoError(t, err)
|
||||
|
||||
assert.Contains(t, env.stdout.String(),
|
||||
"No stale local snapshots found.")
|
||||
})
|
||||
}
|
||||
|
||||
// TestCleanupLocalSnapshots_RemovesOnlyStaleRecords checks that the
|
||||
// --json gate did not change what the function does, only what it
|
||||
// says: the stale record is gone from the index and the one with a
|
||||
// remote manifest is untouched.
|
||||
func TestCleanupLocalSnapshots_RemovesOnlyStaleRecords(t *testing.T) {
|
||||
log.Initialize(log.Config{})
|
||||
t.Parallel()
|
||||
|
||||
env := newListEnv(t)
|
||||
env.addLocal(t, listLocalID, cleanupStart)
|
||||
env.addRemote(t, listLocalID, cleanupStart)
|
||||
env.addLocal(t, cleanupStaleID, cleanupStart)
|
||||
|
||||
err := env.v.CleanupLocalSnapshots(&vaultik.PruneOptions{JSON: true})
|
||||
require.NoError(t, err)
|
||||
|
||||
remaining, err := env.v.Repositories.Snapshots.ListRecent(
|
||||
env.v.Context(), remainingSnapshotLimit)
|
||||
require.NoError(t, err)
|
||||
|
||||
ids := make([]string, 0, len(remaining))
|
||||
for _, snap := range remaining {
|
||||
ids = append(ids, snap.ID.String())
|
||||
}
|
||||
|
||||
assert.Equal(t, []string{listLocalID}, ids,
|
||||
"only the record with no remote manifest may be removed")
|
||||
}
|
||||
@@ -829,7 +829,15 @@ func (v *Vaultik) outputVerifyJSON(result *VerifyResult) error {
|
||||
// behind by incomplete or interrupted backups. Each local snapshot's
|
||||
// human ID is hashed via RemoteSnapshotKey and compared against the
|
||||
// remote listing.
|
||||
func (v *Vaultik) CleanupLocalSnapshots() error {
|
||||
//
|
||||
// It takes the whole *PruneOptions, symmetric with PruneBlobs, because
|
||||
// it is the other half of one command: Prune runs this phase and then
|
||||
// that one. Only JSON is read here. Under --json every write below is
|
||||
// suppressed, because stdout carries the PruneBlobsResult document and
|
||||
// nothing else — prose ahead of it is what made `vaultik prune --json |
|
||||
// jq` fail (issue #108). The narration is duplicated as log records,
|
||||
// which go to stderr and so cannot corrupt the document.
|
||||
func (v *Vaultik) CleanupLocalSnapshots(opts *PruneOptions) error {
|
||||
err := v.EnsureStorageBinding()
|
||||
if err != nil {
|
||||
return err
|
||||
@@ -855,7 +863,11 @@ func (v *Vaultik) CleanupLocalSnapshots() error {
|
||||
for _, snap := range localSnapshots {
|
||||
id := snap.ID.String()
|
||||
if !remoteSet[snapshot.RemoteSnapshotKey(id)] {
|
||||
v.stdoutf("Removing stale local record: %s\n", id)
|
||||
log.Info("Removing stale local snapshot record", "snapshot_id", id)
|
||||
|
||||
if !opts.JSON {
|
||||
v.stdoutf("Removing stale local record: %s\n", id)
|
||||
}
|
||||
|
||||
err = v.deleteSnapshotFromLocalDB(id)
|
||||
if err != nil {
|
||||
@@ -869,6 +881,13 @@ func (v *Vaultik) CleanupLocalSnapshots() error {
|
||||
}
|
||||
}
|
||||
|
||||
log.Info("Reconciled local snapshot records against remote metadata",
|
||||
"removed", removed, "examined", len(localSnapshots))
|
||||
|
||||
if opts.JSON {
|
||||
return nil
|
||||
}
|
||||
|
||||
if removed == 0 {
|
||||
v.printlnStdout("No stale local snapshots found.")
|
||||
} else {
|
||||
|
||||
@@ -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] {
|
||||
|
||||
@@ -108,7 +108,6 @@ type listEnv struct {
|
||||
v *vaultik.Vaultik
|
||||
store *observingStorer
|
||||
stdout *bytes.Buffer
|
||||
stderr *bytes.Buffer
|
||||
}
|
||||
|
||||
func newListEnv(t *testing.T) *listEnv {
|
||||
@@ -122,7 +121,6 @@ func newListEnv(t *testing.T) *listEnv {
|
||||
|
||||
store := newObservingStorer()
|
||||
stdout := &bytes.Buffer{}
|
||||
stderr := &bytes.Buffer{}
|
||||
|
||||
v := &vaultik.Vaultik{
|
||||
Config: &config.Config{
|
||||
@@ -135,13 +133,13 @@ func newListEnv(t *testing.T) *listEnv {
|
||||
Repositories: database.NewRepositories(db),
|
||||
DB: db,
|
||||
Stdout: stdout,
|
||||
Stderr: stderr,
|
||||
Stderr: &bytes.Buffer{},
|
||||
Stdin: &bytes.Buffer{},
|
||||
UI: ui.NewWithColor(stdout, false),
|
||||
}
|
||||
v.SetContext(ctx)
|
||||
|
||||
return &listEnv{v: v, store: store, stdout: stdout, stderr: stderr}
|
||||
return &listEnv{v: v, store: store, stdout: stdout}
|
||||
}
|
||||
|
||||
// addLocal inserts a completed snapshot into the local index.
|
||||
@@ -521,16 +519,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 +540,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 +632,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 +646,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 +669,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 +681,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 +716,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 +738,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 +797,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 +827,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 +853,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,15 @@ 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. No production code writes to Stderr today, so
|
||||
// searching for its writers turns up nothing; it is kept as the
|
||||
// injection point a direct stderr write would otherwise have to
|
||||
// invent, and removing it would make the triple asymmetric for no
|
||||
// gain.
|
||||
Stdout io.Writer
|
||||
Stderr io.Writer
|
||||
Stdin io.Reader
|
||||
|
||||
Reference in New Issue
Block a user