Files
logos-view-module-runtime/tests/test_2proc_bridge_driver.cpp
Dario LipicarandClaude Opus 5 31bbfad97b fix(qml-bridge): defer onModuleEvent instead of refusing it once (#20)
* fix(qml-bridge): defer onModuleEvent instead of refusing it once

A QML plugin subscribes in Component.onCompleted, which runs while the
view is being built -- in Basecamp that is immediately after
PluginLoader spawned the core dependency's host process and well before
that process called listen(). onModuleEvent asked `isConnected()`
anyway, warned once, returned false, and never tried again for the life
of the process. Method calls kept working (they reach the replica by a
path that never asks), so this read as "QML events are broken".

The measured shape, on Windows but platform-independent:

    RemoteTransportConnection: Registry connect attempt started
    LogosQmlBridge::onModuleEvent: "hello_module" not connected   <- same ms
    ... 45 s later ...
    RemoteTransportConnection: Requesting object: "hello_module"  <- the CALL works

Now: no isConnected() probe, no requestObject(), nothing on this path
that can block the GUI thread. The subscription goes to
LogosAPIClient::onEventWhenAvailable and arms when the module becomes
reachable, including a module installed mid-session by the package
manager.

Return-value contract: true now means ACCEPTED, not live. false is kept
only for errors no retry can fix -- no LogosAPI (the existing null-API
test still asserts that), an empty name, or a VIEW module (whose signals
come off its typed replica). Every caller in the workspace was checked:
nothing in production reads the value; the only site that did was
test_2proc_bridge_driver, whose "first subscription proves the
connection is up" probe is replaced by pendingEventSubscriptions()
draining.

De-duplication lives here rather than in the transport, because
lp_subscribe legitimately allows two subscriptions to one event while
QML re-running Component.onCompleted must not double-deliver.

tests/test_logos_qml_bridge_deferred.cpp is the regression guard:
subscribe-before-publish (the bug), publish-before-subscribe (control,
green either way), duplicate-subscribe (was delivering twice), and a
non-blocking budget so a future "just call requestObject() from the
retry" cannot creep back in.

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

* fix(qml-bridge): verify the de-dupe record instead of trusting it

onModuleEvent kept a set of (module, event) pairs it had already subscribed and
short-circuited on it. The set was only ever cleared on the abandon path, so any
other way a subscription could stop being tracked left the bridge believing it
was live: a QML view re-calling logos.onModuleEvent got `true` back and nothing
armed — a permanently silent success, which is the original bug wearing the
fix's clothes.

It now records the subscription id and checks it against
LogosAPIClient::eventSubscriptionState() before short-circuiting. Unknown means
the registry is not tracking it, so the call falls through and re-arms.

Also states on the API what it does not promise: arming is not retroactive and
no transport buffers, so a module that emits a one-shot event synchronously
inside its own init() can still be missed by a view subscribing in
Component.onCompleted.

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

* test(qml-bridge): make the stale-record case actually reproduce the defect

The first version cancelled an ARMED subscription, which by design leaves its
callback attached to the shared handle -- so events kept arriving and the test
passed against the trusting-the-record version too. It now makes the record
stale while the subscription is still PENDING, where nothing is attached, so a
re-subscribe that gets swallowed as a duplicate delivers nothing and the test
goes red. Asserts the cancel hit the right id rather than assuming it.

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

* docs(qml-bridge): answer the three review comments on onModuleEvent

All three were right.

The VIEW-module warning was streamed across << operands with embedded quotes,
and QDebug quotes every QString it is given -- so the one part of the message a
reader is meant to copy came out as logos.module(" "chat_module" "). One
formatted string with noquote(), and the reason recorded at the call site,
because the streamed form looks correct in the source. Deliberately not applied
to the sibling warnings, where << moduleName << eventName WANTS the quoting: it
is what tells an empty name from a missing one.

The "roughly 50-150 ms" arming window was measured on one machine and read as a
contract. Now described as brief and load-dependent, which keeps the two facts a
caller can act on and drops the one they cannot rely on. The advice underneath
is unchanged and is what matters: a module whose one-shot startup event matters
must also expose a method the view can call after subscribing.

The return contract listed three cases; the implementation has five. Both
missing ones are documented rather than tightened away -- "no client for the
module" is LogosAPI failing to build one at all, not the module being down, and
the id == 0 refusal is a guard whose only job is keeping two contracts in
agreement. Deleting it would remove the thing that notices when they stop
agreeing. The comment now also states what was implicit and matters more than
the list: a module that is merely unreachable is still an ACCEPTANCE.

Comment-only apart from the warning's formatting.

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

* chore(deps): re-pin logos-protocol to 07b0fb1 (#47)

This branch calls onEventWhenAvailable, cancelEventSubscription,
eventSubscriptionState and pendingEventSubscriptions. The lock pinned 0f26ffd,
which has none of them, so every green run of this branch until now was produced
with --override-input and the lock itself had never resolved.

07b0fb1 is #47's merge commit. Its narHash is identical to the branch tip the
bridge was verified against, so this pin is byte-for-byte the tree those runs
used, not merely a compatible one.

VERIFIED FROM THE LOCK, which is the part that was missing:

    nix build 'path:./#checks.aarch64-darwin.default'    # no override of any kind
    100% tests passed, 0 tests failed out of 6

Driving the repo's OWN flake matters here. Building the workspace flake's
logos-view-module-runtime target does not test this lock at all: the workspace
supplies logos-protocol to every consumer through `follows`, so it answers a
different question and will happily go green (or red) on a pin this repo does not
use. The first attempt at this verification made exactly that mistake and failed
with "no member named 'onEventWhenAvailable'" while the lock was already correct.

Note the closure still holds two logos-protocol revisions: root and logos-qt-sdk
resolve to 07b0fb1, while logos-cpp-sdk keeps its own, because only qt-sdk
declares `inputs.logos-protocol.follows`. That is the configuration verified
above and it builds clean. Adding the missing follows to logos-cpp-sdk would
collapse it to one revision and is worth doing -- separately, since it changes a
configuration nothing has tested yet.

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

---------

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
2026-08-10 14:06:21 -03:00

176 lines
7.0 KiB
C++

// Process B of the 2-process reproduction: the "parent basecamp" side. Runs the
// LogosQmlBridge on a shared LogosAPI and drives sync/async/fan-out call chains
// through a QJSEngine — but the echo + capability modules live in a SEPARATE
// process (spawned host, process A), so every call crosses the process boundary
// over QtRO, with the two event loops fully independent. This is the one factor
// no in-process harness could reproduce.
//
// Usage: test_2proc_bridge_driver <path-to-modules-host> [chains...]
// chains default to: sync async fanout
// Env passthrough to the host: LOGOS_FIRE_EVENTS, LOGOS_ROTATE_TOKENS.
#include "LogosQmlBridge.h"
#include "logos_api.h"
#include "token_manager.h"
#include "logos_instance.h"
#include "logos_mode.h"
#include <QCoreApplication>
#include <QElapsedTimer>
#include <QJSEngine>
#include <QJSValue>
#include <QProcess>
#include <QString>
#include <QStringList>
#include <QTextStream>
#include <memory>
static QTextStream out(stdout);
static QTextStream err(stderr);
// Build a fresh bridge on its own LogosAPI, subscribe N events, then run one
// call chain of the given kind. Returns how many of N calls completed.
static int runChain(const QString& kind, int N, int nSubs)
{
LogosAPI api(QStringLiteral("caller"));
// Pre-seed ONLY the capability token (the app-boot auth token). echo_module's
// token must be minted via the real cross-process requestModule handshake.
api.getTokenManager()->saveToken(QStringLiteral("capability_module"),
QStringLiteral("cap-token"));
LogosQmlBridge bridge(&api);
for (int i = 0; i < nSubs; ++i)
bridge.onModuleEvent(QStringLiteral("echo_module"), QStringLiteral("ev%1").arg(i));
for (int k = 0; k < 80; ++k)
QCoreApplication::processEvents(QEventLoop::AllEvents, 5);
// onModuleEvent's return value no longer says anything about the
// cross-process connection: a subscription made before the peer is
// listening is now ACCEPTED and armed later, which is the whole point. The
// connection probe is the pending list draining instead.
const QStringList stillPending = bridge.pendingEventSubscriptions();
if (!stillPending.isEmpty()) {
err << " [" << kind << "] WARNING: " << stillPending.size()
<< " event subscription(s) still unarmed after the settle window: "
<< stillPending.join(QStringLiteral(", ")) << "\n";
}
QJSEngine engine;
engine.setObjectOwnership(&bridge, QJSEngine::CppOwnership);
engine.globalObject().setProperty(QStringLiteral("logos"), engine.newQObject(&bridge));
QString js;
if (kind == QLatin1String("sync")) {
js = QStringLiteral(R"JS(
var __results = [];
for (var i = 0; i < %1; ++i) {
var r = logos.callModule("echo_module", "echo", [i]);
__results.push(JSON.parse(r));
}
)JS").arg(N);
} else if (kind == QLatin1String("fanout")) {
js = QStringLiteral(R"JS(
var __results = [];
for (var i = 0; i < %1; ++i)
logos.callModuleAsync("echo_module", "echo", [i], function (p) { __results.push(JSON.parse(p)); });
)JS").arg(N);
} else { // async chain
js = QStringLiteral(R"JS(
var __results = [];
function fireNext(i) {
if (i >= %1) return;
logos.callModuleAsync("echo_module", "echo", [i], function (p) {
__results.push(JSON.parse(p)); fireNext(i + 1);
});
}
fireNext(0);
)JS").arg(N);
}
QJSValue driver = engine.evaluate(js);
if (driver.isError()) {
err << " [" << kind << "] JS error: " << driver.toString() << "\n";
return -1;
}
QJSValue results = engine.globalObject().property(QStringLiteral("__results"));
QElapsedTimer t; t.start();
// For the sync chain the loop already ran to completion inside evaluate();
// this pump only matters for the async/fanout kinds.
while (results.property(QStringLiteral("length")).toInt() < N && t.elapsed() < 20000)
QCoreApplication::processEvents(QEventLoop::AllEvents, 20);
return results.property(QStringLiteral("length")).toInt();
}
int main(int argc, char** argv)
{
QCoreApplication app(argc, argv);
if (argc < 2) {
err << "usage: " << argv[0] << " <modules-host-binary> [sync|async|fanout ...]\n";
return 2;
}
const QString hostPath = QString::fromLocal8Bit(argv[1]);
QStringList chains;
for (int i = 2; i < argc; ++i) chains << QString::fromLocal8Bit(argv[i]);
if (chains.isEmpty()) chains << "sync" << "async" << "fanout";
// Fix the instance id BEFORE spawning the host so both processes derive the
// same socket names. Child inherits LOGOS_INSTANCE_ID via the environment.
qputenv("LOGOS_INSTANCE_ID", QByteArrayLiteral("twoproc-test"));
LogosModeConfig::setMode(LogosMode::Remote);
// ── Spawn process A (modules host) and wait for READY ────────────────────
QProcess host;
host.setProcessChannelMode(QProcess::SeparateChannels);
host.setProcessEnvironment(QProcessEnvironment::systemEnvironment());
host.start(hostPath, {});
if (!host.waitForStarted(10000)) {
err << "failed to start modules host: " << host.errorString() << "\n";
return 2;
}
bool ready = false;
QElapsedTimer t; t.start();
QByteArray acc;
while (!ready && t.elapsed() < 15000) {
if (host.waitForReadyRead(500))
acc += host.readAllStandardOutput();
if (acc.contains("READY")) ready = true;
QCoreApplication::processEvents(QEventLoop::AllEvents, 10);
if (host.state() == QProcess::NotRunning) break;
}
if (!ready) {
err << "modules host never signalled READY (state="
<< host.state() << ", stderr=" << host.readAllStandardError() << ")\n";
host.kill(); host.waitForFinished(3000);
return 2;
}
out << "host READY: " << acc.trimmed() << "\n"; out.flush();
// Give the host's sockets a beat to accept connections.
QElapsedTimer settle; settle.start();
while (settle.elapsed() < 300) QCoreApplication::processEvents(QEventLoop::AllEvents, 10);
// ── Run the chains ───────────────────────────────────────────────────────
constexpr int N = 12;
constexpr int SUBS = 14;
bool allOk = true;
for (const QString& kind : chains) {
const int done = runChain(kind, N, SUBS);
const bool ok = (done == N);
allOk = allOk && ok;
out << " chain=" << kind << " completed=" << done << "/" << N
<< (ok ? " OK" : " *** STALL/DROP ***") << "\n";
out.flush();
}
host.kill();
host.waitForFinished(3000);
out << (allOk ? "RESULT: ALL OK\n" : "RESULT: FAILURE (a chain stalled/dropped)\n");
out.flush();
return allOk ? 0 : 1;
}