Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix Data Race with TraceLog #2120

Closed
wants to merge 1 commit into from
Closed

Conversation

stampy88
Copy link

@stampy88 stampy88 commented Sep 9, 2024

  • a DATA RACE was introduced with pgx 5.7.0 when using a pgxpool.Pool when minConns > 0. Changed from using lazy initialization to return the defaultTimeKey when the tl.Config is nil. Below are the stack traces emitted by the race detector:
==================
WARNING: DATA RACE
Read at 0x00c00094ca58 by goroutine 4079:
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:142 +0x87
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:279 +0x7f
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Previous write at 0x00c00094ca58 by goroutine 4080:
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:143 +0xe5
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:279 +0x7f
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Goroutine 4079 (running) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d

Goroutine 4080 (finished) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d
==================
==================
WARNING: DATA RACE
Read at 0x00c001433700 by goroutine 4079:
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:304 +0x472
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Previous write at 0x00c001433700 by goroutine 4080:
  github.com/jackc/pgx/v5/tracelog.DefaultTraceLogConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:128 +0xb0
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:143 +0xdc
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:279 +0x7f
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Goroutine 4079 (running) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d

Goroutine 4080 (finished) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d

- a `DATA RACE` was introduced with pgx 5.7.0 when using a `pgxpool.Pool` when `minConns > 0`. Changed from using lazy initialization to return the `defaultTimeKey` when the `tl.Config` is `nil`.
Below are the stack traces emitted by the race detector:
```
==================
WARNING: DATA RACE
Read at 0x00c00094ca58 by goroutine 4079:
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:142 +0x87
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:279 +0x7f
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Previous write at 0x00c00094ca58 by goroutine 4080:
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:143 +0xe5
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:279 +0x7f
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Goroutine 4079 (running) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d

Goroutine 4080 (finished) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d
==================
==================
WARNING: DATA RACE
Read at 0x00c001433700 by goroutine 4079:
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:304 +0x472
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Previous write at 0x00c001433700 by goroutine 4080:
  github.com/jackc/pgx/v5/tracelog.DefaultTraceLogConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:128 +0xb0
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:143 +0xdc
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/tracelog/tracelog.go:279 +0x7f
  github.com/xxxx//internal/pkg/pg.compositeTracer.TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/xxxx/@v1.80.1-0.20240906184531-58ce8cae9811/internal/pkg/pg/composite.go:66 +0xdd
  github.com/xxxx//internal/pkg/pg.(*compositeTracer).TraceConnectEnd()
      <autogenerated>:1 +0x37
  github.com/jackc/pgx/v5.connect.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:244 +0xa1
  runtime.deferreturn()
      /home/dave/go/go1.22.2/src/runtime/panic.go:602 +0x5d
  github.com/jackc/pgx/v5.ConnectConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/v2@v2.2.1/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:490 +0x76

Goroutine 4079 (running) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d

Goroutine 4080 (finished) created at:
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/v5@v5.7.0/pgxpool/pool.go:274 +0x5d
jackc added a commit that referenced this pull request Sep 10, 2024
@jackc
Copy link
Owner

jackc commented Sep 10, 2024

Thanks for the report. I ended up fixing it via Sync.Once instead in ce66b1d. Fix is released in v5.7.1.

@jackc jackc closed this Sep 10, 2024
@stampy88 stampy88 deleted the fix_data_race branch September 10, 2024 14:04
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants