From c64b6f80eb7bcf9f0d24e7f56fcced807a263b98 Mon Sep 17 00:00:00 2001 From: Kevin Conner Date: Mon, 11 Nov 2024 20:55:05 -0700 Subject: [PATCH 1/2] Trace across start handler invocations, nesting spans Signed-off-by: Kevin Conner --- .../endpoints/filterlatency/filterlatency.go | 20 ++++---- .../filterlatency/filterlatency_test.go | 48 +++++++++++++++++++ 2 files changed, 57 insertions(+), 11 deletions(-) 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..3967ab9b881 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, _ := tracer.Start(r.Context(), name) + defer trace.SpanFromContext(ctx).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 de138ca3ca0..e3805b7a6c6 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 @@ -216,3 +216,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) + } + } +} From 9f50740b7bcb41c81ec5b7939581b2bb10d641e4 Mon Sep 17 00:00:00 2001 From: Kevin Conner Date: Tue, 12 Nov 2024 12:43:53 -0800 Subject: [PATCH 2/2] Simplify span handling Co-authored-by: David Ashpole --- .../apiserver/pkg/endpoints/filterlatency/filterlatency.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 3967ab9b881..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,8 +76,8 @@ 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, _ := tracer.Start(r.Context(), name) - defer trace.SpanFromContext(ctx).End() + ctx, span := tracer.Start(r.Context(), name) + defer span.End() if fr := requestFilterRecordFrom(ctx); fr != nil { fr.name = name fr.startedTimestamp = clock.Now()