Bug 74

Connect test fails on slow machines by expecting one of two valid errors

Status
Fixed
Symptom
Assertion failure; worst effect seen: test failure only
Where seen
Libmultiprocess tests (mptest)
Trigger
The server side goes away abruptly
First reported
2026-08-12 (first report)
Fixed
2026-08-13
Fix
mp#343

Summary

The mptest case "ConnectStream defers disconnect failure to the first IPC request for interfaces without construct()" failed intermittently on slow machines because it expected one of two error messages that the library can correctly produce after a disconnect, depending on timing. The defect was in test code and did not affect users. It was introduced with the test in mp#298, which reworked error handling when creating clients, and fixed two days after that merged, in mp#343, by accepting both messages.

What happened

Root cause

The test closes the server end of a socketpair, calls ConnectStream<FooInterface> (no construct(), so no IPC call yet), then calls foo->add() and expected "called after disconnect". Two threads decide which error appears:

Both are correct library behaviour; mp#298's own test.cpp change already accepted both strings for the analogous server-disconnect case. Only the new test assumed the first ordering.

The code

Quoted from 137a6e4e0397^. The test in test/mp/test/connect_tests.cpp closes the server end of the socket, connects anyway, and expects one specific error from the first call:

KJ_TEST("ConnectStream defers disconnect failure to the first IPC request for interfaces without construct()")
{
    TestSetup setup;

    close(setup.server_fd);
    // ...
    auto foo = ConnectStream<messages::FooInterface>(*setup.loop, MakeStream(*setup.loop, setup.client_fd));

    try {
        foo->add(1, 2);
        KJ_EXPECT(false);
    } catch (const std::runtime_error& e) {
        std::string_view reason = e.what();

        KJ_EXPECT(reason == "IPC client method called after disconnect.");
    }
}

clientInvoke (include/mp/proxy-types.h) produces either message, depending on whether the event loop has already handled the disconnect:

proxy_client.m_context.loop->sync([&]() {
    if (!proxy_client.m_context.connection) {
        // ...
        disconnected = "IPC client method called after disconnect.";
        // ...
            if (e.getType() == ::kj::Exception::Type::DISCONNECTED) {
                disconnected = "IPC client method call interrupted by disconnect.";

The event loop deletes the Connection, which nulls m_context.connection, in a handler that Connection::onDisconnect (include/mp/proxy-io.h) queues with kj::evalLater after Cap'n Proto sees EOF. If that handler has run before foo->add() reaches sync(), the call fails with "called after disconnect". If add() gets there first, it sends the request, and the disconnect then fails it with "interrupted by disconnect". Both are correct library behaviour; only the test's expectation is wrong, and slow CI runners hit the second ordering.

The fix accepts both messages (137a6e4e0397; comment trimmed):

@@ -139,7 +139,13 @@ KJ_TEST("ConnectStream defers disconnect failure to the first IPC request for in
-        KJ_EXPECT(reason == "IPC client method called after disconnect.");
+        KJ_EXPECT(reason == "IPC client method called after disconnect." ||
+                  reason == "IPC client method call interrupted by disconnect.");

The test now passes whichever thread wins, and still fails if the call succeeds or throws anything else.

Fix

137a6e4e0397 accepts both messages, with a comment explaining the race (test only, +7/-1).

Timeline

Lessons

What would have prevented this bug, found it sooner, or made it easier to debug. The patterns page groups these lessons across all bugs.

Pattern Test timing, and tests that cannot fail: A test that assumes timing

  • Prevented by a review checklist item, a design rule
  • Earliest detector a stress test (did not exist then)
  • Diagnosis easy
  • Fix design easy
  • Debugging aids a clear assertion message
  • Rust no

Would Rust have prevented it? No. A test asserting one of two valid error messages is a test expectation bug about thread scheduling; nothing in the language prevents it. More on Rust

Could it have been prevented?

Yes, and the same PR shows how. mp#298's change to test.cpp already accepted both "called after disconnect" and "interrupted by disconnect" for the analogous server-side case, so the author knew the library can produce either after a disconnect; the new connect_tests.cpp case just did not apply the same allowance. A review question, "which thread decides the value this test asserts?", would have found that the answer is the event-loop thread running a kj::evalLater handler that the test never waits for. The stricter rule, which libmultiprocess follows in its later disconnect tests, is that a test asserting a post-disconnect state either drives the loop to a known point first or accepts every outcome the library documents as correct. Both strings are correct behaviour, so the test was asserting an interleaving, not a property.

Could it have been found sooner?

Only by running the test where the loop thread is slow. The library's CI ran the new test once per job on fast runners and passed; ryanofsky saw it fail the day after merge in local mpcheck runs, and that evening six Bitcoin Core CI jobs on the Windows port branch (32-bit ARM, MSan, TSan and others, whose head lacked the local fix) failed the same assertion, because sanitizer and emulated builds give the event loop the time it needs to run the handler late. A looped run of mptest under TSan, which the library's CI does not do, would have shown it before merge. xyzconstant could not reproduce it on a fast machine, which is the usual shape of this class.

What made it hard to debug?

Little. The failing line was a KJ_EXPECT on the error string, the fix commit (137a6e4e0397) was written within a quarter of an hour of the first local failure, and the race is described in its comment. One small cost: KJ printed (can't stringify) for the std::string_view in the assertion output, so the CI logs did not say which of the two messages had arrived, and the diagnosis came from reading clientInvoke rather than from the log. Comparing std::string values, or logging e.what() before the expectation, would have made every CI failure self-explanatory.

Lesson

A test that asserts which of two correct outcomes a race produced will fail on the slowest machine it ever runs on; assert the property, not the interleaving, or make the interleaving deterministic before asserting.

Notes

Classification

The survey's classification of this bug. The explorer charts these fields across all bugs; the method page explains them.

Field Value
Symptom assert
Worst effect observed test-failure-only
Seen in mptest
Scope test-code
Trigger Server disconnects abruptly (server-unclean-disconnect)
Phase startup
Side client
Component test-harness
Root cause kind assumption-violated
Fix kind test-only
Detection manual-test
Needs a peer that is not libmultiprocess C++ yes
Needed a sanitizer to see no
Confidence high