From faf02147a793f6e1a7799a97728634dc37dfd214 Mon Sep 17 00:00:00 2001 From: fujibee Date: Tue, 18 Aug 2026 16:11:09 -0700 Subject: [PATCH 1/2] fix(remote): report pull bootstrap progress on stderr A pull of 2079 messages runs for 312 seconds and prints nothing. A verifier running it against a real server on Windows saw the silence, concluded the command had hung, and killed it -- a working command was indistinguishable from a stalled one, and the diagnosis went thirty minutes in the wrong direction (#882). Progress goes to stderr only. cmd_pull captures this process's stdout as the result channel and greps it for pull_bootstrap_result, so a line written there would ride in the stream the caller parses. The lines separate fetching from applying because applying spawns a child process per batch and fetching does not: when the output stops moving, which line it stopped on says which half to look at. --- scripts/internal/remote-sync.mjs | 26 ++++++++++++++++ tests/remote_sync_engine.test.mjs | 52 +++++++++++++++++++++++++++++++ 2 files changed, 78 insertions(+) diff --git a/scripts/internal/remote-sync.mjs b/scripts/internal/remote-sync.mjs index 893650b5e..2a61f40e3 100755 --- a/scripts/internal/remote-sync.mjs +++ b/scripts/internal/remote-sync.mjs @@ -3435,6 +3435,29 @@ export async function resyncCycle(config, acceptedFloor, dependencies = {}) { // credential. What it shares with the normal pull is the part that must not // diverge -- evaluatePull decides what may be imported, then roster mutations // and chat records go through the same two drivers as a connected cycle. +/** + * A line of progress for a command that is otherwise silent for minutes (#882). + * + * STDERR, NEVER STDOUT. `cmd_pull` captures this process's stdout as the result + * channel -- `result="$(... pull-bootstrap ...)"` -- so anything written there + * is invisible until the command finishes AND rides in the same stream the + * caller greps for `pull_bootstrap_result`. stderr is not redirected by that + * caller, so it reaches the operator live and changes no parsing. + * + * WHY IT EXISTS: a verifier ran this against a real server, saw nothing for + * five minutes, concluded it had hung, and killed it. On Linux the same command + * takes 312 seconds and succeeds. Silence and a stall were indistinguishable, + * so thirty minutes went into diagnosing a command that was working. + * + * The lines separate FETCHING from APPLYING on purpose. Applying spawns a child + * process per batch; fetching does not. When this stops moving, which line it + * stopped on says which half to look at -- and on Windows, where the report + * came from, that is the whole question. + */ +function pullProgress(message) { + process.stderr.write(`agmsg: ${message}\n`); +} + export async function pullBootstrap(args, dependencies = {}) { const publicSnapshotCall = dependencies.publicSnapshotCall ?? publicSnapshot; const requestPublicCall = dependencies.requestPublicCall ?? requestPublic; @@ -3452,6 +3475,7 @@ export async function pullBootstrap(args, dependencies = {}) { // There is no connected binding yet, so this one call validates itself // rather than going through the checks the rest of the pull relies on. + pullProgress(`pulling ${team} from ${serverUrl} -- this can take several minutes`); const teamSnapshot = await publicSnapshotCall(serverUrl, teamId); const config = { format_version: 1, @@ -3475,8 +3499,10 @@ export async function pullBootstrap(args, dependencies = {}) { let imported = 0; let ageV1Envelopes = 0; for (;;) { + pullProgress(`fetching messages after ${cursor} (${imported} pulled so far)`); const page = await requestPublicCall(config, `/v1/teams/${teamId}/messages?after=${cursor}&limit=${limit}`); + pullProgress(`applying ${page.messages.length} messages`); const records = []; for (const message of page.messages) { if (message.envelope?.cipher === "age-v1") ageV1Envelopes += 1; diff --git a/tests/remote_sync_engine.test.mjs b/tests/remote_sync_engine.test.mjs index 1dfe079fd..6787c08df 100644 --- a/tests/remote_sync_engine.test.mjs +++ b/tests/remote_sync_engine.test.mjs @@ -4085,3 +4085,55 @@ test("runLoop: a non-retryable error that is NOT a refusal still ends the loop", eventCall: async () => {}, }), /config is unreadable/); }); + +test("pull bootstrap reports progress on stderr and leaves stdout as the result channel", async () => { + const teamId = "018f3f7e-0000-7000-8000-000000000001"; + const serverId = "018f3f7e-0000-7000-8000-000000000002"; + // Both streams are captured, not just the one under test. `cmd_pull` reads + // this process's stdout as the result -- result="$(... pull-bootstrap ...)" + // then greps it for pull_bootstrap_result -- so a progress line landing there + // is the regression this case exists to catch, and it is invisible unless + // stdout is measured too. + const out = []; + const err = []; + const realOut = process.stdout.write.bind(process.stdout); + const realErr = process.stderr.write.bind(process.stderr); + process.stdout.write = (chunk) => { out.push(String(chunk)); return true; }; + process.stderr.write = (chunk) => { err.push(String(chunk)); return true; }; + try { + await pullBootstrap({ + team: "clone", "team-id": teamId, endpoint: "http://127.0.0.1:8787", + }, { + publicSnapshotCall: async () => ({ + server_instance_id: serverId, team_id: teamId, team_name: "source", + min_available_seq: "0", + }), + requestPublicCall: async () => ({ + messages: [{ id: "01", seq: "1", envelope: { v: 1, cipher: "plain", blob: "x" } }], + next_after: "1", has_more: false, + }), + evaluateCall: async () => ({ + status: "importable", policy_revision: "0", local_security_revision: "0", + }), + driverCall: async () => [{ type: "sync_apply_result", transport_cursor: "1", corrupt_count: 0 }], + rosterDriverCall: async () => [], + eventCall: async () => {}, + }); + } finally { + process.stdout.write = realOut; + process.stderr.write = realErr; + } + + // stdout: exactly the result, still parseable as one JSON line. + const stdoutLines = out.join("").split("\n").filter((line) => line !== ""); + assert.equal(stdoutLines.length, 1); + assert.equal(JSON.parse(stdoutLines[0]).type, "pull_bootstrap_result"); + + // stderr: the operator can see it start, and can see it move. Both halves are + // named, because when this stops moving the line it stopped on says whether + // to look at the network or at the driver's child process. + const stderrText = err.join(""); + assert.match(stderrText, /agmsg: pulling clone from http:\/\/127\.0\.0\.1:8787/); + assert.match(stderrText, /agmsg: fetching messages after /); + assert.match(stderrText, /agmsg: applying 1 messages/); +}); From 49a96d795d582cd301b2d5c725e7453f797cd7f3 Mon Sep 17 00:00:00 2001 From: fujibee Date: Tue, 18 Aug 2026 16:13:41 -0700 Subject: [PATCH 2/2] fix(remote): stamp each pull progress line with elapsed seconds A terminal does not timestamp its own scrollback, so "it printed this and then stopped" cannot say whether the stop was ten seconds or ten minutes. The Linux run that finished took 312 seconds; without elapsed, a slow phase and a stuck one look identical to whoever is watching. --- scripts/internal/remote-sync.mjs | 17 ++++++++++++----- tests/remote_sync_engine.test.mjs | 6 +++--- 2 files changed, 15 insertions(+), 8 deletions(-) diff --git a/scripts/internal/remote-sync.mjs b/scripts/internal/remote-sync.mjs index 2a61f40e3..53e03bd97 100755 --- a/scripts/internal/remote-sync.mjs +++ b/scripts/internal/remote-sync.mjs @@ -3454,8 +3454,14 @@ export async function resyncCycle(config, acceptedFloor, dependencies = {}) { * stopped on says which half to look at -- and on Windows, where the report * came from, that is the whole question. */ -function pullProgress(message) { - process.stderr.write(`agmsg: ${message}\n`); +function pullProgress(startedAt, message) { + // Elapsed, because a terminal does not timestamp its own scrollback. Without + // it a report of "it printed this and then stopped" cannot say whether the + // stop was ten seconds or ten minutes -- and on the Linux run that finished, + // the whole thing took 312 seconds, so a slow phase and a stuck one look the + // same to whoever is watching. + const elapsed = Math.round((Date.now() - startedAt) / 1000); + process.stderr.write(`agmsg: [${elapsed}s] ${message}\n`); } export async function pullBootstrap(args, dependencies = {}) { @@ -3475,7 +3481,8 @@ export async function pullBootstrap(args, dependencies = {}) { // There is no connected binding yet, so this one call validates itself // rather than going through the checks the rest of the pull relies on. - pullProgress(`pulling ${team} from ${serverUrl} -- this can take several minutes`); + const pullStartedAt = Date.now(); + pullProgress(pullStartedAt, `pulling ${team} from ${serverUrl} -- this can take several minutes`); const teamSnapshot = await publicSnapshotCall(serverUrl, teamId); const config = { format_version: 1, @@ -3499,10 +3506,10 @@ export async function pullBootstrap(args, dependencies = {}) { let imported = 0; let ageV1Envelopes = 0; for (;;) { - pullProgress(`fetching messages after ${cursor} (${imported} pulled so far)`); + pullProgress(pullStartedAt, `fetching messages after ${cursor} (${imported} pulled so far)`); const page = await requestPublicCall(config, `/v1/teams/${teamId}/messages?after=${cursor}&limit=${limit}`); - pullProgress(`applying ${page.messages.length} messages`); + pullProgress(pullStartedAt, `applying ${page.messages.length} messages`); const records = []; for (const message of page.messages) { if (message.envelope?.cipher === "age-v1") ageV1Envelopes += 1; diff --git a/tests/remote_sync_engine.test.mjs b/tests/remote_sync_engine.test.mjs index 6787c08df..2e5c8f52a 100644 --- a/tests/remote_sync_engine.test.mjs +++ b/tests/remote_sync_engine.test.mjs @@ -4133,7 +4133,7 @@ test("pull bootstrap reports progress on stderr and leaves stdout as the result // named, because when this stops moving the line it stopped on says whether // to look at the network or at the driver's child process. const stderrText = err.join(""); - assert.match(stderrText, /agmsg: pulling clone from http:\/\/127\.0\.0\.1:8787/); - assert.match(stderrText, /agmsg: fetching messages after /); - assert.match(stderrText, /agmsg: applying 1 messages/); + assert.match(stderrText, /agmsg: \[\d+s\] pulling clone from http:\/\/127\.0\.0\.1:8787/); + assert.match(stderrText, /agmsg: \[\d+s\] fetching messages after /); + assert.match(stderrText, /agmsg: \[\d+s\] applying 1 messages/); });