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

[vicentsegui]

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:

	log = zerolog.New(output).
			Level(zerolog.Level(logLevel)).
			With().
			Caller().
			Stack().
			Timestamp().
			Str("scm_version", version.ScmVersion).
			Logger()

and configure pgx pool like so:

	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:

{"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

[jackc]

I don't think I want to change the default name. It's been called "time" for as long as there has been logging in pgx. But I'm open to making the name of the time/duration field configurable. Presumably an extra field on tracelog.TraceLog should do it. I don't think any other fields should collide.

[vicentsegui]

Sounds good to me. There is another alternative which is to change the zerologadapter (I've done that to test as a quick fix) and prepend the prefix of choice in there:

func (pl *Logger) Log(ctx context.Context, level tracelog.LogLevel, msg string, inputData map[string]interface{}) {
	var zlevel zerolog.Level
	data := make(map[string]interface{})
	for k, v := range inputData {
		data["pgx."+k] = v
	}
	switch level {
	case tracelog.LogLevelNone:
		zlevel = zerolog.NoLevel
	case tracelog.LogLevelError:
		zlevel = zerolog.ErrorLevel
	case tracelog.LogLevelWarn:
		zlevel = zerolog.WarnLevel
	case tracelog.LogLevelInfo:
		zlevel = zerolog.InfoLevel
	case tracelog.LogLevelDebug:
		zlevel = zerolog.DebugLevel
	case tracelog.LogLevelTrace:
		zlevel = zerolog.TraceLevel
	default:
		zlevel = zerolog.DebugLevel
	}

	var zctx zerolog.Context
	if pl.fromContext {
		logger := zerolog.Ctx(ctx)
		zctx = logger.With()
	} else {
		zctx = pl.logger.With()
	}
	if pl.withFunc != nil {
		zctx = pl.withFunc(ctx, zctx)
	}

	pgxlog := zctx.Logger()
	event := pgxlog.WithLevel(zlevel)
	if event.Enabled() {
		if pl.fromContext && !pl.skipModule {
			event.Str("module", "pgx")
		}

		if pl.subDictionary {
			event.Dict(pl.subDictionaryKey, zerolog.Dict().Fields(data))
		} else {
			event.Fields(data)
		}

		event.Msg(msg)
	}
}

However this creates a copy and more allocations so I think simply changing the tracelog package is for the best.