jackc / jackc/pgx

Tracelog uses "time" when logging which can cause issues with JSON payloads

Open
#2,043 2 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
Go
Stars
14.3k
Forks
1.1k
Avg merge
6d 9h
Merged PRs (30d)
11

Description

**Describe the bug**
The tracelog packlage (github.com/jackc/pgx/v5/tracelog") uses "time" as a label to print the time used to process. This however causes conflicts with other logging systems that will use "time" as a label to mean timestamp of log produced. This causes log ingestors to fail parsing the JSON as there is a duplicate key.

**To Reproduce**
Steps to reproduce the behavior:

Use `github.com/jackc/pgx/v5/tracelog `and `github.com/jackc/pgx-zerolog` and a logger configured roughly like so:

```go
log = zerolog.New(output).
Level(zerolog.Level(logLevel)).
With().
Caller().
Stack().
Timestamp().
Str("scm_version", version.ScmVersion).
Logger()
```
and configure pgx pool like so:

```go
pgLogTrace := &tracelog.TraceLog{
Logger: zerologadapter.NewLogger(log),
LogLevel: tracelog.LogLevelTrace,
}
pgConfig.ConnConfig.Tracer = pgxtrace.CompositeQueryTracer{
pgLogTrace,
}
l.Info().Msg("Connecting to Postgres database")
pgClient, err := pgxpool.NewWithConfig(ctx, pgConfig)
```

Use the pgClient to run some queries and observe the logs:

```json
{"level":"info",
"module":"pgx",
"alreadyPrepared":false,
"name":"stmtcache_11578b0b996ce09b82a573adef17a56ff464aab9bbc4a4af",
"pid":426317,
"sql":"SELECT *********",
"caller":"external/gazelle~~go_deps~com_github_jackc_pgx_zerolog/adapter.go:119",
"time":3.17694,
"time":"2024-06-13T15:20:12.937558654Z",
"message":"Prepare",
....}
```

Notice the duplicate "time" entry,.

**Expected behavior**

The tracelog package should avoid using generic labels like "time", etc as those can likely collide with other labels. I'd suggest adding a prefix (perhaps configurable) so that it will be logged like "pgx.QueryTime", for all tracelog labels.

**Version**
- Go: `$ go version` -> 1.22
- pgx: `github.com/jackc/pgx/v5 v5.6.0`
- pgx-zerolog: `github.com/jackc/pgx-zerolog v0.0.0-20230315001418-f978528409eb`

Contributor guide

Open the contributing guide

Research direction

Start with the tracelog package and the pgx-zerolog adapter at adapter.go:119, then inspect how query timing and timestamp fields are emitted together. Reproduce the duplicate JSON "time" fields using the configuration in the report, and define a consistent, collision-free label scheme before checking that the resulting logs contain no duplicate keys.

Written by the indexing model from the issue text.

Assessment

Tech stack
go, postgresql
Domain
observability
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.