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.

Sign up for GitHub

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

Jump to bottom

Fix Data Race with TraceLog #2120

Closed
wants to merge 1 commit into from
Closed

Fix Data Race with TraceLog #2120

wants to merge 1 commit into from

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/[email protected]/tracelog/tracelog.go:142 +0x87
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/tracelog/tracelog.go:143 +0xe5
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/tracelog/tracelog.go:128 +0xb0
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/tracelog/tracelog.go:143 +0xdc
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:274 +0x5d

@stampy88
Fix Data Race with TraceLog
23c0b6c 
- 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/[email protected]/tracelog/tracelog.go:142 +0x87
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/tracelog/tracelog.go:143 +0xe5
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/tracelog/tracelog.go:128 +0xb0
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).ensureConfig()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/tracelog/tracelog.go:143 +0xdc
  github.com/jackc/pgx/v5/tracelog.(*TraceLog).TraceConnectEnd()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/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/[email protected]/conn.go:159 +0x144
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:227 +0x266
  github.com/jackc/puddle/v2.(*Pool[go.shape.*uint8]).CreateResource()
      /home/dave/go/pkg/mod/github.com/jackc/puddle/[email protected]/pool.go:614 +0x1a2
  github.com/jackc/pgx/v5/pgxpool.(*Pool).createIdleResources.func1()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/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/[email protected]/pgxpool/pool.go:489 +0xf6
  github.com/jackc/pgx/v5/pgxpool.NewWithConfig.func3()
      /home/dave/go/pkg/mod/github.com/jackc/pgx/[email protected]/pgxpool/pool.go:274 +0x5d
jackc added a commit that referenced this pull request Sep 10, 2024
@jackc
Fix data race with TraceLog.Config initialization
ce66b1d 
#2120
@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
ninedraft pushed a commit to ninedraft/pgx that referenced this pull request Dec 9, 2024
@jackc @ninedraft
Fix data race with TraceLog.Config initialization
da51345 
jackc#2120
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@stampy88 @jackc