pgx Tracing Logging and OpenTelemetry Hooks in Go Code

A database client that cannot tell you what it did is hard to operate. pgx's answer is a set of tracer interfaces: small hooks that the driver calls at the start and end of each query, batch, COPY and connect. You implement one to log, to count, to measure or to produce spans, and you can attach several at once. The tracelog package supplies a ready made tracer that writes log lines, and it has a habit you need to know about before you turn it on in production. This article uses both, with a tracer of our own beside it, on Go 1.25.6, pgx v5.11.0 and PostgreSQL 18.6, and prints what each logs.

It belongs to the database cornerstone. The same idea for database/sql is in OpenTelemetry for database/sql, slow query logging in slow query logs, and the tracer interface appears in finding N plus one queries.

The interfaces

pgx defines tracers by what they observe. pgx.QueryTracer has TraceQueryStart and TraceQueryEnd; pgx.BatchTracer adds TraceBatchStart, TraceBatchQuery and TraceBatchEnd; pgx.CopyFromTracer and pgx.PrepareTracer cover COPY and prepare; pgx.ConnectTracer covers connecting. You assign one value to ConnConfig.Tracer, and pgx checks which interfaces it implements and calls those. The Start method returns a context.Context, which is how a span or a timer travels to the matching End.

Two packages combine and use them. tracelog is the logger: a TraceLog{Logger, LogLevel} where Logger is an interface with a single Log(ctx, level, msg, data) method, so adapting it to slog or any other logger is a few lines. multitracer fans events out to several tracers, so one connection can log and count and trace at once.

What gets logged

package main

import (
	"context"
	"fmt"
	"log"
	"sort"
	"strings"
	"sync"

	"github.com/jackc/pgx/v5"
	"github.com/jackc/pgx/v5/multitracer"
	"github.com/jackc/pgx/v5/pgxpool"
	"github.com/jackc/pgx/v5/tracelog"
)

const dsn = "postgres://postgres:[email protected]:55432/lab?sslmode=disable"

func must(err error) {
	if err != nil {
		log.Fatal(err)
	}
}

// printer turns tracelog events into stable lines: durations and process ids change on every run, so they are masked.
type printer struct {
	mu    sync.Mutex
	lines []string
}

func (p *printer) Log(_ context.Context, level tracelog.LogLevel, msg string, data map[string]any) {
	keys := make([]string, 0, len(data))
	for k := range data {
		keys = append(keys, k)
	}
	sort.Strings(keys)
	var parts []string
	for _, k := range keys {
		v := fmt.Sprint(data[k])
		if k == "time" || k == "pid" {
			v = "<" + k + ">"
		}
		parts = append(parts, k+"="+v)
	}
	p.mu.Lock()
	p.lines = append(p.lines, fmt.Sprintf("%-5s %-12s %s", level, msg, strings.Join(parts, " ")))
	p.mu.Unlock()
}

func (p *printer) flush(title string) {
	p.mu.Lock()
	defer p.mu.Unlock()
	fmt.Println(title)
	for _, l := range p.lines {
		fmt.Println("   " + l)
	}
	p.lines = nil
}

// counter is a tracer of our own: it counts statements and keeps the last SQL, and shares the connection with tracelog.
type counter struct {
	mu    sync.Mutex
	count int
	last  string
}

func (c *counter) TraceQueryStart(ctx context.Context, _ *pgx.Conn, d pgx.TraceQueryStartData) context.Context {
	c.mu.Lock()
	c.count++
	c.last = d.SQL
	c.mu.Unlock()
	return ctx
}
func (c *counter) TraceQueryEnd(context.Context, *pgx.Conn, pgx.TraceQueryEndData) {}

func main() {
	ctx := context.Background()
	p := &printer{}
	c := &counter{}
	cfg, err := pgxpool.ParseConfig(dsn)
	must(err)
	cfg.MaxConns = 1 // one connection, so every event comes from the same session
	cfg.ConnConfig.Tracer = multitracer.New(&tracelog.TraceLog{Logger: p, LogLevel: tracelog.LogLevelInfo}, c)
	pool, err := pgxpool.NewWithConfig(ctx, cfg)
	must(err)
	defer pool.Close()
	_, err = pool.Exec(ctx, "drop table if exists t675; create table t675 (id int primary key, secret text)")
	must(err)
	p.lines = nil

	// 1. A statement with arguments: the SQL and the argument values are in the log.
	_, err = pool.Exec(ctx, "insert into t675 values ($1, $2)", 1, "correct horse battery staple")
	must(err)
	p.flush("1. Exec with arguments (note that the argument values are logged):")

	// 2. A query, and an error.
	var n int
	must(pool.QueryRow(ctx, "select count(*) from t675").Scan(&n))
	_, err = pool.Exec(ctx, "insert into t675 values ($1, $2)", 1, "again")
	p.flush("2. a count, then a failing insert:")

	// 3. A batch and a copy.
	b := &pgx.Batch{}
	b.Queue("insert into t675 values (2, 'b')")
	b.Queue("select count(*) from t675")
	must(pool.SendBatch(ctx, b).Close())
	_, err = pool.CopyFrom(ctx, pgx.Identifier{"t675"}, []string{"id", "secret"}, pgx.CopyFromRows([][]any{{10, "x"}, {11, "y"}}))
	must(err)
	p.flush("3. a batch of two statements and a COPY:")

	// 4. A new connection is logged too, with the host and database but not the password.
	conn, err := pgx.ConnectConfig(ctx, cfg.ConnConfig)
	must(err)
	conn.Close(ctx)
	p.flush("4. connecting and closing:")

	// 5. The same data through a tracer of our own, seen by both tracers at once.
	c.mu.Lock()
	fmt.Printf("5. the counter tracer saw %d statements in total; the last SQL was %q\n", c.count, c.last)
	c.mu.Unlock()

	// 6. Turning the level up and down.
	cfg2, _ := pgxpool.ParseConfig(dsn)
	cfg2.MaxConns = 1
	cfg2.ConnConfig.Tracer = &tracelog.TraceLog{Logger: p, LogLevel: tracelog.LogLevelError}
	quiet, err := pgxpool.NewWithConfig(ctx, cfg2)
	must(err)
	defer quiet.Close()
	_, _ = quiet.Exec(ctx, "select 1")
	_, err = quiet.Exec(ctx, "select * from nope675")
	p.flush("6. at LogLevelError only the failure is logged:")
}

1. Exec with arguments (note that the argument values are logged):
   info  Prepare      alreadyPrepared=false name=stmtcache_dd2ac0f8d18587c5b16d33c83a43ae3679dfc18a6b8280fa pid=<pid> sql=insert into t675 values ($1, $2) time=<time>
   info  Query        args=[1 correct horse battery staple] commandTag=INSERT 0 1 pid=<pid> sql=insert into t675 values ($1, $2) time=<time>
2. a count, then a failing insert:
   info  Prepare      alreadyPrepared=false name=stmtcache_805b25c1dcb2fb07ab0a7dff02b1938cec609214ca2296d5 pid=<pid> sql=select count(*) from t675 time=<time>
   info  Query        args=[] commandTag=SELECT 1 pid=<pid> sql=select count(*) from t675 time=<time>
   error Query        args=[1 again] err=ERROR: duplicate key value violates unique constraint "t675_pkey" (SQLSTATE 23505) pid=<pid> sql=insert into t675 values ($1, $2) time=<time>
3. a batch of two statements and a COPY:
   info  BatchQuery   args=[] commandTag=INSERT 0 1 pid=<pid> sql=insert into t675 values (2, 'b')
   info  BatchQuery   args=[] commandTag=SELECT 1 pid=<pid> sql=select count(*) from t675
   info  BatchClose   pid=<pid> time=<time>
   info  Prepare      alreadyPrepared=false name=stmtcache_b63f752dd90dff8f8b41b7a077a9fb835aa7a023b86052af pid=<pid> sql=select "id", "secret" from "t675" time=<time>
   info  CopyFrom     columnNames=[id secret] err=<nil> pid=<pid> rowCount=2 tableName=[t675] time=<time>
4. connecting and closing:
   info  Connect      database=lab host=127.0.0.1 pid=<pid> port=55432 time=<time>
5. the counter tracer saw 4 statements in total; the last SQL was "insert into t675 values ($1, $2)"
6. at LogLevelError only the failure is logged:
   error Query        args=[] err=ERROR: relation "nope675" does not exist (SQLSTATE 42P01) pid=<pid> sql=select * from nope675 time=<time>

The lab's printer records each event as one line, with the data keys sorted and the two that change on every run, time and pid, masked as <time> and <pid>. A pool of one connection is used so the events all come from one session.

An insert with arguments produced two lines: a Prepare event with the statement's cache name (stmtcache_...) and the SQL, and a Query event with commandTag=INSERT 0 1. The Query line contains args=[1 correct horse battery staple]: the argument values are in the log. That is tracelog's default, it is useful in development, and it is a data leak in production: arguments carry emails, tokens, addresses and passwords, and log files outlive and outspread the database. Either do not use tracelog in production, set it to a level that excludes queries (it logs successful queries at Info), or wrap the logger so it strips the args key, as printer.Log could, or write your own tracer that records the SQL and the number of arguments and nothing more, as the slow query logger does.

A failing statement was logged at error level, with err=ERROR: duplicate key value violates unique constraint "t675_pkey" (SQLSTATE 23505), the arguments and the SQL. Errors are the part worth keeping in production, with arguments removed.

A batch logged one BatchQuery line per statement (with command tags and no time) and a BatchClose. A COPY logged a Prepare for the metadata query pgx runs and a CopyFrom event with rowCount=2, the table and the column names. A connection logged a Connect event with host, port and database, and not the password. Each event name is a stable key you can alert on.

Your own tracer beside tracelog

The counter type implements only QueryTracer. It counts statements and remembers the last SQL. multitracer.New(tracelogTracer, counter) returns one value that satisfies all the interfaces its children satisfy and forwards each call to every child. The fifth line of the output shows the counter saw 4 statements while tracelog was logging the same ones. Use this to keep logging separate from metrics and from tracing: a tracelog for development, a counter or histogram for Prometheus, and a span tracer for OpenTelemetry, each simple, none aware of the others.

A tracer runs on every query, on the goroutine that issued it, so it must be fast and must not block. Do the cheap thing inline (increment a counter, read the clock) and push anything slower, such as formatting a log line or sending a span, to a channel or the logging library's own async path.

Levels

tracelog filters by LogLevel: Trace, Debug, Info, Warn, Error and None. Successful queries are logged at Info and failures at Error. The last block builds a second pool with LogLevelError and runs a good statement and a failing one: only the failure produced a line, error Query ... err=ERROR: relation "nope675" does not exist (SQLSTATE 42P01). That is a sensible production setting for the stock logger: silent when things work, one line per failure. For slow statements you need a tracer of your own, since tracelog does not filter by duration.

OpenTelemetry

For distributed tracing, the usual choice is the otelpgx package from the OpenTelemetry contrib ecosystem, which implements these same tracer interfaces and creates a span per query, batch and copy, with the SQL as an attribute and metrics for the pool. You wire it exactly as above: cfg.ConnConfig.Tracer = otelpgx.NewTracer(), or a multitracer with it and others. It was not run for this article, so check its README for the current options and for the version that matches your OpenTelemetry release. The same cautions as for logging apply: record the SQL with its placeholders and never the argument values, and sample so a busy service does not export a span for every query.

What the span gives you that a log line does not is the parent: pass the request's context to every pgx call, and each query's span becomes a child of the request span, so a slow endpoint shows which statements it ran, in which order and for how long, including the wait to acquire a connection.

Choosing what to attach

Whatever you attach, test it: assert in an integration test that a failing statement produces the expected log and that no argument value appears in it. The packages are documented in the tracelog and multitracer references, and the OpenTelemetry side in the OpenTelemetry Go documentation.