[BUG] Waiting for the migration advisory lock is bounded by the command timeout, failing concurrent startups #287

Summary

Instances starting concurrently against one database serialize migrations with the PostgreSQL advisory lock 5410320540103205. Code analysis establishes that the waiting instance blocks in SELECT pg_advisory_lock(...), which is an ordinary database command and therefore subject to the command timeout (Npgsql default 30 s; the application sets none). Each timeout is reported as a transient error and retried by the EF Core retrying execution strategy, so the total wait is bounded at roughly 6–7 minutes with default settings; a migration that holds the lock longer makes the concurrently starting instance fail its startup, and that failure is not logged by the migrator's own failure event.

Area

• docs/areas/hosting.md (added in [Docs] Describe the current behavior by area #263) — Startup sequence step 3, Open question 4
• Security area (.squad/project.md): Database and migrations (the PostgreSQL advisory lock around migrations)

Current behavior

What was established (by code analysis and reflection on the referenced packages — EF Core 10.0.13, Npgsql.EntityFrameworkCore.PostgreSQL 10.0.3 — not by running two instances against a live PostgreSQL):

1. The lock is taken with a blocking call, src/DockerUpdateGuard/DatabaseMigrator.cs:177-181:

if (useAdvisoryLock)
{
    await dbContext.Database.ExecuteSqlInterpolatedAsync($"SELECT pg_advisory_lock({MigrationAdvisoryLockKey})", cancellationToken)
                            .ConfigureAwait(false);
}

2. No command timeout is configured anywhere (no CommandTimeout(...) in src/DockerUpdateGuard/ServiceCollectionExtensions.cs:58-70, no Command Timeout in the shipped configuration or compose files), so Npgsql's default of 30 s applies to this statement.
3. A command timeout surfaces as NpgsqlException with an inner TimeoutException; NpgsqlException.IsTransient is true for it (verified), so the Npgsql retrying execution strategy treats it as transient.
4. The lock acquisition and the migration run as one retriable unit inside executionStrategy.ExecuteAsync(...) (DatabaseMigrator.cs:60-70), with the strategy configured by EnableRetryOnFailure(MaxConnectionRetryCount, MaxConnectionRetryDelaySeconds) (ServiceCollectionExtensions.cs:66-67; defaults 8 and 30 s). With defaults that is 9 attempts × 30 s plus EF Core's exponential back-off (about 0, 1, 3, 7, 15, 30, 30, 30 s) ≈ 6–7 minutes of total waiting.
5. After the last retry EF Core throws RetryLimitExceededException, whose base type is System.Exception (verified). DatabaseMigrator.MigrateAsync only catches DbException and InvalidOperationException (DatabaseMigrator.cs:72-83), so ApplicationDatabaseMigrationFailed is not logged; the exception propagates out of InitializeDockerUpdateGuardAsync and the process ends with an unhandled exception.
6. The MigrationStartupTimeoutSeconds / MigrationRetryDelaySeconds loop (DatabaseMigrator.cs:117-154) only covers opening the first connection; it does not apply to the lock wait.

Failure scenario: instance A starts against a database with a pending migration that takes 10 minutes (e.g. an index build on a large table). Instance B starts a few seconds later, passes the database wait, and blocks in pg_advisory_lock. Every 30 s the statement times out, is retried, and after about 6–7 minutes B exits with RetryLimitExceededException while A is still migrating — B's startup fails although nothing was wrong.

Side note (not in scope, see Implementation notes): each statement of the migration on instance A is subject to the same 30 s command timeout.

Expected behavior

• An instance waiting for the migration advisory lock waits as long as another instance holds it, bounded only by a dedicated, configurable deadline that is independent of the database command timeout.
• New key DockerUpdateGuard:Database:MigrationLockTimeoutSeconds, default 900, must be greater than zero (validated like the other Database keys; read once at startup).
• The wait does not block on the server: the instance polls pg_try_advisory_lock(5410320540103205) on the connection that will run the migration, every MigrationRetryDelaySeconds seconds, logging each wait (attempt number, elapsed time) without connection details.
• Once the lock is acquired, the instance applies pending migrations (finding none if the other instance finished) and releases the lock, as today.
• If the deadline passes without the lock, startup fails with a dedicated, logged error naming the key DockerUpdateGuard:Database:MigrationLockTimeoutSeconds.
• A shutdown request during the wait ends it promptly.
• Any exception that fails migration (including RetryLimitExceededException) is logged through the migrator's failure event before startup fails.

Acceptance criteria

• Test proving the defect is fixed: a unit test shows that a lock held longer than the command timeout (simulated: the lock-acquisition seam returns "not acquired" for longer than 30 s of fake time) does not fail startup, and that the migration runs once the lock becomes available — e.g. DatabaseMigratorLockHeldLongerThanCommandTimeoutWaitsAndMigrates.
• DatabaseMigratorLockNotAcquiredBeforeDeadlineFailsWithLoggedError — startup fails after MigrationLockTimeoutSeconds of fake time with the dedicated log event.
• DatabaseMigratorLockWaitCancelledStopsWaiting — cancellation ends the wait without the failure event.
• DatabaseMigratorRetryLimitExceededIsLogged — a non-DbException/non-InvalidOperationException failure from the execution strategy is logged via ApplicationDatabaseMigrationFailed and rethrown.
• DockerUpdateGuardOptionsValidatorTests: …MigrationLockTimeoutSecondsNotPositiveFails.
• Timing only through an injected TimeProvider (hand-written fake), never the real clock; every assertion has a message.
• Coverage gate passes.
• appsettings.json, README configuration reference (key, DockerUpdateGuard__Database__MigrationLockTimeoutSeconds, default 900) and docs/ARCHITECTURE.md (Configuration model, startup sequence) updated.
• The area document docs/areas/hosting.md describes the new behavior (startup step 3 and Limits and errors) and its Known gaps entry for this issue is removed.

Implementation notes

• Affected: src/DockerUpdateGuard/DatabaseMigrator.cs, Configuration/DatabaseOptions.cs, Configuration/DockerUpdateGuardOptionsValidator.cs, ApplicationInitializationExtensions.cs (passes options/logger), HostLoggingExtensions.cs (new events in the 1000–1009 startup range, e.g. lock waiting / lock timeout), tests in src/Tests/DockerUpdateGuard.Tests/DatabaseMigratorTests.cs.
• Testability: the unit tests cannot run PostgreSQL (see F-050 (P7) — Test DB fidelity: SQLite/InMemory instead of PostgreSQL hides F-021 and provides deceptive F-032 safety #28). Introduce a narrow seam for the lock, e.g. an internal method that takes a Func<CancellationToken, Task<bool>> tryAcquireLock plus a TimeProvider, and unit-test the polling/deadline logic with fakes; the production path passes a delegate that executes SELECT pg_try_advisory_lock(...) and reads the boolean (e.g. SqlQuery<bool>).
• Compute the deadline once, before executionStrategy.ExecuteAsync, so a transient retry of the delegate does not restart the wait. Keep lock and migration on the same explicitly opened connection (session-scoped lock), as the existing comment at DatabaseMigrator.cs:64-68 requires.
• EF Core 9+ also takes its own migration lock inside MigrateAsync (NpgsqlHistoryRepository.AcquireDatabaseLockAsync); once the application lock is held, that lock is uncontended. Do not remove the application lock (guarantee in .squad/project.md: migrations are serialized by a PostgreSQL advisory lock at startup).
• Add a catch for RetryLimitExceededException (or a general catch that logs and rethrows) in MigrateAsync.
• Out of scope, mention in the area document: statements of a long migration are still subject to the command timeout on the migrating instance; if that becomes a problem, a separate issue should set a migration-specific command timeout.
• Must not change: lock key 5410320540103205, release-failure handling (logged, outcome stands), the database wait loop, non-PostgreSQL providers (useAdvisoryLock == false path).

Related

• PR [Docs] Describe the current behavior by area #263 (area documents)
• F-050 (P7) — Test DB fidelity: SQLite/InMemory instead of PostgreSQL hides F-021 and provides deceptive F-032 safety #28 (test database fidelity) — why the test uses a seam instead of PostgreSQL.

Generated by Claude Code