From c290397cdac2d04e421b638c88fd2e8f907d9f6d Mon Sep 17 00:00:00 2001 From: Ben Younes Date: Mon, 10 Aug 2026 08:18:17 +0200 Subject: [PATCH] caddyhttp: log recovered handler panics at ERROR level (#7924) Co-authored-by: Zen Dodd Signed-off-by: Zen Dodd --- caddytest/integration/panic_test.go | 218 ++++++++++++++++++++++++++++ modules/caddyhttp/app.go | 44 +++++- modules/caddyhttp/app_test.go | 65 +++++++++ 3 files changed, 321 insertions(+), 6 deletions(-) create mode 100644 caddytest/integration/panic_test.go create mode 100644 modules/caddyhttp/app_test.go diff --git a/caddytest/integration/panic_test.go b/caddytest/integration/panic_test.go new file mode 100644 index 000000000..2c4cf626d --- /dev/null +++ b/caddytest/integration/panic_test.go @@ -0,0 +1,218 @@ +// Copyright 2015 Matthew Holt and The Caddy Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package integration + +import ( + "bufio" + "bytes" + "encoding/json" + "io" + "net/http" + "strings" + "sync" + "testing" + "time" + + "github.com/caddyserver/caddy/v2" + "github.com/caddyserver/caddy/v2/modules/caddyhttp" + + // register the standard modules (http app, file log writer, etc.) + _ "github.com/caddyserver/caddy/v2/modules/standard" +) + +const ( + // panicTestHandlerID is the module ID of the test-only handler that panics. + panicTestHandlerID = "http.handlers.panic_test" + // panicLogPrefix is the prefix Go's net/http server writes to + // http.Server.ErrorLog when it recovers a handler panic. It mirrors the + // unexported production constant caddyhttp.stdlibLogPrefixPanic. + panicLogPrefix = "http: panic serving" + // panicErrorLevel is the zap level string the JSON encoder emits for + // entries logged at error level. + panicErrorLevel = "error" + // panicListenAddr is the HTTP listener for the panic route. + panicListenAddr = ":9080" + // panicRequestURL hits the panic route. + panicRequestURL = "http://localhost:9080/" + // panicLogPollInterval is how often the test re-reads the log file while + // waiting for the panic entry to be flushed to disk. + panicLogPollInterval = 50 * time.Millisecond + // panicLogPollTimeout bounds how long the test waits for the entry. + panicLogPollTimeout = 5 * time.Second +) + +// panicHandler is a test-only HTTP handler module that panics in ServeHTTP +// with a non-ErrAbortHandler value, so Go's net/http server recovers it and +// writes an "http: panic serving" line to http.Server.ErrorLog. +type panicHandler struct{} + +type panicLogWriter struct{} + +type panicLogBuffer struct { + sync.Mutex + bytes.Buffer +} + +var panicLogs panicLogBuffer + +func (panicHandler) CaddyModule() caddy.ModuleInfo { + return caddy.ModuleInfo{ + ID: panicTestHandlerID, + New: func() caddy.Module { return new(panicHandler) }, + } +} + +func (panicHandler) ServeHTTP(http.ResponseWriter, *http.Request, caddyhttp.Handler) error { + panic("boom from panic_test handler") +} + +func (panicLogWriter) CaddyModule() caddy.ModuleInfo { + return caddy.ModuleInfo{ + ID: "caddy.logging.writers.panic_test", + New: func() caddy.Module { return new(panicLogWriter) }, + } +} + +func (panicLogWriter) String() string { + return "panic test log" +} + +func (panicLogWriter) WriterKey() string { + return "panic_test" +} + +func (panicLogWriter) OpenWriter() (io.WriteCloser, error) { + return &panicLogs, nil +} + +func (b *panicLogBuffer) Write(p []byte) (int, error) { + b.Lock() + defer b.Unlock() + return b.Buffer.Write(p) +} + +func (*panicLogBuffer) Close() error { + return nil +} + +func (b *panicLogBuffer) reset() { + b.Lock() + defer b.Unlock() + b.Buffer.Reset() +} + +func (b *panicLogBuffer) snapshot() []byte { + b.Lock() + defer b.Unlock() + return bytes.Clone(b.Buffer.Bytes()) +} + +func init() { + caddy.RegisterModule(panicHandler{}) + caddy.RegisterModule(panicLogWriter{}) +} + +// TestHandlerPanicLogsAtError boots a real Caddy HTTP server whose route panics +// while serving a request, and asserts that the recovered panic surfaces in +// Caddy's structured logs at ERROR level (so it stays visible at the default +// log level). Booting exercises the App.Start() server-boot wiring that routes +// http.Server.ErrorLog through Caddy's structured logger. Regression test for +// https://github.com/caddyserver/caddy/issues/7923. +func TestHandlerPanicLogsAtError(t *testing.T) { + panicLogs.reset() + + // Boot a real Caddy instance. caddy.Run provisions and calls App.Start + // synchronously, so the panic-log wiring runs before we send the request. + config := `{ + "admin": {"disabled": true}, + "logging": { + "logs": { + "panic_test": { + "writer": {"output": "panic_test"}, + "encoder": {"format": "json"}, + "level": "DEBUG", + "include": ["http"] + } + } + }, + "apps": { + "http": { + "grace_period": 1, + "servers": { + "srv0": { + "listen": ["` + panicListenAddr + `"], + "automatic_https": {"disable": true}, + "routes": [ + {"handle": [{"handler": "panic_test"}]} + ] + } + } + } + } + }` + if err := caddy.Load([]byte(config), true); err != nil { + t.Fatalf("failed to load caddy config: %v", err) + } + t.Cleanup(func() { + if err := caddy.Stop(); err != nil { + t.Errorf("failed to stop caddy: %v", err) + } + }) + + // The panic aborts the connection, so the client sees an error; that's + // expected. We only care that the server logged the panic. + resp, err := http.Get(panicRequestURL) + if err == nil { + resp.Body.Close() + } + + if !waitForPanicLog(t) { + t.Fatalf("did not find an error-level %q entry", panicLogPrefix) + } +} + +// waitForPanicLog polls the log output until it contains a JSON entry logged +// at error level whose message begins with the net/http panic prefix, or the +// timeout elapses. +func waitForPanicLog(t *testing.T) bool { + t.Helper() + deadline := time.Now().Add(panicLogPollTimeout) + for time.Now().Before(deadline) { + if scanForPanicEntry(t) { + return true + } + time.Sleep(panicLogPollInterval) + } + return false +} + +func scanForPanicEntry(t *testing.T) bool { + t.Helper() + + scanner := bufio.NewScanner(bytes.NewReader(panicLogs.snapshot())) + for scanner.Scan() { + var entry struct { + Level string `json:"level"` + Msg string `json:"msg"` + } + if err := json.Unmarshal(scanner.Bytes(), &entry); err != nil { + continue + } + if entry.Level == panicErrorLevel && strings.HasPrefix(entry.Msg, panicLogPrefix) { + return true + } + } + return false +} diff --git a/modules/caddyhttp/app.go b/modules/caddyhttp/app.go index d9d9b9f84..096619498 100644 --- a/modules/caddyhttp/app.go +++ b/modules/caddyhttp/app.go @@ -20,9 +20,11 @@ import ( "crypto/tls" "errors" "fmt" + "log" "net" "net/http" "strconv" + "strings" "sync" "time" @@ -463,11 +465,9 @@ func removeTLSALPN(srv *Server, target string) { // Start runs the app. It finishes automatic HTTPS if enabled, // including management of certificates. func (app *App) Start() error { - // get a logger compatible with http.Server - serverLogger, err := zap.NewStdLogAt(app.logger.Named("stdlib"), zap.DebugLevel) - if err != nil { - return fmt.Errorf("failed to set up server logger: %v", err) - } + // get a logger compatible with http.Server; recovered handler panics are + // routed to ERROR so they remain visible at the default log level (#7923) + serverLogger := serverErrorLogger(app.logger.Named("stdlib")) for srvName, srv := range app.Servers { srv.server = &http.Server{ @@ -662,7 +662,7 @@ func (app *App) Start() error { // finish automatic HTTPS by finally beginning // certificate management - err = app.automaticHTTPSPhase2() + err := app.automaticHTTPSPhase2() if err != nil { return fmt.Errorf("finalizing automatic HTTPS: %v", err) } @@ -670,6 +670,38 @@ func (app *App) Start() error { return nil } +// stdlibLogPrefixPanic is the prefix Go's net/http server uses when it writes a +// recovered handler panic (and its stack trace) to http.Server.ErrorLog. +// See the deferred recover in net/http.(*conn).serve. +const stdlibLogPrefixPanic = "http: panic serving" + +// serverErrorLogger returns a *log.Logger suitable for http.Server.ErrorLog +// that forwards the standard library's server messages to Caddy's structured +// logger. Most of these messages are low-signal and logged at DEBUG, but +// recovered handler panics indicate a real server-side error, so they are +// logged at ERROR to stay visible at the default log level. +func serverErrorLogger(logger *zap.Logger) *log.Logger { + return log.New(stdlibLogRouter{logger: logger}, "", 0) +} + +// stdlibLogRouter is an io.Writer that routes standard library http.Server +// error-log messages to the appropriate level on the wrapped structured logger. +type stdlibLogRouter struct { + logger *zap.Logger +} + +func (w stdlibLogRouter) Write(p []byte) (int, error) { + // log.Logger always appends a trailing newline; trim it so the structured + // message doesn't carry a dangling blank line. + msg := strings.TrimSuffix(string(p), "\n") + if strings.HasPrefix(msg, stdlibLogPrefixPanic) { + w.logger.Error(msg) + } else { + w.logger.Debug(msg) + } + return len(p), nil +} + // Stop gracefully shuts down the HTTP server. func (app *App) Stop() error { ctx := context.Background() diff --git a/modules/caddyhttp/app_test.go b/modules/caddyhttp/app_test.go new file mode 100644 index 000000000..f97b4cca7 --- /dev/null +++ b/modules/caddyhttp/app_test.go @@ -0,0 +1,65 @@ +// Copyright 2015 Matthew Holt and The Caddy Authors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package caddyhttp + +import ( + "testing" + + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "go.uber.org/zap/zaptest/observer" +) + +// TestServerErrorLoggerLevels verifies that recovered net/http handler panics +// written to http.Server.ErrorLog surface at ERROR level (so they're visible +// at the default log level), while other standard library server messages stay +// at DEBUG. Regression test for #7923. +func TestServerErrorLoggerLevels(t *testing.T) { + for _, tc := range []struct { + name string + message string + wantLevel zapcore.Level + }{ + { + name: "recovered handler panic logs at error", + message: "http: panic serving 127.0.0.1:12345: boom\ngoroutine 1 [running]:\nmain.handler()", + wantLevel: zapcore.ErrorLevel, + }, + { + name: "other server message logs at debug", + message: "http: TLS handshake error from 127.0.0.1:12345: EOF", + wantLevel: zapcore.DebugLevel, + }, + } { + t.Run(tc.name, func(t *testing.T) { + core, logs := observer.New(zapcore.DebugLevel) + serverLogger := serverErrorLogger(zap.New(core)) + + serverLogger.Print(tc.message) + + entries := logs.All() + if len(entries) != 1 { + t.Fatalf("expected exactly 1 log entry, got %d", len(entries)) + } + got := entries[0] + if got.Level != tc.wantLevel { + t.Errorf("expected level %s, got %s", tc.wantLevel, got.Level) + } + if got.Message != tc.message { + t.Errorf("expected message %q, got %q", tc.message, got.Message) + } + }) + } +}