diff --git a/scripts/internal/remote-sync.mjs b/scripts/internal/remote-sync.mjs index 893650b5e..53e03bd97 100755 --- a/scripts/internal/remote-sync.mjs +++ b/scripts/internal/remote-sync.mjs @@ -3435,6 +3435,35 @@ 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(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 = {}) { const publicSnapshotCall = dependencies.publicSnapshotCall ?? publicSnapshot; const requestPublicCall = dependencies.requestPublicCall ?? requestPublic; @@ -3452,6 +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. + 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, @@ -3475,8 +3506,10 @@ export async function pullBootstrap(args, dependencies = {}) { let imported = 0; let ageV1Envelopes = 0; for (;;) { + pullProgress(pullStartedAt, `fetching messages after ${cursor} (${imported} pulled so far)`); const page = await requestPublicCall(config, `/v1/teams/${teamId}/messages?after=${cursor}&limit=${limit}`); + 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 1dfe079fd..2e5c8f52a 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: \[\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/); +});