diff --git a/package.json b/package.json index 6b101e3..f3136e0 100644 --- a/package.json +++ b/package.json @@ -31,7 +31,8 @@ "dockerode": "^4.0.5", "express": "^5.1.0", "json5": "^2.2.3", - "tar-stream": "^3.1.7" + "tar-stream": "^3.1.7", + "ws": "^8.21.3" }, "devDependencies": { "@eslint/js": "^9.18.0", @@ -40,6 +41,7 @@ "@types/express-serve-static-core": "^5.1.3", "@types/node": "^22.13.0", "@types/tar-stream": "^3.1.3", + "@types/ws": "^8.18.1", "apify-client": "^2.13.0", "axios": "^1.7.9", "eslint": "^9.18.0", diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index f1d9b00..79862ae 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -29,6 +29,9 @@ importers: tar-stream: specifier: ^3.1.7 version: 3.2.0 + ws: + specifier: ^8.21.3 + version: 8.21.3 devDependencies: '@eslint/js': specifier: ^9.18.0 @@ -48,6 +51,9 @@ importers: '@types/tar-stream': specifier: ^3.1.3 version: 3.1.4 + '@types/ws': + specifier: ^8.18.1 + version: 8.18.1 apify-client: specifier: ^2.13.0 version: 2.25.0 @@ -803,6 +809,9 @@ packages: '@types/tar-stream@3.1.4': resolution: {integrity: sha512-921gW0+g29mCJX0fRvqeHzBlE/XclDaAG0Ousy1LCghsOhvaKacDeRGEVzQP9IPfKn8Vysy7FEXAIxycpc/CMg==} + '@types/ws@8.18.1': + resolution: {integrity: sha512-ThVF6DCVhA8kUGy+aazFQ4kXQ7E1Ty7A3ypFOe0IcJV8O/M511G99AW24irKrW56Wt44yG9+ij8FaqoBGkuBXg==} + '@typescript-eslint/eslint-plugin@8.67.0': resolution: {integrity: sha512-Un7Heoyj65NREbKAyIrFxeM143NZpExWmy1Nep4DLeQOeLlTeumPjoNKnBrU5D5moWXbPJgRa5Uwcdu0faVNGQ==} engines: {node: ^18.18.0 || ^20.9.0 || >=21.1.0} @@ -2195,6 +2204,18 @@ packages: wrappy@1.0.2: resolution: {integrity: sha512-l4Sp/DRseor9wL6EvV2+TuQn63dMkPjZ/sp9XkghTEbV9KlPS1xUsZ3u7/IQO4wxtcFB4bgpQPRcR3QCvezPcQ==} + ws@8.21.3: + resolution: {integrity: sha512-201TZ/kPWxoPr/OKWjquZR1SWKXcvxdH+e1xrx89b3YbmzLMFCLfnaG1HFIgWzJOEWZ7MvpK++odZufgYR50Rw==} + engines: {node: '>=10.0.0'} + peerDependencies: + bufferutil: ^4.0.1 + utf-8-validate: '>=5.0.2' + peerDependenciesMeta: + bufferutil: + optional: true + utf-8-validate: + optional: true + y18n@5.0.8: resolution: {integrity: sha512-0pfFzegeDWJHJIAmTLRP2DwHjdF5s7jo9tuztdQxAhINCdvS+3nGINqPd00AphqJR/0LhANUS6/+7SCb98YOfA==} engines: {node: '>=10'} @@ -2762,6 +2783,10 @@ snapshots: dependencies: '@types/node': 22.20.1 + '@types/ws@8.18.1': + dependencies: + '@types/node': 22.20.1 + '@typescript-eslint/eslint-plugin@8.67.0(@typescript-eslint/parser@8.67.0(eslint@9.39.5)(typescript@5.9.3))(eslint@9.39.5)(typescript@5.9.3)': dependencies: '@eslint-community/regexpp': 4.12.2 @@ -4349,6 +4374,8 @@ snapshots: wrappy@1.0.2: {} + ws@8.21.3: {} + y18n@5.0.8: {} yargs-parser@21.1.1: {} diff --git a/requirements/actor-driver.md b/requirements/actor-driver.md index 22f0938..58ab6af 100644 --- a/requirements/actor-driver.md +++ b/requirements/actor-driver.md @@ -101,6 +101,34 @@ - Actor run details are saved in `__RUNS__` internal storage - Actor run log is saved in `__LOGS__` internal storage +## Resource limits + +- Every run's container has a hard memory limit and a hard CPU limit. Memory is the run's `memoryMbytes`; + CPU is derived from it at the platform's ratio of one core per 4096 MB, so a 1024 MB run gets 0.25 core. +- A derived CPU limit below what Docker accepts is raised to that minimum. +- Limits are applied exactly as requested, even when they exceed the host's own capacity. Such a run is + warned about in its own log, naming the requested and the host figures; the limits still apply. When the + host's capacity cannot be determined, no warning is produced. +- Disk is not limited. `diskMbytes` is reported but never enforced. + +## Run resource telemetry + +- While a run's container is up, its CPU and memory usage are measured once a second and published as + `systemInfo` events on the run's events channel (`api.md`). +- Every event carries all eight fields - `memAvgBytes`, `memCurrentBytes`, `memMaxBytes`, `cpuAvgUsage`, + `cpuMaxUsage`, `cpuCurrentUsage`, `isCpuOverloaded`, `createdAt` - or is not published at all. A + measurement that cannot be read completely is skipped, leaving the run's running figures unaffected. + - `cpuCurrentUsage` is percent of one CPU core, not of the run's own grant. + - `memCurrentBytes` and `memAvgBytes` exclude reclaimable page cache, matching what `docker stats` + reports for the same container. + - `memMaxBytes` is the run's configured memory limit, constant for its lifetime. + - `isCpuOverloaded` is true when used cores exceed 95% of the run's granted cores. + - `memAvgBytes`, `cpuAvgUsage` and `cpuMaxUsage` cover every sample published for that run so far. +- Measurement lasts exactly as long as the container: it starts once the container is running and stops + before the container is removed, and it never delays a run from reaching a terminal state. +- The bundled sample Actors log their granted resources and each `systemInfo` event they receive, so the + contract is observable from a single `apify call`. + # Users - Users are created adhoc by the runtime for each new token used in the API call (`cli.md`'s User bootstrap). @@ -132,3 +160,10 @@ resolved against it (`cli.md`'s User bootstrap). If neither source has a value, the key is absent entirely — never a placeholder value. One host-level password (source 1) or one harvested-per-account password (source 2) used specifically for each user. +- `ACTOR_EVENTS_WEBSOCKET_URL` / `APIFY_ACTOR_EVENTS_WS_URL` — the run's own events channel + (`api.md`), carrying no credential. +- `ACTOR_MEMORY_MBYTES` / `APIFY_MEMORY_MBYTES` — the run's requested `memoryMbytes`. +- `APIFY_DEDICATED_CPUS` — the run's granted CPU cores. No `ACTOR_`-prefixed counterpart; only the + Python SDK reads it. +- Every `ACTOR_*`/`APIFY_*` pair above is set to an identical value: the two SDKs disagree on which name + wins, so a divergent pair would size the same run differently depending on which one reads it. diff --git a/requirements/api.md b/requirements/api.md index dcbd392..5eef3aa 100644 --- a/requirements/api.md +++ b/requirements/api.md @@ -25,12 +25,14 @@ This also protects the runtime's own driver invariant: deleting the record first would permanently strand a running Docker container, since its only stop path (`POST .../abort`) requires the record to still resolve, and startup reconciliation only ever considers _existing_ run records. -- Two endpoints are exceptions to the `{data}` envelope: +- Three endpoints are exceptions to the `{data}` envelope: - `GET /v2/logs/:buildOrRunId` (and its `actor-builds`/`actor-runs` aliases): the body is plain text, never `{data}`-wrapped, matching apify-client-js's `log().get()`. - `GET /v2/datasets/:datasetId/items` (and its `actor-runs/:runId/dataset/items` alias): the body is a bare JSON array of items, never `{data}`-wrapped, with pagination metadata carried in `x-apify-pagination-*` response headers, matching apify-client-js's `_createPaginationList`. + - `GET /actor-runtime/events/:runId`: a websocket upgrade, not a JSON response at all - see "Actor + runtime API" below. - `*At` timestamp fields are ISO-8601 strings. # Actor id encoding @@ -149,6 +151,30 @@ console-local, unauthenticated route on the console's own port. Both routes funnel into the same underlying validate-and-persist path, so the two surfaces can never drift apart in behavior, only in how they are reached. +- **`GET /actor-runtime/events/:runId`** - a websocket upgrade, reachable at exactly this one path on + the fixed API port (`system.md`). It carries the run's platform events: `systemInfo` once a second + (`actor-driver.md`), plus a one-off `aborting` frame under `?gracefully=` (below). Each frame is a + single text message, `{"name": "...", "data": {...}}`. + - The endpoint has no authentication. The run id in the path is the only thing it scopes on, and a + connection only ever receives that run's own frames; one run never sees another's. + - An unknown or already-terminal run id gets a completed upgrade followed immediately by a `1008` + close with a reason, never a non-101 HTTP status - the Python SDK treats a refused first connection + as fatal to the Actor. + - A connection to a live run stays open until the run ends, when the server closes it with `1000`. It + is never dropped while healthy, except that a graceful runtime shutdown terminates every open + connection along with the rest of the server. + - `persistState` is never sent over this channel; both SDKs generate it themselves. + +## Graceful abort (`?gracefully=`) + +- `POST /v2/actor-runs/:runId/abort` accepts an optional `?gracefully=` boolean. +- Omitted or `false`: the run aborts immediately, exactly as before this parameter existed. +- `true` on a running run: the record moves to `ABORTING` at once, an `aborting` frame with an empty + payload is published on the run's events channel, and the container is stopped 30 seconds later. The + request stays open until then, so it is the longest-held response in this API. +- `true` on a run with no container (still `READY`, or already terminal): behaves as if omitted. +- A second abort arriving during an open window: another `?gracefully=true` joins that window and neither + restarts it nor stops the container early; a non-graceful one escalates and stops the container at once. ## Upstream fallback (opt-in, off by default, all HTTP methods) diff --git a/requirements/system.md b/requirements/system.md index 81120f4..f0fc0d6 100644 --- a/requirements/system.md +++ b/requirements/system.md @@ -28,9 +28,7 @@ status message, but every other endpoint - storages, actor/build/run records, console - still works). - The API port (3333) and the console frontend port (3000) are fixed values and are not configurable; they are the same on every start of the container. - -# Running the container - +- Port 3333 also serves the per-run events websocket (`api.md`); no additional port is published for it. - Required `docker run` flags: mount the host Docker socket read-write (`-v /var/run/docker.sock:/var/run/docker.sock`) so the runtime can build and run Actor containers, and mount a persistent data directory (`-v :/data`, e.g. `-v "$(pwd)/data:/data"`) so @@ -63,10 +61,11 @@ reuse the already-pulled base image and every other push/call/log-stream/storage-access needs no outbound network access at all (see `cli.md`'s offline-capability note) - unless the opt-in upstream API fallback (`api.md`'s "Upstream fallback" section) has been switched on, in which case a local miss - that is eligible for it makes one outbound request per such call. -- The bundled sample Actors (`sample_actor_ts`, `sample_actor_py`) are not offline: they crawl a live - site (`https://crawlee.dev/` by default). Running them needs outbound network access from the Actor - container, unlike operating the runtime around them (see `test.md`). + that is eligible for it makes one outbound request per such call. Measuring a run's CPU and memory + needs no network access of its own. +- The sample Actors are not offline: they crawl a live site (`https://crawlee.dev/` by default). Running + them needs outbound network access from the Actor container, unlike operating the runtime around them + (see `test.md`). - The runtime's one-time, per-token, real-console identity check (`cli.md`'s User bootstrap) is best-effort online with a silent offline fallback. @@ -89,6 +88,9 @@ The intended scale of the system is: The intended scale is not enforced, but the system operating above the intended scale can experience performance or functional issues. +The "less than 5 running actors at the same time" budget also bounds the per-run resource measurement and +the open events connections - each running Actor adds at most one of each. + # Tests The system is tested according to the requirements in `test.md` diff --git a/sample_actor_py/src/main.py b/sample_actor_py/src/main.py index db0a30a..17ed0db 100644 --- a/sample_actor_py/src/main.py +++ b/sample_actor_py/src/main.py @@ -7,13 +7,27 @@ from __future__ import annotations -from apify import Actor +from apify import Actor, Event, EventSystemInfoData from crawlee import ConcurrencySettings from crawlee.crawlers import ParselCrawler, ParselCrawlingContext async def main() -> None: async with Actor: + config = Actor.configuration + Actor.log.info( + f'Resources granted to this run: {config.memory_mbytes} MB memory, {config.dedicated_cpus} CPU core(s).' + ) + + # The runtime measures this container and relays a systemInfo event once a second. + async def log_resource_usage(event_data: EventSystemInfoData) -> None: + Actor.log.info( + f'Resource usage: CPU {event_data.cpu_info.used_ratio:.1%} of the grant, ' + f'memory {event_data.memory_info.current_size.to_mb():.1f} MB' + ) + + Actor.on(Event.SYSTEM_INFO, log_resource_usage) + actor_input = await Actor.get_input() or {} start_url = actor_input.get('startUrl', 'https://crawlee.dev/') max_pages = int(actor_input.get('maxPages', 2)) diff --git a/sample_actor_ts/src/main.ts b/sample_actor_ts/src/main.ts index a7531e3..276a43a 100644 --- a/sample_actor_ts/src/main.ts +++ b/sample_actor_ts/src/main.ts @@ -11,6 +11,20 @@ interface Input { maxPages?: number; } +const { memoryMbytes } = Actor.getEnv(); +log.info( + `Resources granted to this run: ${memoryMbytes} MB memory, ${process.env.APIFY_DEDICATED_CPUS ?? 'unknown'} CPU core(s).`, +); + +// The runtime measures this container and relays a systemInfo event once a second. +Actor.on('systemInfo', (info: { cpuCurrentUsage?: number; memCurrentBytes?: number; isCpuOverloaded?: boolean }) => { + const memoryMb = info.memCurrentBytes !== undefined ? (info.memCurrentBytes / 1024 / 1024).toFixed(1) : 'unknown'; + log.info( + `Resource usage: CPU ${info.cpuCurrentUsage?.toFixed(1)}% of one core, memory ${memoryMb} MB, ` + + `CPU overloaded: ${info.isCpuOverloaded}`, + ); +}); + const input = await Actor.getInput(); const startUrl = input?.startUrl ?? 'https://crawlee.dev/'; const maxPages = input?.maxPages ?? 2; diff --git a/src/api/events-ws.ts b/src/api/events-ws.ts new file mode 100644 index 0000000..d96393c --- /dev/null +++ b/src/api/events-ws.ts @@ -0,0 +1,102 @@ +/** + * The events websocket: `GET /actor-runtime/events/:runId`, upgraded on the API server directly + * (Express does not handle `upgrade`). Unauthenticated by decision - cross-run isolation is structural, + * since the path's `:runId` is the only thing this handler scopes on and there is no broadcast listener. + * Rejections complete the upgrade and then close `1008`: refusing the handshake would abort a Python + * Actor at `Actor.init()`. + */ +import type { IncomingMessage, Server } from 'node:http'; +import type { Duplex } from 'node:stream'; +import { WebSocketServer, type WebSocket } from 'ws'; + +import { getRunById } from '../services/runs.js'; +import { isTerminalJobStatus } from '../services/job-status.js'; +import { isEventsTerminal, subscribeEvents } from '../services/events-channel.js'; +import { pollUntilTerminal } from './poll-until-terminal.js'; + +// A trailing slash is a different path, not a second spelling of this one. +const EVENTS_PATH_PATTERN = /^\/actor-runtime\/events\/([^/]+)$/; + +/** Mirrors `api/routes/logs.ts`'s poll cadence. */ +const TERMINAL_POLL_INTERVAL_MS = 250; + +export interface EventsWebSocketServer { + /** + * Stops accepting upgrades and terminates every open connection. Not redundant with + * `closeServer(apiServer)`: neither Node's `closeAllConnections()` nor `wss.close()` ends an + * already-upgraded socket, so without this a connected Actor hangs graceful shutdown indefinitely. + */ + close(): void; +} + +function extractRunId(pathname: string): string | undefined { + return EVENTS_PATH_PATTERN.exec(pathname)?.[1]; +} + +/** + * An unknown or already-terminal run is closed `1008`; a live run is subscribed to its own frames and + * closed `1000` once it ends. A healthy connection is never closed for any other reason. + */ +async function handleConnection(ws: WebSocket, runId: string): Promise { + // Must come first: an `'error'` with no listener crashes the process, and any client can provoke one + // on this unauthenticated socket. `ws` still emits `'close'` after it, so teardown below is unaffected. + ws.on('error', () => undefined); + + const run = await getRunById(runId); + if (!run) { + ws.close(1008, `Unknown run id: ${runId}`); + return; + } + if (isTerminalJobStatus(run.status)) { + ws.close(1008, `Run ${runId} has already ended`); + return; + } + + const unsubscribe = subscribeEvents(runId, (frame) => { + if (ws.readyState === ws.OPEN) ws.send(frame); + }); + + const poller = pollUntilTerminal({ + intervalMs: TERMINAL_POLL_INTERVAL_MS, + isTerminal: () => isEventsTerminal(runId), + refetch: () => getRunById(runId), + onTerminal: () => { + unsubscribe(); + if (ws.readyState === ws.OPEN || ws.readyState === ws.CONNECTING) ws.close(1000, `Run ${runId} has ended`); + }, + }); + + ws.on('close', () => { + poller.stop(); + unsubscribe(); + }); +} + +/** Registers the upgrade handler on the API server and returns a handle shutdown can close. */ +export function attachEventsWebSocket(server: Server): EventsWebSocketServer { + const wss = new WebSocketServer({ noServer: true }); + + server.on('upgrade', (req: IncomingMessage, socket: Duplex, head: Buffer) => { + const pathname = req.url ? new URL(req.url, 'http://localhost').pathname : undefined; + const runId = pathname ? extractRunId(pathname) : undefined; + if (!runId) { + // Not this endpoint's path, and this is the server's only 'upgrade' listener. + socket.destroy(); + return; + } + + wss.handleUpgrade(req, socket, head, (ws) => { + // Contains an unexpected rejection to this one connection; unhandled, it would kill the process. + void handleConnection(ws, runId).catch(() => { + ws.terminate(); + }); + }); + }); + + return { + close() { + for (const client of wss.clients) client.terminate(); + wss.close(); + }, + }; +} diff --git a/src/api/poll-until-terminal.ts b/src/api/poll-until-terminal.ts new file mode 100644 index 0000000..e72f41e --- /dev/null +++ b/src/api/poll-until-terminal.ts @@ -0,0 +1,44 @@ +import { isTerminalJobStatus } from '../services/job-status.js'; +import type { JobStatus } from '../storage/entities.js'; + +/** + * Holds a live connection open against a job and stops it once the job goes terminal. Termination is + * detected two ways: `isTerminal`, an in-memory flag, and `refetch`, a fallback re-read of the record + * for paths that reach a terminal state without flipping it. `stop()` is for the caller's own close + * signal and never runs `onTerminal`. + */ +export function pollUntilTerminal(options: { + intervalMs: number; + isTerminal: () => boolean; + refetch: () => Promise<{ status: JobStatus } | null>; + onTerminal: () => void; +}): { stop(): void } { + let checkingRecord = false; + const poll = setInterval(() => { + if (options.isTerminal()) { + clearInterval(poll); + options.onTerminal(); + return; + } + if (checkingRecord) return; + checkingRecord = true; + options + .refetch() + .then((current) => { + if (!current || isTerminalJobStatus(current.status)) { + clearInterval(poll); + options.onTerminal(); + } + }) + .catch(() => undefined) + .finally(() => { + checkingRecord = false; + }); + }, options.intervalMs); + + return { + stop() { + clearInterval(poll); + }, + }; +} diff --git a/src/api/routes/logs.ts b/src/api/routes/logs.ts index 4b37fd9..deb0df3 100644 --- a/src/api/routes/logs.ts +++ b/src/api/routes/logs.ts @@ -3,6 +3,7 @@ import type { Request, Response, Router } from 'express'; import { recordNotFound } from '../errors.js'; import { h, queryBoolean } from '../handler.js'; import { requireUser } from '../auth.js'; +import { pollUntilTerminal } from '../poll-until-terminal.js'; import { getFullLog, isLogTerminal, subscribeLog } from '../../services/logs.js'; import { getOwnedBuild } from '../../services/builds.js'; import { getOwnedRun } from '../../services/runs.js'; @@ -55,34 +56,18 @@ export async function serveLog(req: Request, res: Response, id: string): Promise res.write(chunk); }); - const finish = (): void => { - clearInterval(poll); - unsubscribe(); - res.end(); - }; - - // Guarded against overlapping ticks: the persisted-record re-check below is async, and a slow read - // must not let a second tick pile another one on top of it while the first is still in flight. - let checkingRecord = false; - const poll = setInterval(() => { - if (isLogTerminal(id)) { - finish(); - return; - } - if (checkingRecord) return; - checkingRecord = true; - resolveOwnedJob(userId, id) - .then((current) => { - if (!current || isTerminalJobStatus(current.status)) finish(); - }) - .catch(() => undefined) - .finally(() => { - checkingRecord = false; - }); - }, 250); + const poller = pollUntilTerminal({ + intervalMs: 250, + isTerminal: () => isLogTerminal(id), + refetch: () => resolveOwnedJob(userId, id), + onTerminal: () => { + unsubscribe(); + res.end(); + }, + }); req.on('close', () => { - clearInterval(poll); + poller.stop(); unsubscribe(); }); } diff --git a/src/api/routes/runs.ts b/src/api/routes/runs.ts index 004ad20..9b184c4 100644 --- a/src/api/routes/runs.ts +++ b/src/api/routes/runs.ts @@ -4,7 +4,7 @@ import { requireUser } from '../auth.js'; import { paginate, sendData, sortByTimestamp } from '../envelope.js'; import { cannotRemoveRunningRun, recordNotFound } from '../errors.js'; -import { h, paginationParams } from '../handler.js'; +import { h, paginationParams, queryBoolean } from '../handler.js'; import { abortRun, deleteRun, getOwnedRun, listOwnedRuns } from '../../services/runs.js'; import { isTerminalJobStatus } from '../../services/job-status.js'; import { runDto } from '../dto/actors.js'; @@ -52,7 +52,11 @@ export function mountRuns(router: Router, deps: ApiServerDeps): void { h(async (req, res) => { const run = await getOwnedRun(requireUser(req).id, req.params.runId as string); if (!run) throw recordNotFound(); - const updated = await abortRun(deps.driver, run); + // Mirrors `apify-core`'s own abort route: `parseBooleanParameter(query.gracefully)`, default + // `false` - omitted or `false` is byte-identical to the pre-existing immediate-abort behavior + // (`services/runs.ts: abortRun`'s doc comment). + const gracefully = queryBoolean(req, 'gracefully') ?? false; + const updated = await abortRun(deps.driver, run, gracefully); sendData(res, runDto(updated ?? run)); }), ); diff --git a/src/api/spec-table.ts b/src/api/spec-table.ts index 28aa6a2..bc13e0e 100644 --- a/src/api/spec-table.ts +++ b/src/api/spec-table.ts @@ -4,7 +4,7 @@ * fetch at runtime (the live spec is not fetched at implementation time or at runtime/build time - * this table's "not implemented" section is a best-effort snapshot of the well-documented, stable * Apify v2 API surface, not a byte-for-byte copy of the live spec; it is deliberately wide enough to - * exercise the 501/404 split required by `api.md` and success criterion 9). + * exercise the 501/404 split required by `api.md`'s "501 vs 404" section). * * `implemented: true` entries all have a real Express route registered for them (including the small * number that are *wired but intentionally answer 501* - request deletion - which is a documented, diff --git a/src/config.ts b/src/config.ts index 2d1a86e..bf5442f 100644 --- a/src/config.ts +++ b/src/config.ts @@ -6,6 +6,12 @@ export const CONSOLE_PORT = 3000; export const CONTAINER_API_ALIAS = 'apify-api'; export const CONTAINER_API_BASE_URL = `http://${CONTAINER_API_ALIAS}:${API_PORT}`; +/** Base for the events-websocket URL every Actor container is given (`ACTOR_EVENTS_WEBSOCKET_URL` / + * `APIFY_ACTOR_EVENTS_WS_URL`, `services/runs.ts: buildEnv`) - the same host:port as + * `CONTAINER_API_BASE_URL`, just `ws://` instead of `http://`: the events endpoint upgrades on the + * existing API server (`api/events-ws.ts`), not a second port (`system.md`'s fixed-ports contract). */ +export const CONTAINER_EVENTS_WS_BASE_URL = `ws://${CONTAINER_API_ALIAS}:${API_PORT}`; + /** Host-facing base URL for the local console UI (fixed port, `system.md`) - used only to build the * `consoleUrl` field storage DTOs return (the real platform's equivalent points at * `console.apify.com`; this points at the one console this runtime actually serves). The path appended diff --git a/src/driver/docker-driver.ts b/src/driver/docker-driver.ts index d9d5eb9..cff147e 100644 --- a/src/driver/docker-driver.ts +++ b/src/driver/docker-driver.ts @@ -31,6 +31,7 @@ import Docker from 'dockerode'; import * as tar from 'tar-stream'; import { CONTAINER_API_ALIAS } from '../config.js'; +import { CPU_PERIOD_US, cpuQuotaFor, dedicatedCpusFor } from '../resources.js'; import { normalizeEntryName } from './tar-entry-name.js'; import type { SourceFile } from '../storage/entities.js'; import { @@ -43,6 +44,7 @@ import { type Driver, type RunContext, type RunOutcome, + type RunResourceSample, } from './types.js'; const NETWORK_NAME = 'apify-local'; @@ -78,6 +80,20 @@ const BIND_SOURCE_MISSING_SUBSTRING = 'bind source path does not exist'; * rejection shape `classifyProbeError` reports as "not a directory" rather than a generic "could not * verify", and never as "does not exist". */ const NOT_A_DIRECTORY_SUBSTRING = 'not a directory'; +/** Per-run CPU/memory sampling cadence - decided, not tunable via env in this PR. A single module + * constant, so it is trivially adjustable later if per-second `stats()` calls against the daemon (up to + * one per concurrently running Actor, `system.md`'s scale budget) ever prove too much load. */ +const SAMPLE_INTERVAL_MS = 1000; +/** Bounds `stop()`'s wait on the in-flight `stats()` call. The daemon client is built without a request + * timeout, so an unanswered call would otherwise hold a run's finalization open forever; a call that + * outlives this grace is abandoned, and `stopped` suppresses its result. Mirrors `LOG_DRAIN_GRACE_MS`. */ +const SAMPLER_STOP_GRACE_MS = 5000; + +/** Host capacity, snapshotted once at `init()`. Absent means "unknown", never "zero". */ +interface HostCapacity { + ncpu: number; + memTotalBytes: number; +} /** Narrows an unknown rejection to the shape `docker-modem` attaches to a daemon HTTP-level error * response (`Modem.prototype.buildPayload`: `msg.statusCode = res.statusCode`) - present only when the @@ -127,6 +143,128 @@ function dockerfileTarball(contents: string): NodeJS.ReadableStream { return pack; } +/** The `cpu_stats` fields the sampler diffs between two of its own successive samples. */ +interface CpuUsageSnapshot { + totalUsage: number; + systemUsage: number; +} + +/** + * `memory_stats.usage` minus the reclaimable page cache, the same adjustment `docker stats`' MEM USAGE + * column makes (cgroup v1 reports it as `total_inactive_file`, v2 as `inactive_file`). Subtracted only + * when smaller than `usage`, so the result can never go negative. `undefined` when `usage` is missing or + * non-finite, which makes `takeSample` skip the tick rather than emit a partial frame. + */ +function memoryUsageBytesExcludingCache(stats: Docker.ContainerStats): number | undefined { + const usage = stats.memory_stats?.usage; + if (typeof usage !== 'number' || !Number.isFinite(usage)) return undefined; + const memStats = stats.memory_stats.stats as { total_inactive_file?: number; inactive_file?: number } | undefined; + const cacheBytes = memStats?.total_inactive_file ?? memStats?.inactive_file; + return cacheBytes !== undefined && cacheBytes < usage ? usage - cacheBytes : usage; +} + +/** + * Presence-and-finiteness guard for the two `cpu_stats` fields the delta reads. A missing field skips the + * tick instead of throwing or producing a `NaN`. `online_cpus` is excluded: it has a sane `|| 1` fallback. + */ +function cpuUsageSnapshotOf(stats: Docker.ContainerStats): CpuUsageSnapshot | undefined { + const totalUsage = stats.cpu_stats?.cpu_usage?.total_usage; + const systemUsage = stats.cpu_stats?.system_cpu_usage; + if (typeof totalUsage !== 'number' || !Number.isFinite(totalUsage)) return undefined; + if (typeof systemUsage !== 'number' || !Number.isFinite(systemUsage)) return undefined; + return { totalUsage, systemUsage }; +} + +/** + * Samples an already-running container once per `SAMPLE_INTERVAL_MS`, reporting CPU as percent of one + * core. The delta is computed against this sampler's own previous sample rather than the response's + * `precpu_stats`, which `'one-shot': true` does not reliably populate; an unemitted baseline read seeds + * it. `stop()` awaits the at-most-one in-flight call, bounded by `SAMPLER_STOP_GRACE_MS`. A tick that + * finds the previous call still in flight is skipped, keeping "at most one in flight" an invariant. + */ +function startResourceSampler( + container: Docker.Container, + memoryLimitBytes: number, + onSample: (sample: RunResourceSample) => void, +): { stop(): Promise } { + let stopped = false; + let previous: CpuUsageSnapshot | undefined; + let inFlight: Promise | undefined; + + const takeSample = async (emit: boolean): Promise => { + let stats: Docker.ContainerStats; + try { + stats = await container.stats({ stream: false, 'one-shot': true }); + } catch { + // The container may have already exited (or be mid-removal) by the time this particular tick's + // round trip lands - not an error condition for the sampler itself, just a skipped sample. + return; + } + if (stopped) return; // `stop()` raced this call to completion - never emit after stop. + + const current = cpuUsageSnapshotOf(stats); + const memoryBytes = memoryUsageBytesExcludingCache(stats); + if (!current || memoryBytes === undefined) { + // This tick's stats blob is missing (or reports non-finite for) a field a complete eight-field + // `systemInfo` frame needs - skipped exactly like the rejecting-stats case above: no emission, + // `previous` left untouched. Never emit a partial frame (a frame missing even one field fails + // Python-SDK-side pydantic validation and is silently dropped there), and never let a + // `NaN`/`undefined` reach `events-channel.ts`'s running avg/max accumulators, which would poison + // every later frame of the run, not just this one tick. + return; + } + + if (emit && previous) { + const cpuDelta = current.totalUsage - previous.totalUsage; + const systemDelta = current.systemUsage - previous.systemUsage; + const onlineCpus = stats.cpu_stats.online_cpus || 1; + // `systemDelta` is 0 only in a degenerate case (no host-wide CPU time elapsed between two + // samples, e.g. two calls landing on the very same daemon tick) - reported as 0% rather than + // producing NaN/Infinity. + const cpuPercentOfOneCore = systemDelta > 0 ? (cpuDelta / systemDelta) * onlineCpus * 100 : 0; + onSample({ + cpuPercentOfOneCore, + memoryBytes, + memoryLimitBytes, + at: new Date(), + }); + } + previous = current; + }; + + // The unemitted baseline read (see doc comment above) - kicked off synchronously so `inFlight` is + // already set before this function returns, exactly like every later tick. + inFlight = takeSample(false).finally(() => { + inFlight = undefined; + }); + + const timer = setInterval(() => { + if (stopped || inFlight) return; // never overlap a still-in-flight call (see doc comment above). + inFlight = takeSample(true).finally(() => { + inFlight = undefined; + }); + }, SAMPLE_INTERVAL_MS); + + return { + async stop() { + stopped = true; + clearInterval(timer); + if (!inFlight) return; + // Bounded per `SAMPLER_STOP_GRACE_MS`'s own doc comment - a `stats()` call that never settles must + // never leave this `await` (and everything waiting on it) unbounded. The grace timer's own handle + // is captured and cleared once the race settles either way, so the common case (`inFlight` wins + // well inside the grace window) never leaves an armed timer behind on the event loop. + let graceTimer: ReturnType | undefined; + await Promise.race([ + inFlight, + new Promise((resolve) => { + graceTimer = setTimeout(resolve, SAMPLER_STOP_GRACE_MS); + }), + ]).finally(() => clearTimeout(graceTimer)); + }, + }; +} + export class DockerDriver implements Driver { private readonly docker: Docker; /** One `AbortController` per in-flight `startBuild` call, keyed by build id - `abortBuild` aborts it. */ @@ -137,6 +275,10 @@ export class DockerDriver implements Driver { private readonly timedOutBuilds = new Set(); private readonly timedOutRuns = new Set(); private readonly runContainers = new Map(); + /** The host's own CPU/memory capacity, snapshotted once at `init()` time - `undefined` when + * `docker.info()` threw or omitted either field, meaning "capacity unknown" (see + * `captureHostCapacity`'s doc comment). */ + private hostCapacity: HostCapacity | undefined; /** Set once `ensureProbeImage` has actually built (or found) the probe image - every later call * returns this without touching the daemon again. */ private probeImageId: string | undefined; @@ -163,6 +305,9 @@ export class DockerDriver implements Driver { return; } + // A `docker.info()` failure must not make an otherwise-reachable daemon look unavailable. + await this.captureHostCapacity(); + try { await this.ensureNetwork(); await this.selfAttachToNetwork(); @@ -173,6 +318,50 @@ export class DockerDriver implements Driver { } } + /** + * Best-effort snapshot of the host's CPU count and total memory. A missing field or a failed call + * leaves `hostCapacity` unset - "unknown", which warns about nothing rather than warning on every run. + */ + private async captureHostCapacity(): Promise { + try { + const info: unknown = await this.docker.info(); + const ncpu = (info as { NCPU?: unknown } | undefined)?.NCPU; + const memTotalBytes = (info as { MemTotal?: unknown } | undefined)?.MemTotal; + if (typeof ncpu === 'number' && typeof memTotalBytes === 'number') { + this.hostCapacity = { ncpu, memTotalBytes }; + } + } catch { + // Capacity stays unknown - see the doc comment above. + } + } + + /** + * A warning naming the requested and host figures for whichever resource is over capacity. The limits + * are applied verbatim regardless; `undefined` covers both "in capacity" and "capacity unknown". + */ + private buildOverCapacityWarning(ctx: RunContext): string | undefined { + if (!this.hostCapacity) return undefined; + + const requestedCores = dedicatedCpusFor(ctx.memoryMbytes); + const hostMemoryMbytes = this.hostCapacity.memTotalBytes / (1024 * 1024); + const memoryOverCapacity = ctx.memoryMbytes > hostMemoryMbytes; + const cpuOverCapacity = requestedCores > this.hostCapacity.ncpu; + if (!memoryOverCapacity && !cpuOverCapacity) return undefined; + + const overCapacityParts: string[] = []; + if (memoryOverCapacity) { + overCapacityParts.push(`${ctx.memoryMbytes} MB (host has ${Math.round(hostMemoryMbytes)} MB)`); + } + if (cpuOverCapacity) { + overCapacityParts.push(`${requestedCores.toFixed(2)} CPU cores (host has ${this.hostCapacity.ncpu})`); + } + + return ( + `Requested ${overCapacityParts.join(' and ')} — applying the requested limits anyway; this ` + + `container is scheduled against resources the host does not have.\n` + ); + } + private async ensureNetwork(): Promise { const networks = await this.docker.listNetworks({ filters: JSON.stringify({ name: [NETWORK_NAME] }) }); if (networks.some((n) => n.Name === NETWORK_NAME)) return; @@ -299,16 +488,23 @@ export class DockerDriver implements Driver { this.buildControllers.get(buildId)?.abort(); } - async startRun(ctx: RunContext, onLog: (chunk: string) => void): Promise { + async startRun( + ctx: RunContext, + onLog: (chunk: string) => void, + onSample?: (sample: RunResourceSample) => void, + ): Promise { if (!this.available) { throw new Error(this.unavailableReason ?? 'Docker is not available'); } const env = Object.entries(ctx.env).map(([key, value]) => `${key}=${value}`); + // Informational only - the requested limits are applied verbatim either way. + const overCapacityWarning = this.buildOverCapacityWarning(ctx); + if (overCapacityWarning) onLog(overCapacityWarning); + // A secondary diagnostic for the residual risk that a folder verified at registration later - // vanishes: written before `createContainer` so it is genuinely the first log line even if that - // call is what ends up failing. + // vanishes: written before `createContainer` so it lands even if that call is what fails. if (ctx.devMount) { onLog( `Mounting local dev folder ${ctx.devMount.localDevFolder} over the image's working directory ` + @@ -323,6 +519,11 @@ export class DockerDriver implements Driver { HostConfig: { NetworkMode: NETWORK_NAME, Memory: ctx.memoryMbytes * 1024 * 1024, + // A CFS quota, never `NanoCpus`: the daemon hard-rejects a `NanoCpus` above the host's own + // CPU count, which would turn "warn, never clamp" into "cannot run at all". `CpuQuota` is + // validated for range only, so an over-capacity request still starts. + CpuPeriod: CPU_PERIOD_US, + CpuQuota: cpuQuotaFor(ctx.memoryMbytes), AutoRemove: false, ...(ctx.devMount ? { Mounts: this.buildDevMounts(ctx.devMount) } : {}), }, @@ -330,54 +531,68 @@ export class DockerDriver implements Driver { }); this.runContainers.set(ctx.runId, container); - await container.start(); - - const logStream = (await container.logs({ - follow: true, - stdout: true, - stderr: true, - })) as NodeJS.ReadableStream; - const stdout = new PassThrough(); - const stderr = new PassThrough(); - stdout.on('data', (chunk: Buffer) => onLog(chunk.toString('utf8'))); - stderr.on('data', (chunk: Buffer) => onLog(chunk.toString('utf8'))); - this.docker.modem.demuxStream(logStream, stdout, stderr); - - // `container.logs({follow:true})` is a separate Docker API connection from `container.wait()` - - // the two settle independently, with no ordering guarantee between "the container process exited" - // and "every byte of its stdout/stderr has actually arrived over the logs connection". Without - // this, `startRun` could resolve (and its caller could write a terminal run status) before the - // run's trailing log output had even reached `onLog` yet: a client that polls status, sees it turn - // terminal, and immediately does a non-stream `GET /v2/logs/:id` could read the log before its - // final chunk landed. - // - // "Logs drained" MUST be derived from `logStream` (the SOURCE multiplexed stream) ending, not from - // `stdout`/`stderr` (the demuxed destinations) ending - `docker-modem`'s `demuxStream` only ever - // copies frames: it registers exactly `streama.on('data', processData)` on the source - // (`node_modules/docker-modem/lib/modem.js`, `Modem.prototype.demuxStream`) and never calls - // `.end()`/`.destroy()` on `stdout`/`stderr` itself. Awaiting the destinations' own `'end'` (the - // previous fix) therefore never resolves against a real daemon, which never ends them on its own - - // the run stayed RUNNING until its `timeoutSecs` finalized it as TIMED-OUT, exactly the CI - // regression this closes. So this driver ends them itself, once the source stream ends. - let sourceEnded = false; - const sourceEndedPromise = new Promise((resolve) => { - const finish = (): void => { - if (sourceEnded) return; - sourceEnded = true; - stdout.end(); - stderr.end(); - resolve(); - }; - logStream.once('end', finish); - logStream.once('close', finish); - }); - - const timeout = setTimeout(() => { - this.timedOutRuns.add(ctx.runId); - void container.stop().catch(() => undefined); - }, ctx.timeoutSecs * 1000); + // Both declared outside the `try` below (so the `finally` can always see them) but only ever + // assigned inside it - `sampler` stays `undefined` if `container.start()` itself throws, and + // `timeout` stays `undefined` if anything before its own `setTimeout` call throws; `finally` guards + // each accordingly. + let sampler: { stop(): Promise } | undefined; + let timeout: ReturnType | undefined; try { + await container.start(); + + // Only started when someone is actually listening - an unconditional sampler would issue + // `container.stats()` calls no caller asked for (and against a stub `dockerode` in tests that + // never mocks `.stats()` at all, a hard failure). Created (and the log stream opened, below) + // Inside the `try` so a throw here still reaches the `finally` that stops the sampler and + // removes the container. + sampler = onSample ? startResourceSampler(container, ctx.memoryMbytes * 1024 * 1024, onSample) : undefined; + + const logStream = (await container.logs({ + follow: true, + stdout: true, + stderr: true, + })) as NodeJS.ReadableStream; + const stdout = new PassThrough(); + const stderr = new PassThrough(); + stdout.on('data', (chunk: Buffer) => onLog(chunk.toString('utf8'))); + stderr.on('data', (chunk: Buffer) => onLog(chunk.toString('utf8'))); + this.docker.modem.demuxStream(logStream, stdout, stderr); + + // `container.logs({follow:true})` is a separate Docker API connection from `container.wait()` - + // the two settle independently, with no ordering guarantee between "the container process exited" + // and "every byte of its stdout/stderr has actually arrived over the logs connection". Without + // this, `startRun` could resolve (and its caller could write a terminal run status) before the + // run's trailing log output had even reached `onLog` yet: a client that polls status, sees it turn + // terminal, and immediately does a non-stream `GET /v2/logs/:id` could read the log before its + // final chunk landed. + // + // "Logs drained" MUST be derived from `logStream` (the SOURCE multiplexed stream) ending, not from + // `stdout`/`stderr` (the demuxed destinations) ending - `docker-modem`'s `demuxStream` only ever + // copies frames: it registers exactly `streama.on('data', processData)` on the source + // (`node_modules/docker-modem/lib/modem.js`, `Modem.prototype.demuxStream`) and never calls + // `.end()`/`.destroy()` on `stdout`/`stderr` itself. Awaiting the destinations' own `'end'` (the + // previous fix) therefore never resolves against a real daemon, which never ends them on its own - + // the run stayed RUNNING until its `timeoutSecs` finalized it as TIMED-OUT, exactly the CI + // regression this closes. So this driver ends them itself, once the source stream ends. + let sourceEnded = false; + const sourceEndedPromise = new Promise((resolve) => { + const finish = (): void => { + if (sourceEnded) return; + sourceEnded = true; + stdout.end(); + stderr.end(); + resolve(); + }; + logStream.once('end', finish); + logStream.once('close', finish); + }); + + timeout = setTimeout(() => { + this.timedOutRuns.add(ctx.runId); + void container.stop().catch(() => undefined); + }, ctx.timeoutSecs * 1000); + const result = (await container.wait()) as { StatusCode: number }; // `container.wait()` resolves the same way whether the process exited on its own or was // stopped by our own timeout timer - the timer having fired is the only signal that @@ -392,10 +607,17 @@ export class DockerDriver implements Driver { // `stdout`/`stderr` are left open so any bytes that do eventually arrive still reach `onLog`, // they just no longer block this method from resolving. const LOG_DRAIN_GRACE_MS = 5000; + // The grace timer's own handle is captured and cleared once the race settles either way (the + // common case: `sourceEndedPromise` wins well inside the grace window) - see + // `SAMPLER_STOP_GRACE_MS`'s own `stop()` above, which clears its identically-shaped timer for + // exactly this reason. + let logDrainGraceTimer: ReturnType | undefined; await Promise.race([ sourceEndedPromise, - new Promise((resolve) => setTimeout(resolve, LOG_DRAIN_GRACE_MS)), - ]); + new Promise((resolve) => { + logDrainGraceTimer = setTimeout(resolve, LOG_DRAIN_GRACE_MS); + }), + ]).finally(() => clearTimeout(logDrainGraceTimer)); if (!sourceEnded) { console.warn( `Run ${ctx.runId}: log stream did not end within ${LOG_DRAIN_GRACE_MS}ms of the container exiting; finalizing the run without waiting further.`, @@ -404,7 +626,9 @@ export class DockerDriver implements Driver { return { exitCode: result.StatusCode, timedOut }; } finally { - clearTimeout(timeout); + if (timeout) clearTimeout(timeout); + // Awaited before `container.remove()` so no `stats()` call is issued against a removed container. + await sampler?.stop(); this.timedOutRuns.delete(ctx.runId); this.runContainers.delete(ctx.runId); // `{ v: true }` also removes the container's anonymous volumes - without it, the anonymous diff --git a/src/driver/types.ts b/src/driver/types.ts index 5738d42..b62f439 100644 --- a/src/driver/types.ts +++ b/src/driver/types.ts @@ -47,6 +47,25 @@ export type DevFolderProbeFailureReason = 'unreachable' | 'image-missing' | 'not export type DevFolderProbeOutcome = { ok: true } | { ok: false; reason: DevFolderProbeFailureReason }; +/** + * One CPU/memory measurement of a live run's container, taken by the driver's own per-run sampler + * (`docker-driver.ts`'s `startResourceSampler`) and handed to `startRun`'s optional `onSample` callback - + * plain numbers (plus a `Date`), never a `dockerode` type, same as every other value that crosses the + * `Driver` boundary. Shaping this into the platform's `systemInfo` envelope (percent-of-grant math, + * running avg/max, `isCpuOverloaded`) is `services/events-channel.ts`'s job, not the driver's - the + * driver only measures. + */ +export interface RunResourceSample { + /** CPU usage as percent of one core - `docker stats`' convention, not percent of the run's grant. */ + cpuPercentOfOneCore: number; + /** Current memory usage in bytes, with the reclaimable page cache subtracted. */ + memoryBytes: number; + /** The container's configured memory limit in bytes - constant, never an observed peak. */ + memoryLimitBytes: number; + /** When this sample was taken. */ + at: Date; +} + export interface RunOutcome { exitCode: number; /** @@ -85,7 +104,16 @@ export interface Driver { startBuild(ctx: BuildContext, onLog: (chunk: string) => void): Promise; abortBuild(buildId: string): Promise; - startRun(ctx: RunContext, onLog: (chunk: string) => void): Promise; + /** + * `onSample`, when given, is called roughly once per second for the lifetime of the run with a + * `RunResourceSample` measured from the run's own container. Optional so existing `Driver` + * implementations keep compiling unchanged. + */ + startRun( + ctx: RunContext, + onLog: (chunk: string) => void, + onSample?: (sample: RunResourceSample) => void, + ): Promise; abortRun(runId: string): Promise; /** Startup reconciliation: any run container this process no longer tracks is removed. Build diff --git a/src/index.ts b/src/index.ts index 42002e3..2563d92 100644 --- a/src/index.ts +++ b/src/index.ts @@ -3,6 +3,7 @@ import { openRegistries } from './storage/registries.js'; import { reconcileOrphanedJobs } from './services/runs.js'; import { createDriver } from './driver/index.js'; import { createApiServer } from './api/server.js'; +import { attachEventsWebSocket } from './api/events-ws.js'; import { createConsoleServer } from './console/server.js'; import { startLogFlusher } from './services/logs.js'; import { gracefulShutdown } from './shutdown.js'; @@ -24,6 +25,10 @@ async function main(): Promise { const apiServer = apiApp.listen(API_PORT); const consoleServer = consoleApp.listen(CONSOLE_PORT); + // Upgrades on the same API server/port - no second port (`system.md`'s fixed-ports contract); see + // `api/events-ws.ts`'s own doc comment for why this attaches here rather than inside `createApiServer` + // (Express never sees an `upgrade` event, so this needs the actual `http.Server` `listen()` returned). + const eventsWebSocketServer = attachEventsWebSocket(apiServer); console.log(`actor-runtime API listening on port ${API_PORT}`); @@ -33,7 +38,7 @@ async function main(): Promise { } const shutdown = async () => { - await gracefulShutdown({ apiServer, consoleServer }); + await gracefulShutdown({ apiServer, consoleServer, eventsWebSocketServer }); process.exit(0); }; diff --git a/src/resources.ts b/src/resources.ts new file mode 100644 index 0000000..fcf7b17 --- /dev/null +++ b/src/resources.ts @@ -0,0 +1,19 @@ +/** Memory (MB) granted one full CPU core, per the platform's own memory-to-CPU ratio. */ +const MEMORY_MBYTES_PER_CPU = 4096; + +/** Docker's CFS period, in microseconds - the denominator `CpuQuota` is expressed against. */ +export const CPU_PERIOD_US = 100_000; + +/** Docker's protocol minimum for `HostConfig.CpuQuota` - a floor on the encoding, not a host clamp. */ +const MIN_CPU_QUOTA_US = 1000; + +/** The run's dedicated CPU cores, derived from its memory grant alone. */ +export function dedicatedCpusFor(memoryMbytes: number): number { + return memoryMbytes / MEMORY_MBYTES_PER_CPU; +} + +/** `HostConfig.CpuQuota` for a run granted `memoryMbytes`, paired with `CPU_PERIOD_US`. */ +export function cpuQuotaFor(memoryMbytes: number): number { + const rawQuota = dedicatedCpusFor(memoryMbytes) * CPU_PERIOD_US; + return Math.max(MIN_CPU_QUOTA_US, Math.round(rawQuota)); +} diff --git a/src/services/events-channel.ts b/src/services/events-channel.ts new file mode 100644 index 0000000..0d6b606 --- /dev/null +++ b/src/services/events-channel.ts @@ -0,0 +1,108 @@ +/** + * Fan-out for the per-run events websocket, modelled on `services/logs.ts`. A subscriber is only ever + * added to its own run's entry and there is no broadcast listener, which is what keeps one run's frames + * away from another. Owns the envelope shaping and the avg/max accumulation; the driver only measures. + */ +import { dedicatedCpusFor } from '../resources.js'; +import type { RunResourceSample } from '../driver/types.js'; + +/** The only part of a run's grant this module needs. */ +export interface RunResourceGrant { + memoryMbytes: number; +} + +/** Strict `>`: a sample computing exactly the threshold is not overloaded. */ +const CPU_OVERLOAD_RATIO_THRESHOLD = 0.95; + +interface RunEventsState { + subscribers: Set<(frame: string) => void>; + /** Covers every sample published for this run so far. */ + sampleCount: number; + cpuUsageSum: number; + cpuUsageMax: number; + memoryUsageSum: number; + terminal: boolean; +} + +const live = new Map(); + +function getOrCreate(runId: string): RunEventsState { + let state = live.get(runId); + if (!state) { + state = { + subscribers: new Set(), + sampleCount: 0, + cpuUsageSum: 0, + cpuUsageMax: 0, + memoryUsageSum: 0, + terminal: false, + }; + live.set(runId, state); + } + return state; +} + +function broadcast(state: RunEventsState, frame: string): void { + for (const subscriber of state.subscribers) subscriber(frame); +} + +/** + * Shapes one sample into the `systemInfo` envelope and sends it to `runId`'s subscribers; a run with + * nobody connected is fine. All eight fields are always present - the Python SDK drops a frame missing + * any of them. `cpuCurrentUsage` is percent of one core, `memMaxBytes` is the configured limit rather + * than an observed peak, and `isCpuOverloaded` compares used cores against the grant. + */ +export function publishSystemInfo(runId: string, sample: RunResourceSample, grant: RunResourceGrant): void { + const state = getOrCreate(runId); + state.sampleCount += 1; + state.cpuUsageSum += sample.cpuPercentOfOneCore; + state.cpuUsageMax = Math.max(state.cpuUsageMax, sample.cpuPercentOfOneCore); + state.memoryUsageSum += sample.memoryBytes; + + const grantedCores = dedicatedCpusFor(grant.memoryMbytes); + const usedCores = sample.cpuPercentOfOneCore / 100; + const isCpuOverloaded = grantedCores > 0 && usedCores / grantedCores > CPU_OVERLOAD_RATIO_THRESHOLD; + + const payload = { + memAvgBytes: state.memoryUsageSum / state.sampleCount, + memCurrentBytes: sample.memoryBytes, + memMaxBytes: sample.memoryLimitBytes, + cpuAvgUsage: state.cpuUsageSum / state.sampleCount, + cpuMaxUsage: state.cpuUsageMax, + cpuCurrentUsage: sample.cpuPercentOfOneCore, + isCpuOverloaded, + createdAt: sample.at.toISOString(), + }; + broadcast(state, JSON.stringify({ name: 'systemInfo', data: payload })); +} + +/** Publishes `{"name":"aborting","data":{}}` - both SDKs define this event as carrying no data. */ +export function publishAborting(runId: string): void { + broadcast(getOrCreate(runId), JSON.stringify({ name: 'aborting', data: {} })); +} + +/** Returns an unsubscribe function, mirroring `logs.ts`'s `subscribeLog`. */ +export function subscribeEvents(runId: string, onFrame: (frame: string) => void): () => void { + const state = getOrCreate(runId); + state.subscribers.add(onFrame); + return () => state.subscribers.delete(onFrame); +} + +/** Marks `runId` terminal; connections observe this by polling and close themselves. */ +export function markEventsTerminal(runId: string): void { + getOrCreate(runId).terminal = true; +} + +export function isEventsTerminal(runId: string): boolean { + return live.get(runId)?.terminal ?? false; +} + +/** Live subscriber count for `runId`, so a leaked subscriber is observable. */ +export function getSubscriberCount(runId: string): number { + return live.get(runId)?.subscribers.size ?? 0; +} + +/** Test-only: drop all in-memory events state. */ +export function resetEventsChannelForTests(): void { + live.clear(); +} diff --git a/src/services/job-status.ts b/src/services/job-status.ts index 23e9d93..96f0539 100644 --- a/src/services/job-status.ts +++ b/src/services/job-status.ts @@ -48,14 +48,25 @@ export interface StatusRegistry { * is always overridden by `next`. Returns the record as it ended up (unchanged if the transition was * refused, `null` if the record does not exist), so callers can tell whether their write actually * landed by comparing `result.status` to `next`. + * + * `onBeforeTransition`, when given, is invoked with the record exactly as read INSIDE this same + * mutex-serialized read-modify-write (`Registry.update`'s per-id `KeyedMutex`), before the + * accept/refuse decision is made - the same moment `current.status` is the freshest it can ever be + * relative to this write. A caller that needs to know the record's status immediately prior to a + * guarded transition (e.g. "was this run actually RUNNING right before it moved to ABORTING?") should + * capture it here, never via a separate, unguarded `registry.get(id)` call made before this one - a + * plain `get` has no ordering relationship with a concurrent `update` on the same id and can read a + * status that a race has already made stale by the time the transition itself lands. */ export async function transitionJobStatus( registry: StatusRegistry, id: string, next: JobStatus, patch: Partial = {}, + onBeforeTransition?: (current: T | null) => void, ): Promise { return registry.update(id, (current) => { + onBeforeTransition?.(current); if (!current) return null; if (isTerminalJobStatus(current.status)) return current; if (!ALLOWED_NEXT[current.status].has(next)) return current; diff --git a/src/services/runs.ts b/src/services/runs.ts index 989fc01..47e1e7c 100644 --- a/src/services/runs.ts +++ b/src/services/runs.ts @@ -5,8 +5,11 @@ import { createStorage } from './storages.js'; import { openKeyValueStore } from '../storage/open.js'; import type { Driver } from '../driver/types.js'; import { appendLog, flushLog, markLogTerminal } from './logs.js'; +import { markEventsTerminal, publishAborting, publishSystemInfo } from './events-channel.js'; import { isTerminalJobStatus, transitionJobStatus } from './job-status.js'; import { DEFAULT_BUILD_TAG, findVersion } from './actors.js'; +import { dedicatedCpusFor } from '../resources.js'; +import { CONTAINER_EVENTS_WS_BASE_URL } from '../config.js'; const DEFAULT_MEMORY_MBYTES = 1024; const DEFAULT_TIMEOUT_SECS = 300; @@ -16,6 +19,8 @@ const DEFAULT_TIMEOUT_SECS = 300; * schema: `memoryMbytes: 1024` example paired with `diskMbytes: 2048`), also the exact ratio in * `apify-client`'s `RunOptions` pydantic model examples. */ const DISK_MBYTES_PER_MEMORY_MBYTE = 2; +/** `?gracefully=true`'s wait between the `aborting` frame and the stop, matching the platform's 30s. */ +const GRACEFUL_ABORT_WINDOW_MS = 30_000; export async function listOwnedRuns(userId: string, actorId?: string): Promise { const all = await getRegistries().runs.list(); @@ -33,7 +38,9 @@ export async function listAllRuns(): Promise { return getRegistries().runs.list(); } -/** Cross-user lookup by id, for the console only (see `listAllRuns`). */ +/** Cross-user lookup by id - for the console (see `listAllRuns`), and for `api/events-ws.ts`'s connection + * handler, which has no authenticated caller at all to scope an owned-lookup against (the events + * websocket's own scoping is the path's run id itself, not a user - see that module's doc comment). */ export async function getRunById(id: string): Promise { return getRegistries().runs.get(id); } @@ -75,6 +82,12 @@ function buildEnv( versionEnv[entry.name] = entry.value; } + // Both names in each pair are byte-identical, deliberately: apify-sdk-js's `ENV_MAP` and pydantic's + // `AliasChoices` resolve `ACTOR_*`-vs-`APIFY_*` in OPPOSITE precedence order, so letting the two ever + // diverge would size the run differently depending on which SDK happens to read it. + const eventsWebSocketUrl = `${CONTAINER_EVENTS_WS_BASE_URL}/actor-runtime/events/${run.id}`; + const memoryMbytes = String(run.options.memoryMbytes); + const env: Record = { ...versionEnv, APIFY_IS_AT_HOME: '1', @@ -88,6 +101,13 @@ function buildEnv( ACTOR_ID: actor.id, APIFY_ACTOR_RUN_ID: run.id, ACTOR_RUN_ID: run.id, + // No token: the endpoint is unauthenticated and the run id in the path is all there is to scope on. + ACTOR_EVENTS_WEBSOCKET_URL: eventsWebSocketUrl, + APIFY_ACTOR_EVENTS_WS_URL: eventsWebSocketUrl, + ACTOR_MEMORY_MBYTES: memoryMbytes, + APIFY_MEMORY_MBYTES: memoryMbytes, + // No `ACTOR_`-prefixed counterpart exists; only the Python SDK reads this. + APIFY_DEDICATED_CPUS: String(dedicatedCpusFor(run.options.memoryMbytes)), }; if (options.proxyPassword) env.APIFY_PROXY_PASSWORD = options.proxyPassword; return env; @@ -197,6 +217,7 @@ export async function runInBackground( appendLog(record.id, `Cannot start run: ${reason}\n`); await flushLog(record.id); markLogTerminal(record.id); + markEventsTerminal(record.id); await transitionJobStatus(runs, record.id, 'FAILED', { finishedAt: new Date().toISOString(), statusMessage: reason, @@ -247,6 +268,7 @@ export async function runInBackground( devMount, }, (chunk) => appendLog(record.id, chunk), + (sample) => publishSystemInfo(record.id, sample, record.options), ); const status: JobStatus = outcome.timedOut ? 'TIMED-OUT' : outcome.exitCode === 0 ? 'SUCCEEDED' : 'FAILED'; // Flush before writing the terminal status, not after: `driver.startRun` resolving is the signal @@ -273,22 +295,47 @@ export async function runInBackground( }); } finally { markLogTerminal(record.id); + // Also what actually drives the events websocket's `1000` close (`api/events-ws.ts` polls this + // exact flag, mirroring `api/routes/logs.ts`'s `?stream=true` handling of `isLogTerminal`). + markEventsTerminal(record.id); } } /** - * Stops the run for real (`driver.abortRun` -> `container.stop()`) and reports `ABORTED` back to the - * caller. The record is moved to `ABORTING` *before* `driver.abortRun` is even called, which is what - * makes the result race-proof against `runInBackground`'s own completion write: from that point on, an - * `ABORTING` record only accepts `ABORTED` as its next status (`job-status.ts`), so whichever of the two - * writes - this function's final `ABORTED`, or `runInBackground`'s `SUCCEEDED`/`FAILED`/`TIMED-OUT` - - * reaches the record first, the other is refused rather than clobbering it. + * Stops the run and reports `ABORTED`. The record moves to `ABORTING` before `driver.abortRun` is called, + * which is what makes this race-proof against `runInBackground`'s own completion write: an `ABORTING` + * record only accepts `ABORTED` next, so whichever write lands first, the other is refused. + * + * `gracefully` on a `RUNNING` run publishes an `aborting` frame and waits `GRACEFUL_ABORT_WINDOW_MS` + * before stopping; other states take the immediate path. A second concurrent graceful abort joins the + * window rather than restarting it - see `requirements/api.md`. + * + * Both flags come from `onBeforeTransition`, read inside the same mutex-serialized write that performs + * the transition: a preceding `get()` could observe a stale status, and only the hook can tell "this call + * wrote ABORTING" apart from "it was already ABORTING". */ -export async function abortRun(driver: Driver, run: RunRecord): Promise { +export async function abortRun(driver: Driver, run: RunRecord, gracefully = false): Promise { if (isTerminalJobStatus(run.status)) return run; const { runs } = getRegistries(); - const aborting = await transitionJobStatus(runs, run.id, 'ABORTING'); + let wasRunning = false; + let alreadyAborting = false; + const aborting = await transitionJobStatus(runs, run.id, 'ABORTING', {}, (current) => { + wasRunning = current?.status === 'RUNNING'; + alreadyAborting = current?.status === 'ABORTING'; + }); if (!aborting || aborting.status !== 'ABORTING') return aborting; + + // A second `?gracefully=true` call joining a window someone else already started: no-op, join it - + // never re-trigger the stop early (see the doc comment above). + if (alreadyAborting && gracefully) return aborting; + + if (!alreadyAborting && gracefully && wasRunning) { + // Best-effort, same no-subscriber tolerance `publishSystemInfo` already has (`events-channel.ts`): + // a run with nobody connected still waits out the window and still gets stopped. + publishAborting(run.id); + await new Promise((resolve) => setTimeout(resolve, GRACEFUL_ABORT_WINDOW_MS)); + } + await driver.abortRun(run.id); return transitionJobStatus(runs, run.id, 'ABORTED', { finishedAt: new Date().toISOString() }); } diff --git a/src/shutdown.ts b/src/shutdown.ts index 0ac4968..eaa95e5 100644 --- a/src/shutdown.ts +++ b/src/shutdown.ts @@ -28,6 +28,8 @@ export function closeServer(server: Server): Promise { export interface ShutdownDeps { apiServer: Server; consoleServer: Server; + /** Must be closed before `closeServer(apiServer)` is awaited - see `EventsWebSocketServer.close()`. */ + eventsWebSocketServer?: { close(): void }; } /** @@ -36,11 +38,19 @@ export interface ShutdownDeps { * queue's native state (`storage/bootstrap.ts`) - must always run on a graceful shutdown; sequencing it * behind a listener `close()` that can block indefinitely (the previous bug) meant it never did while a * `apify push`/`apify call` log stream was open, which is the common case, not the edge case. + * + * `eventsWebSocketServer` is closed before `closeServer(apiServer)`, which would otherwise hang on any + * still-connected client. */ -export async function gracefulShutdown({ apiServer, consoleServer }: ShutdownDeps): Promise { +export async function gracefulShutdown({ + apiServer, + consoleServer, + eventsWebSocketServer, +}: ShutdownDeps): Promise { stopLogFlusher(); await flushAllLogs(); await releaseAllBuffersForShutdown(); + eventsWebSocketServer?.close(); await closeServer(apiServer); await closeServer(consoleServer); await shutdownStorage(); diff --git a/test/integration/api-fallback.test.ts b/test/integration/api-fallback.test.ts index e7580a9..3a7f8b3 100644 --- a/test/integration/api-fallback.test.ts +++ b/test/integration/api-fallback.test.ts @@ -137,8 +137,8 @@ async function warmUpIdentity(baseUrl: string, token: string): Promise { }); } -/** A fixed `2xx` JSON response with a distinguishing header, the "the caller receives exactly this" - * shape criteria 11-15 check for every successful-relay case. */ +/** A fixed `2xx` JSON response with a distinguishing header - the shape every successful-relay test + * below checks the caller receives unchanged (`api.md`'s "A successful relay" bullet). */ function fixedOkResponse(distinguishingValue: string) { return () => ({ status: 200, @@ -380,8 +380,9 @@ describe('api-fallback: eligibility, relay, and fail-closed behaviour', () => { } /** Seeds and returns a non-terminal (`RUNNING`) run owned by the test's default token, so - * `DELETE /v2/actor-runs/:runId` throws `cannot-remove-running-run` - one of the "never forwards" - * conflict-style error types (criterion 18). */ + * `DELETE /v2/actor-runs/:runId` throws `cannot-remove-running-run` - one of the error types `api.md`'s + * "Which local outcome each toggle covers" bullet lists as never relayed, regardless of either + * toggle's state. */ async function seedRunningRun(): Promise { const actor = await server.client.actors().create({ name: `fallback-conflict-actor-${generateId()}` }); const actorRecord = (await getRegistries().actors.get(actor.id))!; @@ -679,12 +680,13 @@ describe('api-fallback: eligibility, relay, and fail-closed behaviour', () => { return res; } - /** Criterion 16's "byte-identical (status, body, and header set)" - checked here as the header - * *name* set plus every value except `date`, whose value legitimately differs run-to-run (its - * mere presence on both sides is asserted instead). This is what would have caught the fail-closed - * mid-body-death path silently dropping `date`/`connection`/`keep-alive`: that regression left - * status, body, and the two marker headers alone, so only a full-header-set comparison against the - * same request's both-toggles-off baseline surfaces it. */ + /** `api.md`'s "Fail-closed guarantee" bullet requires the original local error to be reproduced + * unchanged - checked here as the header *name* set plus every value except `date`, whose value + * legitimately differs run-to-run (its mere presence on both sides is asserted instead). This is + * what would have caught the fail-closed mid-body-death path silently dropping + * `date`/`connection`/`keep-alive`: that regression left status, body, and the two marker headers + * alone, so only a full-header-set comparison against the same request's both-toggles-off baseline + * surfaces it. */ function expectSameHeaderSet( actual: Record, baseline: Record, diff --git a/test/integration/cli-log-stream-race.test.ts b/test/integration/cli-log-stream-race.test.ts index 4547466..3791291 100644 --- a/test/integration/cli-log-stream-race.test.ts +++ b/test/integration/cli-log-stream-race.test.ts @@ -319,7 +319,7 @@ describe('CLI log-stream race: apify-cli outputJobLog must always settle (regres expect(() => appendLog(record.id, 'late line, after end\n')).not.toThrow(); }); - it("stress: many trials with randomized tight timing, the periodic flusher running, and unrelated concurrent traffic never leave the stream unsettled (regression for a low-probability race, cf. iter-12's 0.23%-under-flusher finding)", async () => { + it('stress: many trials with randomized tight timing, the periodic flusher running, and unrelated concurrent traffic never leave the stream unsettled (regression for a low-probability race that only surfaces under the periodic flusher)', async () => { const { startLogFlusher, stopLogFlusher } = await import('../../src/services/logs.js'); const TRIALS = 60; const failures: string[] = []; diff --git a/test/integration/events-websocket.test.ts b/test/integration/events-websocket.test.ts new file mode 100644 index 0000000..17d58e4 --- /dev/null +++ b/test/integration/events-websocket.test.ts @@ -0,0 +1,515 @@ +/** + * `GET /actor-runtime/events/:runId` - the events websocket (`api/events-ws.ts`), end to end against a + * real `ws` client and a real server (`startTestServer`'s `wsBaseUrl`, `api/events-ws.ts` attached the + * same way `index.ts` attaches it in production). Covers the events-endpoint contract documented in + * `requirements/api.md`: `systemInfo` frame delivery, strict per-run isolation (no global/broadcast + * channel), the `1008`/`1000` close-code lifecycle, and the `?gracefully=` `aborting` contract riding the + * same socket. + */ +import { request } from 'node:http'; +import { randomBytes } from 'node:crypto'; +import type { Socket } from 'node:net'; + +import { afterEach, describe, expect, it, vi } from 'vitest'; +import WebSocket from 'ws'; + +import { + multiRunDriver, + startTestServer, + unavailableDriver, + type MultiRunDriver, + type TestServerHandle, +} from './helpers/test-server.js'; +import { realDelay, waitForPendingTimer } from './helpers/fake-timers.js'; +import { abortRun } from '../../src/services/runs.js'; +import { getRegistries } from '../../src/storage/registries.js'; +import { getSubscriberCount } from '../../src/services/events-channel.js'; +import { generateId } from '../../src/storage/ids.js'; +import { recordTaggedBuild, updateActor } from '../../src/services/actors.js'; +import type { ActorRecord, BuildRecord, RunRecord } from '../../src/storage/entities.js'; +import type { RunResourceSample } from '../../src/driver/types.js'; + +async function seedActor(server: TestServerHandle, name: string): Promise { + const created = await server.client.actors().create({ name }); + return (await getRegistries().actors.get(created.id))!; +} + +/** A SUCCEEDED build with a fake image, seeded directly (bypassing the driver, which `multiRunDriver` + * cannot build with) - mirrors `job-lifecycle.test.ts`'s identical helper. */ +async function seedSucceededBuild(actor: ActorRecord): Promise { + const build: BuildRecord = { + id: generateId(), + userId: actor.userId, + actorId: actor.id, + versionNumber: '0.0', + buildNumber: '0.0.1', + tag: 'latest', + status: 'SUCCEEDED', + startedAt: new Date().toISOString(), + finishedAt: new Date().toISOString(), + imageId: 'fake-image:latest', + }; + await getRegistries().builds.set(build.id, build); + return build; +} + +/** Creates an Actor with a taggedBuild ready to run, and starts a run against it (not waiting for + * finish) - the run stays `RUNNING`, its container controllable via the returned `driver`, until the + * test calls `driver.resolveRun`/`abortRun`. */ +async function seedRunnableRun(server: TestServerHandle, driver: MultiRunDriver, name: string): Promise { + const actor = await seedActor(server, name); + const build = await seedSucceededBuild(actor); + await updateActor(actor.id, (current) => recordTaggedBuild(current, 'latest', build.id, build.buildNumber)); + const started = await server.client.actor(actor.id).start({}); + await driver.waitForStart(started.id); + return (await getRegistries().runs.get(started.id))!; +} + +function sample(overrides: Partial = {}): RunResourceSample { + return { + cpuPercentOfOneCore: 20, + memoryBytes: 402_653_184, + memoryLimitBytes: 1024 * 1024 * 1024, + at: new Date(), + ...overrides, + }; +} + +interface EventsSocket { + ws: WebSocket; + messages: Array<{ name: string; data: unknown }>; + closed: Promise<{ code: number; reason: string }>; +} + +function connectEventsSocket(server: TestServerHandle, runId: string): EventsSocket { + const ws = new WebSocket(`${server.wsBaseUrl}/actor-runtime/events/${runId}`); + const messages: Array<{ name: string; data: unknown }> = []; + ws.on('message', (data) => { + messages.push(JSON.parse(data.toString('utf8'))); + }); + const closed = new Promise<{ code: number; reason: string }>((resolve) => { + ws.on('close', (code, reasonBuffer) => resolve({ code, reason: reasonBuffer.toString('utf8') })); + }); + return { ws, messages, closed }; +} + +function waitForOpen(ws: WebSocket): Promise { + return new Promise((resolve, reject) => { + ws.once('open', () => resolve()); + ws.once('error', reject); + }); +} + +/** + * The client's `open` event fires as soon as the HTTP upgrade handshake completes - `api/events-ws.ts`'s + * own `handleConnection` is still an async function running *after* that (it resolves the run, then + * subscribes), so a sample/frame published immediately after `waitForOpen` can race ahead of the actual + * `subscribeEvents()` call and be silently dropped (broadcast to zero subscribers, never replayed). Polling + * `getSubscriberCount` - real-exported for exactly this kind of test synchronization (`events-channel.ts`'s + * own doc comment) - waits out that gap deterministically before a test emits anything. + */ +async function waitForSubscribed(runId: string): Promise { + await waitFor(() => getSubscriberCount(runId) > 0); +} + +/** + * Real-time polling for an async condition driven by a real websocket message arriving over a real + * loopback socket - genuine network I/O, never delivered in the same synchronous tick as the server-side + * `publish*`/`ws.send()` call that triggered it. Deliberately polls via `realDelay` (`setInterval`, never + * `setTimeout`): several of this file's tests fake `setTimeout` (to control `GRACEFUL_ABORT_WINDOW_MS`) + * while a frame is still in flight over the real socket, and a `setTimeout`-based poll would hang forever + * waiting on a fake timer nothing ever advances. + */ +async function waitFor(predicate: () => boolean, timeoutMs = 3000): Promise { + const deadline = Date.now() + timeoutMs; + while (!predicate()) { + if (Date.now() > deadline) throw new Error('waitFor: condition never became true in time'); + await realDelay(10); + } +} + +/** + * Completes a real HTTP upgrade handshake for `runId` and hands back the raw underlying `net.Socket` - + * bypassing the `ws` client library entirely, which (being a correct implementation) could never be made + * to emit an actually-malformed frame. Used to reproduce an unhandled `'error'` event on an + * already-accepted socket: a real upgrade, then raw invalid bytes written directly onto the wire. + */ +function rawUpgrade(server: TestServerHandle, runId: string): Promise { + return new Promise((resolve, reject) => { + const req = request(`${server.baseUrl}/actor-runtime/events/${runId}`, { + headers: { + Connection: 'Upgrade', + Upgrade: 'websocket', + 'Sec-WebSocket-Version': '13', + 'Sec-WebSocket-Key': randomBytes(16).toString('base64'), + }, + }); + req.on('upgrade', (_res, socket) => resolve(socket)); + req.on('error', reject); + req.end(); + }); +} + +/** + * Attempts a websocket upgrade against an arbitrary `path` and resolves with which outcome the raw + * `http.request` observed: `'upgrade'` (a 101 response, handed off to `ws`), `'response'` (a normal, + * non-101 HTTP response), or `'error'` (the connection failed/reset with no response at all - what a + * `socket.destroy()` on the still-pending request produces). + */ +function attemptUpgrade(server: TestServerHandle, path: string): Promise<'upgrade' | 'response' | 'error'> { + return new Promise((resolve) => { + const req = request(`${server.baseUrl}${path}`, { + headers: { + Connection: 'Upgrade', + Upgrade: 'websocket', + 'Sec-WebSocket-Version': '13', + 'Sec-WebSocket-Key': randomBytes(16).toString('base64'), + }, + }); + req.on('upgrade', () => resolve('upgrade')); + req.on('response', () => resolve('response')); + req.on('error', () => resolve('error')); + req.end(); + }); +} + +const SYSTEM_INFO_FIELDS = [ + 'memAvgBytes', + 'memCurrentBytes', + 'memMaxBytes', + 'cpuAvgUsage', + 'cpuMaxUsage', + 'cpuCurrentUsage', + 'isCpuOverloaded', + 'createdAt', +]; + +describe('events websocket (GET /actor-runtime/events/:runId)', () => { + let server: TestServerHandle; + + afterEach(async () => { + vi.useRealTimers(); + await server.close(); + }); + + it("accepts a connection with no auth at all and delivers the systemInfo frame the driver's onSample callback produced, with all eight fields present", async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-basic-actor'); + + const socket = connectEventsSocket(server, run.id); + await waitForOpen(socket.ws); + await waitForSubscribed(run.id); + + driver.emitSample(run.id, sample()); + await waitFor(() => socket.messages.length > 0); + + expect(socket.messages).toHaveLength(1); + expect(socket.messages[0]?.name).toBe('systemInfo'); + expect(Object.keys(socket.messages[0]!.data as Record).sort()).toEqual( + [...SYSTEM_INFO_FIELDS].sort(), + ); + + socket.ws.close(); + driver.resolveRun(run.id, { exitCode: 0, timedOut: false }); + }); + + it("two concurrently running Actors: a client connected to run A never receives run B's systemInfo frames, and vice versa (no global/broadcast channel)", async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const runA = await seedRunnableRun(server, driver, 'ws-iso-actor-a'); + const runB = await seedRunnableRun(server, driver, 'ws-iso-actor-b'); + + const socketA = connectEventsSocket(server, runA.id); + const socketB = connectEventsSocket(server, runB.id); + await Promise.all([waitForOpen(socketA.ws), waitForOpen(socketB.ws)]); + await Promise.all([waitForSubscribed(runA.id), waitForSubscribed(runB.id)]); + + // Distinguishable per-run values, so a leaked cross-run frame would be caught, not just miscounted. + driver.emitSample(runA.id, sample({ memoryBytes: 111_111_111 })); + driver.emitSample(runB.id, sample({ memoryBytes: 222_222_222 })); + + await waitFor(() => socketA.messages.length > 0 && socketB.messages.length > 0); + // Give any (incorrect) cross-delivery a moment to arrive before asserting counts. + await new Promise((resolve) => setTimeout(resolve, 50)); + + expect(socketA.messages).toHaveLength(1); + expect((socketA.messages[0]!.data as Record).memCurrentBytes).toBe(111_111_111); + expect(socketB.messages).toHaveLength(1); + expect((socketB.messages[0]!.data as Record).memCurrentBytes).toBe(222_222_222); + + socketA.ws.close(); + socketB.ws.close(); + driver.resolveRun(runA.id, { exitCode: 0, timedOut: false }); + driver.resolveRun(runB.id, { exitCode: 0, timedOut: false }); + }); + + it("a graceful abort on one of two concurrent runs delivers the aborting frame only on that run's own socket, never the other's", async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const runToAbort = await seedRunnableRun(server, driver, 'ws-abort-iso-actor-a'); + const unrelatedRun = await seedRunnableRun(server, driver, 'ws-abort-iso-actor-b'); + + const abortedSocket = connectEventsSocket(server, runToAbort.id); + const unrelatedSocket = connectEventsSocket(server, unrelatedRun.id); + await Promise.all([waitForOpen(abortedSocket.ws), waitForOpen(unrelatedSocket.ws)]); + await Promise.all([waitForSubscribed(runToAbort.id), waitForSubscribed(unrelatedRun.id)]); + + // Calls the service layer directly (mirrors `graceful-abort.test.ts`'s own tests) rather than a real + // HTTP round trip - the route itself is a thin `queryBoolean` pass-through (`api/routes/runs.ts`) + // already covered elsewhere; this test's own job is the events-channel fan-out and per-run + // isolation, which `abortRun` already exercises for real. + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + const abortPromise = abortRun(driver, runToAbort, true); + + await waitForPendingTimer(); + await waitFor(() => abortedSocket.messages.some((m) => m.name === 'aborting')); + + expect(abortedSocket.messages).toContainEqual({ name: 'aborting', data: {} }); + expect(unrelatedSocket.messages.some((m) => m.name === 'aborting')).toBe(false); + // Never persistState, on either socket, under any circumstance. + expect(abortedSocket.messages.some((m) => m.name === 'persistState')).toBe(false); + expect(unrelatedSocket.messages.some((m) => m.name === 'persistState')).toBe(false); + + await vi.advanceTimersByTimeAsync(30_000); + await abortPromise; + vi.useRealTimers(); + + abortedSocket.ws.close(); + unrelatedSocket.ws.close(); + // Lets both runs' own dangling `runInBackground` background tasks settle (the terminal-status guard + // makes this a safe no-op for the already-`ABORTED` one) - tidiness, not required for the assertions + // above, which the persisted-record fallback in `api/events-ws.ts`'s poll already satisfies. + driver.resolveRun(runToAbort.id, { exitCode: 137, timedOut: false }); + driver.resolveRun(unrelatedRun.id, { exitCode: 0, timedOut: false }); + }); + + it('completes the upgrade and then closes with 1008 and a non-empty reason for an unknown run id (never a non-101 HTTP status)', async () => { + server = await startTestServer(unavailableDriver()); + const socket = connectEventsSocket(server, 'no-such-run-id-at-all'); + + await waitForOpen(socket.ws); // the upgrade itself succeeds + const closeEvent = await socket.closed; + + expect(closeEvent.code).toBe(1008); + expect(closeEvent.reason.length).toBeGreaterThan(0); + }); + + it('completes the upgrade and then closes with 1008 for a run already in a terminal state', async () => { + server = await startTestServer(unavailableDriver()); + const terminalRun: RunRecord = { + id: generateId(), + userId: 'some-user', + actorId: 'some-actor', + buildId: 'some-build', + buildNumber: '0.0.1', + status: 'SUCCEEDED', + startedAt: new Date().toISOString(), + finishedAt: new Date().toISOString(), + exitCode: 0, + defaultDatasetId: 'd', + defaultKeyValueStoreId: 'k', + defaultRequestQueueId: 'r', + options: { memoryMbytes: 1024, timeoutSecs: 300 }, + meta: { origin: 'API' }, + }; + await getRegistries().runs.set(terminalRun.id, terminalRun); + + const socket = connectEventsSocket(server, terminalRun.id); + await waitForOpen(socket.ws); + const closeEvent = await socket.closed; + + expect(closeEvent.code).toBe(1008); + expect(closeEvent.reason.length).toBeGreaterThan(0); + }); + + it('closes with 1000 once a live run reaches a normal end - not 1008, not left hanging', async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-normal-end-actor'); + + const socket = connectEventsSocket(server, run.id); + await waitForOpen(socket.ws); + await waitForSubscribed(run.id); + + driver.resolveRun(run.id, { exitCode: 0, timedOut: false }); + const closeEvent = await socket.closed; + + expect(closeEvent.code).toBe(1000); + }); + + it('closes with 1000 once a graceful abort completes (the container stops, the record reaches ABORTED) - not 1008', async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-graceful-end-actor'); + + const socket = connectEventsSocket(server, run.id); + await waitForOpen(socket.ws); + await waitForSubscribed(run.id); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + const abortPromise = abortRun(driver, run, true); + + await waitForPendingTimer(); + await vi.advanceTimersByTimeAsync(30_000); + await abortPromise; + vi.useRealTimers(); + + const closeEvent = await socket.closed; + expect(closeEvent.code).toBe(1000); + // The graceful abort's own frame arrived, persistState never did. + expect(socket.messages).toContainEqual({ name: 'aborting', data: {} }); + expect(socket.messages.some((m) => m.name === 'persistState')).toBe(false); + }); + + it("never drops a healthy, still-running run's connection for any reason short of the run ending or being rejected", async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-no-server-drop-actor'); + + const socket = connectEventsSocket(server, run.id); + await waitForOpen(socket.ws); + await waitForSubscribed(run.id); + + let closed = false; + void socket.closed.then(() => { + closed = true; + }); + + // Several systemInfo ticks over real time, well within the run's lifetime - no close should occur. + for (let i = 0; i < 3; i++) { + driver.emitSample(run.id, sample()); + await new Promise((resolve) => setTimeout(resolve, 50)); + } + + expect(closed).toBe(false); + expect(socket.ws.readyState).toBe(WebSocket.OPEN); + expect(socket.messages.length).toBe(3); + expect(socket.messages.every((m) => m.name === 'systemInfo')).toBe(true); + + socket.ws.close(); + driver.resolveRun(run.id, { exitCode: 0, timedOut: false }); + }); + + it('a reconnect after a run has already ended (via normal completion) hits the terminal-run check and gets 1008', async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-reconnect-after-end-actor'); + + const firstSocket = connectEventsSocket(server, run.id); + await waitForOpen(firstSocket.ws); + await waitForSubscribed(run.id); + driver.resolveRun(run.id, { exitCode: 0, timedOut: false }); + expect((await firstSocket.closed).code).toBe(1000); + + const reconnectSocket = connectEventsSocket(server, run.id); + await waitForOpen(reconnectSocket.ws); + const closeEvent = await reconnectSocket.closed; + expect(closeEvent.code).toBe(1008); + }); + + it('destroys the raw socket for an upgrade request whose path does not match the events endpoint at all - never upgraded, never left hanging', async () => { + server = await startTestServer(unavailableDriver()); + + const outcome = await attemptUpgrade(server, '/actor-runtime/not-the-events-path'); + + expect(outcome).toBe('error'); + }); + + it('treats a trailing-slash spelling of the events path as a non-match too - reachable at exactly the one documented path (requirements/api.md)', async () => { + server = await startTestServer(unavailableDriver()); + + const outcome = await attemptUpgrade(server, '/actor-runtime/events/some-run-id/'); + + expect(outcome).toBe('error'); + }); + + it("never sends a frame to a socket that has started closing but not yet fully closed - the subscribe callback's readyState guard, not just docker/ws's own no-op-after-close behavior", async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-send-guard-actor'); + + const socket = connectEventsSocket(server, run.id); + await waitForOpen(socket.ws); + await waitForSubscribed(run.id); + + // Spying on the shared `ws.WebSocket` class (the same module both this test's client and the + // server's own connection are instances of) is the only way to observe the SERVER's own connection + // object from outside - `attachEventsWebSocket` exposes no handle to it. `close()` is called + // exactly twice in the sequence below: once by this test (the client), once by the server's own + // `ws` instance reacting to the client's close frame (`receiverOnConclude` -> `websocket.close()` in + // `ws/lib/websocket.js`) - the second call's `this` is the server-side connection, mid-closing- + // handshake, which is the exact window the guard exists for. + const closeSpy = vi.spyOn(WebSocket.prototype, 'close'); + const sendSpy = vi.spyOn(WebSocket.prototype, 'send'); + + socket.ws.close(); + await waitFor(() => closeSpy.mock.contexts.some((ctx) => ctx !== socket.ws)); + const serverWs = closeSpy.mock.contexts.find((ctx) => ctx !== socket.ws) as WebSocket; + expect(serverWs.readyState).not.toBe(WebSocket.OPEN); + + const sendCallsBefore = sendSpy.mock.calls.length; + driver.emitSample(run.id, sample()); + await realDelay(50); + + // The guard skipped the publish entirely - no frame reached this socket, and `ws.send()` was never + // even attempted on the server's own (closing) connection object. + expect(socket.messages).toHaveLength(0); + expect(sendSpy.mock.calls.length).toBe(sendCallsBefore); + + closeSpy.mockRestore(); + sendSpy.mockRestore(); + await socket.closed; + driver.resolveRun(run.id, { exitCode: 0, timedOut: false }); + }); + + it('an unhandled protocol-level error on a connected socket (a malformed frame) never crashes the process - it is contained to that one connection', async () => { + const driver = multiRunDriver(); + server = await startTestServer(driver); + const run = await seedRunnableRun(server, driver, 'ws-malformed-frame-actor'); + + const socket = await rawUpgrade(server, run.id); + + // If `handleConnection` ever again omits an `'error'` listener on the accepted `WebSocket`, `ws` + // throws this synchronously out of its own internal socket-data handler - with nothing up that + // call stack to catch it, Node turns it into a process-wide `'uncaughtException'`, which (with no + // listener of our own) would otherwise crash this entire test worker, not just fail an assertion. + // Registering a listener here doesn't just observe that outcome; per Node's own documented + // semantics, adding an `'uncaughtException'` listener is what prevents the default crash-and-exit, + // which is exactly why this test is able to make a red/green assertion here at all instead of + // taking the whole process down with it pre-fix. + const uncaughtErrors: unknown[] = []; + const onUncaught = (error: unknown): void => { + uncaughtErrors.push(error); + }; + process.on('uncaughtException', onUncaught); + try { + // Ten invalid frame bytes (RSV2/RSV3 set) - the shape of malformed frame the installed `ws` + // package rejects with a synchronous `'error'` emission, per `handleConnection`'s own doc + // comment (`api/events-ws.ts`). + socket.write(Buffer.from([0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff, 0xff])); + + // Give the server a real moment to actually process the bad frame (and, pre-fix, crash). + await new Promise((resolve) => setTimeout(resolve, 200)); + + expect(uncaughtErrors).toEqual([]); + } finally { + process.removeListener('uncaughtException', onUncaught); + } + + // Not just "didn't throw synchronously" - the server is still alive and still serving every other + // run: a fresh connection to an unrelated, healthy run still gets its frames normally. + const otherRun = await seedRunnableRun(server, driver, 'ws-malformed-frame-survivor-actor'); + const otherSocket = connectEventsSocket(server, otherRun.id); + await waitForOpen(otherSocket.ws); + await waitForSubscribed(otherRun.id); + driver.emitSample(otherRun.id, sample()); + await waitFor(() => otherSocket.messages.length > 0); + expect(otherSocket.messages[0]?.name).toBe('systemInfo'); + + socket.destroy(); + otherSocket.ws.close(); + driver.resolveRun(run.id, { exitCode: 0, timedOut: false }); + driver.resolveRun(otherRun.id, { exitCode: 0, timedOut: false }); + }); +}); diff --git a/test/integration/graceful-abort.test.ts b/test/integration/graceful-abort.test.ts new file mode 100644 index 0000000..ac69b01 --- /dev/null +++ b/test/integration/graceful-abort.test.ts @@ -0,0 +1,477 @@ +/** + * `?gracefully=` abort contract (`requirements/api.md`'s "Graceful abort" section, + * `GRACEFUL_ABORT_WINDOW_MS = 30000`): the `aborting` frame published before the fixed wait, + * `driver.abortRun` withheld until the window elapses, the omitted/`false` path staying byte-identical to + * an immediate abort, best-effort behavior with nobody connected, the READY-state and already-terminal + * short-circuits, and two concurrent abort calls racing the same window (a second graceful call joins + * rather than restarting it; a second hard call escalates past it). The second `describe` below exercises + * the same contract over a real HTTP round trip (`apify-client`), not just direct `abortRun` calls. + * + * Split out of `job-lifecycle.test.ts` (which had grown past 1000 lines once these two `describe` blocks + * were added, making both suites harder to navigate) - every test below is unchanged from that file, + * byte-for-byte; only the imports and the small set of shared setup helpers the split needs were copied over. + */ +import { afterEach, describe, expect, it, vi } from 'vitest'; + +import { + deferredRunDriver, + fixedRunOutcomeDriver, + startTestServer, + type TestServerHandle, +} from './helpers/test-server.js'; +import { getRegistries } from '../../src/storage/registries.js'; +import { generateId } from '../../src/storage/ids.js'; +import { recordTaggedBuild, updateActor } from '../../src/services/actors.js'; +import { abortRun, runInBackground } from '../../src/services/runs.js'; +import { subscribeEvents } from '../../src/services/events-channel.js'; +import { realDelay, waitForPendingTimer } from './helpers/fake-timers.js'; +import type { Driver } from '../../src/driver/types.js'; +import type { ActorRecord, BuildRecord, JobStatus, RunRecord } from '../../src/storage/entities.js'; + +/** Creates an Actor via the real client (so it has a genuine owner) and returns the underlying + * `ActorRecord` for direct service-layer calls. */ +async function seedActor(server: TestServerHandle, name: string): Promise { + const created = await server.client.actors().create({ name }); + return (await getRegistries().actors.get(created.id))!; +} + +/** A SUCCEEDED build with a fake image, seeded directly (bypassing the driver) - mirrors the pattern + * already used by `actors-builds-runs.test.ts`. */ +async function seedSucceededBuild(actor: ActorRecord): Promise { + const build: BuildRecord = { + id: generateId(), + userId: actor.userId, + actorId: actor.id, + versionNumber: '0.0', + buildNumber: '0.0.1', + tag: 'latest', + status: 'SUCCEEDED', + startedAt: new Date().toISOString(), + finishedAt: new Date().toISOString(), + imageId: 'fake-image:latest', + }; + await getRegistries().builds.set(build.id, build); + return build; +} + +function bareRunRecord(actor: ActorRecord, build: BuildRecord): RunRecord { + return { + id: generateId(), + userId: actor.userId, + actorId: actor.id, + buildId: build.id, + buildNumber: build.buildNumber, + status: 'READY', + startedAt: new Date().toISOString(), + defaultDatasetId: 'd', + defaultKeyValueStoreId: 'k', + defaultRequestQueueId: 'r', + options: { memoryMbytes: 1024, timeoutSecs: 300 }, + meta: { origin: 'API' }, + }; +} + +/** Fails the test immediately (rather than hanging) if the driver is ever asked to start a run/build - + * used to assert the pre-start abort window really does prevent a container/build from ever starting. */ +function neverStartDriver(): Driver & { abortRunCalls: string[]; abortBuildCalls: string[] } { + const abortRunCalls: string[] = []; + const abortBuildCalls: string[] = []; + return { + available: true, + abortRunCalls, + abortBuildCalls, + async init() {}, + async startBuild() { + throw new Error('startBuild must never be called once the record is already ABORTING'); + }, + async abortBuild(buildId) { + abortBuildCalls.push(buildId); + }, + async startRun() { + throw new Error('startRun must never be called once the record is already ABORTING'); + }, + async abortRun(runId) { + abortRunCalls.push(runId); + }, + async reconcileOrphans() {}, + async probeDevFolder() { + throw new Error('not used by this stub'); + }, + async ensureProbeImage() { + throw new Error('not used by this stub'); + }, + }; +} + +/** + * Real-time polling (never gated by a fake `setTimeout`) for a run's status as observed over a real HTTP + * `GET`, via `apify-client`. Needed instead of `waitForPendingTimer` when the trigger being awaited is a + * real HTTP round trip (`server.client.run(id).abort(...)`): `apify-client`'s own request pipeline (e.g. + * its HTTP agent's keep-alive bookkeeping) can register an incidental `setTimeout` of its own well before + * the server has actually processed the request, so "some fake timer now exists anywhere in this process" + * is not a reliable proxy for "the server's own `ABORTING` write has landed" once a real client is in the + * mix - unlike every other graceful-abort test in this file, which calls `abortRun` directly and has no + * such incidental timer source to race against. + */ +async function pollForRunStatus( + server: TestServerHandle, + runId: string, + status: JobStatus, + timeoutMs = 3000, +): Promise { + const deadline = Date.now() + timeoutMs; + for (;;) { + const current = await server.client.run(runId).get(); + if (current?.status === status) return; + if (Date.now() > deadline) { + throw new Error( + `timed out waiting for run ${runId} to reach status ${status} (last seen: ${current?.status})`, + ); + } + await realDelay(10); + } +} + +describe('graceful abort (?gracefully=) contract', () => { + let server: TestServerHandle; + + afterEach(async () => { + await server.close(); + }); + + describe('graceful abort (?gracefully= contract per requirements/api.md "Graceful abort" section, GRACEFUL_ABORT_WINDOW_MS = 30000)', () => { + afterEach(() => { + vi.useRealTimers(); + }); + + it('gracefully omitted is byte-identical to today: driver.abortRun is called immediately, no aborting frame, no wait', async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-omitted-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + await getRegistries().runs.set(record.id, record); + + const frames: string[] = []; + const unsubscribe = subscribeEvents(record.id, (frame) => frames.push(frame)); + + const bg = runInBackground(driver, actor, record, { apiBaseUrl: server.baseUrl, token: server.token }); + await driver.started; + + const aborted = await abortRun(driver, record); // gracefully omitted entirely + expect(aborted?.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([record.id]); + expect(frames).toEqual([]); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + await bg; + unsubscribe(); + }); + + it('gracefully: false is explicitly the same as omitted', async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-false-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + await getRegistries().runs.set(record.id, record); + + const bg = runInBackground(driver, actor, record, { apiBaseUrl: server.baseUrl, token: server.token }); + await driver.started; + + const aborted = await abortRun(driver, record, false); + expect(aborted?.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([record.id]); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + await bg; + }); + + it('gracefully: true publishes exactly {"name":"aborting","data":{}} before driver.abortRun, moves the run to ABORTING immediately, and only calls driver.abortRun once the full 30000ms window has elapsed', async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-true-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + await getRegistries().runs.set(record.id, record); + + const frames: string[] = []; + const unsubscribe = subscribeEvents(record.id, (frame) => frames.push(frame)); + + const bg = runInBackground(driver, actor, record, { apiBaseUrl: server.baseUrl, token: server.token }); + await driver.started; + + // Faked only from here on, and only `setTimeout`/`clearTimeout` - `abortRun`'s 30s wait is the + // only thing this test needs virtual control over. Deliberately NOT `Date` and NOT + // `setImmediate`: the registry writes below go through `@crawlee/fs-storage`'s real + // (native-addon-backed) storage layer, which this sandbox found does not tolerate a frozen + // `Date.now()` - a write can silently read back stale under a fully-fake clock. Leaving `Date` + // and `setImmediate` real costs nothing here: nothing in this test asserts on wall-clock time + // itself, only on `setTimeout`'s own virtual schedule. + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const abortPromise = abortRun(driver, record, true); + + // requirements/api.md's "Graceful abort" section: ABORTING lands immediately - observable well + // before the 30s window elapses - and the aborting frame is published before the wait, not + // after it. Waiting for the wait's own `setTimeout` to actually be scheduled is what proves both + // already happened, since both come strictly before it in `abortRun`'s own code. + await waitForPendingTimer(); + const midWindow = await getRegistries().runs.get(record.id); + expect(midWindow?.status).toBe('ABORTING'); + expect(frames).toEqual([JSON.stringify({ name: 'aborting', data: {} })]); + expect(driver.abortRunCalls).toEqual([]); + + // Just under the window: still not called. + await vi.advanceTimersByTimeAsync(29_999); + expect(driver.abortRunCalls).toEqual([]); + + // At the window: now called. + await vi.advanceTimersByTimeAsync(1); + expect(driver.abortRunCalls).toEqual([record.id]); + + const aborted = await abortPromise; + expect(aborted?.status).toBe('ABORTED'); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + await bg; + unsubscribe(); + }); + + it('gracefully: true with nobody connected to the events socket is still best-effort - the abort request itself still succeeds and the container is still stopped after the window elapses', async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-no-subscriber-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + await getRegistries().runs.set(record.id, record); + // Deliberately no `subscribeEvents(record.id, ...)` call at all - nobody is connected. + + const bg = runInBackground(driver, actor, record, { apiBaseUrl: server.baseUrl, token: server.token }); + await driver.started; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + const abortPromise = abortRun(driver, record, true); + await waitForPendingTimer(); + await vi.advanceTimersByTimeAsync(30_000); + const aborted = await abortPromise; + + expect(aborted?.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([record.id]); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + await bg; + }); + + it('gracefully: true against a READY-state abort (no container yet) keeps the immediate ABORTING -> ABORTED path - no 30s wait, no aborting frame', async () => { + const driver = neverStartDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-ready-state-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); // status READY, no container ever created + await getRegistries().runs.set(record.id, record); + + const frames: string[] = []; + const unsubscribe = subscribeEvents(record.id, (frame) => frames.push(frame)); + + const aborted = await abortRun(driver, record, true); + + expect(aborted?.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([record.id]); + expect(frames).toEqual([]); // no container running - no aborting frame, no wait + + unsubscribe(); + }); + + it('gracefully: true is a no-op on an already-terminal run, same as gracefully omitted', async () => { + server = await startTestServer(fixedRunOutcomeDriver({ exitCode: 0, timedOut: false })); + const actor = await seedActor(server, 'graceful-terminal-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + const terminalRecord: RunRecord = { ...record, status: 'SUCCEEDED', finishedAt: new Date().toISOString() }; + await getRegistries().runs.set(record.id, terminalRecord); + + const aborted = await abortRun(server.driver, terminalRecord, true); + expect(aborted?.status).toBe('SUCCEEDED'); + }); + + it('a second ?gracefully=true call arriving while a first graceful window is still open does not defeat it: it no-ops (joins, no early stop), and the window still ends in exactly one driver.abortRun call', async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-double-graceful-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + await getRegistries().runs.set(record.id, record); + + const bg = runInBackground(driver, actor, record, { apiBaseUrl: server.baseUrl, token: server.token }); + await driver.started; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const firstAbort = abortRun(driver, record, true); + await waitForPendingTimer(); + const midWindow = await getRegistries().runs.get(record.id); + expect(midWindow?.status).toBe('ABORTING'); + expect(driver.abortRunCalls).toEqual([]); + + // The second call re-fetches the record first, exactly as the real HTTP route does via + // `getOwnedRun`: `abortRun` checks `isTerminalJobStatus(run.status)` on its `run` parameter + // before ever touching the registry, so passing the first call's now-stale local object here + // (instead of a freshly re-fetched one) would let this call observe a different status than a + // genuinely concurrent second request actually would. + const secondAbort = abortRun(driver, midWindow!, true); + const secondResult = await secondAbort; + + // The no-op join: the second call must not itself have started a window or called + // driver.abortRun - it returns the record exactly as it stood (still ABORTING), immediately, + // without waiting. + expect(secondResult?.status).toBe('ABORTING'); + expect(driver.abortRunCalls).toEqual([]); + + // Just under the first call's own window: still not called - the second call did not shorten it. + await vi.advanceTimersByTimeAsync(29_999); + expect(driver.abortRunCalls).toEqual([]); + + // At the window: exactly one driver.abortRun call - the first caller's own, and only one. + await vi.advanceTimersByTimeAsync(1); + expect(driver.abortRunCalls).toEqual([record.id]); + + const firstResult = await firstAbort; + expect(firstResult?.status).toBe('ABORTED'); + + const final = await getRegistries().runs.get(record.id); + expect(final?.status).toBe('ABORTED'); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + await bg; + }); + + it("a second, hard (?gracefully=false) call arriving while a graceful window is still open is a deliberate escalation: it stops the container immediately, and the first caller's own pending window later resolves cleanly (no error, no double-write) once it elapses", async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-then-hard-actor'); + const build = await seedSucceededBuild(actor); + const record = bareRunRecord(actor, build); + await getRegistries().runs.set(record.id, record); + + const bg = runInBackground(driver, actor, record, { apiBaseUrl: server.baseUrl, token: server.token }); + await driver.started; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const firstAbort = abortRun(driver, record, true); + await waitForPendingTimer(); + const midWindow = await getRegistries().runs.get(record.id); + expect(midWindow?.status).toBe('ABORTING'); + expect(driver.abortRunCalls).toEqual([]); + + // The escalation: a plain (hard) abort call, re-fetching the record first like the real HTTP + // route does, stops the container right away - it does not wait out someone else's window. + const secondResult = await abortRun(driver, midWindow!, false); + expect(secondResult?.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([record.id]); + + const afterEscalation = await getRegistries().runs.get(record.id); + expect(afterEscalation?.status).toBe('ABORTED'); + + // The first caller's own window still elapses on its own schedule. Its `driver.abortRun` call + // is then just a harmless second no-op, and its final `-> ABORTED` write is refused (the + // record is already terminal) rather than erroring or clobbering anything - confirmed here by + // awaiting the first call's promise all the way through with no exception. + await vi.advanceTimersByTimeAsync(30_000); + const firstResult = await firstAbort; + expect(firstResult?.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([record.id, record.id]); + + const final = await getRegistries().runs.get(record.id); + expect(final?.status).toBe('ABORTED'); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + await bg; + }); + }); + + describe('?gracefully= exercised over a real HTTP round trip, not just direct service-layer calls', () => { + afterEach(() => { + vi.useRealTimers(); + }); + + it("POST .../abort?gracefully=true (via apify-client, the actors-builds-runs.test.ts .abort() pattern) gets the full graceful contract: ABORTING immediately, the HTTP response itself only resolving after the 30s window, and the aborting frame emitted on the run's own events channel", async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'graceful-http-actor'); + const build = await seedSucceededBuild(actor); + await updateActor(actor.id, (current) => recordTaggedBuild(current, 'latest', build.id, build.buildNumber)); + + // A genuine run started through the real client - not a hand-seeded record - so the run id below + // is one the HTTP abort route's own ownership check (`getOwnedRun`) actually resolves, exactly as + // a real caller's request would. + const started = await server.client.actor(actor.id).start({}); + await driver.started; + expect(driver.startRunCalls).toEqual([started.id]); + + const frames: string[] = []; + const unsubscribe = subscribeEvents(started.id, (frame) => frames.push(frame)); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + // The real HTTP round trip: `apify-client`'s `RunClient.abort({gracefully:true})` issues + // `POST /v2/actor-runs/:runId/abort?gracefully=true`, exercising `api/routes/runs.ts`'s own + // `queryBoolean` parsing and its call into `abortRun` - never `abortRun` called directly, unlike + // every other graceful-abort test in the "graceful abort" section above. + const abortPromise = server.client.run(started.id).abort({ gracefully: true }); + + // requirements/api.md's "Graceful abort" section: ABORTING lands immediately - observable over + // the same real HTTP client, well before the HTTP response itself resolves. Polled in real time + // (not via `waitForPendingTimer`): + // `apify-client`'s own request pipeline can register an incidental `setTimeout` of its own before + // the server has actually processed anything, so "a fake timer now exists somewhere in this + // process" is not a reliable signal here the way it is for every other graceful-abort test in + // this file, none of which go through a real HTTP client. + await pollForRunStatus(server, started.id, 'ABORTING'); + expect(frames).toEqual([JSON.stringify({ name: 'aborting', data: {} })]); + expect(driver.abortRunCalls).toEqual([]); + + let responded = false; + void abortPromise.then(() => { + responded = true; + }); + + // Just under the window: the HTTP response is still being held open server-side. + await vi.advanceTimersByTimeAsync(29_999); + expect(responded).toBe(false); + expect(driver.abortRunCalls).toEqual([]); + + // At the window: `driver.abortRun` fires and the HTTP response finally resolves. + await vi.advanceTimersByTimeAsync(1); + const aborted = await abortPromise; + expect(aborted.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([started.id]); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + unsubscribe(); + }); + + it('POST .../abort with no gracefully parameter, over the same real HTTP round trip, still returns immediately with no wait (matches requirements/api.md\'s "omitted, or false" graceful-abort behavior end to end, not just at the service layer)', async () => { + const driver = deferredRunDriver(); + server = await startTestServer(driver); + const actor = await seedActor(server, 'immediate-http-actor'); + const build = await seedSucceededBuild(actor); + await updateActor(actor.id, (current) => recordTaggedBuild(current, 'latest', build.id, build.buildNumber)); + + const started = await server.client.actor(actor.id).start({}); + await driver.started; + + const frames: string[] = []; + const unsubscribe = subscribeEvents(started.id, (frame) => frames.push(frame)); + + const aborted = await server.client.run(started.id).abort(); + expect(aborted.status).toBe('ABORTED'); + expect(driver.abortRunCalls).toEqual([started.id]); + expect(frames).toEqual([]); + + driver.resolveRun({ exitCode: 137, timedOut: false }); + unsubscribe(); + }); + }); +}); diff --git a/test/integration/helpers/fake-timers.ts b/test/integration/helpers/fake-timers.ts new file mode 100644 index 0000000..a834076 --- /dev/null +++ b/test/integration/helpers/fake-timers.ts @@ -0,0 +1,43 @@ +/** + * A tiny helper for tests that fake `setTimeout`/`clearTimeout` (to control `GRACEFUL_ABORT_WINDOW_MS` + * without a real 30-second wait) while other code in the same test still performs real, `@crawlee/ + * fs-storage`-backed registry I/O (native-addon-backed, genuinely asynchronous - not itself gated by any + * faked timer). `vi.advanceTimersByTimeAsync` only advances *already-scheduled* fake timers; called + * before the real registry write that precedes `abortRun`'s `setTimeout` call has actually landed, it + * finds nothing to advance and returns immediately, leaving that `setTimeout` call to be made moments + * later with no further advance ever coming - a permanent hang. `waitForPendingTimer` closes that window + * by polling (with a genuine real-time pause, `realDelay` below) until the timer actually exists before + * any test advances fake time past it. + */ +import { vi } from 'vitest'; + +/** A genuine real-wall-clock pause. Deliberately not `setTimeout` (faked by callers of this module) and + * deliberately not a bare `setImmediate`/microtask spin either - a spin with no minimum delay can execute + * thousands of iterations within under a millisecond of real time, never actually ceding the CPU long + * enough for a background OS thread (the native fs-storage addon's own thread-pool work) to complete. + * `setInterval`/`clearInterval` are never faked by this module's callers, so this genuinely waits `ms` of + * real time regardless of what else is faked. */ +export function realDelay(ms: number): Promise { + return new Promise((resolve) => { + const timer = setInterval(() => { + clearInterval(timer); + resolve(); + }, ms); + }); +} + +/** Polls (via `realDelay`, real time) until at least one fake timer has actually been scheduled - i.e. + * until whatever real, awaited work precedes the `setTimeout` call under test has genuinely completed. + * Callers should install fake timers with `toFake: ['setTimeout', 'clearTimeout']` only (never `Date` or + * `setImmediate`), and never advance fake time before this resolves. */ +export async function waitForPendingTimer(timeoutMs = 2000): Promise { + const deadline = Date.now() + timeoutMs; + while (vi.getTimerCount() === 0) { + if (Date.now() > deadline) { + throw new Error( + 'Timed out waiting for a fake timer to be scheduled - the real work gated behind it never completed in time.', + ); + } + await realDelay(2); + } +} diff --git a/test/integration/helpers/test-server.ts b/test/integration/helpers/test-server.ts index 0ba8353..0c9d915 100644 --- a/test/integration/helpers/test-server.ts +++ b/test/integration/helpers/test-server.ts @@ -11,8 +11,10 @@ import { openRegistries, resetRegistriesForTests } from '../../../src/storage/re import { resetUsersForTests } from '../../../src/services/users.js'; import { resetApiFallbackStateForTests } from '../../../src/services/api-fallback.js'; import { createApiServer } from '../../../src/api/server.js'; +import { attachEventsWebSocket } from '../../../src/api/events-ws.js'; import { resetLogsForTests, stopLogFlusher } from '../../../src/services/logs.js'; -import type { BuildContext, BuildOutcome, Driver, RunOutcome } from '../../../src/driver/types.js'; +import { resetEventsChannelForTests } from '../../../src/services/events-channel.js'; +import type { BuildContext, BuildOutcome, Driver, RunOutcome, RunResourceSample } from '../../../src/driver/types.js'; /** A driver that is always unavailable, so build/run creation fails fast and deterministically. */ export function unavailableDriver(): Driver { @@ -209,9 +211,106 @@ export function deferredBuildDriver(): DeferredBuildDriver { }; } +/** + * Same idea as `deferredRunDriver`, but tracking an arbitrary number of runs *concurrently* rather than + * exactly one - needed for the events-websocket integration tests, which need two independently + * controllable runs open at once (`deferredRunDriver`'s single `started`/`resolveRun` pair cannot express + * that). Also captures each run's own `onSample` callback (`Driver.startRun`'s optional third parameter) + * so a test can simulate the driver's per-second sampler ticking - `emitSample` - without a real Docker + * daemon or a real 1000ms wait. + */ +export interface MultiRunDriver extends Driver { + abortRunCalls: string[]; + /** Resolves once `startRun` has actually been called for `runId` - mirrors `deferredRunDriver`'s + * `started`, per-run. */ + waitForStart(runId: string): Promise; + resolveRun(runId: string, outcome: RunOutcome): void; + rejectRun(runId: string, error: Error): void; + /** Invokes `runId`'s own captured `onSample` callback, if `startRun` was ever called with one - + * simulates one sampler tick. A no-op (never throws) if `startRun` hasn't been called for `runId` yet, + * or was called without an `onSample` at all. */ + emitSample(runId: string, sample: RunResourceSample): void; +} + +interface MultiRunState { + startedResolve: () => void; + started: Promise; + outcomeResolve: (outcome: RunOutcome) => void; + outcomeReject: (error: Error) => void; + outcomePromise: Promise; + onSample?: (sample: RunResourceSample) => void; +} + +export function multiRunDriver(): MultiRunDriver { + const states = new Map(); + const abortRunCalls: string[] = []; + + function getOrCreateState(runId: string): MultiRunState { + let state = states.get(runId); + if (!state) { + let startedResolve!: () => void; + const started = new Promise((resolve) => { + startedResolve = resolve; + }); + let outcomeResolve!: (outcome: RunOutcome) => void; + let outcomeReject!: (error: Error) => void; + const outcomePromise = new Promise((resolve, reject) => { + outcomeResolve = resolve; + outcomeReject = reject; + }); + state = { startedResolve, started, outcomeResolve, outcomeReject, outcomePromise }; + states.set(runId, state); + } + return state; + } + + return { + available: true, + abortRunCalls, + async init() {}, + async startBuild() { + throw new Error('not used by this stub'); + }, + async abortBuild() {}, + async startRun(ctx, _onLog, onSample) { + const state = getOrCreateState(ctx.runId); + state.onSample = onSample; + state.startedResolve(); + return state.outcomePromise; + }, + async abortRun(runId) { + abortRunCalls.push(runId); + }, + async reconcileOrphans() {}, + async probeDevFolder() { + throw new Error('not used by this stub'); + }, + async ensureProbeImage() { + throw new Error('not used by this stub'); + }, + async waitForStart(runId) { + return getOrCreateState(runId).started; + }, + resolveRun(runId, outcome) { + getOrCreateState(runId).outcomeResolve(outcome); + }, + rejectRun(runId, error) { + getOrCreateState(runId).outcomeReject(error); + }, + emitSample(runId, sample) { + getOrCreateState(runId).onSample?.(sample); + }, + }; +} + export interface TestServerHandle { client: ApifyClient; baseUrl: string; + /** `baseUrl`, `ws://`-scheméd - the same host:port, since the events websocket upgrades on this same + * server (`api/events-ws.ts`), never a second one. Build a run's own events URL by appending + * `/actor-runtime/events/:runId`, exactly like `services/runs.ts: buildEnv` does against the real + * `CONTAINER_EVENTS_WS_BASE_URL`. */ + wsBaseUrl: string; token: string; dataDir: string; driver: Driver; @@ -239,6 +338,10 @@ export async function startTestServer( }); const { port } = server.address() as AddressInfo; const baseUrl = `http://127.0.0.1:${port}`; + const wsBaseUrl = `ws://127.0.0.1:${port}`; + // Same server, same upgrade path as production (`index.ts`) - a real `ws` client against this handle + // exercises the actual `api/events-ws.ts` code, not a stand-in. + const eventsWebSocketServer = attachEventsWebSocket(server); // maxRetries: 0 - real apify-client retries 5xx (so a deliberate 501 from the request-deletion // endpoints would otherwise burn ~8 exponential-backoff retries per test); production behaviour is @@ -248,13 +351,22 @@ export async function startTestServer( return { client, baseUrl, + wsBaseUrl, token, dataDir, driver, async close() { - await new Promise((resolve) => server.close(() => resolve())); + // MUST run before `server.close()` below, not after - see `EventsWebSocketServer.close()`'s + // own doc comment (`api/events-ws.ts`) for why `closeAllConnections()` cannot do this itself; + // same ordering requirement `shutdown.ts`'s `gracefulShutdown` follows in production. + eventsWebSocketServer.close(); + await new Promise((resolve) => { + server.close(() => resolve()); + server.closeAllConnections(); + }); stopLogFlusher(); resetLogsForTests(); + resetEventsChannelForTests(); await shutdownStorage(); resetStorageForTests(); resetRegistriesForTests(); diff --git a/test/integration/multi-user-isolation.test.ts b/test/integration/multi-user-isolation.test.ts index bc63aff..027d4d1 100644 --- a/test/integration/multi-user-isolation.test.ts +++ b/test/integration/multi-user-isolation.test.ts @@ -1,8 +1,9 @@ /** - * Criterion-12, made real: with per-token multi-user (`services/users.ts: getOrCreateUserForToken`) - * every resource is genuinely owned by the requesting token's user, and every list/get is genuinely - * filtered by that ownership - not just structurally (the filter always existed) but *actually*, since - * two different tokens now resolve to two different users instead of the same single bootstrap one. + * With per-token multi-user (`services/users.ts: getOrCreateUserForToken`, `cli.md`'s "User + * bootstrap"), every resource is genuinely owned by the requesting token's user, and every list/get is + * genuinely filtered by that ownership - not just structurally (the filter always existed) but + * *actually*, since two different tokens now resolve to two different users instead of the same single + * bootstrap one. */ import { afterEach, beforeEach, describe, expect, it } from 'vitest'; import { ApifyClient } from 'apify-client'; diff --git a/test/integration/run-env-vars.test.ts b/test/integration/run-env-vars.test.ts index 256833e..a3082cc 100644 --- a/test/integration/run-env-vars.test.ts +++ b/test/integration/run-env-vars.test.ts @@ -1,6 +1,7 @@ import { afterEach, beforeEach, describe, expect, it } from 'vitest'; import { startTestServer, type TestServerHandle } from './helpers/test-server.js'; +import { CONTAINER_EVENTS_WS_BASE_URL } from '../../src/config.js'; import type { Driver } from '../../src/driver/types.js'; /** @@ -128,7 +129,7 @@ describe('actor version envVars are applied to the run container env', () => { // Before this test, only the "absent" arm of `buildEnv`'s `if (options.proxyPassword)` was // ever exercised (grepping the suite for `PROXY_PASSWORD` found zero hits) - this is the - // "present" arm, success criterion 15's explicit contract. + // "present" arm, covering `requirements/actor-driver.md`'s `APIFY_PROXY_PASSWORD` contract. expect(getCapturedEnv()?.APIFY_PROXY_PASSWORD).toBe('super-secret-proxy-password'); } finally { if (previous === undefined) delete process.env.APIFY_PROXY_PASSWORD; @@ -165,4 +166,81 @@ describe('actor version envVars are applied to the run container env', () => { else process.env.APIFY_PROXY_PASSWORD = previous; } }); + + // The five new resource/telemetry env vars (`requirements/actor-driver.md`'s "Environment variables + // in every Actor container" list): byte-identical pairs, the run id in the URL path with no query + // string, present unconditionally (no dev mount involved anywhere in this describe block). + it('sets the five resource/telemetry env vars, byte-identical pairs, run id in the URL path, no query string, present without a dev mount', async () => { + const actor = await server.client.actors().create({ name: 'events-and-resources-env-actor' }); + await server.client + .actor(actor.id) + .versions() + .create({ + versionNumber: '0.0', + buildTag: 'latest', + sourceType: 'SOURCE_FILES' as never, + sourceFiles: [], + } as never); + + const build = await server.client.actor(actor.id).build('0.0', { waitForFinish: 5 }); + expect(build.status).toBe('SUCCEEDED'); + + const run = await server.client.actor(actor.id).start({}, { memory: 2048, waitForFinish: 5 }); + expect(run.status).toBe('SUCCEEDED'); + + const env = getCapturedEnv(); + expect(env).toBeDefined(); + + const expectedEventsUrl = `${CONTAINER_EVENTS_WS_BASE_URL}/actor-runtime/events/${run.id}`; + expect(env?.ACTOR_EVENTS_WEBSOCKET_URL).toBe(expectedEventsUrl); + expect(env?.APIFY_ACTOR_EVENTS_WS_URL).toBe(expectedEventsUrl); + // Byte-identical to each other - the two SDKs resolve `ACTOR_*`-vs-`APIFY_*` in opposite + // precedence order, so letting them ever diverge would size a run differently per SDK. + expect(env?.ACTOR_EVENTS_WEBSOCKET_URL).toBe(env?.APIFY_ACTOR_EVENTS_WS_URL); + + // No token, no query string at all - this endpoint has no authentication (`api/events-ws.ts`). + const parsedUrl = new URL(env!.ACTOR_EVENTS_WEBSOCKET_URL!.replace(/^ws:/, 'http:')); + expect(parsedUrl.search).toBe(''); + expect(parsedUrl.pathname).toBe(`/actor-runtime/events/${run.id}`); + + expect(env?.ACTOR_MEMORY_MBYTES).toBe('2048'); + expect(env?.APIFY_MEMORY_MBYTES).toBe('2048'); + expect(env?.ACTOR_MEMORY_MBYTES).toBe(env?.APIFY_MEMORY_MBYTES); + + // 2048 / 4096 = 0.5 core - the same ratio the CPU limit itself uses (`resources.ts`). + expect(env?.APIFY_DEDICATED_CPUS).toBe('0.5'); + // No `ACTOR_`-prefixed counterpart at all - apify-sdk-js's own `ENV_MAP` has no dedicated-CPU key. + expect(Object.hasOwn(env!, 'ACTOR_DEDICATED_CPUS')).toBe(false); + }); + + it('the five vars are present for a run configured with only default options (no explicit memory/timeout, no dev mount)', async () => { + const actor = await server.client.actors().create({ name: 'default-options-env-actor' }); + await server.client + .actor(actor.id) + .versions() + .create({ + versionNumber: '0.0', + buildTag: 'latest', + sourceType: 'SOURCE_FILES' as never, + sourceFiles: [], + } as never); + + const build = await server.client.actor(actor.id).build('0.0', { waitForFinish: 5 }); + expect(build.status).toBe('SUCCEEDED'); + + const run = await server.client.actor(actor.id).start({}, { waitForFinish: 5 }); + expect(run.status).toBe('SUCCEEDED'); + + const env = getCapturedEnv(); + for (const key of [ + 'ACTOR_EVENTS_WEBSOCKET_URL', + 'APIFY_ACTOR_EVENTS_WS_URL', + 'ACTOR_MEMORY_MBYTES', + 'APIFY_MEMORY_MBYTES', + 'APIFY_DEDICATED_CPUS', + ]) { + expect(Object.hasOwn(env!, key)).toBe(true); + } + expect(env?.ACTOR_EVENTS_WEBSOCKET_URL).toContain(`/actor-runtime/events/${run.id}`); + }); }); diff --git a/test/integration/shutdown.test.ts b/test/integration/shutdown.test.ts index 75665d5..330037c 100644 --- a/test/integration/shutdown.test.ts +++ b/test/integration/shutdown.test.ts @@ -4,13 +4,16 @@ import { join } from 'node:path'; import type { AddressInfo } from 'node:net'; import type { Server } from 'node:http'; import { afterEach, describe, expect, it, vi } from 'vitest'; +import WebSocket from 'ws'; import { bootstrapStorage, getRuntimeStorage, resetStorageForTests } from '../../src/storage/bootstrap.js'; import { openRegistries, resetRegistriesForTests } from '../../src/storage/registries.js'; import { getOrCreateUserForToken, resetUsersForTests } from '../../src/services/users.js'; import { createApiServer } from '../../src/api/server.js'; +import { attachEventsWebSocket, type EventsWebSocketServer } from '../../src/api/events-ws.js'; import { createConsoleServer } from '../../src/console/server.js'; import { resetLogsForTests, stopLogFlusher } from '../../src/services/logs.js'; +import { resetEventsChannelForTests } from '../../src/services/events-channel.js'; import { gracefulShutdown } from '../../src/shutdown.js'; import { unavailableDriver } from './helpers/test-server.js'; @@ -18,15 +21,21 @@ import { unavailableDriver } from './helpers/test-server.js'; * Regression coverage for the graceful-shutdown deadlock: before the fix, closing the API server would * never resolve while a `?stream=true` log response stayed open (`apify push`/`apify call`'s common * case), so `shutdownStorage()` - and its `teardown()` flush of every open request queue - never ran. + * The second `it` below covers the exact same bug class recurring for the events websocket + * (`api/events-ws.ts`) - see its own doc comment for the full evidence that `closeAllConnections()` does + * not reach an already-upgraded socket the way it reaches an ordinary open HTTP response. */ describe('gracefulShutdown', () => { let dataDir: string | undefined; let apiServer: Server | undefined; let consoleServer: Server | undefined; + let eventsWebSocketServer: EventsWebSocketServer | undefined; afterEach(async () => { + eventsWebSocketServer?.close(); stopLogFlusher(); resetLogsForTests(); + resetEventsChannelForTests(); resetRegistriesForTests(); resetUsersForTests(); resetStorageForTests(); @@ -34,6 +43,7 @@ describe('gracefulShutdown', () => { dataDir = undefined; apiServer = undefined; consoleServer = undefined; + eventsWebSocketServer = undefined; }); it('resolves promptly and tears down storage even while a ?stream=true log response is held open', async () => { @@ -98,4 +108,63 @@ describe('gracefulShutdown', () => { controller.abort(); await reader.cancel().catch(() => undefined); }); + + it('resolves promptly even while a live events-websocket client is connected to a RUNNING run - graceful shutdown must not hang on an upgraded socket', async () => { + dataDir = await mkdtemp(join(tmpdir(), 'actor-runtime-shutdown-ws-')); + bootstrapStorage(dataDir); + await openRegistries(); + + const apiApp = createApiServer({ driver: unavailableDriver() }); + const consoleApp = createConsoleServer({ driver: unavailableDriver() }); + apiServer = await new Promise((resolve) => { + const s = apiApp.listen(0, () => resolve(s)); + }); + consoleServer = await new Promise((resolve) => { + const s = consoleApp.listen(0, () => resolve(s)); + }); + // Attached the same way `index.ts` attaches it in production - on the same `http.Server` + // `apiApp.listen()` returned, never a second port. + eventsWebSocketServer = attachEventsWebSocket(apiServer); + const { port } = apiServer.address() as AddressInfo; + + // Seed a non-terminal run directly, so the events socket's upgrade resolves to a live subscription + // (not an immediate 1008) and stays open exactly as an Actor container's own SDK connection would + // for the whole life of a real run. + const { getRegistries } = await import('../../src/storage/registries.js'); + const runId = 'shutdownEventsWsRun12'; + await getRegistries().runs.set(runId, { + id: runId, + userId: 'irrelevant-for-this-endpoint', + actorId: 'x', + buildId: 'y', + buildNumber: '0.0.1', + status: 'RUNNING', + startedAt: new Date().toISOString(), + defaultDatasetId: 'd', + defaultKeyValueStoreId: 'k', + defaultRequestQueueId: 'r', + options: { memoryMbytes: 1024, timeoutSecs: 300 }, + meta: { origin: 'API' }, + }); + + const ws = new WebSocket(`ws://127.0.0.1:${port}/actor-runtime/events/${runId}`); + await new Promise((resolve, reject) => { + ws.once('open', () => resolve()); + ws.once('error', reject); + }); + // Deliberately never closed by this test before `gracefulShutdown` runs - simulating the ordinary + // case, not an edge case: `ACTOR_EVENTS_WEBSOCKET_URL` is now set on every run and neither SDK ever + // disconnects on its own mid-run, so a live run with a still-connected SDK socket at the moment + // `SIGTERM`/`SIGINT` arrives is the common shutdown scenario, not a rare one. + + const timedOut = Symbol('timeout'); + const result = await Promise.race([ + gracefulShutdown({ apiServer, consoleServer, eventsWebSocketServer }).then(() => 'shut down' as const), + new Promise((resolve) => setTimeout(() => resolve(timedOut), 3000)), + ]); + + expect(result).toBe('shut down'); + + ws.terminate(); + }); }); diff --git a/test/unit/docker-driver.test.ts b/test/unit/docker-driver.test.ts index d6e5633..137e8e9 100644 --- a/test/unit/docker-driver.test.ts +++ b/test/unit/docker-driver.test.ts @@ -5,6 +5,7 @@ import type Docker from 'dockerode'; import * as tar from 'tar-stream'; import { DockerDriver } from '../../src/driver/docker-driver.js'; +import { stubDockerForRun } from './helpers/docker-stubs.js'; /** * A stub `dockerode`-shaped object covering only what `reconcileOrphans` calls - there is no Docker @@ -152,70 +153,6 @@ describe('DockerDriver.reconcileOrphans', () => { }); }); -/** - * A stub `dockerode`-shaped object covering only what `startRun` calls, with `container.wait()` and the - * `container.logs()` stream each independently controllable - mirrors the real Docker daemon's two - * genuinely separate API connections (the finding this fixes: nothing guarantees the log stream's final - * chunk has arrived by the time `container.wait()` resolves). - */ -function stubDockerForRun() { - let resolveWait!: (result: { StatusCode: number }) => void; - const waitPromise = new Promise<{ StatusCode: number }>((resolve) => { - resolveWait = resolve; - }); - - // The raw (not-yet-demuxed) combined stdout/stderr stream `container.logs()` would return - a - // separate Docker API connection from `container.wait()` above. - const rawLogStream = new PassThrough(); - - const container = { - start: vi.fn(async () => undefined), - logs: vi.fn(async () => rawLogStream), - wait: vi.fn(async () => waitPromise), - remove: vi.fn(async (_options?: Record) => undefined), - stop: vi.fn(async () => undefined), - }; - - // Real dockerode demuxing splits stdout/stderr apart by frame header; this stub doesn't need that - // distinction, it only needs to forward data. Crucially - faithful to the real - // `docker-modem` `Modem.prototype.demuxStream` (`node_modules/docker-modem/lib/modem.js`) - it must - // NOT end `stdout`/`stderr` when the source stream ends: the real implementation registers only - // `streama.on('data', processData)` and never calls `.end()`/`.destroy()` on either destination. - // `stdout`/`stderr` ending is entirely `DockerDriver.startRun`'s own responsibility (it derives that - // from the SOURCE stream, i.e. `stream` here, ending) - a demux stub that auto-ends the destinations - // (as this one previously did) hides exactly the bug that shipped in production. - const demuxStream = vi.fn((stream: NodeJS.ReadableStream, stdout: PassThrough) => { - stream.on('data', (chunk: Buffer) => stdout.write(chunk)); - }); - - // Typed with the real `dockerode` parameter shape so `mock.calls[0]` is genuinely a - // `[Docker.ContainerCreateOptions]` tuple below - no unsound cast needed to read it back. - const createContainer = vi.fn(async (_options: Docker.ContainerCreateOptions) => container); - const docker = { - createContainer, - modem: { demuxStream }, - } as unknown as Docker; - - return { - docker, - container, - createContainer, - /** Simulates `container.wait()` resolving - the container process has exited. */ - triggerContainerExit(statusCode = 0): void { - resolveWait({ StatusCode: statusCode }); - }, - /** Simulates a trailing chunk still arriving over the separate Docker logs connection. */ - pushFinalLogChunk(chunk: string): void { - rawLogStream.write(chunk); - }, - /** Simulates the logs connection closing - the real daemon does this once the container's full - * output has been delivered. */ - endLogStream(): void { - rawLogStream.end(); - }, - }; -} - describe('DockerDriver.startRun - log stream drain ordering (regression: trailing log chunk race)', () => { it("does not resolve until the container's log stream has fully drained, even after container.wait() has already resolved", async () => { const stub = stubDockerForRun(); @@ -880,3 +817,228 @@ describe('DockerDriver.probeDevFolder (actor-driver.md: "A host-side existence-a expect(outcome).toEqual({ ok: false, reason: 'unknown' }); }); }); + +describe('DockerDriver.startRun - CFS CPU limit (actor-driver.md: CpuPeriod/CpuQuota, never NanoCpus)', () => { + it('encodes the CPU limit as HostConfig.CpuPeriod/CpuQuota derived from memoryMbytes/4096, never sets NanoCpus, and leaves Memory unchanged', async () => { + const stub = stubDockerForRun(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const outcomePromise = driver.startRun( + { runId: 'run-cpu-1', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + ); + await new Promise((resolve) => setImmediate(resolve)); + + const [options] = stub.createContainer.mock.calls[0]!; + // 1024 / 4096 = 0.25 core = 25000us of every 100000us period - the ratio worked example in + // `requirements/actor-driver.md`'s "Resource limits" section. + expect(options.HostConfig?.CpuPeriod).toBe(100_000); + expect(options.HostConfig?.CpuQuota).toBe(25_000); + expect(options.HostConfig?.Memory).toBe(1024 * 1024 * 1024); + expect(options.HostConfig?.NanoCpus).toBeUndefined(); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it("raises the computed quota to Docker's own protocol minimum of 1000us when the raw memoryMbytes/4096 ratio computes lower - a protocol floor, never a host-capacity clamp", async () => { + const stub = stubDockerForRun(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const outcomePromise = driver.startRun( + { runId: 'run-cpu-2', imageId: 'fake-image', env: {}, memoryMbytes: 32, timeoutSecs: 60 }, + () => {}, + ); + await new Promise((resolve) => setImmediate(resolve)); + + const [options] = stub.createContainer.mock.calls[0]!; + // Raw: 32 / 4096 * 100000 = 781.25us, below the 1000us floor. + expect(options.HostConfig?.CpuQuota).toBe(1000); + expect(options.HostConfig?.CpuPeriod).toBe(100_000); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); +}); + +/** + * A stub `dockerode`-shaped object supporting both `init()` (`ping`/`listNetworks`/`createNetwork`/ + * `info`) and `startRun()` (reusing `stubDockerForRun`'s own container/createContainer stub) - for + * exercising the host-capacity warning end to end: `docker.info()`'s snapshot at `init()` time feeding + * `startRun()`'s over-capacity check. `info` is caller-supplied so each test controls exactly what + * `docker.info()` resolves (or rejects) with. + */ +function stubDockerForCapacity(info: () => Promise) { + const run = stubDockerForRun(); + const docker = { + ...run.docker, + ping: vi.fn(async () => undefined), + listNetworks: vi.fn(async () => []), + createNetwork: vi.fn(async () => undefined), + info: vi.fn(info), + } as unknown as Docker; + return { ...run, docker }; +} + +describe('DockerDriver host-capacity warning (actor-driver.md: warn, never clamp)', () => { + it('warns through onLog naming both the requested and host figures for both over-capacity resources, and still applies the requested limits verbatim (never clamped)', async () => { + const stub = stubDockerForCapacity(async () => ({ NCPU: 4, MemTotal: 8_589_934_592 })); + const driver = new DockerDriver(stub.docker); + await driver.init(); + expect(driver.available).toBe(true); + + const chunks: string[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-capacity-1', imageId: 'fake-image', env: {}, memoryMbytes: 65_536, timeoutSecs: 60 }, + (chunk) => chunks.push(chunk), + ); + await new Promise((resolve) => setImmediate(resolve)); + + const warning = chunks.join(''); + expect(warning).toContain('65536 MB'); + expect(warning).toContain('8192 MB'); + expect(warning).toContain('16.00 CPU'); + expect(warning).toContain('host has 4'); + expect(warning).toMatch(/applying the requested limits anyway/); + + // Warned about, never clamped: the created container still carries the full requested limits. + const [options] = stub.createContainer.mock.calls[0]!; + expect(options.HostConfig?.Memory).toBe(65_536 * 1024 * 1024); + expect(options.HostConfig?.CpuQuota).toBe(1_600_000); + expect(options.HostConfig?.CpuPeriod).toBe(100_000); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('warns naming only the over-capacity resource when memory is over capacity but CPU is not', async () => { + // NCPU: 16, MemTotal: 8192 MB - a host with plenty of CPU relative to its RAM at the platform's own + // ratio. memoryMbytes: 16_384 -> 4 dedicated cores, which fits comfortably under 16; the memory + // figure alone (16384 > 8192) is over capacity. + const stub = stubDockerForCapacity(async () => ({ NCPU: 16, MemTotal: 8_589_934_592 })); + const driver = new DockerDriver(stub.docker); + await driver.init(); + + const chunks: string[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-capacity-mem-only', imageId: 'fake-image', env: {}, memoryMbytes: 16_384, timeoutSecs: 60 }, + (chunk) => chunks.push(chunk), + ); + await new Promise((resolve) => setImmediate(resolve)); + + const warning = chunks.join(''); + expect(warning).toContain('16384 MB'); + expect(warning).toContain('host has 8192 MB'); + expect(warning).toMatch(/applying the requested limits anyway/); + // The CPU figure must not appear at all - only the over-capacity resource is named. + expect(warning).not.toContain('CPU cores'); + expect(warning).not.toContain('host has 16'); + + // Still applied verbatim, unclamped. + const [options] = stub.createContainer.mock.calls[0]!; + expect(options.HostConfig?.Memory).toBe(16_384 * 1024 * 1024); + expect(options.HostConfig?.CpuQuota).toBe(400_000); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('warns naming only the over-capacity resource when CPU is over capacity but memory is not', async () => { + // NCPU: 1, MemTotal: 1 TiB - a host with plenty of RAM but only a single core. memoryMbytes: 8192 -> + // 2 dedicated cores, over the host's single core; the memory figure (8192 MB against ~1,048,576 MB + // of host RAM) is comfortably under capacity. + const stub = stubDockerForCapacity(async () => ({ NCPU: 1, MemTotal: 1_099_511_627_776 })); + const driver = new DockerDriver(stub.docker); + await driver.init(); + + const chunks: string[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-capacity-cpu-only', imageId: 'fake-image', env: {}, memoryMbytes: 8192, timeoutSecs: 60 }, + (chunk) => chunks.push(chunk), + ); + await new Promise((resolve) => setImmediate(resolve)); + + const warning = chunks.join(''); + expect(warning).toContain('2.00 CPU cores'); + expect(warning).toContain('host has 1'); + expect(warning).toMatch(/applying the requested limits anyway/); + // The memory figure must not appear at all - only the over-capacity resource is named. + expect(warning).not.toContain('MB (host has'); + + // Still applied verbatim, unclamped. + const [options] = stub.createContainer.mock.calls[0]!; + expect(options.HostConfig?.Memory).toBe(8192 * 1024 * 1024); + expect(options.HostConfig?.CpuQuota).toBe(200_000); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('produces no warning at all for an in-capacity request', async () => { + const stub = stubDockerForCapacity(async () => ({ NCPU: 4, MemTotal: 8_589_934_592 })); + const driver = new DockerDriver(stub.docker); + await driver.init(); + + const chunks: string[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-capacity-2', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + (chunk) => chunks.push(chunk), + ); + await new Promise((resolve) => setImmediate(resolve)); + + expect(chunks.join('')).toBe(''); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('produces no warning when docker.info() rejects outright - capacity unknown, never a crash, never treated as capacity zero', async () => { + const stub = stubDockerForCapacity(async () => { + throw new Error('info unavailable'); + }); + const driver = new DockerDriver(stub.docker); + await driver.init(); + // A docker.info() failure must never make the whole daemon look unavailable. + expect(driver.available).toBe(true); + + const chunks: string[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-capacity-3', imageId: 'fake-image', env: {}, memoryMbytes: 65_536, timeoutSecs: 60 }, + (chunk) => chunks.push(chunk), + ); + await new Promise((resolve) => setImmediate(resolve)); + + expect(chunks.join('')).toBe(''); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('produces no warning when docker.info() resolves but omits NCPU/MemTotal - capacity unknown, not capacity zero', async () => { + const stub = stubDockerForCapacity(async () => ({})); + const driver = new DockerDriver(stub.docker); + await driver.init(); + + const chunks: string[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-capacity-4', imageId: 'fake-image', env: {}, memoryMbytes: 65_536, timeoutSecs: 60 }, + (chunk) => chunks.push(chunk), + ); + await new Promise((resolve) => setImmediate(resolve)); + + expect(chunks.join('')).toBe(''); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); +}); diff --git a/test/unit/events-channel.test.ts b/test/unit/events-channel.test.ts new file mode 100644 index 0000000..8150638 --- /dev/null +++ b/test/unit/events-channel.test.ts @@ -0,0 +1,221 @@ +/** + * `services/events-channel.ts`'s envelope shaping for `systemInfo`/`aborting` - the sample-in, + * platform-JSON-frame-out mapping documented in `requirements/actor-driver.md`'s "Run resource + * telemetry" section: percent-of-one-core (never percent-of-grant), `memMaxBytes` as the configured + * LIMIT (never a genuine peak), the ratio-only, strict-`>`-0.95 `isCpuOverloaded` test, running avg/max, + * and the all-eight-fields contract apify-sdk-python's pydantic model requires on every frame. + */ +import { beforeEach, describe, expect, it } from 'vitest'; + +import { + getSubscriberCount, + isEventsTerminal, + markEventsTerminal, + publishAborting, + publishSystemInfo, + resetEventsChannelForTests, + subscribeEvents, +} from '../../src/services/events-channel.js'; +import type { RunResourceSample } from '../../src/driver/types.js'; + +function sample(overrides: Partial = {}): RunResourceSample { + return { + cpuPercentOfOneCore: 20, + memoryBytes: 402_653_184, + memoryLimitBytes: 1024 * 1024 * 1024, + at: new Date('2026-08-25T09:12:03.481Z'), + ...overrides, + }; +} + +/** Subscribes to `runId` and returns every frame published to it so far, parsed. */ +function captureFrames(runId: string): { frames: Array<{ name: string; data: unknown }>; unsubscribe: () => void } { + const frames: Array<{ name: string; data: unknown }> = []; + const unsubscribe = subscribeEvents(runId, (frame) => frames.push(JSON.parse(frame))); + return { frames, unsubscribe }; +} + +describe('events-channel: publishSystemInfo', () => { + beforeEach(() => { + resetEventsChannelForTests(); + }); + + it('emits a single "systemInfo" frame with all eight fields present, matching the payload shape in requirements/actor-driver.md verbatim', () => { + const runId = 'run-1'; + const { frames } = captureFrames(runId); + + publishSystemInfo(runId, sample({ cpuPercentOfOneCore: 20, memoryBytes: 402_653_184 }), { memoryMbytes: 1024 }); + + expect(frames).toHaveLength(1); + expect(frames[0]).toEqual({ + name: 'systemInfo', + data: { + memAvgBytes: 402_653_184, + memCurrentBytes: 402_653_184, + memMaxBytes: 1024 * 1024 * 1024, + cpuAvgUsage: 20, + cpuMaxUsage: 20, + cpuCurrentUsage: 20, + isCpuOverloaded: false, + createdAt: '2026-08-25T09:12:03.481Z', + }, + }); + }); + + it('cpuCurrentUsage is percent of ONE core, verbatim from the sample - never percent of the grant', () => { + const runId = 'run-2'; + const { frames } = captureFrames(runId); + + // A run granted 0.25 core, observed at 20% of one core (0.8 of its own grant) - the figures + // requirements/actor-driver.md uses to distinguish the two conventions (percent-of-one-core vs + // percent-of-grant). + publishSystemInfo(runId, sample({ cpuPercentOfOneCore: 20 }), { memoryMbytes: 1024 }); + + const data = frames[0]!.data as Record; + expect(data.cpuCurrentUsage).toBe(20); + expect(data.cpuCurrentUsage).not.toBe(80); + }); + + it('memMaxBytes is the configured memory LIMIT and stays constant across samples with different observed usage - never a growing peak', () => { + const runId = 'run-3'; + const { frames } = captureFrames(runId); + const grant = { memoryMbytes: 1024 }; + + publishSystemInfo(runId, sample({ memoryBytes: 50_000_000 }), grant); + publishSystemInfo(runId, sample({ memoryBytes: 900_000_000 }), grant); + + const limits = frames.map((f) => (f.data as Record).memMaxBytes); + expect(limits).toEqual([1024 * 1024 * 1024, 1024 * 1024 * 1024]); + }); + + it.each([ + { label: 'clearly below 0.95', cpuPercentOfOneCore: 20, expected: false }, // usedCores 0.2 / 0.25 = 0.8 + { label: 'exactly 0.95 (strict >, not >=)', cpuPercentOfOneCore: 23.75, expected: false }, // 0.2375/0.25 = 0.95 + { label: 'clearly above 0.95', cpuPercentOfOneCore: 24.9, expected: true }, // 0.249/0.25 = 0.996 + ])('isCpuOverloaded: $label -> $expected', ({ cpuPercentOfOneCore, expected }) => { + const runId = 'run-overload'; + const { frames } = captureFrames(runId); + + publishSystemInfo(runId, sample({ cpuPercentOfOneCore }), { memoryMbytes: 1024 }); + + expect((frames[0]!.data as Record).isCpuOverloaded).toBe(expected); + }); + + it('isCpuOverloaded is false when grantedCores is 0 (memoryMbytes: 0), never a division producing Infinity/NaN', () => { + const runId = 'run-zero-grant'; + const { frames } = captureFrames(runId); + + // grantedCores = dedicatedCpusFor(0) = 0 - the `grantedCores > 0 &&` guard must short-circuit before + // any `usedCores / grantedCores` division ever happens. + publishSystemInfo(runId, sample({ cpuPercentOfOneCore: 20 }), { memoryMbytes: 0 }); + + expect((frames[0]!.data as Record).isCpuOverloaded).toBe(false); + }); + + it('memAvgBytes/cpuAvgUsage/cpuMaxUsage are running figures across every sample published so far for that run, cpuCurrentUsage/memCurrentBytes are just the latest', () => { + const runId = 'run-avg'; + const { frames } = captureFrames(runId); + const grant = { memoryMbytes: 1024 }; + + publishSystemInfo(runId, sample({ cpuPercentOfOneCore: 10, memoryBytes: 100 }), grant); + publishSystemInfo(runId, sample({ cpuPercentOfOneCore: 30, memoryBytes: 300 }), grant); + publishSystemInfo(runId, sample({ cpuPercentOfOneCore: 20, memoryBytes: 200 }), grant); + + const last = frames[2]!.data as Record; + expect(last.cpuCurrentUsage).toBe(20); + expect(last.memCurrentBytes).toBe(200); + expect(last.cpuAvgUsage).toBeCloseTo((10 + 30 + 20) / 3); + expect(last.memAvgBytes).toBeCloseTo((100 + 300 + 200) / 3); + expect(last.cpuMaxUsage).toBe(30); + }); + + it('two different runs accumulate their own independent avg/max state - one run publishing never affects the other', () => { + const { frames: framesA } = captureFrames('run-a'); + const { frames: framesB } = captureFrames('run-b'); + + publishSystemInfo('run-a', sample({ cpuPercentOfOneCore: 90 }), { memoryMbytes: 1024 }); + publishSystemInfo('run-b', sample({ cpuPercentOfOneCore: 5 }), { memoryMbytes: 1024 }); + publishSystemInfo('run-a', sample({ cpuPercentOfOneCore: 10 }), { memoryMbytes: 1024 }); + + expect((framesA[1]!.data as Record).cpuMaxUsage).toBe(90); + expect(framesB).toHaveLength(1); + expect((framesB[0]!.data as Record).cpuMaxUsage).toBe(5); + }); + + it('is a no-op (no throw) when nobody is subscribed to the run yet', () => { + expect(() => publishSystemInfo('run-nobody-listening', sample(), { memoryMbytes: 1024 })).not.toThrow(); + }); +}); + +describe('events-channel: publishAborting', () => { + beforeEach(() => { + resetEventsChannelForTests(); + }); + + it('emits exactly {"name":"aborting","data":{}} - a literal empty object, no keys', () => { + const runId = 'run-abort-1'; + const { frames } = captureFrames(runId); + + publishAborting(runId); + + expect(frames).toEqual([{ name: 'aborting', data: {} }]); + }); + + it('is a no-op (no throw) when nobody is subscribed', () => { + expect(() => publishAborting('run-abort-nobody-listening')).not.toThrow(); + }); + + it('interleaves with systemInfo frames on the same subscriber, in publish order', () => { + const runId = 'run-abort-interleave'; + const { frames } = captureFrames(runId); + const grant = { memoryMbytes: 1024 }; + + publishSystemInfo(runId, sample(), grant); + publishAborting(runId); + publishSystemInfo(runId, sample(), grant); + + expect(frames.map((f) => f.name)).toEqual(['systemInfo', 'aborting', 'systemInfo']); + }); +}); + +describe('events-channel: subscribeEvents/markEventsTerminal/getSubscriberCount', () => { + beforeEach(() => { + resetEventsChannelForTests(); + }); + + it('subscribeEvents returns an unsubscribe function that stops further frames from reaching that callback', () => { + const runId = 'run-unsub'; + const received: string[] = []; + const unsubscribe = subscribeEvents(runId, (frame) => received.push(frame)); + + publishAborting(runId); + unsubscribe(); + publishAborting(runId); + + expect(received).toHaveLength(1); + }); + + it('getSubscriberCount reflects additions and removals, per run, independent of other runs', () => { + expect(getSubscriberCount('run-count-1')).toBe(0); + const unsubscribeA1 = subscribeEvents('run-count-1', () => {}); + const unsubscribeA2 = subscribeEvents('run-count-1', () => {}); + subscribeEvents('run-count-2', () => {}); + + expect(getSubscriberCount('run-count-1')).toBe(2); + expect(getSubscriberCount('run-count-2')).toBe(1); + + unsubscribeA1(); + expect(getSubscriberCount('run-count-1')).toBe(1); + unsubscribeA2(); + expect(getSubscriberCount('run-count-1')).toBe(0); + }); + + it('isEventsTerminal is false until markEventsTerminal is called for that run, and never affects an unrelated run', () => { + expect(isEventsTerminal('run-terminal-1')).toBe(false); + + markEventsTerminal('run-terminal-1'); + + expect(isEventsTerminal('run-terminal-1')).toBe(true); + expect(isEventsTerminal('run-terminal-2')).toBe(false); + }); +}); diff --git a/test/unit/helpers/docker-stubs.ts b/test/unit/helpers/docker-stubs.ts new file mode 100644 index 0000000..4e41ae4 --- /dev/null +++ b/test/unit/helpers/docker-stubs.ts @@ -0,0 +1,76 @@ +import { PassThrough } from 'node:stream'; + +import { vi } from 'vitest'; +import type Docker from 'dockerode'; + +/** + * A stub `dockerode`-shaped object covering only what `startRun` calls, with `container.wait()` and the + * `container.logs()` stream each independently controllable - mirrors the real Docker daemon's two + * genuinely separate API connections (the finding this fixes: nothing guarantees the log stream's final + * chunk has arrived by the time `container.wait()` resolves). + * + * Lives in this non-`.test.ts` helper file - not in `docker-driver.test.ts` itself - specifically so + * `resource-sampler.test.ts` can import it too: a `.test.ts` file's top-level code (its own `describe`/ + * `it` registrations included) re-runs as a side effect of another test file importing anything from it, + * which would silently double-execute every one of `docker-driver.test.ts`'s own tests. Extended (not + * reimplemented) by `resource-sampler.test.ts` via `Object.assign`-ing a `container.stats()` mock onto the + * returned `container` - the same extend-in-place pattern `docker-driver.test.ts`'s own + * `stubDockerForCapacity` uses for `init()`'s extra surface. + */ +export function stubDockerForRun() { + let resolveWait!: (result: { StatusCode: number }) => void; + const waitPromise = new Promise<{ StatusCode: number }>((resolve) => { + resolveWait = resolve; + }); + + // The raw (not-yet-demuxed) combined stdout/stderr stream `container.logs()` would return - a + // separate Docker API connection from `container.wait()` above. + const rawLogStream = new PassThrough(); + + const container = { + start: vi.fn(async () => undefined), + logs: vi.fn(async () => rawLogStream), + wait: vi.fn(async () => waitPromise), + remove: vi.fn(async (_options?: Record) => undefined), + stop: vi.fn(async () => undefined), + }; + + // Real dockerode demuxing splits stdout/stderr apart by frame header; this stub doesn't need that + // distinction, it only needs to forward data. Crucially - faithful to the real + // `docker-modem` `Modem.prototype.demuxStream` (`node_modules/docker-modem/lib/modem.js`) - it must + // NOT end `stdout`/`stderr` when the source stream ends: the real implementation registers only + // `streama.on('data', processData)` and never calls `.end()`/`.destroy()` on either destination. + // `stdout`/`stderr` ending is entirely `DockerDriver.startRun`'s own responsibility (it derives that + // from the SOURCE stream, i.e. `stream` here, ending) - a demux stub that auto-ends the destinations + // (as this one previously did) hides exactly the bug that shipped in production. + const demuxStream = vi.fn((stream: NodeJS.ReadableStream, stdout: PassThrough) => { + stream.on('data', (chunk: Buffer) => stdout.write(chunk)); + }); + + // Typed with the real `dockerode` parameter shape so `mock.calls[0]` is genuinely a + // `[Docker.ContainerCreateOptions]` tuple below - no unsound cast needed to read it back. + const createContainer = vi.fn(async (_options: Docker.ContainerCreateOptions) => container); + const docker = { + createContainer, + modem: { demuxStream }, + } as unknown as Docker; + + return { + docker, + container, + createContainer, + /** Simulates `container.wait()` resolving - the container process has exited. */ + triggerContainerExit(statusCode = 0): void { + resolveWait({ StatusCode: statusCode }); + }, + /** Simulates a trailing chunk still arriving over the separate Docker logs connection. */ + pushFinalLogChunk(chunk: string): void { + rawLogStream.write(chunk); + }, + /** Simulates the logs connection closing - the real daemon does this once the container's full + * output has been delivered. */ + endLogStream(): void { + rawLogStream.end(); + }, + }; +} diff --git a/test/unit/job-status.test.ts b/test/unit/job-status.test.ts index e1220a8..840ec47 100644 --- a/test/unit/job-status.test.ts +++ b/test/unit/job-status.test.ts @@ -1,6 +1,7 @@ import { describe, expect, it } from 'vitest'; import { isTerminalJobStatus, transitionJobStatus, type StatusRegistry } from '../../src/services/job-status.js'; +import { KeyedMutex } from '../../src/storage/mutex.js'; import type { JobStatus } from '../../src/storage/entities.js'; interface FakeJob { @@ -130,4 +131,99 @@ describe('transitionJobStatus', () => { const result = await transitionJobStatus(registry, 'a', 'FAILED', { status: 'SUCCEEDED' } as never); expect(result?.status).toBe('FAILED'); }); + + it('invokes onBeforeTransition with the current record, before the accept/refuse decision is made, without affecting the result', async () => { + const registry = fakeRegistry({ a: { id: 'a', status: 'RUNNING' } }); + const seen: Array = []; + const result = await transitionJobStatus(registry, 'a', 'SUCCEEDED', {}, (current) => { + seen.push(current); + }); + expect(seen).toEqual([{ id: 'a', status: 'RUNNING' }]); + expect(result?.status).toBe('SUCCEEDED'); + }); + + it('invokes onBeforeTransition even when the transition itself is refused (record left unchanged), still with the current record', async () => { + const registry = fakeRegistry({ a: { id: 'a', status: 'ABORTING' } }); + const seen: Array = []; + const result = await transitionJobStatus(registry, 'a', 'FAILED', {}, (current) => { + seen.push(current); + }); + expect(seen).toEqual([{ id: 'a', status: 'ABORTING' }]); + expect(result?.status).toBe('ABORTING'); // unchanged - ABORTING -> FAILED is not allowed + }); + + it('invokes onBeforeTransition with null for a record that does not exist', async () => { + const registry = fakeRegistry({}); + const seen: Array = []; + await transitionJobStatus(registry, 'missing', 'RUNNING', {}, (current) => { + seen.push(current); + }); + expect(seen).toEqual([null]); + }); + + /** + * Regression for `abortRun`'s `wasRunning` TOCTOU (a race between a plain, mutex-bypassing registry + * read and a concurrent mutex-serialized write): built on top of the REAL `KeyedMutex` (already + * independently proven FIFO/no-overlap in `mutex.test.ts`), rather + * than `fakeRegistry` above (whose `update` is synchronous and so never actually races anything). This + * `StatusRegistry` deliberately holds its FIRST `update` call's read+write open behind a gate - mirroring + * `runInBackground`'s own real, slow `@crawlee/fs-storage` I/O not yet having settled - while a SECOND, + * concurrently-issued `transitionJobStatus` call (mirroring `abortRun`) is already queued behind it on + * the same mutex key. `onBeforeTransition` must observe whatever the first call ultimately wrote, never + * the value the record held before that write - which is exactly what a separate, unguarded + * `registry.get(id)` taken at the same wall-clock moment (the pre-fix shape of `abortRun`) would have + * returned instead: the stale, pre-transition status. + */ + it("onBeforeTransition observes the record's true current status under a real concurrent mutex-serialized write, never a stale pre-write snapshot (regression: a plain, mutex-bypassing read taken before the guarded write would return abortRun's wasRunning/alreadyAborting flags stale)", async () => { + const mutex = new KeyedMutex(); + const store = new Map([['a', { id: 'a', status: 'READY' }]]); + let callCount = 0; + let releaseFirstWrite!: () => void; + const firstWriteGate = new Promise((resolve) => { + releaseFirstWrite = resolve; + }); + + const registry: StatusRegistry = { + async get(id) { + return store.get(id) ?? null; + }, + async update(id, mutator) { + return mutex.run(id, async () => { + callCount += 1; + // Only the FIRST call (simulating `runInBackground`'s own READY -> RUNNING write) pauses + // here, before actually reading/writing - a second, concurrently-issued call (simulating + // `abortRun`) still has to wait its turn on this same mutex key regardless, so it can only + // ever observe what THIS call ends up writing, never anything from before it. + if (callCount === 1) await firstWriteGate; + const current = store.get(id) ?? null; + const next = mutator(current); + if (next === null) store.delete(id); + else store.set(id, next); + return next; + }); + }, + }; + + // Issued first, but deliberately held open by the gate above. + const runningPromise = transitionJobStatus(registry, 'a', 'RUNNING'); + + // Issued while the first transition is still in flight - the concurrent-abort-during-a-still-settling + // write interleaving this test exists to cover. + let observedBeforeAborting: JobStatus | null | undefined; + const abortingPromise = transitionJobStatus(registry, 'a', 'ABORTING', {}, (current) => { + observedBeforeAborting = current?.status ?? null; + }); + + // Only now does the first transition's own read+write actually happen. + releaseFirstWrite(); + + const running = await runningPromise; + const aborting = await abortingPromise; + + expect(running?.status).toBe('RUNNING'); + // The crux of the fix: RUNNING, never the pre-transition READY a separate, unguarded `get()` taken + // at the moment `abortRun` was called would have returned instead. + expect(observedBeforeAborting).toBe('RUNNING'); + expect(aborting?.status).toBe('ABORTING'); + }); }); diff --git a/test/unit/resource-sampler.test.ts b/test/unit/resource-sampler.test.ts new file mode 100644 index 0000000..4bad94c --- /dev/null +++ b/test/unit/resource-sampler.test.ts @@ -0,0 +1,816 @@ +/** + * `DockerDriver.startRun`'s per-run CPU/memory sampler (`docker-driver.ts`'s `startResourceSampler`, + * exercised only through `startRun`'s optional third `onSample` parameter - there is no separate exported + * surface for it). Covers the sampling-lifetime contract documented in `requirements/actor-driver.md`'s + * "Run resource telemetry" section: cadence, all-eight-fields shape, and the stop-before-remove ordering + * that keeps a stats call from ever racing container removal. + */ +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; + +import { DockerDriver } from '../../src/driver/docker-driver.js'; +import type { RunResourceSample } from '../../src/driver/types.js'; +import { publishSystemInfo, resetEventsChannelForTests, subscribeEvents } from '../../src/services/events-channel.js'; +import { stubDockerForRun } from './helpers/docker-stubs.js'; + +/** + * Extends `helpers/docker-stubs.ts`'s shared `stubDockerForRun` (also used directly by + * `docker-driver.test.ts`) with a `container.stats()` mock, controllable per-call either via a queue of + * canned `ContainerStats`-shaped results, or left pending indefinitely (until the test resolves it itself + * via `resolvePendingStats`) once the queue is exhausted - the shape a "stats() never resolves until the + * test says so" sampler-lifetime test needs, to prove `stop()` bounds its own wait for an in-flight call + * rather than either abandoning it instantly or hanging on it forever. Mutating the SAME `container` + * object `stubDockerForRun` already hands to `createContainer`'s resolved value - rather than + * reimplementing `start`/`logs`/`wait`/`remove`/`stop` a second time here - is the same extend-in-place + * pattern `docker-driver.test.ts`'s own `stubDockerForCapacity` already uses for `init()`'s extra surface. + * Imported from that neutral helper file, never from `docker-driver.test.ts` directly: a `.test.ts` file + * re-runs its own top-level `describe`/`it` registrations as a side effect of being imported by another + * test file, which would silently double-execute every one of `docker-driver.test.ts`'s own tests. + */ +function stubDockerForSampler() { + const run = stubDockerForRun(); + + const statsResponses: unknown[] = []; + let nextStatsIndex = 0; + const pendingStatsCalls: Array<(value: unknown) => void> = []; + + const stats = vi.fn(async () => { + if (nextStatsIndex < statsResponses.length) { + const response = statsResponses[nextStatsIndex++]; + if (response instanceof Error) throw response; + return response; + } + // The queue is exhausted - this call hangs until `resolvePendingStats` below is called for it. + return new Promise((resolve) => { + pendingStatsCalls.push(resolve); + }); + }); + Object.assign(run.container, { stats }); + + return { + ...run, + stats, + queueStatsResponse(response: unknown): void { + statsResponses.push(response); + }, + /** Resolves the OLDEST still-pending `stats()` call that had no canned response queued for it. */ + resolvePendingStats(response: unknown): void { + const resolve = pendingStatsCalls.shift(); + if (!resolve) throw new Error('no pending stats() call to resolve'); + resolve(response); + }, + }; +} + +/** A minimal, valid `dockerode` `ContainerStats`-shaped object with just the fields the sampler reads. */ +function containerStats(totalUsage: number, systemUsage: number, memoryUsage: number, onlineCpus = 1) { + return { + cpu_stats: { cpu_usage: { total_usage: totalUsage }, system_cpu_usage: systemUsage, online_cpus: onlineCpus }, + memory_stats: { usage: memoryUsage }, + }; +} + +/** A `containerStats` variant that also carries the reclaimable-page-cache field + * `memoryUsageBytesExcludingCache` (`docker-driver.ts`) subtracts from `usage` - `cacheField` picks which + * of the two real cgroup shapes this sample mimics. */ +function containerStatsWithCache( + totalUsage: number, + systemUsage: number, + memoryUsage: number, + cacheField: 'total_inactive_file' | 'inactive_file', + cacheBytes: number, +) { + return { + ...containerStats(totalUsage, systemUsage, memoryUsage), + memory_stats: { usage: memoryUsage, stats: { [cacheField]: cacheBytes } }, + }; +} + +describe('DockerDriver.startRun - per-run resource sampler (onSample)', () => { + beforeEach(() => { + vi.useFakeTimers(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it("samples exactly once per simulated 1000ms tick - not more, not less - computing cpuPercentOfOneCore from the delta against its own previous sample, never the response's own precpu_stats", async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + // An unemitted baseline read, then three ticks - 20%, 40%, 0% of one core, matching the + // percent-of-ONE-core convention `requirements/actor-driver.md` documents (never percent of the + // grant). + stub.queueStatsResponse(containerStats(0, 0, 100)); + stub.queueStatsResponse(containerStats(200, 1000, 150)); + stub.queueStatsResponse(containerStats(600, 2000, 180)); + stub.queueStatsResponse(containerStats(600, 3000, 200)); + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-1', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + await vi.advanceTimersByTimeAsync(1000); + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(3); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + expect(samples[0]?.memoryBytes).toBe(150); + expect(samples[0]?.memoryLimitBytes).toBe(1024 * 1024 * 1024); + expect(samples[1]?.cpuPercentOfOneCore).toBeCloseTo(40); + expect(samples[1]?.memoryBytes).toBe(180); + expect(samples[2]?.cpuPercentOfOneCore).toBeCloseTo(0); + expect(samples[2]?.memoryBytes).toBe(200); + // The configured LIMIT, constant across every sample - never a growing observed peak. + expect(samples.map((s) => s.memoryLimitBytes)).toEqual([ + 1024 * 1024 * 1024, + 1024 * 1024 * 1024, + 1024 * 1024 * 1024, + ]); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('scales cpuPercentOfOneCore by online_cpus (the docker stats convention), not just the raw usage-time ratio', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100, 4)); + // cpuDelta=1000, systemDelta=4000 -> ratio 0.25, * 4 online cpus * 100 = 100% of one core. + stub.queueStatsResponse(containerStats(1000, 4000, 100, 4)); + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-2', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(100); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('reports 0% (never NaN/Infinity) for the degenerate case of a zero system-time delta between two samples', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 1000, 100)); + stub.queueStatsResponse(containerStats(0, 1000, 100)); // identical - zero delta on both axes + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-3', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBe(0); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('treats a reported online_cpus of 0 as 1 - `@types/dockerode` declares the field non-optional, but this defends against a daemon that reports it as 0 anyway', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100, 0)); + // cpuDelta=200, systemDelta=1000 -> ratio 0.2. With the online_cpus=0 -> 1 fallback that's 20%; + // without it (multiplying by the raw 0 instead), it would be 0%. + stub.queueStatsResponse(containerStats(200, 1000, 150, 0)); + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-online-cpus-0', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it("subtracts cgroup v1's total_inactive_file from memory_stats.usage - the same adjustment docker stats' own MEM USAGE column makes", async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); + stub.queueStatsResponse(containerStatsWithCache(200, 1000, 150_000_000, 'total_inactive_file', 50_000_000)); + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-cache-v1', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(1); + expect(samples[0]?.memoryBytes).toBe(100_000_000); // 150M reported usage minus 50M cache + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it("subtracts cgroup v2's inactive_file when total_inactive_file is absent (cgroup v1 has no such field)", async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); + stub.queueStatsResponse(containerStatsWithCache(200, 1000, 150_000_000, 'inactive_file', 60_000_000)); + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-cache-v2', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(1); + expect(samples[0]?.memoryBytes).toBe(90_000_000); // 150M reported usage minus 60M cache + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('never subtracts a cache figure that is not smaller than the reported usage - falls back to the raw usage rather than going to zero or negative', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); + stub.queueStatsResponse(containerStatsWithCache(200, 1000, 100, 'inactive_file', 100)); + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { + runId: 'run-sampler-cache-not-smaller', + imageId: 'fake-image', + env: {}, + memoryMbytes: 1024, + timeoutSecs: 60, + }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + + expect(samples).toHaveLength(1); + expect(samples[0]?.memoryBytes).toBe(100); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('skips a tick outright - no throw, no emission, and the previous sample is left untouched - when stats() rejects (the container may have already exited, or be mid-removal)', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + stub.queueStatsResponse(new Error('stats() failed: container is being removed')); + stub.queueStatsResponse(containerStats(200, 1000, 150)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-stats-reject', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); // tick 1: stats() rejects - skipped, not thrown + expect(samples).toHaveLength(0); + + // Tick 2 succeeds again, diffed against the BASELINE (the rejected tick returned before ever + // updating `previous`, so this is not diffed against anything from the failed tick). + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('skips a tick outright - no frame, accumulators untouched - when memory_stats.usage is missing, and the NEXT good sample emits a full, correct eight-field frame with sane avg/max', async () => { + // Drives the real sample-to-envelope path exactly as `services/runs.ts` wires it in production + // (`onSample` -> `publishSystemInfo`), reproducing the pre-fix poisoning end-to-end rather than only + // at the `RunResourceSample` boundary: pre-fix, this tick's stats blob (`memory_stats: {}`, no + // `usage`) produced a 7-key `systemInfo` frame and then a permanent `NaN` (`null` once + // JSON-serialized) `memAvgBytes` for every later frame of the run, since `state.memoryUsageSum` had + // already summed in a `NaN`. Post-fix, the bad tick never reaches `onSample`/`publishSystemInfo` at all. + resetEventsChannelForTests(); + const runId = 'run-sampler-missing-usage'; + const frames: Array<{ name: string; data: Record }> = []; + subscribeEvents(runId, (frame) => frames.push(JSON.parse(frame))); + + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + // BAD: memory_stats present but with no `usage` field at all - the shape that used to slip past the + // guard and reach `onSample` as a partial (7-key) frame. + stub.queueStatsResponse({ + cpu_stats: { cpu_usage: { total_usage: 50 }, system_cpu_usage: 500, online_cpus: 1 }, + memory_stats: {}, + }); + stub.queueStatsResponse(containerStats(250, 1500, 150)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId, imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => { + samples.push(sample); + publishSystemInfo(runId, sample, { memoryMbytes: 1024 }); + }, + ); + + await vi.advanceTimersByTimeAsync(1000); // tick 1: missing usage - skipped, not a partial frame + expect(samples).toHaveLength(0); + expect(frames).toHaveLength(0); + + // Tick 2 is diffed against the BASELINE (the skipped tick never updated `previous`), and its frame + // is the FIRST one this run has ever published - proving the accumulator was never seeded with the + // bad tick's NaN in the first place. + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.memoryBytes).toBe(150); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(((250 - 0) / (1500 - 0)) * 100); + + expect(frames).toHaveLength(1); + const data = frames[0]!.data; + expect(Object.keys(data).sort()).toEqual( + [ + 'cpuAvgUsage', + 'cpuCurrentUsage', + 'cpuMaxUsage', + 'createdAt', + 'isCpuOverloaded', + 'memAvgBytes', + 'memCurrentBytes', + 'memMaxBytes', + ].sort(), + ); + expect(data.memCurrentBytes).toBe(150); + expect(data.memAvgBytes).toBe(150); // averaged over exactly one (good) sample, never poisoned by the skipped tick + expect(Number.isFinite(data.memAvgBytes as number)).toBe(true); + expect(Number.isFinite(data.cpuAvgUsage as number)).toBe(true); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('skips a tick outright when memory_stats.usage is present but not a finite number (e.g. NaN) - the same guard as a missing field, not just an absent one', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + stub.queueStatsResponse({ + cpu_stats: { cpu_usage: { total_usage: 50 }, system_cpu_usage: 500, online_cpus: 1 }, + memory_stats: { usage: Number.NaN }, + }); + stub.queueStatsResponse(containerStats(250, 1500, 150)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-nan-usage', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(0); + + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.memoryBytes).toBe(150); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('skips a tick outright when cpu_stats.cpu_usage.total_usage is missing - the CPU-side counterpart of the memory guard above', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + // BAD: cpu_usage present but with no total_usage field. + stub.queueStatsResponse({ + cpu_stats: { cpu_usage: {}, system_cpu_usage: 1000, online_cpus: 1 }, + memory_stats: { usage: 150 }, + }); + stub.queueStatsResponse(containerStats(200, 1000, 180)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { + runId: 'run-sampler-missing-total-usage', + imageId: 'fake-image', + env: {}, + memoryMbytes: 1024, + timeoutSecs: 60, + }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); // tick 1: missing total_usage - skipped + expect(samples).toHaveLength(0); + + // Tick 2 is diffed against the BASELINE, not the skipped tick. + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + expect(samples[0]?.memoryBytes).toBe(180); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it("skips a tick outright when cpu_stats.system_cpu_usage is missing while total_usage is present and valid - the shape the guard's second clause exists for", async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + // BAD: total_usage present and finite, but system_cpu_usage is absent entirely - covered because + // the daemon's own stats shape is not guaranteed (docker-driver.ts's cpuUsageSnapshotOf doc + // comment), distinct from - and never reaching the same code path as - the already-tested + // "total_usage missing" case above, which returns before system_cpu_usage is even read. + stub.queueStatsResponse({ + cpu_stats: { cpu_usage: { total_usage: 250 }, online_cpus: 1 }, + memory_stats: { usage: 150 }, + }); + stub.queueStatsResponse(containerStats(200, 1000, 180)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { + runId: 'run-sampler-missing-system-usage', + imageId: 'fake-image', + env: {}, + memoryMbytes: 1024, + timeoutSecs: 60, + }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); // tick 1: missing system_cpu_usage - skipped + expect(samples).toHaveLength(0); + + // Tick 2 is diffed against the BASELINE, not the skipped tick - proves `previous` was left untouched. + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + expect(samples[0]?.memoryBytes).toBe(180); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('skips a tick outright when cpu_stats.system_cpu_usage is present but not a finite number (e.g. NaN) - the same guard as a missing field, not just an absent one', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + stub.queueStatsResponse({ + cpu_stats: { cpu_usage: { total_usage: 250 }, system_cpu_usage: Number.NaN, online_cpus: 1 }, + memory_stats: { usage: 150 }, + }); + stub.queueStatsResponse(containerStats(200, 1000, 180)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { + runId: 'run-sampler-nan-system-usage', + imageId: 'fake-image', + env: {}, + memoryMbytes: 1024, + timeoutSecs: 60, + }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(0); + + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + expect(samples[0]?.memoryBytes).toBe(180); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('skips a tick outright, without throwing or producing an unhandled rejection, when cpu_stats is absent from the stats blob entirely', async () => { + // Pre-fix, `stats.cpu_stats.cpu_usage.total_usage` on a blob with no `cpu_stats` at all throws a + // synchronous TypeError inside `takeSample` - and since the interval callback never attaches a + // `.catch()` to the resulting rejected promise, that becomes an unhandled rejection rather than a + // clean skip. This test proves the optional-chaining guard closes that off too. + const uncaughtErrors: unknown[] = []; + const onUnhandledRejection = (error: unknown): void => { + uncaughtErrors.push(error); + }; + process.on('unhandledRejection', onUnhandledRejection); + + try { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); // baseline + stub.queueStatsResponse({ memory_stats: { usage: 150 } }); // BAD: no cpu_stats at all + stub.queueStatsResponse(containerStats(200, 1000, 180)); // recovers on the next tick + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { + runId: 'run-sampler-no-cpu-stats', + imageId: 'fake-image', + env: {}, + memoryMbytes: 1024, + timeoutSecs: 60, + }, + () => {}, + (sample) => samples.push(sample), + ); + + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(0); + + await vi.advanceTimersByTimeAsync(1000); + expect(samples).toHaveLength(1); + expect(samples[0]?.cpuPercentOfOneCore).toBeCloseTo(20); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + + // Give any (pre-fix) unhandled rejection a moment to actually surface before asserting on it - + // fake timers are active in this suite (`beforeEach`), so this advances virtual time rather than + // waiting on a real one. + await vi.advanceTimersByTimeAsync(0); + expect(uncaughtErrors).toEqual([]); + } finally { + process.removeListener('unhandledRejection', onUnhandledRejection); + } + }); + + it('never starts a sampler at all when no onSample callback is given - no stats() call, ever', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const outcomePromise = driver.startRun( + { runId: 'run-sampler-4', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + ); + await vi.advanceTimersByTimeAsync(3000); + + expect(stub.stats).not.toHaveBeenCalled(); + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + }); + + it('stops sampling for good once the run ends - no further stats() call after startRun resolves, even as more simulated 1000ms boundaries elapse', async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + stub.queueStatsResponse(containerStats(0, 0, 100)); + stub.queueStatsResponse(containerStats(200, 1000, 150)); + + const outcomePromise = driver.startRun( + { runId: 'run-sampler-5', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + () => {}, + ); + await vi.advanceTimersByTimeAsync(1000); + expect(stub.stats).toHaveBeenCalledTimes(2); // the unemitted baseline read, plus tick 1 + + stub.triggerContainerExit(0); + stub.endLogStream(); + await outcomePromise; + + const callCountAtEnd = stub.stats.mock.calls.length; + await vi.advanceTimersByTimeAsync(5000); + // Proves the interval was actually cleared, not merely "hasn't fired yet" - five more simulated + // seconds produce zero further calls. + expect(stub.stats.mock.calls.length).toBe(callCountAtEnd); + }); + + it('awaits the one in-flight stats() call before startRun proceeds to container.remove() when it settles quickly, and issues no further stats() call after stop()', async () => { + // Real timers here: nothing queued at all, so every stats() call (the baseline included) stays + // pending until this test explicitly resolves it - no simulated time needs to elapse. + vi.useRealTimers(); + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const outcomePromise = driver.startRun( + { runId: 'run-sampler-stop-1', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + () => {}, + ); + + // Let `startRun` run past its own setup, far enough that the sampler's baseline `stats()` call has + // actually been issued. + await new Promise((resolve) => setImmediate(resolve)); + expect(stub.stats).toHaveBeenCalledTimes(1); + + // The container exits and its log stream drains - `startRun`'s `finally` block is reached and calls + // `sampler.stop()` - but the one in-flight `stats()` call is still pending, so `container.remove()` + // must not have happened yet. + stub.triggerContainerExit(0); + stub.endLogStream(); + await new Promise((resolve) => setImmediate(resolve)); + await new Promise((resolve) => setImmediate(resolve)); + await new Promise((resolve) => setImmediate(resolve)); + + expect(stub.container.remove).not.toHaveBeenCalled(); + + // Once the in-flight call resolves (well inside `SAMPLER_STOP_GRACE_MS`), `stop()` completes and + // `remove()` is called. + stub.resolvePendingStats(containerStats(0, 0, 100)); + const outcome = await outcomePromise; + + expect(outcome).toEqual({ exitCode: 0, timedOut: false }); + expect(stub.container.remove).toHaveBeenCalledTimes(1); + // No timer tick ever fired (well under 1000ms of real elapsed time throughout this test) and the + // baseline read is unemitted either way - exactly one `stats()` call total, none after `stop()`. + expect(stub.stats).toHaveBeenCalledTimes(1); + }); + + it("bounds stop()'s wait by SAMPLER_STOP_GRACE_MS instead of hanging forever when stats() never resolves - startRun still reaches container.remove(), and the abandoned call resolving later issues no further stats() call and is never emitted", async () => { + // `stop()` deliberately bounds its wait: with no client-side Docker timeout configured anywhere in + // this codebase, an unbounded await on the in-flight `stats()` call would leave `startRun`'s own + // `finally` - and therefore the whole run's finalization - stuck forever against a daemon that + // never answers. This test is the red->green proof that the hang is now bounded: `stats()` is + // never resolved at all here, yet `startRun` still completes. + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const samples: RunResourceSample[] = []; + const outcomePromise = driver.startRun( + { runId: 'run-sampler-stop-2', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + (sample) => samples.push(sample), + ); + + // Let `startRun` run past its own setup, far enough that the sampler's baseline `stats()` call has + // actually been issued - it is never resolved for the rest of this test. + await vi.advanceTimersByTimeAsync(0); + expect(stub.stats).toHaveBeenCalledTimes(1); + + stub.triggerContainerExit(0); + stub.endLogStream(); + + // `startRun`'s `finally` reaches `sampler.stop()`. Just under the grace, `container.remove()` must + // not have fired yet - `stop()` is still (bounded-ly) waiting on the never-resolving call. + await vi.advanceTimersByTimeAsync(4999); + expect(stub.container.remove).not.toHaveBeenCalled(); + + // At/after the grace, `stop()` gives up on the still-pending call and `startRun` proceeds to + // `container.remove()` and resolves - the hang is bounded, not eliminated by some other means. + await vi.advanceTimersByTimeAsync(1); + const outcome = await outcomePromise; + + expect(outcome).toEqual({ exitCode: 0, timedOut: false }); + expect(stub.container.remove).toHaveBeenCalledTimes(1); + + // The abandoned call resolving even later must never be emitted (`stopped` suppresses it, per + // `takeSample`'s own doc comment) and must never trigger a further `stats()` call - `stop()` already + // cleared the interval before starting its bounded wait. + stub.resolvePendingStats(containerStats(999, 999, 999)); + await vi.advanceTimersByTimeAsync(5000); + expect(stub.stats).toHaveBeenCalledTimes(1); + expect(samples).toEqual([]); + }); + + it("clears stop()'s own grace timer once the in-flight stats() call wins the race, instead of leaving it armed for the rest of SAMPLER_STOP_GRACE_MS", async () => { + const stub = stubDockerForSampler(); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const outcomePromise = driver.startRun( + { runId: 'run-sampler-stop-3', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + () => {}, + ); + + // Let `startRun` run past its own setup, far enough that the sampler's baseline `stats()` call has + // actually been issued - it is left pending (no queued response) for the rest of this test. + await vi.advanceTimersByTimeAsync(0); + expect(stub.stats).toHaveBeenCalledTimes(1); + + stub.triggerContainerExit(0); + stub.endLogStream(); + + // A little into the grace window: `stop()`'s own grace `setTimeout` is now the only timer left + // armed (the sampler's `setInterval` and the run's own `timeoutSecs` timer are already cleared by + // this point, and the log-drain race resolved instantly since the log stream already ended). + await vi.advanceTimersByTimeAsync(100); + expect(vi.getTimerCount()).toBe(1); + + // The in-flight call wins the race well inside `SAMPLER_STOP_GRACE_MS`. + stub.resolvePendingStats(containerStats(0, 0, 100)); + const outcome = await outcomePromise; + + expect(outcome).toEqual({ exitCode: 0, timedOut: false }); + // Before this fix, the grace timer's handle was never captured, so it stayed armed on the event + // loop for the rest of the grace window even though the race it was guarding had already settled. + expect(vi.getTimerCount()).toBe(0); + }); + + it('a container.logs() rejection between container.start() and container.wait() still stops the sampler and removes the container', async () => { + // Real timers, same reason as the test above: nothing queued, so the sampler's own baseline + // `stats()` call stays pending until this test resolves it - no simulated time needs to elapse. + vi.useRealTimers(); + const stub = stubDockerForSampler(); + stub.container.logs = vi.fn(async () => { + throw new Error('container.logs failed'); + }); + const driver = new DockerDriver(stub.docker); + driver.available = true; + + const outcomePromise = driver.startRun( + { runId: 'run-sampler-leak-1', imageId: 'fake-image', env: {}, memoryMbytes: 1024, timeoutSecs: 60 }, + () => {}, + () => {}, + ); + + // Let `startRun` run far enough that the sampler's own baseline `stats()` call has actually been + // issued - proof a sampler genuinely existed at the moment `container.logs()` rejects, not just + // that nothing crashed. + await new Promise((resolve) => setImmediate(resolve)); + expect(stub.stats).toHaveBeenCalledTimes(1); + + // Resolve that one in-flight baseline read so `sampler.stop()` - awaited inside the now-widened + // `finally` - can actually complete once `container.logs()`'s rejection unwinds `startRun` into it. + stub.resolvePendingStats(containerStats(0, 0, 100)); + + await expect(outcomePromise).rejects.toThrow('container.logs failed'); + + // The container is never leaked, on this path either - `container.remove()` still runs, even though + // `container.start()` succeeded but everything after it (the sampler, the log stream) never got to + // `container.wait()` at all. + expect(stub.container.remove).toHaveBeenCalledTimes(1); + + // The sampler was genuinely stopped, not merely abandoned mid-flight: no further `stats()` call + // ever arrives. + const statsCallsAtRejection = stub.stats.mock.calls.length; + await new Promise((resolve) => setTimeout(resolve, 50)); + expect(stub.stats.mock.calls.length).toBe(statsCallsAtRejection); + }); +});