db-migrations-expand-contract: add a dedicated reproduction for the DDL-collision exception

While writing the article, chapter 14's first failure mode (a concurrent statement seeing "Table CUSTOMERS not found" while DROP COLUMN runs) was described from the live load-generator run but had no dedicated, committed reproduction of its own - CustomerService's own retry would silently absorb it if triggered through the service layer. DdlCollisionExceptionTest reproduces it directly at the raw JDBC level, and the chapter and README now link to its captured transcript. Co-Authored-By: Claude Sonnet 5 <[email protected]> Claude-Session: https://claude.ai/code/session_019Fb7vW8vLyLKngBc4R3huA
2026-09-16 19:33:31 +00:00
parent e478eafda3
commit a875bea55a
4 changed files with 124 additions and 7 deletions
@@ -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
@@ -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
@@ -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]
@@ -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<String> collisionMessages = new CopyOnWriteArrayList<>();
+            List<Long> 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;
+        }
+    }
+}