jhm --test can hang forever reaping a test that has already exited, burning the whole CI job with no diagnostic. Hit for real on an aarch64 runner: the suite stopped for 110 minutes until the job's cap, having printed exactly one more line than the previous progress update.
The evidence
TESTS: 4 running, 61 queued
TEST: orly/server/import_replication.test
and then nothing, with 61 tests still queued. No TIMEOUT:, no EXITCODE:, no echoed output.
Why the per-test timeout does not catch it
The timeout sweep only runs when nothing has exited:
auto pid = TSubprocess::TryWaitAll();
if (!pid) {
... // deadline sweep, SIGKILL, TIMEOUT: "still running after Ns"
continue;
}
// reap path -- already past the timeout logic
The absence of a TIMEOUT: ... still running line before our TEST: header proves the test exited on its own. jhm was in the reap, where the timeout no longer applies.
Where it blocks
if (timed_out.count(test)) {
EchoOutputBounded(subprocess->TakeStdOutFromChild()); // safe
} else {
EchoOutput(subprocess->TakeStdOutFromChild()); // <-- unbounded
}
and Base::EchoOutput reads to EOF:
while (size_t read = in_cons.TryRead(buf, 4096)) { WriteExactly(STDOUT_FILENO, buf, read); }
EOF on a pipe needs every write end closed. import_replication.test forks orlyi servers; if any survive the test's own exit they still hold the stdout pipe, so EOF never arrives and the reaper blocks forever — taking the remaining 61 tests with it.
The project already solved this, on the other branch
EchoOutputBounded was written for #537 and its comment names this exact failure:
giving up after a quiet period instead of waiting for EOF: a SIGKILLed test can leave grandchildren holding the pipe's write side (its forked servers, say), and then EOF never comes -- the reporter must not inherit the wedge the timeout just cut short (#537)
The reasoning is right; the scope is too narrow. A test that leaves grandchildren does so whether it was SIGKILLed or exited on its own, and only the SIGKILLed path is protected.
Fix
Use the bounded echo on both paths. In the normal case a closed pipe polls readable immediately and read returns 0, so there is no added latency — the 2s quiet period is only ever spent in the pathological case this is about.
Worth noting this defeats the whole point of #537, which set out to make a wedged test "a named failure in minutes, not a silently cancelled job half an hour later". This is the remaining hole in that.
Found while hunting #564; it is what swallowed that investigation's evidence.
jhm --testcan hang forever reaping a test that has already exited, burning the whole CI job with no diagnostic. Hit for real on an aarch64 runner: the suite stopped for 110 minutes until the job's cap, having printed exactly one more line than the previous progress update.The evidence
and then nothing, with 61 tests still queued. No
TIMEOUT:, noEXITCODE:, no echoed output.Why the per-test timeout does not catch it
The timeout sweep only runs when nothing has exited:
The absence of a
TIMEOUT: ... still runningline before ourTEST:header proves the test exited on its own. jhm was in the reap, where the timeout no longer applies.Where it blocks
and
Base::EchoOutputreads to EOF:EOF on a pipe needs every write end closed.
import_replication.testforksorlyiservers; if any survive the test's own exit they still hold the stdout pipe, so EOF never arrives and the reaper blocks forever — taking the remaining 61 tests with it.The project already solved this, on the other branch
EchoOutputBoundedwas written for #537 and its comment names this exact failure:The reasoning is right; the scope is too narrow. A test that leaves grandchildren does so whether it was SIGKILLed or exited on its own, and only the SIGKILLed path is protected.
Fix
Use the bounded echo on both paths. In the normal case a closed pipe polls readable immediately and
readreturns 0, so there is no added latency — the 2s quiet period is only ever spent in the pathological case this is about.Worth noting this defeats the whole point of #537, which set out to make a wedged test "a named failure in minutes, not a silently cancelled job half an hour later". This is the remaining hole in that.
Found while hunting #564; it is what swallowed that investigation's evidence.