Race condition during Gin context cancellation #4588

yfeng997circle · 2023-11-17T15:08:27Z

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.

The text was updated successfully, but these errors were encountered:

marie-j · 2024-01-02T16:32:14Z

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

dmathieu · 2024-01-02T20:45:16Z

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.

dmathieu · 2024-01-02T20:47:26Z

cc @hanyuancheung per code owners.

mxmaxime · 2024-10-06T19:14:47Z

Hi, any news on this topic? 👀

dmathieu · 2024-10-07T07:27:58Z

Gin, having no code owner, is in the process of being deprecated/removed. Hence the lack of updates here.
#6190

flc1125 · 2024-11-21T12:21:57Z

defer func() {
	c.Request = c.Request.WithContext(savedCtx)
}()

I was wondering what would happen if I removed this paragraph.

As far as I know, it doesn't seem to cause any other problems. Maybe it just restores the Request.

But I found that it created other problems. This is the problem that has been found with it so far.

Using otelgin.Middleware will cause temporary MultipartForm files not to be destroyed. #5946

If there are any issues, you can let me know.

Additionally, if there are no problems, I plan to submit a PR to remove this part of the code.

yfeng997circle added area: instrumentation Related to an instrumentation package bug Something isn't working instrumentation: otelgin labels Nov 17, 2023

flc1125 mentioned this issue Nov 27, 2024

REQUEST: New membership for @flc1125 open-telemetry/community#2461

Closed

6 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Race condition during Gin context cancellation #4588

Race condition during Gin context cancellation #4588

yfeng997circle commented Nov 17, 2023

marie-j commented Jan 2, 2024

dmathieu commented Jan 2, 2024

dmathieu commented Jan 2, 2024

mxmaxime commented Oct 6, 2024

dmathieu commented Oct 7, 2024

flc1125 commented Nov 21, 2024 •

edited

Loading

Race condition during Gin context cancellation #4588

Race condition during Gin context cancellation #4588

Comments

yfeng997circle commented Nov 17, 2023

Description

Environment

Steps To Reproduce

Expected behavior

marie-j commented Jan 2, 2024

dmathieu commented Jan 2, 2024

dmathieu commented Jan 2, 2024

mxmaxime commented Oct 6, 2024

dmathieu commented Oct 7, 2024

flc1125 commented Nov 21, 2024 • edited Loading

flc1125 commented Nov 21, 2024 •

edited

Loading