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