Author SHA1 Message Date
sneak 311756d452 Quiet only the stdout UI under --json, not the log level (closes #112)
check / check (pull_request) Failing after 1s
--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
2026-09-21 19:43:56 +00:00
clawbot c355ef4d25 Report a prune count that could not be read as unknown, not 0 (closes #96)
check / check (pull_request) Failing after 1s
check / check (push) Successful in 2m46s
Prune read table row counts before and after to report how many orphaned files, chunks and blobs it removed, and discarded the error from every read. A failed query therefore reported as a count of 0, and the summary showed plausible wrong numbers.

A count that cannot be read is now logged as a warning (on stderr, also under --json) and shown as "unknown"; a difference computed from an unknown count is itself unknown. 0 still means the table was empty. No --json document carries these counts, so none can show a false 0.

model: claude-opus-4-8 (implementation, review); claude-fable-5-1 (merge)
2026-09-21 21:41:57 +02:00
9 changed files with 350 additions and 35 deletions
+21 -1
View File
@@ -25,6 +25,27 @@ release" is exactly the contradiction
# Completed Steps
- 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
query that could not run became a plausible `0` and the before/after
delta computed from it looked like real work. Each read now logs at
warn on failure and renders as `unknown`, never `0`, so an empty table
is distinguishable from one that could not be queried. The counts have
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
@@ -33,7 +54,6 @@ release" is exactly the contradiction
helper (reused by `HeadObject`) and a test that a missing key maps to
`ErrNotFound`
([issue #129](https://git.eeqj.de/sneak/vaultik/issues/129)).
- 2026-09-21: Fixed `verify --deep` reporting healthy snapshots as
corrupt. Its final blob-integrity check hashed the encrypted
downloaded bytes with a single SHA256 and compared that to the blob
+11 -4
View File
@@ -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{
@@ -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
}
+2 -1
View File
@@ -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{
+2 -1
View File
@@ -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{
+2 -1
View File
@@ -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{
+15 -1
View File
@@ -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
}
+79
View File
@@ -0,0 +1,79 @@
package vaultik //nolint:testpackage // exercises unexported count helpers
import (
"context"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"sneak.berlin/go/vaultik/internal/database"
"sneak.berlin/go/vaultik/internal/log"
)
// TestTableCountForReportSurfacesReadFailure is the regression guard for
// the discarded-error bug: getTableCount for a table its query cannot
// resolve must not silently become 0. A count that could not be read is
// reported as unknown, which a reader can tell apart from an empty table.
//
//nolint:paralleltest // installs the global logger via log.Initialize
func TestTableCountForReportSurfacesReadFailure(t *testing.T) {
log.Initialize(log.Config{})
ctx := context.Background()
db, err := database.New(ctx, ":memory:")
require.NoError(t, err)
t.Cleanup(func() { _ = db.Close() })
v := &Vaultik{DB: db}
v.SetContext(ctx)
// A table present in the schema reads as a real count.
blobs := v.tableCountForReport("blobs")
require.NotNil(t, blobs, "an existing table must read as a real count")
assert.Equal(t, int64(0), *blobs)
// A syntactically valid name the sanitizer accepts but whose table
// the query cannot resolve is the exact shape #96 describes: a
// would-be loud failure that used to be discarded into a 0.
_, err = v.getTableCount("snapshots_missing")
require.Error(t, err, "a query against a nonexistent table must fail")
missing := v.tableCountForReport("snapshots_missing")
assert.Nil(t, missing, "a failed read is unknown, not a count")
// The rendered count for a failed read must say unknown, never 0.
assert.Equal(t, countUnknown, countText(missing))
assert.NotEqual(t, "0", countText(missing))
}
// TestCountTextDistinguishesEmptyFromUnknown pins the distinction the
// output has to preserve: 0 means the table was empty, "unknown" means
// the count could not be read.
func TestCountTextDistinguishesEmptyFromUnknown(t *testing.T) {
t.Parallel()
zero := int64(0)
seven := int64(7)
assert.Equal(t, "0", countText(&zero))
assert.Equal(t, "7", countText(&seven))
assert.Equal(t, countUnknown, countText(nil))
}
// TestCountDiffUnknownWhenEitherSideUnknown checks that a delta computed
// from an unreadable count is itself unknown rather than a plausible
// number.
func TestCountDiffUnknownWhenEitherSideUnknown(t *testing.T) {
t.Parallel()
before := int64(10)
after := int64(3)
require.NotNil(t, countDiff(&before, &after))
assert.Equal(t, int64(7), *countDiff(&before, &after))
assert.Nil(t, countDiff(nil, &after), "unknown before yields unknown delta")
assert.Nil(t, countDiff(&before, nil), "unknown after yields unknown delta")
assert.Nil(t, countDiff(nil, nil))
}
+79 -26
View File
@@ -8,6 +8,7 @@ import (
"path/filepath"
"regexp"
"sort"
"strconv"
"strings"
"time"
@@ -1540,12 +1541,17 @@ func (v *Vaultik) outputRemoveJSON(result *RemoveResult) error {
return encoder.Encode(result)
}
// PruneResult contains statistics about the prune operation
// PruneResult contains statistics about the prune operation.
// SnapshotsDeleted counts snapshots actually deleted. FilesDeleted,
// ChunksDeleted, and BlobsDeleted are derived from before/after row
// counts of the local index; each is nil when a count could not be read,
// so an unreadable count is reported as unknown rather than silently
// as 0.
type PruneResult struct {
SnapshotsDeleted int64
FilesDeleted int64
ChunksDeleted int64
BlobsDeleted int64
FilesDeleted *int64
ChunksDeleted *int64
BlobsDeleted *int64
}
// PruneDatabase removes incomplete snapshots and orphaned files, chunks,
@@ -1560,7 +1566,7 @@ func (v *Vaultik) PruneDatabase() (*PruneResult, error) {
result := &PruneResult{}
// Snapshot counts before deletion of incompletes.
snapshotCountBefore, _ := v.getTableCount("snapshots")
snapshotCountBefore := v.tableCountForReport("snapshots")
// First, delete any incomplete snapshots
incompleteSnapshots, err := v.Repositories.Snapshots.GetIncompleteSnapshots(v.ctx)
@@ -1575,9 +1581,9 @@ func (v *Vaultik) PruneDatabase() (*PruneResult, error) {
}
// Get counts before cleanup for reporting
fileCountBefore, _ := v.getTableCount("files")
chunkCountBefore, _ := v.getTableCount("chunks")
blobCountBefore, _ := v.getTableCount("blobs")
fileCountBefore := v.tableCountForReport("files")
chunkCountBefore := v.tableCountForReport("chunks")
blobCountBefore := v.tableCountForReport("blobs")
// Run the cleanup
err = v.SnapshotManager.CleanupOrphanedData(v.ctx)
@@ -1586,36 +1592,83 @@ func (v *Vaultik) PruneDatabase() (*PruneResult, error) {
}
// Get counts after cleanup
fileCountAfter, _ := v.getTableCount("files")
chunkCountAfter, _ := v.getTableCount("chunks")
blobCountAfter, _ := v.getTableCount("blobs")
fileCountAfter := v.tableCountForReport("files")
chunkCountAfter := v.tableCountForReport("chunks")
blobCountAfter := v.tableCountForReport("blobs")
result.FilesDeleted = fileCountBefore - fileCountAfter
result.ChunksDeleted = chunkCountBefore - chunkCountAfter
result.BlobsDeleted = blobCountBefore - blobCountAfter
result.FilesDeleted = countDiff(fileCountBefore, fileCountAfter)
result.ChunksDeleted = countDiff(chunkCountBefore, chunkCountAfter)
result.BlobsDeleted = countDiff(blobCountBefore, blobCountAfter)
log.Info("Local database prune complete",
"incomplete_snapshots", result.SnapshotsDeleted,
"orphaned_files", result.FilesDeleted,
"orphaned_chunks", result.ChunksDeleted,
"orphaned_blobs", result.BlobsDeleted,
"orphaned_files", countText(result.FilesDeleted),
"orphaned_chunks", countText(result.ChunksDeleted),
"orphaned_blobs", countText(result.BlobsDeleted),
)
snapshotCountAfter := snapshotCountBefore - result.SnapshotsDeleted
// Snapshots remaining after removing the incomplete ones; unknown if
// the pre-prune snapshot count could not be read.
snapshotsRemain := countDiff(snapshotCountBefore, &result.SnapshotsDeleted)
v.UI.Completef("Pruned local index database.")
v.UI.Detailf("Incomplete snapshots: %d removed (%d remain).",
result.SnapshotsDeleted, snapshotCountAfter)
v.UI.Detailf("Orphaned files: %d removed (%d remain).",
result.FilesDeleted, fileCountAfter)
v.UI.Detailf("Orphaned chunks: %d removed (%d remain).",
result.ChunksDeleted, chunkCountAfter)
v.UI.Detailf("Orphaned blobs: %d removed (%d remain).",
result.BlobsDeleted, blobCountAfter)
v.UI.Detailf("Incomplete snapshots: %s removed (%s remain).",
countText(&result.SnapshotsDeleted), countText(snapshotsRemain))
v.UI.Detailf("Orphaned files: %s removed (%s remain).",
countText(result.FilesDeleted), countText(fileCountAfter))
v.UI.Detailf("Orphaned chunks: %s removed (%s remain).",
countText(result.ChunksDeleted), countText(chunkCountAfter))
v.UI.Detailf("Orphaned blobs: %s removed (%s remain).",
countText(result.BlobsDeleted), countText(blobCountAfter))
return result, nil
}
// countUnknown is what a count reads as when its query could not be run,
// distinct from "0", which means the table really was empty.
const countUnknown = "unknown"
// tableCountForReport returns the row count of a table for the prune
// summary, or nil if the count could not be read. A read failure is
// logged at warn — visible even under --json, which routes warnings to
// stderr — and then rendered as unknown rather than silently becoming 0,
// so a broken query is a visible failure instead of a plausible wrong
// number.
func (v *Vaultik) tableCountForReport(tableName string) *int64 {
count, err := v.getTableCount(tableName)
if err != nil {
log.Warn("could not read table row count for prune summary",
"table", tableName, "error", err)
return nil
}
return &count
}
// countDiff returns before-after, or nil if either count is unknown so
// that an unreadable count does not collapse into a plausible delta.
func countDiff(before, after *int64) *int64 {
if before == nil || after == nil {
return nil
}
diff := *before - *after
return &diff
}
// countText renders a count that may be unknown: nil (the read failed)
// becomes "unknown", never "0", so a reader can tell an empty table from
// one that could not be queried.
func countText(count *int64) string {
if count == nil {
return countUnknown
}
return strconv.FormatInt(*count, 10)
}
// validTableNameRe matches table names containing only lowercase
// alphanumeric characters and underscores.
var validTableNameRe = regexp.MustCompile(`^[a-z0-9_]+$`)