From f56dc491bb7f65058b1343906f363090a4a39978 Mon Sep 17 00:00:00 2001 From: Yu Xie Date: Mon, 26 Oct 2026 14:09:37 +0100 Subject: [PATCH 1/2] fix(copilot): retry transient foreground log reads Refs YuuuXie/herdr-web-ui#4 Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 1fad73aa-cbc5-42dd-916b-64e5198bc512 --- changelog.d/copilot-transient-log-reads.md | 3 + server/copilot-store.ts | 21 +++++-- server/copilot.test.ts | 67 ++++++++++++++++++++++ 3 files changed, 87 insertions(+), 4 deletions(-) create mode 100644 changelog.d/copilot-transient-log-reads.md diff --git a/changelog.d/copilot-transient-log-reads.md b/changelog.d/copilot-transient-log-reads.md new file mode 100644 index 0000000000..3df647f01f --- /dev/null +++ b/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. diff --git a/server/copilot-store.ts b/server/copilot-store.ts index a45f49930b..7d9d419847 100644 --- a/server/copilot-store.ts +++ b/server/copilot-store.ts @@ -13,10 +13,11 @@ const LOG_TIMESTAMP_MARGIN_NS = 3_000_000_000n; 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 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; + hash: Hash; epoch: string; binding: ForegroundBinding | null | undefined; readConflict?: true; } const foregroundCheckpoints = new Map(); const foregroundLogProcesses = new Map(); @@ -35,6 +36,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 { + 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 LOG_READ_CHANGED { const started = processStartedAt(pid); if (started === null) return undefined; let owner = foregroundLogProcesses.get(pid); @@ -101,7 +110,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 @@ -121,7 +130,11 @@ 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; + owner.observed = observedBefore; + 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); @@ -144,7 +157,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, diff --git a/server/copilot.test.ts b/server/copilot.test.ts index acf242e42b..a6727d773e 100644 --- a/server/copilot.test.ts +++ b/server/copilot.test.ts @@ -556,6 +556,73 @@ 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> | 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(); } + }); + } +} + 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([]); From 0e8e8cf8de0ce662996ad53306561f79e9c2993d Mon Sep 17 00:00:00 2001 From: Yu Xie Date: Mon, 26 Oct 2026 14:53:48 +0100 Subject: [PATCH 2/2] fix(copilot): retain observed-log denial through read conflicts Keep process-lifetime log observation sticky so an initial concurrent read followed by descriptor loss cannot revive a stale held-session fallback. Cover the read conflict, descriptor disappearance, real close/reopen, and fresh-registration recovery. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: 1fad73aa-cbc5-42dd-916b-64e5198bc512 --- server/copilot-store.ts | 1 - server/copilot.test.ts | 50 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 50 insertions(+), 1 deletion(-) diff --git a/server/copilot-store.ts b/server/copilot-store.ts index 7d9d419847..adf60f8249 100644 --- a/server/copilot-store.ts +++ b/server/copilot-store.ts @@ -132,7 +132,6 @@ function scanForegroundLog(pid: number, logDirectories: readonly string[]): Fore if (read !== bytes.length || hash === null || after.size !== stat.size || after.mtimeNs !== stat.mtimeNs || after.ctimeNs !== stat.ctimeNs) { if (cached) cached.readConflict = true; - owner.observed = observedBefore; return LOG_READ_CHANGED; } const text = bytes.subarray(0, read).toString("utf8"); diff --git a/server/copilot.test.ts b/server/copilot.test.ts index a6727d773e..8c580df0e1 100644 --- a/server/copilot.test.ts +++ b/server/copilot.test.ts @@ -623,6 +623,56 @@ for (const registered of [false, true]) { } } +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; + function currentLink(path: fs.PathLike, options?: fs.EncodingOption | fs.BufferEncodingOption): string | Buffer; + function currentLink(path: fs.PathLike, options?: fs.EncodingOption | fs.BufferEncodingOption): string | Buffer { + 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> | undefined; + let links: ReturnType> | 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([]);