diff --git a/cpp/implementations/plain/plain_logos_object.cpp b/cpp/implementations/plain/plain_logos_object.cpp index 84251ab..c5dce2b 100644 --- a/cpp/implementations/plain/plain_logos_object.cpp +++ b/cpp/implementations/plain/plain_logos_object.cpp @@ -9,13 +9,114 @@ #include #include +#include +#include #include #include +#include #include #include namespace logos::plain { +namespace { + +// How long a waiter sleeps before it looks at the stop flag again. +// +// A std::future wait cannot be interrupted, so the only way to make one +// abandonable is to wait in slices against the same overall deadline and check +// the flag between them. That slice IS the teardown-latency bound: releasing a +// handle with a call in flight costs at most one of these, instead of whatever +// is left of the call's timeout (20s on the protocol default, logos_mode.h). +// +// 25ms is chosen off both ends of the trade: +// * latency — a module unloading mid-call should feel instantaneous. 25ms is +// under two 60Hz frames and well below the ~100ms at which a stall becomes +// perceptible, so even a shutdown releasing handles back to back stays +// invisible. +// * cost — one timed wakeup per slice per IN-FLIGHT call: 40/s, i.e. 800 +// spread over a full 20s default timeout, and paid only while a call is +// actually outstanding. That is far below the wakeup rate of the Qt event +// loop these waiters already sit beside. +// Below ~5ms the extra wakeups buy latency nobody can perceive; at 100-250ms +// the teardown hitch starts to show. +constexpr std::chrono::milliseconds kWaitSlice(25); + +enum class WaitOutcome { Ready, TimedOut, Cancelled }; + +// ── the one rule both waits follow ────────────────────────────────────────── +// +// AN ANSWER ALREADY IN HAND BEATS A CONCURRENT STOP. The stop only decides what +// happens when there is nothing to hand over. +// +// The two sites used to resolve this in opposite directions — this one tested +// the flag before polling, so an already-ready future was still reported as +// transport_error, while awaitCompletion deliberately preferred a completion +// that had landed. Both were commented as deliberate, and they cannot both be +// right, so: the callback fires either way (postToQtEventLoop copies everything +// it delivers, precisely so a released handle costs it nothing), which means the +// only thing a stop can change is what the callback SAYS. Reporting +// transport_error while the true answer sits in the future is a failure that did +// not happen, and that code is not inert — callers re-acquire, retry and log on +// it. Preferring the answer is also free: it is already there, so nothing waits +// for it. The teardown-latency bound is untouched, because the flag is still +// checked before every sleep, and a stop with no answer in hand still wins +// immediately. +// +// The interruptible form of `fut.wait_for(milliseconds(timeoutMs))`. +// +// The overall deadline is computed once, so slicing does not stretch the +// timeout the caller asked for: the last slice ends exactly on it. +WaitOutcome waitForResult(std::future& fut, int timeoutMs, + const std::atomic& stopping) +{ + using clock = std::chrono::steady_clock; + const auto deadline = clock::now() + std::chrono::milliseconds(timeoutMs); + for (;;) { + // Poll FIRST, with a zero wait: an answer in hand beats both a + // concurrent stop and the deadline. This is also what makes a + // non-positive timeout behave as the single unsliced wait_for did — + // one poll, then give up — and what reports a future that went ready + // during the last slice. + if (fut.wait_for(clock::duration::zero()) == std::future_status::ready) + return WaitOutcome::Ready; + // Checked before sleeping, so a stop that already happened costs + // nothing, and after every slice, so one that arrives mid-wait costs at + // most kWaitSlice. + if (stopping.load(std::memory_order_acquire)) + return WaitOutcome::Cancelled; + + const auto remaining = deadline - clock::now(); + if (remaining <= clock::duration::zero()) + return WaitOutcome::TimedOut; + fut.wait_for(std::min(kWaitSlice, remaining)); + } +} + +// The honest code for "the object was released while your call was in flight". +// +// logos_call_error.h's vocabulary is part of the wire contract, so this reuses +// it rather than minting a code. "transport_error" is defined there as "the +// connection failed or was torn down mid-call", which is exactly what happened: +// the consumer tore its own end of the call channel down. Every alternative in +// that set misattributes the failure — "object_unavailable" says the module is +// not there (it is, and it is very likely about to answer; callers re-acquire +// on that code), "call_failed" blames the peer for a dispatch it performed +// perfectly well, and "timeout" — what this used to report, after waiting the +// deadline out — claims a deadline elapsed that did not. It is also already the +// code the wire produces for the same event seen from the other end: +// callErrorFromWire maps TRANSPORT_CLOSED / TRANSPORT_ERROR to transport_error. +logos::CallError callErrorReleased(const std::string& objectName, + const std::string& method) +{ + return logos::callErrorTransport( + objectName, + "call to '" + objectName + "." + method + "' was abandoned: the object " + "was released while the call was in flight"); +} + +} // anonymous namespace + PlainLogosObject::PlainLogosObject(std::string objectName, std::shared_ptr conn) : m_objectName(std::move(objectName)) @@ -26,6 +127,119 @@ PlainLogosObject::PlainLogosObject(std::string objectName, PlainLogosObject::~PlainLogosObject() { disconnectEvents(); + stopAndJoinWaiters(); +} + +void PlainLogosObject::stopWaiters() +{ + { + // Published under m_completionMu — the mutex awaitCompletion evaluates + // its predicate under — so a waiter cannot read `false`, decide to + // sleep, and only then miss the notify_all below. The sliced future + // wait reads the same flag lock-free, which is why it is an atomic + // rather than a plain bool guarded by this mutex. + std::lock_guard g(m_completionMu); + m_stopping.store(true, std::memory_order_release); + } + m_completionCv.notify_all(); +} + +void PlainLogosObject::publishFinishedWaiter(std::uint64_t id) +{ + std::lock_guard g(m_waiterMu); + m_finishedWaiters.push_back(id); +} + +void PlainLogosObject::reapFinishedWaiters() +{ + // Only ids a waiter published are taken, and publishing is that waiter's + // last act — so everything moved into `done` has already stopped touching + // this object, and joining it is effectively instant. + std::vector done; + { + std::lock_guard g(m_waiterMu); + std::vector keep; + for (const std::uint64_t id : m_finishedWaiters) { + const auto it = m_waiters.find(id); + if (it == m_waiters.end()) + continue; // teardown already took this one + if (it->second.get_id() == std::this_thread::get_id()) { + // A waiter DOES run this now, on its way out — but always + // BEFORE it publishes, so its own id cannot be in the list it + // is walking, and this branch stays unreachable. It costs one + // comparison, and it turns the ordering slip that would make it + // reachable (publishing before reaping) into a leaked entry + // rather than a self-join, which throws out of the noexcept + // destructor doing the reaping and takes the process with it. + // Leave it registered; the next reaper, or teardown, collects it. + keep.push_back(id); + continue; + } + done.push_back(std::move(it->second)); + m_waiters.erase(it); + } + m_finishedWaiters.swap(keep); + } + // Joined with NO lock held. The deadlock this whole mechanism can + // introduce is a reaper that holds m_waiterMu while it joins a waiter which + // is itself blocked on m_waiterMu trying to publish. TWO INDEPENDENT + // PROPERTIES each prevent it, and either one alone would be enough: + // + // * only PUBLISHED ids are joined, and publishing is a waiter's last + // access — so a thread this function joins can never be a thread that + // still wants m_waiterMu; + // * no join happens with a lock held, so even joining a thread that DID + // still want the mutex could not shut it out. + // + // Both are kept on purpose: the filter is a property of the logic here, + // which a refactor can lose without looking wrong, while "no join under a + // lock" is structural and tends to survive one. Be precise about what that + // costs in testing, though — the hammer in the regression suite only wedges + // when BOTH are gone. A variant that joins under the lock but keeps the + // published-only filter passes it, measured, in the usual few hundred ms. + // stopAndJoinWaiters() keeps the same discipline. + for (auto& t : done) { + if (t.joinable()) + t.join(); + } +} + +void PlainLogosObject::stopAndJoinWaiters() +{ + stopWaiters(); + + std::map waiters; + { + std::lock_guard g(m_waiterMu); + waiters.swap(m_waiters); + } + // Joined with NO lock held: a waiter on its way out still takes + // m_completionMu (awaitCompletion) and then m_waiterMu (to publish), and + // m_waiterMu is also what a concurrent callMethodAsyncWithError needs in + // order to see the stop flag. + // + // Everything outstanding is joined by id-independent brute force, so this + // needs no cooperation from the reaper: a waiter that publishes while this + // loop runs simply leaves a stale id behind, and its thread is joined here + // anyway. + // + // A waiter that a concurrent reaper is in the middle of joining is NOT in + // this map, and that is still safe. The invariant is not "every waiter has + // been joined by the time this returns" but the thing that invariant was + // ever for: NO WAITER TOUCHES THIS OBJECT AFTER THIS RETURNS. An entry + // leaves m_waiters only once its thread has published, and publishing is + // that thread's last access — all it has left to do is unwind. + for (auto& entry : waiters) { + std::thread& t = entry.second; + if (t.joinable()) + t.join(); + } + // Cleared after the joins, so the stale ids just described go too. Nothing + // can be added afterwards: m_stopping is set, so no new waiter registers. + { + std::lock_guard g(m_waiterMu); + m_finishedWaiters.clear(); + } } QVariant PlainLogosObject::callMethod(const QString& authToken, @@ -33,7 +247,24 @@ QVariant PlainLogosObject::callMethod(const QString& authToken, const QVariantList& args, int timeoutMs) { - if (!m_conn || !m_conn->isOpen()) return QVariant(); + // Adapter over the error-carrying implementation: discards the diagnosis, + // which is exactly what this entry point has always done. + return callMethodWithError(authToken, methodName, args, timeoutMs, nullptr); +} + +QVariant PlainLogosObject::callMethodWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + logos::CallError* err) +{ + if (err) err->clear(); + if (!m_conn || !m_conn->isOpen()) { + if (err) + *err = logos::callErrorTransport( + m_objectName, "connection to '" + m_objectName + "' is not open"); + return QVariant(); + } // Subscribe to the completion channel BEFORE sending, so a "multi" provider's // completion can't race ahead of the waiter (it's buffered either way). @@ -50,12 +281,22 @@ QVariant PlainLogosObject::callMethod(const QString& authToken, if (fut.wait_for(std::chrono::milliseconds(timeoutMs)) != std::future_status::ready) { qWarning() << "PlainLogosObject::callMethod: timeout for" << methodName; + if (err) + *err = logos::callErrorTimeout(m_objectName, methodName.toStdString(), + timeoutMs); return QVariant(); } auto res = fut.get(); if (!res.ok) { qWarning() << "PlainLogosObject::callMethod:" << methodName << "failed:" << QString::fromStdString(res.err); + // res.errCode / res.err have been on the wire since the plain transport + // existed; this is the first caller to keep them. MODULE_NOT_LOADED in + // particular is how "the module isn't there" reaches us on this + // transport — requestObject never checks publication — so without this + // the single most common failure was reported as a null result. + if (err) + *err = logos::callErrorFromWire(m_objectName, res.errCode, res.err); return QVariant(); } const QVariant value = rpcValueToQVariant(res.value); @@ -64,7 +305,7 @@ QVariant PlainLogosObject::callMethod(const QString& authToken, { QString callId; if (logos::isPendingCallSentinel(value, &callId)) - return awaitCompletion(callId, timeoutMs); + return awaitCompletion(callId, timeoutMs, methodName, err); } return value; } @@ -90,20 +331,43 @@ void PlainLogosObject::ensureCompletionSub() }); } -QVariant PlainLogosObject::awaitCompletion(const QString& callId, int timeoutMs) +QVariant PlainLogosObject::awaitCompletion(const QString& callId, int timeoutMs, + const QString& methodName, + logos::CallError* err) { std::unique_lock lk(m_completionMu); + const auto effectiveMs = timeoutMs > 0 ? timeoutMs : 30000; const auto deadline = std::chrono::steady_clock::now() - + std::chrono::milliseconds(timeoutMs > 0 ? timeoutMs : 30000); - const bool got = m_completionCv.wait_until(lk, deadline, - [&] { return m_completions.count(callId) > 0; }); - if (!got) { - qWarning() << "PlainLogosObject: deferred call" << callId << "timed out"; + + std::chrono::milliseconds(effectiveMs); + // Unlike the future wait this one is interruptible by construction: widen + // the predicate, and stopWaiters()' notify_all does the rest. No slicing, so + // no latency floor at all here — a stop wakes this wait immediately. + m_completionCv.wait_until(lk, deadline, [&] { + return m_completions.count(callId) > 0 + || m_stopping.load(std::memory_order_relaxed); + }); + + // A completion that actually landed beats a concurrent stop — the same rule + // the future wait follows (see waitForResult): there is a real answer in + // hand, so hand it over rather than manufacture an error. + const auto it = m_completions.find(callId); + if (it != m_completions.end()) { + const QVariant result = it->second; + m_completions.erase(it); + return result; + } + if (m_stopping.load(std::memory_order_relaxed)) { + qWarning() << "PlainLogosObject: deferred call" << callId + << "abandoned — object released while it was in flight"; + if (err) + *err = callErrorReleased(m_objectName, methodName.toStdString()); return QVariant(); } - const QVariant result = m_completions[callId]; - m_completions.erase(callId); - return result; + qWarning() << "PlainLogosObject: deferred call" << callId << "timed out"; + if (err) + *err = logos::callErrorTimeout(m_objectName, methodName.toStdString(), + effectiveMs); + return QVariant(); } namespace { @@ -118,14 +382,23 @@ namespace { // process, regardless of which worker thread completed the future. // If the application has shut down (instance() is null), we drop the // callback rather than invoke it from an arbitrary thread. -void postToQtEventLoop(PlainLogosObject::AsyncResultCallback callback, - QVariant result) +// +// Deliberately a FREE function taking everything BY VALUE, and deliberately not +// a member: the queued lambda runs on a later event-loop iteration, which for a +// waiter cancelled by teardown is after the PlainLogosObject is already gone. +// Nothing it touches may belong to the object — which is why the waiter copies +// objectName/method up front instead of reading m_objectName from inside here. +// Do not give this a `this`; delivering during teardown would become the +// use-after-free that joining the waiters exists to prevent. +void postToQtEventLoop(PlainLogosObject::AsyncResultErrorCallback callback, + QVariant result, logos::CallError err) { QCoreApplication* app = QCoreApplication::instance(); if (!app) return; QMetaObject::invokeMethod(app, - [callback = std::move(callback), result = std::move(result)]() mutable { - callback(result); + [callback = std::move(callback), result = std::move(result), + err = std::move(err)]() mutable { + callback(result, err); }, Qt::QueuedConnection); } @@ -137,12 +410,30 @@ void PlainLogosObject::callMethodAsync(const QString& authToken, const QVariantList& args, int timeoutMs, AsyncResultCallback callback) +{ + // Adapter over the error-carrying implementation: discards the diagnosis, + // which is exactly what this entry point has always done. + if (!callback) return; + callMethodAsyncWithError(authToken, methodName, args, timeoutMs, + [cb = std::move(callback)](QVariant v, const logos::CallError&) mutable { + cb(std::move(v)); + }); +} + +void PlainLogosObject::callMethodAsyncWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + AsyncResultErrorCallback callback) { if (!callback) return; if (!m_conn || !m_conn->isOpen()) { // Defer even the failure path — LogosObject's contract requires // callbacks on a subsequent event-loop iteration, never inline. - postToQtEventLoop(std::move(callback), QVariant()); + postToQtEventLoop(std::move(callback), QVariant(), + logos::callErrorTransport( + m_objectName, + "connection to '" + m_objectName + "' is not open")); return; } @@ -163,23 +454,165 @@ void PlainLogosObject::callMethodAsync(const QString& authToken, // future iteration can fold this wait into the shared Asio // io_context (the connection already runs on it) so we don't spin // up a thread per pending RPC. - std::thread([this, fut, timeoutMs, callback = std::move(callback)]() mutable { - if (fut->wait_for(std::chrono::milliseconds(timeoutMs)) - != std::future_status::ready) { - postToQtEventLoop(std::move(callback), QVariant()); + // + // The thread is JOINed — in reapFinishedWaiters() once it has finished, or + // in stopAndJoinWaiters() (destructor / release) if teardown gets there + // first — never detached: capturing `this` for awaitCompletion / + // m_stopping is only safe while the object is alive, and release() used to + // `delete this` while a waiter could still be mid-flight. + const std::string objectName = m_objectName; + const std::string method = methodName.toStdString(); + // Retire the previous calls' waiters before adding one. The waiters reap + // each other too, on their way out (see the guard below) — that is what + // drains a burst which then goes quiet, and it is why this site is no + // longer the only reaper. It still earns its keep: a waiter can only reap + // OTHERS, so the last one to finish has nobody behind it to collect it. + // Done BEFORE taking m_waiterMu because it joins, and joining under that + // lock is the shape described in reapFinishedWaiters(). + reapFinishedWaiters(); + // Register under the lock BEFORE the thread can outrun release(): a + // detach-then-push left a window where delete this raced the waiter. + { + std::lock_guard g(m_waiterMu); + if (m_stopping.load(std::memory_order_acquire)) { + // Refuse rather than register: teardown has already swapped + // m_waiters out, so a thread pushed now would never be joined. + // + // To be honest about what this branch is: it is NOT a reachable + // window that got closed. m_stopping is raised only by teardown + // (release() / the destructor), so a thread that can read it as + // true here is already calling a method on an object whose + // destructor is running — this very load is the use-after-free, and + // nothing inside this function can repair that. Reproduced as a + // SIGSEGV, on this branch and on its parent alike. It is kept + // because it costs one predictable branch on a path that already + // does a socket write, and because failing this way — one callback, + // with the same error a cancelled call gets — is strictly better + // than pushing a thread nobody will ever join, should some future + // caller of stopWaiters() make the state legitimately observable. + postToQtEventLoop(std::move(callback), QVariant(), + callErrorReleased(objectName, method)); return; } - auto res = fut->get(); - QVariant value = res.ok ? rpcValueToQVariant(res.value) : QVariant(); - // Resolve a "multi" provider's deferred completion (sentinel → wait for - // the completion event) right here on the waiter thread. - { - QString callId; - if (logos::isPendingCallSentinel(value, &callId)) - value = awaitCompletion(callId, timeoutMs); - } - postToQtEventLoop(std::move(callback), std::move(value)); - }).detach(); + const std::uint64_t waiterId = m_nextWaiterId++; + std::thread waiter([this, waiterId, objectName, fut, timeoutMs, methodName, method, + callback = std::move(callback)]() mutable { + // Everything reached through `this` below (m_stopping, + // awaitCompletion's m_completionMu / m_completions) is safe only + // because this thread is joined before the object dies — by the + // reaper if it finishes first, by stopAndJoinWaiters() otherwise. + // Everything handed to postToQtEventLoop is a COPY, because that + // delivery happens after this thread has returned — i.e. possibly + // after the object is gone. Keep it that way. + // + // Declared FIRST so it destructs LAST: publishing this waiter's id + // is what permits somebody else to join and drop it, so it must + // come after every access to the object, on every exit path + // (four returns below, plus anything that throws). What runs after + // it is the unwinding of the captures above, none of which belongs + // to the object: a string, a shared_ptr to the call's future, and a + // callback that has already been moved out. + // + // It REAPS BEFORE IT PUBLISHES, and that order is the safety + // argument rather than a stylistic choice. Two reasons, one of + // which the test suite demonstrates: + // + // * Publishing is what makes a waiter joinable BY ANOTHER WAITER. + // Reaping first keeps that relation one-way — unpublished + // threads join published ones, published ones join nobody — so + // it cannot contain a cycle. Inverted, two waiters that publish + // in the same instant can each take the other's thread out of + // m_waiters and then join it. Both are already out of the + // registry, so teardown does not even wait for them; here + // pthread_join detects the cycle and throws out of + // reapFinishedWaiters, whose half-drained vector then destroys + // a still-joinable thread — std::terminate. Re-measured over a + // longer run than the 5/5 an earlier commit message claimed: + // with the two lines below swapped, ReapingRacesPublishingWith- + // outDeadlocking aborts the process 12 runs in 15. It is a + // race, so it is a probabilistic detector and a single green + // run of it proves nothing. + // * Until it publishes, this waiter is still in m_waiters, so a + // concurrent teardown joins it and the object cannot be + // destroyed under the reap. After publishing, a reaper can take + // its thread out of the map and release() can `delete this`, + // and a reaper running on the CALLER's thread (the spawn path + // above) is one teardown neither knows about nor waits for — so + // the touch of m_waiterMu would land on freed memory. That one + // needs a caller still issuing calls while another thread + // releases, which this class already treats as caller-side UB, + // so no test can provoke it without being red on correct code. + // BE PRECISE ABOUT WHAT THAT MAKES THIS: an invariant the design + // rests on, NOT a live use-after-free waiting to be hit. Under + // supported use every waiter is still joined transitively — one + // leaves m_waiters only via teardown (which joins it) or via a + // reaper, and that reaper is either another waiter, still + // registered itself because it reaps before it publishes, or the + // spawn path, whose join finishes before the call returns. The + // only reaper nobody waits for is that spawn path racing a + // release(), i.e. the caller-side UB above. + // test_plain_waiter_publish_is_last.cpp therefore stops trying + // to provoke it and OBSERVES the accesses instead: it guards the + // object's non-registry state with mprotect while a waiter runs, + // and baits the registry with an entry planted while the waiter + // is parked mid-join. It pins the rule against future edits — + // the TODO above moves where reaping happens — rather than + // closing an open hole. + // + // Reaping here at all is what makes the retention bound hold for a + // module that bursts and then goes quiet: the spawn-path reaper + // only runs if another call ever comes. + struct FinishOnExit { + PlainLogosObject* self; + std::uint64_t id; + ~FinishOnExit() + { + self->reapFinishedWaiters(); // others, never itself + self->publishFinishedWaiter(id); // strictly last + } + } finishOnExit{this, waiterId}; + + const WaitOutcome outcome = waitForResult(*fut, timeoutMs, m_stopping); + if (outcome == WaitOutcome::Cancelled) { + // A cancelled call still DELIVERS, exactly once. Returning + // silently here would honour the "stop fast" half and break the + // half that matters more: callMethodAsyncWithError (and + // lp_invoke_async above it) promise the callback fires exactly + // once, so a dropped one turns a bounded stall into an + // unbounded hang in every caller that awaits it. + postToQtEventLoop(std::move(callback), QVariant(), + callErrorReleased(objectName, method)); + return; + } + if (outcome == WaitOutcome::TimedOut) { + postToQtEventLoop(std::move(callback), QVariant(), + logos::callErrorTimeout(objectName, method, + timeoutMs)); + return; + } + auto res = fut->get(); + if (!res.ok) { + postToQtEventLoop(std::move(callback), QVariant(), + logos::callErrorFromWire(objectName, res.errCode, + res.err)); + return; + } + QVariant value = rpcValueToQVariant(res.value); + // Resolve a "multi" provider's deferred completion (sentinel → wait for + // the completion event) right here on the waiter thread. This is the + // second interruptible site: a stop lands it on callErrorReleased, + // which still falls through to the single post below — one callback, + // whichever way this went. + logos::CallError err; + { + QString callId; + if (logos::isPendingCallSentinel(value, &callId)) + value = awaitCompletion(callId, timeoutMs, methodName, &err); + } + postToQtEventLoop(std::move(callback), std::move(value), std::move(err)); + }); + m_waiters.emplace(waiterId, std::move(waiter)); + } } bool PlainLogosObject::informModuleToken(const QString& authToken, @@ -266,7 +699,16 @@ void PlainLogosObject::release() // the connection for every other holder too, so just unsubscribe our // own events and drop our reference — the connection stays alive // until PlainTransportConnection itself is destroyed. + // + // stopAndJoinWaiters() before delete: in-flight async waiters capture `this` + // (for awaitCompletion). Detaching them used to let release() free the + // object under a still-running waiter — and merely joining them made + // release() block for the rest of the call's timeout, so they are asked to + // stop first. Each abandoned call still delivers its callback, once, with + // callErrorReleased. Waiters that already finished were reaped as the + // calls after them were issued; this collects whatever is left. disconnectEvents(); + stopAndJoinWaiters(); m_conn.reset(); delete this; } diff --git a/cpp/implementations/plain/plain_logos_object.h b/cpp/implementations/plain/plain_logos_object.h index 87f6df1..d580097 100644 --- a/cpp/implementations/plain/plain_logos_object.h +++ b/cpp/implementations/plain/plain_logos_object.h @@ -5,11 +5,14 @@ #include "rpc_connection.h" +#include #include +#include #include #include #include #include +#include #include #include @@ -23,7 +26,7 @@ namespace logos::plain { // Owns a shared_ptr; the transport layer hands the // connection over after opening the socket. release() stops the connection. // ----------------------------------------------------------------------------- -class PlainLogosObject : public LogosObject { +class PlainLogosObject : public LogosObject, public LogosObjectErrorChannel { public: PlainLogosObject(std::string objectName, std::shared_ptr conn); @@ -40,6 +43,21 @@ public: int timeoutMs, AsyncResultCallback callback) override; + // LogosObjectErrorChannel — the real implementations. The two LogosObject + // entry points above are thin adapters that discard the error, so there is + // exactly ONE call path per direction and the two front doors cannot drift. + QVariant callMethodWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + logos::CallError* err) override; + + void callMethodAsyncWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + AsyncResultErrorCallback callback) override; + bool informModuleToken(const QString& authToken, const QString& moduleName, const QString& token, @@ -61,7 +79,49 @@ private: // matching callId lands. The completion arrives on the connection's IO // thread; the caller waits on another thread — m_completionMu/Cv bridge them. void ensureCompletionSub(); - QVariant awaitCompletion(const QString& callId, int timeoutMs); + // `err` (optional) receives the reason when no completion lands: the + // timeout when the deadline elapses (a deferred call that gives up is a + // timeout like any other, and used to be reported as a null result), or a + // transport error when the object is released out from under the wait. + QVariant awaitCompletion(const QString& callId, int timeoutMs, + const QString& methodName = QString(), + logos::CallError* err = nullptr); + + // Ask every in-flight waiter to give up, then join them, then return. + // + // The JOIN is what makes the waiters safe at all: they capture `this` (they + // read m_stopping and call awaitCompletion), and callMethodAsync used to + // DETACH them, so release()/delete racing an in-flight wait was a + // use-after-free. But joining alone means teardown blocks for whatever is + // left of the call's timeout — up to 20s on the protocol default — because + // a waiter has no reason to return early. Hence the stop first: it costs + // one wait slice instead, and a cancelled call still delivers its callback + // exactly once (with an error), because dropping it would turn the stall + // into a permanent hang in the caller awaiting it. + void stopAndJoinWaiters(); + // Raise the stop flag and wake anything parked on m_completionCv. Split out + // because the flag has to be published under m_completionMu (see the .cpp). + void stopWaiters(); + + // Join and drop the waiters that have already FINISHED, so a handle that + // outlives its calls does not accumulate them. TWO call sites, which + // between them cover both shapes of traffic: + // + // * every async spawn — a call pays for the corpses of earlier ones; + // * every waiter as it finishes, BEFORE it publishes its own id — so a + // burst drains itself instead of parking until the next call, which for + // a module that bursts and goes quiet may never come. + // + // NOT called from stopAndJoinWaiters(): teardown joins by id-independent + // brute force and needs no published list. (It used to say otherwise here; + // it never did.) Cheap either way: a join on an already-returned thread is + // a couple of syscalls, and only ids a waiter itself published are touched. + void reapFinishedWaiters(); + // A waiter's FINAL act — see the scope guard in callMethodAsyncWithError. + // After this returns, that thread never touches the object again, which is + // what makes it safe for someone else to join and drop it. Nothing the + // waiter does may follow it, its own reap least of all. + void publishFinishedWaiter(std::uint64_t id); std::string m_objectName; std::shared_ptr m_conn; @@ -72,6 +132,36 @@ private: std::condition_variable m_completionCv; std::map m_completions; bool m_completionSubscribed = false; + + // The waiter registry. KEYED, not a plain vector, because a thread cannot + // join itself: a waiter can therefore never retire its own entry, and a + // vector left only one moment to clear it — teardown — so every completed + // call parked a finished-but-unjoined thread (~one page of resident memory + // each) for the whole life of the handle. The production shape is one + // cached handle per module reused for every call (logos_api_consumer.cpp), + // so that grew without bound. Now a waiter publishes its id into + // m_finishedWaiters as its last act, and both the next spawn and every + // OTHER waiter on its way out join and erase it: see reapFinishedWaiters(). + // + // Retention tracks neither call count nor peak concurrency. A burst drains + // as it completes, because each waiter reaps the ones that finished before + // it. What survives an idle handle is only what published after the last + // reap — at minimum the last waiter to finish, which by construction has + // nobody behind it to collect it (measured: 1-2 after a 2000-call burst). + // The next call, or teardown, takes those. + // + // The real fix is still the TODO in callMethodAsyncWithError — fold the + // wait into the shared Asio io_context and have no thread per pending RPC + // at all. This makes the interim honest, it does not replace that. + std::mutex m_waiterMu; + std::map m_waiters; + std::vector m_finishedWaiters; + std::uint64_t m_nextWaiterId = 0; + // Read lock-free by the sliced future wait and under m_completionMu by + // awaitCompletion's predicate; written under m_completionMu so the + // condition-variable side cannot miss it. Never cleared — an object that + // has begun tearing down does not come back. + std::atomic m_stopping{false}; }; } // namespace logos::plain diff --git a/cpp/implementations/plain/plain_transport_host.cpp b/cpp/implementations/plain/plain_transport_host.cpp index b65d4dc..699c3ad 100644 --- a/cpp/implementations/plain/plain_transport_host.cpp +++ b/cpp/implementations/plain/plain_transport_host.cpp @@ -11,7 +11,10 @@ #include #include +#include +#include +#include #include #include #include @@ -210,6 +213,43 @@ PlainTransportHost::~PlainTransportHost() } if (tcp) tcp->stop(); if (ssl) ssl->stop(); + + // Quiesce the I/O thread before this host (an IncomingCallHandler) is + // destroyed. Server-side RpcConnections hold a RAW `IncomingCallHandler*` + // back to us; a read completion racing this teardown runs + // RpcConnection::fail() on the I/O thread, which calls + // m_handler->onConnectionClosed(this). stop() above closes the sockets but + // does NOT wait for an already-executing fail() — so without this barrier + // the handler can be freed mid-call (a use-after-free that surfaced as a + // flaky SIGSEGV, including on macOS CI in CallErrorAfterAcquireTest right + // after a preceding live-host test tore its PlainTransportHost down). + // There is a single shared I/O thread, so a task posted now runs only after + // every in-flight/queued connection handler has completed; blocking on it + // guarantees no callback still references this host. Skip when we're ON + // the I/O thread (the in-flight handler is our own caller) to avoid + // self-deadlock. + if (tcp || ssl) { + auto& ioc = IoContextPool::shared().ioContext(); + if (!ioc.get_executor().running_in_this_thread()) { + // The promise is shared, NOT captured by reference. The wait below is + // bounded, so on timeout this frame returns while the posted task is + // still queued — a by-reference capture would then set_value() on a + // destroyed stack object, which is the very failure mode this barrier + // exists to prevent. + auto drained = std::make_shared>(); + auto fut = drained->get_future(); + boost::asio::post(ioc, [drained] { drained->set_value(); }); + // Bounded so a wedged I/O thread cannot hang teardown — but a timeout + // means the barrier did NOT hold and we are about to free an + // IncomingCallHandler a connection may still call back into. Say so: + // silently proceeding is how this class of crash stays unexplained. + if (fut.wait_for(std::chrono::seconds(5)) != std::future_status::ready) { + qWarning() << "PlainTransportHost: I/O drain timed out after 5s;" + << "tearing down anyway — a connection callback may still" + << "reference this host (see the barrier comment above)"; + } + } + } } bool PlainTransportHost::start() diff --git a/cpp/implementations/qt_local/local_transport.cpp b/cpp/implementations/qt_local/local_transport.cpp index 55d1c3e..f271846 100644 --- a/cpp/implementations/qt_local/local_transport.cpp +++ b/cpp/implementations/qt_local/local_transport.cpp @@ -39,10 +39,12 @@ private: } // anonymous namespace -class LocalLogosObject : public LogosObject { +class LocalLogosObject : public LogosObject, public LogosObjectErrorChannel { public: - explicit LocalLogosObject(ModuleProxy* proxy) - : m_proxy(proxy), m_helper(nullptr) + // objectName is carried purely so a failure can name the module it belongs + // to (logos::CallError::origin). + LocalLogosObject(ModuleProxy* proxy, QString objectName) + : m_proxy(proxy), m_helper(nullptr), m_objectName(std::move(objectName)) { qDebug() << "[LogosObject] Created LocalLogosObject wrapping ModuleProxy" << reinterpret_cast(proxy); } @@ -52,31 +54,62 @@ public: delete m_helper; } + // Adapters over the error-carrying implementations: they discard the + // diagnosis, which is exactly what these entry points have always done. QVariant callMethod(const QString& authToken, const QString& methodName, const QVariantList& args, - int /*timeoutMs*/) override + int timeoutMs) override { - if (!m_proxy) return QVariant(); - qDebug() << "[LogosObject] LocalLogosObject::callMethod" << methodName << "args:" << args.size(); - return m_proxy->callRemoteMethod(authToken, methodName, args); + return callMethodWithError(authToken, methodName, args, timeoutMs, nullptr); } void callMethodAsync(const QString& authToken, const QString& methodName, const QVariantList& args, - int /*timeoutMs*/, + int timeoutMs, AsyncResultCallback callback) override { if (!callback) return; + callMethodAsyncWithError(authToken, methodName, args, timeoutMs, + [cb = std::move(callback)](QVariant v, const logos::CallError&) mutable { + cb(std::move(v)); + }); + } + + // In-process direct dispatch: there is no wire to drop and no deadline to + // miss, so a vanished ModuleProxy is the only failure this transport has. + QVariant callMethodWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int /*timeoutMs*/, + logos::CallError* err) override + { + if (err) err->clear(); if (!m_proxy) { - QTimer::singleShot(0, [callback]() { callback(QVariant()); }); + if (err) *err = proxyGoneError(); + return QVariant(); + } + qDebug() << "[LogosObject] LocalLogosObject::callMethod" << methodName << "args:" << args.size(); + return m_proxy->callRemoteMethod(authToken, methodName, args); + } + + void callMethodAsyncWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int /*timeoutMs*/, + AsyncResultErrorCallback callback) override + { + if (!callback) return; + if (!m_proxy) { + const logos::CallError e = proxyGoneError(); + QTimer::singleShot(0, [callback, e]() { callback(QVariant(), e); }); return; } ModuleProxy* proxy = m_proxy; QTimer::singleShot(0, [proxy, authToken, methodName, args, callback]() { QVariant result = proxy->callRemoteMethod(authToken, methodName, args); - callback(result); + callback(result, logos::CallError{}); }); } @@ -134,8 +167,16 @@ public: quintptr id() const override { return reinterpret_cast(m_proxy); } private: + logos::CallError proxyGoneError() const + { + const std::string origin = m_objectName.toStdString(); + return logos::callErrorObjectUnavailable( + origin, "module '" + origin + "' is no longer registered locally"); + } + ModuleProxy* m_proxy; EventHelper* m_helper; + QString m_objectName; }; // ── LocalTransportHost ─────────────────────────────────────────────────────── @@ -188,7 +229,7 @@ LogosObject* LocalTransportConnection::requestObject(const QString& objectName, } qDebug() << "[LogosObject] LocalTransportConnection: returning LocalLogosObject for:" << objectName; - return new LocalLogosObject(proxy); + return new LocalLogosObject(proxy, objectName); } #include "local_transport.moc" diff --git a/cpp/implementations/qt_remote/remote_transport.cpp b/cpp/implementations/qt_remote/remote_transport.cpp index 5f3560f..f95987c 100644 --- a/cpp/implementations/qt_remote/remote_transport.cpp +++ b/cpp/implementations/qt_remote/remote_transport.cpp @@ -57,10 +57,13 @@ private: } // anonymous namespace -class RemoteLogosObject : public LogosObject { +class RemoteLogosObject : public LogosObject, public LogosObjectErrorChannel { public: - explicit RemoteLogosObject(QObject* replica) - : m_replica(replica), m_helper(nullptr) + // objectName is carried purely so a failure can name the module it belongs + // to — logos::CallError::origin, the same field the acquire-time error and + // lp_invoke's out_error_json already fill in. + RemoteLogosObject(QObject* replica, QString objectName) + : m_replica(replica), m_helper(nullptr), m_objectName(std::move(objectName)) { qDebug() << "[LogosObject] Created RemoteLogosObject wrapping QRemoteObjectReplica" << reinterpret_cast(replica); if (m_replica) { @@ -96,7 +99,9 @@ public: // first (mirrors the QPointer guard in invokeRemoteMethodAsync). if (cb) QTimer::singleShot(0, m_helper, - [cb = std::move(cb), result]() { cb(result); }); + [cb = std::move(cb), result]() { + cb(result, logos::CallError{}); + }); } }); } @@ -115,13 +120,32 @@ public: } } + // Adapter over the error-carrying implementation: discards the diagnosis, + // which is exactly what this entry point has always done. QVariant callMethod(const QString& authToken, const QString& methodName, const QVariantList& args, int timeoutMs) override { + return callMethodWithError(authToken, methodName, args, timeoutMs, nullptr); + } + + QVariant callMethodWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + logos::CallError* err) override + { + if (err) err->clear(); + const std::string origin = m_objectName.toStdString(); + const std::string method = methodName.toStdString(); + if (!m_replica) { qWarning() << "RemoteLogosObject: Cannot call method on null replica"; + if (err) + *err = logos::callErrorObjectUnavailable( + origin, "replica for '" + origin + "' is gone (module unloaded" + " or transport dropped)"); return QVariant(); } qDebug() << "[LogosObject] RemoteLogosObject::callMethod" << methodName << "args:" << args.size(); @@ -139,22 +163,41 @@ public: if (!success) { qWarning() << "RemoteLogosObject: Failed to invoke callRemoteMethod on replica"; + if (err) + *err = logos::callErrorCallFailed( + origin, "replica did not accept callRemoteMethod for '" + + method + "'"); return QVariant(); } pendingCall.waitForFinished(timeoutMs); - if (!pendingCall.isFinished() || pendingCall.error() != QRemoteObjectPendingCall::NoError) { - qWarning() << "RemoteLogosObject: callRemoteMethod failed or timed out:" << pendingCall.error(); + // Two distinct outcomes that used to collapse into one empty QVariant: + // the deadline elapsed with the call still in flight (timeout), and QtRO + // itself failed the call (transport). + if (!pendingCall.isFinished()) { + qWarning() << "RemoteLogosObject: callRemoteMethod timed out"; + if (err) *err = logos::callErrorTimeout(origin, method, timeoutMs); + return QVariant(); + } + if (pendingCall.error() != QRemoteObjectPendingCall::NoError) { + qWarning() << "RemoteLogosObject: callRemoteMethod failed:" << pendingCall.error(); + if (err) + *err = logos::callErrorTransport( + origin, "QtRO call to '" + origin + "." + method + + "' failed with error " + + std::to_string(static_cast(pendingCall.error()))); return QVariant(); } // A "multi" provider may have deferred the result (returned a pending // sentinel); resolveDeferred waits for the completion event, or returns // the value unchanged for an ordinary (synchronous) result. - return resolveDeferred(pendingCall.returnValue(), timeoutMs); + return resolveDeferred(pendingCall.returnValue(), timeoutMs, methodName, err); } + // Adapter over the error-carrying implementation: discards the diagnosis, + // which is exactly what this entry point has always done. void callMethodAsync(const QString& authToken, const QString& methodName, const QVariantList& args, @@ -162,8 +205,27 @@ public: AsyncResultCallback callback) override { if (!callback) return; + callMethodAsyncWithError(authToken, methodName, args, timeoutMs, + [cb = std::move(callback)](QVariant v, const logos::CallError&) mutable { + cb(std::move(v)); + }); + } + + void callMethodAsyncWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + AsyncResultErrorCallback callback) override + { + if (!callback) return; + const std::string origin = m_objectName.toStdString(); + const std::string method = methodName.toStdString(); + if (!m_replica) { - QTimer::singleShot(0, [callback]() { callback(QVariant()); }); + const logos::CallError e = logos::callErrorObjectUnavailable( + origin, "replica for '" + origin + "' is gone (module unloaded" + " or transport dropped)"); + QTimer::singleShot(0, [callback, e]() { callback(QVariant(), e); }); return; } @@ -182,7 +244,9 @@ public: if (!success) { qWarning() << "RemoteLogosObject: Failed to invoke callRemoteMethod on replica (async)"; - QTimer::singleShot(0, [callback]() { callback(QVariant()); }); + const logos::CallError e = logos::callErrorCallFailed( + origin, "replica did not accept callRemoteMethod for '" + method + "'"); + QTimer::singleShot(0, [callback, e]() { callback(QVariant(), e); }); return; } @@ -193,41 +257,76 @@ public: auto* timer = new QTimer(watcher); timer->setSingleShot(true); + // Exactly-once gate. The finished handler and the timeout timer can + // both be queued around the same moment; without a guard that races + // into a double callback, which violates callMethodAsyncWithError's + // contract and is a latent double-free for every consumer. The same + // gate wraps the deferred-completion path so a late completion cannot + // deliver after the initial timeout already has (or vice versa). + auto delivered = std::make_shared(false); + AsyncResultErrorCallback deliverOnce = + [delivered, callback = std::move(callback)](QVariant result, + const logos::CallError& err) mutable { + if (delivered->exchange(true)) + return; + if (callback) + callback(std::move(result), err); + }; + // Success handler -- delivers result on the consumer's thread QObject::connect(watcher, &QRemoteObjectPendingCallWatcher::finished, - watcher, [this, callback, timer, timeoutMs](QRemoteObjectPendingCallWatcher* w) { + watcher, [this, deliverOnce, timer, timeoutMs, origin, method, delivered](QRemoteObjectPendingCallWatcher* w) { timer->stop(); // cancel timeout + // Timeout may already have won the race and deleteLater'd us; if + // the slot still runs, do not enter the deferred-completion path + // or we would arm a second delivery after the caller already saw + // a timeout. + if (delivered->load()) { + w->deleteLater(); + return; + } QVariant result; + logos::CallError err; if (w->error() == QRemoteObjectPendingCall::NoError) { result = w->returnValue(); } else { qWarning() << "RemoteLogosObject: async callMethod error:" << w->error(); + err = logos::callErrorTransport( + origin, "QtRO call to '" + origin + "." + method + + "' failed with error " + + std::to_string(static_cast(w->error()))); } w->deleteLater(); // A "multi" provider may have deferred the result: wait for the // completion event instead of delivering the pending sentinel. - { + if (err.ok()) { QString callId; if (logos::isPendingCallSentinel(result, &callId)) { - if (m_completions.contains(callId)) { callback(m_completions.take(callId)); return; } - m_asyncCompletionCbs.insert(callId, callback); - // Bound the wait: deliver an empty result once if it never lands. - QTimer::singleShot(timeoutMs, m_helper, [this, callId]() { + if (m_completions.contains(callId)) { + deliverOnce(m_completions.take(callId), logos::CallError{}); + return; + } + m_asyncCompletionCbs.insert(callId, deliverOnce); + // Bound the wait: a completion that never lands is a timeout, + // reported as one instead of as an empty result. + QTimer::singleShot(timeoutMs, m_helper, [this, callId, origin, method, timeoutMs]() { if (m_asyncCompletionCbs.contains(callId)) { auto cb = m_asyncCompletionCbs.take(callId); - if (cb) cb(QVariant()); + if (cb) + cb(QVariant(), + logos::callErrorTimeout(origin, method, timeoutMs)); } }); return; } } - callback(result); + deliverOnce(result, err); }, Qt::QueuedConnection); - // Timeout handler -- stops the watcher and delivers empty result - QObject::connect(timer, &QTimer::timeout, watcher, [watcher, callback]() { + // Timeout handler -- stops the watcher and reports the elapsed deadline + QObject::connect(timer, &QTimer::timeout, watcher, [watcher, deliverOnce, origin, method, timeoutMs]() { qWarning() << "RemoteLogosObject: async callMethod timed out"; - callback(QVariant()); + deliverOnce(QVariant(), logos::callErrorTimeout(origin, method, timeoutMs)); watcher->deleteLater(); // also destroys the timer (child) }); @@ -357,7 +456,9 @@ private: // Resolve a possibly-deferred result. If `rv` is a pending sentinel from a // "multi" provider, wait (up to timeoutMs) for the completion event keyed by // callId, pumping the consumer event loop; otherwise return `rv` unchanged. - QVariant resolveDeferred(const QVariant& rv, int timeoutMs) + QVariant resolveDeferred(const QVariant& rv, int timeoutMs, + const QString& methodName = QString(), + logos::CallError* err = nullptr) { QString callId; if (!logos::isPendingCallSentinel(rv, &callId)) return rv; @@ -373,6 +474,10 @@ private: m_completionWaiters.remove(callId); if (m_completions.contains(callId)) return m_completions.take(callId); qWarning() << "RemoteLogosObject: deferred call" << callId << "timed out"; + if (err) + *err = logos::callErrorTimeout(m_objectName.toStdString(), + methodName.toStdString(), + timeoutMs > 0 ? timeoutMs : 30000); return QVariant(); } @@ -383,7 +488,8 @@ private: // Touched only on the consumer event-loop thread. QHash m_completions; QHash m_completionWaiters; - QHash m_asyncCompletionCbs; + QHash m_asyncCompletionCbs; + QString m_objectName; }; // ── RemoteTransportHost ────────────────────────────────────────────────────── @@ -538,7 +644,7 @@ LogosObject* RemoteTransportConnection::requestObject(const QString& objectName, qDebug() << "[LogosObject] RemoteTransportConnection: returning RemoteLogosObject for:" << objectName; g_acquireCount.fetch_add(1, std::memory_order_relaxed); - return new RemoteLogosObject(replica); + return new RemoteLogosObject(replica, objectName); } long RemoteTransportConnection::acquireCount() { return g_acquireCount.load(std::memory_order_relaxed); } diff --git a/cpp/logos_api_consumer.cpp b/cpp/logos_api_consumer.cpp index d68581e..2c39136 100644 --- a/cpp/logos_api_consumer.cpp +++ b/cpp/logos_api_consumer.cpp @@ -141,6 +141,16 @@ QVariant LogosAPIConsumer::invokeRemoteMethod(const QString& authToken, const QS qDebug() << "[LogosObject] LogosAPIConsumer: calling via LogosObject::callMethod" << methodName; // No release() here: the handle stays cached for the next call. Released in // clearObjectCache() (destructor / reconnect) or evicted when stale. + // + // Prefer the error channel when the transport implements it (see + // LogosObjectErrorChannel in logos_object.h). Without it, `err` could only + // ever describe an ACQUIRE failure — everything that went wrong after the + // handle existed (the deadline elapsing, the connection dropping, the peer + // answering "not published") came back as a bare QVariant() with a clean + // err, i.e. reported as a method that returned null. + if (auto* channel = dynamic_cast(plugin)) + return channel->callMethodWithError(authToken, methodName, args, + timeout.ms, err); return plugin->callMethod(authToken, methodName, args, timeout.ms); } @@ -216,6 +226,23 @@ void LogosAPIConsumer::invokeRemoteMethodAsync(const QString& authToken, const Q // before the transport callback fires, the callback is silently dropped and // the handle is released by the destructor's clearObjectCache(), not here. QPointer self(this); + + // Prefer the error channel when the transport implements it. The lambda + // below used to take only `QVariant result` and hand the caller a + // hard-coded empty logos::CallError — so once acquire had succeeded, every + // async outcome was reported as a success, whatever actually happened. + if (auto* channel = dynamic_cast(plugin)) { + channel->callMethodAsyncWithError(authToken, methodName, args, timeout.ms, + [callback, self](QVariant result, const logos::CallError& err) { + if (!self) + return; + callback(std::move(result), err); + }); + return; + } + + // Transport without an error channel (the mock): unchanged behaviour — + // the value, and no diagnosis to give. plugin->callMethodAsync(authToken, methodName, args, timeout.ms, [callback, self](QVariant result) { if (!self) diff --git a/cpp/logos_call_error.h b/cpp/logos_call_error.h index 34e6564..6055c5c 100644 --- a/cpp/logos_call_error.h +++ b/cpp/logos_call_error.h @@ -16,8 +16,22 @@ namespace logos { // provider dispatch errors) without an ABI break. // // Currently produced: -// "object_unavailable" — the target module/object could not be acquired -// (not loaded, not published, or transport failure). +// "object_unavailable" — the target module/object is not there: it could not +// be acquired, or the transport answered that it is +// not published. One code for one condition, whether +// it is detected at acquire time (QtRO, which resolves +// a replica up front) or at call time (the plain wire, +// whose requestObject hands back a handle for any name +// over an open connection and only learns the truth +// from the reply). +// "timeout" — the caller's deadline elapsed with no reply. +// "transport_error" — the connection failed or was torn down mid-call. +// "call_failed" — the peer could not dispatch the call at all (as +// distinct from a provider that ran and REJECTED it, +// which answers the "dispatch_failed" envelope as its +// result value — see logos-cpp-sdk#129). +// "unauthorized" — the provider rejected our token and the one +// permitted re-exchange also failed. struct CallError { std::string code; // empty = no error std::string message; @@ -27,6 +41,59 @@ struct CallError { void clear() { code.clear(); message.clear(); origin.clear(); } }; +// --------------------------------------------------------------------------- +// Canonical constructors. +// +// Every transport that can detect one of these produces it HERE rather than +// spelling the code out at the failure site, so a caller decoding a +// {code, message, origin} object gets the same vocabulary no matter which wire +// the call went over — and so lp_invoke and lp_invoke_async, which both render +// this struct with the same makeErrorJson(), stay indistinguishable. +// --------------------------------------------------------------------------- + +inline CallError callErrorTimeout(const std::string& origin, + const std::string& method, int timeoutMs) +{ + return {"timeout", + "call to '" + origin + "." + method + "' timed out after " + + std::to_string(timeoutMs) + "ms", + origin}; +} + +inline CallError callErrorObjectUnavailable(const std::string& origin, + const std::string& detail) +{ + return {"object_unavailable", detail, origin}; +} + +inline CallError callErrorTransport(const std::string& origin, + const std::string& detail) +{ + return {"transport_error", detail, origin}; +} + +inline CallError callErrorCallFailed(const std::string& origin, + const std::string& detail) +{ + return {"call_failed", detail, origin}; +} + +// Map a plain-wire ResultMessage failure (errCode + err) onto the vocabulary +// above. The wire's codes are the transport's own spelling; this is the single +// place they are translated, so a new wire code degrades to "call_failed" +// instead of silently becoming an empty CallError (which reads as SUCCESS). +inline CallError callErrorFromWire(const std::string& origin, + const std::string& wireCode, + const std::string& message) +{ + const std::string detail = message.empty() ? wireCode : message; + if (wireCode == "MODULE_NOT_LOADED") + return callErrorObjectUnavailable(origin, detail); + if (wireCode == "TRANSPORT_CLOSED" || wireCode == "TRANSPORT_ERROR") + return callErrorTransport(origin, detail); + return callErrorCallFailed(origin, detail); +} + } // namespace logos #endif // LOGOS_CALL_ERROR_H diff --git a/cpp/logos_object.h b/cpp/logos_object.h index b3f71ba..9243ab9 100644 --- a/cpp/logos_object.h +++ b/cpp/logos_object.h @@ -1,6 +1,8 @@ #ifndef LOGOS_OBJECT_H #define LOGOS_OBJECT_H +#include "logos_call_error.h" + #include #include #include @@ -126,4 +128,71 @@ public: virtual bool isValid() const { return true; } }; +/** + * @brief Optional extension: calls that report WHY they failed. + * + * LogosObject's own callMethod/callMethodAsync answer a bare QVariant() for + * every failure — a timeout, a torn-down connection, and a module that is not + * published all look identical to a provider that legitimately returned null. + * That is the whole reason lp_invoke and lp_invoke_async could report success + * for a call that never happened. + * + * This interface is DELIBERATELY a sibling of LogosObject rather than more + * virtuals on it. LogosObject is an installed header (`include/logos_object.h`) + * whose vtable is baked into every statically-linked copy of liblogos_protocol + * in a process — one per loaded module, each pinned to its own protocol + * revision. Appending a virtual would append a vtable slot, and a caller + * compiled against the new header calling that slot on an object whose vtable + * came from an older copy is undefined behaviour. Declaring a separate + * interface and reaching it with dynamic_cast leaves LogosObject's layout, + * size and vtable byte-for-byte unchanged, so no such pairing can exist: + * a copy that does not know about this interface simply fails the cast. + * + * Consumers therefore MUST treat it as optional: + * + * if (auto* ch = dynamic_cast(obj)) + * ch->callMethodWithError(...); // real diagnosis + * else + * obj->callMethod(...); // today's behaviour, unchanged + * + * Implemented by the plain (tcp/tcp_ssl), qt_remote (QtRO) and qt_local + * transports. NOT implemented by the mock transport: MockStore always answers, + * so there is no failure to report, and leaving MockLogosObject alone keeps the + * one subclass whose header is installed (implementations/mock/mock_transport.h) + * layout-identical too. + */ +class LogosObjectErrorChannel { +public: + virtual ~LogosObjectErrorChannel() = default; + + /** + * @brief callMethod, plus the reason on failure. + * @param err Cleared on entry; set to the canonical {code, message, origin} + * on failure. May be null (then this is exactly callMethod). + * @return The method result, or an invalid QVariant on failure. + */ + virtual QVariant callMethodWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + logos::CallError* err) = 0; + + using AsyncResultErrorCallback = + std::function; + + /** + * @brief callMethodAsync, whose callback carries the reason on failure. + * + * Same delivery contract as LogosObject::callMethodAsync: the callback + * fires on a subsequent event-loop iteration, never synchronously, and + * exactly once. On success the error argument is a default-constructed + * (ok()) CallError. + */ + virtual void callMethodAsyncWithError(const QString& authToken, + const QString& methodName, + const QVariantList& args, + int timeoutMs, + AsyncResultErrorCallback callback) = 0; +}; + #endif // LOGOS_OBJECT_H diff --git a/cpp/logos_protocol.h b/cpp/logos_protocol.h index 761410c..150bce6 100644 --- a/cpp/logos_protocol.h +++ b/cpp/logos_protocol.h @@ -193,9 +193,22 @@ int lp_invoke(lp_client* client, * `cb` carries the same outcome the sync twin splits across its return code * and out-params: ok != 0 → `json` is the result JSON value; ok == 0 → `json` * is the canonical error object lp_invoke would have written to - * out_error_json (e.g. code "object_unavailable" when the target module is - * not loaded). A LP_OK return therefore means "dispatched", never "succeeded" - * — the outcome is only known in the callback. + * out_error_json. A LP_OK return therefore means "dispatched", never + * "succeeded" — the outcome is only known in the callback. + * + * WHAT ok == 0 COVERS, precisely, because "the same outcome as the sync twin" + * is a statement about PARITY and not about completeness. Reported: failure to + * acquire the target ("object_unavailable"), a call that exceeds its deadline, + * a rejected auth token, and MODULE_NOT_LOADED from a host that is up. Both + * twins report all four; neither did before. + * + * NOT reported, and it is not an oversight: an unknown method name. Every + * provider flavour answers one with a bare null, byte-identical to a method + * that legitimately returns null, so the distinction does not exist on the + * wire to be reported. Closing it needs a provider-contract change across the + * SDKs, not a transport change here. A provider's own rejection of well-formed + * arguments ("dispatch_failed") is likewise NOT folded in by either twin — it + * arrives as a result, and the generated wrappers fold it. * * Argument/handle validation still fails synchronously with * LP_ERR_INVALID_ARG and `cb` is NOT called in that case. diff --git a/tests/protocol/CMakeLists.txt b/tests/protocol/CMakeLists.txt index 587b59d..6473d88 100644 --- a/tests/protocol/CMakeLists.txt +++ b/tests/protocol/CMakeLists.txt @@ -36,6 +36,47 @@ add_executable(protocol_tests # canonical error object, a succeeding one must still report ok=1 with its # value. Both over a real (plain TCP) transport. test_lp_invoke_async_error.cpp + # The rest of that channel: everything the TRANSPORT learns once acquire has + # already succeeded — a timeout, and MODULE_NOT_LOADED against a host that is + # up (which is not an acquire failure on the plain transport, because + # requestObject never checks publication). Both were discarded by + # PlainLogosObject and by the hard-coded empty CallError above it, on the + # SYNC path as much as the async one. Matched set: the two failures must + # report the canonical error object, the successes must still report their + # value, and the one case that genuinely cannot be fixed here (an unknown + # method, which every provider answers with a bare null) is pinned as-is. + test_call_error_after_acquire.cpp + # The same channel over the DEFAULT transport (LocalSocket/QtRO), so the fix + # is not silently plain-TCP-only. Exercises the deferred-completion timeout, + # which needs no blocking provider and therefore no second event loop. + test_call_error_qt_remote.cpp + # Teardown of a PlainLogosObject with a call still IN FLIGHT. Joining the + # per-call waiters closed a use-after-free but left release() blocking for + # the remainder of the call's timeout (up to the 20s default), because + # joinWaiters() could only join, never ask a waiter to stop. Pins all three + # halves of the fix: teardown costs one wait slice, the callback still fires + # EXACTLY ONCE on every outcome including cancellation (a waiter that just + # returns turns a stall into a hang), and the join that keeps `this` alive + # under the waiter is still there. + test_plain_object_teardown.cpp + # The other half of the same mechanism: what a COMPLETED call leaves behind. + # A waiter cannot join itself, so while the registry was a plain vector the + # only thing that ever emptied it was teardown, and every finished call + # parked an unjoined thread (~one page of resident memory) for the life of + # the handle — unbounded under the cached-handle shape LogosAPIConsumer + # actually uses. Pins the registry not growing with call count, the + # reap-vs-publish race not deadlocking, and teardown still joining what is + # left. + test_plain_waiter_reaping.cpp + # The ordering rule the other two rest on: publishFinishedWaiter() is a + # waiter's LAST access to the object, which is the only reason + # stopAndJoinWaiters() can return while a reaper is still mid-join on a + # waiter it has already taken out of m_waiters. No supported caller can + # provoke the use-after-free an extra access below the publish would create, + # so this observes the accesses directly: the object is placed across a page + # boundary at m_waiterMu and its non-registry page is guarded while a waiter + # runs. + test_plain_waiter_publish_is_last.cpp # Component tests that moved here with their code (from logos-cpp-sdk) test_token_manager.cpp test_mock_store.cpp diff --git a/tests/protocol/test_call_error_after_acquire.cpp b/tests/protocol/test_call_error_after_acquire.cpp new file mode 100644 index 0000000..7302e27 --- /dev/null +++ b/tests/protocol/test_call_error_after_acquire.cpp @@ -0,0 +1,408 @@ +// The call-error channel AFTER the target has been acquired. +// +// logos-protocol#40 made lp_invoke_async able to report a failure at all, but +// only for the two conditions the layers ABOVE the transport produce: acquire +// failure ("object_unavailable") and the unauthorized sentinel. Everything the +// transport itself learns while the call is in flight was still discarded: +// +// * PlainLogosObject::callMethod / callMethodAsync answer a bare QVariant() +// for BOTH `future timed out` and `ResultMessage.ok == false` — throwing +// away res.err / res.errCode, which the wire already carries; +// * LogosAPIConsumer::invokeRemoteMethodAsync then hard-coded an empty +// logos::CallError next to that value. +// +// So once acquire succeeded, both entry points reported success no matter what +// happened. Two conditions in particular are ordinary, not exotic: +// +// * a TIMEOUT — the caller's own deadline elapsed and nothing came back; +// * MODULE NOT LOADED against a LIVE host. PlainTransportConnection:: +// requestObject never checks publication (it just constructs a handle over +// the open connection), so "the module isn't there" is NOT an acquire +// failure on this transport — it is a MODULE_NOT_LOADED ResultMessage at +// call time, and #40's object_unavailable never fires for it. +// +// These tests are a matched set and only mean something together: the two +// failures must report ok=0 / LP_ERR_UNAVAILABLE with a canonical +// {code,message,origin} object, and the successful control must still report +// ok=1 with its value — a fix that reported failure everywhere would satisfy +// the first half and break the second. +// +// Sync and async are BOTH covered because both had the identical hole: an +// async-only fix would leave lp_invoke lying while lp_invoke_async told the +// truth, which is the opposite of the parity #40 set out to establish. +// +// Everything runs against a real transport (plain TCP) and a live in-process +// PlainTransportHost, never the mock. + +#include + +#include "logos_protocol.h" + +#include "logos_provider_interface.h" +#include "logos_transport_config.h" +#include "module_proxy.h" + +#include "plain_transport_host.h" + +#include +#include +#include +#include +#include +#include +#include + +#include + +#include +#include +#include +#include +#include +#include +#include + +using namespace logos::plain; + +namespace { + +// A provider faithful to the real ones: compute() answers 7, slow() blocks +// past any sane deadline, and an UNKNOWN method answers a bare QVariant() — +// which is exactly what logos-qt-sdk's QtProviderObject and every generated +// provider dispatch do for a name they don't recognise. +class SlowProvider : public LogosProviderObject { +public: + QVariant callMethod(const QString& method, const QVariantList& args) override + { + if (method == QLatin1String("compute")) return QVariant(7); + if (method == QLatin1String("echo")) return args.value(0); + if (method == QLatin1String("slow")) { + std::this_thread::sleep_for(std::chrono::milliseconds(3000)); + return QVariant(1); + } + return QVariant(); // unknown method — indistinguishable from null + } + QJsonArray getMethods() override { return QJsonArray{}; } + bool informModuleToken(const QString&, const QString&) override { return true; } + void setEventListener(EventCallback) override {} + void init(void*) override {} + QString providerName() const override { return QStringLiteral("slow"); } + QString providerVersion() const override { return QStringLiteral("1.0.0"); } +}; + +QCoreApplication* ensureApp() +{ + static int argc = 0; + static char* argv[] = { nullptr }; + if (!QCoreApplication::instance()) + new QCoreApplication(argc, argv); + return QCoreApplication::instance(); +} + +struct Capture { + std::atomic fired{false}; + int ok = -1; + std::string json; +}; + +void captureCb(int ok, const char* json, void* user_data) +{ + auto* c = static_cast(user_data); + c->ok = ok; + c->json = json ? json : ""; + c->fired = true; +} + +bool pumpUntilFired(Capture& c, int budgetMs) +{ + QElapsedTimer timer; + timer.start(); + while (!c.fired && timer.elapsed() < budgetMs) + QCoreApplication::processEvents(QEventLoop::AllEvents, 20); + return c.fired; +} + +// A live host publishing `slow_module` through a ModuleProxy that lives on its +// OWN thread. The worker thread matters: PlainTransportHost::onCall dispatches +// to the proxy's thread, so a provider that sleeps would otherwise block the +// very event loop the consumer needs to deliver its own callback, and the test +// would measure the harness rather than the protocol. +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(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("slow_module", m_proxy); + + const QString endpoint = m_host->endpoint(); + m_port = endpoint.mid(endpoint.lastIndexOf(':') + 1).toUShort(); + } + + ~LiveHost() + { + // Order matters: tear the host down FIRST so no inbound frame can be + // dispatched to the proxy while we are dismantling it, then stop the + // proxy's thread, then delete the proxy it was serving. + m_host.reset(); + QCoreApplication::processEvents(QEventLoop::AllEvents, 50); + m_thread->quit(); + m_thread->wait(); + delete m_proxy; + delete m_thread; + } + + bool ok() const { return m_started && m_published && m_port != 0; } + + std::string target() const + { + return "{\"protocol\":\"tcp\",\"host\":\"127.0.0.1\",\"port\":" + + std::to_string(m_port) + "}"; + } + +private: + SlowProvider m_provider; + std::unique_ptr m_host; + ModuleProxy* m_proxy = nullptr; + QThread* m_thread = nullptr; + bool m_started = false; + bool m_published = false; + uint16_t m_port = 0; +}; + +// Create an lp_client for `module` at `endpoint`, with its token pre-saved so +// the capability_module handshake is skipped and only the call path is under +// test. +lp_client* clientFor(const char* module, const std::string& endpoint) +{ + lp_token_save(module, "live-token"); + return lp_client_create(module, "origin", endpoint.c_str(), endpoint.c_str()); +} + +void destroyClient(lp_client* c) +{ + lp_client_destroy(c); + QCoreApplication::processEvents(QEventLoop::AllEvents, 50); +} + +} // namespace + +class CallErrorAfterAcquireTest : public ::testing::Test { +protected: + void SetUp() override { ensureApp(); } +}; + +// ── control: a successful async call still reports its value ──────────────── +TEST_F(CallErrorAfterAcquireTest, AsyncSuccessStillReportsTheValue) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("slow_module", host.target()); + ASSERT_NE(client, nullptr); + + Capture c; + ASSERT_EQ(lp_invoke_async(client, "compute", "[]", 5000, &captureCb, &c), LP_OK); + ASSERT_TRUE(pumpUntilFired(c, 15000)) << "async callback never fired"; + + std::cout << " ASYNC success -> ok=" << c.ok << " json=" << c.json << std::endl; + + EXPECT_EQ(c.ok, 1) << "a successful async call reported failure"; + nlohmann::json v = nlohmann::json::parse(c.json, nullptr, false); + ASSERT_TRUE(v.is_number()); + EXPECT_DOUBLE_EQ(v.get(), 7.0); + + destroyClient(client); +} + +// ── the caller's deadline elapsed ─────────────────────────────────────────── +// +// The provider sleeps 3s; the call is given 600ms. Pre-fix this delivered +// ok=1 with json "null" — a timeout dressed up as a provider that returned +// nothing. +TEST_F(CallErrorAfterAcquireTest, AsyncTimeoutReportsTheError) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("slow_module", host.target()); + ASSERT_NE(client, nullptr); + + Capture c; + ASSERT_EQ(lp_invoke_async(client, "slow", "[]", 600, &captureCb, &c), LP_OK); + ASSERT_TRUE(pumpUntilFired(c, 15000)) << "async callback never fired"; + + std::cout << " ASYNC timeout -> ok=" << c.ok << " json=" << c.json << std::endl; + + EXPECT_EQ(c.ok, 0) << "a timed-out async call reported success"; + nlohmann::json e = nlohmann::json::parse(c.json, nullptr, false); + ASSERT_TRUE(e.is_object()) << "ok==0 must carry the canonical error object"; + EXPECT_EQ(e.value("code", std::string{}), "timeout"); + EXPECT_EQ(e.value("origin", std::string{}), "slow_module"); + EXPECT_FALSE(e.value("message", std::string{}).empty()); + + destroyClient(client); + // The provider is still sleeping; let it drain before the host goes away. + QElapsedTimer t; t.start(); + while (t.elapsed() < 3500) QCoreApplication::processEvents(QEventLoop::AllEvents, 50); +} + +// ── the module is not loaded, on a host that IS up ────────────────────────── +// +// The single most common real failure, and the one #40's release notes claim +// to have fixed. It does NOT go through the acquire path on this transport: +// PlainTransportConnection::requestObject hands back a handle for any name over +// an open connection, so the failure surfaces as a MODULE_NOT_LOADED +// ResultMessage at call time — which was discarded. +TEST_F(CallErrorAfterAcquireTest, AsyncModuleNotLoadedOnALiveHostReportsTheError) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("ghost_module", host.target()); + ASSERT_NE(client, nullptr); + + Capture c; + ASSERT_EQ(lp_invoke_async(client, "compute", "[]", 5000, &captureCb, &c), LP_OK); + ASSERT_TRUE(pumpUntilFired(c, 15000)) << "async callback never fired"; + + std::cout << " ASYNC not-published -> ok=" << c.ok << " json=" << c.json << std::endl; + + EXPECT_EQ(c.ok, 0) << "a call to an unpublished module reported success"; + nlohmann::json e = nlohmann::json::parse(c.json, nullptr, false); + ASSERT_TRUE(e.is_object()); + EXPECT_EQ(e.value("code", std::string{}), "object_unavailable"); + EXPECT_EQ(e.value("origin", std::string{}), "ghost_module"); + + destroyClient(client); +} + +// ── the synchronous twin had the identical hole ───────────────────────────── +TEST_F(CallErrorAfterAcquireTest, SyncSuccessStillReportsTheValue) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("slow_module", host.target()); + ASSERT_NE(client, nullptr); + + char* result = nullptr; + char* error = nullptr; + const int rc = lp_invoke(client, "compute", "[]", 5000, &result, &error); + + std::cout << " SYNC success -> rc=" << rc + << " result=" << (result ? result : "(null)") + << " error=" << (error ? error : "(null)") << std::endl; + + EXPECT_EQ(rc, LP_OK); + ASSERT_NE(result, nullptr); + EXPECT_STREQ(result, "7"); + EXPECT_EQ(error, nullptr); + + lp_string_free(result); + lp_string_free(error); + destroyClient(client); +} + +TEST_F(CallErrorAfterAcquireTest, SyncTimeoutReportsTheError) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("slow_module", host.target()); + ASSERT_NE(client, nullptr); + + char* result = nullptr; + char* error = nullptr; + const int rc = lp_invoke(client, "slow", "[]", 600, &result, &error); + + std::cout << " SYNC timeout -> rc=" << rc + << " result=" << (result ? result : "(null)") + << " error=" << (error ? error : "(null)") << std::endl; + + EXPECT_EQ(rc, LP_ERR_UNAVAILABLE) << "a timed-out sync call reported success"; + ASSERT_NE(error, nullptr) << "LP_ERR_UNAVAILABLE must carry the error object"; + nlohmann::json e = nlohmann::json::parse(error, nullptr, false); + ASSERT_TRUE(e.is_object()); + EXPECT_EQ(e.value("code", std::string{}), "timeout"); + + lp_string_free(result); + lp_string_free(error); + destroyClient(client); + QElapsedTimer t; t.start(); + while (t.elapsed() < 3500) QCoreApplication::processEvents(QEventLoop::AllEvents, 50); +} + +TEST_F(CallErrorAfterAcquireTest, SyncModuleNotLoadedOnALiveHostReportsTheError) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("ghost_module", host.target()); + ASSERT_NE(client, nullptr); + + char* result = nullptr; + char* error = nullptr; + const int rc = lp_invoke(client, "compute", "[]", 5000, &result, &error); + + std::cout << " SYNC not-published -> rc=" << rc + << " result=" << (result ? result : "(null)") + << " error=" << (error ? error : "(null)") << std::endl; + + EXPECT_EQ(rc, LP_ERR_UNAVAILABLE); + ASSERT_NE(error, nullptr); + nlohmann::json e = nlohmann::json::parse(error, nullptr, false); + ASSERT_TRUE(e.is_object()); + EXPECT_EQ(e.value("code", std::string{}), "object_unavailable"); + + lp_string_free(result); + lp_string_free(error); + destroyClient(client); +} + +// ── the residual gap, pinned deliberately ─────────────────────────────────── +// +// An UNKNOWN METHOD is NOT fixed here and cannot be at this layer: every +// provider flavour answers a bare null for a name it doesn't recognise +// (logos-qt-sdk QtProviderObject's `return QVariant()`, the generated Qt and +// cdylib dispatches' `unknown method` fall-through, the Rust provider's), which +// is byte-identical to a method that legitimately returns null. The transport +// sees ok=true with a null value and MUST report success — reporting failure +// would break every method whose return really is null. Closing it needs the +// PROVIDER contract to answer a rejection object for an unknown name, in every +// SDK, and mirrored into lp_invoke so the twins stay identical. +// +// This test asserts today's behaviour so the boundary is explicit rather than +// assumed, and so it fails loudly if a provider ever starts distinguishing. +TEST_F(CallErrorAfterAcquireTest, UnknownMethodStaysIndistinguishableFromANullReturn) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + + lp_client* client = clientFor("slow_module", host.target()); + ASSERT_NE(client, nullptr); + + Capture c; + ASSERT_EQ(lp_invoke_async(client, "noSuchMethod", "[]", 5000, &captureCb, &c), LP_OK); + ASSERT_TRUE(pumpUntilFired(c, 15000)) << "async callback never fired"; + + std::cout << " ASYNC unknown method -> ok=" << c.ok << " json=" << c.json + << " (residual gap: the provider itself answers a bare null)" + << std::endl; + + EXPECT_EQ(c.ok, 1); + EXPECT_EQ(c.json, "null"); + + destroyClient(client); +} diff --git a/tests/protocol/test_call_error_qt_remote.cpp b/tests/protocol/test_call_error_qt_remote.cpp new file mode 100644 index 0000000..5ef9864 --- /dev/null +++ b/tests/protocol/test_call_error_qt_remote.cpp @@ -0,0 +1,172 @@ +// The same call-error channel, over the DEFAULT transport. +// +// LogosProtocol::LocalSocket (qt_remote / QtRO) is the default in +// LogosTransportConfig, so it is what an in-process module host actually uses. +// test_call_error_after_acquire.cpp proves the channel over plain TCP; if the +// fix stopped there, the transport most calls go over would still be reporting +// a timed-out call as a method that returned null. +// +// The failure exercised here is a DEFERRED ("multi") call whose completion +// event never arrives: RemoteLogosObject answers the pending sentinel, arms its +// bounded wait, and gives up. That branch used to deliver a bare QVariant(); +// it now delivers a "timeout" CallError. Using the deferred path rather than a +// sleeping provider is deliberate — QtRO dispatches the source call on this +// same event loop, so a provider that blocked would stall the very loop the +// consumer needs, and the test would be measuring the harness. +// +// The assertions are made at LogosAPIConsumer::invokeRemoteMethodAsync, which +// is the site that used to hard-code `logos::CallError{}` next to every result. +// lp_invoke_async is a thin renderer over that CallError (proved end-to-end in +// test_call_error_after_acquire.cpp), so pinning it here pins the C ABI too. + +#include + +#include "logos_api_consumer.h" +#include "logos_async_dispatch.h" +#include "logos_instance.h" +#include "logos_object.h" +#include "logos_provider_interface.h" +#include "logos_transport_config.h" +#include "module_proxy.h" +#include "remote_transport.h" +#include "token_manager.h" + +#include +#include +#include +#include +#include + +#include +#include +#include +#include + +namespace { + +QCoreApplication* ensureApp() { + static int argc = 0; + static char* argv[] = { nullptr }; + if (!QCoreApplication::instance()) + new QCoreApplication(argc, argv); + return QCoreApplication::instance(); +} + +// compute() answers straight away; stall() answers the pending sentinel and +// then never pushes the completion event, so the consumer's bounded wait is +// the only thing that ends the call. +class StallProvider : public LogosProviderObject { +public: + QVariant callMethod(const QString& method, const QVariantList& /*args*/) override { + if (method == QLatin1String("compute")) return QVariant(7); + if (method == QLatin1String("stall")) { + QVariantMap sentinel; + sentinel[logos::pendingCallKey()] = QStringLiteral("never-completes"); + return sentinel; + } + return QVariant(); + } + bool informModuleToken(const QString&, const QString&) override { return true; } + QJsonArray getMethods() override { return QJsonArray{}; } + void setEventListener(EventCallback) override {} + void init(void*) override {} + QString providerName() const override { return QStringLiteral("qtro_module"); } + QString providerVersion() const override { return QStringLiteral("1.0.0"); } +}; + +} // namespace + +class QtRemoteCallErrorTest : public ::testing::Test { +protected: + void SetUp() override { ensureApp(); } + + void pumpEventLoop(int ms) { + auto end = std::chrono::steady_clock::now() + + std::chrono::milliseconds(ms); + while (std::chrono::steady_clock::now() < end) { + QCoreApplication::processEvents(); + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + } + } +}; + +// ── control: a successful QtRO async call reports its value and NO error ──── +TEST_F(QtRemoteCallErrorTest, AsyncSuccessCarriesAnEmptyError) +{ + const QString registryUrl = LogosInstance::id("qtro_ok_module"); + + RemoteTransportHost host(registryUrl); + StallProvider provider; + ModuleProxy proxy(&provider); + ASSERT_TRUE(proxy.saveToken(QStringLiteral("origin"), QStringLiteral("tok-1"))); + ASSERT_TRUE(host.publishObject("qtro_ok_module", &proxy)); + + LogosAPIConsumer consumer(QStringLiteral("qtro_ok_module"), + QStringLiteral("origin"), + &TokenManager::instance()); + ASSERT_TRUE(consumer.isConnected()); + + std::atomic delivered{0}; + QVariant got; + logos::CallError err; + consumer.invokeRemoteMethodAsync( + QStringLiteral("tok-1"), QStringLiteral("qtro_ok_module"), + QStringLiteral("compute"), QVariantList{}, + [&](QVariant v, const logos::CallError& e) { + got = std::move(v); + err = e; + delivered.fetch_add(1); + }, + Timeout(3000)); + + for (int i = 0; i < 60 && delivered.load() == 0; ++i) pumpEventLoop(50); + + std::cout << " QtRO success -> ok=" << err.ok() + << " value=" << got.toInt() << std::endl; + + ASSERT_EQ(delivered.load(), 1) << "async callback never fired"; + EXPECT_TRUE(err.ok()) << "a successful QtRO call reported error " << err.code; + EXPECT_EQ(got.toInt(), 7); +} + +// ── the deadline elapsed on the default transport ─────────────────────────── +TEST_F(QtRemoteCallErrorTest, AsyncTimeoutCarriesTheCanonicalError) +{ + const QString registryUrl = LogosInstance::id("qtro_stall_module"); + + RemoteTransportHost host(registryUrl); + StallProvider provider; + ModuleProxy proxy(&provider); + ASSERT_TRUE(proxy.saveToken(QStringLiteral("origin"), QStringLiteral("tok-1"))); + ASSERT_TRUE(host.publishObject("qtro_stall_module", &proxy)); + + LogosAPIConsumer consumer(QStringLiteral("qtro_stall_module"), + QStringLiteral("origin"), + &TokenManager::instance()); + ASSERT_TRUE(consumer.isConnected()); + + std::atomic delivered{0}; + QVariant got; + logos::CallError err; + consumer.invokeRemoteMethodAsync( + QStringLiteral("tok-1"), QStringLiteral("qtro_stall_module"), + QStringLiteral("stall"), QVariantList{}, + [&](QVariant v, const logos::CallError& e) { + got = std::move(v); + err = e; + delivered.fetch_add(1); + }, + Timeout(400)); + + for (int i = 0; i < 100 && delivered.load() == 0; ++i) pumpEventLoop(50); + + std::cout << " QtRO timeout -> code='" << err.code + << "' origin='" << err.origin + << "' message='" << err.message << "'" << std::endl; + + ASSERT_EQ(delivered.load(), 1) << "async callback never fired"; + EXPECT_EQ(err.code, "timeout") << "a timed-out QtRO call reported success"; + EXPECT_EQ(err.origin, "qtro_stall_module"); + EXPECT_FALSE(err.message.empty()); + EXPECT_FALSE(got.isValid()); +} diff --git a/tests/protocol/test_lp_invoke_async_error.cpp b/tests/protocol/test_lp_invoke_async_error.cpp index 2afdd3d..282b25b 100644 --- a/tests/protocol/test_lp_invoke_async_error.cpp +++ b/tests/protocol/test_lp_invoke_async_error.cpp @@ -207,4 +207,11 @@ TEST_F(LpInvokeAsyncErrorTest, LiveTargetStillReportsOkWithItsValue) // Let the deferred client teardown run before the host goes away. QCoreApplication::processEvents(QEventLoop::AllEvents, 50); host.reset(); + // Drain any QueuedConnection onCall invokes that PlainTransportHost + // posted to `proxy` before stop() returned. Without this, those + // slots can fire after `proxy` is destroyed at scope exit — a UAF + // that corrupts the heap and segfaults the *next* test (seen on + // macOS as CallErrorAfterAcquireTest.AsyncSuccessStillReportsTheValue + // crashing with no output of its own). + QCoreApplication::processEvents(QEventLoop::AllEvents, 50); } diff --git a/tests/protocol/test_plain_object_teardown.cpp b/tests/protocol/test_plain_object_teardown.cpp new file mode 100644 index 0000000..3e7ac7c --- /dev/null +++ b/tests/protocol/test_plain_object_teardown.cpp @@ -0,0 +1,572 @@ +// Tearing down a PlainLogosObject with a call still in flight. +// +// The branch this sits on stopped callMethodAsync from DETACHING its waiter +// thread: the waiter captures `this` (it reads m_objectName and calls +// awaitCompletion), and release() used to `delete this` underneath it. Waiters +// are now registered in m_waiters and joined before the object dies. +// +// Joining alone only trades one bug for a stall. The join-only joinWaiters() +// had no way to ASK a waiter to stop, so both of the waiter's blocking sites +// ran to their deadline: +// +// * the std::future wait in callMethodAsyncWithError, and +// * the completion-event wait in awaitCompletion (a "multi" provider's +// deferred result). +// +// Destroying a handle with an in-flight call therefore blocked for the +// remainder of that call's timeout — up to 20s on the protocol default +// (logos_mode.h Timeout). A module unloading mid-call stalls the unload for +// that long, on whichever thread called release(). +// +// What these tests pin, and why each one is here: +// +// 1. TEARDOWN LATENCY. release() with an in-flight call must return in about +// one wait slice, not one call timeout. +// +// 2. THE CALLBACK CONTRACT, which is the part a naive fix breaks. +// callMethodAsyncWithError (and lp_invoke_async above it) promise the +// callback fires EXACTLY ONCE. A waiter that simply RETURNS when asked to +// stop silently drops it — trading a bounded stall for an unbounded hang +// in any caller that awaits that callback. So the three outcomes are +// counted, not just observed: normal completion, timeout, and +// cancellation-by-teardown must each deliver exactly one callback. Zero +// and two are both failures. +// +// 3. THE UAF THAT MUST NOT COME BACK. Cancellation must not become "let the +// waiter go"; the join still has to happen. The release-during-call race +// is hammered here so an ASan/TSan build has something to catch. +// +// Everything runs against a live in-process PlainTransportHost over real TCP, +// and drives PlainLogosObject directly (PlainTransportConnection::requestObject) +// so release() is measured on its own rather than through lp_client_destroy. + +#include + +#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_transport_connection.h" +#include "plain_transport_host.h" + +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +using namespace logos::plain; + +namespace { + +// A provider with a method that parks until the test lets it go. The existing +// suites use a fixed sleep, which cannot express "in flight for as long as the +// test needs": a sleep that is shorter than the call timeout makes the future +// ready on its own and the teardown measurement then times the sleep instead of +// the timeout. +class BlockingProvider : 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 lk(m_mu); + m_cv.wait(lk, [this] { return m_released; }); + return QVariant(42); + } + // The other in-flight shape: a "multi" provider that answers the + // pending sentinel straight away and then never pushes the completion + // event, so the consumer parks in awaitCompletion instead of on the + // future. Returns immediately, so unlike `block` it holds no thread. + if (method == QLatin1String("defer")) { + QVariantMap sentinel; + sentinel[logos::pendingCallKey()] = QStringLiteral("never-completes"); + return sentinel; + } + return QVariant(); + } + + void letGo() + { + { + std::lock_guard g(m_mu); + m_released = true; + } + m_cv.notify_all(); + } + + QJsonArray getMethods() override { return QJsonArray{}; } + bool informModuleToken(const QString&, const QString&) override { return true; } + void setEventListener(EventCallback) override {} + void init(void*) override {} + QString providerName() const override { return QStringLiteral("blocker"); } + QString providerVersion() const override { return QStringLiteral("1.0.0"); } + +private: + std::mutex m_mu; + std::condition_variable m_cv; + bool m_released = false; +}; + +QCoreApplication* ensureApp() +{ + static int argc = 0; + static char* argv[] = { nullptr }; + if (!QCoreApplication::instance()) + new QCoreApplication(argc, argv); + return QCoreApplication::instance(); +} + +// A live host publishing `blocker_module` through a ModuleProxy on its own +// thread — the provider blocks, so it must not be the thread the consumer needs +// to deliver its callbacks on. +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(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("blocker_module", m_proxy); + + const QString endpoint = m_host->endpoint(); + m_port = endpoint.mid(endpoint.lastIndexOf(':') + 1).toUShort(); + } + + ~LiveHost() + { + // Anything still parked in the provider would deadlock the thread quit + // below; let every blocked (and queued) call finish first. + m_provider.letGo(); + QCoreApplication::processEvents(QEventLoop::AllEvents, 200); + m_host.reset(); + QCoreApplication::processEvents(QEventLoop::AllEvents, 50); + m_thread->quit(); + m_thread->wait(); + delete m_proxy; + delete m_thread; + } + + bool ok() const { return m_started && m_published && m_port != 0; } + uint16_t port() const { return m_port; } + BlockingProvider& provider() { return m_provider; } + +private: + BlockingProvider m_provider; + std::unique_ptr m_host; + ModuleProxy* m_proxy = nullptr; + QThread* m_thread = nullptr; + bool m_started = false; + bool m_published = false; + uint16_t m_port = 0; +}; + +// A consumer-side connection to that host. requestObject() hands back a bare +// PlainLogosObject, so release() is exercised directly. +std::unique_ptr connectTo(uint16_t port) +{ + LogosTransportConfig cfg; + cfg.protocol = LogosProtocol::Tcp; + cfg.host = "127.0.0.1"; + cfg.port = port; + auto conn = std::make_unique(cfg); + if (!conn->connectToHost()) return nullptr; + return conn; +} + +// Counts callbacks. `count` is the assertion that matters: the contract is +// EXACTLY ONE, so both 0 and 2 must fail. +struct Sink { + std::atomic count{0}; + std::mutex mu; + QVariant value; + logos::CallError err; + + std::string code() + { + std::lock_guard g(mu); + return err.code; + } + std::string message() + { + std::lock_guard g(mu); + return err.message; + } +}; + +// The callback CO-OWNS its sink. A test that fails its "the callback fired" +// assertion returns with the delivery still queued on the Qt event loop, and a +// sink captured by reference would be a dead stack frame by then — a genuine +// regression would surface as a crash in the harness instead of the clean +// assertion failure that names it. +LogosObjectErrorChannel::AsyncResultErrorCallback cbFor(std::shared_ptr sink) +{ + return [sink](QVariant v, const logos::CallError& e) { + std::lock_guard g(sink->mu); + sink->value = std::move(v); + sink->err = e; + sink->count.fetch_add(1); + }; +} + +void pump(int ms) +{ + QElapsedTimer t; + t.start(); + while (t.elapsed() < ms) + QCoreApplication::processEvents(QEventLoop::AllEvents, 10); +} + +bool pumpUntilFired(Sink& s, int budgetMs) +{ + QElapsedTimer t; + t.start(); + while (s.count.load() == 0 && t.elapsed() < budgetMs) + QCoreApplication::processEvents(QEventLoop::AllEvents, 10); + return s.count.load() > 0; +} + +LogosObjectErrorChannel* channelFor(LogosObject* obj) +{ + return dynamic_cast(obj); +} + +const char* kToken = "live-token"; + +// Long enough that a full-timeout teardown is unmistakable next to a +// one-slice one, short enough that a regression doesn't wedge CI for 20s. +constexpr int kLongTimeoutMs = 8000; + +// The budget release() must fit in. One wait slice is 25ms; this leaves an +// order of magnitude of headroom for a loaded CI box while still being ~10x +// below the call timeout above. +constexpr int kTeardownBudgetMs = 750; + +} // namespace + +class PlainObjectTeardownTest : public ::testing::Test { +protected: + void SetUp() override { ensureApp(); } +}; + +// ── 1. teardown latency ───────────────────────────────────────────────────── +// +// The provider parks forever, the call is given 8s, and then the handle is +// released. Pre-fix release() sat inside joinWaiters() until the waiter's own +// future wait hit 8000ms, because nothing could tell it to stop. +TEST_F(PlainObjectTeardownTest, ReleaseWithACallInFlightDoesNotWaitOutTheTimeout) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, + kLongTimeoutMs, cbFor(sink)); + // Let the call reach the provider and park there, so the waiter really is + // mid-wait when release() lands. + pump(200); + EXPECT_EQ(sink->count.load(), 0) << "the provider answered; nothing was in flight"; + + QElapsedTimer timer; + timer.start(); + obj->release(); + const qint64 releaseMs = timer.elapsed(); + + std::cout << " release() with an in-flight " << kLongTimeoutMs + << "ms call took " << releaseMs << "ms" << std::endl; + + EXPECT_LT(releaseMs, kTeardownBudgetMs) + << "release() waited out the call timeout instead of cancelling the waiter"; + + pumpUntilFired(*sink, 2000); + host.provider().letGo(); + pump(200); +} + +// ── 2. the callback contract, all three outcomes ──────────────────────────── + +TEST_F(PlainObjectTeardownTest, NormalCompletionFiresTheCallbackExactlyOnce) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(7) }, 5000, cbFor(sink)); + ASSERT_TRUE(pumpUntilFired(*sink, 10000)) << "the callback never fired"; + // Keep pumping: a second delivery would arrive here. + pump(300); + + std::cout << " normal completion -> callbacks=" << sink->count.load() + << " code='" << sink->code() << "'" << std::endl; + + EXPECT_EQ(sink->count.load(), 1); + EXPECT_TRUE(sink->code().empty()) << "a successful call reported an error"; + { + std::lock_guard g(sink->mu); + EXPECT_EQ(sink->value.toInt(), 7); + } + + obj->release(); +} + +TEST_F(PlainObjectTeardownTest, TimeoutFiresTheCallbackExactlyOnce) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 400, cbFor(sink)); + ASSERT_TRUE(pumpUntilFired(*sink, 10000)) << "the callback never fired"; + pump(400); + + std::cout << " timeout -> callbacks=" << sink->count.load() + << " code='" << sink->code() << "'" << std::endl; + + EXPECT_EQ(sink->count.load(), 1); + EXPECT_EQ(sink->code(), "timeout") + << "slicing the wait must not change what a real timeout reports"; + + obj->release(); + host.provider().letGo(); + pump(200); +} + +// The one a "just return on stop" fix breaks: the call is abandoned, and the +// caller must still be told — once — and told the truth. +// +// "transport_error" is the honest code. logos_call_error.h defines it as "the +// connection failed or was torn down mid-call", which is exactly this: the +// consumer tore its own end of the call channel down while the call was in +// flight. The alternatives lie about who failed — "object_unavailable" means +// the module is not there (it is, and is very likely about to answer, and +// callers re-acquire on that code), and "call_failed" blames the peer for a +// dispatch it performed perfectly well. It is also what the wire already +// reports for the same event seen from the other side: callErrorFromWire maps +// TRANSPORT_CLOSED to transport_error. +TEST_F(PlainObjectTeardownTest, CancellationByTeardownFiresTheCallbackExactlyOnce) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, + kLongTimeoutMs, cbFor(sink)); + pump(200); + ASSERT_EQ(sink->count.load(), 0); + + obj->release(); + + ASSERT_TRUE(pumpUntilFired(*sink, 2000)) + << "the cancelled call dropped its callback — the caller waits forever"; + pump(400); // a second delivery would land here + + std::cout << " cancelled by release -> callbacks=" << sink->count.load() + << " code='" << sink->code() << "' message='" << sink->message() + << "'" << std::endl; + + EXPECT_EQ(sink->count.load(), 1); + EXPECT_EQ(sink->code(), "transport_error"); + EXPECT_FALSE(sink->message().empty()); + + host.provider().letGo(); + pump(200); +} + +// ── the SECOND blocking site: the deferred-completion wait ────────────────── +// +// A waiter has two places it can be parked, and cancelling only the first would +// be half a fix. Once a "multi" provider answers the pending sentinel, the +// waiter leaves the future wait entirely and blocks in awaitCompletion on +// m_completionCv until the completion event lands or the deadline passes. The +// provider here answers the sentinel and never completes, so release() lands +// while the waiter is in that second wait — not the first. +// +// This one interrupts with no latency floor at all: it is a condition variable, +// so the stop wakes it immediately rather than at the next slice boundary. +TEST_F(PlainObjectTeardownTest, ReleaseDuringADeferredCompletionCancelsThatWaitToo) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("defer"), {}, + kLongTimeoutMs, cbFor(sink)); + // The sentinel comes back fast; this is long enough for the waiter to have + // left the future wait and be sitting in awaitCompletion. + pump(300); + ASSERT_EQ(sink->count.load(), 0) << "the deferred call completed on its own"; + + QElapsedTimer timer; + timer.start(); + obj->release(); + const qint64 releaseMs = timer.elapsed(); + + ASSERT_TRUE(pumpUntilFired(*sink, 2000)) << "the deferred call dropped its callback"; + pump(300); + + std::cout << " cancelled mid-defer -> release=" << releaseMs + << "ms callbacks=" << sink->count.load() + << " code='" << sink->code() << "'" << std::endl; + + EXPECT_LT(releaseMs, kTeardownBudgetMs) + << "release() waited out the deferred-completion deadline"; + EXPECT_EQ(sink->count.load(), 1); + EXPECT_EQ(sink->code(), "transport_error"); +} + +// A call started on an already-released... there is no such thing (release +// deletes), but a handle CAN be torn down between the call being issued and the +// waiter starting. Same contract: one callback. +TEST_F(PlainObjectTeardownTest, ReleaseImmediatelyAfterTheCallStillDeliversOnce) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, + kLongTimeoutMs, cbFor(sink)); + obj->release(); // no pump: the waiter may not even have started + + ASSERT_TRUE(pumpUntilFired(*sink, 2000)) << "callback dropped"; + pump(300); + + std::cout << " released instantly -> callbacks=" << sink->count.load() + << " code='" << sink->code() << "'" << std::endl; + + EXPECT_EQ(sink->count.load(), 1); + + host.provider().letGo(); + pump(200); +} + +// ── 3. the UAF must stay closed ───────────────────────────────────────────── +// +// The waiter must never outlive the object: it reads m_stopping and may call +// awaitCompletion (m_completionMu, m_completions) after the stop, so the join +// is what keeps `this` alive underneath it. Cancelling must not turn into +// detaching. +// +// Hammered with a varying gap between issuing the call and releasing, so the +// release lands at different points of the waiter's startup. Plain, this +// catches a dropped or doubled callback; run under a UAF detector it catches +// the freed `this` directly. Verified with macOS Guard Malloc +// (DYLD_INSERT_LIBRARIES=/usr/lib/libgmalloc.dylib): clean as written, SIGSEGV +// the moment the join is turned back into a detach. ASan/TSan are not usable +// on this toolchain — libclang_rt livelocks in its own init before main. +TEST_F(PlainObjectTeardownTest, ReleaseRacingTheWaiterIsSafeAndDeliversOnce) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + constexpr int kRounds = 60; + int delivered = 0; + QElapsedTimer total; + total.start(); + + for (int i = 0; i < kRounds; ++i) { + LogosObject* obj = conn->requestObject(QStringLiteral("blocker_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + + auto sink = std::make_shared(); + ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, + kLongTimeoutMs, cbFor(sink)); + // 0..~1.5ms of drift across the rounds, sweeping the window between + // registering the waiter and the waiter reaching its first wait. + if (i % 3 != 0) + QThread::usleep(static_cast((i % 30) * 50)); + + obj->release(); + + ASSERT_TRUE(pumpUntilFired(*sink, 3000)) << "round " << i << ": callback dropped"; + pump(20); + ASSERT_EQ(sink->count.load(), 1) << "round " << i << ": callback fired twice"; + ++delivered; + } + + const qint64 elapsed = total.elapsed(); + std::cout << " " << delivered << "/" << kRounds + << " release-during-call rounds delivered exactly once in " + << elapsed << "ms" << std::endl; + EXPECT_EQ(delivered, kRounds); + // 60 rounds x kLongTimeoutMs is 8 minutes if the stop stops working, which + // would otherwise show up only as a suite that got mysteriously slower. + // Post-fix a round costs a slice plus a round trip (~40ms), so this is an + // order of magnitude of headroom. + EXPECT_LT(elapsed, 30000) + << "rounds are waiting out call timeouts again, not cancelling"; + + host.provider().letGo(); + pump(200); +} diff --git a/tests/protocol/test_plain_waiter_publish_is_last.cpp b/tests/protocol/test_plain_waiter_publish_is_last.cpp new file mode 100644 index 0000000..2950ccf --- /dev/null +++ b/tests/protocol/test_plain_waiter_publish_is_last.cpp @@ -0,0 +1,1037 @@ +// PUBLISHING IS A WAITER'S LAST ACCESS TO THE OBJECT. +// +// Its two sibling suites pin the parts of the waiter mechanism that can be +// observed by watching what the object DOES: test_plain_object_teardown.cpp +// pins what happens to a call still in flight when the handle goes away, and +// test_plain_waiter_reaping.cpp pins that finished waiters are retired and that +// retiring them cannot deadlock. This one pins the ORDERING RULE those two rest +// on, which nothing they do can see. +// +// The rule, from plain_logos_object.cpp. A waiter's exit guard runs +// reapFinishedWaiters() and then publishFinishedWaiter(id), and the publish is +// strictly its last access to the object: +// +// struct FinishOnExit { +// ~FinishOnExit() { +// self->reapFinishedWaiters(); // others, never itself +// self->publishFinishedWaiter(id); // strictly last +// } +// }; +// +// Why that is load-bearing. reapFinishedWaiters() takes the ids waiters have +// published, ERASES those entries from m_waiters under m_waiterMu, and joins the +// threads OUTSIDE the lock. stopAndJoinWaiters() (release() / the destructor) +// swaps m_waiters under the same lock and brute-force joins whatever it got. So +// a waiter that a concurrent reaper is mid-join on is NOT in teardown's map, and +// teardown can return — with release() going straight on to `delete this` — +// while that waiter is still unwinding. stopAndJoinWaiters() says so in its own +// comment: the guarantee is not "everything is joined when this returns" but +// "no waiter touches this object after this returns". Publishing being last is +// the entire reason the second sentence is true. +// +// WHAT THIS IS AND IS NOT. It is NOT a lurking use-after-free that this file +// exposes. Be precise, because the window above was overstated in review: on +// every version of this code, a supported caller's waiters are all joined +// transitively, so "teardown returns while a reaped waiter is still unwinding" +// is not reachable. A waiter leaves m_waiters exactly two ways, and both are +// covered: +// +// * teardown takes it — and teardown joins it; +// * a reaper takes it — and that reaper is either ANOTHER WAITER, which is +// itself still registered (it reaps before it publishes), so teardown joins +// the reaper and therefore waits out the join it is in; or the ASYNC-SPAWN +// path, whose join completes before callMethodAsyncWithError returns. +// +// The one reaper nobody waits for is the spawn path racing a concurrent +// release() — i.e. a caller still issuing calls on an object another thread is +// destroying, which is caller-side UB on any version of this class and faults +// on correct code too. +// +// So publish-is-last is an invariant the DESIGN RESTS ON and documents, not a +// hole. This suite pins it against future edits — the TODO above the waiter +// (fold the wait into the shared Asio io_context) moves where reaping happens, +// which is exactly the kind of change that could add an access below the +// publish. It does not close an open bug, and nothing here should be read as +// reporting one. +// +// WHY THAT NEEDS ITS OWN MECHANISM. Because "no supported caller can provoke +// it" also means no test can provoke it, so the defect ships green: with a +// touch added after the publish, the whole of PlainObjectTeardownTest and +// PlainWaiterReapingTest passes cleanly, including under Guard Malloc. A test +// built on the unsupported race would be red on correct code, which is not a +// detector. +// +// So this suite does not race anything. It OBSERVES the accesses directly, in +// two halves, because the object splits cleanly into the state a waiter must +// never touch and the registry it exists to update. +// +// HALF ONE — the state (WaiterTouchesNothingOnTheStatePageAfterPublishing). +// +// * The object is placement-newed into an mmap'd two-page arena, positioned so +// that a page boundary falls at (or just under) m_waiterMu — i.e. the members +// teardown coordinates on (m_waiterMu, m_waiters, m_finishedWaiters, +// m_nextWaiterId, m_stopping) land on the second page and everything else +// (m_objectName, m_conn, m_mu, m_subs, the completion rendezvous) on the +// first. +// * The first page is mprotect(PROT_NONE)'d for exactly as long as a waiter is +// running, and a SIGSEGV/SIGBUS handler RECORDS each access — faulting +// address, thread, and how many ids had been published at that instant — then +// unprotects so the access proceeds. Nothing crashes; the access is +// evidence, not a punishment. The handler cannot re-arm the page itself (the +// faulting instruction would fault forever), so the OBSERVING thread does +// it: it polls the registry anyway, it never touches the guarded page, and +// without it the first legitimate access would silently disarm the detector +// for the rest of the round. +// * WHAT THE ASSERTION IS. The invariant is "no access AFTER the publish", and +// that is what gets asserted: a round starts with nothing published, so a +// recorded access stamped `published >= 1` is one this waiter made below +// publishFinishedWaiter(). It is deliberately NOT "zero accesses", because +// zero is stricter than the rule and FALSE on a correct waiter: on the +// deferred/"multi" path the waiter calls awaitCompletion(), which locks +// m_completionMu and reads m_completions and m_objectName — all on the +// guarded page, all before it publishes, all legitimate. The fourth round +// below drives exactly that path and REQUIRES at least one such access, so +// the narrowing is not a loophole: it is the difference between the two +// halves of the object's life, and both are checked. (This file asserted +// zero when it landed. It was green only because none of its rounds +// deferred; adding one turns the strict form red on correct code, which is +// how the over-strictness was found.) +// * WHERE THE DEFERRED ROUND IS WEAKER, stated because "we relaxed the +// assertion" is exactly the change that can hide a dead detector. On that +// one round the post-publish half is best-effort rather than deterministic: +// a legitimate access opens the page, the re-arm is a syscall behind, and a +// defect firing a microsecond later slips through. Measured with a read of +// m_objectName added below the publish, and every round forced to run: the +// other four catch it 5 times in 5, the deferred round 0 times in 5 — and a +// variant that spins on the re-arm instead of polling records 4-24 accesses +// per round and still catches it 0 times in 5, so this is not a tuning +// problem. +// IT COSTS NOTHING, because FinishOnExit is ONE piece of code shared by all +// five exit paths. A defect below the publish is the same defect on every +// round, and the rounds that can see it deterministically do (25/25 for the +// whole test, unchanged by the narrowing — see the table). The deferred +// round is here to keep the assertion honest about correct code, not to add +// a fifth copy of the same detection. +// +// HALF TWO — the registry (PublishedWaiterDoesNotTouchTheRegistryAgain). The +// page trick cannot cover m_waiterMu, m_waiters or m_finishedWaiters, because +// publishing has to reach them. That half is caught with bait instead; the +// method is described on the test itself. +// +// Everything is driven through a fake RpcConnectionBase, so there is no socket, +// no host, no event loop timing, and no race: the test decides exactly when the +// call's future is satisfied, which is what lets it arm the page while the +// waiter is parked and disarm it only once the waiter is gone. The two rounds +// that end on a deadline (timed out, deferred) are the exception, and they wait +// out a real clock — the budget is set so the thing that has to happen first +// takes microseconds against hundreds of milliseconds of slack, and the deferred +// round asserts that it did rather than assuming it. +// +// WHAT THE TWO HALVES DO AND DO NOT COVER, measured by rebuilding the file under +// test with each defect and running each suite 5-30 times: +// +// defect below publishFinishedWaiter() here teardown+reaping suites +// ------------------------------------ ---- ----------------------- +// read m_objectName 25/25 0/10 +// read m_conn 10/10 0/10 +// read m_completions 10/10 0/10 +// read m_completionSubscribed 10/10 0/10 +// lock m_mu 25/25 0/10 +// write m_completions under m_completionMu 25/25 - +// call reapFinishedWaiters() again 20/20 9/30 +// read m_stopping 0/10 0/10 +// (publish moved ABOVE the reap) 0/5 12/15 +// no defect 0/30 0/10 +// +// TAKE THE RIGHT-HAND COLUMN AS RATES, NOT AS FRACTIONS. Those suites catch +// these by racing, so a sample is a coin count and not a constant: the re-reap +// cell was first reported here as "2/2", which was a two-run sample printed +// beside 10-40 run samples. Over 30 runs it is 9/30, and another 30-run sample +// gave 12/30 — i.e. roughly one run in three, matching what reapFinishedWaiters' +// own comment says ("about one run in four"). The left-hand column is NOT a +// rate: those are deterministic, and anything below 1 there would be a bug in +// this file rather than bad luck. +// +// The one real gap is m_stopping, the single member that shares the registry's +// page and so cannot be guarded without guarding the publish itself. The one +// defect this suite deliberately leaves alone is the inverted order, which the +// reaping suite's hammer already catches — probabilistically, at 12 runs in 15, +// which is the other half of why observing beats racing. +// +// m_waiterMu / m_waiters / m_finishedWaiters / m_stopping stay private: they are +// reached through the same explicit-instantiation access hole the reaping suite +// uses ([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. + +#include + +#include "logos_async_dispatch.h" +#include "logos_call_error.h" + +#include "plain_logos_object.h" +#include "rpc_connection.h" + +#include +#include +#include +#include +#include + +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +using namespace logos::plain; + +namespace { + +// ── reading the waiter registry without touching the production header ────── +template +struct Rob { + friend typename Tag::type get(Tag) { return Member; } +}; + +struct PubWaitersTag { + using type = std::map PlainLogosObject::*; + friend type get(PubWaitersTag); +}; +template struct Rob; + +struct PubWaiterMuTag { + using type = std::mutex PlainLogosObject::*; + friend type get(PubWaiterMuTag); +}; +template struct Rob; + +struct PubFinishedTag { + using type = std::vector PlainLogosObject::*; + friend type get(PubFinishedTag); +}; +template struct Rob; + +struct PubStoppingTag { + using type = std::atomic PlainLogosObject::*; + friend type get(PubStoppingTag); +}; +template struct Rob; + +std::size_t memberOffset(const PlainLogosObject* obj, const void* member) +{ + return static_cast(reinterpret_cast(member) + - reinterpret_cast(obj)); +} + +// ── the access recorder ───────────────────────────────────────────────────── +// +// A guarded page plus a fault handler that logs and then lets the access +// through. Deliberately NOT a crash: a test that dies inside a waiter thread +// reports "signal 11" and nothing else, whereas the interesting part is WHICH +// member was touched and whether the touching thread had already published. + +constexpr int kMaxFaults = 64; + +struct Access { + std::uintptr_t addr = 0; + std::uintptr_t thread = 0; + std::size_t offset = 0; + std::size_t published = 0; // m_finishedWaiters.size() at fault time +}; + +std::atomic gAccessCount{0}; +Access gAccesses[kMaxFaults]; +std::atomic gGuardBase{nullptr}; +std::atomic gGuardLen{0}; +std::atomic gObjBase{nullptr}; +std::atomic gArmed{false}; // false once a fault has let one through +const std::vector* gFinished = nullptr; // on the UNguarded page +struct sigaction gOldSegv; +struct sigaction gOldBus; +bool gHandlersInstalled = false; + +void faultHandler(int /*sig*/, siginfo_t* info, void* /*uctx*/) +{ + char* const base = gGuardBase.load(std::memory_order_acquire); + const std::size_t len = gGuardLen.load(std::memory_order_acquire); + char* const addr = static_cast(info->si_addr); + + if (base == nullptr || addr < base || addr >= base + len) { + // Not our arena: put the original handlers back and return, so the + // faulting instruction re-runs and dies with its real diagnosis rather + // than looping forever in here. + sigaction(SIGSEGV, &gOldSegv, nullptr); + sigaction(SIGBUS, &gOldBus, nullptr); + return; + } + + const int i = gAccessCount.fetch_add(1, std::memory_order_acq_rel); + if (i < kMaxFaults) { + char* const objBase = gObjBase.load(std::memory_order_acquire); + gAccesses[i].addr = reinterpret_cast(addr); + gAccesses[i].thread = reinterpret_cast(pthread_self()); + gAccesses[i].offset = objBase ? static_cast(addr - objBase) : 0; + // On the registry page, which is never guarded — and with a single + // waiter in flight the only writer is the very thread stopped here. + gAccesses[i].published = gFinished ? gFinished->size() : 0; + } + // Let it through: re-arming HERE would need a single-step, since the + // faulting instruction re-runs the moment this returns and would fault + // forever. Unprotect FIRST and only then drop the armed flag, so an + // observer racing to re-arm cannot have its mprotect(PROT_NONE) overwritten + // by this one — the worst interleaving then leaves the page guarded and the + // flag set, which is the truth. + mprotect(base, len, PROT_READ | PROT_WRITE); + gArmed.store(false, std::memory_order_release); +} + +void installHandlers() +{ + if (gHandlersInstalled) return; + struct sigaction sa{}; + sa.sa_sigaction = &faultHandler; + sa.sa_flags = SA_SIGINFO; + sigemptyset(&sa.sa_mask); + ASSERT_EQ(sigaction(SIGSEGV, &sa, &gOldSegv), 0); + ASSERT_EQ(sigaction(SIGBUS, &sa, &gOldBus), 0); + gHandlersInstalled = true; +} + +void resetAccesses() { gAccessCount.store(0, std::memory_order_release); } + +int accessCount() { return gAccessCount.load(std::memory_order_acquire); } + +bool guard(bool on) +{ + char* const base = gGuardBase.load(std::memory_order_acquire); + const std::size_t len = gGuardLen.load(std::memory_order_acquire); + if (!base) return false; + if (mprotect(base, len, on ? PROT_NONE : (PROT_READ | PROT_WRITE)) != 0) + return false; + gArmed.store(on, std::memory_order_release); + return true; +} + +// Put the page back after a recorded access let one through. Called ONLY from +// the observing thread, which never touches the guarded page — from anywhere +// else this would be a way to fault on your own re-arm. +// +// Without it the detector is a ONE-SHOT per round: the first access disarms the +// page and everything after it goes unseen. That was harmless while no correct +// waiter ever touched the page, and stops being harmless the moment one +// legitimately does — the deferred round below. What it buys, honestly: the +// page is blind only from a fault until the next poll, instead of for the rest +// of the round. It is NOT enough to catch a defect that fires a microsecond +// after a legitimate access (measured — see the header), and the reason that is +// acceptable is that FinishOnExit is shared by all five rounds, four of which +// see it deterministically. Keep it anyway: any future legitimate access EARLY +// in a round would otherwise silently switch that round's detector off. +void rearmGuard() +{ + if (gArmed.load(std::memory_order_acquire)) return; + if (accessCount() >= kMaxFaults) return; // nothing left to record + guard(true); +} + +// THE ACTUAL INVARIANT: accesses made below publishFinishedWaiter(). Each round +// starts with m_finishedWaiters empty (the spawn path reaps the previous round's +// id, and the round asserts it), and one waiter runs at a time, so an access +// stamped `published >= 1` is one this waiter made after publishing its own id. +// Everything stamped 0 happened before the publish, where the object is still +// alive by construction and touching it is legal. +int postPublishAccesses(int* firstIndex = nullptr) +{ + const int n = std::min(accessCount(), kMaxFaults); + int count = 0; + for (int i = 0; i < n; ++i) { + if (gAccesses[i].published == 0) continue; + if (count == 0 && firstIndex) *firstIndex = i; + ++count; + } + return count; +} + +// ── a connection that answers exactly when the test says so ───────────────── +class ScriptedConn : public RpcConnectionBase { +public: + void start() override {} + void stop(const std::string& = "stopped") override { m_open = false; } + bool isOpen() const override { return m_open; } + + std::future sendCall(CallMessage msg) override + { + auto p = std::make_shared>(); + auto f = p->get_future(); + std::lock_guard g(m_mu); + m_pending[msg.id] = std::move(p); + m_lastId = msg.id; + return f; + } + + std::future sendMethods(MethodsMessage msg) override + { + std::promise p; + MethodsResultMessage r; + r.id = msg.id; + r.ok = true; + p.set_value(std::move(r)); + return p.get_future(); + } + + void sendSubscribe(SubscribeMessage, std::function) override {} + void sendUnsubscribe(UnsubscribeMessage) override {} + void sendEvent(EventMessage) override {} + void sendToken(TokenMessage) override {} + void setErrorHandler(ErrorHandler) override {} + std::uint64_t nextId() override { return m_nextId++; } + + std::uint64_t lastId() + { + std::lock_guard g(m_mu); + return m_lastId; + } + + // Satisfy the call's future. `ok == false` produces the wire-error shape. + void answer(std::uint64_t id, bool ok) + { + ResultMessage r; + r.id = id; + r.ok = ok; + if (ok) { + r.value = RpcValue(std::string("pong")); + } else { + r.err = "provider said no"; + r.errCode = "CALL_FAILED"; + } + deliver(id, std::move(r)); + } + + // Satisfy it with a "multi" provider's PENDING SENTINEL — ok, but the value + // says "the real result comes later, as a completion event keyed by this + // id". Nothing ever pushes that completion here (this connection has no + // event plumbing at all), so the waiter parks in awaitCompletion() until the + // call's own deadline, which is what the deferred round wants: a CORRECT + // waiter legitimately holding m_completionMu and reading m_completions and + // m_objectName — all on the guarded page — before it publishes. + void answerDeferred(std::uint64_t id, const std::string& callId) + { + RpcMap m; + m.emplace(logos::pendingCallKey().toStdString(), RpcValue(callId)); + ResultMessage r; + r.id = id; + r.ok = true; + r.value = RpcValue(std::move(m)); + deliver(id, std::move(r)); + } + +private: + void deliver(std::uint64_t id, ResultMessage r) + { + std::shared_ptr> p; + { + std::lock_guard g(m_mu); + const auto it = m_pending.find(id); + if (it == m_pending.end()) return; + p = std::move(it->second); + m_pending.erase(it); + } + p->set_value(std::move(r)); + } + + std::mutex m_mu; + std::map>> m_pending; + std::uint64_t m_lastId = 0; + std::atomic m_nextId{1}; + std::atomic m_open{true}; +}; + +// ── the arena ─────────────────────────────────────────────────────────────── +// +// Two pages. The object straddles the boundary between them, placed so that +// m_waiterMu begins exactly on the second page: page 1 is then everything the +// waiter must never touch, and page 2 is the registry it legitimately does. +class GuardedObject { +public: + GuardedObject() + { + m_pageSize = static_cast(sysconf(_SC_PAGESIZE)); + m_conn = std::make_shared(); + + // The offset of m_waiterMu, measured on a throwaway instance so the + // real one can be placed against it. + std::size_t split = 0; + { + PlainLogosObject probe("probe", m_conn); + split = memberOffset(&probe, &(probe.*get(PubWaiterMuTag{}))); + } + m_split = split; + if (m_split % alignof(PlainLogosObject) != 0) + m_split -= m_split % alignof(PlainLogosObject); + + void* mem = mmap(nullptr, m_pageSize * 2, PROT_READ | PROT_WRITE, + MAP_PRIVATE | MAP_ANONYMOUS, -1, 0); + if (mem == MAP_FAILED) return; + m_arena = static_cast(mem); + + char* const at = m_arena + m_pageSize - m_split; + m_obj = new (at) PlainLogosObject("guarded_module", m_conn); + + m_waiterMuOffset = memberOffset(m_obj, &(m_obj->*get(PubWaiterMuTag{}))); + gFinished = &(m_obj->*get(PubFinishedTag{})); + gObjBase.store(reinterpret_cast(m_obj), std::memory_order_release); + gGuardBase.store(m_arena, std::memory_order_release); + gGuardLen.store(m_pageSize, std::memory_order_release); + } + + ~GuardedObject() + { + guard(false); + gGuardBase.store(nullptr, std::memory_order_release); + gObjBase.store(nullptr, std::memory_order_release); + gFinished = nullptr; + // NOT release(): that ends in `delete this`, and this object was never + // new'd. The destructor is the same teardown minus the free. + if (m_obj) m_obj->~PlainLogosObject(); + if (m_arena) munmap(m_arena, m_pageSize * 2); + } + + // The guarded region is [obj, obj + split). What has to hold is that the + // split lands ON the page boundary and NOT past m_waiterMu — the registry + // and its mutex must stay writable, or publishing itself would fault. The + // split is the member offset rounded down to the object's alignment, so on + // a platform where m_waiterMu is not aligned to it the guard simply stops a + // few bytes of padding short, which is still correct. + bool ok() const + { + return m_obj != nullptr && m_arena != nullptr + && m_split > 0 && m_split <= m_waiterMuOffset + && reinterpret_cast(m_obj) + m_split == m_arena + m_pageSize + && sizeof(PlainLogosObject) < m_pageSize; + } + + PlainLogosObject* obj() const { return m_obj; } + ScriptedConn* conn() const { return m_conn.get(); } + std::size_t split() const { return m_split; } + std::size_t waiterMuOffset() const { return m_waiterMuOffset; } + + std::size_t waiterCount() const + { + std::lock_guard g(m_obj->*get(PubWaiterMuTag{})); + return (m_obj->*get(PubWaitersTag{})).size(); + } + + std::size_t publishedCount() const + { + std::lock_guard g(m_obj->*get(PubWaiterMuTag{})); + return (m_obj->*get(PubFinishedTag{})).size(); + } + + void forceStopping() + { + (m_obj->*get(PubStoppingTag{})).store(true, std::memory_order_release); + } + +private: + std::size_t m_pageSize = 0; + std::size_t m_split = 0; + std::size_t m_waiterMuOffset = 0; + char* m_arena = nullptr; + PlainLogosObject* m_obj = nullptr; + std::shared_ptr m_conn; +}; + +QCoreApplication* ensureAppForGuard() +{ + static int argc = 0; + static char* argv[] = { nullptr }; + if (!QCoreApplication::instance()) + new QCoreApplication(argc, argv); + return QCoreApplication::instance(); +} + +void pumpMs(int ms) +{ + QElapsedTimer t; + t.start(); + while (t.elapsed() < ms) + QCoreApplication::processEvents(QEventLoop::AllEvents, 2); +} + +// Wait — WITHOUT pumping, so nothing of ours runs on the object — until the +// waiter has published and had time to unwind past it. +// +// Doubles as the re-armer. Both things it does touch only the registry page +// (publishedCount takes m_waiterMu) or the mapping itself, never the guarded +// page, so this is the one place from which putting the guard back is safe. +bool waitForPublish(const GuardedObject& g, int budgetMs) +{ + QElapsedTimer t; + t.start(); + while (t.elapsed() < budgetMs) { + rearmGuard(); + if (g.publishedCount() > 0) return true; + QThread::usleep(200); + } + return false; +} + +// The publish is the waiter's last act, so anything it does below it lands in +// the moments right after — which is where the guard has to be up. Poll instead +// of sleeping so a page disarmed by a legitimate pre-publish access is back +// before then. +void settleGuarded(int ms) +{ + QElapsedTimer t; + t.start(); + while (t.elapsed() < ms) { + rearmGuard(); + QThread::usleep(200); + } +} + +std::string describe(const Access& a, std::size_t split, std::uintptr_t testThread) +{ + char buf[320]; + std::snprintf(buf, sizeof(buf), + "offset %zu (the guarded state page runs to %zu, where the " + "waiter registry begins), from %s thread, %zu waiter id(s) " + "already published", + a.offset, split, + a.thread == testThread ? "the TEST" : "a non-test", + a.published); + return std::string(buf); +} + +std::uintptr_t selfThread() +{ + return reinterpret_cast(pthread_self()); +} + +// A thread parked until the test lets it go — the bait a reaper picks up and +// then blocks on, which is what holds the window open in the second test. +class Gate { +public: + void wait() + { + std::unique_lock lk(m_mu); + m_cv.wait(lk, [this] { return m_open; }); + } + void open() + { + { + std::lock_guard g(m_mu); + m_open = true; + } + m_cv.notify_all(); + } + +private: + std::mutex m_mu; + std::condition_variable m_cv; + bool m_open = false; +}; + +const char* kGuardToken = "guard-token"; + +} // namespace + +class PlainWaiterPublishIsLastTest : public ::testing::Test { +protected: + void SetUp() override + { + ensureAppForGuard(); + installHandlers(); + resetAccesses(); + } +}; + +// ── 0. the detector has to be able to fire ────────────────────────────────── +// +// The whole suite is an assertion that a counter stays at zero, which is the +// shape of test that passes just as happily when the mechanism under it is +// dead. So prove the mechanism first: a deliberate read of the object's state +// page, from a thread that is not the test's, must be recorded — with the +// address, the thread, and the published-id count that the real check reads. +TEST_F(PlainWaiterPublishIsLastTest, DetectorRecordsADeliberateTouch) +{ + GuardedObject g; + ASSERT_TRUE(g.ok()) << "arena layout: split=" << g.split() + << " m_waiterMu at " << g.waiterMuOffset() + << " sizeof=" << sizeof(PlainLogosObject); + + resetAccesses(); + ASSERT_TRUE(guard(true)) << "mprotect failed: " << strerror(errno); + + std::uintptr_t toucherThread = 0; + std::thread toucher([&] { + toucherThread = reinterpret_cast(pthread_self()); + // Any byte of the state page will do; this is m_objectName's first. + volatile const char* p = reinterpret_cast(g.obj()); + (void)*p; + }); + toucher.join(); + + guard(false); + + ASSERT_GE(accessCount(), 1) + << "the guard page recorded nothing for a read that certainly happened " + "— the detector is dead and every other test in this file is vacuous"; + EXPECT_EQ(gAccesses[0].thread, toucherThread); + EXPECT_NE(gAccesses[0].thread, selfThread()); + EXPECT_EQ(gAccesses[0].offset, 0u); + std::cout << " detector live: " + << describe(gAccesses[0], g.split(), selfThread()) << std::endl; +} + +// ── 1. the invariant ──────────────────────────────────────────────────────── +// +// Five waiters: one per return out of the lambda (answered, rejected, timed out, +// cancelled) plus the deferred detour that awaitCompletion() adds to the +// answered one. Every one of them ends in the same FinishOnExit guard, and it is +// the guard that has to keep its hands off the object once it has published. +// +// Each round arms the state page only after the call has returned (the caller's +// own accesses — m_conn, m_objectName, ensureCompletionSub — are legitimate and +// happen there), and disarms it only once the waiter has published and unwound. +// For that whole window the waiter is the only thing running against the object. +// +// WHAT IS ASSERTED IS "NOTHING AFTER THE PUBLISH", not "nothing at all". Four of +// the five rounds do touch the page zero times, because objectName and method +// are copied into the closure precisely so the waiter needs nothing from the +// object. The DEFERRED round does not, and correctly so: a "multi" provider's +// pending sentinel sends the waiter into awaitCompletion(), which locks +// m_completionMu and reads m_completions and m_objectName — guarded page, before +// the publish, entirely legal. Asserting zero would make this file red on +// correct code, so it asserts what the rule actually says: no access stamped +// `published >= 1`. The deferred round then requires at least one stamped 0, so +// the looser predicate cannot be satisfied by the path simply not running. +// +// Pre-fix — i.e. with any member access added below publishFinishedWaiter — this +// records an access with published >= 1 and fails naming the offset. +TEST_F(PlainWaiterPublishIsLastTest, WaiterTouchesNothingOnTheStatePageAfterPublishing) +{ + GuardedObject g; + ASSERT_TRUE(g.ok()) << "arena layout: split=" << g.split() + << " m_waiterMu at " << g.waiterMuOffset() + << " sizeof=" << sizeof(PlainLogosObject); + + struct Round { + const char* what; + int timeoutMs; + enum { Answer, Fail, Timeout, Deferred, Cancel } how; + // Rounds where a CORRECT waiter must reach the guarded page before it + // publishes. Only the deferred path does; requiring it is what keeps + // that round from passing vacuously if it stops deferring. + bool touchesBeforePublishing; + }; + const Round rounds[] = { + { "a call that ANSWERS", 5000, Round::Answer, false }, + { "a call the provider REJECTS", 5000, Round::Fail, false }, + { "a call that TIMES OUT", 150, Round::Timeout, false }, + // The pending-sentinel path. The budget is the awaitCompletion deadline + // (no completion is ever pushed, so it runs out) and also the slack the + // future has to be satisfied in — microseconds are needed, 400ms given. + { "a DEFERRED call (pending sentinel)", 400, Round::Deferred, true }, + { "a call CANCELLED by teardown", 5000, Round::Cancel, false }, + }; + constexpr int kRounds = static_cast(sizeof(rounds) / sizeof(rounds[0])); + + int delivered = 0; + for (const Round& r : rounds) { + resetAccesses(); + + // Owned by the callback, not by this frame: a bail-out below leaves the + // waiter to be cancelled in teardown, and its callback is delivered on a + // LATER event-loop iteration — after this frame is gone. A captured + // `&got` would be a genuine use-after-free on the way out of a failing + // test, which is a poor advertisement for a file about use-after-free. + auto got = std::make_shared>(0); + g.obj()->callMethodAsyncWithError( + QString::fromLatin1(kGuardToken), QStringLiteral("ping"), + QVariantList{ QVariant(1) }, r.timeoutMs, + [got](QVariant, const logos::CallError&) { got->fetch_add(1); }); + + // The waiter is registered (that happens under m_waiterMu inside the + // call) and parked in waitForResult: nothing can satisfy its future + // until the line below. Safe to close the state page over it. + ASSERT_GT(g.waiterCount(), 0u) << r.what << ": no waiter registered"; + // The spawn path above reaps the previous round's id, so nothing is + // published as this round starts — which is what makes `published >= 1` + // mean "after THIS waiter's publish" rather than "after some earlier + // waiter's". + ASSERT_EQ(g.publishedCount(), 0u) + << r.what << ": a previous round's waiter id is still published, so " + "the after-the-publish stamp no longer means what it says"; + ASSERT_TRUE(guard(true)) << "mprotect failed: " << strerror(errno); + + switch (r.how) { + case Round::Answer: g.conn()->answer(g.conn()->lastId(), true); break; + case Round::Fail: g.conn()->answer(g.conn()->lastId(), false); break; + case Round::Timeout: break; // let the deadline elapse + case Round::Deferred: + g.conn()->answerDeferred(g.conn()->lastId(), "deferred-call-1"); + break; + case Round::Cancel: g.forceStopping(); // registry page, not guarded + break; + } + + const bool published = waitForPublish(g, 10000); + // The publish is the waiter's last act; give the thread room to unwind + // past it, which is where a stray access would land — with the guard + // kept up for all of it. + settleGuarded(30); + + const int recorded = accessCount(); + int firstAfter = 0; + const int afterPublish = postPublishAccesses(&firstAfter); + guard(false); + + EXPECT_TRUE(published) << r.what << ": the waiter never published"; + ASSERT_EQ(afterPublish, 0) + << r.what << ": the object's state page was touched AFTER this " + "waiter published its id, while only the waiter was running — " + << describe(gAccesses[firstAfter], g.split(), selfThread()) << ".\n" + << "That access is below publishFinishedWaiter() in the FinishOnExit " + "guard, and it breaks the guarantee stopAndJoinWaiters() " + "documents: a reaper joining this waiter outside m_waiterMu has " + "already taken it out of m_waiters, so teardown does not wait for " + "it and release() goes on to `delete this` while it runs. No " + "SUPPORTED caller can reach that reaper today (see the header), " + "so this is the regression test for an invariant the design " + "rests on — not the report of a live use-after-free. Publishing " + "must stay the last thing a waiter does."; + + // A round that must have gone through the guarded page has to prove it, + // or it is not testing the path it names. + if (r.touchesBeforePublishing) { + ASSERT_GT(recorded, 0) + << r.what << ": nothing on the guarded page was touched, so " + "awaitCompletion() never ran — the call did not actually " + "defer (a slow machine can turn this into a plain timeout) " + "and this round proves nothing about the deferred path"; + } else { + EXPECT_EQ(recorded, 0) + << r.what << ": the guarded page was touched at all, which on " + "this path a correct waiter never does — " + << describe(gAccesses[0], g.split(), selfThread()); + } + + // Drain the queued callback so the round is provably complete. + pumpMs(60); + delivered += got->load(); + std::cout << " " << r.what << ": published, " << recorded + << " access(es) to the state page, " << afterPublish + << " of them after the publish" << std::endl; + + if (r.how == Round::Cancel) break; // m_stopping never clears + } + + EXPECT_EQ(delivered, kRounds) + << "a callback went missing; the rounds did not all run"; +} + +// ── 2. the other half of the object: the registry itself ──────────────────── +// +// The guard page above cannot cover m_waiterMu, m_waiters or m_finishedWaiters — +// publishing has to be able to reach them. So the one access it cannot see is a +// waiter REAPING AGAIN after publishing, which is precisely the mistake +// publishFinishedWaiter's comment calls out: "Nothing the waiter does may follow +// it, its own reap least of all." +// +// Nothing else catches that either. It is invisible to the reaping suite (the +// self-join guard absorbs it into a leaked registry entry rather than a crash) +// and to the teardown suite, and racing a reaper against it catches it roughly +// one run in three — 9 in 30 measured here, 12 in 30 on another 30-run sample, +// against the "2/2" this file first printed from a two-run sample. That spread +// IS the argument for not racing: at that rate a green run means nothing, and +// the bait below is deterministic. +// +// Instead it uses the reaper's own shape against it. reapFinishedWaiters() +// joins OUTSIDE m_waiterMu, so a waiter that has picked up somebody else's +// finished thread sits in that join with the lock free — a window the test can +// hold open for as long as it likes, because the thread being joined is one the +// test planted and can keep parked: +// +// 1. plant BAIT 1 — a parked thread registered under a synthetic id, and that +// id published — while the call is still in flight; +// 2. answer the call. The waiter's exit guard reaps, takes bait 1, and parks +// in join(bait 1), holding no lock; +// 3. plant BAIT 2 the same way. There is no hurry: the waiter is parked; +// 4. release bait 1. The waiter finishes its reap and publishes; +// 5. bait 2 is now the tell. A waiter that is done never looks at the registry +// again, so bait 2 must still be registered. A waiter that reaps once more +// after publishing takes it. +// +// Bait 1 doubles as a check that the reap really does join with the lock free: +// step 3 needs m_waiterMu while the join is in progress, and says so if it +// cannot get it. +// +// A NOTE ON BAILING OUT, because the bait is a trap for the test as much as for +// the waiter. Every planted thread is parked until this test opens its gate, and +// ~PlainLogosObject joins whatever is still registered — so an early return that +// skips a gate.open() does not fail, it WEDGES. Measured on the first version of +// this test: remove the reap from the exit guard, ASSERT_TRUE(tookBait1) fires +// and prints — and then the destructor blocks forever joining a thread nobody +// will release, so the run ends as a timeout kill (exit 124) with no test result +// at all. With the gates on a scope guard the same break reports the same +// assertion and exits 1 in 10s, which is the tryWithRegistry budget and not a +// hang. +// +// Not hypothetical, either: the TODO above the waiter (fold the wait into the +// shared Asio io_context) moves where reaping happens, which is exactly the edit +// that makes tookBait1 false. So the gates are opened by a scope guard on EVERY +// exit path, and they are declared BEFORE the object so they outlive the +// teardown that joins the threads waiting on them. +TEST_F(PlainWaiterPublishIsLastTest, PublishedWaiterDoesNotTouchTheRegistryAgain) +{ + // Declared first, destroyed last: ~GuardedObject joins the planted threads, + // and a thread parked on an already-destroyed condition_variable would be + // its own use-after-free. + Gate gate1; + Gate gate2; + + GuardedObject g; + + // Destroyed BEFORE g (declared after it), so by the time the object's + // teardown joins the bait, both gates are open. A failed precondition below + // now FAILS — fast, named, with a normal exit code — instead of wedging. + struct OpenGatesOnExit { + Gate& first; + Gate& second; + ~OpenGatesOnExit() { first.open(); second.open(); } + } openGatesOnExit{gate1, gate2}; + + ASSERT_TRUE(g.ok()); + + std::mutex& mu = g.obj()->*get(PubWaiterMuTag{}); + auto& registry = g.obj()->*get(PubWaitersTag{}); + auto& finished = g.obj()->*get(PubFinishedTag{}); + + // Far above anything m_nextWaiterId will reach in this test. + constexpr std::uint64_t kBait1 = 1ull << 40; + constexpr std::uint64_t kBait2 = (1ull << 40) + 1; + + // Every registry read below is a TRY-lock: if the reap ever started joining + // with m_waiterMu held, a blocking lock here would hang the suite instead of + // reporting it. + auto tryWithRegistry = [&](const std::function& fn, int budgetMs, + bool* lockedAtLeastOnce) -> bool { + QElapsedTimer t; + t.start(); + while (t.elapsed() < budgetMs) { + std::unique_lock lk(mu, std::try_to_lock); + if (lk.owns_lock()) { + if (lockedAtLeastOnce) *lockedAtLeastOnce = true; + if (fn()) return true; + } + QThread::usleep(200); + } + return false; + }; + + auto plant = [&](std::uint64_t id, Gate& gate) { + std::lock_guard lk(mu); + registry.emplace(id, std::thread([&gate] { gate.wait(); })); + finished.push_back(id); + }; + + // 1. a call that cannot finish until the test says so. The counter is owned + // by the callback for the same reason as in the test above: on a bail-out + // this callback is delivered after the frame is gone. + auto got = std::make_shared>(0); + g.obj()->callMethodAsyncWithError( + QString::fromLatin1(kGuardToken), QStringLiteral("ping"), + QVariantList{ QVariant(1) }, 20000, + [got](QVariant, const logos::CallError&) { got->fetch_add(1); }); + + plant(kBait1, gate1); + + // 2. let it finish. Its exit guard reaps first, so it takes bait 1. + g.conn()->answer(g.conn()->lastId(), true); + + bool locked = false; + const bool tookBait1 = tryWithRegistry( + [&] { return registry.count(kBait1) == 0; }, 10000, &locked); + ASSERT_TRUE(locked) + << "m_waiterMu was never free while the waiter's reap ran — a reap that " + "joins while holding it is the deadlock reapFinishedWaiters() " + "documents"; + ASSERT_TRUE(tookBait1) + << "the waiter's exit guard never reaped the planted entry, so this " + "probe never got its window; the test needs updating, not the code"; + + // 3. the waiter is now inside join(bait 1), holding nothing. + plant(kBait2, gate2); + + // 4. release it. Reap finishes, then it publishes — and that must be that. + gate1.open(); + + const bool published = tryWithRegistry( + [&] { + for (const std::uint64_t id : finished) + if (id != kBait2) return true; + return false; + }, + 10000, nullptr); + EXPECT_TRUE(published) << "the waiter never published"; + + // 5. anything it did after publishing has had ample room to happen. + QThread::msleep(200); + + bool bait2Gone = false; + { + std::lock_guard lk(mu); + bait2Gone = registry.count(kBait2) == 0; + } + + EXPECT_FALSE(bait2Gone) + << "a waiter that had already published came back and reaped again: the " + "entry planted while it was parked mid-join is gone from m_waiters, " + "so something below publishFinishedWaiter() in the FinishOnExit guard " + "still touches the object.\n" + "That breaks the guarantee stopAndJoinWaiters() documents. A reaper " + "that has taken this waiter out of m_waiters and is joining it " + "outside the lock is not in the map stopAndJoinWaiters() swapped, so " + "teardown does not wait for it and release() goes on to `delete this` " + "while the waiter is still running. No supported caller can reach " + "that reaper today — see the header — so this is a regression test " + "for an invariant the design rests on, not the report of a live " + "use-after-free. Publishing has to stay the last thing a waiter does."; + + // Cleanup: free bait 2 whoever ended up holding it, and retire it if the + // registry still has it. + gate2.open(); + { + std::lock_guard lk(mu); + const auto it = registry.find(kBait2); + if (it != registry.end()) { + std::thread t = std::move(it->second); + registry.erase(it); + if (t.joinable()) t.join(); + } + finished.clear(); + } + + pumpMs(50); + EXPECT_EQ(got->load(), 1) << "the call did not deliver exactly once"; + std::cout << " bait planted mid-join survived the publish: the waiter never " + "came back to the registry" << std::endl; +} diff --git a/tests/protocol/test_plain_waiter_reaping.cpp b/tests/protocol/test_plain_waiter_reaping.cpp new file mode 100644 index 0000000..7b8e897 --- /dev/null +++ b/tests/protocol/test_plain_waiter_reaping.cpp @@ -0,0 +1,685 @@ +// A long-lived PlainLogosObject must not accumulate the waiters of calls that +// have already finished. +// +// Its sibling suite (test_plain_object_teardown.cpp) pins what happens to a +// waiter that is still IN FLIGHT when the handle goes away. This one pins the +// other half: what is left behind by a call that COMPLETED NORMALLY. +// +// The defect these tests exist to prevent. Waiter threads are joined rather +// than detached, because they capture `this` and release() deletes it. But a +// thread cannot join itself, so a waiter cannot retire its own entry, and while +// the registry was a plain vector the only code that ever emptied it was +// teardown. Every completed async call therefore parked a finished-but-unjoined +// std::thread for the whole life of the handle — an exited thread whose stack +// and pthread struct are not reclaimed until somebody joins it, measured at +// ~16KB resident per call on 16KiB-page arm64 (one page; expect less on 4KiB +// Linux, but the growth is the platform-independent part). The production shape +// makes that unbounded rather than academic: LogosAPIConsumer caches ONE handle +// per module and reuses it for every async call, releasing it only on eviction +// or teardown (cpp/logos_api_consumer.cpp), so 30k calls on one handle cost +// ~470MB that never comes back. +// +// What is pinned here: +// +// 1. THE REGISTRY DOES NOT GROW WITH CALL COUNT. Counting threads, not bytes: +// RSS is a noisy proxy and its per-call constant is platform-specific, +// whereas "m_waiters.size() rises 1:1 with completed calls and only ever +// falls in teardown" is the defect itself, exactly and portably. So a +// sequential caller keeps ~1 and NOT ~N. +// +// HOW NOISY, since two commit messages on this branch have now quoted a +// "bytes per call" figure off a single sample. 10k lp_invoke_async on one +// lp_client, run ten times, gave 0, 5, 5, 5, 7, 7, 8, 10, 13, 10 bytes per +// call (mean 7.0); ten more gave 3, 11, 8, 5, 8, 10, 13, 8, 3, 10 (mean +// 7.9). One distribution, range 0-13, and the "+0.09 MiB / 10 B per call" +// of 8f0c60f and the "~6 B/call" offered as its correction are both draws +// from it — neither arithmetic was wrong. THE HONEST STATEMENT IS THAT +// RETENTION IS FLAT: indistinguishable from zero, RSS noise rather than a +// per-call rate. Quote a number off one run of this and the next run will +// correct you. +// +// 1b. AND IT DRAINS WITHOUT ANOTHER CALL. Reaping on the spawn path alone +// leaves the tail of a burst parked until the next call, which for a +// module that bursts and then goes quiet may never come: 2000 completed +// calls kept ~1400 waiters and 24MiB once the handle went idle, and one +// further call dropped that to 1. Waiters therefore reap each other on +// their way out, and this pins the IDLE bound with no further spawn. +// +// 2. THE DEADLOCK THE FIX COULD INTRODUCE. Reaping means joining, and a +// reaper that joined while holding the lock a waiter needs in order to +// announce itself would wedge the process. Hammered here with reaps and +// publishes deliberately overlapped, under a watchdog so a regression is a +// named failure rather than a CI job that hangs until its timeout. +// +// 3. REAPING DOES NOT BREAK TEARDOWN. Completed calls being retired early +// must not lose the join for the one still outstanding, and the callback +// contract stays exactly-once across a run where both happen. +// +// m_waiters is private and stays private: the test reads it 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. + +#include + +#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_transport_connection.h" +#include "plain_transport_host.h" + +#include "plain_logos_object.h" + +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +using namespace logos::plain; + +namespace { + +// ── reading m_waiters without touching the production header ──────────────── +template +struct Rob { + friend typename Tag::type get(Tag) { return Member; } +}; + +struct WaitersTag { + using type = std::map PlainLogosObject::*; + friend type get(WaitersTag); +}; +template struct Rob; + +struct WaiterMuTag { + using type = std::mutex PlainLogosObject::*; + friend type get(WaiterMuTag); +}; +template struct Rob; + +// Taken under the object's OWN mutex — the one the registration path holds — +// so this is a consistent read, not a torn one. +size_t waiterCount(PlainLogosObject* obj) +{ + auto& mu = obj->*get(WaiterMuTag{}); + auto& m = obj->*get(WaitersTag{}); + std::lock_guard g(mu); + return m.size(); +} + +// Answers `ping` immediately — every call in the retention tests COMPLETES, +// which is the case that leaks — and parks on `block` until the test lets go, +// for the one place that needs a call genuinely still in flight. +class EchoProvider : 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 lk(m_mu); + m_cv.wait(lk, [this] { return m_released; }); + return QVariant(42); + } + return QVariant(); + } + + void letGo() + { + { + std::lock_guard g(m_mu); + m_released = true; + } + m_cv.notify_all(); + } + + QJsonArray getMethods() override { return QJsonArray{}; } + bool informModuleToken(const QString&, const QString&) override { return true; } + void setEventListener(EventCallback) override {} + void init(void*) override {} + QString providerName() const override { return QStringLiteral("echo"); } + QString providerVersion() const override { return QStringLiteral("1.0.0"); } + +private: + std::mutex m_mu; + std::condition_variable m_cv; + bool m_released = false; +}; + +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(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("echo_module", m_proxy); + const QString endpoint = m_host->endpoint(); + m_port = endpoint.mid(endpoint.lastIndexOf(':') + 1).toUShort(); + } + + ~LiveHost() + { + // Anything still parked in the provider would deadlock the thread quit + // below; let every blocked (and queued) call finish first. + m_provider.letGo(); + QCoreApplication::processEvents(QEventLoop::AllEvents, 100); + m_host.reset(); + QCoreApplication::processEvents(QEventLoop::AllEvents, 50); + m_thread->quit(); + m_thread->wait(); + delete m_proxy; + delete m_thread; + } + + bool ok() const { return m_started && m_published && m_port != 0; } + uint16_t port() const { return m_port; } + +private: + EchoProvider m_provider; + std::unique_ptr 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 connectTo(uint16_t port) +{ + LogosTransportConfig cfg; + cfg.protocol = LogosProtocol::Tcp; + cfg.host = "127.0.0.1"; + cfg.port = port; + auto conn = std::make_unique(cfg); + if (!conn->connectToHost()) return nullptr; + return conn; +} + +LogosObjectErrorChannel* channelFor(LogosObject* obj) +{ + return dynamic_cast(obj); +} + +// Per-call delivery counts, so "exactly once" is checked per call and not just +// in aggregate — a double delivery on one call plus a dropped one on another +// would balance out in a total. +struct Deliveries { + explicit Deliveries(int n) : counts(n) {} + std::vector> counts; + std::atomic total{0}; + std::atomic errors{0}; + + std::mutex codeMu; + std::string lastCode; + + void record(int i, const logos::CallError& e) + { + { + std::lock_guard g(codeMu); + lastCode = e.code; + } + counts[i].fetch_add(1); + total.fetch_add(1); + if (!e.code.empty()) errors.fetch_add(1); + } + std::string code() + { + std::lock_guard g(codeMu); + return lastCode; + } + int worst() const // the largest per-call count seen + { + 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 pumpUntilTotal(Deliveries& d, int target, int budgetMs) +{ + QElapsedTimer t; + t.start(); + while (d.total.load() < target && t.elapsed() < budgetMs) + QCoreApplication::processEvents(QEventLoop::AllEvents, 5); +} + +void pump(int ms) +{ + QElapsedTimer t; + t.start(); + while (t.elapsed() < ms) + QCoreApplication::processEvents(QEventLoop::AllEvents, 5); +} + +const char* kToken = "live-token"; + +// A deadlock does not fail a test, it hangs it — and a hung gtest binary is a +// CI job that dies on a timeout somewhere far from the cause. This turns that +// into a loud, attributable abort. The budget is ~50x the measured runtime of +// the hammer below, so it can only fire on a genuine wedge. +class Watchdog { +public: + Watchdog(const char* what, int budgetMs) + : m_what(what) + { + m_thread = std::thread([this, budgetMs] { + std::unique_lock lk(m_mu); + if (!m_cv.wait_for(lk, std::chrono::milliseconds(budgetMs), + [this] { return m_done; })) { + std::fprintf(stderr, + "\nWATCHDOG: '%s' made no progress for %dms — the reaper is " + "deadlocked against a waiter trying to publish.\n", + m_what, budgetMs); + std::fflush(stderr); + std::abort(); + } + }); + } + ~Watchdog() + { + { + std::lock_guard g(m_mu); + m_done = true; + } + m_cv.notify_all(); + m_thread.join(); + } + +private: + const char* m_what; + std::mutex m_mu; + std::condition_variable m_cv; + bool m_done = false; + std::thread m_thread; +}; + +} // namespace + +class PlainWaiterReapingTest : public ::testing::Test { +protected: + void SetUp() override { ensureApp(); } +}; + +// ── 1. the registry does not grow with call count ─────────────────────────── +// +// One handle, N completed calls, issued strictly sequentially: each callback is +// awaited before the next call goes out, which is both the realistic shape and +// the harshest one for the claim — with at most one call ever in flight, a +// correct implementation keeps ~1 waiter no matter how large N is. +// +// Pre-fix this ends at N. +TEST_F(PlainWaiterReapingTest, SequentialCompletedCallsDoNotAccumulateWaiters) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("echo_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + auto* plain = dynamic_cast(obj); + ASSERT_NE(plain, nullptr) << "the plain transport must hand back a PlainLogosObject"; + + constexpr int kCalls = 200; + Deliveries d(kCalls); + + size_t peak = 0; + for (int i = 0; i < kCalls; ++i) { + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(i) }, 5000, + [&d, i](QVariant, const logos::CallError& e) { + d.record(i, e); + }); + pumpUntilTotal(d, i + 1, 10000); + ASSERT_EQ(d.total.load(), i + 1) << "call " << i << " never delivered"; + peak = std::max(peak, waiterCount(plain)); + } + + const size_t finalCount = waiterCount(plain); + std::cout << " " << kCalls << " sequential completed calls -> m_waiters peak=" + << peak << " final=" << finalCount << std::endl; + + EXPECT_EQ(d.errors.load(), 0) << "a completed call reported an error"; + EXPECT_EQ(d.worst(), 1) << "a callback fired more than once"; + EXPECT_EQ(d.missing(), 0) << "a callback never fired"; + + // The bound that matters is "does not scale with kCalls". 8 is generous + // headroom over the 1-2 this actually keeps (the current call's waiter, and + // at most the previous one if it published after the current spawn reaped), + // while still being 25x below the kCalls this fails at when nothing prunes. + EXPECT_LE(finalCount, 8u) + << "finished waiters are accumulating: " << finalCount << " left after " + << kCalls << " completed calls"; + EXPECT_LE(peak, 8u) << "the registry grew during the run"; + + obj->release(); + pump(50); +} + +// The same claim with calls in flight concurrently: the bound is then peak +// concurrency, since a waiter can only be reaped once it has finished. What must +// still hold is that it does not scale with the number of CALLS. +TEST_F(PlainWaiterReapingTest, ConcurrentCompletedCallsStayBoundedByInFlight) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("echo_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + auto* plain = dynamic_cast(obj); + ASSERT_NE(plain, nullptr); + + constexpr int kCalls = 600; + constexpr int kInflight = 8; + Deliveries d(kCalls); + + size_t peak = 0; + int issued = 0; + while (issued < kCalls) { + while (issued < kCalls && (issued - d.total.load()) < kInflight) { + const int i = issued++; + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(i) }, 5000, + [&d, i](QVariant, const logos::CallError& e) { + d.record(i, e); + }); + } + peak = std::max(peak, waiterCount(plain)); + pumpUntilTotal(d, issued - kInflight + 1, 10000); + } + pumpUntilTotal(d, kCalls, 20000); + pump(200); // a duplicate delivery would land here + + const size_t finalCount = waiterCount(plain); + std::cout << " " << kCalls << " calls at " << kInflight + << " in flight -> m_waiters peak=" << peak + << " final=" << finalCount << std::endl; + + EXPECT_EQ(d.total.load(), kCalls); + EXPECT_EQ(d.worst(), 1); + EXPECT_EQ(d.missing(), 0); + EXPECT_EQ(d.errors.load(), 0); + + // Bounded by the in-flight window plus the slack of one reap cycle — not by + // kCalls, which is what it reaches when finished waiters are never dropped. + EXPECT_LE(finalCount, size_t(4 * kInflight)) + << "finished waiters accumulated past the in-flight window"; + EXPECT_LE(peak, size_t(4 * kInflight)); + + obj->release(); + pump(50); +} + +// ── 1b. a burst that goes idle drains itself ──────────────────────────────── +// +// The test above always has another call coming, which hides the case that +// actually shows up in production: a module bursts, every call completes, and +// then the handle goes quiet. If reaping only ever happened on the spawn path, +// everything that finished after the LAST spawn would stay parked for the life +// of the handle — measured at 1428 waiters and +24MiB after 2000 completed +// calls, collapsing to 1 the moment one further call was issued. That figure is +// race-dependent, not a constant: a re-measure of the same build gave 1421 (and +// 599 rather than 610 for the 800-call burst below). Same magnitude, different +// number every time — which is the point of asserting a bound and not a value. +// +// So the bound is read here with NO further call: the burst has to have drained +// itself. What remains is what published after the last reap — at minimum the +// last waiter to finish, which has nobody behind it to collect it (1 in almost +// every run, 2 when a waiter's publish slips past the final reap). The bound +// below is generous against that and still ~100x under the pre-fix number. +TEST_F(PlainWaiterReapingTest, BurstThatGoesIdleDrainsWithoutAnotherCall) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("echo_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + auto* plain = dynamic_cast(obj); + ASSERT_NE(plain, nullptr); + + // Issued in one go, with no pumping in between, so they really are + // concurrent and the tail of the burst is large. + constexpr int kBurst = 800; + Deliveries d(kBurst); + for (int i = 0; i < kBurst; ++i) { + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(i) }, 9000, + [&d, i](QVariant, const logos::CallError& e) { + d.record(i, e); + }); + } + pumpUntilTotal(d, kBurst, 60000); + ASSERT_EQ(d.total.load(), kBurst) << "the burst did not all complete"; + + // Every callback has landed; now let the waiters that delivered them finish + // and retire each other. No call is issued in this window — that is the + // whole point — so anything still registered is retained, not in flight. + for (int i = 0; i < 40; ++i) { + QCoreApplication::processEvents(QEventLoop::AllEvents, 5); + QThread::msleep(10); + } + + const size_t idle = waiterCount(plain); + std::cout << " " << kBurst << " completed calls then IDLE -> m_waiters=" + << idle << std::endl; + + EXPECT_EQ(d.worst(), 1); + EXPECT_EQ(d.missing(), 0); + EXPECT_EQ(d.errors.load(), 0); + EXPECT_LE(idle, 8u) + << "a burst that went idle left " << idle << " of " << kBurst + << " waiters parked: they are only being reaped on the spawn path"; + + // And the handle still works afterwards — draining from inside the waiters + // must not have disturbed the object they are draining. + Deliveries after(1); + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(7) }, 5000, + [&after](QVariant, const logos::CallError& e) { + after.record(0, e); + }); + pumpUntilTotal(after, 1, 10000); + EXPECT_EQ(after.total.load(), 1); + EXPECT_EQ(after.errors.load(), 0); + EXPECT_LE(waiterCount(plain), 8u); + + obj->release(); + pump(50); +} + +// ── 2. the deadlock the fix could introduce ───────────────────────────────── +// +// A waiter announces itself as finished under m_waiterMu; the reaper takes that +// list under the same lock and then JOINS. If it joined while still holding the +// lock, a waiter blocked on that lock trying to announce itself would never +// return and the join would never complete — a two-thread deadlock, taking out +// the caller's thread (in production, usually the Qt event loop). +// +// So the two are deliberately overlapped: every spawn reaps, and the calls are +// short enough that waiters are finishing while later ones are being registered. +// The watchdog turns a wedge into an abort that names the cause. +TEST_F(PlainWaiterReapingTest, ReapingRacesPublishingWithoutDeadlocking) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + constexpr int kRounds = 40; + constexpr int kPerRound = 40; + constexpr int kCalls = kRounds * kPerRound; + // ~2s in practice; 60s can only be reached by a genuine wedge. + Watchdog watchdog("ReapingRacesPublishingWithoutDeadlocking", 60000); + + LogosObject* obj = conn->requestObject(QStringLiteral("echo_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + auto* plain = dynamic_cast(obj); + ASSERT_NE(plain, nullptr); + + Deliveries d(kCalls); + QElapsedTimer total; + total.start(); + + int issued = 0; + for (int r = 0; r < kRounds; ++r) { + // A burst with no pumping between the calls: the earlier waiters of the + // burst finish (and publish) while the later ones are still being + // registered and reaping, so publish and reap collide inside the burst. + for (int k = 0; k < kPerRound; ++k) { + const int i = issued++; + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(i) }, 5000, + [&d, i](QVariant, const logos::CallError& e) { + d.record(i, e); + }); + } + // Varying drift, so the burst boundary lands at different points of the + // previous burst's completion — sometimes reaping nothing, sometimes + // reaping a batch that is still growing under it. + if (r % 4 != 0) + QThread::usleep(static_cast((r % 17) * 60)); + pumpUntilTotal(d, issued - kPerRound, 20000); + } + pumpUntilTotal(d, kCalls, 30000); + pump(200); + + const qint64 elapsed = total.elapsed(); + std::cout << " " << kCalls << " calls across " << kRounds + << " bursts in " << elapsed << "ms, m_waiters=" + << waiterCount(plain) << std::endl; + + EXPECT_EQ(d.total.load(), kCalls) << "callbacks went missing under the race"; + EXPECT_EQ(d.worst(), 1) << "a callback fired more than once under the race"; + EXPECT_EQ(d.missing(), 0); + EXPECT_LE(waiterCount(plain), size_t(4 * kPerRound)) + << "the registry grew across the bursts"; + + obj->release(); + pump(50); +} + +// ── 3. reaping must not cost teardown its join ────────────────────────────── +// +// Completed calls being retired early must not disturb the outstanding one: the +// object is released while a call is still in flight, after many others have +// already been reaped. release() must stay fast (it cancels rather than waiting +// the timeout out) and the abandoned call must still deliver, once. +TEST_F(PlainWaiterReapingTest, TeardownAfterReapingStillJoinsAndDeliversOnce) +{ + LiveHost host; + ASSERT_TRUE(host.ok()); + auto conn = connectTo(host.port()); + ASSERT_NE(conn, nullptr); + + LogosObject* obj = conn->requestObject(QStringLiteral("echo_module"), 5000); + ASSERT_NE(obj, nullptr); + auto* ch = channelFor(obj); + ASSERT_NE(ch, nullptr); + auto* plain = dynamic_cast(obj); + ASSERT_NE(plain, nullptr); + + constexpr int kWarm = 100; + Deliveries warm(kWarm); + for (int i = 0; i < kWarm; ++i) { + ch->callMethodAsyncWithError(kToken, QStringLiteral("ping"), + QVariantList{ QVariant(i) }, 5000, + [&warm, i](QVariant, const logos::CallError& e) { + warm.record(i, e); + }); + pumpUntilTotal(warm, i + 1, 10000); + } + ASSERT_EQ(warm.total.load(), kWarm); + ASSERT_LE(waiterCount(plain), 8u) << "the warmup calls were not reaped"; + + // Now release with a call that REALLY is outstanding: `block` parks in the + // provider until the host is torn down, so the waiter is unambiguously + // mid-wait when release() lands, rather than racing a `ping` that may have + // already answered. + Deliveries last(1); + ch->callMethodAsyncWithError(kToken, QStringLiteral("block"), {}, 8000, + [&last](QVariant, const logos::CallError& e) { + last.record(0, e); + }); + pump(200); + ASSERT_EQ(last.total.load(), 0) << "the provider answered; nothing was in flight"; + + QElapsedTimer timer; + timer.start(); + obj->release(); + const qint64 releaseMs = timer.elapsed(); + + pumpUntilTotal(last, 1, 3000); + pump(300); // a second delivery would land here + + std::cout << " release() after " << kWarm << " reaped calls took " + << releaseMs << "ms, in-flight call delivered " + << last.total.load() << " time(s) code='" << last.code() << "'" + << std::endl; + + EXPECT_LT(releaseMs, 750) + << "release() waited out the in-flight call instead of cancelling it"; + // The join that keeps `this` alive under the waiter is still there, and the + // abandoned call is still told — once. Reaping the finished waiters must + // change neither. + EXPECT_EQ(last.total.load(), 1) << "the in-flight call did not deliver exactly once"; + EXPECT_EQ(last.code(), "transport_error"); + EXPECT_EQ(warm.worst(), 1); +}