feat(persistence): log SQLite result codes on failed statements

SQLite reuses one message for errors that need different responses: "database
is locked" is both SQLITE_BUSY, which busy_timeout retries, and
SQLITE_BUSY_SNAPSHOT, which it can never retry because the transaction's read
snapshot is already stale. Reading only the message, the two are
indistinguishable, and a lock error seen in the wild could not be diagnosed
without guessing which one it was.

Add db.ErrorCodes to unwrap a sqlite3.Error and report its result and extended
result codes, and include them in the SQL error log. The helper lives in db
because that package already owns the driver, so persistence does not need to
import it. Constraint, readonly and disk-full errors share messages the same
way, so this applies to every failed statement, not just locks.
This commit is contained in:
Deluan 2026-07-29 08:47:52 -04:00
parent 0dfe460be6
commit 56a36e4da4
2 changed files with 22 additions and 3 deletions

View File

@ -4,6 +4,7 @@ import (
"context"
"database/sql"
"embed"
"errors"
"fmt"
"time"
@ -106,6 +107,17 @@ func Init(ctx context.Context) func() {
}
}
// ErrorCodes reports the SQLite result code and extended result code carried by err.
// The extended code is what distinguishes errors that share a message: "database is locked"
// is both SQLITE_BUSY, which busy_timeout retries, and SQLITE_BUSY_SNAPSHOT, which it never can.
func ErrorCodes(err error) (code, extended int, ok bool) {
var se sqlite3.Error
if !errors.As(err, &se) {
return 0, 0, false
}
return int(se.Code), int(se.ExtendedCode), true
}
type statusLogger struct{ numPending int }
func (*statusLogger) Fatalf(format string, v ...any) { log.Fatal(fmt.Sprintf(format, v...)) }

View File

@ -15,6 +15,7 @@ import (
. "github.com/Masterminds/squirrel"
"github.com/deluan/rest"
"github.com/navidrome/navidrome/conf"
"github.com/navidrome/navidrome/db"
"github.com/navidrome/navidrome/log"
"github.com/navidrome/navidrome/model"
id2 "github.com/navidrome/navidrome/model/id"
@ -597,9 +598,15 @@ func (r sqlRepository) delete(cond Sqlizer) error {
func (r sqlRepository) logSQL(sql string, args dbx.Params, err error, rowsAffected int64, start time.Time) {
elapsed := time.Since(start)
fields := []any{r.ctx, "SQL: `" + sql + "`", "args", args, "rowsAffected", rowsAffected, "elapsedTime", elapsed}
if err == nil || errors.Is(err, context.Canceled) {
log.Trace(r.ctx, "SQL: `"+sql+"`", "args", args, "rowsAffected", rowsAffected, "elapsedTime", elapsed, err)
} else {
log.Error(r.ctx, "SQL: `"+sql+"`", "args", args, "rowsAffected", rowsAffected, "elapsedTime", elapsed, err)
log.Trace(append(fields, err)...)
return
}
// The result codes separate errors that share a message, notably SQLITE_BUSY from
// SQLITE_BUSY_SNAPSHOT, which no busy_timeout can retry.
if code, extended, ok := db.ErrorCodes(err); ok {
fields = append(fields, "sqliteCode", code, "sqliteExtended", extended)
}
log.Error(append(fields, err)...)
}