API Server: Include traceID in HTTP request logs (#88179)

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")

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)
+	})
+}

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

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)
 }