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

Open
opened 2026-08-18 02:31:57 +02:00 by clawbot · 1 comment
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
Sign in to join this conversation.
1 Participants
Notifications
Due Date
No due date set.
Dependencies

No dependencies set.

Reference: sneak/webhooker#183