[BUG]: Data Race in httptrace.WithClientTimings(true)

[diegommm]

Tracer Version(s)

v2.6.0

Go Version(s)

go version go1.26.0 darwin/arm64

Bug Report

Super short summary

ObserveRoundTrip returns an AfterRoundTrip that can be executed before the *httpTraceTimings is completely written.

More details

newClientTrace returns an *httptrace.ClientTrace where the functions directly change the given *httpTraceTimings, but they don't protect it before writing. But ConnectDone does not need to be executed before ObserveRoundTrip returns, and the connection can be done at the same time we're trying to read the metrics and then we get a data race.

Reproduction Code

Run this with go run -race main.go (assuming you first go get github.com/DataDog/dd-trace-go/contrib/net/http/v2@v2.6.0 && go mod tidy):

package main

import (
        "context"
        "net"
        "net/http"
        "sync"

        httptrace "github.com/DataDog/dd-trace-go/contrib/net/http/v2"
)

func main() {
        l := must(net.Listen("tcp", ":0"))
        baseURL := "http://" + l.Addr().String()

        srv := &http.Server{
                Handler: http.HandlerFunc(func(http.ResponseWriter, *http.Request) {}),
        }
        go srv.Serve(l)
        defer srv.Shutdown(context.Background()) // will also call l.Close()

        http.DefaultClient = httptrace.WrapClient(http.DefaultClient, httptrace.WithClientTimings(true))

        const numGoroutines = 10
        const numReqs = 10

        var wg sync.WaitGroup
        for range numGoroutines {
                wg.Add(1)
                go func() {
                        defer wg.Done()

                        for range numReqs {
                                must(http.Get(baseURL)).Body.Close()
                        }
                }()
        }

        wg.Wait()
}

func must[T any](t T, err error) T {
        if err != nil {
                panic(err)
        }
        return t
}

Error Logs

==================
WARNING: DATA RACE
Read at 0x00c000830270 by goroutine 19:
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.(*httpTraceTimings).addTimingTags()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:51 +0x94
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.ObserveRoundTrip.func1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:182 +0x338
  github.com/DataDog/dd-trace-go/contrib/net/http/v2.(*roundTripper).RoundTrip()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/roundtripper.go:26 +0xa0
  net/http.send()
      /usr/local/go/src/net/http/client.go:264 +0x618
  net/http.(*Client).send()
      /usr/local/go/src/net/http/client.go:185 +0x2f8
  net/http.(*Client).do()
      /usr/local/go/src/net/http/client.go:733 +0xd90
  net/http.(*Client).Do()
      /usr/local/go/src/net/http/client.go:592 +0x90
  net/http.(*Client).Get()
      /usr/local/go/src/net/http/client.go:489 +0xa0
  net/http.Get()
      /usr/local/go/src/net/http/client.go:458 +0xdc
  main.main.func2()
      /Users/___/go/src/test/datadog-httptrace-data-race-poc/main.go:34 +0x90

Previous write at 0x00c000830270 by goroutine 113:
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.newClientTrace.func3()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:70 +0x48
  net.(*sysDialer).dialSingle()
      /usr/local/go/src/net/dial.go:778 +0x100
  net.(*sysDialer).dialSerial()
      /usr/local/go/src/net/dial.go:756 +0x1bc
  net.(*sysDialer).dialParallel.func1()
      /usr/local/go/src/net/dial.go:676 +0xa4
  net.(*sysDialer).dialParallel.gowrap2()
      /usr/local/go/src/net/dial.go:691 +0x4c

Goroutine 19 (running) created at:
  main.main()
      /Users/___/go/src/test/datadog-httptrace-data-race-poc/main.go:30 +0x3e4
  runtime.main()
      /usr/local/go/src/runtime/proc.go:290 +0x2b0
  github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.init.1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/v2@v2.6.0/ddtrace/tracer/seelog_leak_workaround.go:28 +0xa8
  github.com/cihub/seelog.(*asyncLogger).Close()
      /Users/___/go/pkg/mod/github.com/cihub/seelog@v0.0.0-20170130134532-f561c5e57575/behavior_asynclogger.go:77 +0xb8
  github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.init.1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/v2@v2.6.0/ddtrace/tracer/seelog_leak_workaround.go:27 +0x88

Goroutine 113 (running) created at:
  net.(*sysDialer).dialParallel()
      /usr/local/go/src/net/dial.go:691 +0x2e4
  net.(*Dialer).DialContext()
      /usr/local/go/src/net/dial.go:557 +0x618
  net.(*Dialer).DialContext-fm()
      <autogenerated>:1 +0x5c
  net/http.(*Transport).dial()
      /usr/local/go/src/net/http/transport.go:1307 +0x90
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1815 +0xa4c
  net/http.(*Transport).dialConnFor()
      /usr/local/go/src/net/http/transport.go:1648 +0xb0
  net/http.(*Transport).startDialConnForLocked.func1()
      /usr/local/go/src/net/http/transport.go:1629 +0x34
==================
==================
WARNING: DATA RACE
Read at 0x00c0005363a8 by goroutine 14:
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.(*httpTraceTimings).addTimingTags()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:51 +0xb8
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.ObserveRoundTrip.func1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:182 +0x338
  github.com/DataDog/dd-trace-go/contrib/net/http/v2.(*roundTripper).RoundTrip()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/roundtripper.go:26 +0xa0
  net/http.send()
      /usr/local/go/src/net/http/client.go:264 +0x618
  net/http.(*Client).send()
      /usr/local/go/src/net/http/client.go:185 +0x2f8
  net/http.(*Client).do()
      /usr/local/go/src/net/http/client.go:733 +0xd90
  net/http.(*Client).Do()
      /usr/local/go/src/net/http/client.go:592 +0x90
  net/http.(*Client).Get()
      /usr/local/go/src/net/http/client.go:489 +0xa0
  net/http.Get()
      /usr/local/go/src/net/http/client.go:458 +0xdc
  main.main.func2()
      /Users/___/go/src/test/datadog-httptrace-data-race-poc/main.go:34 +0x90

Previous write at 0x00c0005363a8 by goroutine 108:
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.newClientTrace.func4()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:71 +0x50
  net.(*sysDialer).dialSingle.func1()
      /usr/local/go/src/net/dial.go:781 +0xb4
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:668 +0x5c
  net.(*sysDialer).dialSerial()
      /usr/local/go/src/net/dial.go:756 +0x1bc
  net.(*sysDialer).dialParallel.func1()
      /usr/local/go/src/net/dial.go:676 +0xa4
  net.(*sysDialer).dialParallel.gowrap2()
      /usr/local/go/src/net/dial.go:691 +0x4c

Goroutine 14 (running) created at:
  main.main()
      /Users/___/go/src/test/datadog-httptrace-data-race-poc/main.go:30 +0x3e4
  runtime.main()
      /usr/local/go/src/runtime/proc.go:290 +0x2b0
  github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.init.1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/v2@v2.6.0/ddtrace/tracer/seelog_leak_workaround.go:28 +0xa8
  github.com/cihub/seelog.(*asyncLogger).Close()
      /Users/___/go/pkg/mod/github.com/cihub/seelog@v0.0.0-20170130134532-f561c5e57575/behavior_asynclogger.go:77 +0xb8
  github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.init.1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/v2@v2.6.0/ddtrace/tracer/seelog_leak_workaround.go:27 +0x88

Goroutine 108 (finished) created at:
  net.(*sysDialer).dialParallel()
      /usr/local/go/src/net/dial.go:691 +0x2e4
  net.(*Dialer).DialContext()
      /usr/local/go/src/net/dial.go:557 +0x618
  net.(*Dialer).DialContext-fm()
      <autogenerated>:1 +0x5c
  net/http.(*Transport).dial()
      /usr/local/go/src/net/http/transport.go:1307 +0x90
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1815 +0xa4c
  net/http.(*Transport).dialConnFor()
      /usr/local/go/src/net/http/transport.go:1648 +0xb0
  net/http.(*Transport).startDialConnForLocked.func1()
      /usr/local/go/src/net/http/transport.go:1629 +0x34
==================
==================
WARNING: DATA RACE
Write at 0x00c000830330 by goroutine 113:
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.newClientTrace.func4()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:71 +0x90
  net.(*sysDialer).dialSingle.func1()
      /usr/local/go/src/net/dial.go:781 +0xb4
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:668 +0x5c
  net.(*sysDialer).dialSerial()
      /usr/local/go/src/net/dial.go:756 +0x1bc
  net.(*sysDialer).dialParallel.func1()
      /usr/local/go/src/net/dial.go:676 +0xa4
  net.(*sysDialer).dialParallel.gowrap2()
      /usr/local/go/src/net/dial.go:691 +0x4c

Previous read at 0x00c000830330 by goroutine 19:
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.(*httpTraceTimings).addTimingTags()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:57 +0x214
  github.com/DataDog/dd-trace-go/contrib/net/http/v2/internal/wrap.ObserveRoundTrip.func1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/internal/wrap/roundtrip.go:182 +0x338
  github.com/DataDog/dd-trace-go/contrib/net/http/v2.(*roundTripper).RoundTrip()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/contrib/net/http/v2@v2.6.0/roundtripper.go:26 +0xa0
  net/http.send()
      /usr/local/go/src/net/http/client.go:264 +0x618
  net/http.(*Client).send()
      /usr/local/go/src/net/http/client.go:185 +0x2f8
  net/http.(*Client).do()
      /usr/local/go/src/net/http/client.go:733 +0xd90
  net/http.(*Client).Do()
      /usr/local/go/src/net/http/client.go:592 +0x90
  net/http.(*Client).Get()
      /usr/local/go/src/net/http/client.go:489 +0xa0
  net/http.Get()
      /usr/local/go/src/net/http/client.go:458 +0xdc
  main.main.func2()
      /Users/___/go/src/test/datadog-httptrace-data-race-poc/main.go:34 +0x90

Goroutine 113 (running) created at:
  net.(*sysDialer).dialParallel()
      /usr/local/go/src/net/dial.go:691 +0x2e4
  net.(*Dialer).DialContext()
      /usr/local/go/src/net/dial.go:557 +0x618
  net.(*Dialer).DialContext-fm()
      <autogenerated>:1 +0x5c
  net/http.(*Transport).dial()
      /usr/local/go/src/net/http/transport.go:1307 +0x90
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1815 +0xa4c
  net/http.(*Transport).dialConnFor()
      /usr/local/go/src/net/http/transport.go:1648 +0xb0
  net/http.(*Transport).startDialConnForLocked.func1()
      /usr/local/go/src/net/http/transport.go:1629 +0x34

Goroutine 19 (running) created at:
  main.main()
      /Users/___/go/src/test/datadog-httptrace-data-race-poc/main.go:30 +0x3e4
  runtime.main()
      /usr/local/go/src/runtime/proc.go:290 +0x2b0
  github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.init.1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/v2@v2.6.0/ddtrace/tracer/seelog_leak_workaround.go:28 +0xa8
  github.com/cihub/seelog.(*asyncLogger).Close()
      /Users/___/go/pkg/mod/github.com/cihub/seelog@v0.0.0-20170130134532-f561c5e57575/behavior_asynclogger.go:77 +0xb8
  github.com/DataDog/dd-trace-go/v2/ddtrace/tracer.init.1()
      /Users/___/go/pkg/mod/github.com/!data!dog/dd-trace-go/v2@v2.6.0/ddtrace/tracer/seelog_leak_workaround.go:27 +0x88
==================
Found 3 data race(s)
exit status 66

Go Env Output

No response

[mtoffl01]

Hi @diegommm , thanks for flagging. A fix is in progress; follow along with this PR: #4591

Thanks.