Tracelog uses "time" when logging which can cause issues with JSON payloads
- 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
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