Skip to content

Commit ad4c6c6

Browse files
ecrum19claude
andcommitted
Retry the comunica warm-up probe instead of failing on a refused port
The cross-engine agreement job failed on a commit that changed only a docstring, and its message named a timeout that had not happened: comunica could not read /work/.../expanded.nt within 3600s (raise --comunica-warmup-timeout, or use --engine qlever): <urlopen error [Errno 111] Connection refused> It had waited milliseconds. `timeout=` on urlopen is the socket timeout -- how long to wait for a response -- and a refused connection comes back from the kernel at once, so the budget never applied. `_await_bind` already loops and tolerates refusal; `_await_warm` made exactly one attempt. That asymmetry was the bug: comunica answers the bind probe and then hands the socket to its worker, so the next connection can be refused for a moment while the process is perfectly healthy. The probe now retries until the budget is genuinely spent, and the reported duration is measured rather than read back from the flag. Retrying must not become tolerance for a dead engine, so two conditions still fail immediately: the server process exiting, which keeps its exit code and log tail, and the endpoint *answering* with an error. An HTTPError means comunica replied -- a source it cannot parse would answer every probe identically, and retrying it would spin for the whole budget before reporting what it knew on the first attempt. This gates merges, and it is timing-dependent rather than rare: the image floats its base and its apt nodejs and python3, so a rebuild can shift the timing that exposes it. `HdtEngine` shares the mixin, so it was exposed to the same failure. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
1 parent 7a6bf37 commit ad4c6c6

5 files changed

Lines changed: 217 additions & 14 deletions

File tree

‎docs/roadmap.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -33,7 +33,7 @@ a record with `ALT=.` satisfies both the shape and `vcfc:missingValuePolicy`.
3333

3434
### ~~1. The validation suite has not been migrated~~ — **done**
3535

36-
The suite passes: 703 tests, mutation score 96/113 (85%) across 60 mutations.
36+
The suite passes: 707 tests, mutation score 96/113 (85%) across 60 mutations.
3737
The runner and the wrapper now share one vocabulary module instead of mirroring
3838
each other, and the census derives every new resource family from the VCF. Ten
3939
of the eighteen new mutations are recorded gaps, each with what would close it.

‎docs/validation-migration-notes.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@ and follows each input's declared VCF version. The validation suite has been
77
migrated with it. This file records what changed, what it found, and what is
88
still open.
99

10-
**Status: the suite passes.** 703 tests, no failures. The mutation score is
10+
**Status: the suite passes.** 707 tests, no failures. The mutation score is
1111
96/113 (85%) across 60 mutations, each listed with its expected detector.
1212

1313
---

‎docs/validation.md‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -97,6 +97,29 @@ vcf-rdfizer --mode full -i cohort.vcf.gz --validate \
9797
--validation-query-timeout 14400 --validation-time-budget 86400 -o ./out
9898
```
9999

100+
### A startup probe that fails on a healthy engine
101+
102+
Comunica's endpoint is probed twice at startup: `_await_bind` waits for the
103+
port to answer at all, then `_await_warm` proves the endpoint can actually read
104+
the source, so that readiness is charged to setup rather than billed to the
105+
first query.
106+
107+
The warm-up probe used to be a single request. Comunica answers the bind probe
108+
and then hands the socket to its worker, so the next connection can be refused
109+
for a moment while the process is perfectly healthy — and a refused connection
110+
comes back from the kernel immediately, not after the warm-up budget. The result
111+
was an engine that failed in milliseconds while reporting
112+
113+
```
114+
comunica could not read /work/…/expanded.nt within 3600s
115+
```
116+
117+
a timeout it had never waited for. The probe now retries until the budget is
118+
genuinely spent, still failing at once if the server process exits or if the
119+
endpoint *answers* with an error, and the duration in the message is measured
120+
rather than read back from the flag. If you see that message now, the wait was
121+
real: raise `--comunica-warmup-timeout`, or use `--engine qlever`.
122+
100123
### A decode that reports success and writes garbage
101124

102125
Every decode into N-Triples is now checked structurally before anything reads

‎src/validation/validation_runner.py‎

Lines changed: 57 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -2254,27 +2254,72 @@ def _await_bind(self, server_log: Path) -> None:
22542254
f"{self.bind_timeout}s: {last_error}"
22552255
)
22562256

2257+
@staticmethod
2258+
def _is_connection_level_error(error: BaseException) -> bool:
2259+
"""Is this the socket never opening, rather than the server answering?
2260+
2261+
An HTTPError means the endpoint replied, so whatever it said is a real
2262+
result and must not be retried. Everything else at this layer -- a
2263+
refused, reset or aborted connection, or a socket that timed out -- is
2264+
about reaching the process, not about what it thinks of the query.
2265+
"""
2266+
import urllib.error
2267+
2268+
if isinstance(error, urllib.error.HTTPError):
2269+
return False
2270+
if isinstance(error, urllib.error.URLError):
2271+
return isinstance(error.reason, (OSError, TimeoutError))
2272+
return isinstance(error, (ConnectionError, TimeoutError))
2273+
22572274
def _await_warm(self, server_log: Path) -> None:
22582275
"""Prove the endpoint can actually read the source, before the suite runs.
22592276
22602277
Charged to setup rather than to the first query, so one query is not
22612278
billed for readiness that every later query got for free.
2279+
2280+
A refused connection is retried rather than fatal. ``_await_bind``
2281+
returns as soon as the port answers one probe, but comunica hands the
2282+
socket to its worker after that reply, so the next connection can be
2283+
refused for a moment while the process is perfectly healthy. Treating
2284+
that as failure made the whole engine unusable on a timing accident --
2285+
and reported it as a timeout that never happened, because a refused
2286+
connection comes back from the kernel at once rather than after the
2287+
warm-up budget. Only the server exiting, an answer from the endpoint,
2288+
or the budget genuinely running out ends this wait.
22622289
"""
22632290
assert self.endpoint is not None
22642291
started = time.monotonic()
2265-
try:
2266-
self._post(
2267-
self.endpoint, "SELECT * WHERE { ?s ?p ?o } LIMIT 1",
2268-
timeout=self.warmup_timeout,
2269-
)
2270-
except Exception as error: # noqa: BLE001 - surfaced as engine failure
2292+
deadline = started + self.warmup_timeout
2293+
last_error: BaseException | None = None
2294+
while True:
22712295
self._assert_alive(server_log)
2272-
raise RuntimeError(
2273-
f"{self.name} could not read {self._endpoint_source_argument()} "
2274-
f"within {self.warmup_timeout}s (raise --comunica-warmup-timeout, "
2275-
f"or use --engine qlever): {error}"
2276-
) from error
2277-
self.warmup_seconds = time.monotonic() - started
2296+
remaining = deadline - time.monotonic()
2297+
if remaining <= 0:
2298+
break
2299+
try:
2300+
self._post(
2301+
self.endpoint, "SELECT * WHERE { ?s ?p ?o } LIMIT 1",
2302+
timeout=remaining,
2303+
)
2304+
except Exception as error: # noqa: BLE001 - surfaced as engine failure
2305+
self._assert_alive(server_log)
2306+
if not self._is_connection_level_error(error):
2307+
raise RuntimeError(
2308+
f"{self.name} could not read "
2309+
f"{self._endpoint_source_argument()}: {error}"
2310+
) from error
2311+
last_error = error
2312+
time.sleep(min(0.5, max(0.0, deadline - time.monotonic())))
2313+
else:
2314+
self.warmup_seconds = time.monotonic() - started
2315+
return
2316+
self._assert_alive(server_log)
2317+
raise RuntimeError(
2318+
f"{self.name} could not read {self._endpoint_source_argument()} "
2319+
f"within {time.monotonic() - started:.0f}s "
2320+
f"(raise --comunica-warmup-timeout, or use --engine qlever): "
2321+
f"{last_error or 'the endpoint never accepted a connection'}"
2322+
)
22782323

22792324
def _assert_alive(self, server_log: Path) -> None:
22802325
if self.server is not None and self.server.poll() is not None:

‎test/test_validation_engines_unit.py‎

Lines changed: 135 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -438,6 +438,141 @@ def fake_popen(command, stdout=None, **kwargs):
438438
engine.start()
439439
self.assertIn("index not found", str(caught.exception))
440440

441+
def _comunica_engine_awaiting_warm(self, tmp_path, *, warmup_timeout):
442+
"""A started comunica engine, parked just before the warm-up probe."""
443+
source = tmp_path / "cohort.nt"
444+
source.write_bytes(TRIPLES)
445+
engine = V.build_engine(
446+
"comunica", source, raw_dir=tmp_path, scratch=tmp_path,
447+
options={"comunica_warmup_timeout": warmup_timeout},
448+
)
449+
engine.endpoint = f"http://127.0.0.1:{engine.port}/sparql"
450+
engine.server = mock.MagicMock()
451+
engine.server.poll.return_value = None
452+
return engine
453+
454+
def test_a_refused_connection_during_warmup_is_retried(self):
455+
"""The bind probe is not a promise that the next connection is accepted.
456+
457+
comunica answers the bind probe and then hands the socket to its
458+
worker, so a connection a moment later can be refused while the process
459+
is perfectly healthy. That briefly-closed port used to fail the whole
460+
engine - and the run it gated - on a timing accident.
461+
"""
462+
import urllib.error
463+
464+
with tempfile.TemporaryDirectory() as td:
465+
tmp_path = Path(td)
466+
engine = self._comunica_engine_awaiting_warm(tmp_path, warmup_timeout=30)
467+
attempts = []
468+
469+
def flaky_post(endpoint, query, *, timeout):
470+
attempts.append(timeout)
471+
if len(attempts) < 3:
472+
raise urllib.error.URLError(ConnectionRefusedError(111, "refused"))
473+
return b'{"results": {"bindings": []}}'
474+
475+
with mock.patch.object(engine, "_post", flaky_post), \
476+
mock.patch.object(V.time, "sleep"):
477+
engine._await_warm(tmp_path / "server.log")
478+
479+
self.assertEqual(len(attempts), 3)
480+
self.assertIsNotNone(engine.warmup_seconds)
481+
# Each attempt is given what is left of the budget, never the whole
482+
# of it again, so retrying cannot outlive --comunica-warmup-timeout.
483+
self.assertLessEqual(attempts[-1], attempts[0])
484+
485+
def test_a_server_that_dies_during_warmup_fails_at_once(self):
486+
"""Retrying a refused port must not paper over a dead engine."""
487+
import urllib.error
488+
489+
with tempfile.TemporaryDirectory() as td:
490+
tmp_path = Path(td)
491+
server_log = tmp_path / "server.log"
492+
server_log.write_text("comunica: out of memory\n", encoding="utf-8")
493+
engine = self._comunica_engine_awaiting_warm(tmp_path, warmup_timeout=3600)
494+
engine.server.poll.return_value = 137
495+
engine.server.returncode = 137
496+
497+
def refused(endpoint, query, *, timeout):
498+
raise urllib.error.URLError(ConnectionRefusedError(111, "refused"))
499+
500+
started = time.monotonic()
501+
with mock.patch.object(engine, "_post", refused):
502+
with self.assertRaises(RuntimeError) as caught:
503+
engine._await_warm(server_log)
504+
505+
# Fails on the dead process, not after the 3600s budget.
506+
self.assertLess(time.monotonic() - started, 30)
507+
self.assertIn("137", str(caught.exception))
508+
self.assertIn("out of memory", str(caught.exception))
509+
510+
def test_an_answered_error_is_not_retried(self):
511+
"""An HTTP reply is the endpoint's verdict, not a connection problem.
512+
513+
A source comunica cannot parse answers every probe the same way, so
514+
retrying it would spin for the whole warm-up budget before reporting
515+
what it already knew on the first attempt.
516+
"""
517+
import urllib.error
518+
519+
with tempfile.TemporaryDirectory() as td:
520+
tmp_path = Path(td)
521+
engine = self._comunica_engine_awaiting_warm(tmp_path, warmup_timeout=3600)
522+
attempts = []
523+
524+
def http_error(endpoint, query, *, timeout):
525+
attempts.append(timeout)
526+
raise urllib.error.HTTPError(
527+
endpoint, 500, "Parse error", {}, None
528+
)
529+
530+
with mock.patch.object(engine, "_post", http_error):
531+
with self.assertRaises(RuntimeError) as caught:
532+
engine._await_warm(tmp_path / "server.log")
533+
534+
self.assertEqual(len(attempts), 1)
535+
message = str(caught.exception)
536+
self.assertIn("could not read", message)
537+
# The old message claimed a timeout it had never waited for.
538+
self.assertNotIn("3600s", message)
539+
540+
def test_an_exhausted_warmup_budget_reports_the_time_it_waited(self):
541+
"""The duration in the message must be measured, not the flag's value.
542+
543+
The original reported the configured budget whatever had happened, so a
544+
connection refused in milliseconds was announced as an hour-long
545+
timeout - pointing every reader at the wrong thing entirely.
546+
"""
547+
import itertools
548+
import urllib.error
549+
550+
with tempfile.TemporaryDirectory() as td:
551+
tmp_path = Path(td)
552+
engine = self._comunica_engine_awaiting_warm(tmp_path, warmup_timeout=30)
553+
attempts = []
554+
555+
def refused(endpoint, query, *, timeout):
556+
attempts.append(timeout)
557+
raise urllib.error.URLError(ConnectionRefusedError(111, "refused"))
558+
559+
# A clock that runs 10s per reading, so the budget expires after one
560+
# attempt without the test waiting for any of it.
561+
clock = itertools.count(0, 10)
562+
with mock.patch.object(V.time, "monotonic", lambda: next(clock)), \
563+
mock.patch.object(V.time, "sleep"), \
564+
mock.patch.object(engine, "_post", refused):
565+
with self.assertRaises(RuntimeError) as caught:
566+
engine._await_warm(tmp_path / "server.log")
567+
568+
self.assertEqual(len(attempts), 1)
569+
message = str(caught.exception)
570+
# 40s elapsed against a 30s budget: the figure is measured, and is
571+
# not simply the flag read back out.
572+
self.assertIn("within 40s", message)
573+
self.assertIn("refused", message)
574+
self.assertIn("--comunica-warmup-timeout", message)
575+
441576
def test_qlever_command_lines_are_overridable(self):
442577
"""QLever's CLI varies by release, so both argv are user-overridable."""
443578
with tempfile.TemporaryDirectory() as td:

0 commit comments

Comments
 (0)