From 5dee4993f1352131a78048345f59c76c6c12ce94 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Tue, 3 Nov 2026 09:26:03 -0600 Subject: [PATCH] fix(server): distinguish aborted HTTP responses in access logs (#18781) ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work. > - Operators use HTTP logs to investigate task updates and database contention. > - Node starts each response with status 200 before it sends any headers. > - The custom HTTP formatter printed that status when the client disconnected before a response. > - This made an aborted request look like a successful task update. > - This pull request labels incomplete responses as aborted and preserves error severity. > - Operators can distinguish HTTP delivery from database commit evidence. ## Linked Issues or Issue Description - Refs: #18753. - Related: #14369 removes writes from legacy comment attribution reads. This change addresses a separate logging defect. The missing-write incident in #18753 remains unconfirmed. We reproduced a misleading `PATCH /issues/:id 200` log when the client received no HTTP response. We did not reproduce an HTTP 200 delivered before the mutation committed. ## What Changed - Label premature connection closure as `request aborted before response` or `request aborted during response` in both success and error log paths. - Log aborts as warnings, including on routes whose successful polling logs are normally silent. Keep explicit errors and 5xx responses at error severity. - Keep private webhook paths and query values out of aborted-request logs. - Add real HTTP disconnect coverage and real PostgreSQL task-update tests with synthetic data. - Document that HTTP completion logs do not establish database commit or rollback. ## Verification - Baseline: the new HTTP disconnect test failed because the log said `PATCH /api/issues/synthetic-task 200` at info level, while the client received no response. - `node node_modules/vitest/vitest.mjs run server/src/__tests__/http-log-aborted-response.test.ts server/src/__tests__/http-log-redaction.test.ts server/src/__tests__/issue-update-lock-contention-postgres.test.ts` passed: 81 tests in 3 files. - `pnpm -r typecheck` and `pnpm build` passed. The build used a second clean clone at the exact PR commit. - GitHub CI completed at `e3e96d836119df5fa1c7f22615484265de5aa700`: 52 checks passed and two Storybook checks were skipped. Greptile returned 5/5 with no findings. - Local `pnpm test:run` passed all six chat shards (1,834 tests). Its general server stage then reported four failures. We stopped the run after preserving these results and comparing the failing cases. The later workspace and serialized stages were not completed locally. The full local suite is not green. - The four observed failures were the two OAuth concurrency cases in `tool-access-service.test.ts`, the bounded workspace conflict case in `workspace-runtime.test.ts`, and the `enableNativeRunner`-disabled stop-control case in `muse-control.test.ts`. - Comparisons used the same sanitized environment on unchanged master `2b14ec03a48f17606db53fd7fc0edc53bc930409` and this PR. Both OAuth cases pass in isolation on both revisions. The full tool-access file passes all 498 tests on the PR; master has a different 15-second timeout, with 497 tests passing. The workspace case passes on the PR but fails port-reservation setup on master. The Muse case passes on both. These results do not explain or clear the original broad-suite OAuth and Muse failures. - Tested on macOS arm64, Node.js 26.4.0, pinned pnpm 9.15.4, and disposable embedded PostgreSQL. The API fixture uses a synthetic process-adapter agent. No model provider runs and no production database or real credentials participate. - The PostgreSQL fixture verifies an actual lock waiter with `pg_blocking_pids`. A blocked issue update does not return 200 before release. After release, status, monitor policy, inline comment, and audit receipt are persisted before the completed response. - Holding the company row with `FOR NO KEY UPDATE` does not block these fixture writes. They return 200 with persisted data while the compatible parent-row lock remains held. - An injected database trigger failure returns 500 and leaves the issue, comment, and mutation audit unchanged. Two influence-attempt receipts remain under the existing documented cap policy. - The combined lock/disconnect/failure test verifies no delivered response, an aborted log, and rollback after an injected database failure. The injected failure is not evidence of the reporter's production root cause. - Source inspection at release `v2026.1023.0` (`1b4c803816e82b0265c8422e1a804327a7ed8c54`) finds the same unconditional success formatter and awaited issue-update transaction. That release was not runtime-tested. ## Risks - Log consumers that parse the literal method/path/status message must handle the aborted-request message. - Client disconnects during streaming or SSE responses also use the aborted warning. Expected disconnects may therefore produce more warnings. - A disconnected request may still commit after the client leaves. This change reports transport completion and does not cancel or retry mutations. - This PR does not close #18753. The original missing-write cause and a received-200-without-commit scenario remain unconfirmed. - Local full-suite failures remain unresolved despite green CI. Keep this PR in draft until that verification gap is accepted or resolved. > This is a targeted bug fix. ROADMAP.md does not list overlapping feature work. ## Model Used - OpenAI GPT-6 through Codex, with reasoning, tool use, code execution, and parallel subagent investigation. - The exact runtime model ID and context window size were not exposed to the agent. ## 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 - [ ] I have run tests locally and they pass - [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 --- doc/DATABASE.md | 7 + .../http-log-aborted-response.test.ts | 99 +++++++++ ...ue-update-lock-contention-postgres.test.ts | 204 ++++++++++++++++++ server/src/middleware/logger.ts | 13 +- 4 files changed, 321 insertions(+), 2 deletions(-) create mode 100644 server/src/__tests__/http-log-aborted-response.test.ts create mode 100644 server/src/__tests__/issue-update-lock-contention-postgres.test.ts diff --git a/doc/DATABASE.md b/doc/DATABASE.md index 9fcab3a9737..13b2aad680e 100644 --- a/doc/DATABASE.md +++ b/doc/DATABASE.md @@ -642,6 +642,13 @@ See [Supabase pricing](https://supabase.com/pricing) for current details. ## Connection loss and retries +HTTP access logs distinguish a completed response from a connection that closes +before or during the response. An aborted request has no success status in the +log message. The structured response status is null when headers were not sent; +after headers, it retains the status sent before the abort. These logs describe +HTTP delivery, not database settlement. A disconnected issue PATCH may continue +running, so an aborted response does not prove that its writes rolled back. + The database client does not replay arbitrary statements after a disconnect. PostgreSQL may have committed a statement before the connection loses its response. The postgres.js message `write CONNECTION_CLOSED` does not prove diff --git a/server/src/__tests__/http-log-aborted-response.test.ts b/server/src/__tests__/http-log-aborted-response.test.ts new file mode 100644 index 00000000000..3a8b370ca18 --- /dev/null +++ b/server/src/__tests__/http-log-aborted-response.test.ts @@ -0,0 +1,99 @@ +import { createServer, request as httpRequest } from "node:http"; +import { Writable } from "node:stream"; +import express from "express"; +import pino from "pino"; +import request from "supertest"; +import { describe, expect, it } from "vitest"; +import { createHttpLogger } from "../middleware/logger.js"; + +async function captureAbortedRequest(input: { path: string; method?: string; partialResponse?: boolean; error?: boolean; status?: number }) { + const logs: Array> = []; + const stream = new Writable({ + write(chunk, _encoding, callback) { + logs.push(JSON.parse(chunk.toString())); + callback(); + }, + }); + const app = express(); + app.use(createHttpLogger(pino(stream))); + const started = Promise.withResolvers(); + const release = Promise.withResolvers(); + const finished = Promise.withResolvers(); + app.use(async (_req, res) => { + if (input.error) (res as any).err = new Error("Synthetic response failure"); + if (input.status) res.status(input.status); + if (input.partialResponse) res.write("Partial response"); + started.resolve(); + await release.promise; + res.end(JSON.stringify({ status: "in_review" })); + finished.resolve(); + }); + const server = createServer(app); + await new Promise(resolve => server.listen(0, "127.0.0.1", resolve)); + const address = server.address(); + if (!address || typeof address === "string") throw new Error("Missing test listener"); + let receivedResponse = false; + const client = httpRequest({ hostname: "127.0.0.1", port: address.port, + path: input.path, method: input.method ?? "PATCH" }, res => { + receivedResponse = true; + if (input.partialResponse) client.destroy(); + res.resume(); + }); + client.on("error", () => undefined); + try { + client.end(); + await started.promise; + if (!input.partialResponse) client.destroy(); + await expect.poll(() => logs.length, { timeout: 3_000 }).toBe(1); + } finally { + client.destroy(); + release.resolve(); + await finished.promise; + await new Promise((resolve, reject) => server.close(error => error ? reject(error) : resolve())); + } + expect(logs).toHaveLength(1); + return { log: logs[0], receivedResponse }; +} + +describe("HTTP response completion logging", () => { + it.each(["/api/issues/synthetic-task", "/api/health"])("does not record a successful status before a response for %s", async path => { + const method = path === "/api/health" ? "GET" : "PATCH"; + const { log, receivedResponse } = await captureAbortedRequest({ path, method }); + expect(receivedResponse).toBe(false); + expect(log).toMatchObject({ level: 40, msg: `${method} ${path} — request aborted before response`, res: { statusCode: null } }); + }); + + it("distinguishes an incomplete response from a completed 200", async () => { + const { log, receivedResponse } = await captureAbortedRequest({ path: "/api/issues/synthetic-task", partialResponse: true }); + expect(receivedResponse).toBe(true); + expect(log).toMatchObject({ level: 40, msg: "PATCH /api/issues/synthetic-task — request aborted during response", res: { statusCode: 200 } }); + }); + + it.each([{ error: true }, { status: 503 }])("keeps error severity on an aborted response (%j)", async fault => { + const { log, receivedResponse } = await captureAbortedRequest({ path: "/api/issues/synthetic-task", ...fault }); + expect(receivedResponse).toBe(false); + expect(log).toMatchObject({ level: 50, msg: "PATCH /api/issues/synthetic-task — request aborted before response", res: { statusCode: null } }); + }); + + it.each([false, true])("keeps webhook paths and query values private when a response aborts (error=%s)", async error => { + const { log } = await captureAbortedRequest({ path: "/api/chat-webhooks/private-path-canary/slack?token=private-token-canary", error }); + expect(log.msg).toBe("PATCH /api/chat-webhooks/:publicId/:provider — request aborted before response"); + expect(JSON.stringify(log)).not.toContain("private-path-canary"); + expect(JSON.stringify(log)).not.toContain("private-token-canary"); + }); + + it("keeps completed success responses unchanged", async () => { + const logs: Array> = []; + const stream = new Writable({ write(chunk, _encoding, callback) { + logs.push(JSON.parse(chunk.toString())); + callback(); + } }); + const app = express(); + app.use(createHttpLogger(pino(stream))); + app.patch("/api/issues/synthetic-task", (_req, res) => res.json({ ok: true })); + await request(app).patch("/api/issues/synthetic-task").expect(200); + expect(logs[0]).toMatchObject({ level: 30, + msg: "PATCH /api/issues/synthetic-task 200", res: { statusCode: 200 } }); + expect(logs[0].res).not.toHaveProperty("responseCompleted"); + }); +}); diff --git a/server/src/__tests__/issue-update-lock-contention-postgres.test.ts b/server/src/__tests__/issue-update-lock-contention-postgres.test.ts new file mode 100644 index 00000000000..b4922193784 --- /dev/null +++ b/server/src/__tests__/issue-update-lock-contention-postgres.test.ts @@ -0,0 +1,204 @@ +import { randomUUID } from "node:crypto"; +import { createServer, request as httpRequest } from "node:http"; +import { Writable } from "node:stream"; +import express, { type ErrorRequestHandler } from "express"; +import pino, { type Logger } from "pino"; +import request from "supertest"; +import { and, eq, sql } from "drizzle-orm"; +import { afterAll, beforeAll, describe, expect, it } from "vitest"; +import { activityLog, agents, companies, createDb, heartbeatRuns, issueComments, issues } from "@paperclipai/db"; +import { errorHandler } from "../middleware/index.js"; +import { issueRoutes } from "../routes/issues.js"; +import { createHttpLogger } from "../middleware/logger.js"; +import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "./helpers/embedded-postgres.js"; + +const support = await getEmbeddedPostgresTestSupport(); +const describePostgres = support.supported ? describe : describe.skip; + +describePostgres("issue PATCH response under PostgreSQL lock contention", () => { + let db: ReturnType; + let temporary: Awaited>; + + beforeAll(async () => { + temporary = await startEmbeddedPostgresTestDatabase("paperclip-issue-write-lock-"); + db = createDb(temporary.connectionString); + }, 90_000); + + afterAll(async () => { + await db?.$client.end(); + await temporary?.cleanup(); + }); + + async function fixture(options: { httpLogger?: Logger; onError?: () => void } = {}) { + const companyId = randomUUID(), agentId = randomUUID(), runId = randomUUID(); + const sourceIssueId = randomUUID(), targetIssueId = randomUUID(); + await db.insert(companies).values({ id: companyId, name: "Synthetic lock test", issuePrefix: `L${companyId.slice(0, 7)}` }); + await db.insert(agents).values({ id: agentId, companyId, name: "Synthetic worker", role: "engineer", + adapterType: "process", adapterConfig: {}, runtimeConfig: { heartbeat: { enabled: false } }, permissions: {} }); + await db.insert(issues).values([ + { id: sourceIssueId, companyId, title: "Source task", status: "in_progress", assigneeAgentId: agentId }, + { id: targetIssueId, companyId, title: "Target task", status: "blocked", assigneeAgentId: agentId }, + ]); + await db.insert(heartbeatRuns).values({ id: runId, companyId, agentId, status: "running", + contextSnapshot: { issueId: sourceIssueId } }); + const app = express(); + if (options.httpLogger) app.use(createHttpLogger(options.httpLogger)); + app.use(express.json()); + app.use((req, _res, next) => { + (req as any).actor = { type: "agent", source: "agent_key", companyId, agentId, runId }; + next(); + }); + app.use("/api", issueRoutes(db, {} as any, {})); + if (options.onError) app.use(((error, _req, _res, next) => { + options.onError?.(); + next(error); + }) as ErrorRequestHandler); + app.use(errorHandler); + return { app, companyId, agentId, runId, targetIssueId }; + } + + const body = { status: "in_review", executionPolicy: { monitor: { + nextCheckAt: "2099-12-01T12:00:00.000Z", notes: "Synthetic monitor" } }, comment: "Synthetic check complete" }; + + it.each(["issue", "company"])("returns 200 only for persisted writes while the %s row is locked", async lockedTable => { + const f = await fixture(); + const locked = Promise.withResolvers(), release = Promise.withResolvers(); + let blockerPid = 0; + const blocker = db.transaction(async tx => { + const [backend] = await tx.execute(sql`select pg_backend_pid() as pid`); + blockerPid = Number(backend.pid); + if (lockedTable === "issue") { + await tx.select().from(issues).where(eq(issues.id, f.targetIssueId)).for("no key update"); + } else { + await tx.select().from(companies).where(eq(companies.id, f.companyId)).for("no key update"); + } + locked.resolve(); + await release.promise; + }); + await locked.promise; + let responded = false; + const mutation = request(f.app).patch(`/api/issues/${f.targetIssueId}`).send(body).timeout({ deadline: 5_000 }) + .then(response => { responded = true; return response; }); + try { + await expect.poll(async () => (await db.select().from(activityLog).where(and( + eq(activityLog.runId, f.runId), eq(activityLog.action, "issue.cross_issue_influence_observed"), + ))).length).toBe(2); + if (lockedTable === "issue") { + await expect.poll(async () => { + const [waiting] = await db.execute(sql`select count(*)::int as count from pg_stat_activity + where datname = current_database() and ${blockerPid} = any(pg_blocking_pids(pid))`); + return Number(waiting.count); + }).toBeGreaterThan(0); + expect(responded).toBe(false); + expect((await db.select().from(issues).where(eq(issues.id, f.targetIssueId)))[0].status).toBe("blocked"); + expect(await db.select().from(issueComments).where(eq(issueComments.issueId, f.targetIssueId))).toHaveLength(0); + } else { + expect((await mutation).status).toBe(200); + expect((await db.select().from(issues).where(eq(issues.id, f.targetIssueId)))[0].status).toBe("in_review"); + } + } finally { + release.resolve(); + await blocker; + } + const response = await mutation; + expect(response.status, JSON.stringify(response.body)).toBe(200); + const [persisted] = await db.select().from(issues).where(eq(issues.id, f.targetIssueId)); + expect(persisted.status).toBe("in_review"); + expect(persisted.executionPolicy).toMatchObject(body.executionPolicy); + expect(await db.select().from(issueComments).where(eq(issueComments.issueId, f.targetIssueId))) + .toMatchObject([{ body: body.comment }]); + expect(await db.select().from(activityLog).where(and( + eq(activityLog.entityId, f.targetIssueId), eq(activityLog.action, "issue.updated"), + ))).toHaveLength(1); + }); + + it("returns an error when the database rejects the issue write", async () => { + const f = await fixture(); + await db.execute(sql`create function reject_synthetic_issue_write() returns trigger language plpgsql as $$ + begin raise exception 'synthetic issue write rejected'; end $$`); + await db.execute(sql`create trigger reject_synthetic_issue_write before update on issues + for each row execute function reject_synthetic_issue_write()`); + let response; + try { + response = await request(f.app).patch(`/api/issues/${f.targetIssueId}`).send(body); + } finally { + await db.execute(sql`drop trigger reject_synthetic_issue_write on issues`); + await db.execute(sql`drop function reject_synthetic_issue_write()`); + } + expect(response.status).toBe(500); + expect((await db.select().from(issues).where(eq(issues.id, f.targetIssueId)))[0].status).toBe("blocked"); + expect(await db.select().from(issueComments).where(eq(issueComments.issueId, f.targetIssueId))).toHaveLength(0); + expect(await db.select().from(activityLog).where(and( + eq(activityLog.runId, f.runId), eq(activityLog.action, "issue.cross_issue_influence_observed"), + ))).toHaveLength(2); + expect(await db.select().from(activityLog).where(and( + eq(activityLog.entityId, f.targetIssueId), eq(activityLog.action, "issue.updated"), + ))).toHaveLength(0); + }); + + it("records an abort, not HTTP 200, when a blocked write fails after the client disconnects", async () => { + const logs: Array> = []; + const stream = new Writable({ write(chunk, _encoding, callback) { + logs.push(JSON.parse(chunk.toString())); + callback(); + } }); + let failed = false; + const f = await fixture({ httpLogger: pino(stream), onError: () => { failed = true; } }); + await db.execute(sql`create function reject_disconnected_issue_write() returns trigger language plpgsql as $$ + begin raise exception 'synthetic disconnected issue write rejected'; end $$`); + await db.execute(sql`create trigger reject_disconnected_issue_write before update on issues + for each row execute function reject_disconnected_issue_write()`); + const locked = Promise.withResolvers(), release = Promise.withResolvers(); + let blockerPid = 0; + const blocker = db.transaction(async tx => { + const [backend] = await tx.execute(sql`select pg_backend_pid() as pid`); + blockerPid = Number(backend.pid); + await tx.select().from(issues).where(eq(issues.id, f.targetIssueId)).for("no key update"); + locked.resolve(); + await release.promise; + }); + const server = createServer(f.app); + await new Promise(resolve => server.listen(0, "127.0.0.1", resolve)); + const address = server.address(); + if (!address || typeof address === "string") throw new Error("Missing test listener"); + let receivedResponse = false; + const client = httpRequest({ hostname: "127.0.0.1", port: address.port, + path: `/api/issues/${f.targetIssueId}`, method: "PATCH", headers: { "content-type": "application/json" } }, res => { + receivedResponse = true; + res.resume(); + }); + client.on("error", () => undefined); + try { + await locked.promise; + client.end(JSON.stringify(body)); + await expect.poll(async () => { + const [waiting] = await db.execute(sql`select count(*)::int as count from pg_stat_activity + where datname = current_database() and ${blockerPid} = any(pg_blocking_pids(pid))`); + return Number(waiting.count); + }).toBeGreaterThan(0); + client.destroy(); + await expect.poll(() => logs.length, { timeout: 3_000 }).toBe(1); + expect(receivedResponse).toBe(false); + expect(logs).toMatchObject([{ level: 40, + msg: `PATCH /issues/${f.targetIssueId} — request aborted before response`, res: { statusCode: null } }]); + release.resolve(); + await blocker; + await expect.poll(() => failed).toBe(true); + expect((await db.select().from(issues).where(eq(issues.id, f.targetIssueId)))[0].status).toBe("blocked"); + expect(await db.select().from(issueComments).where(eq(issueComments.issueId, f.targetIssueId))).toHaveLength(0); + expect(await db.select().from(activityLog).where(and( + eq(activityLog.runId, f.runId), eq(activityLog.action, "issue.cross_issue_influence_observed"), + ))).toHaveLength(2); + expect(await db.select().from(activityLog).where(and( + eq(activityLog.entityId, f.targetIssueId), eq(activityLog.action, "issue.updated"), + ))).toHaveLength(0); + } finally { + client.destroy(); + release.resolve(); + await blocker; + await new Promise((resolve, reject) => server.close(error => error ? reject(error) : resolve())); + await db.execute(sql`drop trigger reject_disconnected_issue_write on issues`); + await db.execute(sql`drop function reject_disconnected_issue_write()`); + } + }); +}); diff --git a/server/src/middleware/logger.ts b/server/src/middleware/logger.ts index 6ca42fa3532..21b8981757d 100644 --- a/server/src/middleware/logger.ts +++ b/server/src/middleware/logger.ts @@ -1,4 +1,5 @@ import pino from "pino"; +import type { IncomingMessage, ServerResponse } from "node:http"; import type { Logger } from "pino"; import { pinoHttp } from "pino-http"; import { HTTP_LOG_REDACT_PATHS } from "./http-log-redaction.js"; @@ -83,6 +84,11 @@ function requestLogUrl(req: { : stripSecretBearingUrlParts(typeof req.url === "string" ? req.url : ""); } +function abortedRequestMessage(req: IncomingMessage, res: ServerResponse) { + if (!req.readableAborted && res.writableFinished) return null; + return `${req.method} ${requestLogUrl(req)} — request aborted${res.headersSent ? " during response" : " before response"}`; +} + export function createHttpLogger(baseLogger: Logger) { return pinoHttp({ logger: baseLogger, @@ -137,17 +143,20 @@ export function createHttpLogger(baseLogger: Logger) { }, }, customLogLevel(_req, res, err) { + if (err || (res as ServerResponse & { err?: unknown }).err || res.statusCode >= 500) return "error"; + if (_req.readableAborted || !res.writableFinished) return "warn"; if (shouldSilenceHttpSuccessLog(_req.method, _req.url, res.statusCode)) { return "silent"; } - if (err || res.statusCode >= 500) return "error"; if (res.statusCode >= 400) return "warn"; return "info"; }, customSuccessMessage(req, res) { - return `${req.method} ${requestLogUrl(req)} ${res.statusCode}`; + return abortedRequestMessage(req, res) ?? `${req.method} ${requestLogUrl(req)} ${res.statusCode}`; }, customErrorMessage(req, res, err) { + const abortedMessage = abortedRequestMessage(req, res); + if (abortedMessage) return abortedMessage; if ( isSecretSensitiveHttpRequest(req.method, requestClassificationUrl(req)) ) {