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

Trace across start handler invocations, nesting spans

staging/src/k8s.io/apiserver/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(),
+			}
+			r = r.WithContext(withRequestFilterRecord(ctx, fr))
 		}
 
-		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()
 	})
 }

staging/src/k8s.io/apiserver/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)
+		}
+	}
+}