From 7fcb78013c34b221bdb2cbf1a9690ccdb16adb90 Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 21 Sep 2026 23:06:22 +0000 Subject: [PATCH] Quiet only the stdout UI under --json, not the log level (closes #112) --json was folded into Quiet, which pinned the stderr log level to WARN. So `prune --json` gave a machine consumer no record of the local index rows it deleted, even under --verbose: the audit records were gated off stdout and pinned below the level on stderr. --json now quiets only the stdout UI, keeping the JSON document clean (issue #108); the stderr log level follows --verbose/--debug again, since diagnostics have gone to stderr since #82. The same coupling is removed for `snapshot verify`, `snapshot remove`, and `remote info`, which carried it for the same outdated reason. A test asserts `--verbose prune --json` emits the cleanup record on stderr while stdout stays exactly one document, and that --json alone keeps it below the level. model: claude-opus-4-8 --- TODO.md | 11 ++ internal/cli/app.go | 17 ++- internal/cli/entry_prune_json_stderr_test.go | 140 +++++++++++++++++++ internal/cli/prune.go | 3 +- internal/cli/remote.go | 3 +- internal/cli/snapshot.go | 3 +- internal/log/module.go | 16 ++- 7 files changed, 184 insertions(+), 9 deletions(-) create mode 100644 internal/cli/entry_prune_json_stderr_test.go diff --git a/TODO.md b/TODO.md index 28d4c28..0094121 100644 --- a/TODO.md +++ b/TODO.md @@ -25,6 +25,17 @@ release" is exactly the contradiction # Completed Steps +- 2026-09-21: Stopped `--json` from silencing stderr diagnostics + ([issue #112](https://git.eeqj.de/sneak/vaultik/issues/112)). `--json` + used to be folded into `Quiet`, which pinned the log level to `WARN`, + so `prune --json` gave a machine consumer no record of the local index + rows it deleted even under `--verbose`. `--json` now quiets only the + stdout UI (the JSON document must stay clean, per + [issue #108](https://git.eeqj.de/sneak/vaultik/issues/108)); the stderr + log level follows `--verbose`/`--debug` again. The coupling was + removed the same way for `snapshot verify`, `snapshot remove`, and + `remote info`, which carried it for the same outdated reason. + - 2026-09-21: Stopped `prune` from reporting a failed row count as 0 ([issue #96](https://git.eeqj.de/sneak/vaultik/issues/96)). The seven `getTableCount` reads in `PruneDatabase` discarded their error, so a diff --git a/internal/cli/app.go b/internal/cli/app.go index e2d8331..5000ea2 100644 --- a/internal/cli/app.go +++ b/internal/cli/app.go @@ -49,6 +49,11 @@ type AppOptions struct { // silenced — per the documented convention that --quiet suppresses // non-error output only. The startup banner is printed by Entry // before cobra parses arguments, gated by the same arg-level check. +// +// --json quiets the UI here too, because stdout then carries a JSON +// document and human narration would corrupt it. Unlike Quiet it does +// not lower the stderr log level (issue #112), so --verbose/--debug +// still surface diagnostics alongside the document. func setupGlobals( lc fx.Lifecycle, g *globals.Globals, v *vaultik.Vaultik, opts log.Options, ) { @@ -56,7 +61,7 @@ func setupGlobals( OnStart: func(_ context.Context) error { g.StartTime = time.Now().UTC() - if opts.Cron || opts.Quiet { + if opts.Cron || opts.Quiet || opts.JSON { v.UI.SetQuiet(true) } @@ -279,10 +284,11 @@ func RunOperation( // shared by the list/purge/verify/remove/remote-info subcommands: // resolve the config, then run op against the Vaultik instance through // RunOperation, reporting a failure prefixed with failMsg (suppressed -// while suppressErrors is true, e.g. under --json). extraQuiet is OR-ed -// into LogOptions.Quiet (e.g. --json output modes). +// while suppressErrors is true, e.g. under --json). jsonOutput marks a +// command whose stdout is a JSON document: it quiets the UI but, unlike +// Quiet, leaves the stderr log level alone. func runVaultikApp( - cmd *cobra.Command, extraQuiet, suppressErrors bool, + cmd *cobra.Command, jsonOutput, suppressErrors bool, failMsg string, op func(v *vaultik.Vaultik) error, ) error { configPath, err := ResolveConfigPath() @@ -297,7 +303,8 @@ func runVaultikApp( LogOptions: log.Options{ Verbose: rootFlags.Verbose, Debug: rootFlags.Debug, - Quiet: rootFlags.Quiet || extraQuiet, + Quiet: rootFlags.Quiet, + JSON: jsonOutput, }, }, op, func(err error) { if suppressErrors { diff --git a/internal/cli/entry_prune_json_stderr_test.go b/internal/cli/entry_prune_json_stderr_test.go new file mode 100644 index 0000000..dd13db5 --- /dev/null +++ b/internal/cli/entry_prune_json_stderr_test.go @@ -0,0 +1,140 @@ +package cli //nolint:testpackage // shares the prune fixtures and capture helpers + +import ( + "bytes" + "io" + "os" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// staleRecordLogMessage is the local-cleanup audit line CleanupLocalSnapshots +// logs for each stale record. It is exactly the signal issue #112 says a +// machine consumer lost under --json: gated off stdout, and pinned below +// the log level on stderr because --json used to force Quiet. +const staleRecordLogMessage = "Removing stale local snapshot record" + +// TestEntryPruneJSONStderrHonoursVerbosity is the end-to-end regression +// guard for issue #112. Under --json the log level must still follow +// --verbose/--debug rather than being pinned to WARN, so the +// local-cleanup records reach stderr under --verbose while stdout stays +// exactly one JSON document; without --verbose they stay below the +// level, as they do without --json. +// +// Both halves are asserted together on the same run, because the fix has +// to keep the document clean (issue #108) while freeing stderr. +// +// Not parallel: it replaces os.Args, os.Stdout, os.Stderr and the xdg +// globals. +// +//nolint:paralleltest // replaces os.Args, os.Stdout, os.Stderr and the xdg globals +func TestEntryPruneJSONStderrHonoursVerbosity(t *testing.T) { + for _, testCase := range []struct { + name string + verbose bool + wantOnStderr bool + }{ + { + name: "verbose json surfaces the cleanup record on stderr", + verbose: true, + wantOnStderr: true, + }, + { + name: "json alone keeps the cleanup record below the level", + verbose: false, + wantOnStderr: false, + }, + } { + t.Run(testCase.name, func(t *testing.T) { + configPath := writeHermeticPruneConfig(t, true) + + previousArgs := os.Args + + t.Cleanup(func() { + os.Args = previousArgs + rootFlags = RootFlags{} + }) + + args := []string{ + programName, flagConfig, configPath, cmdPrune, flagJSON, + } + if testCase.verbose { + args = append(args, "--verbose") + } + + os.Args = args + + stdout, stderr := captureProcessStdoutAndStderr(t, + func() { _ = Entry() }) + + // The document stays clean in both cases: freeing stderr must + // not regress issue #108. + requireExactlyOneJSONDocument(t, stdout) + + if testCase.wantOnStderr { + assert.Contains(t, stderr, staleRecordLogMessage, + "--verbose --json must emit the cleanup record on stderr") + assert.Contains(t, stderr, stalePruneSnapshotID, + "the record must name the snapshot it removed") + } else { + assert.NotContains(t, stderr, staleRecordLogMessage, + "without --verbose the record stays below the log level") + } + }) + } +} + +// captureProcessStdoutAndStderr redirects both of the process's own +// standard streams to pipes for the duration of fn and returns what was +// written to each. The redirection is at the file-descriptor level +// because the logger binds os.Stderr when it initializes inside fn, and +// the JSON document reaches os.Stdout independently; the point is to see +// where each actually lands. +// +// Not parallel-safe: os.Stdout and os.Stderr are process-global. +func captureProcessStdoutAndStderr(t *testing.T, fn func()) (string, string) { + t.Helper() + + outReader, outWriter, err := os.Pipe() + require.NoError(t, err) + + errReader, errWriter, err := os.Pipe() + require.NoError(t, err) + + previousOut, previousErr := os.Stdout, os.Stderr + os.Stdout, os.Stderr = outWriter, errWriter + + capturedOut := drain(outReader) + capturedErr := drain(errReader) + + fn() + + os.Stdout, os.Stderr = previousOut, previousErr + + require.NoError(t, outWriter.Close()) + require.NoError(t, errWriter.Close()) + + out, errOut := <-capturedOut, <-capturedErr + + require.NoError(t, outReader.Close()) + require.NoError(t, errReader.Close()) + + return out, errOut +} + +// drain copies a reader to a string on a goroutine and delivers the +// result once the writer end is closed. +func drain(reader io.Reader) <-chan string { + captured := make(chan string, 1) + + go func() { + var buf bytes.Buffer + + _, _ = io.Copy(&buf, reader) + captured <- buf.String() + }() + + return captured +} diff --git a/internal/cli/prune.go b/internal/cli/prune.go index f37c94c..81feed8 100644 --- a/internal/cli/prune.go +++ b/internal/cli/prune.go @@ -41,7 +41,8 @@ work (e.g. after a crashed backup or to reclaim storage).`, LogOptions: log.Options{ Verbose: rootFlags.Verbose, Debug: rootFlags.Debug, - Quiet: rootFlags.Quiet || opts.JSON, + Quiet: rootFlags.Quiet, + JSON: opts.JSON, }, }, func(v *vaultik.Vaultik) error { return v.Prune(opts) diff --git a/internal/cli/remote.go b/internal/cli/remote.go index 1c8d315..9cc7d74 100644 --- a/internal/cli/remote.go +++ b/internal/cli/remote.go @@ -85,7 +85,8 @@ func newRemoteInfoCommand() *cobra.Command { LogOptions: log.Options{ Verbose: rootFlags.Verbose, Debug: rootFlags.Debug, - Quiet: rootFlags.Quiet || jsonOutput, + Quiet: rootFlags.Quiet, + JSON: jsonOutput, }, }, func(v *vaultik.Vaultik) error { return v.RemoteInfo(jsonOutput) diff --git a/internal/cli/snapshot.go b/internal/cli/snapshot.go index 57e3e51..8007ad4 100644 --- a/internal/cli/snapshot.go +++ b/internal/cli/snapshot.go @@ -209,7 +209,8 @@ func newSnapshotVerifyCommand() *cobra.Command { LogOptions: log.Options{ Verbose: rootFlags.Verbose, Debug: rootFlags.Debug, - Quiet: rootFlags.Quiet || opts.JSON, + Quiet: rootFlags.Quiet, + JSON: opts.JSON, }, }, func(v *vaultik.Vaultik) error { return v.VerifySnapshotWithOptions(snapshotID, opts) diff --git a/internal/log/module.go b/internal/log/module.go index f428604..7e50f45 100644 --- a/internal/log/module.go +++ b/internal/log/module.go @@ -14,8 +14,18 @@ var Module = fx.Module("log", ) // New creates a new logger configuration from provided options. +// +// JSON is intentionally not carried into Config: a command emitting a +// JSON document on stdout must keep its stderr log level under +// --verbose/--debug, so --json must not lower it (issue #112). JSON +// silences the stdout UI in setupGlobals instead. func New(opts Options) Config { - return Config(opts) + return Config{ + Verbose: opts.Verbose, + Debug: opts.Debug, + Cron: opts.Cron, + Quiet: opts.Quiet, + } } // Options are provided by the CLI. @@ -24,4 +34,8 @@ type Options struct { Debug bool Cron bool Quiet bool + // JSON marks a command whose stdout carries a machine-readable + // document. It silences the human UI on stdout (see setupGlobals), + // but unlike Quiet it leaves the stderr log level alone. + JSON bool }