Skip to content

Commit cb1496e

Browse files
dmealingclaude
dmealing
and
claude
committed
test(integration): close the container port race and stop reporting death as slowness
CORRECTION TO THE PREVIOUS COMMIT. I widened the readiness window to 120s on the theory that the containers were merely slow under concurrent load. The next full CI run failed with "did not become ready within 120s" -- a container that cannot start in two minutes is not slow, so the diagnosis was wrong and the fix only made the wrong answer take longer to arrive. The real shape, and it is two bugs wearing one error message. 1. A PORT RACE. pickFreePort() opens a probe socket, closes it, and hands the number to docker, which binds it LATER. Check-then-act. Running one port's suite alone it never bites; a FULL CI run starts five ports' containers at once and two can be handed the same number. The loser's container is created and then dies. 2. A READINESS PROBE THAT CANNOT SEE DEATH. The loop only ever asked `docker exec ... pg_isready`, which fails identically for "still booting" and "exited ten seconds ago". So a container that died on startup burned the whole window and reported a TIMEOUT -- naming a symptom, and one that reads as slowness. Widening the window made this strictly worse: same wrong answer, four times the wait. `--rm` compounded it: an auto-removed container takes its logs with it, so the single artefact that would explain the failure vanished exactly when it was needed. Fixed in all four ports, which each carried their own copy of the same loop: - retry on a FRESH port (3 attempts), covering both the outright bind refusal and the container that starts and dies - drop `--rm` so a corpse survives; close()/stop() already force-remove - fail FAST when docker reports the container is not running -- including "gone", which with --rm was the common case -- and surface `docker logs` - the timeout message now reports the container STATE and its logs, so a real timeout is distinguishable from a death at a glance The 120s window from the previous commit stays. It was not the fix, but it is not wrong either: 30s was a guess, and the bound now only governs the case where a container is genuinely alive and slow. Verified: ApiContractConformanceTest -- the 26-scenario suite whose scenario[2] failed in the last full run -- passes. java, kotlin and typescript integration modules compile; python parses. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 0dc990b commit cb1496e

4 files changed

Lines changed: 302 additions & 55 deletions

File tree

‎server/java/integration-tests-kotlin/src/test/kotlin/com/metaobjects/integration/kotlin/PostgresContainer.kt‎

Lines changed: 79 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -59,16 +59,46 @@ class PostgresContainer : AutoCloseable {
5959
username = PG_USER
6060
password = PG_PASSWORD
6161
name = "metaobjects-test-kt-" + UUID.randomUUID().toString().substring(0, 8)
62-
val port = pickFreePort()
63-
runDocker(
64-
"run", "-d", "--rm",
65-
"--name", name,
66-
"-e", "POSTGRES_PASSWORD=$PG_PASSWORD",
67-
"-p", "$port:5432",
68-
IMAGE,
62+
// PORT RACE. pickFreePort() closes its probe socket and hands the number to
63+
// docker, which binds it LATER -- a check-then-act gap. Alone it never bites;
64+
// under a full CI run several ports start containers at once and two can be
65+
// handed the same number. The loser's container is created and then dies, and
66+
// a readiness probe that only asks `docker exec` cannot tell that from a slow
67+
// boot. Retry on a FRESH port.
68+
//
69+
// Deliberately NOT `--rm`: an auto-removed container takes its logs with it,
70+
// so the one artefact explaining the failure vanishes exactly when it is
71+
// needed. close() force-removes, so nothing leaks.
72+
var startedUrl: String? = null
73+
var lastFailure: RuntimeException? = null
74+
for (attempt in 1..START_ATTEMPTS) {
75+
if (startedUrl != null) break
76+
val port = pickFreePort()
77+
try {
78+
runDocker(
79+
"run", "-d",
80+
"--name", name,
81+
"-e", "POSTGRES_PASSWORD=$PG_PASSWORD",
82+
"-p", "$port:5432",
83+
IMAGE,
84+
)
85+
} catch (e: RuntimeException) {
86+
lastFailure = e // docker refused the bind outright
87+
forceRemove()
88+
continue
89+
}
90+
val candidate = "jdbc:postgresql://localhost:$port/postgres"
91+
try {
92+
waitForReady(candidate)
93+
startedUrl = candidate
94+
} catch (e: RuntimeException) {
95+
lastFailure = e
96+
forceRemove()
97+
}
98+
}
99+
jdbcUrl = startedUrl ?: throw RuntimeException(
100+
"postgres container '$name' failed to start in $START_ATTEMPTS attempts", lastFailure,
69101
)
70-
jdbcUrl = "jdbc:postgresql://localhost:$port/postgres"
71-
waitForReady()
72102
}
73103
}
74104

@@ -99,19 +129,29 @@ class PostgresContainer : AutoCloseable {
99129
}
100130
}
101131

102-
private fun waitForReady() {
132+
private fun waitForReady(url: String) {
103133
// READINESS WINDOW. 30s was too tight: under a FULL local-CI run several ports
104134
// spin their own Postgres concurrently, and a container that is merely slow to
105135
// boot produces a red gate indistinguishable from a real failure -- it fires
106136
// BEFORE any test logic. Raising the bound costs nothing when the container is
107137
// ready quickly (this polls every 250ms and returns immediately).
108138
val deadline = System.currentTimeMillis() + (READY_TIMEOUT_S * 1000L)
109139
while (System.currentTimeMillis() < deadline) {
140+
// FAIL FAST ON A DEAD CONTAINER -- `docker exec` alone cannot tell "still
141+
// booting" from "exited seconds ago", so a dead container used to burn the
142+
// whole window and report a TIMEOUT, which reads as slowness and is not.
143+
val state = inspectState()
144+
if (state != "running") {
145+
throw RuntimeException(
146+
"postgres container '$name' is '$state', not running -- it died during " +
147+
"startup rather than being slow. docker logs:\n" + tailLogs(),
148+
)
149+
}
110150
try {
111151
val p = ProcessBuilder("docker", "exec", name, "pg_isready", "-U", PG_USER)
112152
.redirectErrorStream(true)
113153
.start()
114-
if (p.waitFor() == 0 && canConnect()) return
154+
if (p.waitFor() == 0 && canConnect(url)) return
115155
} catch (_: Exception) {
116156
// Try again.
117157
}
@@ -122,22 +162,47 @@ class PostgresContainer : AutoCloseable {
122162
return
123163
}
124164
}
125-
throw RuntimeException("postgres container '$name' did not become ready within ${READY_TIMEOUT_S}s")
165+
throw RuntimeException(
166+
"postgres container '$name' did not become ready within ${READY_TIMEOUT_S}s " +
167+
"(state=${inspectState()}). docker logs:\n" + tailLogs(),
168+
)
126169
}
127170

128-
private fun canConnect(): Boolean = try {
129-
DriverManager.getConnection(jdbcUrl, PG_USER, PG_PASSWORD).use { c -> c.isValid(2) }
171+
private fun canConnect(url: String): Boolean = try {
172+
DriverManager.getConnection(url, PG_USER, PG_PASSWORD).use { c -> c.isValid(2) }
130173
} catch (_: Exception) {
131174
false
132175
}
133176

177+
/** Best-effort teardown between start attempts. */
178+
private fun forceRemove() {
179+
try { runDocker("rm", "-f", name!!) } catch (_: RuntimeException) { /* already gone */ } // non-null in per-container mode
180+
}
181+
182+
/** The container's docker state, or "gone" when it cannot be determined. */
183+
private fun inspectState(): String = try {
184+
runDocker("inspect", "-f", "{{.State.Status}}", name!!) // non-null in per-container mode
185+
} catch (_: RuntimeException) {
186+
"gone"
187+
}
188+
189+
/** Last few log lines, for an error that would otherwise name only a symptom. */
190+
private fun tailLogs(): String = try {
191+
runDocker("logs", "--tail", "40", name!!) // non-null in per-container mode
192+
} catch (e: RuntimeException) {
193+
"(docker logs unavailable: ${e.message})"
194+
}
195+
134196
companion object {
135197
/** Env var naming the shared CI Postgres sidecar (admin URL). Unset = per-container fallback. */
136198
private const val SHARED_PG_URL_ENV = "METAOBJECTS_TEST_PG_URL"
137199
private const val IMAGE = "postgres:16-alpine"
138200
private const val PG_USER = "postgres"
139201
private const val PG_PASSWORD = "test"
140202

203+
/** Fresh-port retries before giving up -- see the port-race note above. */
204+
private const val START_ATTEMPTS = 3
205+
141206
/** Container readiness bound, seconds. Overridable so a loaded CI box can widen it. */
142207
private val READY_TIMEOUT_S: Int =
143208
(System.getenv("MO_PG_READY_TIMEOUT_S") ?: "120").toInt()

‎server/java/integration-tests/src/test/java/com/metaobjects/integration/PostgresContainer.java‎

Lines changed: 80 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -79,14 +79,47 @@ public PostgresContainer() {
7979
this.username = PG_USER;
8080
this.password = PG_PASSWORD;
8181
this.name = "metaobjects-test-" + UUID.randomUUID().toString().substring(0, 8);
82-
int port = pickFreePort();
83-
runDocker("run", "-d", "--rm",
84-
"--name", name,
85-
"-e", "POSTGRES_PASSWORD=" + PG_PASSWORD,
86-
"-p", port + ":5432",
87-
IMAGE);
88-
this.jdbcUrl = "jdbc:postgresql://localhost:" + port + "/postgres";
89-
waitForReady();
82+
// PORT RACE. pickFreePort() opens a socket, closes it, and hands the number to
83+
// docker, which binds it LATER -- a check-then-act gap. Alone that never bites;
84+
// under a full CI run five ports start containers at once and two can be handed
85+
// the same number. The loser's container is created and then dies, and because
86+
// the readiness probe only ever asked `docker exec`, a dead container was
87+
// indistinguishable from a slow one for the whole window. Retry on a FRESH port.
88+
//
89+
// Deliberately NOT `--rm`: an auto-removed container takes its logs with it, so
90+
// the one artefact that explains the failure disappears exactly when it is
91+
// needed. close() already force-removes, so nothing leaks.
92+
String startedUrl = null;
93+
RuntimeException lastFailure = null;
94+
for (int attempt = 1; attempt <= START_ATTEMPTS && startedUrl == null; attempt++) {
95+
int port = pickFreePort();
96+
try {
97+
runDocker("run", "-d",
98+
"--name", name,
99+
"-e", "POSTGRES_PASSWORD=" + PG_PASSWORD,
100+
"-p", port + ":5432",
101+
IMAGE);
102+
} catch (RuntimeException e) {
103+
// docker refused the bind outright -- the cleanest form of the race.
104+
lastFailure = e;
105+
forceRemove();
106+
continue;
107+
}
108+
String candidate = "jdbc:postgresql://localhost:" + port + "/postgres";
109+
try {
110+
waitForReady(candidate);
111+
startedUrl = candidate;
112+
} catch (RuntimeException e) {
113+
lastFailure = e;
114+
forceRemove();
115+
}
116+
}
117+
if (startedUrl == null) {
118+
throw new RuntimeException(
119+
"postgres container '" + name + "' failed to start in " + START_ATTEMPTS + " attempts",
120+
lastFailure);
121+
}
122+
this.jdbcUrl = startedUrl;
90123
}
91124

92125
public String jdbcUrl() { return jdbcUrl; }
@@ -154,26 +187,60 @@ private static String runDocker(String... args) {
154187
// test logic. Raising the bound costs nothing when the container is ready quickly
155188
// (this polls every 250ms and returns immediately) and only changes how long the
156189
// pathological case takes to give up.
190+
/** Fresh-port retries before giving up -- see the port-race note in the constructor. */
191+
private static final int START_ATTEMPTS = 3;
192+
157193
private static final int READY_TIMEOUT_S =
158194
Integer.parseInt(System.getenv().getOrDefault("MO_PG_READY_TIMEOUT_S", "120"));
159195

160-
private void waitForReady() {
196+
private void waitForReady(String url) {
161197
long deadline = System.currentTimeMillis() + (READY_TIMEOUT_S * 1000L);
162198
while (System.currentTimeMillis() < deadline) {
199+
// FAIL FAST ON A DEAD CONTAINER. Polling `docker exec` alone cannot tell
200+
// "still booting" from "exited seconds ago" -- both just fail -- so a
201+
// container that died on startup used to burn the whole window and then
202+
// report a TIMEOUT, which reads as slowness and is not. Ask docker whether
203+
// it is still running, and if not, surface its logs: that is the actual
204+
// reason, and without it the error names a symptom.
205+
String state = inspectState();
206+
if (state == null || !"running".equals(state)) {
207+
throw new RuntimeException(
208+
"postgres container '" + name + "' is '" + (state == null ? "gone" : state) + "', not"
209+
+ " running -- it died during startup rather than being slow. docker logs:\n" + tailLogs());
210+
}
163211
try {
164212
Process p = new ProcessBuilder("docker", "exec", name, "pg_isready", "-U", PG_USER)
165213
.redirectErrorStream(true).start();
166-
if (p.waitFor() == 0 && canConnect()) return;
214+
if (p.waitFor() == 0 && canConnect(url)) return;
167215
} catch (Exception ignored) { /* try again */ }
168216
try { Thread.sleep(250); } catch (InterruptedException e) {
169217
Thread.currentThread().interrupt(); return;
170218
}
171219
}
172-
throw new RuntimeException("postgres container '" + name + "' did not become ready within " + READY_TIMEOUT_S + "s");
220+
throw new RuntimeException(
221+
"postgres container '" + name + "' did not become ready within " + READY_TIMEOUT_S + "s"
222+
+ " (state=" + inspectState() + "). docker logs:\n" + tailLogs());
223+
}
224+
225+
/** Best-effort teardown between start attempts. */
226+
private void forceRemove() {
227+
try { runDocker("rm", "-f", name); } catch (RuntimeException ignored) { /* already gone */ }
228+
}
229+
230+
/** The container's docker state, or null when it cannot be determined. */
231+
private String inspectState() {
232+
try { return runDocker("inspect", "-f", "{{.State.Status}}", name); }
233+
catch (RuntimeException e) { return null; }
234+
}
235+
236+
/** Last few log lines, for an error that would otherwise name only a symptom. */
237+
private String tailLogs() {
238+
try { return runDocker("logs", "--tail", "40", name); }
239+
catch (RuntimeException e) { return "(docker logs unavailable: " + e.getMessage() + ")"; }
173240
}
174241

175-
private boolean canConnect() {
176-
try (Connection c = DriverManager.getConnection(jdbcUrl, PG_USER, PG_PASSWORD)) {
242+
private boolean canConnect(String url) {
243+
try (Connection c = DriverManager.getConnection(url, PG_USER, PG_PASSWORD)) {
177244
return c.isValid(2);
178245
} catch (SQLException ignored) { return false; }
179246
}

‎server/python/tests/integration/postgres_container.py‎

Lines changed: 76 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,9 @@ class PostgresContainer:
4242
"""Context manager around ``docker run`` for a per-scenario Postgres."""
4343

4444
IMAGE = "postgres:16-alpine"
45+
46+
#: Fresh-port retries before giving up -- see the port-race note in __init__.
47+
START_ATTEMPTS = 3
4548
USER = "postgres"
4649
PASSWORD = "test"
4750
DATABASE = "postgres"
@@ -57,19 +60,45 @@ def __init__(self) -> None:
5760
self._shared = False
5861
self._admin_url = None
5962
self._name = f"metaobjects-test-{uuid.uuid4().hex[:8]}"
60-
self._port = _pick_free_port()
61-
self._info = PostgresInfo(
62-
host="localhost", port=self._port, database=self.DATABASE,
63-
user=self.USER, password=self.PASSWORD,
64-
)
65-
_docker(
66-
"run", "-d", "--rm",
67-
"--name", self._name,
68-
"-e", f"POSTGRES_PASSWORD={self.PASSWORD}",
69-
"-p", f"{self._port}:5432",
70-
self.IMAGE,
63+
# PORT RACE. _pick_free_port() closes its probe socket and hands the number to
64+
# docker, which binds it LATER -- a check-then-act gap. Alone it never bites;
65+
# under a full CI run several ports start containers at once and two can be
66+
# handed the same number. The loser's container is created and then dies, and a
67+
# readiness probe that only asks `docker exec` cannot tell that from a slow
68+
# boot. Retry on a FRESH port.
69+
#
70+
# Deliberately NOT `--rm`: an auto-removed container takes its logs with it, so
71+
# the one artefact explaining the failure vanishes exactly when it is needed.
72+
# close() force-removes, so nothing leaks.
73+
last_failure: Exception | None = None
74+
for _attempt in range(self.START_ATTEMPTS):
75+
self._port = _pick_free_port()
76+
self._info = PostgresInfo(
77+
host="localhost", port=self._port, database=self.DATABASE,
78+
user=self.USER, password=self.PASSWORD,
79+
)
80+
try:
81+
_docker(
82+
"run", "-d",
83+
"--name", self._name,
84+
"-e", f"POSTGRES_PASSWORD={self.PASSWORD}",
85+
"-p", f"{self._port}:5432",
86+
self.IMAGE,
87+
)
88+
except Exception as e: # noqa: BLE001 — docker refused the bind; retry on a new port
89+
last_failure = e
90+
self._force_remove()
91+
continue
92+
try:
93+
self._wait_ready()
94+
return
95+
except Exception as e: # noqa: BLE001 — died on startup; retry on a new port
96+
last_failure = e
97+
self._force_remove()
98+
raise RuntimeError(
99+
f"postgres container '{self._name}' failed to start in "
100+
f"{self.START_ATTEMPTS} attempts; last err: {last_failure}"
71101
)
72-
self._wait_ready()
73102

74103
# -- Shared-sidecar mode -------------------------------------------------
75104
# CREATE a fresh, uniquely-named database on the already-running Postgres
@@ -144,12 +173,44 @@ def __exit__(self, *exc: object) -> None:
144173
# BEFORE any test logic. Raising the bound costs nothing when the container is
145174
# ready quickly (the loop polls every 250ms and returns immediately) and only
146175
# changes how long the pathological case takes to give up.
176+
def _force_remove(self) -> None:
177+
"""Best-effort teardown between start attempts."""
178+
try:
179+
_docker("rm", "-f", self._name)
180+
except Exception: # noqa: BLE001 — already gone
181+
pass
182+
183+
def _inspect_state(self) -> str:
184+
"""The container's docker state, or 'gone' when it cannot be determined."""
185+
r = subprocess.run(
186+
["docker", "inspect", "-f", "{{.State.Status}}", self._name],
187+
capture_output=True, text=True,
188+
)
189+
return r.stdout.strip() if r.returncode == 0 else "gone"
190+
191+
def _tail_logs(self) -> str:
192+
"""Last few log lines, for an error that would otherwise name only a symptom."""
193+
r = subprocess.run(
194+
["docker", "logs", "--tail", "40", self._name], capture_output=True, text=True,
195+
)
196+
return (r.stdout + r.stderr).strip() if r.returncode == 0 else "(docker logs unavailable)"
197+
147198
def _wait_ready(self) -> None:
148199
import pg8000.dbapi # local import — pg8000 lives in the `integration` extra
149200
timeout_s = int(os.environ.get("MO_PG_READY_TIMEOUT_S", "120"))
150201
deadline = time.monotonic() + timeout_s
151202
last_err: Exception | None = None
152203
while time.monotonic() < deadline:
204+
# FAIL FAST ON A DEAD CONTAINER. `docker exec` alone cannot tell "still
205+
# booting" from "exited seconds ago" -- both just fail -- so a container that
206+
# died on startup used to burn the whole window and report a TIMEOUT, which
207+
# reads as slowness and is not. Ask docker for its state and surface its logs.
208+
state = self._inspect_state()
209+
if state != "running":
210+
raise RuntimeError(
211+
f"postgres container '{self._name}' is '{state}', not running -- it died "
212+
f"during startup rather than being slow. docker logs:\n{self._tail_logs()}"
213+
)
153214
ready = subprocess.run(
154215
["docker", "exec", self._name, "pg_isready", "-U", self.USER],
155216
capture_output=True,
@@ -166,7 +227,9 @@ def _wait_ready(self) -> None:
166227
last_err = e
167228
time.sleep(0.25)
168229
raise RuntimeError(
169-
f"postgres container '{self._name}' did not become ready within {timeout_s}s; last err: {last_err}"
230+
f"postgres container '{self._name}' did not become ready within {timeout_s}s "
231+
f"(state={self._inspect_state()}); last err: {last_err}. "
232+
f"docker logs:\n{self._tail_logs()}"
170233
)
171234

172235

0 commit comments

Comments
 (0)