chi's Recoverer panics instead of handling a handler panic, so a panicking request drops the connection instead of answering 500 #187

New Issue

clawbot · 2026-08-18T03:15:07+02:00

clawbot commented

2026-08-18 03:15:07 +02:00

Found by measurement while correcting the writer enumeration for #182. Not fixed there — it is an independent defect with its own remediation choice.

What happens

internal/server/routes.go:32 installs middleware.Recoverer (chi v1.5.5) in front of every route. On a handler panic it is supposed to print the panic and its stack to standard error via PrintPrettyStack and answer 500. It does neither.

PrintPrettyStack calls prettyStack.parse, which locates the panic frame with:

if strings.HasPrefix(stack[i], "panic(0x") {
    lines = lines[0 : len(lines)-2] // remove boilerplate
    break
}

Go no longer emits that frame as panic(0x.... It emits panic({0x19611a0?, 0xc00003e8a0?}). The prefix never matches, the loop never breaks, and every stack line is then handed to decorateLine. decorateFuncCallLine does idx = strings.Index(pkg, ".") followed by method = pkg[idx:] with no check for -1, and panics with slice bounds out of range [-1:].

That second panic escapes Recoverer's deferred function, so w.WriteHeader(http.StatusInternalServerError) on the next line never runs. net/http's own conn.serve recover catches it, closes the connection, and reports it through the server's ErrorLog.

Reachable on any handler panic. The service uses its own s.mw.Logging() rather than chi's RequestLogger, so GetLogEntry(r) is nil and the PrintPrettyStack branch is always the one taken.

Measured

A chi.NewRouter() with middleware.Recoverer and a panicking handler, behind a real httptest server, in a subprocess so the process's actual fd 1 and fd 2 are captured:

child-stderr: 0 bytes
child-stdout line 0: 2772 bytes: {"time":"...","level":"INFO","msg":"http: panic serving 127.0.0.1:...: runtime error: slice bounds out of range [-1:]\ngoroutine 35 [running]:\nnet/http.(*conn).serve.func1()\n\t/usr/local/go/src/net/http/server.go:1907 +0xff\npanic({0x19611a0?, 0xc00003e8a0?})\n\t/usr/local/go/src/runtime/panic.go:860 +0x13a\ngithub.com/go-chi/chi/middleware.prettyStack.decorateFuncCa...
child-stdout line 1: PROBE-B-CHILD status=0 geterr=Get "http://127.0.0.1:39953/boom": EOF

So, against what a reader would expect:

Expected	Actual
Pretty stack on standard error	Nothing on standard error
`500 Internal Server Error`	Connection closed; client gets `EOF`
The original panic value reported	The secondary panic reported, with the original value nowhere in the output

The reported line lands on standard output at INFO, not standard error, because the nil ErrorLog falls back to the log package's default logger and internal/logger redirects that through slog.SetDefault. That routing is correct and documented; what is wrong is that the line describes chi's crash rather than the fault that caused it.

The record is also 2,772 bytes, above the 2,560-byte per-line ceiling MaxAccessLogLineBytes states. It is not client-sized, so it is a disclosed carve-out rather than a bound violation, but it is the widest line the service can be made to write.

Why it matters

A panicking handler answers with a dropped connection rather than a 500, so a client cannot tell a crash from a network fault.
The original panic value and stack are lost entirely. The only thing logged is chi's own crash, which names decorateFuncCallLine and tells an operator nothing about what actually failed.
Sentry still receives the original panic: sentryhttp is registered with Repanic: true inside Recoverer, so an operator with SENTRY_DSN set keeps that signal. An operator without one has nothing.

Options

Upgrade to github.com/go-chi/chi/v5. The v5 pretty-printer has the same panic(0x prefix check, so verify against the shipped Go version before assuming this is fixed rather than moved.
Replace middleware.Recoverer with a local recover middleware that logs the panic value and debug.Stack() through internal/logger and answers 500. That also puts the widest line this service writes under the same handler and level as everything else, and would let the README drop the carve-out above rather than merely state it.

Option 2 is the smaller dependency surface and the one that makes the stated ceiling true of one more writer, but the choice is an observability decision, which is why this is filed rather than folded into #182.

The writer enumeration in README.md is corrected against this in #182, and #183 names the pre-correction set of writers.

Found by measurement while correcting the writer enumeration for https://git.eeqj.de/sneak/webhooker/pulls/182. Not fixed there — it is an independent defect with its own remediation choice. ## What happens `internal/server/routes.go:32` installs `middleware.Recoverer` (chi v1.5.5) in front of every route. On a handler panic it is supposed to print the panic and its stack to standard error via `PrintPrettyStack` and answer `500`. It does neither. `PrintPrettyStack` calls `prettyStack.parse`, which locates the panic frame with: ```go if strings.HasPrefix(stack[i], "panic(0x") { lines = lines[0 : len(lines)-2] // remove boilerplate break } ``` Go no longer emits that frame as `panic(0x...`. It emits `panic({0x19611a0?, 0xc00003e8a0?})`. The prefix never matches, the loop never breaks, and every stack line is then handed to `decorateLine`. `decorateFuncCallLine` does `idx = strings.Index(pkg, ".")` followed by `method = pkg[idx:]` with no check for `-1`, and panics with `slice bounds out of range [-1:]`. That second panic escapes `Recoverer`'s deferred function, so `w.WriteHeader(http.StatusInternalServerError)` on the next line never runs. `net/http`'s own `conn.serve` recover catches it, closes the connection, and reports it through the server's `ErrorLog`. Reachable on any handler panic. The service uses its own `s.mw.Logging()` rather than chi's `RequestLogger`, so `GetLogEntry(r)` is nil and the `PrintPrettyStack` branch is always the one taken. ## Measured A `chi.NewRouter()` with `middleware.Recoverer` and a panicking handler, behind a real `httptest` server, in a subprocess so the process's actual fd 1 and fd 2 are captured: ``` child-stderr: 0 bytes child-stdout line 0: 2772 bytes: {"time":"...","level":"INFO","msg":"http: panic serving 127.0.0.1:...: runtime error: slice bounds out of range [-1:]\ngoroutine 35 [running]:\nnet/http.(*conn).serve.func1()\n\t/usr/local/go/src/net/http/server.go:1907 +0xff\npanic({0x19611a0?, 0xc00003e8a0?})\n\t/usr/local/go/src/runtime/panic.go:860 +0x13a\ngithub.com/go-chi/chi/middleware.prettyStack.decorateFuncCa... child-stdout line 1: PROBE-B-CHILD status=0 geterr=Get "http://127.0.0.1:39953/boom": EOF ``` So, against what a reader would expect: | Expected | Actual | | --- | --- | | Pretty stack on standard error | Nothing on standard error | | `500 Internal Server Error` | Connection closed; client gets `EOF` | | The original panic value reported | The **secondary** panic reported, with the original value nowhere in the output | The reported line lands on standard output at `INFO`, not standard error, because the nil `ErrorLog` falls back to the `log` package's default logger and `internal/logger` redirects that through `slog.SetDefault`. That routing is correct and documented; what is wrong is that the line describes chi's crash rather than the fault that caused it. The record is also 2,772 bytes, above the 2,560-byte per-line ceiling `MaxAccessLogLineBytes` states. It is not client-sized, so it is a disclosed carve-out rather than a bound violation, but it is the widest line the service can be made to write. ## Why it matters - A panicking handler answers with a dropped connection rather than a `500`, so a client cannot tell a crash from a network fault. - The original panic value and stack are lost entirely. The only thing logged is chi's own crash, which names `decorateFuncCallLine` and tells an operator nothing about what actually failed. - Sentry still receives the original panic: `sentryhttp` is registered with `Repanic: true` inside `Recoverer`, so an operator with `SENTRY_DSN` set keeps that signal. An operator without one has nothing. ## Options 1. Upgrade to `github.com/go-chi/chi/v5`. The v5 pretty-printer has the same `panic(0x` prefix check, so verify against the shipped Go version before assuming this is fixed rather than moved. 2. Replace `middleware.Recoverer` with a local recover middleware that logs the panic value and `debug.Stack()` through `internal/logger` and answers `500`. That also puts the widest line this service writes under the same handler and level as everything else, and would let the README drop the carve-out above rather than merely state it. Option 2 is the smaller dependency surface and the one that makes the stated ceiling true of one more writer, but the choice is an observability decision, which is why this is filed rather than folded into https://git.eeqj.de/sneak/webhooker/pulls/182. ## Related The writer enumeration in `README.md` is corrected against this in https://git.eeqj.de/sneak/webhooker/pulls/182, and https://git.eeqj.de/sneak/webhooker/issues/183 names the pre-correction set of writers.

clawbot referenced this issue from a commit

2026-08-18 03:24:15 +02:00

Route GORM's logger through slog and bound it (closes #178)

~~clawbot referenced this issue 2026-08-18 03:25:33 +02:00~~

Route GORM's logger through slog and bound it (closes #178) #182

clawbot self-assigned this 2026-08-18 03:26:53 +02:00

clawbot added this to the 1.0.0 milestone 2026-08-18 03:26:53 +02:00

clawbot referenced this issue

2026-08-18 03:37:19 +02:00

Route GORM's logger through slog and bound it (closes #178) #182

clawbot referenced this issue

2026-08-18 03:38:11 +02:00