Merge pull request #128767 from knrc/nested-filterlatency-tracing

Trace across start handler invocations, nesting spans

Kubernetes-commit: a87674895178ced3f6fc1987e3fc1ee76b05629c

go.mod

@@ -50,8 +50,8 @@ require (
 	gopkg.in/natefinch/lumberjack.v2 v2.2.1
 	k8s.io/api v0.0.0-20250626212533-a8e4c192362f
 	k8s.io/apimachinery v0.0.0-20250625172236-d6651abdfec8
-	k8s.io/client-go v0.0.0-20250627212930-267615c1eb68
-	k8s.io/component-base v0.0.0-20250625174139-179392ef0450
+	k8s.io/client-go v0.0.0-20250630172937-5e8db78e0499
+	k8s.io/component-base v0.0.0-20250627214227-48c508093cdb
 	k8s.io/klog/v2 v2.130.1
 	k8s.io/kms v0.0.0-20250527175117-e6cd4d7331a4
 	k8s.io/kube-openapi v0.0.0-20250610211856-8b98d1ed966a

go.sum

@@ -301,10 +301,10 @@ k8s.io/api v0.0.0-20250626212533-a8e4c192362f h1:2YOP2vawF3nJH5bLqFqE7/FSCEvLx3D
 k8s.io/api v0.0.0-20250626212533-a8e4c192362f/go.mod h1:LeP8EGRerQcaOFKs8aGWs2rBBrJi5ByIeqfuMPuxCPk=
 k8s.io/apimachinery v0.0.0-20250625172236-d6651abdfec8 h1:MsspBt/pf3hqgJCgzv8XGYLMuKtRIKq77uZ13QyJ/eU=
 k8s.io/apimachinery v0.0.0-20250625172236-d6651abdfec8/go.mod h1:8gnN3W0XUgFL9P1KdRepAJFA98YuYViPoaUkwNZ1q70=
-k8s.io/client-go v0.0.0-20250627212930-267615c1eb68 h1:T87z3AbF+ev2UFg+Fbb4HKaT77Ek29h9GCPS1oUQymA=
-k8s.io/client-go v0.0.0-20250627212930-267615c1eb68/go.mod h1:S35/NV7N0qaT+n8zdnMvSHhv01b7Gh36CDzj/Ei/1G0=
-k8s.io/component-base v0.0.0-20250625174139-179392ef0450 h1:nUV4kvIczLp0P70TR+o0w99Zs1BpssHCnZBqT0DrnoQ=
-k8s.io/component-base v0.0.0-20250625174139-179392ef0450/go.mod h1:1x8lr7IgSZFmqqCK82ptOofUzOT7UAqyxK/+xKXh9To=
+k8s.io/client-go v0.0.0-20250630172937-5e8db78e0499 h1:H1ALazQeWf1yF0qhlkwsdEvMFgUorS4vAIaB5hxw/tA=
+k8s.io/client-go v0.0.0-20250630172937-5e8db78e0499/go.mod h1:S35/NV7N0qaT+n8zdnMvSHhv01b7Gh36CDzj/Ei/1G0=
+k8s.io/component-base v0.0.0-20250627214227-48c508093cdb h1:/SlQXukQyfHPZgdysGd7/sFbCbkAbUIYbdU/lix9YxA=
+k8s.io/component-base v0.0.0-20250627214227-48c508093cdb/go.mod h1:/vzEgMwklKytYpKL5RZgmP1G8vrqZCCefCKBixxOEDU=
 k8s.io/klog/v2 v2.130.1 h1:n9Xl7H1Xvksem4KFG4PYbdQCQxqc/tTUyrgXaOhHSzk=
 k8s.io/klog/v2 v2.130.1/go.mod h1:3Jpz1GvMt720eyJH1ckRHK1EDfpxISzJ7I9OYgaDtPE=
 k8s.io/kms v0.0.0-20250527175117-e6cd4d7331a4 h1:zom2NKyPKUou0oBny5sJa6yZotv/e31dPlvGctPVzU4=

pkg/endpoints/filterlatency/filterlatency.go

@@ -76,21 +76,20 @@ func trackStarted(handler http.Handler, tp trace.TracerProvider, name string, cl
 	// This is a noop if the tracing is disabled, since tp will be a NoopTracerProvider
 	tracer := tp.Tracer("k8s.op/apiserver/pkg/endpoints/filterlatency")
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		ctx := r.Context()
+		ctx, span := tracer.Start(r.Context(), name)
+		defer span.End()
 		if fr := requestFilterRecordFrom(ctx); fr != nil {
 			fr.name = name
 			fr.startedTimestamp = clock.Now()
-
-			handler.ServeHTTP(w, r)
-			return
-		}
-
+			r = r.WithContext(ctx)
+		} else {
 			fr := &requestFilterRecord{
 				name:             name,
 				startedTimestamp: clock.Now(),
 			}
-		ctx, _ = tracer.Start(ctx, name)
 			r = r.WithContext(withRequestFilterRecord(ctx, fr))
+		}
+
 		handler.ServeHTTP(w, r)
 	})
 }
@@ -106,6 +105,5 @@ func trackCompleted(handler http.Handler, clock clock.PassiveClock, action func(
 		if fr := requestFilterRecordFrom(ctx); fr != nil {
 			action(ctx, fr, completedAt)
 		}
-		trace.SpanFromContext(ctx).End()
 	})
 }

pkg/endpoints/filterlatency/filterlatency_test.go

@@ -221,3 +221,51 @@ func TestStartedAndCompletedOpenTelemetryTracing(t *testing.T) {
 		t.Fatalf("got %s; expected span.Name == my-filter", span.Name())
 	}
 }
+
+func TestNestedStartedAndCompletedOpenTelemetryTracing(t *testing.T) {
+	outerFilterName := "outer-filter"
+	innerFilterName := "inner-filter"
+	// Seup OTel for testing
+	fakeRecorder := tracetest.NewSpanRecorder()
+	tp := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(fakeRecorder))
+
+	// base handler func
+	var callCount int
+	handler := http.HandlerFunc(func(_ http.ResponseWriter, req *http.Request) {
+		// we expect the handler to be invoked just once.
+		callCount++
+	})
+	// wrap the handler with the inner start and completed handler
+	wrapped := TrackCompleted(handler)
+	wrapped = TrackStarted(wrapped, tp, innerFilterName)
+
+	// wrap with an external handler, nesting the inner span
+	wrapped = TrackCompleted(wrapped)
+	wrapped = TrackStarted(wrapped, tp, outerFilterName)
+
+	testRequest, err := http.NewRequest(http.MethodGet, "/api/v1/namespaces", nil)
+	if err != nil {
+		t.Fatalf("failed to create new http request - %v", err)
+	}
+
+	wrapped.ServeHTTP(httptest.NewRecorder(), testRequest)
+
+	if callCount != 1 {
+		t.Errorf("expected the given handler to be invoked once, but was actually invoked %d times", callCount)
+	}
+
+	checkSpans(t, fakeRecorder.Started(), []string{outerFilterName, innerFilterName})
+	checkSpans(t, fakeRecorder.Ended(), []string{innerFilterName, outerFilterName})
+}
+
+func checkSpans[T sdktrace.ReadOnlySpan](t *testing.T, output []T, spanNames []string) {
+	if len(output) != len(spanNames) {
+		t.Fatalf("got %d; expected len(output) == %d", len(output), len(spanNames))
+	}
+	for idx, spanName := range spanNames {
+		span := output[idx]
+		if span.Name() != spanName {
+			t.Fatalf("index %d: got %s; expected span.Name == %s", idx, span.Name(), spanName)
+		}
+	}
+}