Files
logos-protocol/tests/protocol/test_iofold.cpp
T
Dario LipicarandClaude Opus 5 7be3a6b856 perf(plain): fold the per-call waiter thread into a call object with its own clock (#46)
* perf(plain): fold the per-call waiter thread into a call object with its own clock

An async call on the plain transport used to be an OS thread whose entire job
was to be blockable: std::future cannot be waited on with a deadline AND a
cancel, so the waiter polled it in 25ms slices, parked on a condition variable
for the deferred half, and delivered. Three costs came with that — one thread
per pending RPC, a 25ms floor on teardown, and a registry-plus-reaping protocol
to stop finished threads accumulating, because a thread cannot join itself. The
TODO in callMethodAsyncWithError has said to fold it away since it was written.

A call is now a shared_ptr<AsyncCall>: state that the reply (delivered as a
handler rather than parked in a promise), a deadline, and cancellation race to
finish. Nothing captures `this`. Handlers hold a shared_ptr to their AsyncCall
and a weak_ptr to CallState, so "no handler touches a destroyed object" is true
by construction rather than by a barrier, and the join is replaced by ownership.
postToQtEventLoop is kept verbatim as the re-entrancy firebreak: all four
completion sites route through it, so no user callback ever runs on an Asio
stack.

Measured against pristine 0f26ffd, same probe compiled into both:

  * 32 calls parked in a provider that will not answer: threads 5 -> 37 on
    master, 6 -> 6 here (the 6th is the deadline clock below, not per-call);
  * release() with those 32 in flight: 26-29ms -> 0ms;
  * 24,000 calls resolved by their deadline and never answered: 8.5MB of
    resident memory on master, 353 bytes per call growing strictly linearly,
    against 0.95MB here that has stopped growing by 3,000 calls.

THE DEADLINE GETS ITS OWN THREAD, and that is the one decision worth arguing
with. Hanging the per-call timer off the connection's strand is the obvious
move and it has a real regression: IoContextPool runs ONE thread for the whole
process and this transport delivers user onEvent callbacks INLINE on it, so an
event handler that calls another module — ordinary module code — holds every
deadline in the process. Measured on that design: an onEvent handler making a
2000ms call delayed a 200ms deadline on a DIFFERENT connection to 2003ms, and a
handler that never returns meant the deadline never fired at all. A second io
thread does not fix it (user handlers are unbounded, so N blocked handlers need
N+1 threads); moving inline event delivery off the strand is a much larger
change to event ordering for every consumer; a Qt timer is strictly worse,
because a synchronous call from the Qt thread blocks that loop too. So:
DeadlineService, one thread process-wide, doing nothing but arming, cancelling
and firing timers. Both shapes are back to 200ms and 250ms, and are pinned.

Two things closed on the way, neither of them inherited:

  * RpcConnection::cancelPending(). m_pendingCalls was emptied only by a decoded
    reply and by fail()'s sweep, so a call resolved by its DEADLINE left its
    registration there for the life of the connection — which outlives every
    handle it hands out. That was true of the promise before this change too;
    the fold would have made the orphan bigger, so it is closed rather than
    passed on. The sync call path and getMethods withdraw theirs as well.
  * A sentinel that arrives after its own deadline used to be filed under
    CallState::deferred by a reply handler that had not noticed the call was
    already resolved. deliver() therefore leaves the registries BEFORE the
    exactly-once gate, not after it.

TESTS. tests/protocol/test_iofold.cpp is the evidence, and its detectors are
validated by an explicit inverted build rather than asserted:

  cmake -S tests -B build-broken -DLOGOS_PROTOCOL_DETECTOR_INVERSIONS=ON

which removes the exactly-once CAS and puts the deadline back on the shared
io_context. In that build the deadline tests fail at 2002ms and never-fires
respectively, and the release-vs-replies race reports 6-16 double deliveries per
10,000 calls. Finding a race wide enough to be a RELIABLE exactly-once detector
took three attempts and the two rejected candidates are documented in the file:
the plain outcomes are weak detectors (one resolver, one deliver()), and
release-against-a-single-completion caught one double in seven runs. Teardown
against a burst of arriving replies is the one that works, because teardown
snapshots the whole in-flight map and then delivers with the lock released.

test_plain_waiter_publish_is_last.cpp is DELETED. It pinned exactly one rule —
publishFinishedWaiter() is a waiter thread's last access to the object, which
was the only reason stopAndJoinWaiters() could return while a reaper was still
mid-join. There are no waiter threads, no reaper and no publish list, so there
is no ordering left to pin; the property it protected is now structural.
test_plain_waiter_reaping.cpp is retargeted at CallState::inflight, keeping its
claims and losing its mechanism.

The four guarantees from #41 all re-measured on this branch: no thread growth
with in-flight calls, teardown 0ms with 32 outstanding, exactly one callback on
normal/deferred/timeout/cancellation counted per call over 10,000 calls
including a release race, and retention final 0 on both registries. Guard Malloc
clean over the lifetime suites (27 tests), with the completion-subscription
detector still faulting 3/3 on pristine master. ctest 296/296 (287 before, minus
3 deleted, plus 12); nix build .#tests 296/296.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* docs(plain): say what cancelPending() actually guarantees, and pin it

rpc_connection.h claimed that "a caller that gives up before the reply arrives
calls cancelPending() and is never called back at all". It is not true.
dispatchIncoming copies the handler out of m_pendingCalls under m_mu and invokes
it with the mutex RELEASED, so a cancelPending() landing in that gap erases an
entry that is already gone and returns having stopped nothing — the handler then
runs to completion, after cancelPending() has returned.

THE CODE IS FINE; THE COMMENT WAS NOT, and the distinction it was blurring is
the load-bearing one:

  * at-most-once INVOCATION of a registered handler is this layer's, and comes
    from the extract-and-erase under m_mu — three contenders (dispatchIncoming,
    fail()'s sweep, cancelPending) and only one can have it;
  * exactly-once DELIVERY to the user is NOT this layer's. It is
    AsyncCall::deliver()'s CAS, and nothing else.

Both callers of sendCallAsync() were checked, because a non-idempotent one would
have made this a bug rather than a comment. PlainLogosObject funnels every
outcome into deliver(). RpcConnection::sendCall()'s promise handler has no CAS
and needs none: only one contender ever reaches it, and fulfilling a future its
caller has already walked away from is a no-op. Same for the two cancelPending()
callers that are not deliver() — the sync callMethodWithError timeout and
getMethods().

Three comment sites corrected (ResultHandler, dispatchIncoming's Result arm,
cancelPending's own contract) and the claims moved out of prose into
tests/protocol/test_plain_cancel_pending_race.cpp, which BUILDS the interleaving
instead of racing for it: a stub connection reproduces dispatchIncoming's
extract-then-invoke and lets the test stand between the halves. Four tests — the
callback that fires after cancelPending() returns, the extracted reply racing
teardown (exactly one delivery), the promise-shaped handler in the same gap, and
a real RpcConnection pair proving the half of the old comment that IS true.

The exactly-once one goes RED under -DLOGOS_PROTOCOL_DETECTOR_INVERSIONS=ON:
2 deliveries for 1 call, deterministically rather than probabilistically. Six
tests now go red in that build, listed in tests/protocol/CMakeLists.txt. Full
suite 302/302.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* test(plain): take the fold's detector inversions out of the transport too

Three more compiled-in alternative implementations, same anti-pattern as
the one the base branch just lost: production source holding a second,
deliberately wrong version of its own contract so the suite could be
built once with the mechanism removed.

  * deadlineContext() had LOGOS_PLAIN_DETECTOR_BREAK_DEADLINE_ISOLATION
    returning IoContextPool::shared().ioContext() — the rejected design
    DeadlineService exists to avoid. Kept DeadlineService::shared()
    .context(); the io_context_pool.h include the fold added for that
    branch alone goes with it.
  * AsyncCall::claim() had LOGOS_PLAIN_DETECTOR_BREAK_ONCE storing
    `delivered` and returning true unconditionally. Kept the CAS.
  * AsyncCall::takeCallback() had the same macro returning a COPY of the
    callback. Kept the swap.

And the CMake option that defined all three, whose surviving content —
which six tests are real detectors, and that the per-path exactly-once
tests are PINS rather than detectors because a call resolved once calls
deliver() once whatever guards it — moved into the note that replaces
it.

The comments now describe the validation that actually happened: a local
edit in a throwaway checkout, with the numbers each run produced. The
sub-order detector needs no edit at all, since it goes red on pristine
master.

302 tests pass, unchanged in count: no test deleted or weakened.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

* test(iofold): count the provider's completion workers so none outlives the proxy

Fixes the Linux SIGSEGV (exit 139) in the "Run protocol tests" step.

`OmniProvider::defer` is a "multi" provider: it answers with a pending sentinel
and pushes the real completion later from a worker of its own. That worker calls
the EventCallback ModuleProxy handed the provider, and that listener captures
`this` RAW (module_proxy.cpp) — its first act is
`QMetaObject::invokeMethod(this, …, Qt::QueuedConnection)`, which dereferences
the QObject. The worker was spawned DETACHED, so nothing proved it had finished,
and `~LiveHost` runs `delete m_proxy` a couple of milliseconds after the last
spawn.

Nothing keeps the two apart. A round of ReleaseRacingAnInFlightCompletionIsSafe
ends when the CALLER is answered, and a release()d call is answered by teardown —
so the round can be over before the provider has run at all, and the proxy's
thread is still working through a backlog of `defer` calls while ~LiveHost is
already tearing down. Two to five workers were standing in the same frame at the
moment of the fault:

    Thread "QThread" received signal SIGSEGV
    QObject::thread() const
    QMetaObject::invokeMethodImpl(QObject*, …)
    ModuleProxy::ModuleProxy(...)::<lambda(const QString&, const QVariantList&)>
                                                       module_proxy.cpp:37
    std::function<void(const QString&, const QList<QVariant>&)>::operator()
    OmniProvider::callMethod(...)::<lambda()>           test_iofold.cpp, in defer
    std::thread::_State_impl<…>::_M_run()

WHY ONLY THE WHOLE-BINARY RUN. The corpse is left by the test that spawned the
worker and lands in whichever test runs NEXT — in CI, always
ReleaseFromInsideAnIoThreadEventCallbackDoesNotWedge, which follows the 300-round
ReleaseRacingAnInFlightCompletionIsSafe and its 300 `defer` calls. Under ctest
every test is its own process, so the worker dies with the process that owned the
proxy and there is nothing left to fault: `nix build '.#tests'` is green on the
unfixed tree, which is exactly how this hid.

Measured on Linux (aarch64, Qt 6.9.2, gcc 14.3, `nix build '.#tests'` artifact,
QT_QPA_PLATFORM=offscreen, five concurrent copies):

    tree                          IoFoldTest.*     whole binary
    master (03842db)              n/a (no test)    0/10
    feat/plain-async-io-fold       6/50  (12%)     2/20  (10%)
    + harness-host-thread-affinity 10/50 (20%)     5/20  (25%)
    this commit, on either tree     0/50            0/20

So it is latent HERE and merely widened by destroying the fixtures' host on the
proxy's thread: that order lets the queued `defer` backlog RUN instead of
discarding it with QThread::quit(), which is why the rate roughly doubles. The
defect and the fix both belong to this commit's tree.

macOS never opens the window — 3/3 clean whole-binary runs on the unfixed tree,
and 4/4 clean under Guard Malloc (which unmaps the freed page, so a late worker
would fault every time), which is why that half of the matrix stayed green.

A COUNT, NOT A JOIN. Joinable workers would hold their 8MB stacks until reaped —
400 outstanding in NormalAndDeferredCompletionsDeliverExactlyOnceAtVolume — and
reaping from the dispatch thread would block the very thread `defer` exists to
free. So they stay detached and the provider counts them, with the decrement and
its notify under one mutex so a drain() woken by it cannot return before the
worker has released that mutex.

~LiveHost drains AFTER `m_thread->wait()`: the proxy's event loop has stopped, so
no queued call can reach the provider any more and the worker set is FINAL —
before that point a drain could pass and the backlog spawn more. ~OmniProvider
drains too, because a worker's last act touches one of its members.

Verification, all on the fixed tree:
  * `nix build '.#tests'` — 402/402, Linux and macOS (173s on macOS).
  * 20 whole-binary Linux runs: 402/402 every time.
  * Exactly-once, on the release-race shape rather than the per-path pins:
    200,000 calls released mid-burst across those 20 runs (20 rounds x 500 each)
    reported DOUBLE deliveries=0 dropped=0, and all 20 runs of
    ReleaseRacingAnInFlightCompletionIsSafe were 300/300 with 0 doubles.
  * Teardown stays fast: `release()` 0-2ms with 32 calls in flight, and the
    added wait is on the FIXTURE, not on release() — it delays `delete m_proxy`
    by however long a completion worker still had to sleep (<=2.4ms here).
  * No production code touched, so "no user callback inline on an io thread" and
    the deadline guarantees are unchanged.

Not touched: test_plain_completion_sub_order.cpp (InstantMultiModule) and
test_concurrent_dispatch.cpp spawn the same detached completion worker, and read
the callback member through a captured `this` on top of it. Neither has been
observed to fault.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
2026-08-12 16:23:57 -03:00

1515 lines
63 KiB
C++

// The io_context fold: an async call is state plus a deadline, not a thread.
// This file is the evidence for that, and the replacement for
// test_plain_waiter_publish_is_last.cpp, whose subject (a waiter thread's
// publish ordering) no longer exists.
//
// WHAT IS PINNED HERE, and why each one needs its own test:
//
// 1. NO THREAD PER PENDING RPC — the point of the exercise. Measured with the
// OS thread count of the PROCESS, against calls genuinely parked in a
// provider that will not answer. Pre-fold this is +1 per in-flight call.
//
// 2. EXACTLY ONCE, on every path, counted PER CALL. This is the guarantee most
// at risk from the rework, because its mechanism changed: it used to be
// structural (one thread, one function body, and a join proving it had
// finished) and is now a single CAS that three independent callers race for
// — the reply handler, the deadline, and teardown. The plain outcomes
// (normal / deferred / timeout / cancelled) are WEAK detectors of that: a
// call resolved once calls deliver() once, and stays green with the CAS
// removed. Measured, not assumed — so the strong one is a separate test
// that puts teardown and a stream of arriving replies on the same calls.
//
// 3. THE DEADLINE IS NOT HOSTAGE TO THE IO THREAD. The version of this work
// that put the per-call timer on the connection's strand had exactly one
// regression, and this was it: IoContextPool runs ONE thread for the whole
// process and this transport delivers user onEvent callbacks INLINE on it,
// so an event handler that made a 2000ms call delayed a 200ms deadline on a
// DIFFERENT connection to 2003ms. Both shapes are pinned — a busy io thread
// and a permanently blocked one.
//
// 4. RETENTION IS BOUNDED BY WHAT IS IN FLIGHT, on both sides: the handle's
// CallState registries AND the connection's pending-call map, which nothing
// used to erase for a call resolved by its deadline.
//
// 5. NO USE-AFTER-FREE, which is what replaced the join. Nothing waits for the
// io thread; instead no handler can reach the handle.
//
// HOW THE DETECTORS ARE VALIDATED. By running them against a transport that
// does not have the mechanism, in a throwaway checkout — two edits, neither of
// which is carried in this tree:
//
// (a) AsyncCall::claim() stores `delivered` and returns true unconditionally
// instead of compare-exchanging it, and takeCallback() returns a COPY of
// the callback instead of swapping it out. Both halves have to go: they
// are independently sufficient.
// (b) deadlineContext() returns IoContextPool::shared().ioContext() — the
// connections' own thread — instead of DeadlineService::shared()
// .context(). That is the rejected design named in the DeadlineService
// comment, so this measures the regression that class exists to prevent.
//
// A build option that did this from inside the shipped source was tried and
// removed: it left a second, knowingly wrong implementation of the exactly-once
// gate in the production translation unit, which is not a thing a correctness
// change gets to ship. (An earlier draft used getenv() probes and was worse in
// the same way.) Doing it as a local edit costs one throwaway build and proves
// the same thing. The related sub-order detector needs no edit at all — it goes
// red on pristine master; see test_plain_completion_sub_order.cpp.
//
// The numbers those runs produced, on an aarch64-darwin box:
//
// ReleaseRacingRepliesInFlightDeliversEachCallOnce (a) 6-16 double
// deliveries per
// 10,000 calls, 4 runs
// DeadlineFiresOnTimeWhileTheIoThreadIsBusy (b) 200ms deadline fires
// at 2002ms
// DeadlineFiresWhileTheIoThreadIsBlockedForever (b) never fires at all
//
// A green run of any of those against the stripped transport means the test is
// not exercising what it claims to, and is a bug in the test. Two candidates
// were REJECTED as exactly-once detectors on exactly that ground — see the
// comment on ReleaseRacingRepliesInFlightDeliversEachCallOnce.
//
// Everything runs against a live in-process PlainTransportHost over real TCP.
#include <gtest/gtest.h>
#include "logos_async_dispatch.h"
#include "logos_call_error.h"
#include "logos_object.h"
#include "logos_provider_interface.h"
#include "logos_transport_config.h"
#include "module_proxy.h"
#include "plain_logos_object.h"
#include "plain_transport_connection.h"
#include "plain_transport_host.h"
#include <boost/asio/ip/tcp.hpp>
#include <QCoreApplication>
#include <QElapsedTimer>
#include <QJsonArray>
#include <QString>
#include <QThread>
#include <QVariant>
#include <QVariantList>
#include <QVariantMap>
#include <algorithm>
#include <atomic>
#include <chrono>
#include <condition_variable>
#include <cstdint>
#include <cstdio>
#include <cstdlib>
#include <iostream>
#include <map>
#include <memory>
#include <mutex>
#include <string>
#include <thread>
#include <vector>
#ifdef __APPLE__
#include <mach/mach.h>
#else
#include <cstring>
#include <fstream>
#endif
using namespace logos::plain;
namespace {
// Live OS threads in this process. The measurement has to be of the PROCESS,
// not of anything the object reports about itself: the claim is that pending
// calls stopped costing threads, and an object-level counter would only be
// restating the implementation.
int liveThreads()
{
#ifdef __APPLE__
thread_act_array_t list = nullptr;
mach_msg_type_number_t n = 0;
if (task_threads(mach_task_self(), &list, &n) != KERN_SUCCESS) return -1;
for (mach_msg_type_number_t i = 0; i < n; ++i)
mach_port_deallocate(mach_task_self(), list[i]);
vm_deallocate(mach_task_self(), reinterpret_cast<vm_address_t>(list),
n * sizeof(thread_act_t));
return static_cast<int>(n);
#elif defined(__linux__)
std::ifstream st("/proc/self/status");
std::string line;
while (std::getline(st, line)) {
if (line.rfind("Threads:", 0) == 0)
return std::atoi(line.c_str() + 8);
}
return -1;
#else
return -1; // the assertions below are skipped where this is unavailable
#endif
}
// ── the provider's own worker threads, and why they are counted ──────────────
//
// A "multi" provider answers with a pending sentinel and completes the call
// LATER, from a worker of its own — that is the whole point of `defer` below,
// and it is what makes the completion arrive on the consumer's io thread instead
// of inline in the reply. The worker calls the EventCallback ModuleProxy handed
// the provider in setEventListener(), and that listener captures `this` RAW
// (module_proxy.cpp): its first act is
// QMetaObject::invokeMethod(this, …, Qt::QueuedConnection), which dereferences
// the QObject.
//
// This fixture DELETES that proxy. The worker was spawned detached, so nothing
// proved it had finished, and `delete m_proxy` followed the last spawn by a
// couple of milliseconds — the fixture drains the CALLER's side of each round
// (pumpUntilTotal) but a release()d call is answered by teardown, so the round
// can be over before the provider has even run, leaving a backlog of `defer`
// calls that the proxy's thread is still working through while ~LiveHost runs.
//
// Reproduced on Linux (aarch64, Qt 6.9.2, gcc 14.3), `nix build .#tests`
// artifact, `--gtest_filter=IoFoldTest.*`, five concurrent copies — 6 of 50 runs
// on the tree this provider arrived on, 10 of 50 once the fixtures started
// destroying their host on the proxy's thread (which lets the backlog RUN instead
// of discarding it with QThread::quit(), so it widens this window rather than
// opening it). Every one of them with two to five worker threads standing in the
// same frame:
//
// Thread "QThread" received signal SIGSEGV
// QObject::thread() const
// QMetaObject::invokeMethodImpl(QObject*, …)
// ModuleProxy::ModuleProxy(...)::<lambda(const QString&, const QVariantList&)>
// module_proxy.cpp:37
// std::function<void(const QString&, const QList<QVariant>&)>::operator()
// OmniProvider::callMethod(...)::<lambda()> this file, in defer
// std::thread::_State_impl<…>::_M_run()
//
// The corpse is left by the test that spawned the worker and lands in whichever
// test runs NEXT, so it only appears in the WHOLE-BINARY run — the CI step that
// runs ./result/bin/protocol_tests. Under ctest every test is its own process, so
// the worker dies with the process that owned the proxy and there is nothing left
// to fault; `nix build .#tests` is green on the same tree, which is exactly how
// this hid.
//
// A COUNT, NOT A JOIN, deliberately. Making the workers joinable would hold their
// 8MB stacks until something reaped them — 400 outstanding in
// NormalAndDeferredCompletionsDeliverExactlyOnceAtVolume — and reaping from the
// dispatch thread would block the very thread `defer` exists to free. So they
// stay detached and the provider counts them; ~LiveHost waits for the count to
// reach zero at the one point where it is final.
//
// The same shape exists in test_plain_completion_sub_order.cpp
// (InstantMultiModule) and test_concurrent_dispatch.cpp, which additionally read
// the callback member through a captured `this`. Neither has been observed to
// fault and neither is touched here.
class EmitterGate {
public:
// Raised on the DISPATCH thread, BEFORE the worker is spawned. Raising it
// inside the worker instead would leave drain() free to pass through the gap
// between the spawn and the worker's first instruction.
void enter()
{
std::lock_guard<std::mutex> g(m_mu);
++m_live;
}
// The worker's LAST act. notify_all() runs with m_mu HELD, and that is the
// whole of the guarantee: a drain() woken by it has to re-acquire m_mu, which
// it cannot do until this thread has released it. So once drain() returns, no
// worker touches this gate — or the provider that holds it, or the proxy —
// ever again.
void leave()
{
std::lock_guard<std::mutex> g(m_mu);
if (--m_live == 0) m_cv.notify_all();
}
// Unbounded on purpose: the caller is a fixture already sitting on
// QThread::wait() with no timeout one line above, and a bounded wait here
// would hand back exactly the "probably finished" that the bare detach had.
void drain()
{
std::unique_lock<std::mutex> lk(m_mu);
m_cv.wait(lk, [this] { return m_live == 0; });
}
private:
std::mutex m_mu;
std::condition_variable m_cv;
int m_live = 0;
};
// enter() then spawn, so the count is up before the worker exists; leave() from a
// scope guard, so an emitter that throws cannot strand the count and wedge
// drain() forever. `gate` is captured by reference because it is a member of the
// provider, and the drain is precisely what keeps that alive long enough.
template <typename Fn>
void spawnGatedEmitter(EmitterGate& gate, Fn fn)
{
gate.enter();
try {
std::thread([&gate, fn = std::move(fn)]() mutable {
struct Leave {
EmitterGate* g;
~Leave() { g->leave(); }
} leave{&gate};
fn();
}).detach();
} catch (...) {
gate.leave();
throw;
}
}
// One provider covering every outcome the fold has to preserve:
// ping — answers immediately (normal completion)
// block — parks until letGo() (in-flight; timeout; cancellation)
// defer — "multi": returns the pending sentinel and completes it later
// sink — "multi": returns the sentinel and NEVER completes it
// slowsink — "multi": the sentinel itself arrives after the caller's deadline
// fire — emits a user event, which this transport delivers INLINE on the
// consumer's io thread
class OmniProvider : public LogosProviderObject {
public:
QVariant callMethod(const QString& method, const QVariantList& args) override
{
if (method == QLatin1String("ping")) return args.value(0, QVariant(1));
if (method == QLatin1String("block")) {
std::unique_lock<std::mutex> lk(m_mu);
m_cv.wait(lk, [this] { return m_released; });
return QVariant(42);
}
if (method == QLatin1String("fire")) {
if (m_eventCb) m_eventCb(QStringLiteral("tick"), QVariantList{ QVariant(1) });
return QVariant(true);
}
if (method == QLatin1String("slowsink")) {
// The sentinel itself arrives LATE — after the caller's deadline
// has already elapsed and the call has been resolved as a timeout.
std::this_thread::sleep_for(std::chrono::milliseconds(400));
QVariantMap pending;
pending[logos::pendingCallKey()] = QStringLiteral("late-%1").arg(
static_cast<qulonglong>(m_counter.fetch_add(1)));
return pending;
}
if (method == QLatin1String("sink")) {
QVariantMap pending;
pending[logos::pendingCallKey()] = QStringLiteral("never-%1").arg(
static_cast<qulonglong>(m_counter.fetch_add(1)));
return pending;
}
if (method == QLatin1String("defer")) {
const int delayUs = args.value(0).toInt();
const QString callId = QStringLiteral("cid-%1").arg(
static_cast<qulonglong>(m_counter.fetch_add(1)));
auto cb = m_eventCb;
// The completion is pushed from a worker, which is what a real
// "multi" provider does and what makes the event arrive on the
// consumer's io thread rather than inline in the reply.
//
// GATED rather than plain-detached, because `cb` reaches the
// ModuleProxy through a raw `this` and this fixture deletes that
// proxy: the gate is what lets ~LiveHost prove no worker is left
// before it does. Reproduced SIGSEGV and full reasoning at
// EmitterGate above.
spawnGatedEmitter(m_emitters, [cb, callId, delayUs]() {
if (delayUs > 0)
std::this_thread::sleep_for(std::chrono::microseconds(delayUs));
if (cb) cb(logos::callCompleteEvent(),
QVariantList{ callId, QVariant(7) });
});
QVariantMap pending;
pending[logos::pendingCallKey()] = callId;
return pending;
}
return QVariant();
}
void letGo()
{
{
std::lock_guard<std::mutex> g(m_mu);
m_released = true;
}
m_cv.notify_all();
}
// Wait out every worker `defer` has spawned. ~LiveHost calls this once the
// proxy's event loop has stopped — the point after which no further
// callMethod can be dispatched, so the set of workers is final — and before
// the proxy those workers emit into is deleted.
void drainEmitters() { m_emitters.drain(); }
// The same wait, as this provider's OWN invariant: a worker's last act is
// EmitterGate::leave() on a member of this object, so none may outlive it.
// The destructor BODY runs before any member is destroyed, so m_emitters is
// still alive here. This does NOT cover the proxy — by the time a provider is
// destroyed its owner has usually deleted that already — which is why
// ~LiveHost has to drain too, and earlier.
~OmniProvider() override { m_emitters.drain(); }
QJsonArray getMethods() override { return QJsonArray{}; }
bool informModuleToken(const QString&, const QString&) override { return true; }
void setEventListener(EventCallback cb) override { m_eventCb = std::move(cb); }
void init(void*) override {}
QString providerName() const override { return QStringLiteral("omni"); }
QString providerVersion() const override { return QStringLiteral("1.0.0"); }
private:
std::mutex m_mu;
std::condition_variable m_cv;
bool m_released = false;
EventCallback m_eventCb;
std::atomic<std::uint64_t> m_counter{0};
EmitterGate m_emitters;
};
QCoreApplication* ensureApp()
{
static int argc = 0;
static char* argv[] = { nullptr };
if (!QCoreApplication::instance())
new QCoreApplication(argc, argv);
return QCoreApplication::instance();
}
class LiveHost {
public:
LiveHost()
{
LogosTransportConfig cfg;
cfg.protocol = LogosProtocol::Tcp;
cfg.host = "127.0.0.1";
cfg.port = 0; // ephemeral
m_host = std::make_unique<PlainTransportHost>(cfg);
m_started = m_host->start();
m_proxy = new ModuleProxy(&m_provider);
m_proxy->saveToken(QStringLiteral("origin"), QStringLiteral("live-token"));
m_thread = new QThread;
m_proxy->moveToThread(m_thread);
m_thread->start();
m_published = m_host->publishObject("omni_module", m_proxy);
const QString endpoint = m_host->endpoint();
m_port = endpoint.mid(endpoint.lastIndexOf(':') + 1).toUShort();
}
~LiveHost()
{
m_provider.letGo();
QCoreApplication::processEvents(QEventLoop::AllEvents, 200);
m_host.reset();
QCoreApplication::processEvents(QEventLoop::AllEvents, 50);
m_thread->quit();
m_thread->wait();
// The proxy's event loop has stopped, so no queued call can reach the
// provider any more and the set of `defer` workers is now FINAL. Wait
// them out before deleting the proxy they emit into — one of them
// outliving this line is the SIGSEGV recorded at EmitterGate above.
m_provider.drainEmitters();
delete m_proxy;
delete m_thread;
}
bool ok() const { return m_started && m_published && m_port != 0; }
uint16_t port() const { return m_port; }
OmniProvider& provider() { return m_provider; }
private:
OmniProvider m_provider;
std::unique_ptr<PlainTransportHost> m_host;
ModuleProxy* m_proxy = nullptr;
QThread* m_thread = nullptr;
bool m_started = false;
bool m_published = false;
uint16_t m_port = 0;
};
std::unique_ptr<PlainTransportConnection> connectTo(uint16_t port)
{
LogosTransportConfig cfg;
cfg.protocol = LogosProtocol::Tcp;
cfg.host = "127.0.0.1";
cfg.port = port;
auto conn = std::make_unique<PlainTransportConnection>(cfg);
if (!conn->connectToHost()) return nullptr;
return conn;
}
LogosObjectErrorChannel* channelFor(LogosObject* obj)
{
return dynamic_cast<LogosObjectErrorChannel*>(obj);
}
// Reads the registries through the explicit-instantiation access hole
// ([temp.spec] does not check access on the template arguments of an explicit
// instantiation), so the code under test is observed exactly as it ships — no
// friend, no test-only accessor, no `#define private public`.
template <typename Tag, typename Tag::type Member>
struct Rob {
friend typename Tag::type get(Tag) { return Member; }
};
struct StateTag {
using type = std::shared_ptr<PlainLogosObject::CallState> PlainLogosObject::*;
friend type get(StateTag);
};
template struct Rob<StateTag, &PlainLogosObject::m_state>;
struct ConnTag {
using type = std::shared_ptr<RpcConnectionBase> PlainLogosObject::*;
friend type get(ConnTag);
};
template struct Rob<ConnTag, &PlainLogosObject::m_conn>;
using TcpConn = RpcConnection<boost::asio::ip::tcp::socket>;
struct PendingCallsTag {
using type = std::map<std::uint64_t, RpcConnectionBase::ResultHandler> TcpConn::*;
friend type get(PendingCallsTag);
};
template struct Rob<PendingCallsTag, &TcpConn::m_pendingCalls>;
struct ConnMuTag {
using type = std::mutex TcpConn::*;
friend type get(ConnMuTag);
};
template struct Rob<ConnMuTag, &TcpConn::m_mu>;
struct Registries {
size_t inflight;
size_t deferred;
size_t completions;
size_t pendingOnConnection;
};
Registries registries(PlainLogosObject* obj)
{
Registries r{0, 0, 0, 0};
{
auto& st = obj->*get(StateTag{});
std::lock_guard<std::mutex> g(st->mu);
r.inflight = st->inflight.size();
r.deferred = st->deferred.size();
r.completions = st->completions.size();
}
auto& base = obj->*get(ConnTag{});
if (auto* c = dynamic_cast<TcpConn*>(base.get())) {
std::lock_guard<std::mutex> g(c->*get(ConnMuTag{}));
r.pendingOnConnection = (c->*get(PendingCallsTag{})).size();
}
return r;
}
// Per-call delivery counts. Both 0 and 2 are failures, and they are counted per
// call rather than in aggregate — a double delivery on one call plus a dropped
// one on another balances out in a total.
struct Deliveries {
explicit Deliveries(int n) : counts(n) {}
std::vector<std::atomic<int>> counts;
std::atomic<int> total{0};
std::mutex mu;
std::string lastCode;
QVariant lastValue;
void record(int i, QVariant v, const logos::CallError& e)
{
{
std::lock_guard<std::mutex> g(mu);
lastCode = e.code;
lastValue = std::move(v);
}
counts[i].fetch_add(1);
total.fetch_add(1);
}
std::string code() { std::lock_guard<std::mutex> g(mu); return lastCode; }
int worst() const
{
int w = 0;
for (const auto& c : counts) w = std::max(w, c.load());
return w;
}
int missing() const
{
int m = 0;
for (const auto& c : counts) if (c.load() == 0) ++m;
return m;
}
};
void pump(int ms)
{
QElapsedTimer t;
t.start();
while (t.elapsed() < ms)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
}
void pumpUntilTotal(Deliveries& d, int target, int budgetMs)
{
QElapsedTimer t;
t.start();
while (d.total.load() < target && t.elapsed() < budgetMs)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
}
const char* kToken = "live-token";
} // namespace
class IoFoldTest : public ::testing::Test {
protected:
void SetUp() override { ensureApp(); }
};
// ── 1. no thread per pending RPC ────────────────────────────────────────────
//
// 32 calls parked in a provider that will not answer. Pre-fold each of those is
// an OS thread sitting in a sliced future wait — measured at exactly +1 per
// in-flight call. The claim here is that the same 32 calls cost none.
//
// The bound is 2 rather than 0 on purpose: Qt is free to service the connection
// from a pool thread of its own, and the two singleton threads this transport
// owns (the io worker and the deadline clock) are lazily created, which is what
// the warm-up call below is for. What must not happen is growth WITH the call
// count — with 32 in flight, anything at or near 32 is the old design.
TEST_F(IoFoldTest, PendingCallsDoNotCostThreads)
{
if (liveThreads() < 0) GTEST_SKIP() << "no thread counter on this platform";
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
// One warm-up call, completed, so the io worker, the deadline thread and any
// Qt pool threads exist before the baseline is taken. Otherwise the fold gets
// blamed for threads that lazy initialisation created.
{
Deliveries warm(1);
ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"),
QVariantList{ QVariant(1) }, 5000,
[&warm](QVariant v, const logos::CallError& e) {
warm.record(0, std::move(v), e);
});
pumpUntilTotal(warm, 1, 10000);
ASSERT_EQ(warm.total.load(), 1);
}
pump(150);
const int base = liveThreads();
constexpr int kInFlight = 32;
Deliveries d(kInFlight);
for (int i = 0; i < kInFlight; ++i) {
ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 20000,
[&d, i](QVariant v, const logos::CallError& e) {
d.record(i, std::move(v), e);
});
}
// Long enough for every call to be registered and genuinely outstanding.
pump(400);
const int parked = liveThreads();
ASSERT_EQ(d.total.load(), 0) << "the provider answered; nothing was in flight";
std::cout << " " << kInFlight << " calls PARKED in the provider -> threads "
<< base << " -> " << parked << " (delta " << (parked - base) << ")"
<< std::endl;
EXPECT_LE(parked - base, 2)
<< "in-flight calls are still costing threads: +" << (parked - base)
<< " for " << kInFlight << " pending calls";
QElapsedTimer timer;
timer.start();
obj->release();
const qint64 releaseMs = timer.elapsed();
pumpUntilTotal(d, kInFlight, 5000);
pump(200);
const int after = liveThreads();
std::cout << " release() with " << kInFlight << " in flight took "
<< releaseMs << "ms -> threads " << after
<< ", callbacks " << d.total.load() << "/" << kInFlight
<< " worst=" << d.worst() << std::endl;
// Fast teardown in its harshest form: 32 calls outstanding, each with 20s
// left on its clock. The old design's floor was one 25ms wait slice; there
// is no slice any more, because there is no future being polled.
EXPECT_LT(releaseMs, 100)
<< "teardown is waiting for something again";
EXPECT_EQ(d.total.load(), kInFlight);
EXPECT_EQ(d.worst(), 1);
EXPECT_EQ(d.missing(), 0);
host.provider().letGo();
pump(200);
}
// ── 2. exactly once, per call, on the four ordinary outcomes ────────────────
//
// NORMAL and DEFERRED-THEN-COMPLETED are run at volume because they are the two
// that go through the reply handler and the completion-event handler
// respectively — the two sites where the deadline is still armed and racing.
//
// These are WEAK detectors of the exactly-once gate on their own (one resolver,
// one deliver()); the two race tests further down are the strong ones.
TEST_F(IoFoldTest, NormalAndDeferredCompletionsDeliverExactlyOnceAtVolume)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
auto* plain = dynamic_cast<PlainLogosObject*>(obj);
ASSERT_NE(plain, nullptr);
constexpr int kNormal = 400;
constexpr int kDeferred = 400;
Deliveries normal(kNormal);
Deliveries deferred(kDeferred);
for (int i = 0; i < kNormal; ++i) {
ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"),
QVariantList{ QVariant(i) }, 5000,
[&normal, i](QVariant v, const logos::CallError& e) {
normal.record(i, std::move(v), e);
});
}
// Completion delays swept across the sub-millisecond band, so the event
// sometimes beats the sentinel's own reply out of the provider and
// sometimes trails it — both orders exercised rather than assumed.
for (int i = 0; i < kDeferred; ++i) {
ch->callMethodAsyncWithError(kToken, QStringLiteral("defer"),
QVariantList{ QVariant((i % 12) * 40) }, 8000,
[&deferred, i](QVariant v, const logos::CallError& e) {
deferred.record(i, std::move(v), e);
});
}
pumpUntilTotal(normal, kNormal, 60000);
pumpUntilTotal(deferred, kDeferred, 60000);
pump(500); // a duplicate delivery would land here
const Registries r = registries(plain);
std::cout << " normal " << normal.total.load() << "/" << kNormal
<< " worst=" << normal.worst() << " missing=" << normal.missing()
<< " code='" << normal.code() << "'" << std::endl;
std::cout << " deferred " << deferred.total.load() << "/" << kDeferred
<< " worst=" << deferred.worst() << " missing=" << deferred.missing()
<< " code='" << deferred.code() << "'" << std::endl;
std::cout << " after " << (kNormal + kDeferred) << " completed calls: inflight="
<< r.inflight << " deferred=" << r.deferred << " completions="
<< r.completions << " connection-pending=" << r.pendingOnConnection
<< std::endl;
EXPECT_EQ(normal.worst(), 1);
EXPECT_EQ(normal.missing(), 0);
EXPECT_TRUE(normal.code().empty());
EXPECT_EQ(deferred.worst(), 1);
EXPECT_EQ(deferred.missing(), 0);
EXPECT_TRUE(deferred.code().empty()) << "a completed deferred call reported an error";
{
std::lock_guard<std::mutex> g(deferred.mu);
EXPECT_EQ(deferred.lastValue.toInt(), 7)
<< "the deferred call delivered the sentinel instead of the completion";
}
// Retention, on both sides, after 800 completed calls on one handle.
EXPECT_EQ(r.inflight, 0u);
EXPECT_EQ(r.deferred, 0u);
EXPECT_EQ(r.completions, 0u);
EXPECT_EQ(r.pendingOnConnection, 0u);
obj->release();
pump(100);
}
// TIMEOUT and CANCELLATION, the two outcomes the deadline and teardown own. Run
// in alternation so a cancellation lands while other calls are mid-timeout.
TEST_F(IoFoldTest, TimeoutAndCancellationDeliverExactlyOnce)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
constexpr int kRounds = 40;
Deliveries timedOut(kRounds);
Deliveries cancelled(kRounds);
for (int r = 0; r < kRounds; ++r) {
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
// One that will hit its deadline, and one the release will cancel.
ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 250,
[&timedOut, r](QVariant v, const logos::CallError& e) {
timedOut.record(r, std::move(v), e);
});
ch->callMethodAsyncWithError(kToken, QStringLiteral("sink"), {}, 9000,
[&cancelled, r](QVariant v, const logos::CallError& e) {
cancelled.record(r, std::move(v), e);
});
// Let the deadline pass and the sentinel come back, so the release
// lands on a call that is genuinely parked in the deferred half.
pumpUntilTotal(timedOut, r + 1, 5000);
obj->release();
pumpUntilTotal(cancelled, r + 1, 5000);
}
pump(500);
std::cout << " timeout " << timedOut.total.load() << "/" << kRounds
<< " worst=" << timedOut.worst() << " code='" << timedOut.code()
<< "'" << std::endl;
std::cout << " cancelled " << cancelled.total.load() << "/" << kRounds
<< " worst=" << cancelled.worst() << " code='" << cancelled.code()
<< "'" << std::endl;
EXPECT_EQ(timedOut.worst(), 1);
EXPECT_EQ(timedOut.missing(), 0);
EXPECT_EQ(timedOut.code(), "timeout")
<< "moving the deadline onto a steady_timer must not change what it reports";
EXPECT_EQ(cancelled.worst(), 1);
EXPECT_EQ(cancelled.missing(), 0);
EXPECT_EQ(cancelled.code(), "transport_error")
<< "a call abandoned by release() is a torn-down transport, not a timeout";
host.provider().letGo();
pump(200);
}
// ── 2b. a call that hits its deadline and is THEN answered ──────────────────
//
// The shape that used to be the second resolver: the timer resolves the call,
// the reply turns up afterwards, and something has to make sure the caller is
// not told twice. TWO independent mechanisms now cover it, and this pins the
// pair:
//
// * the delivery WITHDRAWS the registration from the connection
// (cancelPending), so a reply arriving later finds no handler and is dropped
// at the transport — which is also the retention fix, and is why the count
// of pending registrations below must be zero;
// * if the reply beats the withdrawal, the exactly-once CAS in deliver() takes
// it.
//
// Be precise about what that makes this test: with an 800ms gap the withdrawal
// always wins, so it is a strong detector of the WITHDRAWAL and a weak one of
// the CAS. The strong CAS detector is ReleaseRacingAnInFlightCompletionIsSafe,
// where teardown and the completion handler genuinely arrive together.
TEST_F(IoFoldTest, ATimedOutCallThatIsLaterAnsweredStillDeliversOnce)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
auto* plain = dynamic_cast<PlainLogosObject*>(obj);
ASSERT_NE(plain, nullptr);
constexpr int kCalls = 24;
Deliveries d(kCalls);
for (int i = 0; i < kCalls; ++i) {
// 200ms deadline against a provider that is parked: the timer fires
// first, then letGo() releases the real reply into the same call.
ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 200,
[&d, i](QVariant v, const logos::CallError& e) {
d.record(i, std::move(v), e);
});
}
pumpUntilTotal(d, kCalls, 10000);
ASSERT_EQ(d.total.load(), kCalls);
ASSERT_EQ(d.code(), "timeout");
host.provider().letGo();
pump(800); // the reply arrives here, for calls already timed out
const Registries r = registries(plain);
std::cout << " " << kCalls << " timed-out-then-answered calls -> deliveries="
<< d.total.load() << " worst=" << d.worst()
<< " inflight=" << r.inflight
<< " connection-pending=" << r.pendingOnConnection << std::endl;
EXPECT_EQ(d.worst(), 1)
<< "a call was delivered twice: the exactly-once gate is not holding";
EXPECT_EQ(d.missing(), 0);
EXPECT_EQ(r.inflight, 0u);
obj->release();
pump(100);
}
// ── 2c. THE STRONG exactly-once detector: teardown against replies in flight ─
//
// Finding a race wide enough to be a reliable detector took some doing, and the
// two obvious candidates are both too narrow to trust — this comment is the map,
// because a detector that "usually" fires is not one.
//
// * timeout-then-answer (2b above) is not a race at all any more: the delivery
// withdraws the registration, so a reply arriving a comfortable interval
// later never reaches the call.
// * release-against-one-completion (further down) needs teardown to snapshot
// the call in the few instructions between the completion handler taking it
// out of `deferred` and deliver() taking it out of `inflight`. With the gate
// removed it caught nothing in 6 solo runs of 300 rounds each, and caught
// one double in a seventh run inside the full suite. It is a fine
// use-after-free hammer and an unreliable exactly-once detector; a test that
// fails one run in seven on broken code is not a gate.
//
// This one is wide by construction. Teardown snapshots the whole in-flight map
// under the lock and then delivers the calls ONE AT A TIME with the lock
// released, so with N calls outstanding the window in which the io thread can
// deliver a reply for a call teardown has already claimed is N deliveries long
// — not a handful of instructions. Both paths then arrive at deliver() for the
// same AsyncCall, and the CAS is the only thing deciding.
//
// Against a transport with the gate removed (edit (a) at the top of this file)
// this must report double deliveries. If it does not, the exactly-once
// assertions everywhere else in this file are decoration.
TEST_F(IoFoldTest, ReleaseRacingRepliesInFlightDeliversEachCallOnce)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
constexpr int kRounds = 20;
constexpr int kCalls = 500;
int doubled = 0;
int dropped = 0;
int byReply = 0;
int byTeardown = 0;
for (int r = 0; r < kRounds; ++r) {
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
auto d = std::make_shared<Deliveries>(kCalls);
auto codes = std::make_shared<std::vector<std::atomic<int>>>(2); // [reply, teardown]
for (int i = 0; i < kCalls; ++i) {
ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"),
QVariantList{ QVariant(i) }, 20000,
[d, codes, i](QVariant v, const logos::CallError& e) {
(*codes)[e.code.empty() ? 0 : 1].fetch_add(1);
d->record(i, std::move(v), e);
});
}
// No pump: release() lands while the provider is still answering, so the
// io thread is delivering replies for exactly the calls teardown is
// walking. A tiny jittered pause sweeps where in the burst it lands.
QThread::usleep(static_cast<unsigned long>((r % 6) * 120));
obj->release();
pumpUntilTotal(*d, kCalls, 15000);
pump(50); // a duplicate would land here
for (const auto& c : d->counts) {
if (c.load() > 1) doubled += c.load() - 1;
if (c.load() == 0) ++dropped;
}
byReply += (*codes)[0].load();
byTeardown += (*codes)[1].load();
}
std::cout << " " << kRounds << " rounds x " << kCalls
<< " calls released mid-burst -> answered-by-reply=" << byReply
<< " cancelled-by-teardown=" << byTeardown
<< " DOUBLE deliveries=" << doubled << " dropped=" << dropped
<< std::endl;
// Both resolvers have to have been live, or the race was not run.
EXPECT_GT(byReply, 0) << "no call was answered by its reply";
EXPECT_GT(byTeardown, 0) << "no call was cancelled by teardown — release() "
"is landing after the whole burst completed and "
"this test is racing nothing";
EXPECT_EQ(doubled, 0) << doubled << " calls were delivered more than once";
EXPECT_EQ(dropped, 0) << dropped << " calls were never delivered at all";
host.provider().letGo();
pump(200);
}
// ── 3. the deadline is not hostage to the io thread ─────────────────────────
//
// THE ONE REGRESSION THE FIRST CUT OF THIS WORK HAD. Putting the per-call timer
// on the connection's strand looks obviously right — it serializes with the
// reply handler for free — and it makes every deadline in the process wait on a
// single thread that ordinary module code is allowed to occupy: this transport
// runs user onEvent callbacks INLINE on it (rpc_connection.h dispatchIncoming),
// and an event handler calling another module is not exotic.
//
// This is the exact shape that failed, and the numbers it produced: an onEvent
// handler holding the io thread for 2000ms, while a 200ms deadline is
// outstanding on a COMPLETELY DIFFERENT connection. On the pre-fold design that
// deadline fires at ~200ms because it has its own thread. With the timer on the
// shared strand it fired at 2003ms. It must be back to ~200ms.
TEST_F(IoFoldTest, DeadlineFiresOnTimeWhileTheIoThreadIsBusy)
{
LiveHost host;
ASSERT_TRUE(host.ok());
// TWO connections, to make the point that this is not about one call
// queueing behind another on the same socket: they share nothing except the
// process-wide io_context, which is the whole problem.
auto connA = connectTo(host.port());
ASSERT_NE(connA, nullptr);
auto connB = connectTo(host.port());
ASSERT_NE(connB, nullptr);
LogosObject* a = connA->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(a, nullptr);
auto* chA = channelFor(a);
ASSERT_NE(chA, nullptr);
LogosObject* b = connB->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(b, nullptr);
auto* chB = channelFor(b);
ASSERT_NE(chB, nullptr);
std::atomic<bool> handlerRunning{false};
std::atomic<bool> handlerDone{false};
std::atomic<qint64> handlerHeldMs{0};
const std::thread::id mainThread = std::this_thread::get_id();
std::atomic<bool> onIoThread{false};
a->onEvent(QStringLiteral("tick"), [&](const QString&, const QVariantList&) {
onIoThread.store(std::this_thread::get_id() != mainThread);
handlerRunning.store(true);
QElapsedTimer held;
held.start();
// A SYNCHRONOUS call with a 2000ms budget, from inside an event handler.
// Ordinary module code. It cannot be answered — the thread that would
// decode the reply is this one — so it occupies the io thread for its
// full 2000ms and then reports a timeout, which is precisely the
// "handler that takes a while" case.
logos::CallError err;
chA->callMethodWithError(kToken, QStringLiteral("block"), {}, 2000, &err);
handlerHeldMs.store(held.elapsed());
handlerDone.store(true);
});
// Kick the event off. `fire` makes the provider emit "tick" back at us.
Deliveries fired(1);
chA->callMethodAsyncWithError(kToken, QStringLiteral("fire"), {}, 5000,
[&fired](QVariant v, const logos::CallError& e) {
fired.record(0, std::move(v), e);
});
// Wait for the handler to actually be on the io thread and blocking.
{
QElapsedTimer t;
t.start();
while (!handlerRunning.load() && t.elapsed() < 5000)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
}
ASSERT_TRUE(handlerRunning.load()) << "the event handler never ran";
ASSERT_TRUE(onIoThread.load())
<< "the event did not arrive on the io thread — this test is not "
"exercising the coupling it claims to";
// Now, with the io thread held, put a 200ms deadline on the OTHER connection.
Deliveries d(1);
QElapsedTimer deadline;
deadline.start();
chB->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 200,
[&d](QVariant v, const logos::CallError& e) {
d.record(0, std::move(v), e);
});
pumpUntilTotal(d, 1, 6000);
const qint64 firedAt = deadline.elapsed();
// Sampled BEFORE the unwind below, because it is half the claim: the io
// thread has to still be held at the moment the deadline fires, or this
// test is measuring an idle process.
const bool stillHeld = !handlerDone.load();
// Let everything unwind, so the held time can be reported rather than
// guessed at.
host.provider().letGo();
{
QElapsedTimer t;
t.start();
while (!handlerDone.load() && t.elapsed() < 8000)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
}
std::cout << " io thread held by an onEvent handler for "
<< handlerHeldMs.load() << "ms (still held when the deadline fired: "
<< stillHeld << "); a 200ms deadline on another connection fired at "
<< firedAt << "ms" << std::endl;
EXPECT_EQ(d.total.load(), 1) << "the deadline never fired at all";
EXPECT_EQ(d.code(), "timeout");
EXPECT_LT(firedAt, 800)
<< "the deadline waited for the io thread: fired at " << firedAt
<< "ms instead of ~200ms. The per-call timer is coupled to the shared "
"io_context again.";
EXPECT_GE(firedAt, 150)
<< "the deadline fired early — this is measuring something else";
EXPECT_TRUE(stillHeld)
<< "the handler let go before the deadline fired; the test proved nothing";
pump(300);
a->release();
b->release();
pump(100);
}
// The harsher half: a handler that never lets go at all. With the deadline on
// the shared io thread this call would hang for as long as the handler does,
// which is forever — the timeout stops existing exactly when it is most needed.
TEST_F(IoFoldTest, DeadlineFiresWhileTheIoThreadIsBlockedForever)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto connA = connectTo(host.port());
ASSERT_NE(connA, nullptr);
auto connB = connectTo(host.port());
ASSERT_NE(connB, nullptr);
LogosObject* a = connA->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(a, nullptr);
auto* chA = channelFor(a);
ASSERT_NE(chA, nullptr);
LogosObject* b = connB->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(b, nullptr);
auto* chB = channelFor(b);
ASSERT_NE(chB, nullptr);
std::mutex mu;
std::condition_variable cv;
bool letHandlerGo = false;
std::atomic<bool> handlerRunning{false};
std::atomic<bool> handlerDone{false};
// The handler holds the process's only io thread, so EVERY exit from this
// function — including a failed ASSERT — has to let it go. Without this a
// regression here does not fail the suite, it hangs it, and every test that
// runs afterwards hangs too.
struct Unblock {
std::mutex* mu; std::condition_variable* cv; bool* flag;
~Unblock()
{
{ std::lock_guard<std::mutex> g(*mu); *flag = true; }
cv->notify_all();
}
} unblock{&mu, &cv, &letHandlerGo};
a->onEvent(QStringLiteral("tick"), [&](const QString&, const QVariantList&) {
handlerRunning.store(true);
std::unique_lock<std::mutex> lk(mu);
cv.wait(lk, [&] { return letHandlerGo; });
handlerDone.store(true);
});
Deliveries fired(1);
chA->callMethodAsyncWithError(kToken, QStringLiteral("fire"), {}, 5000,
[&fired](QVariant v, const logos::CallError& e) {
fired.record(0, std::move(v), e);
});
{
QElapsedTimer t;
t.start();
while (!handlerRunning.load() && t.elapsed() < 5000)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
}
ASSERT_TRUE(handlerRunning.load()) << "the event handler never ran";
Deliveries d(1);
QElapsedTimer deadline;
deadline.start();
chB->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 250,
[&d](QVariant v, const logos::CallError& e) {
d.record(0, std::move(v), e);
});
pumpUntilTotal(d, 1, 4000);
const qint64 firedAt = deadline.elapsed();
std::cout << " io thread blocked with no end in sight; a 250ms deadline "
<< (d.total.load() ? "fired at " : "NEVER FIRED (")
<< firedAt << "ms" << (d.total.load() ? "" : ")")
<< ", handler still blocked: " << (!handlerDone.load()) << std::endl;
EXPECT_FALSE(handlerDone.load())
<< "the handler unblocked itself; the test proved nothing";
EXPECT_EQ(d.total.load(), 1)
<< "the deadline never fired: it is waiting for an io thread that is "
"never coming back";
if (d.total.load() == 1) {
EXPECT_EQ(d.code(), "timeout");
EXPECT_LT(firedAt, 1500);
}
{
std::lock_guard<std::mutex> g(mu);
letHandlerGo = true;
}
cv.notify_all();
host.provider().letGo();
{
QElapsedTimer t;
t.start();
while (!handlerDone.load() && t.elapsed() < 8000)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
}
pump(300);
a->release();
b->release();
pump(100);
}
// The same deadline, with nothing in the way: the accuracy the timer thread
// delivers when the process is idle. This is the baseline the two tests above
// are compared against, and it is what a caller's timeoutMs actually means.
TEST_F(IoFoldTest, DeadlineAccuracyWhenIdle)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
constexpr int kRounds = 12;
constexpr int kDeadlineMs = 200;
std::vector<qint64> observed;
for (int i = 0; i < kRounds; ++i) {
Deliveries d(1);
QElapsedTimer t;
t.start();
ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, kDeadlineMs,
[&d](QVariant v, const logos::CallError& e) {
d.record(0, std::move(v), e);
});
pumpUntilTotal(d, 1, 5000);
ASSERT_EQ(d.total.load(), 1);
ASSERT_EQ(d.code(), "timeout");
observed.push_back(t.elapsed());
}
std::sort(observed.begin(), observed.end());
const qint64 lo = observed.front();
const qint64 med = observed[observed.size() / 2];
const qint64 hi = observed.back();
std::cout << " " << kRounds << " idle " << kDeadlineMs
<< "ms deadlines: min=" << lo << " median=" << med
<< " max=" << hi << "ms" << std::endl;
EXPECT_GE(lo, kDeadlineMs - 20) << "a deadline fired early";
// Generous, because the delivery hop through the Qt event loop and this
// test's own 5ms pump granularity are both inside the measurement.
EXPECT_LE(med, kDeadlineMs + 120);
EXPECT_LE(hi, kDeadlineMs + 400);
host.provider().letGo();
obj->release();
pump(100);
}
// ── 4. retention: what a call that is never answered leaves behind ──────────
//
// TWO registries, and until this change only one of them was emptied. The
// handle's CallState::inflight is erased by the delivery. The CONNECTION's
// m_pendingCalls was erased by exactly two events — a decoded reply carrying
// that id, and fail()'s teardown sweep — so a call resolved by its DEADLINE was
// in neither, and its registration stayed for the life of the connection, which
// outlives every handle it hands out. That was true of the promise it held
// before the fold too; the fold made the orphan bigger (a handler closing over
// the caller's std::function rather than a promise), so it is closed here
// rather than inherited: AsyncCall::deliver() withdraws the registration.
TEST_F(IoFoldTest, CallsResolvedByTheirDeadlineLeaveNothingBehind)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
auto* plain = dynamic_cast<PlainLogosObject*>(obj);
ASSERT_NE(plain, nullptr);
// Every one of these times out against a provider parked in `block`, and is
// never answered — the exact shape nothing used to clean up.
constexpr int kCalls = 200;
Deliveries d(kCalls);
for (int i = 0; i < kCalls; ++i) {
ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 60,
[&d, i](QVariant v, const logos::CallError& e) {
d.record(i, std::move(v), e);
});
}
pumpUntilTotal(d, kCalls, 30000);
pump(300);
const Registries r = registries(plain);
std::cout << " " << kCalls << " deadline-orphaned calls -> inflight="
<< r.inflight << " deferred=" << r.deferred
<< " connection-pending=" << r.pendingOnConnection
<< " deliveries=" << d.total.load() << " worst=" << d.worst()
<< " code='" << d.code() << "'" << std::endl;
EXPECT_EQ(d.total.load(), kCalls);
EXPECT_EQ(d.worst(), 1);
EXPECT_EQ(d.code(), "timeout");
EXPECT_EQ(r.inflight, 0u);
EXPECT_EQ(r.deferred, 0u);
EXPECT_EQ(r.pendingOnConnection, 0u)
<< r.pendingOnConnection << " of " << kCalls << " calls left their "
<< "registration in the connection's pending map: retention is growing "
<< "with call count on the connection, which outlives every handle.";
host.provider().letGo();
pump(200);
obj->release();
pump(100);
}
// A "multi" provider can answer the pending sentinel AFTER the caller's deadline
// has passed. The deadline has already resolved the call by then; the reply
// handler then arrives, sees a sentinel, and — in the first cut of this design —
// filed the AsyncCall under CallState::deferred and re-armed. Nothing took it out
// again, because the re-armed deadline's deliver() returned at the exactly-once
// gate before reaching the erase: one leaked map entry per slow-sentinel call,
// which is exactly the retention the fold exists to remove, reintroduced by a
// different route.
//
// The fix is two-part and both parts are load-bearing: deliver() leaves the
// registries BEFORE the gate rather than after it, and the reply handler declines
// to file a call that is already delivered.
TEST_F(IoFoldTest, ASentinelArrivingAfterItsDeadlineDoesNotLeakARegistryEntry)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
auto* plain = dynamic_cast<PlainLogosObject*>(obj);
ASSERT_NE(plain, nullptr);
// The provider sleeps 400ms per call on its single proxy thread, so these
// serialize; each one's 100ms deadline is long gone when its sentinel lands.
constexpr int kCalls = 6;
Deliveries d(kCalls);
for (int i = 0; i < kCalls; ++i) {
ch->callMethodAsyncWithError(kToken, QStringLiteral("slowsink"), {}, 100,
[&d, i](QVariant v, const logos::CallError& e) {
d.record(i, std::move(v), e);
});
}
pumpUntilTotal(d, kCalls, 20000);
// Every call has timed out; now let the late sentinels arrive and be
// processed. This is the window the leak opens in.
pump(3000);
const Registries r = registries(plain);
std::cout << " " << kCalls << " late-sentinel calls -> inflight=" << r.inflight
<< " deferred=" << r.deferred << " connection-pending="
<< r.pendingOnConnection << " deliveries=" << d.total.load()
<< " worst=" << d.worst() << " code='" << d.code() << "'" << std::endl;
EXPECT_EQ(d.total.load(), kCalls);
EXPECT_EQ(d.worst(), 1);
EXPECT_EQ(d.code(), "timeout");
EXPECT_EQ(r.inflight, 0u);
EXPECT_EQ(r.deferred, 0u)
<< "a sentinel that arrived after its own deadline left " << r.deferred
<< " entries behind: retention is growing with call count again";
EXPECT_EQ(r.pendingOnConnection, 0u);
obj->release();
pump(100);
}
// ── 5. release racing an in-flight COMPLETION ───────────────────────────────
//
// The hazard that already existed, and the second strong exactly-once detector.
// The completion-event subscription runs on the Asio io thread, RpcConnection
// invokes it with its own lock released, and NOTHING joins that thread. Under
// the thread-per-call design the subscription captured raw `this`, so release()'s
// `delete this` could land inside the callback — reproduced as a SIGSEGV under
// Guard Malloc in test_plain_completion_sub_lifetime.cpp, which is a separate
// change from this one and where that detector lives.
//
// What this adds is the FOLD's version of the same race: teardown and the
// completion handler both trying to resolve the same call. It is one of the two
// places where two resolvers genuinely arrive at deliver() for one call, so it
// is also where a broken exactly-once gate shows up.
//
// Run it under Guard Malloc to make a freed access fatal rather than
// probabilistic:
// DYLD_INSERT_LIBRARIES=/usr/lib/libgmalloc.dylib \
// ./protocol_tests --gtest_filter='IoFoldTest.ReleaseRacing*'
TEST_F(IoFoldTest, ReleaseRacingAnInFlightCompletionIsSafe)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
constexpr int kRounds = 300;
int done = 0;
int doubled = 0;
QElapsedTimer total;
total.start();
for (int i = 0; i < kRounds; ++i) {
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
auto d = std::make_shared<Deliveries>(1);
// 0..~2.4ms of completion delay, swept, so the release below lands
// before, during and after the completion callback across the run.
ch->callMethodAsyncWithError(kToken, QStringLiteral("defer"),
QVariantList{ QVariant((i % 25) * 100) }, 8000,
[d](QVariant v, const logos::CallError& e) {
d->record(0, std::move(v), e);
});
if (i % 4 != 0)
QThread::usleep(static_cast<unsigned long>((i % 25) * 100));
obj->release();
// Whatever the race decided, the caller is told once: either the
// completion landed first (value 7) or the release did (transport_error).
pumpUntilTotal(*d, 1, 5000);
pump(5);
if (d->total.load() > 1) ++doubled;
ASSERT_EQ(d->total.load(), 1)
<< "round " << i << ": " << d->total.load() << " callbacks, not one";
++done;
}
std::cout << " " << done << "/" << kRounds
<< " release-during-completion rounds, exactly one callback each, in "
<< total.elapsed() << "ms (double deliveries: " << doubled << ")"
<< std::endl;
EXPECT_EQ(done, kRounds);
EXPECT_EQ(doubled, 0);
}
// ── why "wait for the io thread" was not an option ──────────────────────────
//
// The obvious alternative to shared ownership is a barrier: post a no-op onto
// the strand at teardown and block until it runs, which would prove no handler
// is mid-flight. It cannot be used here, and this is the reason.
//
// IoContextPool runs EXACTLY ONE worker thread and is a process-wide singleton
// (io_context_pool.cpp), and the plain transport delivers user event callbacks
// INLINE on it (rpc_connection.h). So a user handler that releases its handle —
// the reentrant-release-from-event-dispatch shape remote_transport.cpp documents
// as shipped production behaviour — is running ON the only thread that could
// ever drain that barrier. It would wedge the process. (Measured: it does.)
//
// This design has nothing to wait for, so the same call just returns. The
// watchdog turns a regression into a named abort rather than a CI job that hangs
// until its timeout.
TEST_F(IoFoldTest, ReleaseFromInsideAnIoThreadEventCallbackDoesNotWedge)
{
LiveHost host;
ASSERT_TRUE(host.ok());
auto conn = connectTo(host.port());
ASSERT_NE(conn, nullptr);
LogosObject* obj = conn->requestObject(QStringLiteral("omni_module"), 5000);
ASSERT_NE(obj, nullptr);
auto* ch = channelFor(obj);
ASSERT_NE(ch, nullptr);
std::atomic<bool> releasedFromCallback{false};
std::atomic<bool> onIoThread{false};
const std::thread::id mainThread = std::this_thread::get_id();
obj->onEvent(QStringLiteral("tick"),
[&](const QString&, const QVariantList&) {
onIoThread.store(std::this_thread::get_id() != mainThread);
obj->release(); // reentrant, on the io thread
releasedFromCallback.store(true);
});
// A call left outstanding, so the reentrant release has real work to do:
// it must cancel this and deliver its callback.
Deliveries d(1);
ch->callMethodAsyncWithError(kToken, QStringLiteral("sink"), {}, 9000,
[&d](QVariant v, const logos::CallError& e) {
d.record(0, std::move(v), e);
});
pump(200);
ASSERT_EQ(d.total.load(), 0);
// A watchdog, because the failure mode is a hang and not an assertion.
std::atomic<bool> finished{false};
std::thread dog([&] {
for (int i = 0; i < 200 && !finished.load(); ++i)
std::this_thread::sleep_for(std::chrono::milliseconds(50));
if (!finished.load()) {
std::fprintf(stderr, "\nWATCHDOG: reentrant release() from an io-thread "
"event callback wedged the process.\n");
std::fflush(stderr);
std::abort();
}
});
// Fire the event. The provider's own reply to `fire` is irrelevant; what
// matters is that the event handler runs on the io thread and releases.
auto fired = std::make_shared<Deliveries>(1);
ch->callMethodAsyncWithError(kToken, QStringLiteral("fire"), {}, 5000,
[fired](QVariant v, const logos::CallError& e) {
fired->record(0, std::move(v), e);
});
QElapsedTimer t;
t.start();
while (!releasedFromCallback.load() && t.elapsed() < 5000)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
finished.store(true);
dog.join();
pumpUntilTotal(d, 1, 3000);
pump(300);
std::cout << " reentrant release from the io thread returned after "
<< t.elapsed() << "ms (on io thread: " << onIoThread.load()
<< "), abandoned call delivered " << d.total.load()
<< " time(s) code='" << d.code() << "'" << std::endl;
EXPECT_TRUE(releasedFromCallback.load())
<< "release() never returned from inside the io-thread event callback";
EXPECT_TRUE(onIoThread.load())
<< "the event did not arrive on the io thread — this test is not "
"exercising the reentrancy it claims to";
EXPECT_EQ(d.total.load(), 1);
EXPECT_EQ(d.code(), "transport_error");
host.provider().letGo();
pump(200);
}