From 506c017c2b1b85b004711c71516f1f807de5b1df Mon Sep 17 00:00:00 2001 From: Tonis Tiigi Date: Mon, 26 Feb 2024 21:59:53 -0800 Subject: [PATCH 1/5] otelhttptrace: handle missing getconn hook without panic We have many reports that end() gets called without the span being defined in start() and causes a panic. Signed-off-by: Tonis Tiigi --- CHANGELOG.md | 1 + .../net/http/httptrace/otelhttptrace/clienttrace.go | 4 ++++ 2 files changed, 5 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 16e09533c0b..0c25edbbf21 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -53,6 +53,7 @@ The next release will require at least [Go 1.22]. ### Fixed - Race condition when reading the HTTP body and writing the response in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#5916) +- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5187) ## [1.28.0/0.53.0/0.22.0/0.8.0/0.3.0/0.1.0] - 2024-07-02 diff --git a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go index 67e03f24810..6ef23721cb7 100644 --- a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go +++ b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go @@ -215,6 +215,10 @@ func (ct *clientTracer) start(hook, spanName string, attrs ...attribute.KeyValue func (ct *clientTracer) end(hook string, err error, attrs ...attribute.KeyValue) { if !ct.useSpans { + // sometimes end may be called without previous start + if ct.root == nil { + ct.root = trace.SpanFromContext(ct.Context) + } if err != nil { attrs = append(attrs, attribute.String(hook+".error", err.Error())) } From d7b32dfae6f51e6c430fef6b42046164d4cffbad Mon Sep 17 00:00:00 2001 From: Kranti Saini <7384112+krantideep95@users.noreply.github.com> Date: Wed, 31 Jul 2024 23:54:40 +0100 Subject: [PATCH 2/5] add tests for clientTracer.end --- .../otelhttptrace/clienttrace_test.go | 127 ++++++++++++++++++ 1 file changed, 127 insertions(+) diff --git a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go index 966473dd0c3..b6eebfe703e 100644 --- a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go +++ b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go @@ -5,9 +5,20 @@ package otelhttptrace import ( "context" + "errors" "fmt" "net/http" "net/http/httptrace" + "testing" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + sdktrace "go.opentelemetry.io/otel/sdk/trace" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + "go.opentelemetry.io/otel/trace" "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" ) @@ -32,3 +43,119 @@ func ExampleNewClientTrace() { fmt.Println(resp.Status) } + +func Test_clientTracer_end(t *testing.T) { + t.Run("end called with no parent clientTracer span", func(t *testing.T) { + fixture := prepareClientTraceTest() + fixture.ct.end("http.getconn", nil, HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) + assert.Len(t, fixture.spanRecorder.Ended(), 0) + }) + + t.Run("end called with no sub spans, no root span, and no errors", func(t *testing.T) { + fixture := prepareClientTraceTest() + WithoutSubSpans().apply(fixture.ct) + + ctx, span := fixture.tracer.Start(fixture.ct.Context, "client request") + fixture.ct.Context = ctx + + fixture.ct.end("http.getconn", nil, HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) + span.End() + + require.Len(t, fixture.spanRecorder.Ended(), 1) + recSpan := fixture.spanRecorder.Ended()[0] + + require.Len(t, recSpan.Events(), 1) + gotEvent := recSpan.Events()[0] + assert.Equal(t, "http.getconn.done", gotEvent.Name) + + assert.Equal(t, + []attribute.KeyValue{HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)}, + gotEvent.Attributes, + ) + }) + + t.Run("end called with no sub spans, root span set, and no errors", func(t *testing.T) { + fixture := prepareClientTraceTest() + WithoutSubSpans().apply(fixture.ct) + + ctx, span := fixture.tracer.Start(fixture.ct.Context, "client request") + fixture.ct.Context = ctx + fixture.ct.root = span + + fixture.ct.end("http.getconn", nil, HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) + span.End() + + require.Len(t, fixture.spanRecorder.Ended(), 1) + recSpan := fixture.spanRecorder.Ended()[0] + + require.Len(t, recSpan.Events(), 1) + gotEvent := recSpan.Events()[0] + assert.Equal(t, "http.getconn.done", gotEvent.Name) + + assert.Equal(t, + []attribute.KeyValue{ + HTTPConnectionReused.Bool(true), + HTTPConnectionWasIdle.Bool(true), + }, + gotEvent.Attributes, + ) + }) + + t.Run("end called with no sub spans, root span set, and error", func(t *testing.T) { + fixture := prepareClientTraceTest() + WithoutSubSpans().apply(fixture.ct) + + ctx, span := fixture.tracer.Start(fixture.ct.Context, "client request") + fixture.ct.Context = ctx + fixture.ct.root = span + + fixture.ct.end("http.getconn", errors.New("testError"), HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) + span.End() + + require.Len(t, fixture.spanRecorder.Ended(), 1) + recSpan := fixture.spanRecorder.Ended()[0] + + require.Len(t, recSpan.Events(), 1) + gotEvent := recSpan.Events()[0] + assert.Equal(t, "http.getconn.done", gotEvent.Name) + + assert.Equal(t, + []attribute.KeyValue{ + HTTPConnectionReused.Bool(true), + HTTPConnectionWasIdle.Bool(true), + attribute.Key("http.getconn.error").String("testError"), + }, + gotEvent.Attributes, + ) + }) +} + +type clientTraceTestFixture struct { + spanRecorder *tracetest.SpanRecorder + tracer trace.Tracer + ct *clientTracer +} + +func prepareClientTraceTest() clientTraceTestFixture { + fixture := clientTraceTestFixture{} + fixture.spanRecorder = tracetest.NewSpanRecorder() + provider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(fixture.spanRecorder)) + otel.SetTracerProvider(provider) + + fixture.tracer = provider.Tracer( + ScopeName, + trace.WithInstrumentationVersion(Version())) + + fixture.ct = &clientTracer{ + Context: context.Background(), + tracerProvider: otel.GetTracerProvider(), + root: nil, + tr: fixture.tracer, + activeHooks: make(map[string]context.Context), + redactedHeaders: map[string]struct{}{}, + addHeaders: true, + useSpans: true, + } + + return fixture +} From 67945df001649b1935c93b290541d74a4185d8b2 Mon Sep 17 00:00:00 2001 From: Kranti Saini <7384112+krantideep95@users.noreply.github.com> Date: Thu, 1 Aug 2024 00:13:20 +0100 Subject: [PATCH 3/5] CHANGELOG.md: update PR number for changelog entry --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0c25edbbf21..74808781c13 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -53,7 +53,7 @@ The next release will require at least [Go 1.22]. ### Fixed - Race condition when reading the HTTP body and writing the response in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#5916) -- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5187) +- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5965) ## [1.28.0/0.53.0/0.22.0/0.8.0/0.3.0/0.1.0] - 2024-07-02 From 6e6185e66e5d755cfe723ff8916db29a7b2b3fbf Mon Sep 17 00:00:00 2001 From: Kranti Saini <7384112+krantideep95@users.noreply.github.com> Date: Tue, 10 Sep 2024 23:31:54 +0100 Subject: [PATCH 4/5] move to otelhttptrace/test/clienttrace_test.go --- CHANGELOG.md | 2 +- .../otelhttptrace/clienttrace_test.go | 127 ------------------ .../otelhttptrace/test/clienttrace_test.go | 16 +++ 3 files changed, 17 insertions(+), 128 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 74808781c13..f2120caf850 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -21,6 +21,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - Superfluous call to `WriteHeader` when flushing after setting a status code in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#6074) - Superfluous call to `WriteHeader` when writing the response body after setting a status code in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#6055) +- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5965) @@ -53,7 +54,6 @@ The next release will require at least [Go 1.22]. ### Fixed - Race condition when reading the HTTP body and writing the response in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#5916) -- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5965) ## [1.28.0/0.53.0/0.22.0/0.8.0/0.3.0/0.1.0] - 2024-07-02 diff --git a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go index b6eebfe703e..966473dd0c3 100644 --- a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go +++ b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go @@ -5,20 +5,9 @@ package otelhttptrace import ( "context" - "errors" "fmt" "net/http" "net/http/httptrace" - "testing" - - "github.com/stretchr/testify/assert" - "github.com/stretchr/testify/require" - - "go.opentelemetry.io/otel" - "go.opentelemetry.io/otel/attribute" - sdktrace "go.opentelemetry.io/otel/sdk/trace" - "go.opentelemetry.io/otel/sdk/trace/tracetest" - "go.opentelemetry.io/otel/trace" "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp" ) @@ -43,119 +32,3 @@ func ExampleNewClientTrace() { fmt.Println(resp.Status) } - -func Test_clientTracer_end(t *testing.T) { - t.Run("end called with no parent clientTracer span", func(t *testing.T) { - fixture := prepareClientTraceTest() - fixture.ct.end("http.getconn", nil, HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) - assert.Len(t, fixture.spanRecorder.Ended(), 0) - }) - - t.Run("end called with no sub spans, no root span, and no errors", func(t *testing.T) { - fixture := prepareClientTraceTest() - WithoutSubSpans().apply(fixture.ct) - - ctx, span := fixture.tracer.Start(fixture.ct.Context, "client request") - fixture.ct.Context = ctx - - fixture.ct.end("http.getconn", nil, HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) - span.End() - - require.Len(t, fixture.spanRecorder.Ended(), 1) - recSpan := fixture.spanRecorder.Ended()[0] - - require.Len(t, recSpan.Events(), 1) - gotEvent := recSpan.Events()[0] - assert.Equal(t, "http.getconn.done", gotEvent.Name) - - assert.Equal(t, - []attribute.KeyValue{HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)}, - gotEvent.Attributes, - ) - }) - - t.Run("end called with no sub spans, root span set, and no errors", func(t *testing.T) { - fixture := prepareClientTraceTest() - WithoutSubSpans().apply(fixture.ct) - - ctx, span := fixture.tracer.Start(fixture.ct.Context, "client request") - fixture.ct.Context = ctx - fixture.ct.root = span - - fixture.ct.end("http.getconn", nil, HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) - span.End() - - require.Len(t, fixture.spanRecorder.Ended(), 1) - recSpan := fixture.spanRecorder.Ended()[0] - - require.Len(t, recSpan.Events(), 1) - gotEvent := recSpan.Events()[0] - assert.Equal(t, "http.getconn.done", gotEvent.Name) - - assert.Equal(t, - []attribute.KeyValue{ - HTTPConnectionReused.Bool(true), - HTTPConnectionWasIdle.Bool(true), - }, - gotEvent.Attributes, - ) - }) - - t.Run("end called with no sub spans, root span set, and error", func(t *testing.T) { - fixture := prepareClientTraceTest() - WithoutSubSpans().apply(fixture.ct) - - ctx, span := fixture.tracer.Start(fixture.ct.Context, "client request") - fixture.ct.Context = ctx - fixture.ct.root = span - - fixture.ct.end("http.getconn", errors.New("testError"), HTTPConnectionReused.Bool(true), HTTPConnectionWasIdle.Bool(true)) - span.End() - - require.Len(t, fixture.spanRecorder.Ended(), 1) - recSpan := fixture.spanRecorder.Ended()[0] - - require.Len(t, recSpan.Events(), 1) - gotEvent := recSpan.Events()[0] - assert.Equal(t, "http.getconn.done", gotEvent.Name) - - assert.Equal(t, - []attribute.KeyValue{ - HTTPConnectionReused.Bool(true), - HTTPConnectionWasIdle.Bool(true), - attribute.Key("http.getconn.error").String("testError"), - }, - gotEvent.Attributes, - ) - }) -} - -type clientTraceTestFixture struct { - spanRecorder *tracetest.SpanRecorder - tracer trace.Tracer - ct *clientTracer -} - -func prepareClientTraceTest() clientTraceTestFixture { - fixture := clientTraceTestFixture{} - fixture.spanRecorder = tracetest.NewSpanRecorder() - provider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(fixture.spanRecorder)) - otel.SetTracerProvider(provider) - - fixture.tracer = provider.Tracer( - ScopeName, - trace.WithInstrumentationVersion(Version())) - - fixture.ct = &clientTracer{ - Context: context.Background(), - tracerProvider: otel.GetTracerProvider(), - root: nil, - tr: fixture.tracer, - activeHooks: make(map[string]context.Context), - redactedHeaders: map[string]struct{}{}, - addHeaders: true, - useSpans: true, - } - - return fixture -} diff --git a/instrumentation/net/http/httptrace/otelhttptrace/test/clienttrace_test.go b/instrumentation/net/http/httptrace/otelhttptrace/test/clienttrace_test.go index 846f4fd128f..685ea49ec7c 100644 --- a/instrumentation/net/http/httptrace/otelhttptrace/test/clienttrace_test.go +++ b/instrumentation/net/http/httptrace/otelhttptrace/test/clienttrace_test.go @@ -250,6 +250,22 @@ func TestEndBeforeStartCreatesSpan(t *testing.T) { require.Len(t, spans, 1) } +func TestEndBeforeStartWithoutSubSpansDoesNotPanic(t *testing.T) { + sr := tracetest.NewSpanRecorder() + tp := trace.NewTracerProvider(trace.WithSpanProcessor(sr)) + otel.SetTracerProvider(tp) + + ct := otelhttptrace.NewClientTrace(context.Background(), otelhttptrace.WithoutSubSpans()) + + require.NotPanics(t, func() { + ct.DNSDone(httptrace.DNSDoneInfo{}) + }) + + // no spans created because we were just using background context without span + // and Start wasn't called which would have started a span + require.Len(t, sr.Ended(), 0) +} + type clientTraceTestFixture struct { Address string URL string From bf05062a696064d90fa0a7a9011ffe72952d1932 Mon Sep 17 00:00:00 2001 From: dmathieu <42@dmathieu.com> Date: Thu, 12 Sep 2024 09:05:14 +0200 Subject: [PATCH 5/5] move changelog entry to the unreleased section --- CHANGELOG.md | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7c48be22ba2..96a9981cc5f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -8,6 +8,10 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm ## [Unreleased] +### Fixed + +- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5965) + @@ -26,7 +30,6 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - Superfluous call to `WriteHeader` when flushing after setting a status code in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#6074) - Superfluous call to `WriteHeader` when writing the response body after setting a status code in `go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp`. (#6055) -- Possible nil dereference panic in `go.opentelemetry.io/contrib/instrumentation/net/http/httptrace/otelhttptrace`. (#5965) ## [1.29.0/0.54.0/0.23.0/0.9.0/0.4.0/0.2.0/0.1.0] - 2024-08-23