From f02bbb60f7a02ba115c1425b1b2c911ca08d5076 Mon Sep 17 00:00:00 2001 From: Jonathan Amsterdam Date: Tue, 16 Mar 2021 09:55:46 -0400 Subject: internal/database: downgrade retryable errors to warnings If a DB statement that is inside a retryable transaction fails because of a serialization error, the the transaction will be retried. That is a normal condition, not an error, so don't log it as an error. Instead, log it as a warning so that if we ever exceed the max number of retries, we can easily find the problem. Change-Id: I481a0c900ccf12fc7d1c897a14b45ae5d2169529 Reviewed-on: https://go-review.googlesource.com/c/pkgsite/+/302190 Trust: Jonathan Amsterdam Run-TryBot: Jonathan Amsterdam TryBot-Result: kokoro Reviewed-by: Julie Qiu --- internal/database/database.go | 23 +++++++++++++++++------ 1 file changed, 17 insertions(+), 6 deletions(-) (limited to 'internal/database/database.go') diff --git a/internal/database/database.go b/internal/database/database.go index f2d29f9e..96e858f4 100644 --- a/internal/database/database.go +++ b/internal/database/database.go @@ -33,6 +33,7 @@ type DB struct { db *sql.DB instanceID string tx *sql.Tx + opts sql.TxOptions // valid when tx != nil mu sync.Mutex maxRetries int // max times a single transaction was retried } @@ -68,6 +69,10 @@ func (db *DB) InTransaction() bool { return db.tx != nil } +func (db *DB) IsRetryable() bool { + return db.tx != nil && isRetryable(db.opts.Isolation) +} + var passwordRegexp = regexp.MustCompile(`password=\S+`) func redactPassword(dbinfo string) string { @@ -81,7 +86,7 @@ func (db *DB) Close() error { // Exec executes a SQL statement and returns the number of rows it affected. func (db *DB) Exec(ctx context.Context, query string, args ...interface{}) (_ int64, err error) { - defer logQuery(ctx, query, args, db.instanceID)(&err) + defer logQuery(ctx, query, args, db.instanceID, db.IsRetryable())(&err) res, err := db.execResult(ctx, query, args...) if err != nil { return 0, err @@ -103,7 +108,7 @@ func (db *DB) execResult(ctx context.Context, query string, args ...interface{}) // Query runs the DB query. func (db *DB) Query(ctx context.Context, query string, args ...interface{}) (_ *sql.Rows, err error) { - defer logQuery(ctx, query, args, db.instanceID)(&err) + defer logQuery(ctx, query, args, db.instanceID, db.IsRetryable())(&err) if db.tx != nil { return db.tx.QueryContext(ctx, query, args...) } @@ -112,7 +117,7 @@ func (db *DB) Query(ctx context.Context, query string, args ...interface{}) (_ * // QueryRow runs the query and returns a single row. func (db *DB) QueryRow(ctx context.Context, query string, args ...interface{}) *sql.Row { - defer logQuery(ctx, query, args, db.instanceID)(nil) + defer logQuery(ctx, query, args, db.instanceID, db.IsRetryable())(nil) start := time.Now() defer func() { if ctx.Err() != nil { @@ -128,7 +133,7 @@ func (db *DB) QueryRow(ctx context.Context, query string, args ...interface{}) * } func (db *DB) Prepare(ctx context.Context, query string) (*sql.Stmt, error) { - defer logQuery(ctx, "preparing "+query, nil, db.instanceID) + defer logQuery(ctx, "preparing "+query, nil, db.instanceID, db.IsRetryable()) if db.tx != nil { return db.tx.PrepareContext(ctx, query) } @@ -169,12 +174,16 @@ func (db *DB) Transact(ctx context.Context, iso sql.IsolationLevel, txFunc func( // For the levels which require retry, see // https://www.postgresql.org/docs/11/transaction-iso.html. opts := &sql.TxOptions{Isolation: iso} - if iso == sql.LevelRepeatableRead || iso == sql.LevelSerializable { + if isRetryable(iso) { return db.transactWithRetry(ctx, opts, txFunc) } return db.transact(ctx, opts, txFunc) } +func isRetryable(iso sql.IsolationLevel) bool { + return iso == sql.LevelRepeatableRead || iso == sql.LevelSerializable +} + // serializationFailureCode is the Postgres error code returned when a serializable // transaction fails because it would violate serializability. // See https://www.postgresql.org/docs/current/errcodes-appendix.html. @@ -193,6 +202,7 @@ func (db *DB) transactWithRetry(ctx context.Context, opts *sql.TxOptions, txFunc db.maxRetries = i } db.mu.Unlock() + log.Debugf(ctx, "serialization failure; retrying") continue } if err != nil { @@ -246,7 +256,8 @@ func (db *DB) transact(ctx context.Context, opts *sql.TxOptions, txFunc func(*DB dbtx := New(db.db, db.instanceID) dbtx.tx = tx - defer dbtx.logTransaction(ctx, opts)(&err) + dbtx.opts = *opts + defer dbtx.logTransaction(ctx)(&err) if err := txFunc(dbtx); err != nil { return fmt.Errorf("txFunc(tx): %w", err) } -- cgit v1.3