From 087a75018a4fc45891bed228b620b1a8fe0c7287 Mon Sep 17 00:00:00 2001 From: StarpTech Date: Thu, 24 Apr 2025 21:10:51 +0200 Subject: [PATCH 1/4] feat: improve access logs --- router-tests/go.mod | 2 +- router-tests/structured_logging_test.go | 15 ++-- router-tests/telemetry/telemetry_test.go | 6 +- router-tests/testenv/testenv.go | 4 +- router/cmd/instance.go | 17 +++-- router/core/engine_loader_hooks.go | 12 +++- router/core/errors.go | 14 ++-- router/core/graph_server.go | 1 + router/core/graphql_handler.go | 14 ++-- router/core/request_context_fields.go | 70 +++++++++++++++++-- router/core/router.go | 2 + router/go.mod | 2 +- .../internal/requestlogger/requestlogger.go | 30 +++++--- .../internal/requestlogger/subgraphlogger.go | 5 ++ .../requestlogger/subgraphlogger_test.go | 17 ++--- router/pkg/config/config.go | 12 ++-- router/pkg/config/config.schema.json | 16 +++++ .../pkg/config/testdata/config_defaults.json | 2 + router/pkg/config/testdata/config_full.json | 2 + router/pkg/logging/logging.go | 36 +++++----- 20 files changed, 205 insertions(+), 74 deletions(-) diff --git a/router-tests/go.mod b/router-tests/go.mod index afa33416df..3b7d110d8f 100644 --- a/router-tests/go.mod +++ b/router-tests/go.mod @@ -177,7 +177,7 @@ require ( replace ( github.com/wundergraph/cosmo/demo => ../demo github.com/wundergraph/cosmo/router => ../router -// github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 + github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 ) replace github.com/hashicorp/consul/sdk => github.com/wundergraph/consul/sdk v0.0.0-20250204115147-ed842a8fd301 diff --git a/router-tests/structured_logging_test.go b/router-tests/structured_logging_test.go index 8141ac66c0..46c354bd72 100644 --- a/router-tests/structured_logging_test.go +++ b/router-tests/structured_logging_test.go @@ -4,17 +4,18 @@ import ( "bytes" "encoding/json" "fmt" - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - "go.opentelemetry.io/otel/sdk/metric" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" "math" "net/http" "os" "path/filepath" "testing" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/sdk/metric" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "github.com/wundergraph/cosmo/router-tests/testenv" "github.com/wundergraph/cosmo/router/core" "github.com/wundergraph/cosmo/router/pkg/config" @@ -193,7 +194,7 @@ func TestAccessLogsFileOutput(t *testing.T) { require.NoError(t, os.RemoveAll(fp)) }) - logger := logging.NewZapAccessLogger(f, false, false) + logger := logging.NewZapAccessLogger(f, zap.InfoLevel, false, false, false) require.NoError(t, err) testenv.Run(t, &testenv.Config{ @@ -249,7 +250,7 @@ func TestAccessLogsFileOutput(t *testing.T) { require.NoError(t, os.RemoveAll(fp)) }) - logger := logging.NewZapAccessLogger(f, false, false) + logger := logging.NewZapAccessLogger(f, zap.InfoLevel, false, false, false) require.NoError(t, err) testenv.Run(t, &testenv.Config{ diff --git a/router-tests/telemetry/telemetry_test.go b/router-tests/telemetry/telemetry_test.go index 26602185a5..2d145ad382 100644 --- a/router-tests/telemetry/telemetry_test.go +++ b/router-tests/telemetry/telemetry_test.go @@ -6766,7 +6766,8 @@ func TestFlakyTelemetry(t *testing.T) { require.Equal(t, trace.SpanKindInternal, sn[8].SpanKind()) require.Equal(t, codes.Error, sn[8].Status().Code) require.Lenf(t, sn[8].Attributes(), 14, "expected 14 attributes, got %d", len(sn[8].Attributes())) - require.Contains(t, sn[8].Status().Description, "connect: connection refused\nFailed to fetch from Subgraph 'products' at Path: 'employees'.") + require.Contains(t, sn[8].Status().Description, "Failed to fetch from Subgraph 'products' at Path: 'employees'.") + require.Contains(t, sn[8].Status().Description, "connect: connection refused") events := sn[8].Events() require.Len(t, events, 1, "expected 1 event because the GraphQL request failed") @@ -6776,7 +6777,8 @@ func TestFlakyTelemetry(t *testing.T) { require.Equal(t, "query unnamed", sn[10].Name()) require.Equal(t, trace.SpanKindServer, sn[10].SpanKind()) require.Equal(t, codes.Error, sn[10].Status().Code) - require.Contains(t, sn[10].Status().Description, "connect: connection refused\nFailed to fetch from Subgraph 'products' at Path: 'employees'.") + require.Contains(t, sn[10].Status().Description, "Failed to fetch from Subgraph 'products' at Path: 'employees'.") + require.Contains(t, sn[10].Status().Description, "connect: connection refused") }) }) diff --git a/router-tests/testenv/testenv.go b/router-tests/testenv/testenv.go index 8ce23179ad..337923e2e6 100644 --- a/router-tests/testenv/testenv.go +++ b/router-tests/testenv/testenv.go @@ -408,14 +408,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) - cfg.Logger = logging.NewZapLoggerWithCore(zCore, true) + cfg.Logger = logging.NewZapLoggerWithCore(zCore, true, true) } else { ec := zap.NewProductionEncoderConfig() ec.EncodeDuration = zapcore.SecondsDurationEncoder ec.TimeKey = "time" syncer := zapcore.AddSync(os.Stderr) - cfg.Logger = logging.NewZapLogger(syncer, false, true, zapcore.ErrorLevel) + cfg.Logger = logging.NewZapLogger(syncer, false, true, true, zapcore.ErrorLevel) } if cfg.AccessLogger == nil { diff --git a/router/cmd/instance.go b/router/cmd/instance.go index 33904ff3c9..b4ba4c3890 100644 --- a/router/cmd/instance.go +++ b/router/cmd/instance.go @@ -156,6 +156,13 @@ func NewRouter(ctx context.Context, params Params, additionalOptions ...core.Opt Attributes: cfg.AccessLogs.Router.Fields, SubgraphEnabled: cfg.AccessLogs.Subgraphs.Enabled, SubgraphAttributes: cfg.AccessLogs.Subgraphs.Fields, + Level: cfg.AccessLogs.Level, + AddStacktrace: cfg.AccessLogs.AddStacktrace, + } + + level, err := logging.ZapLogLevelFromString(cfg.AccessLogs.Level) + if err != nil { + return nil, fmt.Errorf("could not parse log level: %w for access logs", err) } if cfg.AccessLogs.Output.File.Enabled { @@ -168,8 +175,9 @@ func NewRouter(ctx context.Context, params Params, additionalOptions ...core.Opt WS: f, BufferSize: int(cfg.AccessLogs.Buffer.Size.Uint64()), FlushInterval: cfg.AccessLogs.Buffer.FlushInterval, + Stacktrace: c.AddStacktrace, Development: cfg.DevelopmentMode, - Level: zap.InfoLevel, + Level: level, Pretty: !cfg.JSONLog, }) if err != nil { @@ -177,7 +185,7 @@ func NewRouter(ctx context.Context, params Params, additionalOptions ...core.Opt } c.Logger = bl.Logger } else { - c.Logger = logging.NewZapAccessLogger(f, cfg.DevelopmentMode, !cfg.JSONLog) + c.Logger = logging.NewZapAccessLogger(f, level, c.AddStacktrace, cfg.DevelopmentMode, !cfg.JSONLog) } } else if cfg.AccessLogs.Output.Stdout.Enabled { if cfg.AccessLogs.Buffer.Enabled { @@ -185,8 +193,9 @@ func NewRouter(ctx context.Context, params Params, additionalOptions ...core.Opt WS: os.Stdout, BufferSize: int(cfg.AccessLogs.Buffer.Size.Uint64()), FlushInterval: cfg.AccessLogs.Buffer.FlushInterval, + Stacktrace: cfg.AccessLogs.AddStacktrace, Development: cfg.DevelopmentMode, - Level: zap.InfoLevel, + Level: level, Pretty: !cfg.JSONLog, }) if err != nil { @@ -194,7 +203,7 @@ func NewRouter(ctx context.Context, params Params, additionalOptions ...core.Opt } c.Logger = bl.Logger } else { - c.Logger = logging.NewZapAccessLogger(os.Stdout, cfg.DevelopmentMode, !cfg.JSONLog) + c.Logger = logging.NewZapAccessLogger(os.Stdout, level, c.AddStacktrace, cfg.DevelopmentMode, !cfg.JSONLog) } } diff --git a/router/core/engine_loader_hooks.go b/router/core/engine_loader_hooks.go index 9cb95d9e40..60c8fb24d6 100644 --- a/router/core/engine_loader_hooks.go +++ b/router/core/engine_loader_hooks.go @@ -4,6 +4,9 @@ import ( "context" "errors" "fmt" + "slices" + "time" + "github.com/wundergraph/cosmo/router/internal/requestlogger" "github.com/wundergraph/cosmo/router/internal/unique" "github.com/wundergraph/cosmo/router/pkg/metric" @@ -17,8 +20,6 @@ import ( semconv "go.opentelemetry.io/otel/semconv/v1.21.0" "go.opentelemetry.io/otel/trace" "go.uber.org/zap" - "slices" - "time" ) var ( @@ -148,7 +149,12 @@ func (f *engineLoaderHooks) OnFinished(ctx context.Context, ds resolve.DataSourc path = responseInfo.Request.URL.Path } } - f.accessLogger.Info(path, fields) + + if responseInfo.Err != nil { + f.accessLogger.Error(path, fields) + } else { + f.accessLogger.Info(path, fields) + } } if responseInfo.Err != nil { diff --git a/router/core/errors.go b/router/core/errors.go index c13cad30ed..031d7eecd2 100644 --- a/router/core/errors.go +++ b/router/core/errors.go @@ -174,10 +174,14 @@ func getAggregatedSubgraphServiceNames(err error) []string { return nil } -// propagateSubgraphErrors propagates the subgraph errors to the request context -func propagateSubgraphErrors(ctx *resolve.Context) { - err := ctx.SubgraphErrors() +// trackResponseError propagates the errors during engine execution to the request context. +func trackResponseError(ctx *resolve.Context, err error) { + if err != nil { + trackFinalResponseError(ctx.Context(), err) + return + } + err = ctx.ExecutionError() if err != nil { trackFinalResponseError(ctx.Context(), err) } @@ -276,8 +280,8 @@ func writeMultipartError( // before, some clients that rely on both CR and LF strictly to parse blocks were broken and not parsing our // multipart chunks correctly. With this fix here (and in a few other places) the clients are now working. resp = append(resp, []byte("\r\n--graphql--")...) - - if _, err := w.Write([]byte(resp)); err != nil { + + if _, err := w.Write(resp); err != nil { return err } diff --git a/router/core/graph_server.go b/router/core/graph_server.go index 34afa96522..670d004432 100644 --- a/router/core/graph_server.go +++ b/router/core/graph_server.go @@ -896,6 +896,7 @@ func (s *graphServer) buildGraphMux(ctx context.Context, requestlogger.WithFields(baseLogFields...), requestlogger.WithAttributes(s.accessLogsConfig.Attributes), requestlogger.WithExprAttributes(exprAttributes), + requestlogger.WithLogLevelHandler(LogLevelHandler), requestlogger.WithFieldsHandler(RouterAccessLogsFieldHandler), } diff --git a/router/core/graphql_handler.go b/router/core/graphql_handler.go index 3263bebef3..66e2d81887 100644 --- a/router/core/graphql_handler.go +++ b/router/core/graphql_handler.go @@ -175,13 +175,13 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { ctx = WithResponseHeaderPropagation(ctx) } - defer propagateSubgraphErrors(ctx) - resp, err := h.executor.Resolver.ResolveGraphQLResponse(ctx, p.Response, nil, HeaderPropagationWriter(w, ctx.Context())) + + defer trackResponseError(ctx, err) + requestContext.dataSourceNames = getSubgraphNames(p.Response.DataSources) if err != nil { - trackFinalResponseError(ctx.Context(), err) h.WriteError(ctx, err, p.Response, w) return } @@ -194,7 +194,6 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { ) h.setDebugCacheHeaders(w, requestContext.operation) - defer propagateSubgraphErrors(ctx) ctx, writer, ok = GetSubscriptionResponseWriter(ctx, r, w, h.apolloSubscriptionMultipartPrintBoundary) if !ok { requestContext.logger.Error("unable to get subscription response writer", zap.Error(errCouldNotFlushResponse)) @@ -211,25 +210,24 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { err := h.executor.Resolver.ResolveGraphQLSubscription(ctx, p.Response, writer) requestContext.dataSourceNames = getSubgraphNames(p.Response.Response.DataSources) + defer trackResponseError(ctx, err) + if err != nil { if errors.Is(err, context.Canceled) { requestContext.logger.Debug("context canceled: unable to resolve subscription response", zap.Error(err)) - trackFinalResponseError(r.Context(), err) return } else if errors.Is(err, ErrUnauthorized) { - trackFinalResponseError(ctx.Context(), err) writeRequestErrors(r, w, http.StatusUnauthorized, graphqlerrors.RequestErrorsFromError(err), requestContext.logger) return } requestContext.logger.Error("unable to resolve subscription response", zap.Error(err)) - trackFinalResponseError(ctx.Context(), err) writeRequestErrors(r, w, http.StatusInternalServerError, graphqlerrors.RequestErrorsFromError(errCouldNotResolveResponse), requestContext.logger) return } default: requestContext.logger.Error("unsupported plan kind") - trackFinalResponseError(ctx.Context(), errOperationPlanUnsupported) + trackResponseError(ctx, errOperationPlanUnsupported) writeRequestErrors(r, w, http.StatusInternalServerError, graphqlerrors.RequestErrorsFromError(errOperationPlanUnsupported), requestContext.logger) } } diff --git a/router/core/request_context_fields.go b/router/core/request_context_fields.go index 023858b2c1..db9037237e 100644 --- a/router/core/request_context_fields.go +++ b/router/core/request_context_fields.go @@ -1,7 +1,6 @@ package core import ( - "fmt" "net/http" "strconv" "time" @@ -28,6 +27,7 @@ const ( ContextFieldOperationNormalizationTime = "operation_normalization_time" ContextFieldPersistedOperationSha256 = "persisted_operation_sha256" ContextFieldOperationSha256 = "operation_sha256" + ContextFieldResponseError = "response_error" ContextFieldResponseErrorMessage = "response_error_message" ContextFieldRequestError = "request_error" ) @@ -61,6 +61,21 @@ func NewStringLogField(val string, attribute config.CustomAttribute) zap.Field { return zap.Skip() } +func NewErrorLogField(val error, attribute config.CustomAttribute) zap.Field { + if v := val; v != nil { + if unwrapped, ok := v.(multiError); ok { + errs := unwrapped.Unwrap() + if len(errs) > 0 { + return zap.Errors(attribute.Key, errs) + } + } + return zap.Errors(attribute.Key, []error{v}) + } else if attribute.Default != "" { + return zap.String(attribute.Key, attribute.Default) + } + return zap.Skip() +} + func NewBoolLogField(val bool, attribute config.CustomAttribute) zap.Field { if val { return zap.Bool(attribute.Key, val) @@ -88,6 +103,24 @@ func NewDurationLogField(val time.Duration, attribute config.CustomAttribute) za return zap.Skip() } +func LogLevelHandler(r *http.Request) zapcore.Level { + + if r == nil { + return zapcore.InfoLevel + } + + reqContext := getRequestContext(r.Context()) + if reqContext == nil { + return zapcore.InfoLevel + } + + if reqContext.error != nil { + return zapcore.ErrorLevel + } + + return zapcore.InfoLevel +} + func RouterAccessLogsFieldHandler( logger *zap.Logger, attributes []config.CustomAttribute, @@ -190,6 +223,8 @@ func GetLogFieldFromCustomAttribute(field config.CustomAttribute, req *requestCo return NewStringSliceLogField(v, field) case time.Duration: return NewDurationLogField(v, field) + case error: + return NewErrorLogField(v, field) } return zap.Skip() @@ -209,7 +244,9 @@ func getCustomDynamicAttributeValue( if attribute.ContextField == ContextFieldRequestError { return err != nil } else if attribute.ContextField == ContextFieldResponseErrorMessage && err != nil { - return fmt.Sprintf("%v", err) + return getErrorString(err) + } else if attribute.ContextField == ContextFieldResponseError && err != nil { + return err } return "" } @@ -266,11 +303,20 @@ func getCustomDynamicAttributeValue( } return reqContext.operation.persistedID case ContextFieldResponseErrorMessage: + var fErr any + if err != nil { + fErr = err + } else if reqContext.error != nil { + fErr = reqContext.error + } + + return getErrorString(fErr) + case ContextFieldResponseError: if err != nil { - return fmt.Sprintf("%v", err) + return err } if reqContext.error != nil { - return reqContext.error.Error() + return reqContext.error } case ContextFieldOperationServices: return reqContext.dataSourceNames @@ -282,3 +328,19 @@ func getCustomDynamicAttributeValue( return "" } + +func getErrorString(err any) string { + if err == nil { + return "" + } + + if e, ok := err.(error); ok { + return e.Error() + } + + if e, ok := err.(string); ok { + return e + } + + return "" +} diff --git a/router/core/router.go b/router/core/router.go index c9662362b2..c0ebc50244 100644 --- a/router/core/router.go +++ b/router/core/router.go @@ -152,9 +152,11 @@ type ( AccessLogsConfig struct { Attributes []config.CustomAttribute + Level string Logger *zap.Logger SubgraphEnabled bool SubgraphAttributes []config.CustomAttribute + AddStacktrace bool } // Config defines the configuration options for the Router. diff --git a/router/go.mod b/router/go.mod index f0ae7c0eb7..e4015090b8 100644 --- a/router/go.mod +++ b/router/go.mod @@ -151,4 +151,4 @@ require ( // Remember you can use Go workspaces to avoid using replace directives in multiple go.mod files // Use what is best for your personal workflow. See CONTRIBUTING.md for more information -// replace github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 +replace github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 diff --git a/router/internal/requestlogger/requestlogger.go b/router/internal/requestlogger/requestlogger.go index c5dd1a0036..54bc8ad896 100644 --- a/router/internal/requestlogger/requestlogger.go +++ b/router/internal/requestlogger/requestlogger.go @@ -3,13 +3,14 @@ package requestlogger import ( "crypto/sha256" "fmt" + "net" + "net/http" + "time" + "github.com/wundergraph/cosmo/router/internal/errors" "github.com/wundergraph/cosmo/router/pkg/config" "github.com/wundergraph/cosmo/router/pkg/logging" rtrace "github.com/wundergraph/cosmo/router/pkg/trace" - "net" - "net/http" - "time" "github.com/go-chi/chi/v5/middleware" @@ -46,9 +47,10 @@ const ( ) type handler struct { - accessLogger *accessLogger - handler http.Handler - logger *zap.Logger + accessLogger *accessLogger + handler http.Handler + logLevelHandler func(r *http.Request) zapcore.Level + logger *zap.Logger } func parseOptions(r *handler, opts ...Option) http.Handler { @@ -96,6 +98,12 @@ func WithFields(fields ...zapcore.Field) Option { } } +func WithLogLevelHandler(fn func(r *http.Request) zapcore.Level) Option { + return func(r *handler) { + r.logLevelHandler = fn + } +} + func WithDefaultOptions() Option { return func(r *handler) { r.accessLogger.timeFormat = time.RFC3339 @@ -157,7 +165,7 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { h.logger.Error("[Recovery from panic]", fields...) } - // Dpanic will panic already in development but in production it will log the error and continue + // Dpanic will panic already in development, but in production it will log the error and continue // For those reasons we panic here to pass it to the recovery middleware in all cases panic(err) } @@ -178,7 +186,13 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) { resFields = append(resFields, h.accessLogger.fieldsHandler(h.logger, h.accessLogger.attributes, h.accessLogger.exprAttributes, nil, r, nil)...) } - h.logger.Info(path, append(fields, resFields...)...) + logLevel := zapcore.InfoLevel + + if h.logLevelHandler != nil { + logLevel = h.logLevelHandler(r) + } + + h.logger.Log(logLevel, path, append(fields, resFields...)...) } func (al *accessLogger) getRequestFields(r *http.Request) []zapcore.Field { diff --git a/router/internal/requestlogger/subgraphlogger.go b/router/internal/requestlogger/subgraphlogger.go index afc124c24f..890d4ce2bc 100644 --- a/router/internal/requestlogger/subgraphlogger.go +++ b/router/internal/requestlogger/subgraphlogger.go @@ -56,6 +56,7 @@ func (h *SubgraphAccessLogger) RequestFields(respInfo *resolve.ResponseInfo, sub if h.accessLogger.fieldsHandler != nil { fields = append(fields, h.accessLogger.fieldsHandler(h.logger, h.accessLogger.attributes, h.accessLogger.exprAttributes, respInfo.Err, respInfo.Request, &respInfo.ResponseHeaders)...) } + fields = append(fields, subgraphFields...) return fields } @@ -63,3 +64,7 @@ func (h *SubgraphAccessLogger) RequestFields(respInfo *resolve.ResponseInfo, sub func (h *SubgraphAccessLogger) Info(message string, fields []zap.Field) { h.logger.Info(message, fields...) } + +func (h *SubgraphAccessLogger) Error(message string, fields []zap.Field) { + h.logger.Error(message, fields...) +} diff --git a/router/internal/requestlogger/subgraphlogger_test.go b/router/internal/requestlogger/subgraphlogger_test.go index 4ad71968a8..a8eb3b0f5a 100644 --- a/router/internal/requestlogger/subgraphlogger_test.go +++ b/router/internal/requestlogger/subgraphlogger_test.go @@ -2,6 +2,9 @@ package requestlogger_test import ( "errors" + "net/http" + "testing" + "github.com/stretchr/testify/require" "github.com/wundergraph/cosmo/router/core" "github.com/wundergraph/cosmo/router/internal/requestlogger" @@ -10,8 +13,6 @@ import ( "github.com/wundergraph/graphql-go-tools/v2/pkg/engine/resolve" "go.uber.org/zap/zapcore" "go.uber.org/zap/zaptest/observer" - "net/http" - "testing" ) func TestSubgraphAccessLogger(t *testing.T) { @@ -20,7 +21,7 @@ func TestSubgraphAccessLogger(t *testing.T) { t.Run("writes correct request log", func(t *testing.T) { var zCore zapcore.Core zCore, logObserver := observer.New(zapcore.InfoLevel) - l := logging.NewZapLoggerWithCore(zCore, true) + l := logging.NewZapLoggerWithCore(zCore, true, true) subgraphLogger := requestlogger.NewSubgraphAccessLogger(l, requestlogger.SubgraphOptions{}) req, err := http.NewRequest("POST", "http://localhost:3002/graphql", nil) @@ -48,7 +49,7 @@ func TestSubgraphAccessLogger(t *testing.T) { t.Run("Should include IP as custom attribute if requested", func(t *testing.T) { var zCore zapcore.Core zCore, logObserver := observer.New(zapcore.InfoLevel) - l := logging.NewZapLoggerWithCore(zCore, true) + l := logging.NewZapLoggerWithCore(zCore, true, true) subgraphLogger := requestlogger.NewSubgraphAccessLogger(l, requestlogger.SubgraphOptions{}) req, err := http.NewRequest("POST", "http://localhost:3002/graphql", nil) @@ -77,7 +78,7 @@ func TestSubgraphAccessLogger(t *testing.T) { t.Run("Should redact client IP and add as a custom attribute", func(t *testing.T) { var zCore zapcore.Core zCore, logObserver := observer.New(zapcore.InfoLevel) - l := logging.NewZapLoggerWithCore(zCore, true) + l := logging.NewZapLoggerWithCore(zCore, true, true) subgraphLogger := requestlogger.NewSubgraphAccessLogger(l, requestlogger.SubgraphOptions{ IPAnonymizationConfig: &requestlogger.IPAnonymizationConfig{ @@ -111,7 +112,7 @@ func TestSubgraphAccessLogger(t *testing.T) { t.Run("Should hash client IP and add it as a custom attribute", func(t *testing.T) { var zCore zapcore.Core zCore, logObserver := observer.New(zapcore.InfoLevel) - l := logging.NewZapLoggerWithCore(zCore, true) + l := logging.NewZapLoggerWithCore(zCore, true, true) subgraphLogger := requestlogger.NewSubgraphAccessLogger(l, requestlogger.SubgraphOptions{ IPAnonymizationConfig: &requestlogger.IPAnonymizationConfig{ @@ -145,7 +146,7 @@ func TestSubgraphAccessLogger(t *testing.T) { t.Run("calls fields handler and adds request/response headers", func(t *testing.T) { var zCore zapcore.Core zCore, logObserver := observer.New(zapcore.InfoLevel) - l := logging.NewZapLoggerWithCore(zCore, true) + l := logging.NewZapLoggerWithCore(zCore, true, true) subgraphLogger := requestlogger.NewSubgraphAccessLogger(l, requestlogger.SubgraphOptions{ FieldsHandler: core.SubgraphAccessLogsFieldHandler, @@ -195,7 +196,7 @@ func TestSubgraphAccessLogger(t *testing.T) { t.Run("can handle a null request", func(t *testing.T) { var zCore zapcore.Core zCore, logObserver := observer.New(zapcore.InfoLevel) - l := logging.NewZapLoggerWithCore(zCore, true) + l := logging.NewZapLoggerWithCore(zCore, true, true) subgraphLogger := requestlogger.NewSubgraphAccessLogger(l, requestlogger.SubgraphOptions{ FieldsHandler: core.SubgraphAccessLogsFieldHandler, diff --git a/router/pkg/config/config.go b/router/pkg/config/config.go index 83de4e412e..e5acf338f2 100644 --- a/router/pkg/config/config.go +++ b/router/pkg/config/config.go @@ -762,11 +762,13 @@ type AutomaticPersistedQueriesConfig struct { } type AccessLogsConfig struct { - Enabled bool `yaml:"enabled" env:"ACCESS_LOGS_ENABLED" envDefault:"true"` - Buffer AccessLogsBufferConfig `yaml:"buffer,omitempty" env:"ACCESS_LOGS_BUFFER"` - Output AccessLogsOutputConfig `yaml:"output,omitempty" env:"ACCESS_LOGS_OUTPUT"` - Router AccessLogsRouterConfig `yaml:"router,omitempty" env:"ACCESS_LOGS_ROUTER"` - Subgraphs AccessLogsSubgraphsConfig `yaml:"subgraphs,omitempty" env:"ACCESS_LOGS_SUBGRAPH"` + Enabled bool `yaml:"enabled" env:"ACCESS_LOGS_ENABLED" envDefault:"true"` + Level string `yaml:"level" env:"ACCESS_LOGS_LEVEL" envDefault:"info"` + AddStacktrace bool `yaml:"addstacktrace" env:"ACCESS_LOGS_ADD_STACK_TRACE" envDefault:"false"` + Buffer AccessLogsBufferConfig `yaml:"buffer,omitempty" env:"ACCESS_LOGS_BUFFER"` + Output AccessLogsOutputConfig `yaml:"output,omitempty" env:"ACCESS_LOGS_OUTPUT"` + Router AccessLogsRouterConfig `yaml:"router,omitempty" env:"ACCESS_LOGS_ROUTER"` + Subgraphs AccessLogsSubgraphsConfig `yaml:"subgraphs,omitempty" env:"ACCESS_LOGS_SUBGRAPH"` } type BatchingConfig struct { diff --git a/router/pkg/config/config.schema.json b/router/pkg/config/config.schema.json index 3841df6580..13d7943b2e 100644 --- a/router/pkg/config/config.schema.json +++ b/router/pkg/config/config.schema.json @@ -661,6 +661,20 @@ "description": "Enable the access logs. The access logs are used to log the incoming requests. By default, the access logs are enabled and logged to the standard output.", "default": true }, + "level": { + "type": "string", + "description": "The level of the access logs. The supported levels are 'info', 'error'. The default value is 'info'. The 'info' level logs all requests. The 'error' level logs only the errors.", + "default": "info", + "enum": [ + "info", + "error" + ] + }, + "add_stacktrace": { + "type": "boolean", + "description": "Enable the stacktrace in the access logs. The stacktrace is used to log the stacktrace of the error. The default value is false.", + "default": false + }, "buffer": { "type": "object", "additionalProperties": false, @@ -760,6 +774,7 @@ "operation_planning_time", "operation_normalization_time", "request_error", + "response_error", "response_error_message" ] } @@ -3156,6 +3171,7 @@ "persisted_operation_sha256", "operation_sha256", "request_error", + "response_error", "response_error_message", "graphql_error_codes", "graphql_error_service_names", diff --git a/router/pkg/config/testdata/config_defaults.json b/router/pkg/config/testdata/config_defaults.json index e292d2a5b9..c87f402763 100644 --- a/router/pkg/config/testdata/config_defaults.json +++ b/router/pkg/config/testdata/config_defaults.json @@ -160,6 +160,8 @@ }, "AccessLogs": { "Enabled": true, + "Level": "info", + "AddStacktrace": false, "Buffer": { "Enabled": false, "Size": 256000, diff --git a/router/pkg/config/testdata/config_full.json b/router/pkg/config/testdata/config_full.json index 5325580e73..b65088e1b2 100644 --- a/router/pkg/config/testdata/config_full.json +++ b/router/pkg/config/testdata/config_full.json @@ -325,6 +325,8 @@ }, "AccessLogs": { "Enabled": true, + "Level": "info", + "AddStacktrace": false, "Buffer": { "Enabled": false, "Size": 256000, diff --git a/router/pkg/logging/logging.go b/router/pkg/logging/logging.go index 0f05c9a981..5b39437c67 100644 --- a/router/pkg/logging/logging.go +++ b/router/pkg/logging/logging.go @@ -20,7 +20,7 @@ const ( type RequestIDKey struct{} func New(pretty bool, development bool, level zapcore.Level) *zap.Logger { - return NewZapLogger(zapcore.AddSync(os.Stdout), pretty, development, level) + return NewZapLogger(zapcore.AddSync(os.Stdout), pretty, true, development, level) } func zapBaseEncoderConfig() zapcore.EncoderConfig { @@ -62,30 +62,33 @@ func attachBaseFields(logger *zap.Logger) *zap.Logger { return logger } -func defaultZapCoreOptions(development bool) []zap.Option { +func defaultZapCoreOptions(stacktrace, development bool) []zap.Option { var zapOpts []zap.Option if development { - zapOpts = append(zapOpts, zap.AddCaller(), zap.Development()) + zapOpts = append(zapOpts, + zap.AddCaller(), + ) + } + if stacktrace { + // Stacktrace is included on logs of ErrorLevel and above. + zapOpts = append(zapOpts, + zap.AddStacktrace(zap.ErrorLevel), + ) } - - // Stacktrace is included on logs of ErrorLevel and above. - zapOpts = append(zapOpts, - zap.AddStacktrace(zap.ErrorLevel), - ) return zapOpts } -func NewZapLoggerWithCore(core zapcore.Core, development bool) *zap.Logger { - zapLogger := zap.New(core, defaultZapCoreOptions(development)...) +func NewZapLoggerWithCore(core zapcore.Core, stacktrace, development bool) *zap.Logger { + zapLogger := zap.New(core, defaultZapCoreOptions(stacktrace, development)...) zapLogger = attachBaseFields(zapLogger) return zapLogger } -func NewZapLogger(syncer zapcore.WriteSyncer, pretty, development bool, level zapcore.Level) *zap.Logger { +func NewZapLogger(syncer zapcore.WriteSyncer, pretty, stacktrace, development bool, level zapcore.Level) *zap.Logger { var encoder zapcore.Encoder if pretty { @@ -99,13 +102,13 @@ func NewZapLogger(syncer zapcore.WriteSyncer, pretty, development bool, level za syncer, level, ) - zapLogger := zap.New(c, defaultZapCoreOptions(development)...) + zapLogger := zap.New(c, defaultZapCoreOptions(stacktrace, development)...) zapLogger = attachBaseFields(zapLogger) return zapLogger } -func NewZapAccessLogger(syncer zapcore.WriteSyncer, development, pretty bool) *zap.Logger { +func NewZapAccessLogger(syncer zapcore.WriteSyncer, level zapcore.Level, stacktrace, development, pretty bool) *zap.Logger { var encoder zapcore.Encoder if pretty { @@ -117,9 +120,9 @@ func NewZapAccessLogger(syncer zapcore.WriteSyncer, development, pretty bool) *z c := zapcore.NewCore( encoder, syncer, - zapcore.InfoLevel, + level, ) - zapLogger := zap.New(c, defaultZapCoreOptions(development)...) + zapLogger := zap.New(c, defaultZapCoreOptions(stacktrace, development)...) zapLogger = attachBaseFields(zapLogger) return zapLogger @@ -134,6 +137,7 @@ type BufferedLoggerOptions struct { WS *os.File BufferSize int FlushInterval time.Duration + Stacktrace bool Development bool Level zapcore.Level Pretty bool @@ -148,7 +152,7 @@ func NewJSONZapBufferedLogger(options BufferedLoggerOptions) (*BufferedLogger, e FlushInterval: options.FlushInterval, } - fl.Logger = NewZapAccessLogger(fl.bufferedWriteSyncer, options.Development, options.Pretty) + fl.Logger = NewZapAccessLogger(fl.bufferedWriteSyncer, options.Level, options.Stacktrace, options.Development, options.Pretty) return fl, nil } From c2e1c00291ceeebd0bd8de3c0b09217a30f72238 Mon Sep 17 00:00:00 2001 From: StarpTech Date: Thu, 24 Apr 2025 21:15:20 +0200 Subject: [PATCH 2/4] chore: bump to engine pr --- router-tests/go.mod | 2 +- router-tests/go.sum | 2 -- router/go.mod | 2 +- router/go.sum | 2 -- 4 files changed, 2 insertions(+), 6 deletions(-) diff --git a/router-tests/go.mod b/router-tests/go.mod index 3b7d110d8f..200ee2cf01 100644 --- a/router-tests/go.mod +++ b/router-tests/go.mod @@ -26,7 +26,7 @@ require ( github.com/twmb/franz-go/pkg/kadm v1.11.0 github.com/wundergraph/cosmo/demo v0.0.0-20250422163037-46e4333ac50e github.com/wundergraph/cosmo/router v0.0.0-20250422163037-46e4333ac50e - github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172 + github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172.0.20250424191051-430af8af6c64 go.opentelemetry.io/otel v1.28.0 go.opentelemetry.io/otel/sdk v1.28.0 go.opentelemetry.io/otel/sdk/metric v1.28.0 diff --git a/router-tests/go.sum b/router-tests/go.sum index fb2a559c88..8349982a58 100644 --- a/router-tests/go.sum +++ b/router-tests/go.sum @@ -323,8 +323,6 @@ github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083 h1:8/D7f8gKxTB github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083/go.mod h1:eOTL6acwctsN4F3b7YE+eE2t8zcJ/doLm9sZzsxxxrE= github.com/wundergraph/consul/sdk v0.0.0-20250204115147-ed842a8fd301 h1:EzfKHQoTjFDDcgaECCCR2aTePqMu9QBmPbyhqIYOhV0= github.com/wundergraph/consul/sdk v0.0.0-20250204115147-ed842a8fd301/go.mod h1:wxI0Nak5dI5RvJuzGyiEK4nZj0O9X+Aw6U0tC1wPKq0= -github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172 h1:jrme3DFqhEp+mKYbg4brcc+Y4nw6PIQmPed0uG00pVI= -github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172/go.mod h1:B7eV0Qh8Lop9QzIOQcsvKp3S0ejfC6mgyWoJnI917yQ= github.com/xeipuuv/gojsonpointer v0.0.0-20180127040702-4e3ac2762d5f/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU= github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb h1:zGWFAtiMcyryUHoUjUJX0/lt1H2+i2Ka2n+D3DImSNo= github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU= diff --git a/router/go.mod b/router/go.mod index e4015090b8..a74d3cc832 100644 --- a/router/go.mod +++ b/router/go.mod @@ -31,7 +31,7 @@ require ( github.com/tidwall/gjson v1.18.0 github.com/tidwall/sjson v1.2.5 github.com/twmb/franz-go v1.16.1 - github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172 + github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172.0.20250424191051-430af8af6c64 // Do not upgrade, it renames attributes we rely on go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.46.1 go.opentelemetry.io/contrib/propagators/b3 v1.23.0 diff --git a/router/go.sum b/router/go.sum index a94794d38b..547c67b79b 100644 --- a/router/go.sum +++ b/router/go.sum @@ -270,8 +270,6 @@ github.com/vektah/gqlparser/v2 v2.5.16 h1:1gcmLTvs3JLKXckwCwlUagVn/IlV2bwqle0vJ0 github.com/vektah/gqlparser/v2 v2.5.16/go.mod h1:1lz1OeCqgQbQepsGxPVywrjdBHW2T08PUS3pJqepRww= github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083 h1:8/D7f8gKxTBjW+SZK4mhxTTBVpxcqeBgWF1Rfmltbfk= github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083/go.mod h1:eOTL6acwctsN4F3b7YE+eE2t8zcJ/doLm9sZzsxxxrE= -github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172 h1:jrme3DFqhEp+mKYbg4brcc+Y4nw6PIQmPed0uG00pVI= -github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172/go.mod h1:B7eV0Qh8Lop9QzIOQcsvKp3S0ejfC6mgyWoJnI917yQ= github.com/yosida95/uritemplate/v3 v3.0.2 h1:Ed3Oyj9yrmi9087+NczuL5BwkIc4wvTb5zIM+UJPGz4= github.com/yosida95/uritemplate/v3 v3.0.2/go.mod h1:ILOh0sOhIJR3+L/8afwt/kE++YT040gmv5BQTMR2HP4= github.com/yuin/gopher-lua v1.1.1 h1:kYKnWBjvbNP4XLT3+bPEwAXJx262OhaHDWDVOPjL46M= From 21b0e67d9c947848840142e7c31c53658a0e57d5 Mon Sep 17 00:00:00 2001 From: StarpTech Date: Thu, 24 Apr 2025 21:27:49 +0200 Subject: [PATCH 3/4] chore: add comment --- router/core/graphql_handler.go | 2 ++ 1 file changed, 2 insertions(+) diff --git a/router/core/graphql_handler.go b/router/core/graphql_handler.go index 66e2d81887..1c75f7e1c5 100644 --- a/router/core/graphql_handler.go +++ b/router/core/graphql_handler.go @@ -177,6 +177,7 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { resp, err := h.executor.Resolver.ResolveGraphQLResponse(ctx, p.Response, nil, HeaderPropagationWriter(w, ctx.Context())) + // Respects resolver errors and execution errors defer trackResponseError(ctx, err) requestContext.dataSourceNames = getSubgraphNames(p.Response.DataSources) @@ -210,6 +211,7 @@ func (h *GraphQLHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { err := h.executor.Resolver.ResolveGraphQLSubscription(ctx, p.Response, writer) requestContext.dataSourceNames = getSubgraphNames(p.Response.Response.DataSources) + // Respects resolver errors and execution errors defer trackResponseError(ctx, err) if err != nil { From d939395a0a2d246128ec8f2c0aeb38c827b4353c Mon Sep 17 00:00:00 2001 From: StarpTech Date: Thu, 24 Apr 2025 21:35:41 +0200 Subject: [PATCH 4/4] chore: comment replace --- router-tests/go.mod | 2 +- router-tests/go.sum | 2 ++ router/go.mod | 2 +- router/go.sum | 2 ++ 4 files changed, 6 insertions(+), 2 deletions(-) diff --git a/router-tests/go.mod b/router-tests/go.mod index 200ee2cf01..358efebb27 100644 --- a/router-tests/go.mod +++ b/router-tests/go.mod @@ -177,7 +177,7 @@ require ( replace ( github.com/wundergraph/cosmo/demo => ../demo github.com/wundergraph/cosmo/router => ../router - github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 +//github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 ) replace github.com/hashicorp/consul/sdk => github.com/wundergraph/consul/sdk v0.0.0-20250204115147-ed842a8fd301 diff --git a/router-tests/go.sum b/router-tests/go.sum index 8349982a58..68f10967f6 100644 --- a/router-tests/go.sum +++ b/router-tests/go.sum @@ -323,6 +323,8 @@ github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083 h1:8/D7f8gKxTB github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083/go.mod h1:eOTL6acwctsN4F3b7YE+eE2t8zcJ/doLm9sZzsxxxrE= github.com/wundergraph/consul/sdk v0.0.0-20250204115147-ed842a8fd301 h1:EzfKHQoTjFDDcgaECCCR2aTePqMu9QBmPbyhqIYOhV0= github.com/wundergraph/consul/sdk v0.0.0-20250204115147-ed842a8fd301/go.mod h1:wxI0Nak5dI5RvJuzGyiEK4nZj0O9X+Aw6U0tC1wPKq0= +github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172.0.20250424191051-430af8af6c64 h1:liXxR8ddgPVY4uyYUTi1KEs0eQr1Ttq3ns4go+4IlG4= +github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172.0.20250424191051-430af8af6c64/go.mod h1:B7eV0Qh8Lop9QzIOQcsvKp3S0ejfC6mgyWoJnI917yQ= github.com/xeipuuv/gojsonpointer v0.0.0-20180127040702-4e3ac2762d5f/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU= github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb h1:zGWFAtiMcyryUHoUjUJX0/lt1H2+i2Ka2n+D3DImSNo= github.com/xeipuuv/gojsonpointer v0.0.0-20190905194746-02993c407bfb/go.mod h1:N2zxlSyiKSe5eX1tZViRH5QA0qijqEDrYZiPEAiq3wU= diff --git a/router/go.mod b/router/go.mod index a74d3cc832..28243db4e2 100644 --- a/router/go.mod +++ b/router/go.mod @@ -151,4 +151,4 @@ require ( // Remember you can use Go workspaces to avoid using replace directives in multiple go.mod files // Use what is best for your personal workflow. See CONTRIBUTING.md for more information -replace github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 +//replace github.com/wundergraph/graphql-go-tools/v2 => ../../graphql-go-tools/v2 diff --git a/router/go.sum b/router/go.sum index 547c67b79b..e4ea0e5452 100644 --- a/router/go.sum +++ b/router/go.sum @@ -270,6 +270,8 @@ github.com/vektah/gqlparser/v2 v2.5.16 h1:1gcmLTvs3JLKXckwCwlUagVn/IlV2bwqle0vJ0 github.com/vektah/gqlparser/v2 v2.5.16/go.mod h1:1lz1OeCqgQbQepsGxPVywrjdBHW2T08PUS3pJqepRww= github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083 h1:8/D7f8gKxTBjW+SZK4mhxTTBVpxcqeBgWF1Rfmltbfk= github.com/wundergraph/astjson v0.0.0-20250106123708-be463c97e083/go.mod h1:eOTL6acwctsN4F3b7YE+eE2t8zcJ/doLm9sZzsxxxrE= +github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172.0.20250424191051-430af8af6c64 h1:liXxR8ddgPVY4uyYUTi1KEs0eQr1Ttq3ns4go+4IlG4= +github.com/wundergraph/graphql-go-tools/v2 v2.0.0-rc.172.0.20250424191051-430af8af6c64/go.mod h1:B7eV0Qh8Lop9QzIOQcsvKp3S0ejfC6mgyWoJnI917yQ= github.com/yosida95/uritemplate/v3 v3.0.2 h1:Ed3Oyj9yrmi9087+NczuL5BwkIc4wvTb5zIM+UJPGz4= github.com/yosida95/uritemplate/v3 v3.0.2/go.mod h1:ILOh0sOhIJR3+L/8afwt/kE++YT040gmv5BQTMR2HP4= github.com/yuin/gopher-lua v1.1.1 h1:kYKnWBjvbNP4XLT3+bPEwAXJx262OhaHDWDVOPjL46M=