opentelemetry-go-contrib Race condition during Gin context cancellation

Description

Using golang's race detector we identified a race condition with otelgin instrumentation. The race happens when

The read happens when Gin gonic, the go server, tries to cancel the Gin context and checks if a request has the proper context.
The write happens when opentelemetry, after instrumenting the http call with trace and span id, reverts the request context to original.

Below we give a detailed race report.

==================
WARNING: DATA RACE
Write at 0x00c001b7a920 by goroutine 61853:
  go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/otelgin.Middleware.func1.1()
      /home/runner/go/pkg/mod/go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/[email protected]/gintrace.go:68 +0x151
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.19.13/x64/src/runtime/panic.go:476 +0x32
  github.com/gin-gonic/gin.(*Context).Next()
      /home/runner/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174 +0x14a
  github.com/circlefin/platform-common-go/v4/middleware.recoveryWithLogger.func1()
      /home/runner/go/pkg/mod/github.com/circlefin/platform-common-go/[email protected]/middleware/recovery.go:58 +0xae
  github.com/gin-gonic/gin.(*Context).Next()
      /home/runner/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174 +0xb83
  github.com/gin-gonic/gin.(*Engine).handleHTTPRequest()
      /home/runner/go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:620 +0x779
  github.com/gin-gonic/gin.(*Engine).ServeHTTP()
      /home/runner/go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:576 +0x44b
  net/http.serverHandler.ServeHTTP()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:2947 +0x641
  net/http.(*conn).serve()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:1991 +0xbe4
  net/http.(*Server).Serve.func3()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:3102 +0x58

Previous read at 0x00c001b7a920 by goroutine 62212:
  github.com/gin-gonic/gin.(*Context).hasRequestContext()
      /home/runner/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:1186 +0xa7
  github.com/gin-gonic/gin.(*Context).Done()
      /home/runner/go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:1200 +0x14a
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.(*valueCtx).Done()
      <autogenerated>:1 +0x49
  context.parentCancelCtx()
      /opt/hostedtoolcache/go/1.19.13/x64/src/context/context.go:298 +0x3b
  context.removeChild()
      /opt/hostedtoolcache/go/1.19.13/x64/src/context/context.go:315 +0x44
  context.(*cancelCtx).cancel()
      /opt/hostedtoolcache/go/1.19.13/x64/src/context/context.go:421 +0x284
  context.WithCancel.func1()
      /opt/hostedtoolcache/go/1.19.13/x64/src/context/context.go:238 +0x4f
  runtime.deferreturn()
      /opt/hostedtoolcache/go/1.19.13/x64/src/runtime/panic.go:476 +0x32
  crypto/tls.(*Conn).HandshakeContext()
      /opt/hostedtoolcache/go/1.19.13/x64/src/crypto/tls/conn.go:1438 +0xae
  net/http.(*persistConn).addTLS.func2()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/transport.go:1538 +0x9a

Goroutine 61853 (running) created at:
  net/http.(*Server).Serve()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:3102 +0x837
  net/http.(*Server).ServeTLS()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:3142 +0x608
  net/http.(*Server).ListenAndServeTLS()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/server.go:3299 +0x175
  github.com/circlefin/platform-common-go/v4/public.(*Server).serveHTTPS()
      /home/runner/go/pkg/mod/github.com/circlefin/platform-common-go/[email protected]/public/server.go:37 +0x84
  github.com/circlefin/platform-common-go/v4/public.(*Server).Run()
      /home/runner/go/pkg/mod/github.com/circlefin/platform-common-go/[email protected]/public/server.go:23 +0x7e
  github.com/circlefin/platform-common-go/v4/common.(*Lifecycle).Run.func1()
      /home/runner/go/pkg/mod/github.com/circlefin/platform-common-go/[email protected]/common/lifecycle.go:47 +0x53
  github.com/circlefin/platform-common-go/v4/common.(*Lifecycle).Run.func3()
      /home/runner/go/pkg/mod/github.com/circlefin/platform-common-go/[email protected]/common/lifecycle.go:51 +0x58

Goroutine 62212 (finished) created at:
  net/http.(*persistConn).addTLS()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/transport.go:1534 +0x705
  net/http.(*Transport).dialConn()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/transport.go:1618 +0x12c4
  net/http.(*Transport).dialConnFor()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/transport.go:1450 +0x13a
  net/http.(*Transport).queueForDial.func1()
      /opt/hostedtoolcache/go/1.19.13/x64/src/net/http/transport.go:1419 +0x47
==================

Environment

OS: linux
Architecture: amd64
Go Version: 1.19
otelgin version: v0.45.0

Steps To Reproduce

This race is profiled using our internal codebase.

Expected behavior

The golang race detector shouldn't give a race report when using otelgin.

Nov 17 '23 15:11 yfeng997circle

We seem to be facing the same issue

Go Version: 1.21
otelgin version: v0.46.1

Running:

go test -race -p 1 ./...

Provides the stack trace below:

WARNING: DATA RACE
Write at 0x00c00028e420 by goroutine 63:
  go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/otelgin.Middleware.func1.1()
      /go/pkg/mod/go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/[email protected]/gintrace.go:69 +0x14e
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:477 +0x30
  github.com/gin-gonic/gin.(*Context).Next()
      /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:174 +0xb89
  github.com/gin-gonic/gin.(*Engine).handleHTTPRequest()
      /go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:620 +0x774
  github.com/gin-gonic/gin.(*Engine).ServeHTTP()
      /go/pkg/mod/github.com/gin-gonic/[email protected]/gin.go:576 +0x424
  github.com/wI2L/fizz.(*Fizz).ServeHTTP()
      /go/pkg/mod/github.com/w!i2!l/[email protected]/fizz.go:84 +0x84
  main.(*Router).ServeHTTP()
      <autogenerated>:1 +0x1f
  github.com/maxatome/go-testdeep/helpers/tdhttp.(*TestAPI).Request()
      /go/pkg/mod/github.com/maxatome/[email protected]/helpers/tdhttp/test_api.go:167 +0x24d
  github.com/maxatome/go-testdeep/helpers/tdhttp.(*TestAPI).Get()
      /go/pkg/mod/github.com/maxatome/[email protected]/helpers/tdhttp/test_api.go:208 +0x1bb
  main_test.(*MainTestSuite).SimpleTest()
      /tmp/id/main_test.go:40 +0xb9
  runtime.call16()
      /usr/local/go/src/runtime/asm_amd64.s:747 +0x42
  reflect.Value.Call()
      /usr/local/go/src/reflect/value.go:380 +0xb5
  reflect.Value.Call-fm()
      <autogenerated>:1 +0x7b
  github.com/maxatome/go-testdeep/helpers/tdsuite.run.func2()
      /go/pkg/mod/github.com/maxatome/[email protected]/helpers/tdsuite/suite.go:323 +0x4c9
  github.com/maxatome/go-testdeep/td.(*T).Run.func1()
      /go/pkg/mod/github.com/maxatome/[email protected]/td/t_struct.go:737 +0x136
  reflect.callReflect()
      /usr/local/go/src/reflect/value.go:782 +0x9e6
  reflect.callReflect()
      <autogenerated>:1 +0x56
  reflect.makeFuncStub()
      /usr/local/go/src/reflect/asm_amd64.s:47 +0x6d
  testing.(*T).Run.func1()
      /usr/local/go/src/testing/testing.go:1648 +0x44

Previous read at 0x00c00028e420 by goroutine 82:
  github.com/gin-gonic/gin.(*Context).hasRequestContext()
      /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:1186 +0x1ad
  github.com/gin-gonic/gin.(*Context).Value()
      /go/pkg/mod/github.com/gin-gonic/[email protected]/context.go:1229 +0x242
  context.value()
      /usr/local/go/src/context/context.go:782 +0x310
  context.(*valueCtx).Value()
      /usr/local/go/src/context/context.go:751 +0x91
  net.(*Resolver).lookupIPAddr()
      /usr/local/go/src/net/lookup.go:310 +0x1ac
  net.(*Resolver).internetAddrList()
      /usr/local/go/src/net/ipsock.go:288 +0x804
  net.(*Resolver).resolveAddrList()
      /usr/local/go/src/net/dial.go:282 +0x544
  net.(*Dialer).DialContext()
      /usr/local/go/src/net/dial.go:488 +0x706
  net.(*Dialer).DialContext-fm()
      <autogenerated>:1 +0x8f
  net/http.(*Transport).dial()
      /usr/local/go/src/net/http/transport.go:1183 +0xef
  net/http.(*Transport).dialConn()
      /usr/local/go/src/net/http/transport.go:1625 +0xdc4
  net/http.(*Transport).dialConnFor()
      /usr/local/go/src/net/http/transport.go:1467 +0x129
  net/http.(*Transport).queueForDial.func1()
      /usr/local/go/src/net/http/transport.go:1436 +0x44

Jan 02 '24 16:01 marie-j

I think this would need a change in the gin API. We can't create a mutex to change the gin context, as it wouldn't be used within gin itself.

Jan 02 '24 20:01 dmathieu

cc @hanyuancheung per code owners.

Jan 02 '24 20:01 dmathieu

opentelemetry-go-contrib opentelemetry-go-contrib copied to clipboard

Race condition during Gin context cancellation

Description

Environment

Steps To Reproduce

Expected behavior

opentelemetry-go-contrib
opentelemetry-go-contrib copied to clipboard