diff --git a/.npmrc b/.npmrc index 90668dc7..00f9e7a4 100644 --- a/.npmrc +++ b/.npmrc @@ -2,4 +2,4 @@ # Overrides global `omit=dev` so `npm ci` installs everything needed # for `npm run typecheck` and `npm run test` to work from a clean checkout. # CAUTION: include=dev overrides --omit=dev (npm config precedence), which is why scripts.audit passes an explicit --include=prod. See package.json "//".audit, SECURITY-ACCEPTED-RISKS.md, and #1166. -include=dev +include=dev \ No newline at end of file diff --git a/AGENTS.md b/AGENTS.md index fce65a86..f5026838 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -317,6 +317,8 @@ The `tasks/report` endpoint accepts these outcomes: Queue-backed `followup-pr` reports must echo the `prFixItem.{id, generation}` token issued by `next-task` on the task. Reports without it still record the AgentRun, but never settle PR-fix queue state — the item stays queued and the report is a no-op against the queue (#1074). +The report body also accepts an optional `startedAt` — an extended ISO 8601 timestamp with timezone (`Z` or `±HH:MM`), for example `2026-10-03T04:20:58Z` or `2026-10-03T04:20:58.123456+00:00`, marking when the worker began the task. When it parses, is not in the future, and is no more than 24 hours before the report, it is stored as the run's start time so the run records a real duration; missing, malformed, future, or too-old values silently fall back to the report time (never a 400). The raw body value participates in the idempotency payload identity, so an identical-body retry always replays as a duplicate. An accepted `startedAt` is normalized to UTC (`Z`) form when stored and echoed back in the response. The echo reflects re-validation of the current request, so on an idempotent duplicate replay the echoed `startedAt` may be absent even though the original accepted run stored it — for example when an identical-body retry lands more than 24 hours after the reported start (the stored AgentRun is unaffected). + #### Idempotent reporting (optional) `tasks/report` accepts an optional `idempotencyKey` (opaque string, trimmed, at most 200 characters). When present, `(agentName, idempotencyKey)` uniquely identifies the logical report: a retried request with the same key and the same payload returns the original `agentRunId` (with `duplicate: true`) without creating another `AgentRun` or re-running PR-fix resolution — the stored resolution is replayed when it has been persisted, and while the original report is still completing (or if its persistence failed) the retry receives an explicit `action: "skipped"` resolution instead; side effects are never repeated either way. Reusing the same key with a different payload is rejected with `409`, as is a claim that exists without a recorded result (only possible if the referenced run was deleted). An unexpected persistence failure returns a structured `500` — a worker that retries after it lands in the duplicate branch above. If a referenced `AgentRun` is later deleted, its claim stays behind and further retries with that key return `409`; the recovery is for the worker to proceed under a fresh key, or for an operator to delete the stale `AgentReportDedupe` row. Reports that omit the key keep the current at-least-once behavior. Workers that may crash between reporting and recording the result locally should derive the key from a durable per-run identity (for example `":"`); Dispatch treats the value as fully opaque. Keys are persisted in Dispatch's database — do not embed secrets or personal data in them. diff --git a/src/app/api/agents/[agentName]/tasks/report/route.test.ts b/src/app/api/agents/[agentName]/tasks/report/route.test.ts index 15fb09f6..1b43f21b 100644 --- a/src/app/api/agents/[agentName]/tasks/report/route.test.ts +++ b/src/app/api/agents/[agentName]/tasks/report/route.test.ts @@ -730,6 +730,314 @@ describe("POST /api/agents/[agentName]/tasks/report — AgentRun persistence", ( }); }); +describe("POST /api/agents/[agentName]/tasks/report — startedAt (#1120)", () => { + beforeEach(() => { + delete process.env.DISPATCH_AUTH_MODE; + resetAuthCaches(); + vi.clearAllMocks(); + }); + + it("stores a valid worker-reported startedAt as the run start (duration > 0)", async () => { + const startInstant = new Date(Date.now() - 60 * 60 * 1000); + const startedAtIso = startInstant.toISOString(); + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: startedAtIso, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt).toBeInstanceOf(Date); + expect(call.startedAt.getTime()).toBe(startInstant.getTime()); + expect(call.finishedAt).toBeInstanceOf(Date); + expect(call.finishedAt.getTime()).toBeGreaterThanOrEqual(call.startedAt.getTime()); + expect(call.finishedAt.getTime() - call.startedAt.getTime()).toBeGreaterThan(0); + }); + + it("falls back to the report time when startedAt is missing (startedAt ≈ finishedAt)", async () => { + const before = Date.now(); + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + }); + const after = Date.now(); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt).toBeInstanceOf(Date); + expect(call.finishedAt).toBeInstanceOf(Date); + // Same instant: both collapse to the report time. + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + expect(call.finishedAt.getTime()).toBeGreaterThanOrEqual(before); + expect(call.finishedAt.getTime()).toBeLessThanOrEqual(after); + }); + + it("falls back to the report time when startedAt is a malformed string", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: "not-a-date", + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + }); + + it("falls back to the report time when startedAt is a number (no 400)", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: 123, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + }); + + it("falls back to the report time when startedAt is an object (no 400)", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: {}, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + }); + + it("falls back to the report time when startedAt is an empty string", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: "", + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + }); + + it("falls back to the report time when startedAt is in the future", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: new Date(Date.now() + 60 * 60 * 1000).toISOString(), + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + }); + + it("falls back to the report time when startedAt is older than 24h", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: new Date(Date.now() - 25 * 60 * 60 * 1000).toISOString(), + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(call.finishedAt.getTime()); + }); + + it("accepts a startedAt ~23h old (24h bound is not over-eager)", async () => { + const startInstant = new Date(Date.now() - 23 * 60 * 60 * 1000); + const startedAtIso = startInstant.toISOString(); + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: startedAtIso, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt.getTime()).toBe(startInstant.getTime()); + expect(call.finishedAt.getTime() - call.startedAt.getTime()).toBeGreaterThan(0); + }); + + it("echoes the normalized startedAt in the response for a valid value", async () => { + const startInstant = new Date(Date.now() - 60 * 60 * 1000); + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: startInstant.toISOString(), + }); + + expect(res.status).toBe(200); + const body = await res.json(); + expect(body.report.startedAt).toBe(startInstant.toISOString()); + }); + + it("omits startedAt from the response when the value is invalid", async () => { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: "not-a-date", + }); + + expect(res.status).toBe(200); + const body = await res.json(); + expect(body.report.startedAt).toBeUndefined(); + }); + + it("reports differing only by startedAt hash to distinct idempotency payload hashes", async () => { + const base = { + taskType: "implement", + outcome: "pr_opened", + idempotencyKey: "worker-run-1:report", + }; + const first = await postRequest({ + ...base, + startedAt: new Date(Date.now() - 60 * 60 * 1000).toISOString(), + }); + const second = await postRequest({ + ...base, + startedAt: new Date(Date.now() - 120 * 60 * 60 * 1000).toISOString(), + }); + + expect(first.status).toBe(200); + expect(second.status).toBe(200); + expect(mockDedupe.create).toHaveBeenCalledTimes(2); + const hashA = mockDedupe.create.mock.calls[0][0].data.payloadHash; + const hashB = mockDedupe.create.mock.calls[1][0].data.payloadHash; + expect(hashA).not.toBe(hashB); + }); + + it("falls back to the report time for malformed formats (bare-year, date-only, locale string)", async () => { + const malformedFormats = ["2026", "2026-10-02", "10/02/2026 12:00"]; + + for (const startedAt of malformedFormats) { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls.at(-1)![0].data; + expect(call.startedAt).toBeInstanceOf(Date); + expect(call.finishedAt).toBeInstanceOf(Date); + // Malformed → collapsed to the report time: within ~2s of finishedAt. + expect(Math.abs(call.startedAt.getTime() - call.finishedAt.getTime())).toBeLessThan(2000); + // And the response must not echo the malformed value. + const body = await res.json(); + expect(body.report.startedAt).toBeUndefined(); + } + }); + + it("accepts a python-isoformat offset (+00:00) as a valid startedAt", async () => { + const startInstant = new Date(Date.now() - 2 * 60 * 60 * 1000); + const pythonIso = startInstant.toISOString().replace("Z", "+00:00"); + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: pythonIso, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt).toBeInstanceOf(Date); + expect(call.startedAt.getTime()).toBe(startInstant.getTime()); + }); + + it("accepts a non-zero UTC offset (+05:30) and stores the normalized UTC instant", async () => { + const startInstant = new Date(Date.now() - 2 * 60 * 60 * 1000); + // Same instant rendered in a +05:30 zone: shift the UTC clock by the + // offset and tag the reading with it. + const shifted = new Date(startInstant.getTime() + 5.5 * 60 * 60 * 1000); + const startedAt = shifted.toISOString().replace("Z", "+05:30"); + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt).toBeInstanceOf(Date); + // Proves TZ conversion, not just acceptance: the stored instant equals + // the UTC reading, not the +05:30 clock reading. + expect(call.startedAt.toISOString()).toBe(startInstant.toISOString()); + }); + + it("accepts a startedAt exactly 24h old (24h bound is inclusive)", async () => { + const T0 = new Date("2026-10-03T12:00:00Z").getTime(); + const startedAtIso = new Date(T0 - 24 * 60 * 60 * 1000).toISOString(); + + vi.useFakeTimers({ now: T0 }); + try { + const res = await postRequest({ + taskType: "implement", + outcome: "pr_opened", + startedAt: startedAtIso, + }); + + expect(res.status).toBe(200); + const call = mockAgentRun.create.mock.calls[0][0].data; + expect(call.startedAt).toBeInstanceOf(Date); + expect(call.startedAt.getTime()).toBe(T0 - 24 * 60 * 60 * 1000); + // Accepted: the run kept the worker-reported start, not the report + // time (a fallback would collapse startedAt onto finishedAt). + expect(call.startedAt.getTime()).not.toBe(call.finishedAt.getTime()); + } finally { + vi.useRealTimers(); + } + }); + + it("an identical-body retry keeps the same payload hash across the 24h boundary (duplicate, not 409)", async () => { + const T0 = new Date("2026-10-03T12:00:00Z").getTime(); + const startedAtIso = new Date(T0 - 23 * 60 * 60 * 1000).toISOString(); + const body = { + taskType: "implement", + outcome: "issue_updated", + idempotencyKey: "key-stability", + startedAt: startedAtIso, + }; + + vi.useFakeTimers({ now: T0 }); + try { + const first = await postRequest(body); + expect(first.status).toBe(200); + const payloadHash = mockDedupe.create.mock.calls[0][0].data.payloadHash; + + // 25h later: the same startedAt string is now 48h old and no longer + // accepted, so the validated report changes — but the RAW-body hash + // must stay the same, so the retry dedupes instead of 409ing. + vi.setSystemTime(T0 + 25 * 60 * 60 * 1000); + + mockDedupe.create.mockRejectedValueOnce( + new Prisma.PrismaClientKnownRequestError("Unique constraint failed", { + code: "P2002", + clientVersion: "test", + }), + ); + mockDedupe.findUnique.mockResolvedValueOnce({ + id: "claim-1", + agentName: "test-agent", + idempotencyKey: "key-stability", + payloadHash, + agentRunId: "run-1", + prFixResolution: null, + }); + + const retry = await postRequest(body); + + expect(retry.status).toBe(200); + expect(retry.status).not.toBe(409); + const retryBody = await retry.json(); + expect(retryBody.duplicate).toBe(true); + expect(retryBody.agentRunId).toBe("run-1"); + } finally { + vi.useRealTimers(); + } + }); +}); + describe("POST /api/agents/[agentName]/tasks/report — idempotencyKey", () => { beforeEach(() => { delete process.env.DISPATCH_AUTH_MODE; diff --git a/src/app/api/agents/[agentName]/tasks/report/route.ts b/src/app/api/agents/[agentName]/tasks/report/route.ts index b14f8226..a47a7326 100644 --- a/src/app/api/agents/[agentName]/tasks/report/route.ts +++ b/src/app/api/agents/[agentName]/tasks/report/route.ts @@ -32,6 +32,11 @@ export interface TaskReportBody { error?: string; // #1121: evidence string (commit SHAs / paths) carried by an already_addressed report; recorded in settlement history. evidence?: string; + // #1120: worker-reported task start time (ISO 8601). Accepted only when + // parseable, not in the future, and within 24h of the report; otherwise + // omitted and the report time is used. It participates in the idempotency + // payload hash like the other fields. + startedAt?: string; // The (id, generation) attempt token next-task issued on this followup-pr // task, echoed back by the worker (#1074). Required for PR-fix queue // settlement; part of the report's payload identity (idempotency hash). @@ -44,6 +49,30 @@ function deriveStatus(outcome: ValidOutcome): string { return "completed"; } +// #1120: optional worker-reported start time. Accepted only when it is a +// string that parses to a real date, is not in the future, and is no more +// than MAX_STARTED_AT_AGE_MS before the report; anything else silently falls +// back to the report time so a clock-skewed or bogus value can never produce +// a negative or absurd duration. +const MAX_STARTED_AT_AGE_MS = 24 * 60 * 60 * 1000; + +// Require an extended ISO 8601 timestamp with timezone (Z or ±HH:MM), e.g. +// 2026-10-03T04:20:58Z or 2026-10-03T04:20:58.123456+00:00 (Python isoformat). +// Date-only, bare-year, and locale-ambiguous strings are malformed → fallback. +const ISO_8601_TIMESTAMP_PATTERN = + /^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}(:\d{2}(\.\d+)?)?(Z|[+-]\d{2}:\d{2})$/; + +function resolveReportedStartedAt(rawStartedAt: unknown, now: Date): string | undefined { + if (typeof rawStartedAt !== "string") return undefined; + if (!ISO_8601_TIMESTAMP_PATTERN.test(rawStartedAt)) return undefined; + const parsed = new Date(rawStartedAt); + const time = parsed.getTime(); + if (Number.isNaN(time)) return undefined; + if (time > now.getTime()) return undefined; + if (now.getTime() - time > MAX_STARTED_AT_AGE_MS) return undefined; + return parsed.toISOString(); +} + async function resolveIssueId( repoFullName: string | undefined, issueNumber: number | undefined, @@ -97,8 +126,10 @@ function canonicalJson(value: unknown): string { return `{${entries.map(([k, v]) => `${JSON.stringify(k)}:${canonicalJson(v)}`).join(",")}}`; } -function reportPayloadHash(report: TaskReportBody): string { - return createHash("sha256").update(canonicalJson(report)).digest("hex"); +function reportPayloadHash( + payload: Omit & { startedAt?: unknown }, +): string { + return createHash("sha256").update(canonicalJson(payload)).digest("hex"); } function isUniqueViolation(error: unknown): boolean { @@ -207,6 +238,10 @@ export async function POST( } : undefined; + // #1120: computed once before the report so the same instant is used for + // startedAt validation and finishedAt. + const now = new Date(); + const report: TaskReportBody = { taskType: taskType as ValidTaskType, outcome: outcome as ValidOutcome, @@ -217,6 +252,8 @@ export async function POST( summary: raw.summary as string | undefined, error: raw.error as string | undefined, evidence, + // #1120: normalized worker start time; undefined → report time (now). + startedAt: resolveReportedStartedAt(raw.startedAt, now), prFixItem, }; @@ -228,12 +265,12 @@ export async function POST( const touchedIssueUrls = buildTouchedUrls(report); // Persist AgentRun - const now = new Date(); const runData = { agentName, runType: report.taskType, status: deriveStatus(report.outcome), - startedAt: now, + // #1120: worker-reported start time when valid, else the report time. + startedAt: report.startedAt ? new Date(report.startedAt) : now, finishedAt: now, summary: report.summary, errorMessage: report.error, @@ -251,7 +288,10 @@ export async function POST( // concurrent or retried report with the same (agentName, idempotencyKey) // loses the unique-index race (P2002) and replays the stored result // instead of re-running the report or its side effects. - const payloadHash = reportPayloadHash(report); + // #1120/#1044: hash the RAW body value, not the time-validated one, so an + // identical-body retry keeps the same payload identity even when + // startedAt's acceptance flips across the 24h boundary between attempts. + const payloadHash = reportPayloadHash({ ...report, startedAt: raw.startedAt }); try { run = await prisma.$transaction(async (tx) => { const claim = await tx.agentReportDedupe.create({