diff --git a/dbtracer/consts.go b/dbtracer/consts.go new file mode 100644 index 0000000..12507c9 --- /dev/null +++ b/dbtracer/consts.go @@ -0,0 +1,13 @@ +package dbtracer + +import "go.opentelemetry.io/otel/attribute" + +const ( + SQLCQueryNameKey = attribute.Key("sqlc.query.name") + SQLCQueryTypeKey = attribute.Key("sqlc.query.type") + PGXOperationTypeKey = attribute.Key("pgx.operation.type") + PGXPrepareStmtNameKey = attribute.Key("pgx.prepare_stmt.name") + PGXStatusKey = attribute.Key("pgx.status") + + DBStatusCodeKey = attribute.Key("db.response.status_code") +) diff --git a/dbtracer/dbtracer.go b/dbtracer/dbtracer.go index 3989de4..7420816 100644 --- a/dbtracer/dbtracer.go +++ b/dbtracer/dbtracer.go @@ -1,15 +1,20 @@ package dbtracer import ( + "context" "encoding/hex" "errors" "fmt" "log/slog" + "time" "unicode/utf8" + "github.com/jackc/pgconn" "github.com/jackc/pgx/v5" "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/metric" + semconv "go.opentelemetry.io/otel/semconv/v1.26.0" "go.opentelemetry.io/otel/trace" ) @@ -33,6 +38,7 @@ type dbTracer struct { histogram metric.Float64Histogram traceProvider trace.TracerProvider traceLibraryName string + includeQueryText bool } func NewDBTracer( @@ -57,11 +63,12 @@ func NewDBTracer( unit string description string }{ - description: "The duration of database queries by sqlc function names", - unit: "s", - name: "db_query_duration", + description: semconv.DBClientOperationDurationDescription, + unit: semconv.DBClientOperationDurationUnit, + name: semconv.DBClientOperationDurationName, }, - logger: slog.Default(), + logger: slog.Default(), + includeSQLText: false, } for _, opt := range opts { opt(&optCtx) @@ -85,6 +92,7 @@ func NewDBTracer( histogram: histogram, traceProvider: optCtx.traceProvider, traceLibraryName: optCtx.name, + includeQueryText: optCtx.includeSQLText, }, nil } @@ -99,6 +107,39 @@ const ( dbTracerPrepareCtxKey ) +func (dt *dbTracer) recordSpanError(span trace.Span, err error) { + if err != nil && !errors.Is(err, pgx.ErrNoRows) { + span.RecordError(err) + span.SetStatus(codes.Error, err.Error()) + + var pgErr *pgconn.PgError + if errors.As(err, &pgErr) { + span.SetAttributes(DBStatusCodeKey.String(pgErr.Code)) + } + } +} + +func (dt *dbTracer) recordHistogramMetric(ctx context.Context, pgxOperation string, queryName string, duration time.Duration, err error) { + dt.histogram.Record(ctx, duration.Seconds(), metric.WithAttributes( + PGXStatusKey.String(pgxStatusFromErr(err)), + PGXOperationTypeKey.String(pgxOperation), + SQLCQueryNameKey.String(queryName), + )) +} + +func pgxStatusFromErr(err error) string { + if err == nil { + return "OK" + } + + var pgErr *pgconn.PgError + if errors.As(err, &pgErr) { + return pgErr.Severity + } + + return "UNKNOWN_ERROR" +} + func (dt *dbTracer) logQueryArgs(args []any) []any { if !dt.logArgs { return nil @@ -137,6 +178,16 @@ func (dt *dbTracer) logQueryArgs(args []any) []any { return logArgs } +func (dt *dbTracer) startSpan(ctx context.Context, name string) (context.Context, trace.Span) { + ctx, span := dt.getTracer().Start(ctx, name) + span.SetAttributes( + semconv.DBSystemPostgreSQL, + semconv.DBNamespace(dt.databaseName), + ) + + return ctx, span +} + func (dt *dbTracer) getTracer() trace.Tracer { return dt.traceProvider.Tracer(dt.traceLibraryName) } diff --git a/dbtracer/dbtracer_test.go b/dbtracer/dbtracer_test.go index 0cbbaa9..c27d111 100644 --- a/dbtracer/dbtracer_test.go +++ b/dbtracer/dbtracer_test.go @@ -7,7 +7,6 @@ import ( "fmt" "io" "log/slog" - "math/rand" "sync" "testing" "time" @@ -19,6 +18,7 @@ import ( "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" "go.opentelemetry.io/otel/metric" + semconv "go.opentelemetry.io/otel/semconv/v1.26.0" mockmetric "github.com/amirsalarsafaei/sqlc-pgx-monitoring/mocks/go.opentelemetry.io/otel/metric" mocktracer "github.com/amirsalarsafaei/sqlc-pgx-monitoring/mocks/go.opentelemetry.io/otel/trace" @@ -84,6 +84,13 @@ func (s *DBTracerSuite) SetupTest() { Float64Histogram(mock.Anything, mock.Anything, mock.Anything). Return(s.histogram, nil) + s.span.EXPECT(). + SetAttributes( + semconv.DBSystemPostgreSQL, + semconv.DBNamespace(s.defaultDBName), + ). + Return().Maybe() + var err error s.dbTracer, err = NewDBTracer( s.defaultDBName, @@ -114,9 +121,9 @@ func (s *DBTracerSuite) TestNewDBTracer() { Return(m) m.EXPECT(). Float64Histogram( - "db_query_duration", - metric.WithDescription("The duration of database queries by sqlc function names"), - metric.WithUnit("s"), + semconv.DBClientOperationDurationName, + metric.WithDescription(semconv.DBClientOperationDurationDescription), + metric.WithUnit(semconv.DBClientOperationDurationUnit), ). Return(h, nil) }, @@ -143,9 +150,9 @@ func (s *DBTracerSuite) TestNewDBTracer() { Return(m) m.EXPECT(). Float64Histogram( - "db_query_duration", - metric.WithDescription("The duration of database queries by sqlc function names"), - metric.WithUnit("s"), + semconv.DBClientOperationDurationName, + metric.WithDescription(semconv.DBClientOperationDurationDescription), + metric.WithUnit(semconv.DBClientOperationDurationUnit), ). Return(h, nil) }, @@ -238,10 +245,9 @@ func (s *DBTracerSuite) TestTraceQueryStart() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), + PGXOperationTypeKey.String("query"), ). Return() @@ -264,10 +270,9 @@ func (s *DBTracerSuite) TestTraceQueryEnd_Success() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), + PGXOperationTypeKey.String("query"), ). Return() @@ -286,10 +291,9 @@ func (s *DBTracerSuite) TestTraceQueryEnd_Success() { s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), s.matchAttributes( - attribute.String("operation", "query"), - attribute.String("query_name", "get_users"), - attribute.String("query_type", "one"), - attribute.Bool("error", false), + PGXOperationTypeKey.String("query"), + PGXStatusKey.String("OK"), + SQLCQueryNameKey.String("get_users"), )). Return() @@ -306,10 +310,9 @@ func (s *DBTracerSuite) TestTraceQueryDuration() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), + PGXOperationTypeKey.String("query"), ). Return() @@ -348,8 +351,7 @@ func (s *DBTracerSuite) TestTraceBatchDuration() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.operation", "batch"), + PGXOperationTypeKey.String("batch"), ). Return() @@ -357,11 +359,13 @@ func (s *DBTracerSuite) TestTraceBatchDuration() { s.span.EXPECT(). SetAttributes( - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), ). Return() + s.span.EXPECT().SetName(mock.Anything).Return() + s.span.EXPECT(). SetStatus(codes.Ok, ""). Return() @@ -398,16 +402,15 @@ func (s *DBTracerSuite) TestTracePrepareWithDuration() { stmtName := "get_user_by_id" s.tracer.EXPECT(). - Start(s.ctx, "postgresql.prepare"). + Start(s.ctx, "prepare.get_users"). Return(s.ctx, s.span) s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.operation", "prepare"), - attribute.String("db.prepared_statement_name", stmtName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), + PGXOperationTypeKey.String("prepare"), + PGXPrepareStmtNameKey.String(stmtName), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), ). Return() @@ -441,14 +444,20 @@ func (s *DBTracerSuite) TestTracePrepareWithDuration() { func (s *DBTracerSuite) TestTraceConnectSuccess() { connConfig := &pgx.ConnConfig{} + s.tracer.EXPECT().Start(mock.Anything, "postgresql.connect"). + Return(s.ctx, s.span) + ctx := s.dbTracer.TraceConnectStart(s.ctx, pgx.TraceConnectStartData{ ConnConfig: connConfig, }) + s.span.EXPECT().End().Return() + s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), s.matchAttributes( - attribute.String("operation", "connect"), - attribute.Bool("error", false), + PGXOperationTypeKey.String("connect"), + PGXStatusKey.String("OK"), + SQLCQueryNameKey.String("connect"), )). Return() @@ -464,13 +473,22 @@ func (s *DBTracerSuite) TestTraceConnectError() { connConfig := &pgx.ConnConfig{} expectedErr := errors.New("connection failed") + s.tracer.EXPECT().Start(mock.Anything, "postgresql.connect"). + Return(s.ctx, s.span) + ctx := s.dbTracer.TraceConnectStart(s.ctx, pgx.TraceConnectStartData{ ConnConfig: connConfig, }) + + s.span.EXPECT().End().Return() + s.span.EXPECT().RecordError(mock.Anything).Return() + s.span.EXPECT().SetStatus(mock.Anything, mock.Anything).Return() + s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), s.matchAttributes( - attribute.String("operation", "connect"), - attribute.Bool("error", true), + PGXOperationTypeKey.String("connect"), + PGXStatusKey.String("UNKNOWN_ERROR"), + SQLCQueryNameKey.String("connect"), )). Return() @@ -494,8 +512,7 @@ func (s *DBTracerSuite) TestTraceCopyFromSuccess() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.operation", "copy"), + PGXOperationTypeKey.String("copy_from"), attribute.String("db.table", "\"users\""), ). Return() @@ -515,9 +532,9 @@ func (s *DBTracerSuite) TestTraceCopyFromSuccess() { s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), s.matchAttributes( - attribute.String("operation", "copy"), - attribute.String("table", "\"users\""), - attribute.Bool("error", false), + PGXOperationTypeKey.String("copy_from"), + PGXStatusKey.String("OK"), + SQLCQueryNameKey.String("copy_from"), )). Return() @@ -538,8 +555,7 @@ func (s *DBTracerSuite) TestTraceCopyFromError() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.operation", "copy"), + PGXOperationTypeKey.String("copy_from"), attribute.String("db.table", "\"users\""), ). Return() @@ -566,9 +582,9 @@ func (s *DBTracerSuite) TestTraceCopyFromError() { s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), metric.WithAttributes( - attribute.String("operation", "copy"), - attribute.String("table", "\"users\""), - attribute.Bool("error", true), + PGXOperationTypeKey.String("copy_from"), + PGXStatusKey.String("UNKNOWN_ERROR"), + SQLCQueryNameKey.String("copy_from"), )). Return() @@ -582,16 +598,15 @@ func (s *DBTracerSuite) TestTracePrepareAlreadyPrepared() { stmtName := "get_user_by_id" s.tracer.EXPECT(). - Start(s.ctx, "postgresql.prepare"). + Start(s.ctx, "prepare.get_users"). Return(s.ctx, s.span) s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.operation", "prepare"), - attribute.String("db.prepared_statement_name", stmtName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), + PGXOperationTypeKey.String("prepare"), + PGXPrepareStmtNameKey.String(stmtName), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), ). Return() @@ -610,11 +625,9 @@ func (s *DBTracerSuite) TestTracePrepareAlreadyPrepared() { s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), metric.WithAttributes( - attribute.String("operation", "prepare"), - attribute.String("statement_name", stmtName), - attribute.String("query_name", "get_users"), - attribute.String("query_type", "one"), - attribute.Bool("error", false), + PGXOperationTypeKey.String("prepare"), + PGXStatusKey.String("OK"), + SQLCQueryNameKey.String("get_users"), )). Return() @@ -628,16 +641,15 @@ func (s *DBTracerSuite) TestTracePrepareError() { expectedErr := errors.New("prepare failed") s.tracer.EXPECT(). - Start(s.ctx, "postgresql.prepare"). + Start(s.ctx, "prepare.get_users"). Return(s.ctx, s.span) s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.operation", "prepare"), - attribute.String("db.prepared_statement_name", stmtName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), + PGXOperationTypeKey.String("prepare"), + PGXPrepareStmtNameKey.String(stmtName), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), ). Return() @@ -664,11 +676,9 @@ func (s *DBTracerSuite) TestTracePrepareError() { s.histogram.EXPECT(). Record(ctx, mock.AnythingOfType("float64"), metric.WithAttributes( - attribute.String("operation", "prepare"), - attribute.String("statement_name", stmtName), - attribute.String("query_name", "get_users"), - attribute.String("query_type", "one"), - attribute.Bool("error", true), + PGXOperationTypeKey.String("prepare"), + PGXStatusKey.String("UNKNOWN_ERROR"), + SQLCQueryNameKey.String("get_users"), )). Return() @@ -679,7 +689,7 @@ func (s *DBTracerSuite) TestTracePrepareError() { func (s *DBTracerSuite) TestTraceConcurrent() { numGoroutines := 10 - var wg sync.WaitGroup + var wg, startWg sync.WaitGroup results := make(chan error, numGoroutines) trigger := make(chan int) @@ -691,10 +701,9 @@ func (s *DBTracerSuite) TestTraceConcurrent() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), + PGXOperationTypeKey.String("query"), ). Return(). Times(numGoroutines) @@ -714,18 +723,19 @@ func (s *DBTracerSuite) TestTraceConcurrent() { Return(). Times(numGoroutines) + wg.Add(numGoroutines) + startWg.Add(numGoroutines) for i := 0; i < numGoroutines; i++ { - wg.Add(1) go func(id int, trigger <-chan int) { defer wg.Done() + startWg.Done() + startWg.Wait() ctx := s.dbTracer.TraceQueryStart(s.ctx, s.pgxConn, pgx.TraceQueryStartData{ SQL: s.defaultQuerySQL, Args: []interface{}{id}, }) - time.Sleep(time.Duration(rand.Intn(100)) * time.Millisecond) - s.dbTracer.TraceQueryEnd(ctx, s.pgxConn, pgx.TraceQueryEndData{ CommandTag: pgconn.CommandTag{}, Err: nil, @@ -735,8 +745,6 @@ func (s *DBTracerSuite) TestTraceConcurrent() { }(i, trigger) } - time.Sleep(500 * time.Millisecond) - close(trigger) wg.Wait() close(results) @@ -772,10 +780,9 @@ func (s *DBTracerSuite) TestLoggerBehavior() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), + PGXOperationTypeKey.String("query"), ). Return() @@ -820,10 +827,9 @@ func (s *DBTracerSuite) TestTraceQueryEndOnError() { s.span.EXPECT(). SetAttributes( - attribute.String("db.name", s.defaultDBName), - attribute.String("db.query_name", "get_users"), - attribute.String("db.query_type", "one"), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String("get_users"), + SQLCQueryTypeKey.String("one"), + PGXOperationTypeKey.String("query"), ). Return() diff --git a/dbtracer/options.go b/dbtracer/options.go index 0666f74..8b1d36b 100644 --- a/dbtracer/options.go +++ b/dbtracer/options.go @@ -22,6 +22,7 @@ type optionCtx struct { logger *slog.Logger logArgs bool logArgsLenLimit int + includeSQLText bool } type Option func(*optionCtx) @@ -69,3 +70,9 @@ func WithLogArgsLenLimit(limit int) Option { oc.logArgsLenLimit = limit } } + +func WithIncludeSQLText(includeSQLText bool) Option { + return func(oc *optionCtx) { + oc.includeSQLText = includeSQLText + } +} diff --git a/dbtracer/tracebatch.go b/dbtracer/tracebatch.go index afbe8e0..135b547 100644 --- a/dbtracer/tracebatch.go +++ b/dbtracer/tracebatch.go @@ -2,14 +2,12 @@ package dbtracer import ( "context" - "fmt" "log/slog" "time" "github.com/jackc/pgx/v5" - "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" - "go.opentelemetry.io/otel/metric" + semconv "go.opentelemetry.io/otel/semconv/v1.26.0" "go.opentelemetry.io/otel/trace" ) @@ -20,10 +18,9 @@ type traceBatchData struct { } func (dt *dbTracer) TraceBatchStart(ctx context.Context, _ *pgx.Conn, _ pgx.TraceBatchStartData) context.Context { - ctx, span := dt.getTracer().Start(ctx, "postgresql.batch") + ctx, span := dt.startSpan(ctx, "postgresql.batch") span.SetAttributes( - attribute.String("db.name", dt.databaseName), - attribute.String("db.operation", "batch"), + PGXOperationTypeKey.String("batch"), ) return context.WithValue(ctx, dbTracerBatchCtxKey, &traceBatchData{ startTime: time.Now(), @@ -33,12 +30,20 @@ func (dt *dbTracer) TraceBatchStart(ctx context.Context, _ *pgx.Conn, _ pgx.Trac func (dt *dbTracer) TraceBatchQuery(ctx context.Context, conn *pgx.Conn, data pgx.TraceBatchQueryData) { queryData := ctx.Value(dbTracerBatchCtxKey).(*traceBatchData) + if queryData == nil { + return + } queryName, queryType := queryNameFromSQL(data.SQL) queryData.queryName = queryName + queryData.span.SetAttributes( - attribute.String("db.query_name", queryName), - attribute.String("db.query_type", queryType), + SQLCQueryNameKey.String(queryName), + SQLCQueryTypeKey.String(queryType), ) + queryData.span.SetName(queryName) + if dt.includeQueryText { + queryData.span.SetAttributes(semconv.DBQueryText(data.SQL)) + } if data.Err != nil { queryData.span.SetStatus(codes.Error, data.Err.Error()) @@ -46,7 +51,7 @@ func (dt *dbTracer) TraceBatchQuery(ctx context.Context, conn *pgx.Conn, data pg if dt.shouldLog(data.Err) { dt.logger.LogAttrs(ctx, slog.LevelError, - "Query", + queryName, slog.String("sql", data.SQL), slog.Any("args", dt.logQueryArgs(data.Args)), slog.Uint64("pid", uint64(extractConnectionID(conn))), @@ -56,7 +61,7 @@ func (dt *dbTracer) TraceBatchQuery(ctx context.Context, conn *pgx.Conn, data pg } else { queryData.span.SetStatus(codes.Ok, "") dt.logger.LogAttrs(ctx, slog.LevelInfo, - "Query", + queryName, slog.String("sql", data.SQL), slog.Any("args", dt.logQueryArgs(data.Args)), slog.Uint64("pid", uint64(extractConnectionID(conn))), @@ -67,23 +72,22 @@ func (dt *dbTracer) TraceBatchQuery(ctx context.Context, conn *pgx.Conn, data pg func (dt *dbTracer) TraceBatchEnd(ctx context.Context, conn *pgx.Conn, data pgx.TraceBatchEndData) { queryData := ctx.Value(dbTracerBatchCtxKey).(*traceBatchData) + if queryData == nil { + return + } defer queryData.span.End() endTime := time.Now() interval := endTime.Sub(queryData.startTime) - dt.histogram.Record(ctx, interval.Seconds(), metric.WithAttributes( - attribute.String("operation", "batch"), - attribute.String("query_name", queryData.queryName), - attribute.Bool("error", data.Err != nil), - )) + + dt.recordHistogramMetric(ctx, "batch", queryData.queryName, interval, data.Err) if data.Err != nil { - queryData.span.SetStatus(codes.Error, data.Err.Error()) - queryData.span.RecordError(data.Err) + dt.recordSpanError(queryData.span, data.Err) if dt.shouldLog(data.Err) { dt.logger.LogAttrs(ctx, slog.LevelError, - fmt.Sprintf("Query: %s", queryData.queryName), + "batch queries", slog.Duration("interval", interval), slog.Uint64("pid", uint64(extractConnectionID(conn))), slog.String("error", data.Err.Error()), @@ -92,7 +96,7 @@ func (dt *dbTracer) TraceBatchEnd(ctx context.Context, conn *pgx.Conn, data pgx. } else { queryData.span.SetStatus(codes.Ok, "") dt.logger.LogAttrs(ctx, slog.LevelInfo, - "Query", + "batch queries", slog.Duration("interval", interval), slog.Uint64("pid", uint64(extractConnectionID(conn))), ) diff --git a/dbtracer/traceconnect.go b/dbtracer/traceconnect.go index d59d11e..b7ffd7b 100644 --- a/dbtracer/traceconnect.go +++ b/dbtracer/traceconnect.go @@ -6,19 +6,22 @@ import ( "time" "github.com/jackc/pgx/v5" - "go.opentelemetry.io/otel/attribute" - "go.opentelemetry.io/otel/metric" + "go.opentelemetry.io/otel/trace" ) type traceConnectData struct { + span trace.Span startTime time.Time connConfig *pgx.ConnConfig } func (dt *dbTracer) TraceConnectStart(ctx context.Context, data pgx.TraceConnectStartData) context.Context { + ctx, span := dt.startSpan(ctx, "postgresql.connect") + return context.WithValue(ctx, dbTracerConnectCtxKey, &traceConnectData{ startTime: time.Now(), connConfig: data.ConnConfig, + span: span, }) } @@ -28,12 +31,13 @@ func (dt *dbTracer) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEn endTime := time.Now() interval := endTime.Sub(connectData.startTime) - dt.histogram.Record(ctx, interval.Seconds(), metric.WithAttributes( - attribute.String("operation", "connect"), - attribute.Bool("error", data.Err != nil), - )) + dt.recordHistogramMetric(ctx, "connect", "connect", interval, data.Err) + + defer connectData.span.End() if data.Err != nil { + dt.recordSpanError(connectData.span, data.Err) + if dt.shouldLog(data.Err) { dt.logger.LogAttrs(ctx, slog.LevelError, "database connect", @@ -41,11 +45,10 @@ func (dt *dbTracer) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEn slog.Uint64("port", uint64(connectData.connConfig.Port)), slog.String("database", connectData.connConfig.Database), slog.Duration("time", interval), - slog.String("error", data.Err.Error()), + slog.Any("error", data.Err), ) } return - } dt.logger.LogAttrs(ctx, slog.LevelInfo, @@ -55,14 +58,4 @@ func (dt *dbTracer) TraceConnectEnd(ctx context.Context, data pgx.TraceConnectEn slog.String("database", connectData.connConfig.Database), slog.Duration("time", interval), ) - - if data.Conn != nil { - dt.logger.LogAttrs(ctx, slog.LevelInfo, - "database connect", - slog.String("host", connectData.connConfig.Host), - slog.Uint64("port", uint64(connectData.connConfig.Port)), - slog.String("database", connectData.connConfig.Database), - slog.Duration("time", interval), - ) - } } diff --git a/dbtracer/tracecopyfrom.go b/dbtracer/tracecopyfrom.go index 8dcd13f..8e7d71d 100644 --- a/dbtracer/tracecopyfrom.go +++ b/dbtracer/tracecopyfrom.go @@ -8,7 +8,6 @@ import ( "github.com/jackc/pgx/v5" "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" - "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" ) @@ -20,10 +19,9 @@ type traceCopyFromData struct { } func (dt *dbTracer) TraceCopyFromStart(ctx context.Context, _ *pgx.Conn, data pgx.TraceCopyFromStartData) context.Context { - ctx, span := dt.getTracer().Start(ctx, "postgresql.copy_from") + ctx, span := dt.startSpan(ctx, "postgresql.copy_from") span.SetAttributes( - attribute.String("db.name", dt.databaseName), - attribute.String("db.operation", "copy"), + PGXOperationTypeKey.String("copy_from"), attribute.String("db.table", data.TableName.Sanitize()), ) return context.WithValue(ctx, dbTracerCopyFromCtxKey, &traceCopyFromData{ @@ -40,15 +38,10 @@ func (dt *dbTracer) TraceCopyFromEnd(ctx context.Context, conn *pgx.Conn, data p endTime := time.Now() interval := endTime.Sub(copyFromData.startTime) - dt.histogram.Record(ctx, interval.Seconds(), metric.WithAttributes( - attribute.String("operation", "copy"), - attribute.String("table", copyFromData.TableName.Sanitize()), - attribute.Bool("error", data.Err != nil), - )) + dt.recordHistogramMetric(ctx, "copy_from", "copy_from", interval, data.Err) if data.Err != nil { - copyFromData.span.SetStatus(codes.Error, data.Err.Error()) - copyFromData.span.RecordError(data.Err) + dt.recordSpanError(copyFromData.span, data.Err) if dt.shouldLog(data.Err) { dt.logger.LogAttrs(ctx, slog.LevelError, diff --git a/dbtracer/traceprepare.go b/dbtracer/traceprepare.go index e04dc38..daa5df8 100644 --- a/dbtracer/traceprepare.go +++ b/dbtracer/traceprepare.go @@ -2,13 +2,13 @@ package dbtracer import ( "context" + "fmt" "log/slog" "time" "github.com/jackc/pgx/v5" - "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" - "go.opentelemetry.io/otel/metric" + semconv "go.opentelemetry.io/otel/semconv/v1.26.0" "go.opentelemetry.io/otel/trace" ) @@ -27,14 +27,18 @@ func (dt *dbTracer) TracePrepareStart( data pgx.TracePrepareStartData, ) context.Context { queryName, queryType := queryNameFromSQL(data.SQL) - ctx, span := dt.getTracer().Start(ctx, "postgresql.prepare") + ctx, span := dt.startSpan(ctx, fmt.Sprintf("prepare.%s", queryName)) span.SetAttributes( - attribute.String("db.name", dt.databaseName), - attribute.String("db.operation", "prepare"), - attribute.String("db.prepared_statement_name", data.Name), - attribute.String("db.query_name", queryName), - attribute.String("db.query_type", queryType), + PGXOperationTypeKey.String("prepare"), + PGXPrepareStmtNameKey.String(data.Name), + SQLCQueryNameKey.String(queryName), + SQLCQueryTypeKey.String(queryType), ) + + if dt.includeQueryText { + span.SetAttributes(semconv.DBQueryText(data.SQL)) + } + return context.WithValue(ctx, dbTracerPrepareCtxKey, &tracePrepareData{ startTime: time.Now(), statementName: data.Name, @@ -55,17 +59,11 @@ func (dt *dbTracer) TracePrepareEnd( endTime := time.Now() interval := endTime.Sub(prepareData.startTime) - dt.histogram.Record(ctx, interval.Seconds(), metric.WithAttributes( - attribute.String("operation", "prepare"), - attribute.String("statement_name", prepareData.statementName), - attribute.String("query_name", prepareData.queryName), - attribute.String("query_type", prepareData.queryType), - attribute.Bool("error", data.Err != nil), - )) + dt.recordHistogramMetric(ctx, "prepare", prepareData.queryName, interval, data.Err) if data.Err != nil { - prepareData.span.SetStatus(codes.Error, data.Err.Error()) - prepareData.span.RecordError(data.Err) + dt.recordSpanError(prepareData.span, data.Err) + if dt.shouldLog(data.Err) { dt.logger.LogAttrs(ctx, slog.LevelError, "prepare failed", diff --git a/dbtracer/tracequery.go b/dbtracer/tracequery.go index d36c9d0..368fc33 100644 --- a/dbtracer/tracequery.go +++ b/dbtracer/tracequery.go @@ -7,9 +7,8 @@ import ( "time" "github.com/jackc/pgx/v5" - "go.opentelemetry.io/otel/attribute" "go.opentelemetry.io/otel/codes" - "go.opentelemetry.io/otel/metric" + semconv "go.opentelemetry.io/otel/semconv/v1.26.0" "go.opentelemetry.io/otel/trace" ) @@ -28,13 +27,17 @@ func (dt *dbTracer) TraceQueryStart( data pgx.TraceQueryStartData, ) context.Context { queryName, queryType := queryNameFromSQL(data.SQL) - ctx, span := dt.getTracer().Start(ctx, "postgresql.query") + ctx, span := dt.startSpan(ctx, "postgresql.query") span.SetAttributes( - attribute.String("db.name", dt.databaseName), - attribute.String("db.query_name", queryName), - attribute.String("db.query_type", queryType), - attribute.String("db.operation", "query"), + SQLCQueryNameKey.String(queryName), + SQLCQueryTypeKey.String(queryType), + PGXOperationTypeKey.String("query"), ) + + if dt.includeQueryText { + span.SetAttributes(semconv.DBQueryText(data.SQL)) + } + return context.WithValue(ctx, dbTracerQueryCtxKey, &traceQueryData{ startTime: time.Now(), sql: data.SQL, @@ -50,19 +53,13 @@ func (dt *dbTracer) TraceQueryEnd(ctx context.Context, conn *pgx.Conn, data pgx. endTime := time.Now() interval := endTime.Sub(queryData.startTime) - histogramAttrs := []attribute.KeyValue{ - attribute.String("operation", "query"), - attribute.String("query_name", queryData.queryName), - attribute.String("query_type", queryData.queryType), - attribute.Bool("error", data.Err != nil), - } - dt.histogram.Record(ctx, interval.Seconds(), metric.WithAttributes(histogramAttrs...)) + + dt.recordHistogramMetric(ctx, "query", queryData.queryName, interval, data.Err) defer queryData.span.End() if data.Err != nil { - queryData.span.SetStatus(codes.Error, data.Err.Error()) - queryData.span.RecordError(data.Err) + dt.recordSpanError(queryData.span, data.Err) if dt.shouldLog(data.Err) { dt.logger.LogAttrs(ctx, slog.LevelError, diff --git a/go.mod b/go.mod index 9c252e7..4e8fd9a 100644 --- a/go.mod +++ b/go.mod @@ -12,10 +12,17 @@ require ( go.opentelemetry.io/otel/trace v1.33.0 ) +require ( + github.com/jackc/chunkreader/v2 v2.0.1 // indirect + github.com/jackc/pgio v1.0.0 // indirect + github.com/jackc/pgproto3/v2 v2.3.3 // indirect +) + require ( github.com/davecgh/go-spew v1.1.1 // indirect github.com/go-logr/logr v1.4.2 // indirect github.com/go-logr/stdr v1.2.2 // indirect + github.com/jackc/pgconn v1.14.3 github.com/jackc/pgpassfile v1.0.0 // indirect github.com/jackc/pgservicefile v0.0.0-20221227161230-091c0ba34f0a // indirect github.com/jackc/puddle/v2 v2.2.1 // indirect diff --git a/go.sum b/go.sum index 75bd9ff..af06e42 100644 --- a/go.sum +++ b/go.sum @@ -8,8 +8,17 @@ github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= +github.com/jackc/chunkreader/v2 v2.0.0/go.mod h1:odVSm741yZoC3dpHEUXIqA9tQRhFrgOHwnPIn9lDKlk= +github.com/jackc/chunkreader/v2 v2.0.1 h1:i+RDz65UE+mmpjTfyz0MoVTnzeYxroil2G82ki7MGG8= +github.com/jackc/chunkreader/v2 v2.0.1/go.mod h1:odVSm741yZoC3dpHEUXIqA9tQRhFrgOHwnPIn9lDKlk= +github.com/jackc/pgconn v1.14.3 h1:bVoTr12EGANZz66nZPkMInAV/KHD2TxH9npjXXgiB3w= +github.com/jackc/pgconn v1.14.3/go.mod h1:RZbme4uasqzybK2RK5c65VsHxoyaml09lx3tXOcO/VM= +github.com/jackc/pgio v1.0.0 h1:g12B9UwVnzGhueNavwioyEEpAmqMe1E/BN9ES+8ovkE= +github.com/jackc/pgio v1.0.0/go.mod h1:oP+2QK2wFfUWgr+gxjoBH9KGBb31Eio69xUb0w5bYf8= github.com/jackc/pgpassfile v1.0.0 h1:/6Hmqy13Ss2zCq62VdNG8tM1wchn8zjSGOBJ6icpsIM= github.com/jackc/pgpassfile v1.0.0/go.mod h1:CEx0iS5ambNFdcRtxPj5JhEz+xB6uRky5eyVu/W2HEg= +github.com/jackc/pgproto3/v2 v2.3.3 h1:1HLSx5H+tXR9pW3in3zaztoEwQYRC9SQaYUHjTSUOag= +github.com/jackc/pgproto3/v2 v2.3.3/go.mod h1:WfJCnwN3HIg9Ish/j3sgWXnAfK8A9Y0bwXYU5xKaEdA= github.com/jackc/pgservicefile v0.0.0-20221227161230-091c0ba34f0a h1:bbPeKD0xmW/Y25WS6cokEszi5g+S0QxI/d45PkRi7Nk= github.com/jackc/pgservicefile v0.0.0-20221227161230-091c0ba34f0a/go.mod h1:5TJZWKEWniPve33vlWYSoGYefn3gLQRzjfDlhSJ9ZKM= github.com/jackc/pgx/v5 v5.4.3 h1:cxFyXhxlvAifxnkKKdlxv8XqUf59tDlYjnV5YYfsJJY= @@ -28,6 +37,7 @@ github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+ github.com/stretchr/objx v0.5.2 h1:xuMeJ0Sdp5ZMRXx/aWO6RZxdr3beISkG5/G/aIRr3pY= github.com/stretchr/objx v0.5.2/go.mod h1:FRsXN1f5AsAjCGJKqEizvkpNtU+EGNCLh3NxZ/8L+MA= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= +github.com/stretchr/testify v1.4.0/go.mod h1:j7eGeouHqKxXV5pUuKE4zz7dFj8WfuZ+81PSLYec5m4= github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/stretchr/testify v1.10.0 h1:Xv5erBjTwe/5IxqUQTdXv5kgmIvbHo3QQyRwhJsOfJA= github.com/stretchr/testify v1.10.0/go.mod h1:r2ic/lqez/lEtzL7wO/rwa5dbSLXVDPFyf8C91i36aY= @@ -48,6 +58,7 @@ golang.org/x/text v0.21.0/go.mod h1:4IBbMaMmOPCJ8SecivzSH54+73PCFmPWxNTLm+vZkEQ= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= +gopkg.in/yaml.v2 v2.2.2/go.mod h1:hI93XBmqTisBFMUTm0b8Fm+jr3Dg1NNxqwp+5A1VGuI= gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=