diff --git a/backend/src/lib/waitForActivityTxHash.js b/backend/src/lib/waitForActivityTxHash.js index d219673..229a795 100644 --- a/backend/src/lib/waitForActivityTxHash.js +++ b/backend/src/lib/waitForActivityTxHash.js @@ -7,19 +7,48 @@ * @param {{ maxWaitMs: number, initialDelayMs: number, maxDelayMs: number }} options * @param {(entry: { txHash?: string }) => boolean} [matchesEntry] * @param {(ms: number) => Promise} [sleep] + * @param {AbortSignal} [signal] — when aborted, the loop breaks and returns ''. * @returns {Promise} */ +function sleepWithAbort(ms, signal) { + return new Promise((resolve) => { + let timer; + + const onAbort = () => { + clearTimeout(timer); + signal.removeEventListener('abort', onAbort); + resolve(); + }; + + timer = setTimeout(() => { + signal?.removeEventListener('abort', onAbort); + resolve(); + }, ms); + + if (signal) { + if (signal.aborted) { + onAbort(); + } else { + signal.addEventListener('abort', onAbort, { once: true }); + } + } + }); +} + export async function waitForActivityTxHash( getFeed, activityCountBefore, { maxWaitMs, initialDelayMs, maxDelayMs }, matchesEntry, - sleep = (ms) => new Promise((resolve) => setTimeout(resolve, ms)), + sleep = (ms, signal) => sleepWithAbort(ms, signal), + signal, ) { let elapsedMs = 0; let currentDelay = initialDelayMs; while (true) { + // Early exit when the client disconnected mid-request (see demo.js). + if (signal?.aborted) break; const feed = getFeed(); const addedCount = Math.max(feed.length - activityCountBefore, 0); if (addedCount > 0) { @@ -39,7 +68,8 @@ export async function waitForActivityTxHash( break; } - await sleep(delay); + await sleep(delay, signal); + if (signal?.aborted) break; elapsedMs += delay; currentDelay = Math.min(currentDelay * 2, maxDelayMs); } diff --git a/backend/src/lib/waitForActivityTxHash.test.js b/backend/src/lib/waitForActivityTxHash.test.js index 6617522..1f0b646 100644 --- a/backend/src/lib/waitForActivityTxHash.test.js +++ b/backend/src/lib/waitForActivityTxHash.test.js @@ -97,6 +97,34 @@ describe('waitForActivityTxHash', () => { expect(delays.length).toBeGreaterThan(0); }); + it('aborts an in-flight default sleep and cleans up its timer', async () => { + vi.useFakeTimers(); + try { + const controller = new AbortController(); + const getFeed = vi.fn(() => []); + const resultPromise = waitForActivityTxHash( + getFeed, + 0, + { maxWaitMs: 1000, initialDelayMs: 100, maxDelayMs: 100 }, + undefined, + undefined, + controller.signal, + ); + + // The poll sleep is scheduled: exactly one timer is active. + expect(vi.getTimerCount()).toBe(1); + + controller.abort(); + + // The abort wakes the sleep: the promise resolves and the timer is gone. + await expect(resultPromise).resolves.toBe(''); + expect(vi.getTimerCount()).toBe(0); + expect(getFeed).toHaveBeenCalledTimes(1); + } finally { + vi.useRealTimers(); + } + }); + it('ignores unrelated new entries when a matcher is provided', async () => { const { sleep, delays } = makeSleepRecorder(); const myId = 'request-a'; diff --git a/backend/src/routes/demo.js b/backend/src/routes/demo.js index 58114fc..389c804 100644 --- a/backend/src/routes/demo.js +++ b/backend/src/routes/demo.js @@ -46,6 +46,17 @@ function buildHttpClient() { } router.post('/demo-run', async (req, res) => { + // NOTE: use res.on('close'), not req.on('close'). In Node >=22, req 'close' + // fires once the request body is fully consumed — not on client disconnect — + // so keeping it registered would abort every normal request (HTTP 499). + // res 'close' + !writableEnded distinguishes a real mid-request disconnect + // from normal completion. Verified on Node 22.23.1 (CI) and 24.15.0. + const abortController = new AbortController(); + const onClose = () => { + if (!res.writableEnded) abortController.abort(); + }; + res.on('close', onClose); + try { const { serviceId, category } = req.body; @@ -83,55 +94,58 @@ router.post('/demo-run', async (req, res) => { const httpClient = buildHttpClient(); const activityCountBefore = getActivityFeed().length; - const abortController = new AbortController(); - const onClose = () => abortController.abort(); - req.on('close', onClose); - - const { response, txHash: fetchedTxHash } = await httpClient.fetchWithTx(finalEndpointUrl, { signal: abortController.signal }); - req.removeListener('close', onClose); - - if (!response.ok) { - throw new Error(`Service responded with ${response.status}`); - } - - const data = await response.json(); - - // Evaluate data quality: the response must be a non-null object (or a - // non-empty array) and must not carry a top-level `error` field. - const dataValid = - data !== null && - typeof data === 'object' && - !('error' in data) && - (Array.isArray(data) ? data.length > 0 : Object.keys(data).length > 0); - - if (!dataValid) { - logger.warn({ serviceId, category }, 'Demo run returned empty or error payload — marking data invalid'); - } - - const txHash = fetchedTxHash || (await waitForActivityTxHash( - getActivityFeed, - activityCountBefore, - { - maxWaitMs: config.demoRun.pollMaxWaitMs, - initialDelayMs: config.demoRun.pollInitialDelayMs, - maxDelayMs: config.demoRun.pollMaxDelayMs, - }, - (entry) => entry.demoRunId === demoRunId, - )); - if (!txHash) { - logger.warn({ serviceId, category, maxWaitMs: config.demoRun.pollMaxWaitMs }, 'Activity txHash not found before poll timeout'); + try { + const { response, txHash: fetchedTxHash } = await httpClient.fetchWithTx(finalEndpointUrl, { signal: abortController.signal }); + + if (!response.ok) { + throw new Error(`Service responded with ${response.status}`); + } + + const data = await response.json(); + + // Evaluate data quality: the response must be a non-null object (or a + // non-empty array) and must not carry a top-level `error` field. + const dataValid = + data !== null && + typeof data === 'object' && + !('error' in data) && + (Array.isArray(data) ? data.length > 0 : Object.keys(data).length > 0); + + if (!dataValid) { + logger.warn({ serviceId, category }, 'Demo run returned empty or error payload — marking data invalid'); + } + + const txHash = fetchedTxHash || (await waitForActivityTxHash( + getActivityFeed, + activityCountBefore, + { + maxWaitMs: config.demoRun.pollMaxWaitMs, + initialDelayMs: config.demoRun.pollInitialDelayMs, + maxDelayMs: config.demoRun.pollMaxDelayMs, + }, + (entry) => entry.demoRunId === demoRunId, + undefined, + abortController.signal, + )); + if (!txHash) { + logger.warn({ serviceId, category, maxWaitMs: config.demoRun.pollMaxWaitMs }, 'Activity txHash not found before poll timeout'); + } + + recordActivity({ + timestamp: new Date().toISOString(), + agent: config.server.address, + service: service.name, + amount: service.price_usdc, + txHash, + }); + + logger.info({ serviceId, category, txHash, dataValid }, 'Demo run complete'); + if (!abortController.signal.aborted && !res.writableEnded) { + res.json({ data, txHash, dataValid }); + } + } finally { + res.removeListener('close', onClose); } - - recordActivity({ - timestamp: new Date().toISOString(), - agent: config.server.address, - service: service.name, - amount: service.price_usdc, - txHash, - }); - - logger.info({ serviceId, category, txHash, dataValid }, 'Demo run complete'); - res.json({ data, txHash, dataValid }); } catch (err) { if (err.name === 'AbortError') { logger.info({ serviceId: req.body?.serviceId, category: req.body?.category }, 'Demo run aborted by client'); diff --git a/backend/test/demo-disconnect.test.js b/backend/test/demo-disconnect.test.js new file mode 100644 index 0000000..793fd91 --- /dev/null +++ b/backend/test/demo-disconnect.test.js @@ -0,0 +1,212 @@ +/** + * Issue #531 — client disconnect during /api/demo-run polling. + * + * This test lives OUTSIDE the repo's existing suites on purpose: it covers + * the scenario that the current tests structurally cannot see (disconnect + * DURING the real polling phase). The existing suite mocks + * waitForActivityTxHash to resolve instantly, so the handler completes + * before the 'close' event fires and the abort never matters. + * + * Here we run the REAL waitForActivityTxHash (not mocked) and destroy the + * client socket mid-poll, exactly like a real browser tab being closed. + * + * Expected behavior with the fix: + * - normal request -> 200, poll runs (not aborted) + * - disconnect mid-poll -> poll cancels early (no full budget waste) + */ +import { describe, it, expect, vi, beforeEach } from 'vitest'; +import express from 'express'; +import http from 'node:http'; +import demoRouter from '../src/routes/demo.js'; +import * as contract from '../src/lib/contract.js'; + +vi.mock('../src/lib/contract.js', () => ({ + getService: vi.fn(), +})); + +vi.mock('../src/routes/demoValidate.js', () => ({ + validateDemoEndpoint: vi.fn().mockReturnValue('http://localhost:9999/demo'), +})); + +vi.mock('../src/routes/services.js', () => ({ + recordActivity: vi.fn(), + getActivityFeed: vi.fn(() => []), +})); + +vi.mock('@x402/core/client', () => ({ + x402Client: vi.fn().mockImplementation(() => ({ + register: vi.fn().mockReturnThis(), + })), + x402HTTPClient: vi.fn().mockImplementation(() => ({ + fetchWithTx: vi.fn().mockResolvedValue({ + response: { + ok: true, + status: 200, + json: async () => ({ weather: 'sunny' }), + headers: { get: () => null }, + }, + txHash: '', + }), + })), +})); + +vi.mock('@x402/stellar', () => ({ + createEd25519Signer: vi.fn(), +})); + +vi.mock('@x402/stellar/exact/client', () => ({ + ExactStellarScheme: vi.fn(), +})); + +import * as services from '../src/routes/services.js'; + +// buildHttpClient() overrides fetchWithTx with the real implementation, which +// calls global fetch(). Stub fetch so the route's "payment" succeeds without +// touching the network: a 200 response means "no payment required" and the +// flow proceeds straight into the polling phase. +const fetchMock = vi.fn(async () => + new Response(JSON.stringify({ weather: 'sunny' }), { + status: 200, + headers: { 'content-type': 'application/json' }, + }), +); +vi.stubGlobal('fetch', fetchMock); + +// ── helpers ───────────────────────────────────────────────────────────────── + +function makeSleepRecorder() { + const delays = []; + const sleep = vi.fn(async (ms) => { + delays.push(ms); + }); + return { sleep, delays }; +} + +const defaultOptions = { maxWaitMs: 8000, initialDelayMs: 250, maxDelayMs: 2000 }; + +async function startServer(app) { + const server = http.createServer(app); + await new Promise((resolve) => server.listen(0, resolve)); + return server; +} + +function sendDemoRun(port, onResponse) { + const req = http.request( + { + hostname: '127.0.0.1', + port, + path: '/api/demo-run', + method: 'POST', + headers: { 'content-type': 'application/json' }, + }, + (res) => { + let data = ''; + res.on('data', (c) => (data += c)); + res.on('end', () => onResponse({ status: res.statusCode, body: data })); + }, + ); + req.on('error', () => {}); // ECONNRESET on destroy is expected + req.end(JSON.stringify({ serviceId: 1, category: 'weather' })); + return req; +} + +// ── unit tests: abort signal in waitForActivityTxHash ──────────────────────── + +import { waitForActivityTxHash } from '../src/lib/waitForActivityTxHash.js'; + +describe('waitForActivityTxHash — abort signal (issue #531)', () => { + it('breaks immediately when the signal is already aborted', async () => { + const { sleep, delays } = makeSleepRecorder(); + const controller = new AbortController(); + controller.abort(); + const getFeed = vi.fn(() => [{ txHash: 'abc123' }]); + + const result = await waitForActivityTxHash( + getFeed, + 0, + defaultOptions, + undefined, + sleep, + controller.signal, + ); + + expect(result).toBe(''); + expect(getFeed).not.toHaveBeenCalled(); + expect(delays).toEqual([]); + }); + + it('stops polling once the signal aborts mid-wait', async () => { + const { sleep, delays } = makeSleepRecorder(); + const controller = new AbortController(); + const getFeed = vi.fn(() => []); + + // Simulate a disconnect arriving during the first sleep delay. + sleep.mockImplementationOnce(async (ms) => { + delays.push(ms); + controller.abort(); + }); + + const result = await waitForActivityTxHash( + getFeed, + 0, + defaultOptions, + undefined, + sleep, + controller.signal, + ); + + expect(result).toBe(''); + expect(getFeed).toHaveBeenCalledTimes(1); + expect(delays.length).toBe(1); // one delay, then the loop stops + }); +}); + +// ── integration tests: real HTTP socket, real polling ─────────────────────── + +describe('POST /api/demo-run — client disconnect during real polling (issue #531)', () => { + beforeEach(() => { + vi.clearAllMocks(); + services.getActivityFeed.mockReturnValue([]); + services.recordActivity.mockClear(); + }); + + it('completes a normal request without aborting the poll', async () => { + contract.getService.mockResolvedValue({ name: 'Test Service', endpoint: 'test', price_usdc: '1' }); + const app = express(); + app.use(express.json()); + app.use('/api', demoRouter); + const server = await startServer(app); + + const started = Date.now(); + const result = await new Promise((resolve) => { + sendDemoRun(server.address().port, resolve); + }); + const elapsed = Date.now() - started; + + server.close(); + expect(result.status).toBe(200); + expect(elapsed).toBeGreaterThan(200); // the poll actually ran + }, 15_000); // real polling runs the full 8s budget by design + + it('cancels the poll when the client disconnects mid-request', async () => { + contract.getService.mockResolvedValue({ name: 'Test Service', endpoint: 'test', price_usdc: '1' }); + const app = express(); + app.use(express.json()); + app.use('/api', demoRouter); + const server = await startServer(app); + + const started = Date.now(); + // Real client that pays and then closes the tab ~200ms in. + await new Promise((resolve) => { + const req = sendDemoRun(server.address().port, () => resolve()); + setTimeout(() => req.destroy(), 200); + setTimeout(resolve, 400); // give the handler time to react + }); + const elapsed = Date.now() - started; + + server.close(); + // The poll budget is 8000ms; after a disconnect it must stop well before. + expect(elapsed).toBeLessThan(2000); + expect(services.recordActivity).toHaveBeenCalled(); + }); +});