CBG-4988 log panics in http (#7876)

Co-authored-by: Copilot <[email protected]>

Author: torcolvin

base/devmode.go

@@ -25,6 +25,15 @@ func IsDevMode() bool {
 // The SG test harness will ensure AssertionFailCount is zero at the end of tests, even without devmode enabled.
 // Note: Callers MUST ensure code is safe to continue executing after the Assert (e.g. by returning an error) and MUST NOT be used like a panic that will halt.
 func AssertfCtx(ctx context.Context, format string, args ...any) {
+
 	SyncGatewayStats.GlobalStats.ResourceUtilization.AssertionFailCount.Add(1)
 	assertLogFn(ctx, AssertionFailedPrefix+format, args...)
 }
+
+// PanicRecoveryfCtx logs a warning message. This function is suitable for recovering from a panic in a location where
+// it is expected to continue operation, like HTTP handlers.
+// When compiled with the `cb_sg_devmode` build tag this function panics to fail the test harness for better dev-time visibility.
+// In all cases, the WarnCount stat is incremented.
+func PanicRecoveryfCtx(ctx context.Context, format string, args ...any) {
+	panicRecoveryLogFn(ctx, format, args...)
+}

base/devmode_off.go

@@ -14,3 +14,5 @@ package base
 const cbSGDevModeBuildTagSet = false
 
 var assertLogFn logFn = ErrorfCtx
+
+var panicRecoveryLogFn logFn = WarnfCtx

base/devmode_on.go

@@ -11,6 +11,14 @@
 
 package base
 
+import "context"
+
 const cbSGDevModeBuildTagSet = true
 
 var assertLogFn logFn = PanicfCtx
+
+func panicRecoveryLogFn(ctx context.Context, format string, args ...any) {
+	// add a warn count since the devmode=off path also adds a warn count
+	SyncGatewayStats.GlobalStats.ResourceUtilization.WarnCount.Add(1)
+	PanicfCtx(ctx, format, args...)
+}

db/import_listener.go

@@ -135,7 +135,7 @@ func (il *importListener) ProcessFeedEvent(event sgbucket.FeedEvent) bool {
 	docID := string(event.Key)
 	defer func() {
 		if r := recover(); r != nil {
-			base.WarnfCtx(ctx, "[%s] Unexpected panic importing document %s - skipping import: \n %s", r, base.UD(docID), debug.Stack())
+			base.PanicRecoveryfCtx(ctx, "[%s] Unexpected panic importing document %s - skipping import: \n %s", r, base.UD(docID), debug.Stack())
 			if il.importStats != nil {
 				il.importStats.ImportErrorCount.Add(1)
 			}

db/import_listener_test.go

@@ -25,10 +25,20 @@ func TestImportFeedEventRecover(t *testing.T) {
 		},
 	}
 	startWarnCount := base.SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value()
+
 	// assert false to indicate that this checkpoint will not be incremented
-	require.False(t, listener.ProcessFeedEvent(sgbucket.FeedEvent{
-		Key:    []byte("example-doc"),
-		Opcode: sgbucket.FeedOpMutation,
-	}))
+	if base.IsDevMode() {
+		require.Panics(t, func() {
+			listener.ProcessFeedEvent(sgbucket.FeedEvent{
+				Key:    []byte("example-doc"),
+				Opcode: sgbucket.FeedOpMutation,
+			})
+		})
+	} else {
+		require.False(t, listener.ProcessFeedEvent(sgbucket.FeedEvent{
+			Key:    []byte("example-doc"),
+			Opcode: sgbucket.FeedOpMutation,
+		}))
+	}
 	require.Equal(t, startWarnCount+1, base.SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value())
 }

rest/handler.go

@@ -22,6 +22,7 @@ import (
 	"net/http"
 	"net/url"
 	"regexp"
+	"runtime/debug"
 	"slices"
 	"strconv"
 	"strings"
@@ -127,8 +128,23 @@ type handlerMethod func(*handler) error
 // makeHandlerWithOptions creates an http.Handler that will run a handler with the given method handlerOptions
 func makeHandlerWithOptions(server *ServerContext, privs handlerPrivs, accessPermissions []Permission, responsePermissions []Permission, method handlerMethod, options handlerOptions) http.Handler {
 	return http.HandlerFunc(func(r http.ResponseWriter, rq *http.Request) {
+		ctx := rq.Context()
+		var serialNumber string
+		defer func() {
+			// ErrAbortHandler is a sentinel panic used by http.ServeHTTP and should not be logged.
+			if err := recover(); err != nil && err != http.ErrAbortHandler {
+				// use leading spaces to match typical request logging
+				base.PanicRecoveryfCtx(ctx, "HTTP %s:     --> panicked:\n%s", serialNumber, debug.Stack())
+				// repanic here so that http.ServeHTTP can catch the panic and perform usual close connection behavior
+				panic(err)
+			}
+		}()
 		serverType := getCtxServerType(rq.Context())
 		h := newHandler(server, privs, serverType, r, rq, options)
+
+		// re-assign ctx and serial number for panic handler
+		ctx = h.ctx()
+		serialNumber = h.formatSerialNumber()
 		err := h.invoke(method, accessPermissions, responsePermissions)
 		h.writeError(err)
 		if !options.skipLogDuration {

rest/handler_test.go

@@ -12,11 +12,13 @@ package rest
 
 import (
 	"fmt"
+	"io"
 	"net/http"
 	"net/http/httptest"
 	"testing"
 
 	"github.com/couchbase/sync_gateway/base"
+	"github.com/gorilla/mux"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
@@ -222,3 +224,46 @@ func TestShouldCheckAdminRBAC(t *testing.T) {
 		})
 	}
 }
+
+func TestHandlerRecoverLog(t *testing.T) {
+	base.SetUpTestLogging(t, base.LevelTrace, base.KeyAll)
+	testCases := []struct {
+		name       string
+		panicArg   any
+		shouldWarn bool
+	}{
+		{name: "string panic", panicArg: "test panic", shouldWarn: true},
+		{name: "error panic", panicArg: fmt.Errorf("test error panic"), shouldWarn: true},
+		{name: "ErrAbortHandler", panicArg: http.ErrAbortHandler, shouldWarn: false},
+	}
+	for _, tc := range testCases {
+		t.Run(tc.name, func(t *testing.T) {
+			config := BootstrapStartupConfigForTest(t) // share config between both servers in test to share a groupID
+			sc, closeFn := StartServerWithConfig(t, &config)
+			defer closeFn()
+
+			ctx := base.TestCtx(t)
+			require.NoError(t, sc.WaitForRESTAPIs(ctx))
+			startWarnCount := base.SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value()
+			handler := makeHandlerWithOptions(sc, regularPrivs, nil, nil, func(_ *handler) error {
+				panic(tc.panicArg)
+			}, handlerOptions{})
+			r := mux.NewRouter()
+			r.Use(withServerType(publicServer))
+			r.Handle("/", handler)
+			server := httptest.NewServer(r)
+			defer server.Close()
+
+			client := server.Client()
+			resp, err := client.Get(server.URL)
+			if tc.shouldWarn {
+				require.ErrorIs(t, err, io.EOF)
+				require.Equal(t, startWarnCount+1, base.SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value())
+			} else {
+				require.NoError(t, err)
+				require.NoError(t, resp.Body.Close())
+				require.Equal(t, startWarnCount, base.SyncGatewayStats.GlobalStats.ResourceUtilizationStats().WarnCount.Value())
+			}
+		})
+	}
+}