logger: fix HandlePanic to actually recover deferred panics

logger/async.go

@@ -121,7 +121,8 @@ 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)
 	}

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

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

logger/logger.go

@@ -165,27 +165,27 @@ 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
+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) {
+	if e := recover(); e != nil {
+		l.logPanic(tag, e)
 		os.Exit(2)
 	}
 }

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