From b124133425c73ff9f785d1c84fe5207e787e1128 Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Tue, 16 Sep 2025 16:44:30 +0300 Subject: [PATCH 1/3] dbutil: log caller without dbutil code --- dbutil/log.go | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/dbutil/log.go b/dbutil/log.go index 918c79b..a77bd44 100644 --- a/dbutil/log.go +++ b/dbutil/log.go @@ -3,6 +3,7 @@ package dbutil import ( "context" "regexp" + "runtime" "strings" "time" @@ -112,6 +113,13 @@ func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args Str("query", query). Interface("query_args", args). Msg("Query") + callerSkipFrame := z.CallerSkipFrame + for ; callerSkipFrame < 10; callerSkipFrame++ { + _, filename, _, _ := runtime.Caller(callerSkipFrame) + if !strings.Contains(filename, "/dbutil/") { + break + } + } if duration >= 1*time.Second { evt := log.Warn(). Float64("duration_seconds", duration.Seconds()). @@ -119,7 +127,7 @@ func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args Str("method", method). Str("query", query) if z.Caller { - evt = evt.Caller(z.CallerSkipFrame) + evt = evt.Caller(callerSkipFrame) } evt.Msg("Query took long") } From c6c5cd515b147b8f5d0eeb29224128800e13d6ef Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Tue, 16 Sep 2025 16:44:52 +0300 Subject: [PATCH 2/3] dbutil: add flag to log all queries without variables --- dbutil/log.go | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/dbutil/log.go b/dbutil/log.go index a77bd44..682e5a6 100644 --- a/dbutil/log.go +++ b/dbutil/log.go @@ -93,12 +93,14 @@ func (z zeroLogger) DoUpgrade(from, to int, message string, txn TxnMode) { var whitespaceRegex = regexp.MustCompile(`\s+`) +var TemporarySafeQueryLog bool + func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args []any, nrows int, duration time.Duration, err error) { log := zerolog.Ctx(ctx) if log.GetLevel() == zerolog.Disabled || log == zerolog.DefaultContextLogger { log = z.l } - if (!z.TraceLogAllQueries || log.GetLevel() != zerolog.TraceLevel) && duration < 1*time.Second { + if (!z.TraceLogAllQueries || log.GetLevel() != zerolog.TraceLevel) && !TemporarySafeQueryLog && duration < 1*time.Second { return } if nrows > -1 { @@ -120,6 +122,15 @@ func (z zeroLogger) QueryTiming(ctx context.Context, method, query string, args break } } + if TemporarySafeQueryLog { + log.Debug(). + Err(err). + Int64("duration_µs", duration.Microseconds()). + Str("method", method). + Str("query", query). + Caller(callerSkipFrame). + Msg("Query") + } if duration >= 1*time.Second { evt := log.Warn(). Float64("duration_seconds", duration.Seconds()). From 4300b2bcdc856f148df32df227a3061aaf248e60 Mon Sep 17 00:00:00 2001 From: Tulir Asokan Date: Wed, 17 Sep 2025 16:48:51 +0300 Subject: [PATCH 3/3] Log transaction start/end on debug level --- dbutil/transaction.go | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/dbutil/transaction.go b/dbutil/transaction.go index d010ea5..c3b56d7 100644 --- a/dbutil/transaction.go +++ b/dbutil/transaction.go @@ -120,7 +120,11 @@ func (db *Database) DoTxn(ctx context.Context, opts *TxnOptions, fn func(ctx con log.Trace().Err(err).Msg("Failed to begin transaction") return exerrors.NewDualError(ErrTxnBegin, err) } - log.Trace().Msg("Transaction started") + logLevel := zerolog.TraceLevel + if TemporarySafeQueryLog { + logLevel = zerolog.DebugLevel + } + log.WithLevel(logLevel).Msg("Transaction started") tx.noTotalLog = true ctx = log.WithContext(ctx) ctx = context.WithValue(ctx, db.txnCtxKey, tx) @@ -131,16 +135,16 @@ func (db *Database) DoTxn(ctx context.Context, opts *TxnOptions, fn func(ctx con if rollbackErr != nil { log.Warn().Err(rollbackErr).Msg("Rollback after transaction error failed") } else { - log.Trace().Msg("Rollback successful") + log.WithLevel(logLevel).Msg("Rollback successful") } return err } err = tx.Commit() if err != nil { - log.Trace().Err(err).Msg("Commit failed") + log.WithLevel(logLevel).Err(err).Msg("Commit failed") return exerrors.NewDualError(ErrTxnCommit, err) } - log.Trace().Msg("Commit successful") + log.WithLevel(logLevel).Msg("Commit successful") return nil }