fix(copilot): retry transient foreground log reads

changelog.d/copilot-transient-log-reads.md

@@ -0,0 +1,3 @@
+### Fixed
+- Copilot Chat retains verified session continuity across safe partial log lines and retries
+  concurrent log writes without permanently discarding the last verified checkpoint.

server/copilot-store.ts

@@ -14,10 +14,11 @@ const LOG_NAME = /^process-\d+-(\d+)\.log$/;
 const FOREGROUND_PREFIXES = ["Registering foreground session: ", "Unregistering foreground session: "] as const;
 const FOREGROUND_EVENT = new RegExp(String.raw`^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d\.\d+Z \[INFO\] (${FOREGROUND_PREFIXES.join("|")})([\da-f-]{36})$`);
 const VERIFIED_UNREGISTER = Symbol("verified unregister");
+const LOG_READ_CHANGED = Symbol("log read changed");
 interface ForegroundBinding { sessionId: string; generation: string }
 interface ForegroundCheckpoint {
   dev: bigint; ino: bigint; path: string; size: number; observedSize: number; mtimeNs: bigint; ctimeNs: bigint; checkedAtNs: bigint; pendingSwitch: boolean;
-  hash: Hash; epoch: string; binding: ForegroundBinding | null | undefined; unregistered: ForegroundBinding | null;
+  hash: Hash; epoch: string; binding: ForegroundBinding | null | undefined; unregistered: ForegroundBinding | null; readConflict?: true;
 }
 const foregroundCheckpoints = new Map<number, ForegroundCheckpoint>();
 const foregroundLogProcesses = new Map<number, { started: number; observed: boolean }>();
@@ -36,6 +37,14 @@ function logPrefix(fd: number, size: number): Hash | null {
 
 /** The latest complete lifecycle event in the CLI's own open log, never the newest transcript. */
 function loggedForeground(pid: number, logDirectories: readonly string[]): ForegroundBinding | null | undefined | typeof VERIFIED_UNREGISTER {
+  for (let attempt = 0; attempt < 2; attempt++) {
+    const result = scanForegroundLog(pid, logDirectories);
+    if (result !== LOG_READ_CHANGED) return result;
+  }
+  return undefined;
+}
+
+function scanForegroundLog(pid: number, logDirectories: readonly string[]): ForegroundBinding | null | undefined | typeof VERIFIED_UNREGISTER | typeof LOG_READ_CHANGED {
   const started = processStartedAt(pid);
   if (started === null) return undefined;
   let owner = foregroundLogProcesses.get(pid);
@@ -102,7 +111,7 @@ function loggedForeground(pid: number, logDirectories: readonly string[]): Foreg
           const cached = foregroundCheckpoints.get(pid);
           // A same-size rewrite can share both timestamps with this check.
           // Only a check already outside that tick can attest unchanged bytes.
-          if (cached?.dev === stat.dev && cached.ino === stat.ino && cached.path === target
+          if (!cached?.readConflict && cached?.dev === stat.dev && cached.ino === stat.ino && cached.path === target
             && cached.observedSize === size && cached.mtimeNs === stat.mtimeNs && cached.ctimeNs === stat.ctimeNs
             && checkedAtNs >= cached.checkedAtNs
             && cached.checkedAtNs - stat.mtimeNs >= LOG_TIMESTAMP_MARGIN_NS
@@ -123,7 +132,10 @@ function loggedForeground(pid: number, logDirectories: readonly string[]): Foreg
           const hash = same ? prefix : logPrefix(fd, start);
           const after = fstatSync(fd, { bigint: true });
           if (read !== bytes.length || hash === null || after.size !== stat.size
-            || after.mtimeNs !== stat.mtimeNs || after.ctimeNs !== stat.ctimeNs) return unavailable();
+            || after.mtimeNs !== stat.mtimeNs || after.ctimeNs !== stat.ctimeNs) {
+            if (cached) cached.readConflict = true;
+            return LOG_READ_CHANGED;
+          }
           const text = bytes.subarray(0, read).toString("utf8");
           const skip = start === 0 || same ? 0 : text.indexOf("\n") + 1;
           const complete = text.slice(skip, text.lastIndexOf("\n") + 1);
@@ -152,7 +164,7 @@ function loggedForeground(pid: number, logDirectories: readonly string[]): Foreg
           // Cache the visible result separately from the last complete binding:
           // an unchanged partial timestamp or switch must remain unavailable.
           const message = /^\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d\.\d+Z \[INFO\] (.*)$/.exec(tail)?.[1];
-          const pendingSwitch = !!tail && (selected == null || (/^\d/.test(tail) && (message === undefined
+          const pendingSwitch = !!tail && (selected === undefined || (/^\d/.test(tail) && (message === undefined
             || FOREGROUND_PREFIXES.some((event) => event.startsWith(message) || message.startsWith(event)))));
           foregroundCheckpoints.set(pid, {
             dev: stat.dev, ino: stat.ino, path: target, size: start + completeBytes,

server/copilot.test.ts

@@ -599,6 +599,123 @@ it.skipIf(process.platform !== "linux")("keeps report-and-marker fallback for a
   } finally { await fixture.close(); }
 });
 
+it.skipIf(process.platform !== "linux")("keeps marker fallback through ordinary partial lines but rejects pending and completed revocation", async () => {
+  const fixture = await logFixture([session]);
+  const { root, log, environment, pid } = fixture;
+  const path = join(root, "session-state", session, "events.jsonl");
+  const read = () => copilotTranscriptFile(session, environment, ["copilot"], pid);
+  try {
+    writeFileSync(path, start + prompt("existing conversation"));
+    appendFileSync(log, "CLI started\n");
+    expect(read()).toBe(path);
+    for (const tail of ["ordinary partial line", "2026-10-24T00:00:00.000Z [INFO] Writing session"]) {
+      appendFileSync(log, tail);
+      expect(read()).toBe(path);
+      expect(read()).toBe(path);
+      appendFileSync(log, "\n");
+      expect(read()).toBe(path);
+    }
+    appendFileSync(log, register(session, "Unregistering").trimEnd());
+    expect(read()).toBeNull();
+    appendFileSync(log, "\nordinary complete line\n");
+    expect(read()).toBeNull();
+    expect(read()).toBeNull();
+  } finally { await fixture.close(); }
+});
+
+for (const registered of [false, true]) {
+  for (const writes of [1, 2]) {
+    it.skipIf(process.platform !== "linux")(`recovers ${registered ? "registered" : "marker"} continuity after ${writes} concurrent log appends`, async () => {
+      const fixture = await logFixture([session]);
+      const { root, log, environment, pid } = fixture;
+      const path = join(root, "session-state", session, "events.jsonl");
+      const read = () => copilotProcessSession(environment, ["copilot"], pid);
+      const realRead = fs.readSync;
+      let remaining = writes;
+      function concurrentRead(fd: number, buffer: NodeJS.ArrayBufferView, offset: number, length: number, position: fs.ReadPosition | null): number;
+      function concurrentRead(fd: number, buffer: NodeJS.ArrayBufferView, options?: fs.ReadSyncOptions): number;
+      function concurrentRead(fd: number, buffer: NodeJS.ArrayBufferView, offset?: number | fs.ReadSyncOptions, length?: number, position?: fs.ReadPosition | null): number {
+        const count = typeof offset === "number" ? realRead(fd, buffer, offset, length!, position ?? null) : realRead(fd, buffer, offset);
+        if (position === 0 && remaining > 0 && fs.readlinkSync(`/proc/self/fd/${fd}`) === log) {
+          remaining--;
+          appendFileSync(log, "concurrent ordinary append\n");
+        }
+        return count;
+      }
+      let reads: ReturnType<typeof spyOn<typeof fs, "readSync">> | undefined;
+      try {
+        writeFileSync(path, start + prompt("existing conversation"));
+        appendFileSync(log, registered ? register(session) : "CLI started\n");
+        const original = read();
+        expect(original?.sessionId).toBe(session);
+        reads = spyOn(fs, "readSync").mockImplementation(concurrentRead);
+        const raced = read();
+        expect(remaining).toBe(0);
+        if (writes === 1) expect(raced?.sessionId).toBe(session);
+        else expect(raced).toBeNull();
+        const recovered = read();
+        expect(recovered?.sessionId).toBe(session);
+        expect(recovered?.logged).toBe(registered);
+        if (original?.logged && recovered?.logged) expect(recovered.generation).toBe(original.generation);
+        appendFileSync(log, register(session, "Unregistering"));
+        expect(read()).toBeNull();
+        appendFileSync(log, "ordinary append after unregister\n");
+        expect(read()).toBeNull();
+      } finally { reads?.mockRestore(); await fixture.close(); }
+    });
+  }
+}
+
+it.skipIf(process.platform !== "linux")("does not fall back to a stale marker when the first log read races and its descriptor disappears", async () => {
+  const fixture = await logFixture([session]);
+  const { root, log, environment, pid } = fixture;
+  const path = join(root, "session-state", session, "events.jsonl");
+  const read = () => copilotTranscriptFile(session, environment, ["copilot"], pid);
+  const realRead = fs.readSync;
+  const realLink = fs.readlinkSync;
+  let missing = false;
+  function concurrentRead(fd: number, buffer: NodeJS.ArrayBufferView, offset: number, length: number, position: fs.ReadPosition | null): number;
+  function concurrentRead(fd: number, buffer: NodeJS.ArrayBufferView, options?: fs.ReadSyncOptions): number;
+  function concurrentRead(fd: number, buffer: NodeJS.ArrayBufferView, offset?: number | fs.ReadSyncOptions, length?: number, position?: fs.ReadPosition | null): number {
+    const count = typeof offset === "number" ? realRead(fd, buffer, offset, length!, position ?? null) : realRead(fd, buffer, offset);
+    if (!missing && position === 0 && realLink(`/proc/self/fd/${fd}`) === log) {
+      appendFileSync(log, "concurrent ordinary append\n");
+      missing = true;
+    }
+    return count;
+  }
+  function currentLink(path: fs.PathLike, options?: fs.EncodingOption): string;
+  function currentLink(path: fs.PathLike, options: fs.BufferEncodingOption): Buffer<ArrayBuffer>;
+  function currentLink(path: fs.PathLike, options?: fs.EncodingOption | fs.BufferEncodingOption): string | Buffer<ArrayBuffer>;
+  function currentLink(path: fs.PathLike, options?: fs.EncodingOption | fs.BufferEncodingOption): string | Buffer<ArrayBuffer> {
+    const encoding = typeof options === "object" ? options?.encoding : options;
+    const target = encoding === "buffer" ? realLink(path, "buffer") : realLink(path, encoding);
+    if (missing && String(path).startsWith(`/proc/${pid}/fd/`) && target.toString() === log) {
+      throw Object.assign(new Error("fixture log descriptor closed"), { code: "ENOENT" });
+    }
+    return target;
+  }
+  let reads: ReturnType<typeof spyOn<typeof fs, "readSync">> | undefined;
+  let links: ReturnType<typeof spyOn<typeof fs, "readlinkSync">> | undefined;
+  try {
+    writeFileSync(path, start + prompt("stale held conversation"));
+    appendFileSync(log, register(other));
+    reads = spyOn(fs, "readSync").mockImplementation(concurrentRead);
+    links = spyOn(fs, "readlinkSync").mockImplementation(currentLink);
+    expect(read()).toBeNull();
+    expect(missing).toBe(true);
+    reads.mockRestore();
+    links.mockRestore();
+    await fixture.command("close");
+    expect(read()).toBeNull();
+    await fixture.command("open");
+    writeFileSync(log, "ordinary complete line\n");
+    expect(read()).toBeNull();
+    appendFileSync(log, register(session));
+    expect(read()).toBe(path);
+  } finally { reads?.mockRestore(); links?.mockRestore(); await fixture.close(); }
+});
+
 for (const scenario of ["rewrite", "gap"] as const) {
   it.skipIf(process.platform !== "linux")(`recovers foreground discovery after a log ${scenario}`, async () => {
     const fixture = await logFixture([]);