caddyhttp: log recovered handler panics at ERROR level (#7924)

Co-authored-by: Zen Dodd <mail@steadytao.com>
Signed-off-by: Zen Dodd <mail@steadytao.com>

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
+}

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()

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)
+			}
+		})
+	}
+}