fix(router): ensure consistent request logs in error conditions (#1192)

router-tests/structured_logging_test.go

@@ -1,14 +1,50 @@
 package integration_test
 
 import (
+	"fmt"
+	"github.com/wundergraph/cosmo/router/core"
+	"github.com/wundergraph/cosmo/router/pkg/config"
 	"go.uber.org/zap"
 	"go.uber.org/zap/zapcore"
+	"math"
+	"net/http"
 	"testing"
 
 	"github.com/stretchr/testify/require"
 	"github.com/wundergraph/cosmo/router-tests/testenv"
 )
 
+// Interface guard
+var (
+	_ core.EnginePreOriginHandler = (*MyPanicModule)(nil)
+	_ core.Module                 = (*MyPanicModule)(nil)
+)
+
+type MyPanicModule struct{}
+
+func (m MyPanicModule) OnOriginRequest(req *http.Request, ctx core.RequestContext) (*http.Request, *http.Response) {
+
+	if req.Header.Get("panic-with-string") == "true" {
+		panic("implement me")
+	}
+
+	if req.Header.Get("panic-with-error") == "true" {
+		panic(fmt.Errorf("implement me"))
+	}
+
+	return req, nil
+}
+
+func (m MyPanicModule) Module() core.ModuleInfo {
+	return core.ModuleInfo{
+		ID:       "myPanicModule",
+		Priority: math.MaxInt32,
+		New: func() core.Module {
+			return &MyPanicModule{}
+		},
+	}
+}
+
 func TestRouterStartLogs(t *testing.T) {
 	t.Parallel()
 	testenv.Run(t, &testenv.Config{LogObservation: testenv.LogObservationConfig{
@@ -55,17 +91,202 @@ func TestQueryWithLogging(t *testing.T) {
 			"ip":     "[REDACTED]",
 		}
 		additionalExpectedKeys := []string{
-			"user_agent", "latency", "config_version", "request_id",
+			"user_agent", "latency", "config_version", "request_id", "pid", "hostname",
+		}
+		require.Len(t, requestContext, len(expectedValues)+len(additionalExpectedKeys))
+		for key, val := range expectedValues {
+			mapVal, exists := requestContext[key]
+			require.Truef(t, exists, "key '%s' not found", key)
+			require.Equalf(t, mapVal, val, "expected '%v', got '%v'", val, mapVal)
+		}
+		for _, key := range additionalExpectedKeys {
+			_, exists := requestContext[key]
+			require.Truef(t, exists, "key '%s' not found", key)
+		}
+	})
+}
+
+func TestQueryWithLoggingError(t *testing.T) {
+	t.Parallel()
+	testenv.Run(t, &testenv.Config{
+		NoRetryClient: true,
+		Subgraphs: testenv.SubgraphsConfig{
+			Employees: testenv.SubgraphConfig{
+				CloseOnStart: true,
+			},
+		},
+		RouterOptions: []core.Option{
+			core.WithEngineExecutionConfig(config.EngineExecutionConfiguration{
+				EnableSingleFlight:     true,
+				MaxConcurrentResolvers: 1,
+			}),
+			core.WithSubgraphRetryOptions(false, 0, 0, 0),
+		},
+		LogObservation: testenv.LogObservationConfig{
+			Enabled:  true,
+			LogLevel: zapcore.InfoLevel,
+		}}, func(t *testing.T, xEnv *testenv.Environment) {
+		res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{
+			Query: `{ employees { id } }`,
+		})
+		require.NoError(t, err)
+		require.JSONEq(t, `{"errors":[{"message":"Failed to fetch from Subgraph 'employees'."}],"data":{"employees":null}}`, res.Body)
+		logEntries := xEnv.Observer().All()
+		require.Len(t, logEntries, 13)
+		requestLog := xEnv.Observer().FilterMessage("/graphql")
+		require.Equal(t, requestLog.Len(), 1)
+		requestContext := requestLog.All()[0].ContextMap()
+		expectedValues := map[string]interface{}{
+			"status":     int64(200),
+			"method":     "POST",
+			"path":       "/graphql",
+			"query":      "", // http query is empty
+			"ip":         "[REDACTED]",
+			"user_agent": "Go-http-client/1.1",
+		}
+		additionalExpectedKeys := []string{
+			"latency", "config_version", "request_id", "pid", "hostname",
+		}
+		require.Len(t, requestContext, len(expectedValues)+len(additionalExpectedKeys))
+		for key, val := range expectedValues {
+			mapVal, exists := requestContext[key]
+			require.Truef(t, exists, "key '%s' not found", key)
+			require.Equalf(t, mapVal, val, "expected '%v', got '%v'", val, mapVal)
+		}
+		for _, key := range additionalExpectedKeys {
+			_, exists := requestContext[key]
+			require.Truef(t, exists, "key '%s' not found", key)
+		}
+	})
+}
+
+func TestQueryWithLoggingPanicWithString(t *testing.T) {
+	t.Parallel()
+	testenv.Run(t, &testenv.Config{
+		NoRetryClient: true,
+		RouterOptions: []core.Option{
+			core.WithCustomModules(&MyPanicModule{}),
+			core.WithHeaderRules(config.HeaderRules{
+				All: &config.GlobalHeaderRule{
+					Request: []*config.RequestHeaderRule{
+						{Named: "panic-with-string", Operation: config.HeaderRuleOperationPropagate},
+					},
+				},
+			}),
+			core.WithEngineExecutionConfig(config.EngineExecutionConfiguration{
+				EnableSingleFlight:     true,
+				MaxConcurrentResolvers: 1,
+			}),
+			core.WithSubgraphRetryOptions(false, 0, 0, 0),
+		},
+		LogObservation: testenv.LogObservationConfig{
+			Enabled:  true,
+			LogLevel: zapcore.InfoLevel,
+		}}, func(t *testing.T, xEnv *testenv.Environment) {
+		res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{
+			Header: map[string][]string{
+				"panic-with-string": {"true"},
+			},
+			Query: `{ employees { id } }`,
+		})
+		require.NoError(t, err)
+		require.Equal(t, "", res.Body)
+		logEntries := xEnv.Observer().All()
+		require.Len(t, logEntries, 13)
+		requestLog := xEnv.Observer().FilterMessage("[Recovery from panic]")
+		require.Equal(t, requestLog.Len(), 1)
+		requestContext := requestLog.All()[0].ContextMap()
+		expectedValues := map[string]interface{}{
+			"status":     int64(500),
+			"method":     "POST",
+			"path":       "/graphql",
+			"query":      "", // http query is empty
+			"ip":         "[REDACTED]",
+			"user_agent": "Go-http-client/1.1",
+			"error":      "implement me",
+		}
+		additionalExpectedKeys := []string{
+			"latency", "config_version", "request_id", "pid", "hostname",
 		}
+
 		require.Len(t, requestContext, len(expectedValues)+len(additionalExpectedKeys))
+
+		require.NotEmpty(t, logEntries[12].Stack)
+
+		for key, val := range expectedValues {
+			mapVal, exists := requestContext[key]
+			require.Truef(t, exists, "key '%s' not found", key)
+			require.Equalf(t, mapVal, val, "expected '%v', got '%v'", val, mapVal)
+		}
+
+		for _, key := range additionalExpectedKeys {
+			_, exists := requestContext[key]
+			require.Truef(t, exists, "key '%s' not found", key)
+		}
+	})
+}
+
+func TestQueryWithLoggingPanicWithError(t *testing.T) {
+	t.Parallel()
+	testenv.Run(t, &testenv.Config{
+		NoRetryClient: true,
+		RouterOptions: []core.Option{
+			core.WithCustomModules(&MyPanicModule{}),
+			core.WithHeaderRules(config.HeaderRules{
+				All: &config.GlobalHeaderRule{
+					Request: []*config.RequestHeaderRule{
+						{Named: "panic-with-error", Operation: config.HeaderRuleOperationPropagate},
+					},
+				},
+			}),
+			core.WithEngineExecutionConfig(config.EngineExecutionConfiguration{
+				EnableSingleFlight:     true,
+				MaxConcurrentResolvers: 1,
+			}),
+			core.WithSubgraphRetryOptions(false, 0, 0, 0),
+		},
+		LogObservation: testenv.LogObservationConfig{
+			Enabled:  true,
+			LogLevel: zapcore.InfoLevel,
+		}}, func(t *testing.T, xEnv *testenv.Environment) {
+		res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{
+			Header: map[string][]string{
+				"panic-with-error": {"true"},
+			},
+			Query: `{ employees { id } }`,
+		})
+		require.NoError(t, err)
+		require.Equal(t, "", res.Body)
+		logEntries := xEnv.Observer().All()
+		require.Len(t, logEntries, 13)
+		requestLog := xEnv.Observer().FilterMessage("[Recovery from panic]")
+		require.Equal(t, requestLog.Len(), 1)
+		requestContext := requestLog.All()[0].ContextMap()
+		expectedValues := map[string]interface{}{
+			"status":     int64(500),
+			"method":     "POST",
+			"path":       "/graphql",
+			"query":      "", // http query is empty
+			"ip":         "[REDACTED]",
+			"user_agent": "Go-http-client/1.1",
+			"error":      "implement me",
+		}
+		additionalExpectedKeys := []string{
+			"latency", "config_version", "request_id", "pid", "hostname",
+		}
+
+		require.Len(t, requestContext, len(expectedValues)+len(additionalExpectedKeys))
+
+		require.NotEmpty(t, logEntries[12].Stack)
+
 		for key, val := range expectedValues {
 			mapVal, exists := requestContext[key]
-			require.True(t, exists)
-			require.Equal(t, mapVal, val)
+			require.Truef(t, exists, "key '%s' not found", key)
+			require.Equalf(t, mapVal, val, "expected '%v', got '%v'", val, mapVal)
 		}
 		for _, key := range additionalExpectedKeys {
 			_, exists := requestContext[key]
-			require.True(t, exists)
+			require.Truef(t, exists, "key '%s' not found", key)
 		}
 	})
 }

router-tests/testenv/testenv.go

@@ -10,6 +10,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"github.com/wundergraph/cosmo/router/pkg/logging"
 	"io"
 	"log"
 	"math/rand"
@@ -419,19 +420,14 @@ func createTestEnv(t testing.TB, cfg *Config) (*Environment, error) {
 	if oc := cfg.LogObservation; oc.Enabled {
 		var zCore zapcore.Core
 		zCore, logObserver = observer.New(oc.LogLevel)
-		zapLogger = zap.New(zCore)
+		zapLogger = logging.NewZapLoggerWithCore(zCore, true)
 	} else {
 		ec := zap.NewProductionEncoderConfig()
 		ec.EncodeDuration = zapcore.SecondsDurationEncoder
 		ec.TimeKey = "time"
 
 		syncer := zapcore.AddSync(os.Stderr)
-
-		zapLogger = zap.New(zapcore.NewCore(
-			zapcore.NewConsoleEncoder(ec),
-			syncer,
-			zapcore.ErrorLevel,
-		))
+		zapLogger = logging.NewZapLoggerWithSyncer(syncer, false, true, zapcore.ErrorLevel)
 	}
 
 	rr, err := configureRouter(listenerAddr, cfg, &routerConfig, cdn, natsData.Server, zapLogger)

router/core/graph_server.go

@@ -168,10 +168,7 @@ func newGraphServer(ctx context.Context, r *Router, routerConfig *nodev1.RouterC
 		s.publicKey = publicKey
 	}
 
-	recoveryHandler := recoveryhandler.New(
-		recoveryhandler.WithLogger(s.logger),
-		recoveryhandler.WithPrintStack(),
-	)
+	recoveryHandler := recoveryhandler.New()
 
 	httpRouter := chi.NewRouter()
 

router/core/graphql_handler.go

@@ -6,12 +6,11 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	rotel "github.com/wundergraph/cosmo/router/pkg/otel"
 	"io"
 	"net/http"
 	"strings"
 
-	rotel "github.com/wundergraph/cosmo/router/pkg/otel"
-
 	"go.opentelemetry.io/otel/attribute"
 
 	"github.com/wundergraph/graphql-go-tools/v2/pkg/graphqlerrors"