From 1561254dc2b91e2dddae6a4033c1efa5cb8e48a3 Mon Sep 17 00:00:00 2001 From: Nayden Petrov Date: Wed, 14 Oct 2026 14:17:52 +0300 Subject: [PATCH 1/2] logger: fix HandlePanic to actually recover deferred panics HandlePanic delegated recover() to an inner helper (recoverPanic). Go only honours recover() when it is called directly by the function that was deferred, not by any function that function calls. Because callers use "defer logger.HandlePanic(tag)", recover() ran one frame too deep, always returned nil, and the panic escaped unhandled -- so the structured "Panic: ..." log and os.Exit(2) never ran and the process crashed with a raw runtime trace instead. Call recover() directly inside both logger.HandlePanic and asyncLogger.HandlePanic, and move only the formatting into a logPanic helper that takes the already-recovered value. Add an osExit seam and internal tests covering both loggers; the tests fail against the previous delegated implementation. This regression dates back to the async logger refactor (f8bb60f0, 2016). --- logger/async.go | 6 +- logger/handle_panic_internal_test.go | 82 ++++++++++++++++++++++++++++ logger/logger.go | 40 ++++++++------ 3 files changed, 107 insertions(+), 21 deletions(-) create mode 100644 logger/handle_panic_internal_test.go diff --git a/logger/async.go b/logger/async.go index 27e8c4ad..efc4d6ba 100644 --- a/logger/async.go +++ b/logger/async.go @@ -4,7 +4,6 @@ import ( "errors" "io" "log" - "os" "time" ) @@ -121,9 +120,10 @@ func (l *asyncLogger) ErrorWithDetails(tag, msg string, args ...interface{}) { } func (l *asyncLogger) HandlePanic(tag string) { - if l.log.recoverPanic(tag) { + if e := recover(); e != nil { + l.log.logPanic(tag, e) l.FlushTimeout(time.Second * 30) //nolint:errcheck - os.Exit(2) + osExit(2) } } diff --git a/logger/handle_panic_internal_test.go b/logger/handle_panic_internal_test.go new file mode 100644 index 00000000..1c43b5a1 --- /dev/null +++ b/logger/handle_panic_internal_test.go @@ -0,0 +1,82 @@ +package logger + +import ( + "bytes" + "io" + "sync" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" +) + +type lockedBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (w *lockedBuffer) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + return w.buf.Write(p) +} + +func (w *lockedBuffer) String() string { + w.mu.Lock() + defer w.mu.Unlock() + return w.buf.String() +} + +var _ = Describe("HandlePanic", func() { + var ( + out *lockedBuffer + origExit func(int) + exitCode int + exited bool + ) + + BeforeEach(func() { + out = &lockedBuffer{} + origExit = osExit + exited = false + exitCode = 0 + osExit = func(code int) { + exited = true + exitCode = code + } + }) + + AfterEach(func() { + osExit = origExit + }) + + // deferHandlePanic mimics a real caller: HandlePanic is the deferred + // function. recover() only works when called directly in the deferred + // function, so if the panic is honoured this returns normally; otherwise + // the panic escapes and the matcher below observes it. + deferHandlePanic := func(l Logger) { + defer l.HandlePanic("test-tag") + panic("boom") + } + + DescribeTable("recovers a deferred panic, logs it, and exits 2", + func(newLogger func(LogLevel, io.Writer) Logger) { + l := newLogger(LevelError, out) + + Expect(func() { deferHandlePanic(l) }).ToNot(Panic()) + + Expect(exited).To(BeTrue()) + Expect(exitCode).To(Equal(2)) + Expect(out.String()).To(ContainSubstring("Panic: boom")) + }, + Entry("sync logger", NewWriterLogger), + Entry("async logger", NewAsyncWriterLogger), + ) + + It("does nothing when the deferred function sees no panic", func() { + l := NewWriterLogger(LevelError, out) + func() { defer l.HandlePanic("test-tag") }() + + Expect(exited).To(BeFalse()) + Expect(out.String()).To(BeEmpty()) + }) +}) diff --git a/logger/logger.go b/logger/logger.go index 32cff824..b1fafc89 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -165,28 +165,32 @@ func (l *logger) ErrorWithDetails(tag, msg string, args ...interface{}) { l.Error(tag, msg, args...) } -func (l *logger) recoverPanic(tag string) (didPanic bool) { - if e := recover(); e != nil { - var msg string - switch obj := e.(type) { - case string: - msg = obj - case fmt.Stringer: - msg = obj.String() - case error: - msg = obj.Error() - default: - msg = fmt.Sprintf("%#v", obj) - } - l.ErrorWithDetails(tag, "Panic: %s", msg, debug.Stack()) - return true +// osExit is a seam so tests can assert HandlePanic's exit behaviour without +// terminating the test process. +var osExit = os.Exit + +func (l *logger) logPanic(tag string, e interface{}) { + var msg string + switch obj := e.(type) { + case string: + msg = obj + case fmt.Stringer: + msg = obj.String() + case error: + msg = obj.Error() + default: + msg = fmt.Sprintf("%#v", obj) } - return false + l.ErrorWithDetails(tag, "Panic: %s", msg, debug.Stack()) } +// HandlePanic must call recover() directly: Go only honours recover() in the +// function that was deferred, not in any function it calls. Delegating to a +// helper that calls recover() leaves the panic unhandled. func (l *logger) HandlePanic(tag string) { - if l.recoverPanic(tag) { - os.Exit(2) + if e := recover(); e != nil { + l.logPanic(tag, e) + osExit(2) } } From e73a51f72868a4440b607412c17804a1ae9cc5dc Mon Sep 17 00:00:00 2001 From: Nayden Petrov Date: Tue, 20 Oct 2026 08:09:00 +0300 Subject: [PATCH 2/2] logger: test HandlePanic via gexec subprocess instead of an os.Exit seam Replace the package-level osExit seam with a real subprocess test: HandlePanic now calls os.Exit(2) directly, and a small fixture binary (handle_panic_fixture) is compiled and run via gexec to assert the real exit code and panic log on stderr, for both the sync and async loggers. This matches the existing gexec pattern in the main/ suite and keeps test-only scaffolding out of production code. --- logger/async.go | 3 +- logger/handle_panic_fixture/main.go | 30 ++++++++++ logger/handle_panic_internal_test.go | 82 ---------------------------- logger/handle_panic_test.go | 44 +++++++++++++++ logger/logger.go | 6 +- logger/logger_suite_test.go | 15 +++++ 6 files changed, 92 insertions(+), 88 deletions(-) create mode 100644 logger/handle_panic_fixture/main.go delete mode 100644 logger/handle_panic_internal_test.go create mode 100644 logger/handle_panic_test.go diff --git a/logger/async.go b/logger/async.go index efc4d6ba..737f8ecf 100644 --- a/logger/async.go +++ b/logger/async.go @@ -4,6 +4,7 @@ import ( "errors" "io" "log" + "os" "time" ) @@ -123,7 +124,7 @@ func (l *asyncLogger) HandlePanic(tag string) { if e := recover(); e != nil { l.log.logPanic(tag, e) l.FlushTimeout(time.Second * 30) //nolint:errcheck - osExit(2) + os.Exit(2) } } diff --git a/logger/handle_panic_fixture/main.go b/logger/handle_panic_fixture/main.go new file mode 100644 index 00000000..ee6bead4 --- /dev/null +++ b/logger/handle_panic_fixture/main.go @@ -0,0 +1,30 @@ +package main + +import ( + "flag" + "os" + + "github.com/cloudfoundry/bosh-utils/logger" +) + +func main() { + var ( + async = flag.Bool("async", false, "use the async writer logger") + noPanic = flag.Bool("no-panic", false, "defer HandlePanic without panicking") + ) + flag.Parse() + + newLogger := logger.NewWriterLogger + if *async { + newLogger = logger.NewAsyncWriterLogger + } + l := newLogger(logger.LevelError, os.Stderr) + + defer l.HandlePanic("test-tag") + + if *noPanic { + return + } + + panic("boom") +} diff --git a/logger/handle_panic_internal_test.go b/logger/handle_panic_internal_test.go deleted file mode 100644 index 1c43b5a1..00000000 --- a/logger/handle_panic_internal_test.go +++ /dev/null @@ -1,82 +0,0 @@ -package logger - -import ( - "bytes" - "io" - "sync" - - . "github.com/onsi/ginkgo/v2" - . "github.com/onsi/gomega" -) - -type lockedBuffer struct { - mu sync.Mutex - buf bytes.Buffer -} - -func (w *lockedBuffer) Write(p []byte) (int, error) { - w.mu.Lock() - defer w.mu.Unlock() - return w.buf.Write(p) -} - -func (w *lockedBuffer) String() string { - w.mu.Lock() - defer w.mu.Unlock() - return w.buf.String() -} - -var _ = Describe("HandlePanic", func() { - var ( - out *lockedBuffer - origExit func(int) - exitCode int - exited bool - ) - - BeforeEach(func() { - out = &lockedBuffer{} - origExit = osExit - exited = false - exitCode = 0 - osExit = func(code int) { - exited = true - exitCode = code - } - }) - - AfterEach(func() { - osExit = origExit - }) - - // deferHandlePanic mimics a real caller: HandlePanic is the deferred - // function. recover() only works when called directly in the deferred - // function, so if the panic is honoured this returns normally; otherwise - // the panic escapes and the matcher below observes it. - deferHandlePanic := func(l Logger) { - defer l.HandlePanic("test-tag") - panic("boom") - } - - DescribeTable("recovers a deferred panic, logs it, and exits 2", - func(newLogger func(LogLevel, io.Writer) Logger) { - l := newLogger(LevelError, out) - - Expect(func() { deferHandlePanic(l) }).ToNot(Panic()) - - Expect(exited).To(BeTrue()) - Expect(exitCode).To(Equal(2)) - Expect(out.String()).To(ContainSubstring("Panic: boom")) - }, - Entry("sync logger", NewWriterLogger), - Entry("async logger", NewAsyncWriterLogger), - ) - - It("does nothing when the deferred function sees no panic", func() { - l := NewWriterLogger(LevelError, out) - func() { defer l.HandlePanic("test-tag") }() - - Expect(exited).To(BeFalse()) - Expect(out.String()).To(BeEmpty()) - }) -}) diff --git a/logger/handle_panic_test.go b/logger/handle_panic_test.go new file mode 100644 index 00000000..02d891a6 --- /dev/null +++ b/logger/handle_panic_test.go @@ -0,0 +1,44 @@ +package logger_test + +import ( + "os/exec" + "time" + + . "github.com/onsi/ginkgo/v2" + . "github.com/onsi/gomega" + "github.com/onsi/gomega/gbytes" + "github.com/onsi/gomega/gexec" +) + +var _ = Describe("HandlePanic", func() { + run := func(args ...string) *gexec.Session { + session, err := gexec.Start(exec.Command(handlePanicFixtureBinPath, args...), GinkgoWriter, GinkgoWriter) + Expect(err).NotTo(HaveOccurred()) + return session + } + + DescribeTable("recovers a deferred panic, logs it, and exits 2", + func(extraArgs ...string) { + session := run(extraArgs...) + + Eventually(session).WithTimeout(10 * time.Second).Should(gexec.Exit(2)) + // "ERROR - Panic: ..." is only produced by our recovery path; an + // unrecovered panic would exit 2 too but print the runtime's raw + // lowercase "panic: ..." trace instead. + Eventually(session.Err).Should(gbytes.Say("ERROR - Panic: boom")) + }, + Entry("sync logger"), + Entry("async logger", "-async"), + ) + + DescribeTable("does not exit when the deferred function sees no panic", + func(extraArgs ...string) { + session := run(extraArgs...) + + Eventually(session).WithTimeout(10 * time.Second).Should(gexec.Exit(0)) + Expect(string(session.Err.Contents())).NotTo(ContainSubstring("Panic:")) + }, + Entry("sync logger", "-no-panic"), + Entry("async logger", "-async", "-no-panic"), + ) +}) diff --git a/logger/logger.go b/logger/logger.go index b1fafc89..24de0feb 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -165,10 +165,6 @@ func (l *logger) ErrorWithDetails(tag, msg string, args ...interface{}) { l.Error(tag, msg, args...) } -// osExit is a seam so tests can assert HandlePanic's exit behaviour without -// terminating the test process. -var osExit = os.Exit - func (l *logger) logPanic(tag string, e interface{}) { var msg string switch obj := e.(type) { @@ -190,7 +186,7 @@ func (l *logger) logPanic(tag string, e interface{}) { func (l *logger) HandlePanic(tag string) { if e := recover(); e != nil { l.logPanic(tag, e) - osExit(2) + os.Exit(2) } } diff --git a/logger/logger_suite_test.go b/logger/logger_suite_test.go index d041fa0c..2236957f 100644 --- a/logger/logger_suite_test.go +++ b/logger/logger_suite_test.go @@ -3,6 +3,7 @@ package logger_test import ( . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" + "github.com/onsi/gomega/gexec" "testing" ) @@ -11,3 +12,17 @@ func TestLogger(t *testing.T) { RegisterFailHandler(Fail) RunSpecs(t, "Logger Suite") } + +var handlePanicFixtureBinPath string + +var _ = SynchronizedBeforeSuite(func() []byte { + binPath, err := gexec.Build("github.com/cloudfoundry/bosh-utils/logger/handle_panic_fixture") + Expect(err).NotTo(HaveOccurred()) + return []byte(binPath) +}, func(data []byte) { + handlePanicFixtureBinPath = string(data) +}) + +var _ = SynchronizedAfterSuite(func() {}, func() { + gexec.CleanupBuildArtifacts() +})