diff --git a/db-migrations-expand-contract/README.md b/db-migrations-expand-contract/README.md index 22d3419..f170763 100644 --- a/db-migrations-expand-contract/README.md +++ b/db-migrations-expand-contract/README.md @@ -93,6 +93,7 @@ a transcript going stale fails the build. Files `11`–`13` come from the live | [`11-live-deploy-sequence.txt`](docs/output/11-live-deploy-sequence.txt) | [`scripts/run-all.sh`](scripts/run-all.sh) | | [`12-load-generator-summary.txt`](docs/output/12-load-generator-summary.txt) | [`LoadGenerator`](src/main/java/com/ankurm/expandcontract/loadgen/LoadGenerator.java), via `run-all.sh` | | [`13-schema-diagnostics-timeline.txt`](docs/output/13-schema-diagnostics-timeline.txt) | [`SchemaDiagnosticsController`](src/main/java/com/ankurm/expandcontract/diag/SchemaDiagnosticsController.java), via `run-all.sh` | +| [`14-ddl-collision-exception.txt`](docs/output/14-ddl-collision-exception.txt) | [`DdlCollisionExceptionTest`](src/test/java/com/ankurm/expandcontract/DdlCollisionExceptionTest.java) | | [`14-ddl-silent-data-loss.txt`](docs/output/14-ddl-silent-data-loss.txt) | [`DdlSilentDataLossTest`](src/test/java/com/ankurm/expandcontract/DdlSilentDataLossTest.java) | ## Findings worth the trip diff --git a/db-migrations-expand-contract/docs/14-the-ddl-lock-window.md b/db-migrations-expand-contract/docs/14-the-ddl-lock-window.md index 4a689c4..a602361 100644 --- a/db-migrations-expand-contract/docs/14-the-ddl-lock-window.md +++ b/db-migrations-expand-contract/docs/14-the-ddl-lock-window.md @@ -16,17 +16,31 @@ the handful of errors it reported. ## Failure mode 1: a statement that collides with the DDL, and says so -While `V3__drop_email_column.sql` runs, a concurrent, otherwise-correct `INSERT` or -`UPDATE` can briefly see: +While `V3__drop_email_column.sql` runs, a concurrent, otherwise-correct query can +briefly see the table disappear out from under it. +[`DdlCollisionExceptionTest`](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/db-migrations-expand-contract/src/test/java/com/ankurm/expandcontract/DdlCollisionExceptionTest.java) +reproduces this directly, at the raw JDBC level — one thread reading the table in a +tight loop while `V3` (`DROP COLUMN`) runs concurrently on another connection: ``` -org.h2.jdbc.JdbcSQLSyntaxErrorException: Table "CUSTOMERS" not found +successful reads while DROP COLUMN was in flight: 222 +reads that collided with the in-flight DROP COLUMN: 1 +example: org.h2.jdbc.JdbcSQLSyntaxErrorException: Table "CUSTOMERS" not found; SQL statement: +SELECT COUNT(*) FROM customers [42102-240] ``` -This is a real, transient condition captured live, twice, in independent runs of this -module's load generator — not a bug in the application's SQL. H2's TCP server -appears to make the table briefly unavailable to other sessions while `DROP COLUMN` -executes. The fix is a narrowly scoped single retry in +Full transcript: +[`docs/output/14-ddl-collision-exception.txt`](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/db-migrations-expand-contract/docs/output/14-ddl-collision-exception.txt). +This test bypasses `CustomerService` deliberately — its own retry would silently +absorb the very exception this test exists to show — and, like +`DdlSilentDataLossTest` below, repeats the race until it reproduces, since exactly +when it fires is OS thread scheduling, not application logic. + +This same condition is what first showed up as `create-http-500` / `update-http-500` +errors in this module's own live load-generator run, twice, in independent runs — +not a bug in the application's SQL. H2's TCP server appears to make the table +briefly unavailable to other sessions while `DROP COLUMN` executes. The fix is a +narrowly scoped single retry in [`CustomerService.withRetryForConcurrentDdl`](https://ankurm.com/git.app/asmhatre/spring-boot-demo/src/branch/main/db-migrations-expand-contract/src/main/java/com/ankurm/expandcontract/customer/CustomerService.java): ```java diff --git a/db-migrations-expand-contract/docs/output/14-ddl-collision-exception.txt b/db-migrations-expand-contract/docs/output/14-ddl-collision-exception.txt new file mode 100644 index 0000000..c9337e2 --- /dev/null +++ b/db-migrations-expand-contract/docs/output/14-ddl-collision-exception.txt @@ -0,0 +1,10 @@ +============================================================================== +Failure mode 1: a concurrent statement that collides with DROP COLUMN, and is told so +============================================================================== +captured: 2026-09-16T19:29:03.872467327Z + +attempts needed to reproduce the race: 4 of 20 +successful reads while DROP COLUMN was in flight: 222 +reads that collided with the in-flight DROP COLUMN: 1 +example: org.h2.jdbc.JdbcSQLSyntaxErrorException: Table "CUSTOMERS" not found; SQL statement: +SELECT COUNT(*) FROM customers [42102-240] diff --git a/db-migrations-expand-contract/src/test/java/com/ankurm/expandcontract/DdlCollisionExceptionTest.java b/db-migrations-expand-contract/src/test/java/com/ankurm/expandcontract/DdlCollisionExceptionTest.java new file mode 100644 index 0000000..fa666fb --- /dev/null +++ b/db-migrations-expand-contract/src/test/java/com/ankurm/expandcontract/DdlCollisionExceptionTest.java @@ -0,0 +1,92 @@ +package com.ankurm.expandcontract; + +import org.junit.jupiter.api.Test; +import org.junit.jupiter.api.io.TempDir; +import org.springframework.jdbc.core.simple.JdbcClient; + +import java.nio.file.Path; +import java.util.List; +import java.util.concurrent.CopyOnWriteArrayList; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.atomic.AtomicBoolean; + +import static org.assertj.core.api.Assertions.assertThat; + +/** + * The first of two failure modes covered in docs/14-the-ddl-lock-window.md, isolated here at + * the raw JDBC level rather than through {@link com.ankurm.expandcontract.customer.CustomerService}, + * because that class's {@code withRetryForConcurrentDdl} would silently absorb exactly the + * exception this test exists to show. While {@code ALTER TABLE ... DROP COLUMN} (V3) executes, + * a concurrent, otherwise-correct statement against the same table can briefly see + * {@code Table "CUSTOMERS" not found} - a real, transient condition, first noticed in this + * module's own live load-generator run and reproduced here on demand. See + * {@link DdlSilentDataLossTest} for the second, stranger failure mode the same root cause + * produces - a statement that succeeds and is still lost, with no exception at all. + */ +class DdlCollisionExceptionTest { + + private static final int MAX_ATTEMPTS = 20; + + @Test + void concurrentStatementCanSeeTableNotFoundWhileDropColumnRuns(@TempDir Path tmp) throws Exception { + Transcript t = Transcript.start("14-ddl-collision-exception", + "Failure mode 1: a concurrent statement that collides with DROP COLUMN, and is told so"); + + for (int attempt = 1; attempt <= MAX_ATTEMPTS; attempt++) { + Path db = tmp.resolve("collision-exception-" + attempt); + TestSupport.migrateTo(db, "2"); + JdbcClient jdbc = TestSupport.jdbcClient(db); + + AtomicBoolean stop = new AtomicBoolean(false); + List collisionMessages = new CopyOnWriteArrayList<>(); + List okCount = new CopyOnWriteArrayList<>(); + CountDownLatch started = new CountDownLatch(1); + + Thread reader = new Thread(() -> { + started.countDown(); + long ok = 0; + while (!stop.get()) { + try { + jdbc.sql("SELECT COUNT(*) FROM customers").query(Long.class).single(); + ok++; + } catch (Exception ex) { + Throwable root = ex; + while (root.getCause() != null) { + root = root.getCause(); + } + if (root.getMessage() != null && root.getMessage().contains("CUSTOMERS")) { + collisionMessages.add(root.getClass().getName() + ": " + root.getMessage()); + } + } + } + okCount.add(ok); + }); + reader.start(); + started.await(); + + // Deploy 4b, running live while the reader above keeps querying the same table. + TestSupport.migrateTo(db, "3"); + + stop.set(true); + reader.join(); + + if (collisionMessages.isEmpty() && attempt < MAX_ATTEMPTS) { + continue; + } + + t.line("attempts needed to reproduce the race: " + attempt + " of " + MAX_ATTEMPTS); + t.line("successful reads while DROP COLUMN was in flight: " + okCount.get(0)); + t.line("reads that collided with the in-flight DROP COLUMN: " + collisionMessages.size()); + if (!collisionMessages.isEmpty()) { + t.line("example: " + collisionMessages.get(0)); + } + t.write(); + + assertThat(collisionMessages) + .withFailMessage("expected at least one concurrent read to collide with DROP COLUMN " + + "within %d attempts", MAX_ATTEMPTS) + .isNotEmpty(); + return; + } + } +}