Files
PaperClipAI/server/src/services/run-log-store.test.ts
T
DottaandPaperclip 94e8dec56b fix(runner): preserve tool outcomes through shutdown and restart (#14734)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work.
> - The runner sends authorized tool calls to the server and saves their
results.
> - A provider turn can stop while a server write is still running.
> - The old shutdown path invented a failed result that could conflict
with the real result.
> - Truncated execution input and incomplete recovery records made the
failure harder to diagnose.
> - This pull request preserves exact inputs and actual outcomes through
shutdown and restart.
> - Tests force the race and crash boundaries so safe retries do not
repeat writes.

## Linked Issues or Issue Description

**What happened?**

Stopping a turn during a server tool call could record a false failure,
then reject the actual result as a conflict. The diagnostic input
formatter could truncate instruction content before execution. A crash
during saved-result delivery could leave that delivery permanently
indeterminate. Cleanup could hide the first failure, and a retry could
overwrite earlier run logs.

**Expected behavior**

Keep dispatched tools pending until their actual result is known.
Preserve accepted input bytes. Accept identical result delivery without
failing the task. Reject conflicting results with enough evidence to
diagnose them. Recover saved-result delivery without repeating the
business operation.

**Steps to reproduce**

1. Hold an instruction update at the filesystem commit barrier.
2. Stop its provider turn before the server returns the result.
3. Release the write, deliver its result, and replay the same result.
4. Repeat with a restart before and after the delivery receipt is saved.
5. Check that there is one write and one audit row, and that the exact
result survives.

**Paperclip version or commit**

The change was developed from `44736c9c7` and rebased onto `0e5830887`.

**Deployment mode**

Self-hosted server with the native runner. Tests use local runner
processes, scripted providers, and PostgreSQL.

Related work: #12353 added durable semantic tool receipts; #12384 added
durable Codex tool recovery; #12404 bound semantic tools to ACPX
sessions. #14633 covers separate native-provider cancellation and
qualification work. This PR addresses server semantic-tool outcomes and
their durable delivery. No duplicate fix was found. AgentMail discovery
is outside this PR.

## What Changed

- Close turn admission without inventing results for dispatched tools.
Keep pending calls and accept late actual results.
- Accept identical result replay with a diagnostic warning. Include call
identity and both result hashes in real conflict errors.
- Preserve exact execution arguments. Reject prohibited or oversized
input before dispatch. Keep diagnostic previews redacted and bounded.
- Commit instruction-attempt evidence before the filesystem write. Save
completed mutation receipts so concurrent and restarted duplicates
return the first result. Recheck authorization before replay. An attempt
without a completed result stays unknown and cannot execute again.
Definite pre-write failures save and replay their original error without
another write.
- Recover an interrupted saved-result delivery only for backends with
durable result receipts. Never replay an ordinary business operation
with an unknown outcome.
- Preserve the initiating error when cleanup also fails. Record
incomplete settlement evidence. Propagate typed unknown-outcome errors
through the native tool wrapper without creating a false completed tool
result.
- Append run-log attempts and restore the durable log before appending
after local file loss. Reject incomplete restores. Publish a restored
prefix only if the destination is absent so concurrent attempts cannot
overwrite new lines.
- Add deterministic race, crash, replay, authorization, exact-content,
and log-restoration tests. Document their assertions in
`packages/paperclip-runner/docs/durable-recovery.md`.

## Verification

- Current head: `7e088f4c7fba8ebabf98ae95485a5753b013d489`. All 55
applicable checks pass; four conditional/manual checks are skipped. This
includes build, typecheck, Rust, both runner TypeScript shards, server
and workspace tests, all eight browser shards, isolated runner
compilation, and the clean-install release dry run. [CI
run](https://github.com/paperclipai/paperclip/actions/runs/36746101110).
- Greptile reviewed this exact head at 5/5 with zero new findings. All
three earlier review threads are resolved.
- Focused local verification includes 11 instruction integration tests,
23 surrounding authority/tool tests, 26 run-log tests, and 169
controller/driver tests. The post-rebase controller/transport/runtime
selection passed 415 tests. The full Rust release suite passed 617 tests
with two ignored. The real-process SIGKILL recovery test passed three
consecutive runs.
- The fault matrix in
`packages/paperclip-runner/docs/durable-recovery.md` uses explicit
barriers, real PostgreSQL rollback, durable journal reloads, and killed
runner processes. It covers late results, identical and conflicting
replay, exact long content, concurrent log restoration, lost commit
acknowledgements, and definite failure replay after the original CAS
base becomes valid again. No paid model calls are needed.
- Full local recursive typecheck and build passed during implementation.
Server typecheck and the runner TypeScript build passed after the review
fixes. The broad local repository test run was stopped after repeated
database startup timeouts. Four timing/launch failures in an earlier
broad runner run passed focused reruns without changed assertions or
timeouts. These are local verification limitations; the complete
current-head CI suite is green. An earlier CI workspace job received an
infrastructure shutdown signal; its current-head replacement passed.

## Risks

- A stopped turn can remain blocked when a dispatched operation has no
proven result. The system does not guess its outcome or rerun its
effect.
- Conflicting results still fail settlement. Existing failed or
conflicting journals are not repaired automatically.
- Accepted semantic input is limited to 480 KiB of encoded JSON to fit
the encrypted transport. Larger input fails before execution.
- Instruction filesystem writes and database receipts are not one atomic
storage operation. A separately committed attempt and audit record
survive rollback. An attempt without a completed success or definite
pre-write failure receipt remains blocked as an unknown outcome. It is
not replayed or reported as success.
- Run-log restoration now reads the durable object before appending when
the local log is missing. Failed or incomplete reads reject the append.
- No schema migration, dependency change, workflow change, or AgentMail
change is included.

## Model Used

OpenAI Codex, GPT-6, with reasoning, tool use, code execution, and test
analysis. The exact served model ID and context-window size are not
exposed in this session.

## Checklist

- [x] I have included a thinking path that traces from project context
to this change
- [x] I have specified the model used (with version and capability
details)
- [x] I have checked ROADMAP.md and confirmed this PR does not duplicate
planned core work
- [x] I have searched GitHub for duplicate or related PRs and linked
them above
- [x] I have either (a) linked existing issues with `Fixes: #` / `Closes
#` / `Refs #` OR (b) described the issue in-PR following the relevant
issue template
- [x] I have not referenced internal/instance-local Paperclip issues or
links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip`
URLs)
- [x] My branch name describes the change (e.g. `docs/...`, `fix/...`)
and contains no internal Paperclip ticket id or instance-derived details
- [x] I have run tests locally and they pass (focused suites; the broad
local run limitation is recorded above)
- [x] I have added or updated tests where applicable
- [x] I have updated relevant documentation to reflect my changes
- [x] I have considered and documented any risks above
- [x] All Paperclip CI gates are green
- [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups
- [x] I will address all Greptile and reviewer comments before
requesting merge

---------

Co-authored-by: Paperclip <noreply@paperclip.ing>
2026-09-30 11:54:56 -05:00

557 lines
26 KiB
TypeScript

import { afterEach, beforeEach, describe, expect, it, vi } from "vitest";
import { promises as fs } from "node:fs";
import path from "node:path";
import os from "node:os";
import { createHash } from "node:crypto";
import { Readable } from "node:stream";
import { createDurableRunLogStore } from "./run-log-store.js";
import type { StorageProvider } from "../storage/types.js";
// In-memory StorageProvider stand-in: durable, survives the "pod roll" (local
// dir wipe) the same way Cubbit does. Records calls so we can assert behaviour.
function createMemoryProvider() {
const objects = new Map<string, Buffer>();
const calls = { put: 0, get: 0, head: 0 };
const provider: StorageProvider = {
id: "s3",
async putObject(input) {
calls.put++;
if (Buffer.isBuffer(input.body)) {
objects.set(input.objectKey, Buffer.from(input.body));
return;
}
const chunks: Buffer[] = [];
for await (const chunk of input.body) {
chunks.push(Buffer.isBuffer(chunk) ? chunk : Buffer.from(chunk));
}
objects.set(input.objectKey, Buffer.concat(chunks));
},
async getObject(input) {
calls.get++;
const buf = objects.get(input.objectKey);
if (!buf) {
const err = new Error("Object not found") as Error & { name: string };
err.name = "NoSuchKey";
throw err;
}
// Real S3 answers 416 when the range starts at or past EOF — the mock
// must too, or caught-up-reader regressions (PAPERCLIP-BACKEND-9) pass
// silently with an empty slice.
if (input.range && (input.range.start >= buf.length || input.range.start > input.range.end)) {
const err = new Error("Invalid range") as Error & { name: string };
err.name = "InvalidRange";
throw err;
}
const slice = input.range ? buf.subarray(input.range.start, input.range.end + 1) : buf;
return { stream: Readable.from(slice), contentLength: slice.length };
},
async headObject(input) {
calls.head++;
const buf = objects.get(input.objectKey);
return buf ? { exists: true, contentLength: buf.length } : { exists: false };
},
async deleteObject(input) {
objects.delete(input.objectKey);
},
};
return { provider, objects, calls };
}
let baseDir: string;
beforeEach(async () => {
baseDir = await fs.mkdtemp(path.join(os.tmpdir(), "run-log-store-test-"));
});
afterEach(async () => {
await fs.rm(baseDir, { recursive: true, force: true });
});
const begin = { companyId: "co1", agentId: "ag1", runId: "run1" };
describe("createDurableRunLogStore", () => {
it("keeps store id 'local_file' so downstream coupling (feedback, casts) is unchanged", async () => {
const { provider } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
expect(handle.store).toBe("local_file");
});
it("appends locally and reads back during a run WITHOUT hitting S3 (fast live tail)", async () => {
const { provider, calls } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "hello", ts: "t1" });
const res = await store.read(handle);
expect(res.content).toContain("hello");
expect(calls.get).toBe(0); // local file present -> no S3 read
});
it.each([false, true])("retains every attempt across retry (pod restart: %s)", async (restart) => {
const { provider, objects } = createMemoryProvider();
let store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const attempts: string[] = [];
for (let attempt = 1; attempt <= 3; attempt++) {
if (restart && attempt > 1) {
await fs.rm(baseDir, { recursive: true, force: true });
store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
}
const handle = await store.begin(begin);
attempts.push(handle.attemptId!);
await store.append(handle, { stream: "stderr", chunk: `attempt-${attempt}`, ts: "same-time", seq: attempt });
const summary = await store.finalize(handle);
const saved = objects.get(handle.logRef)!;
const lines = saved.toString().trim().split("\n").map((line) => JSON.parse(line));
expect(lines.map((line) => line.chunk)).toEqual(Array.from({length: attempt}, (_, i) => `attempt-${i + 1}`));
expect(lines.map((line) => line.attemptId)).toEqual(attempts);
expect(new Set(attempts).size).toBe(attempt);
expect(summary.bytes).toBe(saved.length);
expect(summary.sha256).toBe(createHash("sha256").update(saved).digest("hex"));
}
});
it("never replaces concurrent appends when two stores restore the same missing log", async () => {
const { provider, objects } = createMemoryProvider();
const firstStore = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const secondStore = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const original = await firstStore.begin(begin);
await firstStore.append(original, { stream: "stderr", chunk: "original", ts: "t0" });
await firstStore.finalize(original);
const prefix = Buffer.from(objects.get(original.logRef)!);
await fs.rm(baseDir, { recursive: true, force: true });
let reached!: () => void, release!: () => void;
const restoring = new Promise<void>((resolve) => { reached = resolve; });
const barrier = new Promise<void>((resolve) => { release = resolve; });
const spy = vi.spyOn(provider, "getObject").mockImplementationOnce(async () => ({
stream: Readable.from((async function* () {
yield prefix;
reached();
await barrier;
})()),
contentLength: prefix.length,
}));
const slow = firstStore.begin(begin);
try {
await restoring;
const fast = await secondStore.begin(begin);
await secondStore.append(fast, { stream: "stderr", chunk: "fast attempt", ts: "t1" });
release();
const late = await slow;
await firstStore.append(late, { stream: "stderr", chunk: "slow attempt", ts: "t2" });
await firstStore.finalize(late);
const saved = objects.get(original.logRef)!;
expect(saved).toEqual(await fs.readFile(path.join(baseDir, original.logRef)));
expect(saved.toString().trim().split("\n").map((line) => JSON.parse(line).chunk))
.toEqual(["original", "fast attempt", "slow attempt"]);
} finally {
release();
await slow.catch(() => undefined);
spy.mockRestore();
}
});
it.each(["stream_failure", "short_read"])("preserves the durable prefix when restore fails (%s)", async (fault) => {
const { provider, objects, calls } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stderr", chunk: "original failure evidence", ts: "t1" });
await store.finalize(handle);
const prefix = Buffer.from(objects.get(handle.logRef)!);
await fs.rm(baseDir, { recursive: true, force: true });
const spy = vi.spyOn(provider, "getObject").mockResolvedValueOnce({
stream: Readable.from((async function* () {
yield prefix.subarray(0, 10);
if (fault === "stream_failure") throw new Error("storage connection lost");
})()),
contentLength: prefix.length,
});
try {
await expect(store.begin(begin)).rejects.toThrow(
fault === "stream_failure" ? "storage connection lost" : "incomplete prefix",
);
await expect(fs.stat(path.join(baseDir, handle.logRef))).rejects.toMatchObject({ code: "ENOENT" });
expect(objects.get(handle.logRef)).toEqual(prefix);
expect(calls.put).toBe(1);
const next = await store.begin(begin);
expect(await fs.readFile(path.join(baseDir, next.logRef))).toEqual(prefix);
} finally { spy.mockRestore(); }
});
it("uploads the complete log to S3 on finalize", async () => {
const { provider, objects, calls } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider, keyPrefix: "run-logs" } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "line-A", ts: "t1" });
await store.append(handle, { stream: "stdout", chunk: "line-B", ts: "t2" });
const summary = await store.finalize(handle);
expect(calls.put).toBe(1);
expect(summary.bytes).toBeGreaterThan(0);
// keyed by prefix + the handle's logRef so read can find it later
const key = `run-logs/${handle.logRef}`;
expect(objects.has(key)).toBe(true);
expect(objects.get(key)!.toString("utf8")).toContain("line-A");
expect(objects.get(key)!.toString("utf8")).toContain("line-B");
});
it.each(["finishes", "fails"])("waits for an accepted file append that %s before finalizing", async (outcome) => {
const { provider, objects } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
let release!: () => void;
const gate = new Promise<void>((resolve) => { release = resolve; });
const appendFile = fs.appendFile.bind(fs);
const spy = vi.spyOn(fs, "appendFile").mockImplementationOnce(async (...args) => {
await gate;
if (outcome === "fails") throw new Error("disk unavailable");
await appendFile(...args);
});
const append = store.append(handle, { stream: "stderr", chunk: "late diagnostic", ts: "t1" });
// Observe the deliberate rejection independently of finalization.
void append.catch(() => {});
let finalized = false;
const finalize = store.finalize(handle).then((summary) => {
finalized = true;
return summary;
});
try {
await new Promise((resolve) => setTimeout(resolve, 100));
expect(finalized).toBe(false);
release();
if (outcome === "fails") await expect(append).rejects.toThrow("disk unavailable");
else await append;
const summary = await finalize;
const local = await fs.readFile(path.join(baseDir, handle.logRef));
expect(summary.bytes).toBe(local.length);
expect(summary.sha256).toBe(createHash("sha256").update(local).digest("hex"));
expect(objects.get(handle.logRef)).toEqual(local);
expect(local.toString()).toBe(outcome === "fails" ? "" : JSON.stringify({
ts: "t1", attemptId: handle.attemptId, stream: "stderr", chunk: "late diagnostic",
}) + "\n");
} finally {
release();
await append.catch(() => {});
await finalize;
spy.mockRestore();
}
});
it("ignores appends once finalization starts so the durable snapshot stays immutable", async () => {
const { provider, objects } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "accepted", ts: "t1" });
const finalize = store.finalize(handle);
expect(await store.append(handle, { stream: "stderr", chunk: "too late", ts: "t2" })).toBe(0);
const summary = await finalize;
expect(await store.append(handle, { stream: "stderr", chunk: "also too late", ts: "t3" })).toBe(0);
const local = await fs.readFile(path.join(baseDir, handle.logRef));
expect(local.toString()).not.toContain("too late");
expect(summary.bytes).toBe(local.length);
expect(summary.sha256).toBe(createHash("sha256").update(local).digest("hex"));
expect(objects.get(handle.logRef)).toEqual(local);
});
it("leaves final metadata unknown when an append stalls and never mirrors its late completion", async () => {
const { provider, calls } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider, inflightMirrorMs: 10_000 } });
const handle = await store.begin(begin);
let release!: () => void;
const gate = new Promise<void>((resolve) => { release = resolve; });
const appendFile = fs.appendFile.bind(fs);
const spy = vi.spyOn(fs, "appendFile").mockImplementationOnce(async (...args) => {
await gate;
await appendFile(...args);
});
const warn = vi.spyOn(console, "warn").mockImplementation(() => {});
vi.useFakeTimers({ toFake: ["setTimeout", "clearTimeout"] });
const append = store.append(handle, { stream: "stderr", chunk: "stalled diagnostic", ts: "t1" });
let summary: Awaited<ReturnType<typeof store.finalize>> | undefined;
const finalize = store.finalize(handle).then((result) => { summary = result; });
try {
await vi.advanceTimersByTimeAsync(3_000);
expect(summary).toEqual({ bytes: null, sha256: null, compressed: false });
expect(warn).toHaveBeenCalled();
expect(calls.put).toBe(0);
release();
await append;
await vi.advanceTimersByTimeAsync(20_000);
await store.flushInflightMirrors!();
expect(calls.put).toBe(0);
expect(await store.finalize(handle)).toEqual(summary);
expect(await store.append(handle, { stream: "stderr", chunk: "too late", ts: "t2" })).toBe(0);
} finally {
release();
await append;
await finalize;
vi.useRealTimers();
spy.mockRestore();
warn.mockRestore();
}
});
it("falls back to S3 when the local file is gone (the pod-roll case that caused 'Run log not found')", async () => {
const { provider } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider, keyPrefix: "run-logs" } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "persisted-line", ts: "t1" });
await store.finalize(handle);
// Simulate a pod restart wiping the emptyDir.
await fs.rm(baseDir, { recursive: true, force: true });
const res = await store.read(handle);
expect(res.content).toContain("persisted-line");
});
it("S3 fallback honours offset/limitBytes (range read) and reports nextOffset", async () => {
const { provider } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider, keyPrefix: "p" } });
const handle = await store.begin(begin);
// one line; persisted bytes = JSON line + "\n"
await store.append(handle, { stream: "stdout", chunk: "0123456789", ts: "t" });
await store.finalize(handle);
const full = await store.read(handle); // from local, to learn total size
const total = Buffer.byteLength(full.content, "utf8");
await fs.rm(baseDir, { recursive: true, force: true }); // force S3 path
const firstHalf = await store.read(handle, { offset: 0, limitBytes: 5 });
expect(Buffer.byteLength(firstHalf.content, "utf8")).toBe(5);
expect(firstHalf.nextOffset).toBe(5);
const tail = await store.read(handle, { offset: total - 3, limitBytes: 100 });
expect(Buffer.byteLength(tail.content, "utf8")).toBe(3);
expect(tail.nextOffset).toBeUndefined();
});
it("S3 fallback returns an empty read (no InvalidRange) when the reader is fully caught up", async () => {
// Regression test for PAPERCLIP-BACKEND-9: a poller that had consumed the
// whole log kept polling at offset === total after the pod rolled; the S3
// path clamped end up to start and requested `bytes=total-total`, which
// S3 rejects with 416 InvalidRange -> 500.
const { provider } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider, keyPrefix: "p" } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "0123456789", ts: "t" });
await store.finalize(handle);
const full = await store.read(handle);
const total = Buffer.byteLength(full.content, "utf8");
await fs.rm(baseDir, { recursive: true, force: true }); // force S3 path
const caughtUp = await store.read(handle, { offset: total, limitBytes: 100 });
expect(caughtUp.content).toBe("");
expect(caughtUp.nextOffset).toBeUndefined();
// Past-EOF offsets clamp to the same empty read.
const pastEof = await store.read(handle, { offset: total + 50, limitBytes: 100 });
expect(pastEof.content).toBe("");
expect(pastEof.nextOffset).toBeUndefined();
});
it("local read at offset === size returns an empty read with undefined nextOffset", async () => {
const store = createDurableRunLogStore({ basePath: baseDir });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "abc", ts: "t" });
const full = await store.read(handle);
const total = Buffer.byteLength(full.content, "utf8");
const caughtUp = await store.read(handle, { offset: total, limitBytes: 100 });
expect(caughtUp.content).toBe("");
expect(caughtUp.nextOffset).toBeUndefined();
});
it("reads local pages without waiting for a separate metadata request", async () => {
const store = createDurableRunLogStore({ basePath: baseDir });
const handle = await store.begin(begin);
await fs.writeFile(path.join(baseDir, handle.logRef), "0123456789");
const statSpy = vi.spyOn(fs, "stat").mockRejectedValue(new Error("Metadata unavailable"));
try {
expect(await store.read(handle, { offset: 2, limitBytes: 4 })).toEqual({ content: "2345", nextOffset: 6 });
expect(await store.read(handle, { offset: 6, limitBytes: 4 })).toEqual({ content: "6789", nextOffset: undefined });
expect(await store.read(handle, { offset: 20, limitBytes: 4 })).toEqual({ content: "", nextOffset: undefined });
} finally {
statSpy.mockRestore();
}
});
it("throws notFound when neither local nor S3 has the log (pre-S3 run after a roll)", async () => {
const { provider } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
await fs.rm(baseDir, { recursive: true, force: true }); // never finalized -> never uploaded
await expect(store.read(handle)).rejects.toThrow(/not found/i);
});
it("without S3 configured behaves exactly like the local-only store (safe degrade)", async () => {
const store = createDurableRunLogStore({ basePath: baseDir });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "local-only", ts: "t1" });
await store.finalize(handle);
const res = await store.read(handle);
expect(res.content).toContain("local-only");
// and a roll loses it (documented limitation; this is the pre-fix behaviour)
await fs.rm(baseDir, { recursive: true, force: true });
await expect(store.read(handle)).rejects.toThrow(/not found/i);
});
});
describe("in-flight mirror", () => {
it("is OFF by default: appends never upload before finalize", async () => {
const { provider, calls } = createMemoryProvider();
const store = createDurableRunLogStore({ basePath: baseDir, s3: { provider } });
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "tail-1", ts: "t1" });
await store.append(handle, { stream: "stdout", chunk: "tail-2", ts: "t2" });
await new Promise((resolve) => setTimeout(resolve, 50));
expect(calls.put).toBe(0);
// flush is a no-op with the mirror off
await store.flushInflightMirrors?.();
expect(calls.put).toBe(0);
});
it("mirrors the running log after the interval so a wipe without finalize preserves the tail", async () => {
const { provider, objects } = createMemoryProvider();
const store = createDurableRunLogStore({
basePath: baseDir,
s3: { provider, keyPrefix: "run-logs", inflightMirrorMs: 10 },
});
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "crash-tail", ts: "t1" });
const key = `run-logs/${handle.logRef}`;
await vi.waitFor(() => expect(objects.has(key)).toBe(true), { timeout: 2000 });
// Simulate a crash mid-run: local dir wiped, run never finalized.
await fs.rm(baseDir, { recursive: true, force: true });
const res = await store.read(handle);
expect(res.content).toContain("crash-tail");
});
it("throttles: rapid appends coalesce into one upload, delivered by flush", async () => {
const { provider, objects, calls } = createMemoryProvider();
// Interval far beyond the test's lifetime: nothing may upload until the
// flush, and the flush must carry every appended line in ONE put.
const store = createDurableRunLogStore({
basePath: baseDir,
s3: { provider, keyPrefix: "run-logs", inflightMirrorMs: 60_000 },
});
const handle = await store.begin(begin);
for (let i = 0; i < 5; i++) {
await store.append(handle, { stream: "stdout", chunk: `line-${i}`, ts: `t${i}` });
}
await new Promise((resolve) => setTimeout(resolve, 50));
expect(calls.put).toBe(0); // throttled: no per-append PUT
await store.flushInflightMirrors?.();
expect(calls.put).toBe(1);
const body = objects.get(`run-logs/${handle.logRef}`)!.toString("utf8");
for (let i = 0; i < 5; i++) expect(body).toContain(`line-${i}`);
// Nothing dirty afterwards: flushing again uploads nothing.
await store.flushInflightMirrors?.();
expect(calls.put).toBe(1);
});
it("finalize supersedes the in-flight mirror and retires its timer", async () => {
const { provider, objects, calls } = createMemoryProvider();
const store = createDurableRunLogStore({
basePath: baseDir,
s3: { provider, keyPrefix: "run-logs", inflightMirrorMs: 10 },
});
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "early-tail", ts: "t1" });
const key = `run-logs/${handle.logRef}`;
await vi.waitFor(() => expect(objects.has(key)).toBe(true), { timeout: 2000 });
await store.append(handle, { stream: "stdout", chunk: "final-line", ts: "t2" });
await store.finalize(handle);
const body = objects.get(key)!.toString("utf8");
expect(body).toContain("early-tail");
expect(body).toContain("final-line");
// No retired timer fires a stale partial upload over the finalized log.
const putsAfterFinalize = calls.put;
await new Promise((resolve) => setTimeout(resolve, 60));
expect(calls.put).toBe(putsAfterFinalize);
expect(objects.get(key)!.toString("utf8")).toContain("final-line");
});
it("shutdown flush re-checks dirtiness after an upload already on the wire completes", async () => {
const { provider, objects, calls } = createMemoryProvider();
let releaseFirstPut: (() => void) | null = null;
const firstPutGate = new Promise<void>((resolve) => {
releaseFirstPut = resolve;
});
let putStarts = 0;
const realPut = provider.putObject.bind(provider);
provider.putObject = async (input) => {
putStarts++;
if (putStarts === 1) await firstPutGate; // hold the first upload on the wire
return realPut(input);
};
const store = createDurableRunLogStore({
basePath: baseDir,
s3: { provider, keyPrefix: "run-logs", inflightMirrorMs: 10 },
});
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "mirrored-line", ts: "t1" });
await vi.waitFor(() => expect(putStarts).toBe(1), { timeout: 2000 });
// Re-dirty the entry while the first upload is still in flight.
await store.append(handle, { stream: "stdout", chunk: "tail-during-upload", ts: "t2" });
const flush = store.flushInflightMirrors!();
releaseFirstPut!();
await flush;
// A single-pass flush would exit after the first upload and leave the
// tail on an unref'ed timer that never fires once the process exits.
const body = objects.get(`run-logs/${handle.logRef}`)!.toString("utf8");
expect(body).toContain("tail-during-upload");
expect(calls.put).toBeGreaterThanOrEqual(2);
});
it("bounds the in-flight upload to the stat'ed size when appends race the stream", async () => {
const { provider, objects } = createMemoryProvider();
const store = createDurableRunLogStore({
basePath: baseDir,
s3: { provider, keyPrefix: "run-logs", inflightMirrorMs: 60_000 },
});
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "counted-line", ts: "t1" });
const absPath = path.join(baseDir, handle.logRef);
const sizeAtStat = (await fs.stat(absPath)).size;
// Grow the file between the mirror's stat() and its stream reaching EOF:
// the upload must carry exactly the stat'ed bytes, not the racing tail
// (an unbounded stream would violate the declared contentLength).
const realStat = fs.stat.bind(fs);
const statSpy = vi.spyOn(fs, "stat").mockImplementation(async (target, ...rest) => {
const result = await realStat(target as Parameters<typeof realStat>[0], ...(rest as []));
if (String(target).endsWith(".ndjson")) {
await fs.appendFile(absPath, `${JSON.stringify({ ts: "t2", stream: "stdout", chunk: "raced-append" })}\n`);
}
return result;
});
try {
await store.flushInflightMirrors!();
} finally {
statSpy.mockRestore();
}
const body = objects.get(`run-logs/${handle.logRef}`)!;
expect(body.length).toBe(sizeAtStat);
expect(body.toString("utf8")).toContain("counted-line");
expect(body.toString("utf8")).not.toContain("raced-append");
});
it("in-flight upload failures never break appends and recover on the next flush", async () => {
const { provider, objects, calls } = createMemoryProvider();
let failPuts = true;
const realPut = provider.putObject.bind(provider);
provider.putObject = async (input) => {
if (failPuts) throw new Error("endpoint down");
return realPut(input);
};
const warn = vi.spyOn(console, "warn").mockImplementation(() => {});
try {
const store = createDurableRunLogStore({
basePath: baseDir,
s3: { provider, keyPrefix: "run-logs", inflightMirrorMs: 60_000 },
});
const handle = await store.begin(begin);
await store.append(handle, { stream: "stdout", chunk: "survives-outage", ts: "t1" });
await store.flushInflightMirrors?.(); // upload fails, append flow unaffected
expect(warn).toHaveBeenCalled();
await store.append(handle, { stream: "stdout", chunk: "post-outage", ts: "t2" });
failPuts = false;
await store.flushInflightMirrors?.();
const body = objects.get(`run-logs/${handle.logRef}`)!.toString("utf8");
expect(body).toContain("survives-outage");
expect(body).toContain("post-outage");
expect(calls.put).toBe(1); // only the successful upload reached storage
} finally {
warn.mockRestore();
}
});
});