Every --json subcommand writes its document to the same stream. Any
log record that is not suppressed therefore lands in the middle of the
document and makes it unparseable. WARN and ERROR are never
suppressed, so this is not hypothetical.
Reproduction
Any config file with permissions looser than 0600 triggers a WARN at internal/config/config.go:271 during startup:
vaultik snapshot list --json | jq . fails on that first line. The same
applies to snapshot verify --json, snapshot remove --json, prune --json, and remote info --json.
Expected
Diagnostics go to stderr; stdout carries only the requested output. That
is the usual contract and the one a caller piping to jq relies on.
Notes
internal/cli already passes a Quiet flag through for some --json paths, which suppresses INFO but not WARN/ERROR, so
quiet mode is not a fix.
snapshot list --json works around this locally as of #64: its
remote-listing warning is written to v.Stderr directly rather than
through log or v.UI. That workaround should be removed once the
logger itself writes to stderr.
Fixing this centrally is a one-line change to the handler
destination, but it will move all --verbose/--debug output to
stderr too, which is a user-visible change worth confirming
deliberately.
Found while implementing #64. Filing rather than fixing drive-by, since
it is outside that issue's scope and affects every `--json` command.
## Problem
`internal/log/log.go:73-78` attaches both handlers to `os.Stdout`:
```go
if term.IsTerminal(int(os.Stdout.Fd())) {
logger = slog.New(NewTTYHandler(os.Stdout, opts))
} else {
logger = slog.New(slog.NewJSONHandler(os.Stdout, opts))
}
```
Every `--json` subcommand writes its document to the same stream. Any
log record that is not suppressed therefore lands in the middle of the
document and makes it unparseable. `WARN` and `ERROR` are never
suppressed, so this is not hypothetical.
## Reproduction
Any config file with permissions looser than 0600 triggers a `WARN` at
`internal/config/config.go:271` during startup:
```
$ vaultik --config /tmp/demo/config.yml snapshot list --json
{"time":"...","level":"WARN","msg":"Config file has insecure permissions (contains S3 credentials)",...}
[
{
"id": "",
...
}
]
```
`vaultik snapshot list --json | jq .` fails on that first line. The same
applies to `snapshot verify --json`, `snapshot remove --json`, `prune
--json`, and `remote info --json`.
## Expected
Diagnostics go to stderr; stdout carries only the requested output. That
is the usual contract and the one a caller piping to `jq` relies on.
## Notes
- `internal/cli` already passes a `Quiet` flag through for some
`--json` paths, which suppresses `INFO` but not `WARN`/`ERROR`, so
quiet mode is not a fix.
- `snapshot list --json` works around this locally as of #64: its
remote-listing warning is written to `v.Stderr` directly rather than
through `log` or `v.UI`. That workaround should be removed once the
logger itself writes to stderr.
- Fixing this centrally is a one-line change to the handler
destination, but it will move all `--verbose`/`--debug` output to
stderr too, which is a user-visible change worth confirming
deliberately.
Implementing this together with issue #97 on one branch,
since both are defects in internal/log and #97 touches the same
handler construction site.
1. Move the logger to stderr
internal/log/log.goInitialize builds both handlers over os.Stderr instead of os.Stdout, and the TTY/JSON handler choice
switches to term.IsTerminal(int(os.Stderr.Fd())) — the format
decision has to follow the stream the records actually land on, not an
unrelated one. AGENTS.md policy 9 ("if stdout is not a terminal,
output jsonl") is read as "if the log stream is not a terminal", which
is what it meant when logs went to stdout.
User-visible consequence, called out deliberately: --verbose and --debug output moves to stderr as well. vaultik snapshot list -v > out.txt no longer captures the diagnostics. That is the intended
contract and will be documented in README.md and in the PR body.
--quiet/--cron semantics are untouched: level selection in Initialize and ui.Writer quiet handling are not modified, so UI.SetQuiet(true) still suppresses Begin/Complete/Info/Notice/
Detail/Progress/Banner and still does not suppress Warning/Error (see issue #84).
2. Remove the snapshot_list.go workaround
The workaround goes away rather than staying. Concretely:
warnWhileListing is deleted. It hand-rolled structured-log
formatting (fmt.Fprintf(&line, " %v=%v", ...) plus a kvPairSize
constant) purely to reach a non-stdout writer; with the logger on
stderr, log.Warn is the right call in both output modes.
The jsonOutput parameter threaded through collectRemoteSnapshots and describeRemoteOnlySnapshots only ever
selected between those two writers, so it goes too.
reportJSONListingLimits moves from fmt.Fprintf(v.Stderr, ...) to log.Warn with structured fields, for the same reason.
warnRemoteListingFailed keeps its jsonOutput branch, but for a
different and still-true reason: table mode wants the prose v.UI.Warningf line, and v.UI writes to stdout, so JSON mode goes
through log.Warn. The comment is rewritten to say that instead of
citing this issue.
The listingWarning collect-then-emit machinery stays, with a
rewritten rationale. Its original justification (the chosen writer is
not concurrency-safe) is obsolete — slog handlers are safe for
concurrent use. What remains is that emitting from the worker
goroutines makes warning order depend on manifest-fetch completion
order; collecting and emitting in key order after group.Wait()
keeps diagnostics deterministic run to run. No comment is left
referencing this issue as pending work.
Existing tests that assert these warnings land on the injected v.Stderr buffer are updated to capture the process's real stderr,
since that is where they now go. The assertions themselves (same
substrings, same guarantees) are preserved. captureProcessStdout's
doc comment, which currently cites this issue as the reason no
injectable sink exists, gets a matching captureProcessStderr and an
updated explanation.
3. Verification
Existing regression guard TestListSnapshots_JSONStdoutIsOnlyTheDocument continues to point
every stdout writer at one pipe and assert the capture parses as a
single JSON array.
End-to-end with the genuine trigger from the report: a config file at
mode 0644 (so internal/config/config.go fires its insecure-
permissions WARN) plus a file:// destination, then vaultik snapshot list --json | jq . with stdout and stderr captured
separately. stdout must parse; the warning must be on stderr.
make check and script/cibuild.
Out of scope
The --cron help string
(issue #87) and the
suppression semantics themselves
(issue #84) are not
touched.
## Implementation plan
Implementing this together with
[issue #97](https://git.eeqj.de/sneak/vaultik/issues/97) on one branch,
since both are defects in `internal/log` and #97 touches the same
handler construction site.
### 1. Move the logger to stderr
`internal/log/log.go` `Initialize` builds both handlers over
`os.Stderr` instead of `os.Stdout`, and the TTY/JSON handler choice
switches to `term.IsTerminal(int(os.Stderr.Fd()))` — the format
decision has to follow the stream the records actually land on, not an
unrelated one. `AGENTS.md` policy 9 ("if stdout is not a terminal,
output jsonl") is read as "if the log stream is not a terminal", which
is what it meant when logs went to stdout.
User-visible consequence, called out deliberately: `--verbose` and
`--debug` output moves to stderr as well. `vaultik snapshot list -v >
out.txt` no longer captures the diagnostics. That is the intended
contract and will be documented in `README.md` and in the PR body.
`--quiet`/`--cron` semantics are untouched: level selection in
`Initialize` and `ui.Writer` quiet handling are not modified, so
`UI.SetQuiet(true)` still suppresses Begin/Complete/Info/Notice/
Detail/Progress/Banner and still does not suppress Warning/Error (see
[issue #84](https://git.eeqj.de/sneak/vaultik/issues/84)).
### 2. Remove the `snapshot_list.go` workaround
The workaround goes away rather than staying. Concretely:
- `warnWhileListing` is deleted. It hand-rolled structured-log
formatting (`fmt.Fprintf(&line, " %v=%v", ...)` plus a `kvPairSize`
constant) purely to reach a non-stdout writer; with the logger on
stderr, `log.Warn` is the right call in both output modes.
- The `jsonOutput` parameter threaded through
`collectRemoteSnapshots` and `describeRemoteOnlySnapshots` only ever
selected between those two writers, so it goes too.
- `reportJSONListingLimits` moves from `fmt.Fprintf(v.Stderr, ...)` to
`log.Warn` with structured fields, for the same reason.
- `warnRemoteListingFailed` keeps its `jsonOutput` branch, but for a
different and still-true reason: table mode wants the prose
`v.UI.Warningf` line, and `v.UI` writes to stdout, so JSON mode goes
through `log.Warn`. The comment is rewritten to say that instead of
citing this issue.
- The `listingWarning` collect-then-emit machinery **stays**, with a
rewritten rationale. Its original justification (the chosen writer is
not concurrency-safe) is obsolete — `slog` handlers are safe for
concurrent use. What remains is that emitting from the worker
goroutines makes warning order depend on manifest-fetch completion
order; collecting and emitting in key order after `group.Wait()`
keeps diagnostics deterministic run to run. No comment is left
referencing this issue as pending work.
Existing tests that assert these warnings land on the injected
`v.Stderr` buffer are updated to capture the process's real stderr,
since that is where they now go. The assertions themselves (same
substrings, same guarantees) are preserved. `captureProcessStdout`'s
doc comment, which currently cites this issue as the reason no
injectable sink exists, gets a matching `captureProcessStderr` and an
updated explanation.
### 3. Verification
- Existing regression guard
`TestListSnapshots_JSONStdoutIsOnlyTheDocument` continues to point
every stdout writer at one pipe and assert the capture parses as a
single JSON array.
- End-to-end with the genuine trigger from the report: a config file at
mode 0644 (so `internal/config/config.go` fires its insecure-
permissions `WARN`) plus a `file://` destination, then `vaultik
snapshot list --json | jq .` with stdout and stderr captured
separately. stdout must parse; the warning must be on stderr.
- `make check` and `script/cibuild`.
### Out of scope
The `--cron` help string
([issue #87](https://git.eeqj.de/sneak/vaultik/issues/87)) and the
suppression semantics themselves
([issue #84](https://git.eeqj.de/sneak/vaultik/issues/84)) are not
touched.
Implemented in PR #107 (branch fix-log-stdout), together with issue #97.
What changed
Initialize now builds both handlers over os.Stderr, and the
TTY/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.
The internal/vaultik/snapshot_list.go workaround is removed rather
than kept:
warnWhileListing deleted, along with the kvPairSize constant and
the hand-rolled %v=%v formatting it used to reach a non-stdout
writer. Those warnings go through log.Warn in every mode now.
The jsonOutput parameter is gone from collectRemoteSnapshots and describeRemoteOnlySnapshots; it only ever selected between the two
writers.
reportJSONListingLimits moved from fmt.Fprintf(v.Stderr, ...) to log.Warn with structured fields.
warnRemoteListingFailed keeps its jsonOutput branch, but the
comment now gives the reason that is still true: table mode wants the
prose v.UI.Warningf line and v.UI writes to stdout, so --json
mode uses the logger.
The listingWarning collect-then-emit machinery stays, with a
rewritten rationale. Concurrency safety is no longer the reason — slog handlers are safe for concurrent use — but emitting from the
manifest-fetch workers would order warnings by network timing, where
collecting and emitting in key order after group.Wait() makes two
runs over the same damaged store produce the same diagnostics in the
same order.
No comment in the tree still refers to this issue as pending work. The captureProcessStdout test helper's doc, which cited it as the reason
no injectable sink exists, was rewritten too.
User-visible change
--verbose and --debug output moves to stderr as well, so vaultik snapshot list -v > out.txt no longer captures the diagnostics. README.md gains a "stdout and stderr" section documenting the split,
and the flag entries point at it. Called out prominently at the top of
the PR body.
Verification
Reproduced with the exact trigger from the report — a config file at
mode 0644 with a file:// destination — against a binary built from main:
$ vaultik -q --config .../config.yml snapshot list --json | python3 -c 'import json,sys; json.load(sys.stdin)'
json.decoder.JSONDecodeError: Extra data: line 2 column 1 (char 279)
Same config and command on this branch: stdout is [] and nothing else, json.load accepts it, and the WARN is on stderr as a JSON record.
--quiet semantics confirmed unchanged in the same run: it used -q
and the warning still fired, per issue #84. Level
selection and ui.Writer's quiet handling were not touched, and --cron shares the same branch in Initialize.
make check green. script/cibuild exit 0 in 140s with the check
layers executed rather than replayed — make fmt-check 2.4s, make lint 40.4s, make test 58.5s under a fresh CHECK_EPOCH — 14 ok lines and zero (cached) markers.
One thing this does not finish
Filed as issue #106: the
startup banner is written to stdout by internal/cli/entry.go before
cobra parses, and bannerSuppressedInArgs does not recognize --json.
So snapshot list --json still emits two banner lines and a blank line
ahead of the document unless -q is passed. Different writer, different
path, so it is filed rather than fixed here — but stdout is not fully
clean until it lands. The reproductions above use -q for that reason.
Implemented in
[PR #107](https://git.eeqj.de/sneak/vaultik/pulls/107) (branch
`fix-log-stdout`), together with
[issue #97](https://git.eeqj.de/sneak/vaultik/issues/97).
## What changed
`Initialize` now builds both handlers over `os.Stderr`, and the
TTY/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.
The `internal/vaultik/snapshot_list.go` workaround is removed rather
than kept:
- `warnWhileListing` deleted, along with the `kvPairSize` constant and
the hand-rolled ` %v=%v` formatting it used to reach a non-stdout
writer. Those warnings go through `log.Warn` in every mode now.
- The `jsonOutput` parameter is gone from `collectRemoteSnapshots` and
`describeRemoteOnlySnapshots`; it only ever selected between the two
writers.
- `reportJSONListingLimits` moved from `fmt.Fprintf(v.Stderr, ...)` to
`log.Warn` with structured fields.
- `warnRemoteListingFailed` keeps its `jsonOutput` branch, but the
comment now gives the reason that is still true: table mode wants the
prose `v.UI.Warningf` line and `v.UI` writes to stdout, so `--json`
mode uses the logger.
- The `listingWarning` collect-then-emit machinery stays, with a
rewritten rationale. Concurrency safety is no longer the reason —
`slog` handlers are safe for concurrent use — but emitting from the
manifest-fetch workers would order warnings by network timing, where
collecting and emitting in key order after `group.Wait()` makes two
runs over the same damaged store produce the same diagnostics in the
same order.
No comment in the tree still refers to this issue as pending work. The
`captureProcessStdout` test helper's doc, which cited it as the reason
no injectable sink exists, was rewritten too.
## User-visible change
`--verbose` and `--debug` output moves to stderr as well, so
`vaultik snapshot list -v > out.txt` no longer captures the diagnostics.
`README.md` gains a "stdout and stderr" section documenting the split,
and the flag entries point at it. Called out prominently at the top of
the PR body.
## Verification
Reproduced with the exact trigger from the report — a config file at
mode 0644 with a `file://` destination — against a binary built from
`main`:
```
$ vaultik -q --config .../config.yml snapshot list --json | python3 -c 'import json,sys; json.load(sys.stdin)'
json.decoder.JSONDecodeError: Extra data: line 2 column 1 (char 279)
```
Same config and command on this branch: stdout is `[]` and nothing else,
`json.load` accepts it, and the `WARN` is on stderr as a JSON record.
`--quiet` semantics confirmed unchanged in the same run: it used `-q`
and the warning still fired, per
[issue #84](https://git.eeqj.de/sneak/vaultik/issues/84). Level
selection and `ui.Writer`'s quiet handling were not touched, and
`--cron` shares the same branch in `Initialize`.
`make check` green. `script/cibuild` exit 0 in 140s with the check
layers executed rather than replayed — `make fmt-check` 2.4s,
`make lint` 40.4s, `make test` 58.5s under a fresh `CHECK_EPOCH` — 14
`ok` lines and zero `(cached)` markers.
## One thing this does not finish
Filed as [issue #106](https://git.eeqj.de/sneak/vaultik/issues/106): the
startup banner is written to stdout by `internal/cli/entry.go` before
cobra parses, and `bannerSuppressedInArgs` does not recognize `--json`.
So `snapshot list --json` still emits two banner lines and a blank line
ahead of the document unless `-q` is passed. Different writer, different
path, so it is filed rather than fixed here — but stdout is not fully
clean until it lands. The reproductions above use `-q` for that reason.
Blocking a user prevents them from interacting with repositories, such as opening or commenting on pull requests or issues. Learn more about blocking a user.
Found while implementing #64. Filing rather than fixing drive-by, since
it is outside that issue's scope and affects every
--jsoncommand.Problem
internal/log/log.go:73-78attaches both handlers toos.Stdout:Every
--jsonsubcommand writes its document to the same stream. Anylog record that is not suppressed therefore lands in the middle of the
document and makes it unparseable.
WARNandERRORare neversuppressed, so this is not hypothetical.
Reproduction
Any config file with permissions looser than 0600 triggers a
WARNatinternal/config/config.go:271during startup:vaultik snapshot list --json | jq .fails on that first line. The sameapplies to
snapshot verify --json,snapshot remove --json,prune --json, andremote info --json.Expected
Diagnostics go to stderr; stdout carries only the requested output. That
is the usual contract and the one a caller piping to
jqrelies on.Notes
internal/clialready passes aQuietflag through for some--jsonpaths, which suppressesINFObut notWARN/ERROR, soquiet mode is not a fix.
snapshot list --jsonworks around this locally as of #64: itsremote-listing warning is written to
v.Stderrdirectly rather thanthrough
logorv.UI. That workaround should be removed once thelogger itself writes to stderr.
destination, but it will move all
--verbose/--debugoutput tostderr too, which is a user-visible change worth confirming
deliberately.
Implementation plan
Implementing this together with
issue #97 on one branch,
since both are defects in
internal/logand #97 touches the samehandler construction site.
1. Move the logger to stderr
internal/log/log.goInitializebuilds both handlers overos.Stderrinstead ofos.Stdout, and the TTY/JSON handler choiceswitches to
term.IsTerminal(int(os.Stderr.Fd()))— the formatdecision has to follow the stream the records actually land on, not an
unrelated one.
AGENTS.mdpolicy 9 ("if stdout is not a terminal,output jsonl") is read as "if the log stream is not a terminal", which
is what it meant when logs went to stdout.
User-visible consequence, called out deliberately:
--verboseand--debugoutput moves to stderr as well.vaultik snapshot list -v > out.txtno longer captures the diagnostics. That is the intendedcontract and will be documented in
README.mdand in the PR body.--quiet/--cronsemantics are untouched: level selection inInitializeandui.Writerquiet handling are not modified, soUI.SetQuiet(true)still suppresses Begin/Complete/Info/Notice/Detail/Progress/Banner and still does not suppress Warning/Error (see
issue #84).
2. Remove the
snapshot_list.goworkaroundThe workaround goes away rather than staying. Concretely:
warnWhileListingis deleted. It hand-rolled structured-logformatting (
fmt.Fprintf(&line, " %v=%v", ...)plus akvPairSizeconstant) purely to reach a non-stdout writer; with the logger on
stderr,
log.Warnis the right call in both output modes.jsonOutputparameter threaded throughcollectRemoteSnapshotsanddescribeRemoteOnlySnapshotsonly everselected between those two writers, so it goes too.
reportJSONListingLimitsmoves fromfmt.Fprintf(v.Stderr, ...)tolog.Warnwith structured fields, for the same reason.warnRemoteListingFailedkeeps itsjsonOutputbranch, but for adifferent and still-true reason: table mode wants the prose
v.UI.Warningfline, andv.UIwrites to stdout, so JSON mode goesthrough
log.Warn. The comment is rewritten to say that instead ofciting this issue.
listingWarningcollect-then-emit machinery stays, with arewritten rationale. Its original justification (the chosen writer is
not concurrency-safe) is obsolete —
sloghandlers are safe forconcurrent use. What remains is that emitting from the worker
goroutines makes warning order depend on manifest-fetch completion
order; collecting and emitting in key order after
group.Wait()keeps diagnostics deterministic run to run. No comment is left
referencing this issue as pending work.
Existing tests that assert these warnings land on the injected
v.Stderrbuffer are updated to capture the process's real stderr,since that is where they now go. The assertions themselves (same
substrings, same guarantees) are preserved.
captureProcessStdout'sdoc comment, which currently cites this issue as the reason no
injectable sink exists, gets a matching
captureProcessStderrand anupdated explanation.
3. Verification
TestListSnapshots_JSONStdoutIsOnlyTheDocumentcontinues to pointevery stdout writer at one pipe and assert the capture parses as a
single JSON array.
mode 0644 (so
internal/config/config.gofires its insecure-permissions
WARN) plus afile://destination, thenvaultik snapshot list --json | jq .with stdout and stderr capturedseparately. stdout must parse; the warning must be on stderr.
make checkandscript/cibuild.Out of scope
The
--cronhelp string(issue #87) and the
suppression semantics themselves
(issue #84) are not
touched.
Implemented in
PR #107 (branch
fix-log-stdout), together withissue #97.
What changed
Initializenow builds both handlers overos.Stderr, and theTTY/JSON format choice tests
os.Stderrrather thanos.Stdout— theformat has to follow the stream the records land on, or a redirected
stderr gets colorized whenever stdout happens to be a terminal.
The
internal/vaultik/snapshot_list.goworkaround is removed ratherthan kept:
warnWhileListingdeleted, along with thekvPairSizeconstant andthe hand-rolled
%v=%vformatting it used to reach a non-stdoutwriter. Those warnings go through
log.Warnin every mode now.jsonOutputparameter is gone fromcollectRemoteSnapshotsanddescribeRemoteOnlySnapshots; it only ever selected between the twowriters.
reportJSONListingLimitsmoved fromfmt.Fprintf(v.Stderr, ...)tolog.Warnwith structured fields.warnRemoteListingFailedkeeps itsjsonOutputbranch, but thecomment now gives the reason that is still true: table mode wants the
prose
v.UI.Warningfline andv.UIwrites to stdout, so--jsonmode uses the logger.
listingWarningcollect-then-emit machinery stays, with arewritten rationale. Concurrency safety is no longer the reason —
sloghandlers are safe for concurrent use — but emitting from themanifest-fetch workers would order warnings by network timing, where
collecting and emitting in key order after
group.Wait()makes tworuns over the same damaged store produce the same diagnostics in the
same order.
No comment in the tree still refers to this issue as pending work. The
captureProcessStdouttest helper's doc, which cited it as the reasonno injectable sink exists, was rewritten too.
User-visible change
--verboseand--debugoutput moves to stderr as well, sovaultik snapshot list -v > out.txtno longer captures the diagnostics.README.mdgains a "stdout and stderr" section documenting the split,and the flag entries point at it. Called out prominently at the top of
the PR body.
Verification
Reproduced with the exact trigger from the report — a config file at
mode 0644 with a
file://destination — against a binary built frommain:Same config and command on this branch: stdout is
[]and nothing else,json.loadaccepts it, and theWARNis on stderr as a JSON record.--quietsemantics confirmed unchanged in the same run: it used-qand the warning still fired, per
issue #84. Level
selection and
ui.Writer's quiet handling were not touched, and--cronshares the same branch inInitialize.make checkgreen.script/cibuildexit 0 in 140s with the checklayers executed rather than replayed —
make fmt-check2.4s,make lint40.4s,make test58.5s under a freshCHECK_EPOCH— 14oklines and zero(cached)markers.One thing this does not finish
Filed as issue #106: the
startup banner is written to stdout by
internal/cli/entry.gobeforecobra parses, and
bannerSuppressedInArgsdoes not recognize--json.So
snapshot list --jsonstill emits two banner lines and a blank lineahead of the document unless
-qis passed. Different writer, differentpath, so it is filed rather than fixed here — but stdout is not fully
clean until it lands. The reproductions above use
-qfor that reason.