Backend: Report recovered panics via SystemLog, not the DB logger #5637

This commit is contained in:
Michael Mayer 2026-06-03 08:18:05 +00:00
parent 2d3aa02dac
commit 188aba723f
2 changed files with 51 additions and 44 deletions

View file

@ -2,17 +2,24 @@ package event
import "runtime/debug"
// LogPanic logs a recovered panic value together with the current stack trace,
// so that crashes which would otherwise terminate the process without any output
// can be diagnosed from the regular log. It does not stop the process; the caller
// decides whether to exit.
// LogPanic reports a recovered panic value together with the current stack
// trace so that crashes which would otherwise terminate the process without any
// output can be diagnosed. It does not stop the process; the caller decides
// whether to exit.
//
// It deliberately reports through SystemError (the system log) rather than the
// default Log: the default logger is persisted to the database via the event
// hub (the errors and audit_logs tables), so reporting a panic through it could
// trigger a follow-up error or panic when the database is itself the cause of
// the crash or is unavailable. The system log writes to the console only.
func LogPanic(r any) {
if r == nil || Log == nil {
if r == nil {
return
}
Log.Errorf("panic: %v", r)
Log.Errorf("stack trace:\n%s", debug.Stack())
// SystemError already prefixes messages with "system: ", so the wording
// avoids a leading "panic:" that would read as "system: panic:".
SystemError([]string{"panic", "%v", "%s"}, r, debug.Stack())
}
// Recover recovers from a panic in the calling goroutine, if any, and logs it

View file

@ -8,39 +8,45 @@ import (
"github.com/stretchr/testify/assert"
)
// newTestLogger returns a logrus logger writing to buf at error level.
func newTestLogger(buf *bytes.Buffer) *logrus.Logger {
logger := logrus.New()
logger.SetOutput(buf)
logger.SetLevel(logrus.ErrorLevel)
return logger
}
func TestLogPanic(t *testing.T) {
t.Run("Success", func(t *testing.T) {
var buf bytes.Buffer
logger := logrus.New()
logger.SetOutput(&buf)
logger.SetLevel(logrus.ErrorLevel)
orig := Log
Log = logger
t.Cleanup(func() { Log = orig })
var sysBuf, logBuf bytes.Buffer
origSys, origLog := SystemLog, Log
SystemLog = newTestLogger(&sysBuf)
Log = newTestLogger(&logBuf)
t.Cleanup(func() { SystemLog = origSys; Log = origLog })
LogPanic("boom")
out := buf.String()
assert.Contains(t, out, "panic: boom")
assert.Contains(t, out, "stack trace")
out := sysBuf.String()
assert.Contains(t, out, "panic")
assert.Contains(t, out, "boom")
assert.Contains(t, out, "goroutine")
// Must not be routed through the default, database-persisted logger.
assert.Empty(t, logBuf.String())
})
t.Run("Nil", func(t *testing.T) {
var buf bytes.Buffer
logger := logrus.New()
logger.SetOutput(&buf)
orig := Log
Log = logger
t.Cleanup(func() { Log = orig })
orig := SystemLog
SystemLog = newTestLogger(&buf)
t.Cleanup(func() { SystemLog = orig })
LogPanic(nil)
assert.Empty(t, buf.String())
})
t.Run("NoLogger", func(t *testing.T) {
orig := Log
Log = nil
t.Cleanup(func() { Log = orig })
orig := SystemLog
SystemLog = nil
t.Cleanup(func() { SystemLog = orig })
assert.NotPanics(t, func() { LogPanic("boom") })
})
@ -49,12 +55,9 @@ func TestLogPanic(t *testing.T) {
func TestRecover(t *testing.T) {
t.Run("Panic", func(t *testing.T) {
var buf bytes.Buffer
logger := logrus.New()
logger.SetOutput(&buf)
logger.SetLevel(logrus.ErrorLevel)
orig := Log
Log = logger
t.Cleanup(func() { Log = orig })
orig := SystemLog
SystemLog = newTestLogger(&buf)
t.Cleanup(func() { SystemLog = orig })
func() {
defer Recover()
@ -62,16 +65,15 @@ func TestRecover(t *testing.T) {
}()
out := buf.String()
assert.Contains(t, out, "panic: kaboom")
assert.Contains(t, out, "panic")
assert.Contains(t, out, "kaboom")
assert.Contains(t, out, "goroutine")
})
t.Run("NoPanic", func(t *testing.T) {
var buf bytes.Buffer
logger := logrus.New()
logger.SetOutput(&buf)
orig := Log
Log = logger
t.Cleanup(func() { Log = orig })
orig := SystemLog
SystemLog = newTestLogger(&buf)
t.Cleanup(func() { SystemLog = orig })
func() { defer Recover() }()
@ -82,12 +84,9 @@ func TestRecover(t *testing.T) {
func TestSafe(t *testing.T) {
t.Run("RecoversAndContinues", func(t *testing.T) {
var buf bytes.Buffer
logger := logrus.New()
logger.SetOutput(&buf)
logger.SetLevel(logrus.ErrorLevel)
orig := Log
Log = logger
t.Cleanup(func() { Log = orig })
orig := SystemLog
SystemLog = newTestLogger(&buf)
t.Cleanup(func() { SystemLog = orig })
ran := 0
assert.NotPanics(t, func() {
@ -96,7 +95,8 @@ func TestSafe(t *testing.T) {
})
assert.Equal(t, 1, ran)
assert.Contains(t, buf.String(), "panic: boom")
assert.Contains(t, buf.String(), "panic")
assert.Contains(t, buf.String(), "boom")
})
t.Run("Success", func(t *testing.T) {
called := false