otelhttp.WithClientTrace lost span when proxy can not connect

[ddatsh]

Description

otelhttp.WithClientTrace lost span when proxy can not connect

Environment

• OS: [e.g. win11]
• Architecture: [e.g. x86]
• Go Version: [e.g. 1.23.4]
• go.opentelemetry.io/contrib version: [e.g. v0.58.0]

Steps To Reproduce

1. Using this code ...

t := &http.Transport{}
t.Proxy = func(request *http.Request) (*url.URL, error) {
  // 127.0.0.1:10809 can not connect 
  return &url.URL{Scheme: "http", Host: "127.0.0.1:10809"}, nil
}

client = &http.Client{
Transport: otelhttp.NewTransport(
	t,
	otelhttp.WithClientTrace(func(ctx context.Context) *httptrace.ClientTrace {
		return otelhttptrace.NewClientTrace(ctx)
	}),
)}

client.Get("xxxxx")

2. Run ...
3. See error ...

go.opentelemetry.io\contrib\instrumentation\net\http\httptrace\otelhttptrace clienttrace.go

func (ct *clientTracer) gotConn(info httptrace.GotConnInfo) {

 ...
 ct.end("http.getconn", nil, attrs...) //  gotConn()   do not call when  127.0.0.1:10809 can not connect

now http.getconn span lost

func (ct *clientTracer) getConn(host string) {
	ct.start("http.getconn", "http.getconn", semconv.NetHostName(host))
}

Expected behavior

when 127.0.0.1:10809 works,

net/http/transport.go:1481

case r := <-w.result:
		// Trace success but only for HTTP/1.
		// HTTP/2 calls trace.GotConn itself.
		if r.pc != nil && r.pc.alt == nil && trace != nil && trace.GotConn != nil {
			info := httptrace.GotConnInfo{
				Conn:   r.pc.conn,
				Reused: r.pc.isReused(),
			}
			if !r.idleAt.IsZero() {
				info.WasIdle = true
				info.IdleTime = time.Since(r.idleAt)
			}
			trace.GotConn(info)      // will call  func (ct *clientTracer) getConn(host string) { ct.start("http.getconn",
		}

[railmisaka]

This problem is actually not specific to the proxy but occur every time the connection can not be established (with proxy or whatever). This is not important if we're using otelhttp.Transport or not.

Minimal example to reproduce:

// init trace provider

ctx := context.Background()
ctx := httptrace.WithClientTrace(ctx, otelhttptrace.NewClientTrace(ctx))
req, _ := http.NewRequest(http.MethodGet, "http://localhost:50000", nil)
req = req.WithContext(ctx)
http.DefaultClient.Do(req)

I also found a similar issue #2855

This happens because the span (http.getconn) closed in ClientTrace.GotConn, but the hook is not called, which also said in the comment:

// GotConn is called after a successful connection is
// obtained. There is no hook for failure to obtain a
// connection; instead, use the error from
// Transport.RoundTrip.

https://cs.opensource.google/go/go/+/master:src/net/http/httptrace/trace.go;l=91

(Btw WithoutSubSpans() works better - stil no http.getconn.done, but at least nothing red in the UI)

I've been thinking about this for a while and here's one option: Introduce a new ClientTraceOption like WithCancel(cancel *func(err error)) to provide a cancel callback which should be called by user in case of error to close the span (cancel might not be a best name though)

The usage could look like this:

// init trace provider

ctx := context.Background()
var cancel func(err error)
ctx = httptrace.WithClientTrace(ctx, otelhttptrace.NewClientTrace(ctx, otelhttptrace.WithCancel(&cancel)))

req, _ := http.NewRequest(http.MethodGet, "http://localhost:50000", nil)
req = req.WithContext(ctx)
_, err := http.DefaultClient.Do(req)
if err != nil {
    cancel(err)
}

[flc1125]

I guess you want to realize link tracking through the agent. This is my implementation, and it can report correctly.

package main

import (
	"net/http"
	"net/url"
	"testing"

	"github.com/davecgh/go-spew/spew"
	"github.com/stretchr/testify/require"
	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
	"go.opentelemetry.io/otel"
	"go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/sdk/trace/tracetest"
)

func TestProxy(t *testing.T) {
	imsb := tracetest.NewInMemoryExporter()
	otel.SetTracerProvider(trace.NewTracerProvider(trace.WithSyncer(imsb)))

	proxyURL, err := url.Parse("http://non-existent-proxy:1234")
	require.NoError(t, err)

	proxyTransport := &http.Transport{
		Proxy: http.ProxyURL(proxyURL),
	}

	client := &http.Client{
		Transport: otelhttp.NewTransport(proxyTransport),
	}

	client.Get("http://example.com")

	spew.Dump(imsb.GetSpans())
}

output:

GOROOT=/usr/local/go #gosetup
GOPATH=/Users/flc/go #gosetup
/usr/local/go/bin/go test -c -o /Users/flc/Library/Caches/JetBrains/GoLand2024.3/tmp/GoLand/___example__TestProxy.test example #gosetup
/usr/local/go/bin/go tool test2json -t /Users/flc/Library/Caches/JetBrains/GoLand2024.3/tmp/GoLand/___example__TestProxy.test -test.v=test2json -test.paniconexit0 -test.run ^\QTestProxy\E$ #gosetup
=== RUN   TestProxy
(tracetest.SpanStubs) (len=1 cap=1) {
 (tracetest.SpanStub) {
  Name: (string) (len=8) "HTTP GET",
  SpanContext: (trace.SpanContext) {
   traceID: (trace.TraceID) (len=16 cap=16) 91848bfd3834a1613d1b91926fd93579,
   spanID: (trace.SpanID) (len=8 cap=8) 6e3d7634b55852ba,
   traceFlags: (trace.TraceFlags) 01,
   traceState: (trace.TraceState) ,
   remote: (bool) false
  },
  Parent: (trace.SpanContext) {
   traceID: (trace.TraceID) (len=16 cap=16) 00000000000000000000000000000000,
   spanID: (trace.SpanID) (len=8 cap=8) 0000000000000000,
   traceFlags: (trace.TraceFlags) 00,
   traceState: (trace.TraceState) ,
   remote: (bool) false
  },
  SpanKind: (trace.SpanKind) client,
  StartTime: (time.Time) 2025-02-12 12:06:23.532882 +0800 CST m=+0.003988834,
  EndTime: (time.Time) 2025-02-12 12:06:23.592174875 +0800 CST m=+0.063281709,
  Attributes: ([]attribute.KeyValue) (len=3 cap=3) {
   (attribute.KeyValue) {
    Key: (attribute.Key) (len=11) "http.method",
    Value: (attribute.Value) {
     vtype: (attribute.Type) STRING,
     numeric: (uint64) 0,
     stringly: (string) (len=3) "GET",
     slice: (interface {}) <nil>
    }
   },
   (attribute.KeyValue) {
    Key: (attribute.Key) (len=8) "http.url",
    Value: (attribute.Value) {
     vtype: (attribute.Type) STRING,
     numeric: (uint64) 0,
     stringly: (string) (len=18) "http://example.com",
     slice: (interface {}) <nil>
    }
   },
   (attribute.KeyValue) {
    Key: (attribute.Key) (len=13) "net.peer.name",
    Value: (attribute.Value) {
     vtype: (attribute.Type) STRING,
     numeric: (uint64) 0,
     stringly: (string) (len=11) "example.com",
     slice: (interface {}) <nil>
    }
   }
  },
  Events: ([]trace.Event) (len=1 cap=1) {
   (trace.Event) {
    Name: (string) (len=9) "exception",
    Attributes: ([]attribute.KeyValue) (len=2 cap=2) {
     (attribute.KeyValue) {
      Key: (attribute.Key) (len=14) "exception.type",
      Value: (attribute.Value) {
       vtype: (attribute.Type) STRING,
       numeric: (uint64) 0,
       stringly: (string) (len=12) "*net.OpError",
       slice: (interface {}) <nil>
      }
     },
     (attribute.KeyValue) {
      Key: (attribute.Key) (len=17) "exception.message",
      Value: (attribute.Value) {
       vtype: (attribute.Type) STRING,
       numeric: (uint64) 0,
       stringly: (string) (len=73) "proxyconnect tcp: dial tcp 192.168.8.24:1234: connect: connection refused",
       slice: (interface {}) <nil>
      }
     }
    },
    DroppedAttributeCount: (int) 0,
    Time: (time.Time) 2025-02-12 12:06:23.592172 +0800 CST m=+0.063279209
   }
  },
  Links: ([]trace.Link) <nil>,
  Status: (trace.Status) {
   Code: (codes.Code) Error,
   Description: (string) (len=73) "proxyconnect tcp: dial tcp 192.168.8.24:1234: connect: connection refused"
  },
  DroppedAttributes: (int) 0,
  DroppedEvents: (int) 0,
  DroppedLinks: (int) 0,
  ChildSpanCount: (int) 0,
  Resource: (*resource.Resource)(0x140001627e0)(service.name=unknown_service:___example__TestProxy.test,telemetry.sdk.language=go,telemetry.sdk.name=opentelemetry,telemetry.sdk.version=1.33.0),
  InstrumentationScope: (instrumentation.Scope) {
   Name: (string) (len=61) "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp",
   Version: (string) (len=6) "0.59.0",
   SchemaURL: (string) "",
   Attributes: (attribute.Set) {
    equivalent: (attribute.Distinct) {
     iface: (interface {}) <nil>
    }
   }
  },
  InstrumentationLibrary: (instrumentation.Scope) {
   Name: (string) (len=61) "go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp",
   Version: (string) (len=6) "0.59.0",
   SchemaURL: (string) "",
   Attributes: (attribute.Set) {
    equivalent: (attribute.Distinct) {
     iface: (interface {}) <nil>
    }
   }
  }
 }
}
--- PASS: TestProxy (0.06s)
PASS