Compare commits

4 Commits

Author SHA1 Message Date
696ed9ab4d Gate prune's local-cleanup output on --json, and make make build build (closes #108)
All checks were successful
check / check (push) Successful in 2m16s
Closes #110.

CleanupLocalSnapshots wrote three prose lines to stdout with no --json
awareness, covering every branch, so `vaultik prune --json | jq` failed
on any input. -q never helped either: printlnStdout and stdoutf write
straight to v.Stdout and never consult v.UI, which is what SetQuiet
affects. It now takes *PruneOptions, symmetric with its sibling phase
PruneBlobs, and gates all three writes.

Threading opts.JSON was chosen over moving the lines to log.Info,
because internal/log/log.go defaults the level to Warn: log.Info would
not have relocated them to stderr, it would have deleted them from a
plain `vaultik prune`, and "Removing stale local record" narrates the
deletion of local index rows. The stale-record count is deliberately not
added to PruneBlobsResult - every field there is blob-scoped and produced
by the phase that runs after this reconciliation, so adding it would
change a published --json schema as a side effect of a stream fix.

Note for anyone reading the --json contract: under --json the
stale-record removal now produces no signal in either stream. stdout is
correctly gated, stderr is level-pinned to Warn because --json sets
Quiet, and the count is not in the document. That is inherited behaviour
- PruneBlobs' own log.Info calls are equally invisible under --json - not
something this change introduced, and it is tracked separately.

make build exited 0 and produced nothing: .PHONY listed build with no
build: rule, and a phony target with no prerequisites and no recipe is
considered already satisfied, which turns what would be a hard error into
a silent success. In a repo where `make build` is the documented way to
build, a caller checking the exit code concluded the build worked. Now
`build: vaultik`, verified in both directions - a clean build produces
the binary, a deliberately broken one exits non-zero and produces none.

All 19 .PHONY names were audited; build was the only one lacking a rule.
TestPhonyTargetsAllHaveRules keeps that true for names added later, so
the class is closed rather than the instance.
2026-08-09 19:53:46 +02:00
f21e7c9e70 Suppress the startup banner for --json (closes #106)
All checks were successful
check / check (push) Successful in 2m31s
The banner is printed to stdout before cobra parses, and
bannerSuppressedInArgs recognised only --quiet, -q and --cron. So every
--json document was preceded by two banner lines and a blank one, and
`vaultik snapshot list --json | jq` failed. Passing opts.JSON as
extraQuiet did not help: that calls UI.SetQuiet in an fx OnStart hook,
long after Entry has printed.

The raw-argv scan is extended rather than the banner moved after
parsing. root.go documents that the banner must survive cobra rejecting
its arguments and --help, and no single post-parse location covers those
paths. The subcommand-versus-persistent distinction does not decide it:
--cron is already in the suppression list and is itself subcommand-only,
existing on snapshot create alone, so this adds another instance of an
accepted imprecision rather than a new kind. The error directions are
asymmetric - a false positive loses a decorative banner, a false negative
corrupts a document - so the scan errs toward suppression, which is also
why --json=false suppresses, exactly as --quiet=false already does.

Four of the five --json commands now pipe into jq cleanly with no other
flags: snapshot list, snapshot verify, snapshot remove, remote info.
prune does not, because pruneLocalSnapshots writes three prose lines to
stdout with no --json awareness. That reproduces identically before this
change and -q never suppressed it either, since printlnStdout and
stdoutf bypass v.UI entirely. Tracked as #108.

Also fixed: TTYHandler's human-readable byte formatting did not survive
grouping, because the key check compared against the bare attribute name
and a grouped record presents it qualified. AGENTS.md policy 9 keyed the
log format on stdout's TTY-ness, which #82 made false by moving the
logger to stderr; it now names the log stream. Vaultik.Stderr keeps its
field with the comment amended to say outright that nothing writes to
it, and the dead listEnv.stderr is removed.
2026-08-09 19:18:36 +02:00
c16ef476a9 Log to stderr and stop discarding With attributes (closes #82)
All checks were successful
check / check (push) Successful in 4m20s
Closes #97.

internal/log attached both handlers to os.Stdout, so any record that was
not suppressed landed in the middle of a --json document. WARN and ERROR
are never suppressed, so this was not hypothetical: a config file with
permissions looser than 0600 was enough to break
`vaultik snapshot list --json | jq`.

Both handlers now write to os.Stderr, and the TTY-vs-JSON format choice
tests os.Stderr rather than os.Stdout - the format has to follow the
stream the records land on, or a redirected stderr gets colorized
whenever stdout happens to be a terminal.

User-visible: --verbose and --debug output moves to stderr too, so
`vaultik snapshot list -v > out.txt` no longer captures diagnostics.
--quiet and --cron semantics are unchanged.

TTYHandler.WithAttrs and WithGroup discarded their arguments and returned
the receiver, while their doc comments claimed otherwise, so attributes
passed through the exported log.With vanished. The effect was
environment-dependent in the worst direction: handler choice is by
TTY-ness, so attributes disappeared on a terminal - where a developer is
debugging - and appeared correctly in CI. Both now return a new handler
with copied state rather than mutating the receiver, since slog permits a
handler to be shared and derived from concurrently. A test asserts the
TTY and JSON handlers emit the same attribute set, which is the test that
would have caught the original defect.

The local workaround in snapshot_list.go is removed now that the logger
no longer writes to stdout. The collect-then-emit machinery is kept, but
for a different reason than it was added: emitting from the fetch workers
would order warnings by network timing, whereas key-order emission after
group.Wait() is deterministic run to run.

Not yet complete: --json stdout still carries the startup banner, which
internal/cli/entry.go writes before cobra parses and which
bannerSuppressedInArgs does not recognise --json for. That is the
remaining stdout contamination path and is tracked in #106.
2026-08-09 18:43:55 +02:00
e3f407b440 Make the tagged-release path work on Gitea (closes #65)
All checks were successful
check / check (push) Successful in 3m7s
No tag could be cut at all: .goreleaser.yaml had no gitea_urls block, so
goreleaser defaulted to the GitHub API, and the repo has zero tags.

.goreleaser.yaml now points at git.eeqj.de. Version derives from git via
a new script/version - exact tag with any leading v stripped, else
dev-<12-char sha>, with a -dirty suffix when tracked files are modified -
replacing the hardcoded 1.0.0-rc.1 that every local build was stamping
regardless of git state. A tag-triggered .gitea/workflows/release.yml
runs goreleaser with a scoped token (RELEASE_TOKEN); script/bootstrap
installs a sha256-verified goreleaser, and make release / release-snapshot
become script shims like every other target.

Two fabrications were removed rather than merely replaced. goreleaser's
snapshot.version_template was `{{ incpatch .Version }}-next`, which
invents a release number from the last tag - and with no tags, from
goreleaser's own fabricated v0.0.0. And internal/cli/version.go gated its
development-build notice on Version == "dev" exactly, so the moment
untagged builds carried a sha that notice would have gone silent and an
unreleased binary would have read as a release. Replaced with a tested
IsDevVersion predicate, and closed at both layers: the Makefile now
refuses to build when script/version yields nothing, and an empty version
counts as a development build - reachable today via
`docker build --build-arg VERSION=`.

The release workflow installs Go from a sha-pinned actions/setup-go
(v5.6.0) using go-version-file, so the compiler that produces released
binaries is pinned like every other external reference. Without it the
first tag push would either fail at goreleaser's before-hook or compile
the published artifacts with whatever unpinned Go the runner happened to
carry - the one unpinned thing in a release path that already refuses an
unpinned goreleaser.

Known gap: the Go tarball setup-go fetches is version-pinned but not
checksum-verified against a value in this repo, unlike the goreleaser
install and the Dockerfile digest.
2026-08-09 18:03:18 +02:00
18 changed files with 1854 additions and 188 deletions

View File

@@ -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

View File

@@ -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

View File

@@ -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
View File

@@ -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

View 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
}

View File

@@ -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.

View 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)
}

View 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)
}

View File

@@ -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

View File

@@ -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

View 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
View 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"))
}

View File

@@ -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)
}

View 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")
}

View File

@@ -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 {

View File

@@ -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] {

View File

@@ -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`)
}

View File

@@ -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