fix(remote): report pull bootstrap progress on stderr (#882)

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;

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/);
+});