From 7ac081e68f95b1b49e7e14d1ac1b4cb3dde90df6 Mon Sep 17 00:00:00 2001 From: coryb Date: Sun, 11 Jul 2021 13:22:18 -0700 Subject: [PATCH] Add WithoutSubSpans option to NewClientTrace This adds an optional behavior to NewClientTrace so that it only adds events and annotations to the span found in SpanFromContext. The default behavior remains unchanged, several sub-spans will be created for each request. This optional behavior is useful when tracing "complex" processes that have many http calls. In this case the added sub-spans become "noise" and may distract from the overall trace. This also adds several useful attributes from data available in the httptrace callbacks: http.conn.reused - bool if connection was reused http.conn.wasidle - bool if connection was idle http.conn.idletime - if wasidle, duration of idletime http.conn.start.network - start connection network type [tcp/udp] http.conn.done.network - end connection network type [tcp/udp] http.conn.done.addr - connection address when done http.dns.addrs - list of addrs returned from dns lookup Signed-off-by: coryb --- .../httptrace/otelhttptrace/clienttrace.go | 101 +++++++++++++--- .../otelhttptrace/clienttrace_test.go | 109 +++++++++++++++++- 2 files changed, 191 insertions(+), 19 deletions(-) diff --git a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go index e83cbf268d8..c5a66469d30 100644 --- a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go +++ b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace.go @@ -32,10 +32,17 @@ import ( // HTTP attributes. var ( - HTTPStatus = attribute.Key("http.status") - HTTPHeaderMIME = attribute.Key("http.mime") - HTTPRemoteAddr = attribute.Key("http.remote") - HTTPLocalAddr = attribute.Key("http.local") + HTTPStatus = attribute.Key("http.status") + HTTPHeaderMIME = attribute.Key("http.mime") + HTTPRemoteAddr = attribute.Key("http.remote") + HTTPLocalAddr = attribute.Key("http.local") + HTTPConnectionReused = attribute.Key("http.conn.reused") + HTTPConnectionWasIdle = attribute.Key("http.conn.wasidle") + HTTPConnectionIdleTime = attribute.Key("http.conn.idletime") + HTTPConnectionStartNetwork = attribute.Key("http.conn.start.network") + HTTPConnectionDoneNetwork = attribute.Key("http.conn.done.network") + HTTPConnectionDoneAddr = attribute.Key("http.conn.done.addr") + HTTPDNSAddrs = attribute.Key("http.dns.addrs") ) var ( @@ -53,6 +60,19 @@ func parentHook(hook string) string { return hookMap[hook] } +// ClientTraceOption allows customizations to how the httptrace.Client +// collects information. +type ClientTraceOption func(*clientTracer) + +// WithoutSubSpans will modify the httptrace.Client to only collect data +// as Events and Attributes on a span found in the context. By default +// sub-spans will be generated. +func WithoutSubSpans() ClientTraceOption { + return func(ct *clientTracer) { + ct.useSpans = false + } +} + type clientTracer struct { context.Context @@ -61,12 +81,17 @@ type clientTracer struct { activeHooks map[string]context.Context root trace.Span mtx sync.Mutex + useSpans bool } -func NewClientTrace(ctx context.Context) *httptrace.ClientTrace { +func NewClientTrace(ctx context.Context, opts ...ClientTraceOption) *httptrace.ClientTrace { ct := &clientTracer{ Context: ctx, activeHooks: make(map[string]context.Context), + useSpans: true, + } + for _, opt := range opts { + opt(ct) } ct.tr = otel.GetTracerProvider().Tracer( @@ -95,6 +120,14 @@ func NewClientTrace(ctx context.Context) *httptrace.ClientTrace { } func (ct *clientTracer) start(hook, spanName string, attrs ...attribute.KeyValue) { + if !ct.useSpans { + if ct.root == nil { + ct.root = trace.SpanFromContext(ct.Context) + } + ct.root.AddEvent(hook+".start", trace.WithAttributes(attrs...)) + return + } + ct.mtx.Lock() defer ct.mtx.Unlock() @@ -115,6 +148,15 @@ func (ct *clientTracer) start(hook, spanName string, attrs ...attribute.KeyValue } func (ct *clientTracer) end(hook string, err error, attrs ...attribute.KeyValue) { + if !ct.useSpans { + ct.root.AddEvent(hook + ".done") + if err != nil { + attrs = append(attrs, attribute.String(hook+".error", err.Error())) + } + ct.root.SetAttributes(attrs...) + return + } + ct.mtx.Lock() defer ct.mtx.Unlock() if ctx, ok := ct.activeHooks[hook]; ok { @@ -159,11 +201,16 @@ func (ct *clientTracer) getConn(host string) { } func (ct *clientTracer) gotConn(info httptrace.GotConnInfo) { - ct.end("http.getconn", - nil, + attrs := []attribute.KeyValue{ HTTPRemoteAddr.String(info.Conn.RemoteAddr().String()), HTTPLocalAddr.String(info.Conn.LocalAddr().String()), - ) + HTTPConnectionReused.Bool(info.Reused), + HTTPConnectionWasIdle.Bool(info.WasIdle), + } + if info.WasIdle { + attrs = append(attrs, HTTPConnectionIdleTime.String(info.IdleTime.String())) + } + ct.end("http.getconn", nil, attrs...) } func (ct *clientTracer) putIdleConn(err error) { @@ -179,15 +226,25 @@ func (ct *clientTracer) dnsStart(info httptrace.DNSStartInfo) { } func (ct *clientTracer) dnsDone(info httptrace.DNSDoneInfo) { - ct.end("http.dns", info.Err) + var addrs []string + for _, netAddr := range info.Addrs { + addrs = append(addrs, netAddr.String()) + } + ct.end("http.dns", info.Err, HTTPDNSAddrs.String(sliceToString(addrs))) } func (ct *clientTracer) connectStart(network, addr string) { - ct.start("http.connect."+addr, "http.connect", HTTPRemoteAddr.String(addr)) + ct.start("http.connect."+addr, "http.connect", + HTTPRemoteAddr.String(addr), + HTTPConnectionStartNetwork.String(network), + ) } func (ct *clientTracer) connectDone(network, addr string, err error) { - ct.end("http.connect."+addr, err) + ct.end("http.connect."+addr, err, + HTTPConnectionDoneAddr.String(addr), + HTTPConnectionDoneNetwork.String(network), + ) } func (ct *clientTracer) tlsHandshakeStart() { @@ -199,14 +256,14 @@ func (ct *clientTracer) tlsHandshakeDone(_ tls.ConnectionState, err error) { } func (ct *clientTracer) wroteHeaderField(k string, v []string) { - if ct.span("http.headers") == nil { + if ct.useSpans && ct.span("http.headers") == nil { ct.start("http.headers", "http.headers") } ct.root.SetAttributes(attribute.String("http."+strings.ToLower(k), sliceToString(v))) } func (ct *clientTracer) wroteHeaders() { - if ct.span("http.headers") != nil { + if ct.useSpans && ct.span("http.headers") != nil { ct.end("http.headers", nil) } ct.start("http.send", "http.send") @@ -220,15 +277,27 @@ func (ct *clientTracer) wroteRequest(info httptrace.WroteRequestInfo) { } func (ct *clientTracer) got100Continue() { - ct.span("http.receive").AddEvent("GOT 100 - Continue") + span := ct.root + if ct.useSpans { + span = ct.span("http.receive") + } + span.AddEvent("GOT 100 - Continue") } func (ct *clientTracer) wait100Continue() { - ct.span("http.receive").AddEvent("GOT 100 - Wait") + span := ct.root + if ct.useSpans { + span = ct.span("http.receive") + } + span.AddEvent("GOT 100 - Wait") } func (ct *clientTracer) got1xxResponse(code int, header textproto.MIMEHeader) error { - ct.span("http.receive").AddEvent("GOT 1xx", trace.WithAttributes( + span := ct.root + if ct.useSpans { + span = ct.span("http.receive") + } + span.AddEvent("GOT 1xx", trace.WithAttributes( HTTPStatus.Int(code), HTTPHeaderMIME.String(sm2s(header)), )) diff --git a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go index e2b0b887926..7bf19aac5b1 100644 --- a/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go +++ b/instrumentation/net/http/httptrace/otelhttptrace/clienttrace_test.go @@ -89,15 +89,20 @@ func TestHTTPRequestWithClientTrace(t *testing.T) { { name: "http.connect", attributes: map[attribute.Key]attribute.Value{ - attribute.Key("http.remote"): attribute.StringValue(address.String()), + attribute.Key("http.conn.done.addr"): attribute.StringValue(address.String()), + attribute.Key("http.conn.done.network"): attribute.StringValue("tcp"), + attribute.Key("http.conn.start.network"): attribute.StringValue("tcp"), + attribute.Key("http.remote"): attribute.StringValue(address.String()), }, parent: "http.getconn", }, { name: "http.getconn", attributes: map[attribute.Key]attribute.Value{ - attribute.Key("http.remote"): attribute.StringValue(address.String()), - attribute.Key("http.host"): attribute.StringValue(address.String()), + attribute.Key("http.remote"): attribute.StringValue(address.String()), + attribute.Key("http.host"): attribute.StringValue(address.String()), + attribute.Key("http.conn.reused"): attribute.BoolValue(false), + attribute.Key("http.conn.wasidle"): attribute.BoolValue(false), }, parent: "test", }, @@ -205,7 +210,13 @@ func TestConcurrentConnectionStart(t *testing.T) { expectedRemotes := []attribute.KeyValue{ attribute.String("http.remote", "127.0.0.1:3000"), + attribute.String("http.conn.start.network", "tcp"), + attribute.String("http.conn.done.addr", "127.0.0.1:3000"), + attribute.String("http.conn.done.network", "tcp"), attribute.String("http.remote", "[::1]:3000"), + attribute.String("http.conn.start.network", "tcp"), + attribute.String("http.conn.done.addr", "[::1]:3000"), + attribute.String("http.conn.done.network", "tcp"), } for _, tt := range tts { t.Run(tt.name, func(t *testing.T) { @@ -243,3 +254,95 @@ func TestEndBeforeStartCreatesSpan(t *testing.T) { spans := getSpansFromRecorder(sr, name) require.Len(t, spans, 1) } + +func TestWithoutSubSpans(t *testing.T) { + sr := &oteltest.SpanRecorder{} + otel.SetTracerProvider( + oteltest.NewTracerProvider(oteltest.WithSpanRecorder(sr)), + ) + + // Mock http server + ts := httptest.NewServer( + http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + }), + ) + defer ts.Close() + address := ts.Listener.Addr().String() + + ctx := context.Background() + ctx = httptrace.WithClientTrace(ctx, + otelhttptrace.NewClientTrace(ctx, + otelhttptrace.WithoutSubSpans(), + ), + ) + req, err := http.NewRequestWithContext(ctx, http.MethodGet, ts.URL, nil) + require.NoError(t, err) + resp, err := ts.Client().Do(req) + require.NoError(t, err) + resp.Body.Close() + // no spans created because we were just using background context without span + require.Len(t, sr.Completed(), 0) + + // Start again with a "real" span in the context, now tracing should add + // events and annotations. + ctx, span := otel.Tracer("oteltest").Start(context.Background(), "root") + ctx = httptrace.WithClientTrace(ctx, + otelhttptrace.NewClientTrace(ctx, + otelhttptrace.WithoutSubSpans(), + ), + ) + req, err = http.NewRequestWithContext(ctx, http.MethodGet, ts.URL, nil) + req.Header.Set("User-Agent", "oteltest/1.1") + require.NoError(t, err) + resp, err = ts.Client().Do(req) + require.NoError(t, err) + resp.Body.Close() + span.End() + // we just have the one span we created + require.Len(t, sr.Completed(), 1) + recSpan := sr.Completed()[0] + expectedEventNames := []string{ + "http.getconn.start", + "http.getconn.done", + "http.send.start", + "http.send.done", + "http.receive.start", + "http.receive.done", + } + gotEventNames := []string{} + for _, e := range recSpan.Events() { + gotEventNames = append(gotEventNames, e.Name) + } + assert.Equal(t, expectedEventNames, gotEventNames) + + gotAttributes := recSpan.Attributes() + require.Len(t, gotAttributes, 8) + assert.Equal(t, + attribute.StringValue("gzip"), + gotAttributes[attribute.Key("http.accept-encoding")], + ) + assert.Equal(t, + attribute.StringValue("oteltest/1.1"), + gotAttributes[attribute.Key("http.user-agent")], + ) + // value is dynamic, just verify we have the attribute + assert.Contains(t, gotAttributes, attribute.Key("http.conn.idletime")) + assert.Equal(t, + attribute.BoolValue(true), + gotAttributes[attribute.Key("http.conn.reused")], + ) + assert.Equal(t, + attribute.BoolValue(true), + gotAttributes[attribute.Key("http.conn.wasidle")], + ) + assert.Equal(t, + attribute.StringValue(address), + gotAttributes[attribute.Key("http.host")], + ) + assert.Equal(t, + attribute.StringValue(address), + gotAttributes[attribute.Key("http.remote")], + ) + // value is dynamic, just verify we have the attribute + assert.Contains(t, gotAttributes, attribute.Key("http.local")) +}