diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go index f2bbfe54371..694ac8880d9 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency.go +++ b/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() }) } diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency_test.go index 3ff8f5b7f77..ab181099edc 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/filterlatency/filterlatency_test.go +++ b/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) + } + } +}