From e109cb602e8b12e49bb06df4951f768095605bb1 Mon Sep 17 00:00:00 2001 From: Bryan Frimin Date: Sat, 11 Oct 2025 23:14:45 +0200 Subject: [PATCH] Add graphql log Signed-off-by: Bryan Frimin --- pkg/server/api/console/v1/resolver.go | 2 +- pkg/server/api/trust/v1/resolver.go | 1 + .../tracing.go} | 61 +++++++++++++++---- 3 files changed, 52 insertions(+), 12 deletions(-) rename pkg/server/{api/console/v1/tracing_extensions.go => graphql/tracing.go} (58%) diff --git a/pkg/server/api/console/v1/resolver.go b/pkg/server/api/console/v1/resolver.go index e643c2a88..7caf09728 100644 --- a/pkg/server/api/console/v1/resolver.go +++ b/pkg/server/api/console/v1/resolver.go @@ -233,7 +233,7 @@ func graphqlHandler(logger *log.Logger, proboSvc *probo.Service, usrmgrSvc *usrm }, ) srv.Use(extension.Introspection{}) - srv.Use(tracingExtension{}) + srv.Use(gqlutils.NewTracingExtension(logger)) srv.SetRecoverFunc(gqlutils.RecoverFunc) srv.AroundOperations( diff --git a/pkg/server/api/trust/v1/resolver.go b/pkg/server/api/trust/v1/resolver.go index 5f6ebd0cc..93931eb0e 100644 --- a/pkg/server/api/trust/v1/resolver.go +++ b/pkg/server/api/trust/v1/resolver.go @@ -133,6 +133,7 @@ func graphqlHandler(logger *log.Logger, usrmgrSvc *usrmgr.Service, trustSvc *tru srv.AddTransport(transport.Options{}) srv.Use(extension.Introspection{}) + srv.Use(gqlutils.NewTracingExtension(logger)) srv.SetRecoverFunc(gqlutils.RecoverFunc) diff --git a/pkg/server/api/console/v1/tracing_extensions.go b/pkg/server/graphql/tracing.go similarity index 58% rename from pkg/server/api/console/v1/tracing_extensions.go rename to pkg/server/graphql/tracing.go index 5d4194159..1efe9eafa 100644 --- a/pkg/server/api/console/v1/tracing_extensions.go +++ b/pkg/server/graphql/tracing.go @@ -12,28 +12,37 @@ // OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR // PERFORMANCE OF THIS SOFTWARE. -package console_v1 +package graphql import ( "context" + "fmt" + "time" "github.com/99designs/gqlgen/graphql" + "go.gearno.de/kit/log" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/trace" ) -type tracingExtension struct{} +type TracingExtension struct { + logger *log.Logger +} -func (t tracingExtension) ExtensionName() string { +func NewTracingExtension(logger *log.Logger) TracingExtension { + return TracingExtension{logger: logger} +} + +func (t TracingExtension) ExtensionName() string { return "Tracing" } -func (t tracingExtension) Validate(schema graphql.ExecutableSchema) error { +func (t TracingExtension) Validate(schema graphql.ExecutableSchema) error { return nil } -func (t tracingExtension) InterceptField(ctx context.Context, next graphql.Resolver) (interface{}, error) { +func (t TracingExtension) InterceptField(ctx context.Context, next graphql.Resolver) (interface{}, error) { rootSpan := trace.SpanFromContext(ctx) if rootSpan.IsRecording() { @@ -61,18 +70,20 @@ func (t tracingExtension) InterceptField(ctx context.Context, next graphql.Resol return next(ctx) } -func (t tracingExtension) InterceptOperation(ctx context.Context, next graphql.OperationHandler) graphql.ResponseHandler { +func (t TracingExtension) InterceptOperation(ctx context.Context, next graphql.OperationHandler) graphql.ResponseHandler { rootSpan := trace.SpanFromContext(ctx) + requestContext := graphql.GetOperationContext(ctx) + startTime := time.Now() if rootSpan.IsRecording() { tracer := otel.Tracer("graphql-operation") - requestContext := graphql.GetOperationContext(ctx) operationName := "GraphQL Operation" if requestContext.OperationName != "" { operationName = "GraphQL " + requestContext.OperationName } - ctx, span := tracer.Start(ctx, operationName) + var span trace.Span + ctx, span = tracer.Start(ctx, operationName) defer span.End() span.SetAttributes( @@ -80,9 +91,37 @@ func (t tracingExtension) InterceptOperation(ctx context.Context, next graphql.O attribute.String("graphql.operation_type", string(requestContext.Operation.Operation)), attribute.String("graphql.query", requestContext.RawQuery), ) - - return next(ctx) } - return next(ctx) + handler := next(ctx) + + return func(ctx context.Context) *graphql.Response { + resp := handler(ctx) + duration := time.Since(startTime) + + operationType := string(requestContext.Operation.Operation) + operationName := requestContext.OperationName + if operationName == "" { + operationName = "unnamed" + } + + if resp.Errors != nil { + t.logger.ErrorCtx(ctx, + fmt.Sprintf("%s %s failed %s", operationType, operationName, duration.String()), + log.String("graphql_operation_name", operationName), + log.String("graphql_operation_type", operationType), + log.Duration("graphql_operation_duration", duration), + log.Any("graphql_operation_errors", resp.Errors), + ) + } else { + t.logger.InfoCtx(ctx, + fmt.Sprintf("%s %s succeed %s", operationType, operationName, duration.String()), + log.String("graphql_operation_name", operationName), + log.String("graphql_operation_type", operationType), + log.Duration("graphql_operation_duration", duration), + ) + } + + return resp + } }