TTYHandler silently discards log.With attributes, so diagnostics differ between terminal and CI #97

New Issue

Closed

opened 2026-08-09 11:55:49 +02:00 by clawbot · 2 comments

clawbot commented 2026-08-09 11:55:49 +02:00

Collaborator

Copy Link

internal/log exports a With function whose attributes vanish when
stdout is a terminal and appear when it is not. Found while checking
whether a defect reported against simplelog applied here — vaultik does
not use that library, but the same defect shape exists in our own handler.

The code

internal/log/tty_handler.go:116-124:

// WithAttrs returns a new handler with the given attributes.
func (h *TTYHandler) WithAttrs(_ []slog.Attr) slog.Handler {
	return h // Simplified for now
}

// WithGroup returns a new handler with the given group name.
func (h *TTYHandler) WithGroup(_ string) slog.Handler {
	return h // Simplified for now
}

Both discard their argument and return the receiver unchanged. Note the
doc comments assert the opposite of what the code does — "returns a new
handler with the given attributes" is false.

This is reachable through an exported API. internal/log/log.go:181:

func With(args ...any) *slog.Logger {
	...
	return logger.With(args...)
}

The environment inversion

log.go:73-78 selects the handler by TTY-ness:

stdout	handler	log.With attributes
terminal	TTYHandler	silently dropped
not a terminal (CI, container, pipe)	slog.NewJSONHandler	correctly emitted

So the interactive path — the one a developer uses while debugging — is
the one that loses the fields, and CI is fine. That is the inverse of the
simplelog bug, where a local TTY run looked healthy and containers
broke. Both are the same underlying hazard: behavior that differs by
environment, in the component you use to diagnose behavior.

WithGroup discards group names on the same path.

Current impact: latent, but it is an exported footgun

grep finds no caller of log.With(...) outside the package today, so
nothing is losing fields right now. The defect is that the package
offers the function, and the first person to reach for it will be
someone adding context to a hard bug — which is exactly when silently
missing fields cost the most, and exactly when they will be hardest to
notice, because the same code prints correctly in CI.

Related: the lint remediation in #61 blanked unused parameters to satisfy
revive. That did not cause this — the parameters were already unused —
but it removed the compiler-visible hint that something was ignored.
Worth knowing when reading similar signatures elsewhere.

Definition of done

1. TTYHandler.WithAttrs retains the attributes and emits them on every
   subsequent record, and WithGroup applies grouping — or, if
   implementing grouping properly is judged out of scope, WithGroup
   documents honestly what it does and a follow-up is filed. Do not leave
   a doc comment claiming behavior the code does not have.
2. Both must return a new handler rather than mutating the receiver —
   slog permits a handler to be shared and derived from concurrently, so
   mutating h in place would be a data race.
3. A test asserts a log.With("key", "value") attribute appears in
   TTYHandler output. It must fail against the current implementation —
   verify by reverting the fix and watching it fail, not by assuming.
4. A test asserts TTY and JSON handlers emit the same attribute set
   for the same logger, so the two paths cannot drift again. This is the
   test that would have caught the original defect.
5. // Simplified for now comments removed or replaced with something
   true.
6. script/cibuild exits 0, verified per #93 (expected ok count, zero
   (cached) markers, plausible wall time).

Out of scope

The logger writing to stdout at all (#82) and the --cron suppression
semantics (#84, #87). This issue is only about attributes being dropped.

`internal/log` exports a `With` function whose attributes **vanish when stdout is a terminal** and appear when it is not. Found while checking whether a defect reported against `simplelog` applied here — vaultik does not use that library, but the same defect shape exists in our own handler. ## The code `internal/log/tty_handler.go:116-124`: ```go // WithAttrs returns a new handler with the given attributes. func (h *TTYHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h // Simplified for now } // WithGroup returns a new handler with the given group name. func (h *TTYHandler) WithGroup(_ string) slog.Handler { return h // Simplified for now } ``` Both discard their argument and return the receiver unchanged. Note the doc comments assert the opposite of what the code does — "returns a new handler with the given attributes" is false. This is reachable through an **exported** API. `internal/log/log.go:181`: ```go func With(args ...any) *slog.Logger { ... return logger.With(args...) } ``` ## The environment inversion `log.go:73-78` selects the handler by TTY-ness: | stdout | handler | `log.With` attributes | | --- | --- | --- | | terminal | `TTYHandler` | **silently dropped** | | not a terminal (CI, container, pipe) | `slog.NewJSONHandler` | correctly emitted | So the interactive path — the one a developer uses while debugging — is the one that loses the fields, and CI is fine. That is the inverse of the `simplelog` bug, where a local TTY run looked healthy and containers broke. Both are the same underlying hazard: **behavior that differs by environment, in the component you use to diagnose behavior.** `WithGroup` discards group names on the same path. ## Current impact: latent, but it is an exported footgun `grep` finds no caller of `log.With(...)` outside the package today, so nothing is losing fields right now. The defect is that the package *offers* the function, and the first person to reach for it will be someone adding context to a hard bug — which is exactly when silently missing fields cost the most, and exactly when they will be hardest to notice, because the same code prints correctly in CI. Related: the lint remediation in #61 blanked unused parameters to satisfy `revive`. That did not cause this — the parameters were already unused — but it removed the compiler-visible hint that something was ignored. Worth knowing when reading similar signatures elsewhere. ## Definition of done 1. `TTYHandler.WithAttrs` retains the attributes and emits them on every subsequent record, and `WithGroup` applies grouping — or, if implementing grouping properly is judged out of scope, `WithGroup` documents honestly what it does and a follow-up is filed. Do not leave a doc comment claiming behavior the code does not have. 2. Both must return a **new** handler rather than mutating the receiver — `slog` permits a handler to be shared and derived from concurrently, so mutating `h` in place would be a data race. 3. A test asserts a `log.With("key", "value")` attribute appears in TTYHandler output. It must fail against the current implementation — verify by reverting the fix and watching it fail, not by assuming. 4. A test asserts TTY and JSON handlers emit the **same attribute set** for the same logger, so the two paths cannot drift again. This is the test that would have caught the original defect. 5. `// Simplified for now` comments removed or replaced with something true. 6. `script/cibuild` exits 0, verified per #93 (expected `ok` count, zero `(cached)` markers, plausible wall time). ## Out of scope The logger writing to stdout at all (#82) and the `--cron` suppression semantics (#84, #87). This issue is only about attributes being dropped.

clawbot added this to the 1.0.0 milestone 2026-08-09 11:55:49 +02:00

clawbot referenced this issue 2026-08-09 18:10:40 +02:00

Logger writes to stdout, so any warning corrupts --json output #82

clawbot commented 2026-08-09 18:10:59 +02:00

Author

Collaborator

Copy Link

Implementation plan

Implementing this together with
issue #82 on one branch —
that one moves the logger's sink and this one fixes the handler, and
both edit the same construction site in internal/log.

TTYHandler state

TTYHandler gains two fields and one changes type:

• attrs []slog.Attr — attributes accumulated through WithAttrs,
  stored with their group path already folded into the key.
• groups []string — the open group path, so attributes arriving later
  (on a record, or through a further WithAttrs) get qualified.
• mu becomes *sync.Mutex. Derived handlers share the receiver's
  writer, so they must share one mutex; a value mutex would give each
  derived handler its own lock and stop serialising writes to the same
  stream. NewTTYHandler allocates it.

WithAttrs / WithGroup

Both clone() the receiver — copying the attrs and groups slices,
not just reslicing them, so two handlers derived from one parent cannot
append into a shared backing array — and return the clone. The receiver
is never written to, which is what makes concurrent derivation safe.
WithAttrs(nil) and WithGroup("") return the receiver unchanged, per
the slog.Handler contract.

Grouping

Grouping is implemented rather than deferred, using dotted keys:
WithGroup("db").With("rows", 3) renders db.rows=3. That is the
conventional flattening for a line-oriented format that has nowhere to
nest, and it round-trips against slog.JSONHandler's nested object
under the same flattening rule, which is what makes item 4 below
testable. slog.KindGroup values on a record are flattened the same
way. Empty attrs are dropped and an empty-key group is inlined, both
per the slog.Handler contract.

So the doc comments will describe exactly this, and the // Simplified for now markers are removed rather than reworded.

Tests (new internal/log test files)

1. log.With("key", "value") through the exported package-level
   API, with the package logger pointed at a TTYHandler over a
   buffer, asserting the attribute appears in the output. Written as an
   in-package test so it can set the package logger; that is the only
   way to exercise With itself rather than a hand-built slog.Logger.
2. TTY and JSON handlers fed the identical With/WithGroup
   derivation chain and the identical record, then their emitted
   attribute sets compared after flattening JSON's nesting to dotted
   keys. This is the drift guard.
3. Non-mutation: derive twice from one handler with different
   attributes, assert neither derived handler sees the other's, and
   assert the parent still emits none. Plus a concurrent-derivation
   test, since script/test already runs -race.
4. WithGroup qualification and empty-group/empty-attr handling.

Item 3 of the definition of done — the test must fail against the
current implementation — will be verified by reverting tty_handler.go
to the current return h bodies, running the suite, and recording the
observed failures in the PR body. Not asserted, observed.

Verification

make check (which runs -race) and script/cibuild.

## Implementation plan Implementing this together with [issue #82](https://git.eeqj.de/sneak/vaultik/issues/82) on one branch — that one moves the logger's sink and this one fixes the handler, and both edit the same construction site in `internal/log`. ### `TTYHandler` state `TTYHandler` gains two fields and one changes type: - `attrs []slog.Attr` — attributes accumulated through `WithAttrs`, stored with their group path already folded into the key. - `groups []string` — the open group path, so attributes arriving later (on a record, or through a further `WithAttrs`) get qualified. - `mu` becomes `*sync.Mutex`. Derived handlers share the receiver's writer, so they must share one mutex; a value mutex would give each derived handler its own lock and stop serialising writes to the same stream. `NewTTYHandler` allocates it. ### `WithAttrs` / `WithGroup` Both `clone()` the receiver — copying the `attrs` and `groups` slices, not just reslicing them, so two handlers derived from one parent cannot append into a shared backing array — and return the clone. The receiver is never written to, which is what makes concurrent derivation safe. `WithAttrs(nil)` and `WithGroup("")` return the receiver unchanged, per the `slog.Handler` contract. ### Grouping Grouping is implemented rather than deferred, using dotted keys: `WithGroup("db").With("rows", 3)` renders `db.rows=3`. That is the conventional flattening for a line-oriented format that has nowhere to nest, and it round-trips against `slog.JSONHandler`'s nested object under the same flattening rule, which is what makes item 4 below testable. `slog.KindGroup` values on a record are flattened the same way. Empty attrs are dropped and an empty-key group is inlined, both per the `slog.Handler` contract. So the doc comments will describe exactly this, and the `// Simplified for now` markers are removed rather than reworded. ### Tests (new `internal/log` test files) 1. `log.With("key", "value")` through the **exported** package-level API, with the package logger pointed at a `TTYHandler` over a buffer, asserting the attribute appears in the output. Written as an in-package test so it can set the package logger; that is the only way to exercise `With` itself rather than a hand-built `slog.Logger`. 2. TTY and JSON handlers fed the identical `With`/`WithGroup` derivation chain and the identical record, then their emitted attribute sets compared after flattening JSON's nesting to dotted keys. This is the drift guard. 3. Non-mutation: derive twice from one handler with different attributes, assert neither derived handler sees the other's, and assert the parent still emits none. Plus a concurrent-derivation test, since `script/test` already runs `-race`. 4. `WithGroup` qualification and empty-group/empty-attr handling. Item 3 of the definition of done — the test must fail against the current implementation — will be verified by reverting `tty_handler.go` to the current `return h` bodies, running the suite, and recording the observed failures in the PR body. Not asserted, observed. ### Verification `make check` (which runs `-race`) and `script/cibuild`.

clawbot referenced this issue from a commit 2026-08-09 18:28:37 +02:00

Send diagnostics to stderr and stop dropping log attributes (closes #82)

clawbot referenced a pull request that will close this issue 2026-08-09 18:29:21 +02:00

Send diagnostics to stderr and stop dropping log attributes (closes #82, closes #97) #107

clawbot referenced this issue 2026-08-09 18:29:42 +02:00

Logger writes to stdout, so any warning corrupts --json output #82

clawbot commented 2026-08-09 18:30:03 +02:00

Author

Collaborator

Copy Link

Implemented in
PR #107 (branch
fix-log-stdout), together with
issue #82.

Against the definition of done, point by point.

1. WithAttrs retains attributes; WithGroup applies grouping.
Both done, grouping implemented rather than deferred. TTYHandler gained
an attrs []slog.Attr field (keys already qualified when added) and a
groups []string path applied to attributes arriving later. Grouping is
rendered as a dotted key prefix — WithGroup("db").With("rows", 3)
emits db.rows=3 — because this format is a single line with nowhere to
nest. Record-level slog.KindGroup values flatten the same way, empty
attrs are dropped, and an empty-key group is inlined, per the
slog.Handler contract. WithGroup("") and WithAttrs(nil) return the
receiver, also per the contract. No follow-up issue needed.

2. New handler, not a mutated receiver. Both derive through a
clone() that copies the attrs and groups slices rather than
reslicing them, so two concurrent derivations cannot append over each
other's attribute. The receiver is never written to. mu became a
*sync.Mutex so a handler and everything derived from it keep sharing
one lock — a value mutex would have given each derived handler its own
and stopped serializing writes to the stream they have in common.
Verified under -race: script/test runs go test -race, and
TestTTYHandlerConcurrentDerivation has sixteen goroutines deriving
from and writing through one handler.

3. A test asserting log.With("key","value") reaches TTYHandler
output, verified to fail against the current implementation.
TestWithAttributesReachTTYOutput goes through the exported package-level
With — an in-package test, because pointing the package logger at a
buffer is the only way to exercise With itself rather than a
hand-built slog.Logger; //nolint:testpackage carries that reason.

Verified by observation, not assumption: internal/log/tty_handler.go
was reverted to its main version with the new tests in place and
make test run. Result:

--- FAIL: TestWithAttributesReachTTYOutput
--- FAIL: TestTTYHandlerWithAttrsEmitsAttributes
--- FAIL: TestTTYHandlerWithAttrsPersistsAcrossRecords
--- FAIL: TestTTYHandlerWithGroupQualifiesKeys
--- FAIL: TestTTYHandlerWithAttrsDoesNotMutateReceiver
--- FAIL: TestTTYHandlerConcurrentDerivation
--- FAIL: TestTTYHandlerEmptyGroupAndAttrsAreNoOps
--- FAIL: TestTTYHandlerMatchesJSONHandlerAttributes
    --- FAIL: .../handler_attributes
    --- FAIL: .../handler_attributes_accumulate
    --- FAIL: .../group_qualifies_later_attributes
    --- FAIL: .../nested_groups
    --- FAIL: .../attributes_before_and_after_a_group
    --- FAIL: .../inline_group_value_on_the_record
FAIL	sneak.berlin/go/vaultik/internal/log

Every other package stayed green, so the failures are the handler and
nothing else. The handler was then restored and the suite went green.

4. A test asserting TTY and JSON emit the same attribute set.
TestTTYHandlerMatchesJSONHandlerAttributes builds both handlers over
buffers, applies an identical With/WithGroup derivation chain and an
identical record to each, and compares the emitted attribute sets after
flattening JSONHandler's nested groups to the same dotted keys. Seven
cases: record attributes only, handler attributes, accumulated handler
attributes, a group qualifying later attributes, nested groups,
attributes straddling a group, and an inline slog.Group value on the
record. Six of the seven fail against the unfixed handler, as listed
above.

5. // Simplified for now removed. Both are gone, and the doc
comments describe what the code does — including WithGroup naming the
dotted-prefix rendering explicitly.

6. script/cibuild exits 0, verified per
issue #93. Exit 0, 140s
wall. The check layers executed rather than replaying from cache —
make fmt-check 2.4s, make lint 40.4s, make test 58.5s under a
fresh CHECK_EPOCH — with 14 ok lines and zero (cached) markers.
The 10 CACHED layers are dependency and module layers, which is the
intended behaviour. make check is green on the host as well.

Implemented in [PR #107](https://git.eeqj.de/sneak/vaultik/pulls/107) (branch `fix-log-stdout`), together with [issue #82](https://git.eeqj.de/sneak/vaultik/issues/82). Against the definition of done, point by point. **1. `WithAttrs` retains attributes; `WithGroup` applies grouping.** Both done, grouping implemented rather than deferred. `TTYHandler` gained an `attrs []slog.Attr` field (keys already qualified when added) and a `groups []string` path applied to attributes arriving later. Grouping is rendered as a dotted key prefix — `WithGroup("db").With("rows", 3)` emits `db.rows=3` — because this format is a single line with nowhere to nest. Record-level `slog.KindGroup` values flatten the same way, empty attrs are dropped, and an empty-key group is inlined, per the `slog.Handler` contract. `WithGroup("")` and `WithAttrs(nil)` return the receiver, also per the contract. No follow-up issue needed. **2. New handler, not a mutated receiver.** Both derive through a `clone()` that copies the `attrs` and `groups` slices rather than reslicing them, so two concurrent derivations cannot append over each other's attribute. The receiver is never written to. `mu` became a `*sync.Mutex` so a handler and everything derived from it keep sharing one lock — a value mutex would have given each derived handler its own and stopped serializing writes to the stream they have in common. Verified under `-race`: `script/test` runs `go test -race`, and `TestTTYHandlerConcurrentDerivation` has sixteen goroutines deriving from and writing through one handler. **3. A test asserting `log.With("key","value")` reaches TTYHandler output, verified to fail against the current implementation.** `TestWithAttributesReachTTYOutput` goes through the exported package-level `With` — an in-package test, because pointing the package logger at a buffer is the only way to exercise `With` itself rather than a hand-built `slog.Logger`; `//nolint:testpackage` carries that reason. Verified by observation, not assumption: `internal/log/tty_handler.go` was reverted to its `main` version with the new tests in place and `make test` run. Result: ``` --- FAIL: TestWithAttributesReachTTYOutput --- FAIL: TestTTYHandlerWithAttrsEmitsAttributes --- FAIL: TestTTYHandlerWithAttrsPersistsAcrossRecords --- FAIL: TestTTYHandlerWithGroupQualifiesKeys --- FAIL: TestTTYHandlerWithAttrsDoesNotMutateReceiver --- FAIL: TestTTYHandlerConcurrentDerivation --- FAIL: TestTTYHandlerEmptyGroupAndAttrsAreNoOps --- FAIL: TestTTYHandlerMatchesJSONHandlerAttributes --- FAIL: .../handler_attributes --- FAIL: .../handler_attributes_accumulate --- FAIL: .../group_qualifies_later_attributes --- FAIL: .../nested_groups --- FAIL: .../attributes_before_and_after_a_group --- FAIL: .../inline_group_value_on_the_record FAIL sneak.berlin/go/vaultik/internal/log ``` Every other package stayed green, so the failures are the handler and nothing else. The handler was then restored and the suite went green. **4. A test asserting TTY and JSON emit the same attribute set.** `TestTTYHandlerMatchesJSONHandlerAttributes` builds both handlers over buffers, applies an identical `With`/`WithGroup` derivation chain and an identical record to each, and compares the emitted attribute sets after flattening `JSONHandler`'s nested groups to the same dotted keys. Seven cases: record attributes only, handler attributes, accumulated handler attributes, a group qualifying later attributes, nested groups, attributes straddling a group, and an inline `slog.Group` value on the record. Six of the seven fail against the unfixed handler, as listed above. **5. `// Simplified for now` removed.** Both are gone, and the doc comments describe what the code does — including `WithGroup` naming the dotted-prefix rendering explicitly. **6. `script/cibuild` exits 0, verified per [issue #93](https://git.eeqj.de/sneak/vaultik/issues/93).** Exit 0, 140s wall. The check layers executed rather than replaying from cache — `make fmt-check` 2.4s, `make lint` 40.4s, `make test` 58.5s under a fresh `CHECK_EPOCH` — with 14 `ok` lines and zero `(cached)` markers. The 10 `CACHED` layers are dependency and module layers, which is the intended behaviour. `make check` is green on the host as well.

clawbot referenced this issue 2026-08-09 18:43:02 +02:00

Send diagnostics to stderr and stop dropping log attributes (closes #82, closes #97) #107

clawbot closed this issue 2026-08-09 18:43:56 +02:00

clawbot referenced this issue from a commit 2026-08-09 18:43:58 +02:00

Log to stderr and stop discarding With attributes (closes #82)

clawbot referenced this issue 2026-08-09 18:44:19 +02:00

Startup banner goes to stdout and --json does not suppress it, so every --json document is preceded by three lines of prose #106

Sign in to join this conversation.

No Branch/Tag Specified

Branches Tags

main

next

feature/daemon-mode

No results found.

Labels

Clear labels

merge-ready

All checks pass, reviewed, rebased, ready for merge

needs-checks

make check does not pass cleanly

needs-rebase

PR has merge conflicts or is behind main

needs-review

Code review not yet done

needs-rework

Code review found issues to fix

No Label

Milestone

No items

No Milestone 1.0.0

Projects

Clear projects

No project

Assignees

Clear assignees

clawbot sneak

No Assignees

1 Participants

Notifications

Subscribe

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: sneak/vaultik#97