From b110271c9b2fd6dd5a1beb119e7f0663385df8b9 Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Sat, 31 Oct 2026 20:40:35 -0500 Subject: [PATCH] test: observe GitHub enrollment after worker settlement (#18506) ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work. > - GitHub connection events use a worker that must return to quiet after it drains an event. > - The integration test checks that work with real PostgreSQL and signed loopback requests. > - The loopback server can receive an ACK before the worker completes that request. > - The test reads the next deadline too early and can reject valid work in progress. > - This pull request waits for the observed work state without moving the fake clock. > - It keeps the exact work counts, identity checks, deadline bound and quietness checks. ## Linked Issues or Issue Description Refs #18395 and #18351. This is a test-only repair for the event-worker integration fixture. **What happened?** [CI run 41257779002](https://github.com/paperclipai/paperclip/actions/runs/41257779002/job/124704574485) failed at the replacement follow-up deadline assertion. `coordinator.nextWakeAt()` was `null` after the server received the second ACK. The worker can still be waiting for that ACK response at this point. **Expected behavior** Wait for the worker to expose a deadline or finish the exact expected follow-up. Do not drive fake time during an observation. Require the scheduled follow-up to stay within five seconds of the first observation. Keep one empty follow-up, the new identity and no I/O after the worker becomes quiet. **Steps to reproduce** 1. Run the existing enrollment integration test on the original CI merge `a1e25444a95f3698c3761cd1796bd1e11567224c`. 2. Hold only the second loopback ACK response after its server counter increments. 3. The original deadline assertion fails while the worker remains active. **Paperclip version or commit** The causal control used the exact CI merge above. This repair starts from verified master `66e8fab9447aa21350f87ddec79fcd027f3e23ad`. The fixture and relevant worker files match the earlier `b889` inputs. The original failure remains preserved. The controlled race does not prove the unique historical scheduling of that CI attempt. ## What Changed - Use bounded real I/O yields for observations. Assert that the fake clock stays fixed during each observation. - Advance fake time only to actual pending follow-up deadlines. Keep one fixed five-second reference for each drain. - Accept an already finished follow-up only when the exact expected lease count is present. Quietness must still follow. - Hold the replacement ACK on a Promise gate in the existing test. Release it during normal work and in cleanup. This keeps a deterministic regression without a sleep. - Keep the signed request, identity replacement, exact lease counts, 25-minute no-I/O checks and 30-second test budget. ## Verification - Original CI: one assertion failure at line 126; 2,619 other tests passed in that lane. It was not a test timeout or host failure. - Earlier controls: the same test and relevant worker inputs passed in two fresh CI lanes. Both used zero Turbo cache hits. Input identity alone is not the cause proof. - Causal controls on the original CI source: unchanged baseline passed; held ACK failed at the original assertion with active work; a settlement barrier passed all original assertions; a missing second hint still failed. - Final patch with real PostgreSQL 17 and current source migrations: the direct test passes, including its deterministic ACK gate. An extra 750 ms ACK delay also passes. The missing-second-hint negative still fails at the expected observation. - Focused command: `pnpm exec vitest run --project server server/src/__tests__/github-connection-enrollment-work.test.ts`. Local checks used current-source package aliases and one disposable loopback PostgreSQL instance. The test creates a unique database and no user data. - Fresh Greptile review is 5/5 for `519c3fd4a99bf77aea7b085b67c38701358fef95`. The exact head has no open review threads. The current Paperclip assessment is also 5/5 with a final response footer for that full commit. Its check conclusion is neutral. - [Canonical CI 41260540629](https://github.com/paperclipai/paperclip/actions/runs/41260540629) completed successfully for the exact head. All 57 checks are terminal with no failures or pending checks. This includes `ci / verify` and Snyk. The PR is mergeable and clean. - `git diff --check` passes. Full repository typecheck, tests and build are delegated to fresh PR CI. No QA journey, model run, deployment or CI retry was performed for this repair. ## Risks This change affects one integration fixture. Production worker logic, schedules and deadlines do not change. The observer retains a one-second real-time bound and the test retains its 30-second budget. The test still fails on missing work, extra work, a late deadline, a wrong identity or I/O after quiet. The database and HTTP server remain owned by the fixture. ## Model Used OpenAI Codex, GPT-6 family. The session does not expose a more specific backend model ID or fixed context window. Used reasoning, repository tools and test execution. ## 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 - [x] My branch name describes the change and contains no internal Paperclip ticket id or instance-derived details - [x] I have run the focused tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes (test-only behavior; described here) - [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 --- .../github-connection-enrollment-work.test.ts | 55 ++++++++++++++----- 1 file changed, 42 insertions(+), 13 deletions(-) diff --git a/server/src/__tests__/github-connection-enrollment-work.test.ts b/server/src/__tests__/github-connection-enrollment-work.test.ts index c888565b3d9..80a014e7bb6 100644 --- a/server/src/__tests__/github-connection-enrollment-work.test.ts +++ b/server/src/__tests__/github-connection-enrollment-work.test.ts @@ -3,6 +3,7 @@ import os from "node:os"; import path from "node:path"; import { createServer, type Server } from "node:http"; import { once } from "node:events"; +import { setImmediate as yieldForIo } from "node:timers/promises"; import { createCipheriv, createPublicKey, diffieHellman, generateKeyPairSync, hkdfSync, randomBytes, randomUUID, verify } from "node:crypto"; import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { companies, connectionEventDeliveries, connectionGrants, createDb, toolApplications, toolConnections } from "@paperclipai/db"; @@ -38,6 +39,8 @@ const support = await getEmbeddedPostgresTestSupport(); let origin = "", eventId = randomUUID(), grantId = "", companyId = ""; const identities: string[] = []; const delivered = new Set(); + let releaseReplacementAck!: () => void; + const replacementAck = new Promise(resolve => { releaseReplacementAck = resolve; }); try { server = createServer(async (req, res) => { try { @@ -59,7 +62,11 @@ const support = await getEmbeddedPostgresTestSupport(); res.end(JSON.stringify({ id: enrollment!.instanceId, environment: "test", origins: [enrollment!.origin] })); return; } identities.push(claims.iss); - if (req.url === "/v1/connector/events/ack") { acknowledged++; delivered.add(eventId); res.end(JSON.stringify({ acknowledged: 1 })); return; } + if (req.url === "/v1/connector/events/ack") { + acknowledged++; delivered.add(eventId); + if (acknowledged === 2) await replacementAck; + res.end(JSON.stringify({ acknowledged: 1 })); return; + } expect(req.url).toBe("/v1/connector/events/lease"); leases++; if (delivered.has(eventId)) { res.end(JSON.stringify({ events: [], eventWakeVersion: 1 })); return; } const ephemeral = generateKeyPairSync("x25519"), epk = ephemeral.publicKey.export({ format: "jwk" }).x!; @@ -83,13 +90,37 @@ const support = await getEmbeddedPostgresTestSupport(); grantId = grant!.id; const env = { PAPERCLIP_CLOUD_CONNECTOR_BASE_URL: origin, PAPERCLIP_CLOUD_CONNECTOR_ENVIRONMENT: "test" }; const service = githubConnectionEventService(db, { env }); - vi.useFakeTimers({ toFake: ["Date", "setTimeout", "clearTimeout"], shouldAdvanceTime: true }); + vi.useFakeTimers({ toFake: ["Date", "setTimeout", "clearTimeout"] }); coordinator = createDeliveryWorkCoordinator({ owner: db, canRun: () => true, onError: e => errors.push(e) }); const selects = vi.spyOn(db, "select"), transactions = vi.spyOn(db, "transaction"), executes = vi.spyOn(db, "execute"); worker = registerGitHubConnectionEventWork(db, coordinator, service, () => true); await worker.ready; + async function observe(assertion: () => void) { + const observedAt = Date.now(), until = performance.now() + 1_000; + let failure: unknown; + do { + expect(Date.now()).toBe(observedAt); + try { assertion(); return; } catch (error) { failure = error; } + await yieldForIo(); + } while (performance.now() < until); + throw failure; + } + async function drainFollowup(expectedLeases: number) { + const observedAt = Date.now(); + while (leases < expectedLeases) { + await observe(() => { + expect(leases).toBeLessThanOrEqual(expectedLeases); + expect(coordinator!.nextWakeAt() !== null || leases === expectedLeases).toBe(true); + }); + const followup = coordinator!.nextWakeAt(); + if (followup === null) break; + expect(followup - observedAt).toBeLessThanOrEqual(5_000); + await vi.advanceTimersByTimeAsync(Math.max(0, followup - Date.now()) + 1); + } + await observe(() => expect(leases).toBe(expectedLeases)); + } async function quiet(stage: string) { - await vi.waitFor(() => { expect(idleWorkSnapshot().active, stage).toBe(0); expect(coordinator!.nextWakeAt(), stage).toBeNull(); }); + await observe(() => { expect(idleWorkSnapshot().active, stage).toBe(0); expect(coordinator!.nextWakeAt(), stage).toBeNull(); }); selects.mockClear(); transactions.mockClear(); executes.mockClear(); const before = requests; await vi.advanceTimersByTimeAsync(25 * 60_000); expect(selects).not.toHaveBeenCalled(); expect(transactions).not.toHaveBeenCalled(); expect(executes).not.toHaveBeenCalled(); expect(requests).toBe(before); @@ -104,31 +135,29 @@ const support = await getEmbeddedPostgresTestSupport(); const firstIdentity = await enroll(); expect(wakeConnectionEvents(db)).toBe(true); await vi.advanceTimersByTimeAsync(6_000); - await vi.waitFor(() => expect(acknowledged).toBe(1)); + await observe(() => expect(acknowledged).toBe(1)); expect(await db.select().from(connectionEventDeliveries).where(eq(connectionEventDeliveries.providerDeliveryId, eventId))).toMatchObject([{ status: "processed" }]); expect((await db.select().from(connectionGrants).where(eq(connectionGrants.id, grantId)))[0]!.providerTenant!.github!.webhookHealth).toBe("healthy"); // The applied installation update publishes one credential-change hint. // Join that existing minimum-spacing pass once; the broker now has no debt. - const followup = coordinator.nextWakeAt(); expect(followup).not.toBeNull(); - expect(followup! - Date.now()).toBeLessThanOrEqual(5_000); - await vi.advanceTimersByTimeAsync(Math.max(0, followup! - Date.now()) + 1); - await vi.waitFor(() => expect(leases).toBe(2)); + await drainFollowup(2); await quiet("first event plus its one empty follow-up"); await rm(paperclipCloudConnectorIdentityPath()); const oldLeases = leases; expect(wakeConnectionEvents(db)).toBe(true); await vi.advanceTimersByTimeAsync(6_000); await quiet("removed identity"); expect(leases).toBe(oldLeases); eventId = randomUUID(); const secondIdentity = await enroll(); expect(secondIdentity).not.toBe(firstIdentity); expect(wakeConnectionEvents(db)).toBe(true); await vi.advanceTimersByTimeAsync(6_000); - await vi.waitFor(() => expect(acknowledged).toBe(2)); + await observe(() => expect(acknowledged).toBe(2)); expect(identities).toContain(firstIdentity); expect(identities).toContain(secondIdentity); expect(identities.slice(identities.indexOf(secondIdentity))).toEqual(expect.arrayContaining([secondIdentity, secondIdentity])); expect(identities.slice(identities.indexOf(secondIdentity)).every(id => id === secondIdentity)).toBe(true); - const replacementFollowup = coordinator.nextWakeAt(); expect(replacementFollowup).not.toBeNull(); - expect(replacementFollowup! - Date.now()).toBeLessThanOrEqual(5_000); - await vi.advanceTimersByTimeAsync(Math.max(0, replacementFollowup! - Date.now()) + 1); - await vi.waitFor(() => expect(leases).toBe(oldLeases + 2)); + expect(idleWorkSnapshot().active).toBeGreaterThan(0); + expect(coordinator.nextWakeAt()).toBeNull(); + releaseReplacementAck(); + await drainFollowup(oldLeases + 2); await quiet("replacement event plus its one empty follow-up"); expect(errors).toEqual([]); expect(httpErrors).toEqual([]); } finally { + releaseReplacementAck(); await worker?.stop(); await coordinator?.stop(); vi.restoreAllMocks(); vi.useRealTimers(); if (server) { const closed = once(server, "close"); server.close(); server.closeAllConnections(); await closed; } if (previous.home === undefined) delete process.env.PAPERCLIP_HOME; else process.env.PAPERCLIP_HOME = previous.home;