Skip to content

Commit

Permalink
Fix Data Race with TraceLog
Browse files Browse the repository at this point in the history 
- 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
  • Loading branch information
@stampy88
stampy88 committed Sep 9, 2024
1 parent d1205a6 commit 23c0b6c
Showing 1 changed file with 29 additions and 26 deletions.
55 changes: 29 additions & 26 deletions tracelog/tracelog.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -122,10 +122,13 @@ type TraceLogConfig struct {
TimeKey string
}

// defaultTimeKey is the name used in log statements for the timing, i.e. end time - start time, of an operation.
const defaultTimeKey = "time"

// DefaultTraceLogConfig returns the default configuration for TraceLog
func DefaultTraceLogConfig() *TraceLogConfig {
return &TraceLogConfig{
TimeKey: "time",
TimeKey: defaultTimeKey,
}
}

Expand All @@ -137,11 +140,11 @@ type TraceLog struct {
Config *TraceLogConfig
}

// ensureConfig initializes the Config field with default values if it is nil.
func (tl *TraceLog) ensureConfig() {
func (tl *TraceLog) determineTimeKey() string {
if tl.Config == nil {
tl.Config = DefaultTraceLogConfig()
return defaultTimeKey
}
return tl.Config.TimeKey
}

type ctxKey int
Expand Down Expand Up @@ -170,21 +173,21 @@ func (tl *TraceLog) TraceQueryStart(ctx context.Context, conn *pgx.Conn, data pg
}

func (tl *TraceLog) TraceQueryEnd(ctx context.Context, conn *pgx.Conn, data pgx.TraceQueryEndData) {
tl.ensureConfig()
queryData := ctx.Value(tracelogQueryCtxKey).(*traceQueryData)

endTime := time.Now()
interval := endTime.Sub(queryData.startTime)
timeKey := tl.determineTimeKey()

if data.Err != nil {
if tl.shouldLog(LogLevelError) {
tl.log(ctx, conn, LogLevelError, "Query", map[string]any{"sql": queryData.sql, "args": logQueryArgs(queryData.args), "err": data.Err, tl.Config.TimeKey: interval})
tl.log(ctx, conn, LogLevelError, "Query", map[string]any{"sql": queryData.sql, "args": logQueryArgs(queryData.args), "err": data.Err, timeKey: interval})
}
return
}

if tl.shouldLog(LogLevelInfo) {
tl.log(ctx, conn, LogLevelInfo, "Query", map[string]any{"sql": queryData.sql, "args": logQueryArgs(queryData.args), tl.Config.TimeKey: interval, "commandTag": data.CommandTag.String()})
tl.log(ctx, conn, LogLevelInfo, "Query", map[string]any{"sql": queryData.sql, "args": logQueryArgs(queryData.args), timeKey: interval, "commandTag": data.CommandTag.String()})
}
}

Expand Down Expand Up @@ -212,21 +215,21 @@ func (tl *TraceLog) TraceBatchQuery(ctx context.Context, conn *pgx.Conn, data pg
}

func (tl *TraceLog) TraceBatchEnd(ctx context.Context, conn *pgx.Conn, data pgx.TraceBatchEndData) {
tl.ensureConfig()
queryData := ctx.Value(tracelogBatchCtxKey).(*traceBatchData)

endTime := time.Now()
interval := endTime.Sub(queryData.startTime)
timeKey := tl.determineTimeKey()

if data.Err != nil {
if tl.shouldLog(LogLevelError) {
tl.log(ctx, conn, LogLevelError, "BatchClose", map[string]any{"err": data.Err, tl.Config.TimeKey: interval})
tl.log(ctx, conn, LogLevelError, "BatchClose", map[string]any{"err": data.Err, timeKey: interval})
}
return
}

if tl.shouldLog(LogLevelInfo) {
tl.log(ctx, conn, LogLevelInfo, "BatchClose", map[string]any{tl.Config.TimeKey: interval})
tl.log(ctx, conn, LogLevelInfo, "BatchClose", map[string]any{timeKey: interval})
}
}

Expand All @@ -245,21 +248,21 @@ func (tl *TraceLog) TraceCopyFromStart(ctx context.Context, conn *pgx.Conn, data
}

func (tl *TraceLog) TraceCopyFromEnd(ctx context.Context, conn *pgx.Conn, data pgx.TraceCopyFromEndData) {
tl.ensureConfig()
copyFromData := ctx.Value(tracelogCopyFromCtxKey).(*traceCopyFromData)

endTime := time.Now()
interval := endTime.Sub(copyFromData.startTime)
timeKey := tl.determineTimeKey()

if data.Err != nil {
if tl.shouldLog(LogLevelError) {
tl.log(ctx, conn, LogLevelError, "CopyFrom", map[string]any{"tableName": copyFromData.TableName, "columnNames": copyFromData.ColumnNames, "err": data.Err, tl.Config.TimeKey: interval})
tl.log(ctx, conn, LogLevelError, "CopyFrom", map[string]any{"tableName": copyFromData.TableName, "columnNames": copyFromData.ColumnNames, "err": data.Err, timeKey: interval})
}
return
}

if tl.shouldLog(LogLevelInfo) {
tl.log(ctx, conn, LogLevelInfo, "CopyFrom", map[string]any{"tableName": copyFromData.TableName, "columnNames": copyFromData.ColumnNames, "err": data.Err, tl.Config.TimeKey: interval, "rowCount": data.CommandTag.RowsAffected()})
tl.log(ctx, conn, LogLevelInfo, "CopyFrom", map[string]any{"tableName": copyFromData.TableName, "columnNames": copyFromData.ColumnNames, "err": data.Err, timeKey: interval, "rowCount": data.CommandTag.RowsAffected()})
}
}

Expand All @@ -276,20 +279,20 @@ func (tl *TraceLog) TraceConnectStart(ctx context.Context, data pgx.TraceConnect
}

func (tl *TraceLog) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEndData) {
tl.ensureConfig()
connectData := ctx.Value(tracelogConnectCtxKey).(*traceConnectData)

endTime := time.Now()
interval := endTime.Sub(connectData.startTime)
timeKey := tl.determineTimeKey()

if data.Err != nil {
if tl.shouldLog(LogLevelError) {
tl.Logger.Log(ctx, LogLevelError, "Connect", map[string]any{
"host": connectData.connConfig.Host,
"port": connectData.connConfig.Port,
"database": connectData.connConfig.Database,
tl.Config.TimeKey: interval,
"err": data.Err,
"host": connectData.connConfig.Host,
"port": connectData.connConfig.Port,
"database": connectData.connConfig.Database,
timeKey: interval,
"err": data.Err,
})
}
return
Expand All @@ -298,10 +301,10 @@ func (tl *TraceLog) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEn
if data.Conn != nil {
if tl.shouldLog(LogLevelInfo) {
tl.log(ctx, data.Conn, LogLevelInfo, "Connect", map[string]any{
"host": connectData.connConfig.Host,
"port": connectData.connConfig.Port,
"database": connectData.connConfig.Database,
tl.Config.TimeKey: interval,
"host": connectData.connConfig.Host,
"port": connectData.connConfig.Port,
"database": connectData.connConfig.Database,
timeKey: interval,
})
}
}
Expand All @@ -322,21 +325,21 @@ func (tl *TraceLog) TracePrepareStart(ctx context.Context, _ *pgx.Conn, data pgx
}

func (tl *TraceLog) TracePrepareEnd(ctx context.Context, conn *pgx.Conn, data pgx.TracePrepareEndData) {
tl.ensureConfig()
prepareData := ctx.Value(tracelogPrepareCtxKey).(*tracePrepareData)

endTime := time.Now()
interval := endTime.Sub(prepareData.startTime)
timeKey := tl.determineTimeKey()

if data.Err != nil {
if tl.shouldLog(LogLevelError) {
tl.log(ctx, conn, LogLevelError, "Prepare", map[string]any{"name": prepareData.name, "sql": prepareData.sql, "err": data.Err, tl.Config.TimeKey: interval})
tl.log(ctx, conn, LogLevelError, "Prepare", map[string]any{"name": prepareData.name, "sql": prepareData.sql, "err": data.Err, timeKey: interval})
}
return
}

if tl.shouldLog(LogLevelInfo) {
tl.log(ctx, conn, LogLevelInfo, "Prepare", map[string]any{"name": prepareData.name, "sql": prepareData.sql, tl.Config.TimeKey: interval, "alreadyPrepared": data.AlreadyPrepared})
tl.log(ctx, conn, LogLevelInfo, "Prepare", map[string]any{"name": prepareData.name, "sql": prepareData.sql, timeKey: interval, "alreadyPrepared": data.AlreadyPrepared})
}
}

Expand Down

0 comments on commit 23c0b6c

Please sign in to comment.