diff --git a/pkg/apiserver/builder/helper.go b/pkg/apiserver/builder/helper.go index 89f95f62b77..12cf81896a2 100644 --- a/pkg/apiserver/builder/helper.go +++ b/pkg/apiserver/builder/helper.go @@ -91,7 +91,9 @@ func SetupConfig( panic(fmt.Sprintf("could not build handler chain func: %s", err.Error())) } - handler := genericapiserver.DefaultBuildHandlerChain(requestHandler, c) + // Needs to run last in request chain to function as expected, hence we register it first. + handler := filters.WithTracingHTTPLoggingAttributes(requestHandler) + handler = genericapiserver.DefaultBuildHandlerChain(handler, c) handler = filters.WithAcceptHeader(handler) handler = filters.WithPathRewriters(handler, pathRewriters) handler = k8stracing.WithTracing(handler, serverConfig.TracerProvider, "KubernetesAPI") diff --git a/pkg/apiserver/endpoints/filters/tracing_log.go b/pkg/apiserver/endpoints/filters/tracing_log.go new file mode 100644 index 00000000000..e32970e6cd9 --- /dev/null +++ b/pkg/apiserver/endpoints/filters/tracing_log.go @@ -0,0 +1,26 @@ +package filters + +import ( + "net/http" + + "go.opentelemetry.io/otel/trace" + "k8s.io/apiserver/pkg/server/httplog" +) + +// WithTracingHTTPLoggingAttributes adds tracing attributes to HTTP request logs. +func WithTracingHTTPLoggingAttributes(handler http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + spanCtx := trace.SpanContextFromContext(r.Context()) + if spanCtx.IsValid() { + if spanCtx.HasTraceID() { + httplog.AddKeyValue(r.Context(), "traceID", spanCtx.TraceID().String()) + } + + if spanCtx.HasSpanID() { + httplog.AddKeyValue(r.Context(), "spanID", spanCtx.SpanID().String()) + } + } + + handler.ServeHTTP(w, r) + }) +} diff --git a/pkg/apiserver/go.mod b/pkg/apiserver/go.mod index 390efe41d20..21f15bc2cda 100644 --- a/pkg/apiserver/go.mod +++ b/pkg/apiserver/go.mod @@ -9,6 +9,7 @@ require ( github.com/grafana/grafana/pkg/apimachinery v0.0.0-20240409140820-518d3341d58f github.com/prometheus/client_golang v1.19.0 github.com/stretchr/testify v1.9.0 + go.opentelemetry.io/otel/trace v1.26.0 golang.org/x/mod v0.15.0 k8s.io/apimachinery v0.29.2 k8s.io/apiserver v0.29.2 @@ -122,7 +123,6 @@ require ( go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.26.0 // indirect go.opentelemetry.io/otel/metric v1.26.0 // indirect go.opentelemetry.io/otel/sdk v1.26.0 // indirect - go.opentelemetry.io/otel/trace v1.26.0 // indirect go.opentelemetry.io/proto/otlp v1.2.0 // indirect go.uber.org/multierr v1.11.0 // indirect go.uber.org/zap v1.26.0 // indirect diff --git a/pkg/registry/apis/query/query.go b/pkg/registry/apis/query/query.go index 84f891c8e2f..755898f03b7 100644 --- a/pkg/registry/apis/query/query.go +++ b/pkg/registry/apis/query/query.go @@ -23,7 +23,6 @@ import ( "github.com/grafana/grafana/pkg/expr/mathexp" "github.com/grafana/grafana/pkg/infra/log" "github.com/grafana/grafana/pkg/services/datasources" - "github.com/grafana/grafana/pkg/util/errutil" "github.com/grafana/grafana/pkg/web" ) @@ -87,28 +86,22 @@ func (r *queryREST) Connect(ctx context.Context, name string, opts runtime.Objec b := r.builder return http.HandlerFunc(func(w http.ResponseWriter, httpreq *http.Request) { - start := time.Now() ctx, span := b.tracer.Start(httpreq.Context(), "QueryService.Query") defer span.End() - logger := r.logger.FromContext(ctx) - responder := newResponderWrapper(incomingResponder, func(statusCode int, obj runtime.Object) { if statusCode >= 400 { span.SetStatus(codes.Error, fmt.Sprintf("error with HTTP status code %s", strconv.Itoa(statusCode))) } - - logRequest(logger, start, statusCode) }, func(err error) { - span.SetStatus(codes.Error, "request failed") + span.SetStatus(codes.Error, "query error") if err == nil { return } span.RecordError(err) - logRequestError(logger, start, err) }) raw := &query.QueryDataRequest{} @@ -309,7 +302,7 @@ func (b *QueryAPIBuilder) executeConcurrentQueries(ctx context.Context, requests // Unlike the implementation in expr/node.go, all datasource queries have been processed first func (b *QueryAPIBuilder) handleExpressions(ctx context.Context, req parsedRequestInfo, data *backend.QueryDataResponse) (qdr *backend.QueryDataResponse, err error) { start := time.Now() - ctx, span := b.tracer.Start(ctx, "SSE.handleExpressions") + ctx, span := b.tracer.Start(ctx, "Query.handleExpressions") defer func() { var respStatus string switch { @@ -370,30 +363,6 @@ func (b *QueryAPIBuilder) handleExpressions(ctx context.Context, req parsedReque return qdr, nil } -// logRequest short-term hack until k8s have added support for traceIDs in request logs. -func logRequest(logger log.Logger, startTime time.Time, statusCode int) { - duration := time.Since(startTime) - logger.Debug("Query request completed", "status", statusCode, "duration", duration.String()) -} - -func logRequestError(logger log.Logger, startTime time.Time, err error) { - var args []any - var gfErr errutil.Error - if !errors.As(err, &gfErr) { - args = []any{"error", err.Error()} - } else { - args = []any{ - "errorReason", gfErr.Reason, - "errorMessageID", gfErr.MessageID, - "error", gfErr.LogMessage, - } - } - - duration := time.Since(startTime) - args = append(args, "duration", duration.String()) - logger.Error("Query request completed", args...) -} - type responderWrapper struct { wrapped rest.Responder onObjectFn func(statusCode int, obj runtime.Object) @@ -409,11 +378,17 @@ func newResponderWrapper(responder rest.Responder, onObjectFn func(statusCode in } func (r responderWrapper) Object(statusCode int, obj runtime.Object) { - r.onObjectFn(statusCode, obj) + if r.onObjectFn != nil { + r.onObjectFn(statusCode, obj) + } + r.wrapped.Object(statusCode, obj) } func (r responderWrapper) Error(err error) { - r.onErrorFn(err) + if r.onErrorFn != nil { + r.onErrorFn(err) + } + r.wrapped.Error(err) }