diff --git a/core/services/testutil/testdb.go b/core/services/testutil/testdb.go index 7e2c061dd..4f36d52c3 100644 --- a/core/services/testutil/testdb.go +++ b/core/services/testutil/testdb.go @@ -165,61 +165,70 @@ func SetupTestDB() *gorm.DB { return db } -// openPool connects to dsn with logging off and with every server-side timeout -// disabled on the session. Used for the short-lived maintenance connections -// only; the database a spec is handed keeps gorm's silent logger and the -// server's defaults, because setting timeouts on it is a thing specs do on -// purpose. +// maintenanceDSN is dsn with every server-side timeout disabled as a CONNECTION +// STARTUP OPTION rather than as a statement. // -// The timeouts are cleared because CREATE DATABASE and DROP DATABASE must not -// be bounded by anything a spec configured. A spec that sets a short -// statement_timeout on ITS database cannot reach this one, but a spec that -// names the maintenance database by mistake can, and that is not hypothetical: -// two advisory-lock specs did exactly that until this round. The consequence -// there is a load-dependent failure in another spec's setup or a silently -// swallowed DROP, which is the same invisible single-spec flake this helper was -// rewritten to remove. +// The timeouts have to go because CREATE DATABASE and DROP DATABASE must not be +// bounded by anything a spec configured. A spec that sets a short +// statement_timeout on ITS own database cannot reach this connection, but a spec +// that names the maintenance database by mistake can, and that is not +// hypothetical: two advisory-lock specs did exactly that. // -// MaxOpenConns(1) is what makes the SET reach the statement that follows it: a -// session setting lives on one connection, and with a single connection in the -// pool there is no other one for CREATE or DROP to land on. +// Clearing it with `SET statement_timeout = 0` on an already-open connection is +// circular and was a real defect here: that connection has already inherited the +// database's bound, so the statement that clears the bound runs under it and can +// be aborted by it with SQLSTATE 57014. It failed roughly once in fifty at +// 8-way concurrency, which is the same invisible load-dependent single-spec +// flake this helper exists to remove. A startup option removes the circularity +// instead of buying headroom against it: the value is delivered in the startup +// packet, so the connection is already unbounded before it can run anything. +// +// The route is verified in the driver rather than assumed. pgx puts every URL +// query parameter into settings (pgconn/config.go:614), `options` is absent from +// notRuntimeParams (pgconn/config.go:340-362) so it becomes a runtime parameter +// (pgconn/config.go:374-378), and runtime parameters are copied into the startup +// message (pgconn/pgconn.go:382-388). PostgreSQL treats `options` as backend +// command-line switches, so `-c statement_timeout=0` is applied before the +// session accepts a query. +func maintenanceDSN(dsn string) (string, error) { + u, err := url.Parse(dsn) + if err != nil { + return "", err + } + q := u.Query() + // Percent-encoded by Encode, and pgx decodes query values before they reach + // settings, so the server receives the switches with their spaces intact. + q.Set("options", "-c statement_timeout=0 -c lock_timeout=0") + u.RawQuery = q.Encode() + return u.String(), nil +} + +// openPool connects to the maintenance database with logging off and no +// server-side timeouts. Used for the short-lived maintenance connections only; +// the database a spec is handed keeps gorm's silent logger and the server's +// defaults, because setting timeouts on it is a thing specs do on purpose. func openPool(dsn string) *gorm.DB { GinkgoHelper() - db, err := gorm.Open(postgres.Open(dsn), &gorm.Config{Logger: logger.Discard}) + db, err := openTolerantPool(dsn) Expect(err).ToNot(HaveOccurred()) - - sqlDB, err := db.DB() - Expect(err).ToNot(HaveOccurred()) - sqlDB.SetMaxOpenConns(1) - - Expect(db.Exec("SET statement_timeout = 0").Error).To(Succeed()) - Expect(db.Exec("SET lock_timeout = 0").Error).To(Succeed()) return db } // openTolerantPool is openPool for the cleanup path, which must report a // failure rather than assert one: an assertion here would fail a spec that had // already passed, and bury whatever the next real failure was. +// +// It carries the same startup options, and the DROP is the statement that most +// needs them: FORCE waits on terminating other sessions, measured at up to 169ms +// against the 300ms bound that used to leak here, and a DROP aborted mid-way is +// swallowed and leaks a database. func openTolerantPool(dsn string) (*gorm.DB, error) { - db, err := gorm.Open(postgres.Open(dsn), &gorm.Config{Logger: logger.Discard}) + maintenance, err := maintenanceDSN(dsn) if err != nil { return nil, err } - sqlDB, err := db.DB() + db, err := gorm.Open(postgres.Open(maintenance), &gorm.Config{Logger: logger.Discard}) if err != nil { - closePool(db) - return nil, err - } - sqlDB.SetMaxOpenConns(1) - // The DROP below is the statement most likely to be slow, since it waits on - // FORCE terminating other sessions, so it is the one a leaked timeout would - // abort. Measured at up to 169ms under load, against a 300ms bound. - if err := db.Exec("SET statement_timeout = 0").Error; err != nil { - closePool(db) - return nil, err - } - if err := db.Exec("SET lock_timeout = 0").Error; err != nil { - closePool(db) return nil, err } return db, nil diff --git a/core/services/testutil/testdb_internal_test.go b/core/services/testutil/testdb_internal_test.go index 457d6f7d5..b3003c0d0 100644 --- a/core/services/testutil/testdb_internal_test.go +++ b/core/services/testutil/testdb_internal_test.go @@ -5,6 +5,9 @@ import ( . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" + "gorm.io/driver/postgres" + "gorm.io/gorm" + gormlogger "gorm.io/gorm/logger" ) // These are white-box on purpose: the property is about the connection this @@ -45,6 +48,11 @@ var _ = Describe("the maintenance connection", func() { Expect(impose.Exec(fmt.Sprintf("ALTER DATABASE %q SET lock_timeout = '1ms'", maintenance)).Error).To(Succeed()) }() + // The bound is delivered before the first statement, so the check + // below is also the connection's first statement. That ordering is the + // point: clearing the bound with a SET would be circular, because the + // clearing statement inherits the bound it is clearing and can be + // aborted by it with 57014. There is no such bootstrap statement now. fresh := openPool(dsn) defer closePool(fresh) var statementTimeout, lockTimeout string @@ -55,9 +63,48 @@ var _ = Describe("the maintenance connection", func() { Expect(lockTimeout).To(Equal("0"), "a lock_timeout on the maintenance database reached the helper's own connection") - // And the thing the timeouts would actually abort still works while the - // bound is in force. A 1ms statement_timeout is far below the 14-26ms a - // CREATE DATABASE takes here, so this could not pass by being fast. + // A control, and the reason this spec is not a race. Clearing the bound + // with a statement is circular: the clearing statement runs on a + // connection that has already inherited the bound. Whether that + // particular statement exceeds 1ms is a matter of load, which makes the + // defect an intermittent one; whether the FIRST statement on a plain + // connection is bounded at all is not. So the control asks the + // deterministic question, with a first statement that certainly exceeds + // the bound. + func() { + plain, err := gorm.Open(postgres.Open(dsn), &gorm.Config{Logger: gormlogger.Discard}) + Expect(err).ToNot(HaveOccurred()) + defer closePool(plain) + err = plain.Exec("SELECT pg_sleep(0.05)").Error + Expect(err).To(HaveOccurred(), + "the imposed bound does not reach a fresh connection's first statement, so this spec's subject is not actually under test") + Expect(err.Error()).To(ContainSubstring("57014"), + "expected the imposed statement_timeout to abort this, got something else") + }() + + // The same first statement on a maintenance connection is unbounded. + Expect(fresh.Exec("SELECT pg_sleep(0.05)").Error).To(Succeed()) + + // And this is the assertion that says WHY, which is the part a + // statement-based clearing cannot satisfy. reset_val is the value the + // session would fall back to, that is, the value that was in force when + // the connection started, before it could run anything. Clearing the + // bound with `SET statement_timeout = 0` leaves reset_val at the + // database's 1ms: the session is unbounded only because a statement + // said so, and that statement ran under the 1ms bound and can be + // aborted by it. Delivering it as a startup option makes the connection + // unbounded with no statement in between, which is the difference + // between a fix and a wider margin. + var resetVal string + Expect(fresh.Raw( + "SELECT reset_val FROM pg_settings WHERE name = 'statement_timeout'", + ).Scan(&resetVal).Error).To(Succeed()) + Expect(resetVal).To(Equal("0"), + "the maintenance connection started under a %s bound and cleared it with a statement, so the clearing statement itself runs under the bound it is clearing", resetVal) + + // And the operation the bound would abort still works while it is in + // force. 1ms is far below the 14-26ms a CREATE DATABASE takes here, so + // this cannot pass by being fast. Expect(SetupTestDB()).ToNot(BeNil()) }) })