Two writers bypass internal/logger: fx's console logger and the Go runtime #183

Closed
opened 2026-08-18 02:31:57 +02:00 by clawbot · 3 comments
Collaborator

Found by the writer sweep #178 required. Deliberately NOT milestoned 1.0.0 — neither writer is client-sized, so neither is the log-amplification class that #146, #176 and #178 were milestoned for.

Title and body corrected 2026-08-18. As filed this said three writers and led with net/http's ErrorLog. The review of #182 measured the set at fd level instead of reading it, and disproved that. See the comment below; the corrected set is what follows. The original claim was mine and was wrong.

The writers, as measured

Writer Measured Verdict
fx console logger 501 bytes on stderr, 0 on stdout Genuine bypass. No fx.WithLogger anywhere, so fx.New builds fxlog.DefaultLogger(os.Stderr) directly.
Go runtime, on an unrecovered panic or fatal error 359 bytes on stderr, exit 2 Genuine bypass, and irreducible. Measured in a subprocess panicking in a background goroutine — the case no HTTP recover middleware ever sees.
net/http nil ErrorLog 223 bytes on stdout, 0 on stderr Not a bypass. slog.SetDefault (internal/logger/logger.go:80) redirects the log package's default logger into the installed handler, so these arrive as ordinary JSON records at INFO. Struck from this issue.

Two further counts in the original body were also wrong and are corrected here: there are six os.Stdout/os.Stderr references outside _test.go files, not zero-outside-internal/logger — four in internal/logger/logger.go and two in internal/database/testing.go; and there are five panic calls in the tree, not three (internal/delivery/ssrf.go:64, internal/database/password.go:140, :145, :308, :316). All five are invariant guards over constants and crypto/rand, so the conclusion held even though the count did not.

Not in scope here

The handler-panic path is #187, which is milestoned 1.0.0. chi's Recoverer panics inside its own stack pretty-printer before writing anything, the second panic escapes, and the connection is dropped — a real defect the original sweep missed entirely while chasing ErrorLog. Do not fix it here.

Why this is still worth fixing

Not for amplification — for coherence. An operator who configures JSON logging and ships it to a collector gets a different shape on a second file descriptor for the startup graph, and no shape at all for a fatal error. The fx graph dump is also the one line an operator reads on every restart.

Definition of done

  • fx.WithLogger installs an fxevent.Logger over internal/logger. Choose the level deliberately: the graph dump is useful once at startup and noise thereafter.
  • The Go runtime's own output cannot be redirected. Say so explicitly, in the README, rather than leaving it looking unhandled or silently omitted.
  • The README's logging carve-out shrinks to what genuinely remains after this and #187 land. Check what those two actually left behind rather than assuming — both edit that same passage.
  • A test that the fx lifecycle events arrive as structured records on the configured handler.

Implementation requirements

  • Branch from next, PR based on next, single commit, title ending (closes #N).
  • Do not modify TODO.md (see #112).
  • Run make bootstrap in a fresh clone before gating — browser assets are fetched at build time, and make lint needs Docker.
  • Gate on make check plus the Docker lint path with the cache defeated. All linting runs in Docker, never on the host. Clean up every container and image you start; never prune.
  • Do not restate a measurement from this issue in the PR body without re-running it. That is precisely how the original error propagated.
Found by the writer sweep https://git.eeqj.de/sneak/webhooker/issues/178 required. Deliberately NOT milestoned 1.0.0 — neither writer is client-sized, so neither is the log-amplification class that https://git.eeqj.de/sneak/webhooker/issues/146, https://git.eeqj.de/sneak/webhooker/issues/176 and https://git.eeqj.de/sneak/webhooker/issues/178 were milestoned for. **Title and body corrected 2026-08-18.** As filed this said *three* writers and led with `net/http`'s `ErrorLog`. The review of https://git.eeqj.de/sneak/webhooker/pulls/182 measured the set at fd level instead of reading it, and disproved that. See the comment below; the corrected set is what follows. The original claim was mine and was wrong. ## The writers, as measured | Writer | Measured | Verdict | | --- | --- | --- | | `fx` console logger | 501 bytes on **stderr**, 0 on stdout | Genuine bypass. No `fx.WithLogger` anywhere, so `fx.New` builds `fxlog.DefaultLogger(os.Stderr)` directly. | | Go runtime, on an unrecovered panic or fatal error | 359 bytes on **stderr**, exit 2 | Genuine bypass, and irreducible. Measured in a subprocess panicking in a background goroutine — the case no HTTP recover middleware ever sees. | | `net/http` nil `ErrorLog` | 223 bytes on **stdout**, **0 on stderr** | **Not a bypass.** `slog.SetDefault` (`internal/logger/logger.go:80`) redirects the `log` package's default logger into the installed handler, so these arrive as ordinary JSON records at `INFO`. Struck from this issue. | Two further counts in the original body were also wrong and are corrected here: there are **six** `os.Stdout`/`os.Stderr` references outside `_test.go` files, not zero-outside-`internal/logger` — four in `internal/logger/logger.go` and two in `internal/database/testing.go`; and there are **five** `panic` calls in the tree, not three (`internal/delivery/ssrf.go:64`, `internal/database/password.go:140`, `:145`, `:308`, `:316`). All five are invariant guards over constants and `crypto/rand`, so the conclusion held even though the count did not. ## Not in scope here The handler-panic path is https://git.eeqj.de/sneak/webhooker/issues/187, which is milestoned 1.0.0. chi's `Recoverer` panics inside its own stack pretty-printer before writing anything, the second panic escapes, and the connection is dropped — a real defect the original sweep missed entirely while chasing `ErrorLog`. Do not fix it here. ## Why this is still worth fixing Not for amplification — for coherence. An operator who configures JSON logging and ships it to a collector gets a different shape on a second file descriptor for the startup graph, and no shape at all for a fatal error. The `fx` graph dump is also the one line an operator reads on every restart. ## Definition of done - `fx.WithLogger` installs an `fxevent.Logger` over `internal/logger`. Choose the level deliberately: the graph dump is useful once at startup and noise thereafter. - The Go runtime's own output cannot be redirected. Say so explicitly, in the README, rather than leaving it looking unhandled or silently omitted. - The README's logging carve-out shrinks to what genuinely remains after this and https://git.eeqj.de/sneak/webhooker/issues/187 land. Check what those two actually left behind rather than assuming — both edit that same passage. - A test that the `fx` lifecycle events arrive as structured records on the configured handler. ## Implementation requirements - Branch from `next`, PR based on `next`, single commit, title ending ` (closes #N)`. - Do not modify `TODO.md` (see https://git.eeqj.de/sneak/webhooker/issues/112). - Run `make bootstrap` in a fresh clone before gating — browser assets are fetched at build time, and `make lint` needs Docker. - Gate on `make check` plus the Docker lint path with the cache defeated. All linting runs in Docker, never on the host. Clean up every container and image you start; never prune. - Do not restate a measurement from this issue in the PR body without re-running it. That is precisely how the original error propagated.
clawbot self-assigned this 2026-08-18 02:31:57 +02:00
Author
Collaborator

Correcting this issue: the enumeration in the body above is wrong. It came from the writer sweep in #182, and the independent review of that PR disproved two of its three claims by measurement. I filed it on that basis, so the error is mine to fix.

What is actually true:

  • net/http's ErrorLog is NOT outside internal/logger, and NOT on stderr. internal/logger/logger.go:80 calls slog.SetDefault, which internally does log.SetOutput(&handlerWriter{...}). So the nil ErrorLog falls through to log.Default(), which is already rerouted through the service's own handler — and lands on stdout at INFO. Measured, not read. It is therefore structured and levelled already; what is arguably wrong is only the level and the stream, which is a much smaller thing than this issue claims.
  • There is a fourth writer, and it is the one that actually matters. internal/server/routes.go:32 installs chi's middleware.Recoverer, whose PrintPrettyStack writes to os.Stderr directly. That is what really catches a handler panic — the case this issue's body used as its motivating example for net/http. The review of #180 had already named it, and I did not carry it across.
  • The fx console logger and the Go runtime remain as described. The runtime panic count is five, not three, all invariant guards.

Net: the shape of the issue survives — there are writers that bypass or diverge from internal/logger, and a panic stack still lands unstructured on stderr — but the specific writer to fix is chi's Recoverer, not net/http's ErrorLog, and the ErrorLog item shrinks to a level-and-stream question.

Still NOT milestoned 1.0.0: none of these is client-sized, so none is the log-amplification class #146, #176 and #178 were milestoned for.

Whoever picks this up should re-derive the writer list from the tree rather than trusting either the body or this comment — that is twice now this enumeration has been stated wrong from reading rather than measuring.

**Correcting this issue: the enumeration in the body above is wrong.** It came from the writer sweep in https://git.eeqj.de/sneak/webhooker/pulls/182, and the independent review of that PR disproved two of its three claims by measurement. I filed it on that basis, so the error is mine to fix. What is actually true: - **`net/http`'s `ErrorLog` is NOT outside `internal/logger`, and NOT on stderr.** `internal/logger/logger.go:80` calls `slog.SetDefault`, which internally does `log.SetOutput(&handlerWriter{...})`. So the nil `ErrorLog` falls through to `log.Default()`, which is already rerouted through the service's own handler — and lands on **stdout at INFO**. Measured, not read. It is therefore structured and levelled already; what is arguably wrong is only the level and the stream, which is a much smaller thing than this issue claims. - **There is a fourth writer, and it is the one that actually matters.** `internal/server/routes.go:32` installs chi's `middleware.Recoverer`, whose `PrintPrettyStack` writes to `os.Stderr` directly. That is what really catches a handler panic — the case this issue's body used as its motivating example for `net/http`. The review of https://git.eeqj.de/sneak/webhooker/pulls/180 had already named it, and I did not carry it across. - The `fx` console logger and the Go runtime remain as described. The runtime `panic` count is five, not three, all invariant guards. Net: the shape of the issue survives — there are writers that bypass or diverge from `internal/logger`, and a panic stack still lands unstructured on stderr — but the specific writer to fix is chi's `Recoverer`, not `net/http`'s `ErrorLog`, and the `ErrorLog` item shrinks to a level-and-stream question. Still NOT milestoned `1.0.0`: none of these is client-sized, so none is the log-amplification class https://git.eeqj.de/sneak/webhooker/issues/146, https://git.eeqj.de/sneak/webhooker/issues/176 and https://git.eeqj.de/sneak/webhooker/issues/178 were milestoned for. Whoever picks this up should re-derive the writer list from the tree rather than trusting either the body or this comment — that is twice now this enumeration has been stated wrong from reading rather than measuring.
clawbot changed title from Three writers bypass internal/logger entirely: net/http's ErrorLog, fx's console logger, and the Go runtime to Two writers bypass internal/logger: fx's console logger and the Go runtime 2026-08-18 03:43:08 +02:00
Author
Collaborator

Plan. Still true on next: nothing calls fx.WithLogger, so the app built in cmd/webhooker prints its dependency graph and lifecycle hooks through fx's console logger on standard error.

  • Install fx.WithLogger in the production app with the library's own fxevent.SlogLogger over the service's logger, so the events arrive as structured records on the configured handler. Events that only describe the graph (provided, supplied, decorated, invoked) log at debug; lifecycle events, start and stop failures at info and error. Tests keep fx.NopLogger.
  • README: shrink the "two writers" passage to the Go runtime alone, and say plainly that its panic and fatal-error output cannot be redirected.
  • A test builds the app's fx options with a recording handler and shows a lifecycle event arrives there as a structured record.

Model: opus-5-5

Plan. Still true on `next`: nothing calls `fx.WithLogger`, so the app built in `cmd/webhooker` prints its dependency graph and lifecycle hooks through fx's console logger on standard error. - Install `fx.WithLogger` in the production app with the library's own `fxevent.SlogLogger` over the service's logger, so the events arrive as structured records on the configured handler. Events that only describe the graph (provided, supplied, decorated, invoked) log at debug; lifecycle events, start and stop failures at info and error. Tests keep `fx.NopLogger`. - README: shrink the "two writers" passage to the Go runtime alone, and say plainly that its panic and fatal-error output cannot be redirected. - A test builds the app's fx options with a recording handler and shows a lifecycle event arrives there as a structured record. Model: opus-5-5
Author
Collaborator

Done in #443. The app built in cmd/webhooker now sends fx's own events through internal/logger, so they reach the configured handler as records: how the dependency graph was built at DEBUG, start and stop hooks, the start and the stopping signal at INFO, failures at ERROR. Tests keep fx.NopLogger. The README's bypass passage now names only the Go runtime and says its output cannot be redirected.

  • Deviation: fx's fxevent.SlogLogger takes one level for all non-failure events, so a small FxLogger in internal/logger holds one at each level and picks by event type.
  • Dependency change: go.uber.org/fx moves from v1.20.1 to v1.24.0, since v1.20.1 has no SlogLogger.
  • Judgement call: the README's count of five panic calls became a description, since the hand-back of http.ErrAbortHandler is a sixth.

Model: opus-5-5

Done in https://git.eeqj.de/sneak/webhooker/pulls/443. The app built in `cmd/webhooker` now sends fx's own events through `internal/logger`, so they reach the configured handler as records: how the dependency graph was built at `DEBUG`, start and stop hooks, the start and the stopping signal at `INFO`, failures at `ERROR`. Tests keep `fx.NopLogger`. The README's bypass passage now names only the Go runtime and says its output cannot be redirected. - Deviation: fx's `fxevent.SlogLogger` takes one level for all non-failure events, so a small `FxLogger` in `internal/logger` holds one at each level and picks by event type. - Dependency change: `go.uber.org/fx` moves from v1.20.1 to v1.24.0, since v1.20.1 has no `SlogLogger`. - Judgement call: the README's count of five `panic` calls became a description, since the hand-back of `http.ErrAbortHandler` is a sixth. Model: opus-5-5
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#183