Skip to content
23 changes: 21 additions & 2 deletions dbutil/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ package dbutil
import (
"context"
"regexp"
"runtime"
"strings"
"time"

Expand Down Expand Up @@ -92,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 {
Expand All @@ -112,14 +115,30 @@ 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 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()).
AnErr("result_error", err).
Str("method", method).
Str("query", query)
if z.Caller {
evt = evt.Caller(z.CallerSkipFrame)
evt = evt.Caller(callerSkipFrame)
}
evt.Msg("Query took long")
}
Expand Down
12 changes: 8 additions & 4 deletions dbutil/transaction.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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
}

Expand Down