From 311756d452cbe9365c0f16475ec9b670278c3a23 Mon Sep 17 00:00:00 2001 From: sneak Date: Mon, 21 Sep 2026 19:25:11 +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 | 15 +- internal/cli/entry_prune_json_stderr_test.go | 139 +++++++++++++++++++ internal/cli/prune.go | 3 +- internal/cli/remote.go | 3 +- internal/cli/snapshot.go | 3 +- internal/log/module.go | 16 ++- 7 files changed, 182 insertions(+), 8 deletions(-) create mode 100644 internal/cli/entry_prune_json_stderr_test.go diff --git a/TODO.md b/TODO.md index 28d4c28..ae2f933 100644 --- a/TODO.md +++ b/TODO.md @@ -35,6 +35,17 @@ release" is exactly the contradiction no `--json` representation — under `--json` the summary is suppressed entirely — so nothing there can show a false `0`. +- 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: Made the s3 storage backend report a missing object as `storage.ErrNotFound`, like the `file` and `rclone` backends and as the `Storer` interface documents. `S3Storer.Get` and `Stat` returned the raw diff --git a/internal/cli/app.go b/internal/cli/app.go index 492f7e4..0e16857 100644 --- a/internal/cli/app.go +++ b/internal/cli/app.go @@ -48,6 +48,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, ) { @@ -55,7 +60,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) } @@ -202,9 +207,10 @@ func RunApp(ctx context.Context, app *fx.App) error { // instance in a goroutine, report a failure prefixed with failMsg // (suppressed while suppressErrors is true, e.g. under --json), then // trigger shutdown. The operation is cancelled when the app stops. -// extraQuiet is OR-ed into LogOptions.Quiet (e.g. --json output modes). +// 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() @@ -219,7 +225,8 @@ func runVaultikApp( LogOptions: log.Options{ Verbose: rootFlags.Verbose, Debug: rootFlags.Debug, - Quiet: rootFlags.Quiet || extraQuiet, + Quiet: rootFlags.Quiet, + JSON: jsonOutput, }, Modules: []fx.Option{}, Invokes: []fx.Option{ 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..5402c83 --- /dev/null +++ b/internal/cli/entry_prune_json_stderr_test.go @@ -0,0 +1,139 @@ +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, 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 950e7fd..3b379e3 100644 --- a/internal/cli/prune.go +++ b/internal/cli/prune.go @@ -46,7 +46,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, }, Modules: []fx.Option{}, Invokes: []fx.Option{ diff --git a/internal/cli/remote.go b/internal/cli/remote.go index 61987a3..92f03d1 100644 --- a/internal/cli/remote.go +++ b/internal/cli/remote.go @@ -88,7 +88,8 @@ func newRemoteInfoCommand() *cobra.Command { LogOptions: log.Options{ Verbose: rootFlags.Verbose, Debug: rootFlags.Debug, - Quiet: rootFlags.Quiet || jsonOutput, + Quiet: rootFlags.Quiet, + JSON: jsonOutput, }, Modules: []fx.Option{}, Invokes: []fx.Option{ diff --git a/internal/cli/snapshot.go b/internal/cli/snapshot.go index a702386..898a274 100644 --- a/internal/cli/snapshot.go +++ b/internal/cli/snapshot.go @@ -239,7 +239,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, }, Modules: []fx.Option{}, Invokes: []fx.Option{ 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 }