diff --git a/go.mod b/go.mod index 14124f2da..8bda0aa3b 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 2fa3dadbf..2b689e696 100644 --- a/go.sum +++ b/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= diff --git a/pkg/endpoints/filterlatency/filterlatency.go b/pkg/endpoints/filterlatency/filterlatency.go index f2bbfe543..694ac8880 100644 --- a/pkg/endpoints/filterlatency/filterlatency.go +++ b/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/pkg/endpoints/filterlatency/filterlatency_test.go b/pkg/endpoints/filterlatency/filterlatency_test.go index 3ff8f5b7f..ab181099e 100644 --- a/pkg/endpoints/filterlatency/filterlatency_test.go +++ b/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) + } + } +}