diff --git a/AGENTS.md b/AGENTS.md index 102f70c..2dc6fc7 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -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 diff --git a/README.md b/README.md index bf3202f..0f49813 100644 --- a/README.md +++ b/README.md @@ -139,6 +139,11 @@ 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. +The startup banner is the other thing that writes to stdout, and +`--json` suppresses it, as `--quiet` and `--cron` do. So +`vaultik snapshot list --json | jq .` works on its own, with no +additional flag to quiet the banner first. + ### environment variables * `VAULTIK_AGE_SECRET_KEY`: Age private key for decryption (required for `snapshot restore` and `snapshot verify --deep`) diff --git a/TODO.md b/TODO.md index 8d05580..be8d2e4 100644 --- a/TODO.md +++ b/TODO.md @@ -25,6 +25,44 @@ release" is exactly the contradiction # Completed Steps +- 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), diff --git a/internal/cli/entry.go b/internal/cli/entry.go index 2dfee66..5f405cc 100644 --- a/internal/cli/entry.go +++ b/internal/cli/entry.go @@ -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. diff --git a/internal/cli/entry_banner_test.go b/internal/cli/entry_banner_test.go new file mode 100644 index 0000000..fd1ab6e --- /dev/null +++ b/internal/cli/entry_banner_test.go @@ -0,0 +1,295 @@ +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" + + // 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": { + "--config", "/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{ + "vaultik", "--config", 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) +} diff --git a/internal/log/tty_handler.go b/internal/log/tty_handler.go index 7691e98..00239ed 100644 --- a/internal/log/tty_handler.go +++ b/internal/log/tty_handler.go @@ -16,9 +16,23 @@ import ( const groupSeparator = "." // bytesAttrKey is the attribute key whose int64 value is rendered as a -// human-readable byte count rather than a bare number. +// 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" @@ -236,7 +250,7 @@ func (h *TTYHandler) writeAttr(a slog.Attr) { value = formatDuration(d) } case slog.KindInt64: - if a.Key == bytesAttrKey { + if isBytesAttr(a.Key) { value = formatBytes(a.Value.Int64()) } case slog.KindAny, slog.KindBool, slog.KindFloat64, slog.KindString, diff --git a/internal/log/tty_handler_test.go b/internal/log/tty_handler_test.go index a54fa60..694657f 100644 --- a/internal/log/tty_handler_test.go +++ b/internal/log/tty_handler_test.go @@ -190,6 +190,51 @@ func TestTTYHandlerWithGroupQualifiesKeys(t *testing.T) { 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 diff --git a/internal/vaultik/snapshot_list_test.go b/internal/vaultik/snapshot_list_test.go index 2bb0e4a..030f545 100644 --- a/internal/vaultik/snapshot_list_test.go +++ b/internal/vaultik/snapshot_list_test.go @@ -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. diff --git a/internal/vaultik/vaultik.go b/internal/vaultik/vaultik.go index a6a2630..21783eb 100644 --- a/internal/vaultik/vaultik.go +++ b/internal/vaultik/vaultik.go @@ -47,7 +47,11 @@ type Vaultik struct { // 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. + // 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