From 23c0b6c4794dd8e9b2b18d1e758a369513ba3897 Mon Sep 17 00:00:00 2001 From: dave sinclair Date: Mon, 9 Sep 2024 10:57:02 -0400 Subject: [PATCH] Fix Data Race with TraceLog - 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() :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() :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() :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() :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 --- tracelog/tracelog.go | 55 +++++++++++++++++++++++--------------------- 1 file changed, 29 insertions(+), 26 deletions(-) diff --git a/tracelog/tracelog.go b/tracelog/tracelog.go index 212a25407..9d0cf4a6f 100644 --- a/tracelog/tracelog.go +++ b/tracelog/tracelog.go @@ -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, } } @@ -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 @@ -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()}) } } @@ -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}) } } @@ -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()}) } } @@ -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 @@ -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, }) } } @@ -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}) } }