diff --git a/apps/daemon/src/docker/client.spec.ts b/apps/daemon/src/docker/client.spec.ts index f42ac0c..ffbd0a5 100644 --- a/apps/daemon/src/docker/client.spec.ts +++ b/apps/daemon/src/docker/client.spec.ts @@ -1,7 +1,20 @@ import { execFileSync } from 'node:child_process'; -import { afterAll, afterEach, beforeAll, describe, expect, it } from 'vitest'; +import { createServer, type Server, type Socket } from 'node:net'; +import { mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { randomUUID } from 'node:crypto'; +import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it, vi } from 'vitest'; import { daemonConfigSchema } from '../config/schema.js'; -import { DockerClient } from './client.js'; +import { + boundEveryRequest, + DockerClient, + DOCKER_ANSWER_TIMEOUT_MS, + DockerUnansweredError, + dockerRequestTimeout, + PULL_STALL_TIMEOUT_MS, + type DockerRequest, +} from './client.js'; /** * These tests drive a real Docker engine. @@ -56,14 +69,14 @@ afterAll(() => { const TEST_IMAGE = 'alpine:3.20'; const NETWORK = 'hopper-test-net'; -function makeClient(): DockerClient { +function makeClient(socket: string | null = dockerSocket): DockerClient { const config = daemonConfigSchema.parse({ uuid: '3f2504e0-4f89-41d3-9a0c-0305e82c3301', tokenId: 'a'.repeat(16), tokenSecret: 'b'.repeat(64), panel: { url: 'http://127.0.0.1:8080', jwtSecret: 'c'.repeat(32) }, docker: { - socket: dockerSocket ?? '', + socket: socket ?? '', // A range of its own, away from the default the daemon ships: these tests // run on machines that may already host a real Hopper network, and // colliding with it would take its servers off the network. @@ -224,3 +237,490 @@ describe.runIf(dockerSocket)('DockerClient against a real engine', () => { }, 120_000); }); }); + +/** + * A registry that accepts the connection and then stops sending. + * + * No engine can be made to do this on demand, and no engine is needed to: the + * failure is entirely inside `followProgress`, which used to be wrapped in a + * promise with no timeout of any kind. A registry that goes quiet mid-transfer + * never ends the stream, so the completion callback never fires and the promise + * never settles — and the caller is an installation, which is then blocked on a + * line that cannot return, before any of its own deadlines have been armed. It + * is the same hang as an unbounded `container.wait()`, one line earlier. + * + * Dockerode is driven through `client.api` here rather than mocked as a module: + * what is under test is this class's handling of the three callbacks, and + * substituting them is the smallest thing that isolates it. + */ +describe('a pull the registry stops answering', () => { + afterEach(() => { + vi.useRealTimers(); + }); + + function stalling() { + const client = makeClient(); + const state = { destroyed: false }; + + let progress: ((event: { status?: string; progress?: string }) => void) | null = null; + let finished: ((error: Error | null) => void) | null = null; + + const api = client.api as unknown as { + listImages: () => Promise; + pull: () => Promise; + modem: { + followProgress: ( + stream: unknown, + onFinished: (error: Error | null) => void, + onProgress: (event: { status?: string; progress?: string }) => void, + ) => void; + }; + }; + + // Absent, so the pull is really attempted rather than short-circuited. + api.listImages = () => Promise.resolve([]); + api.pull = () => + Promise.resolve({ + destroy: () => { + state.destroyed = true; + }, + }); + api.modem.followProgress = (_stream, onFinished, onProgress) => { + finished = onFinished; + progress = onProgress; + }; + + return { + client, + state, + layer: (): void => progress?.({ status: 'Downloading', progress: '[===> ]' }), + complete: (): void => finished?.(null), + }; + } + + it('gives up rather than waiting for ever', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const fake = stalling(); + const pulling = fake.client.pullImage('alpine:3.20'); + const settled = expect(pulling).rejects.toThrow(/stopped sending/); + + await vi.advanceTimersByTimeAsync(PULL_STALL_TIMEOUT_MS + 1); + await settled; + + // Destroyed, not merely abandoned: `followProgress` still holds the stream, + // and the socket to the registry would otherwise stay open for the life of + // the daemon. + expect(fake.state.destroyed).toBe(true); + }); + + // The bound is on inactivity, like the installation's own. A pull receiving + // layers is alive however large the image is, and a total-duration cap would + // break precisely the images worth pulling. + it('never gives up on a pull that is still receiving layers', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const fake = stalling(); + const pulling = fake.client.pullImage('alpine:3.20'); + + // Ten windows' worth of downloading, an event just inside each one. + for (let layer = 0; layer < 10; layer += 1) { + await vi.advanceTimersByTimeAsync(PULL_STALL_TIMEOUT_MS - 1_000); + fake.layer(); + } + + fake.complete(); + + await expect(pulling).resolves.toBeUndefined(); + expect(fake.state.destroyed).toBe(false); + }); +}); + +/** + * The rule itself, read as a rule. + * + * `dockerRequestTimeout` is what decides how long any request gets, so its + * default branch is the guarantee the whole design rests on: **an endpoint + * nobody thought about is bounded**. The cases below are the exceptions, and + * every one of them is an exception somebody had to write down. + */ +describe('how long a request to Docker gets', () => { + const asked = (method: string, path: string, options?: Record) => + dockerRequestTimeout({ method, path, ...(options ? { options } : {}) }); + + /** + * The one endpoint that answers when something happens rather than when asked. + * + * `POST /containers/{id}/wait` is how the daemon learns a container ended: + * Docker holds it open until it does, which for an installation may be hours + * and for a *server* is the whole time it is up. A bound on it would report + * every long-running server as a crash. + */ + it('never bounds the wait for a container to end', () => { + expect(asked('POST', '/containers/hopper-3f2504e0/wait?')).toBeNull(); + }); + + /** + * Everything else, including endpoints this daemon does not call today. The + * list is deliberately not a list: the function bounds by default and names + * only what it excuses. + */ + it.each([ + ['POST', '/containers/create?'], + ['GET', '/containers/hopper-3f2504e0/json?'], + ['POST', '/containers/hopper-3f2504e0/start?'], + ['POST', '/containers/hopper-3f2504e0/kill?'], + ['DELETE', '/containers/hopper-3f2504e0?'], + ['GET', '/containers/hopper-3f2504e0/stats?'], + ['GET', '/containers/hopper-3f2504e0/logs?'], + ['POST', '/containers/hopper-3f2504e0/attach?'], + ['GET', '/containers/json?'], + ['GET', '/images/json?'], + ['GET', '/networks?'], + ['POST', '/networks/create?'], + ['GET', '/_ping'], + // Two nobody here calls yet, which is the point of asking. + ['POST', '/containers/hopper-3f2504e0/exec'], + ['POST', '/volumes/create'], + ])('bounds %s %s', (method, path) => { + expect(asked(method, path)).toBe(DOCKER_ANSWER_TIMEOUT_MS); + }); + + /** + * A pull's own request, which is bounded on the registry's silence rather than + * on this node's: Docker does not write the response headers until the + * registry has answered the manifest behind them, and this file already + * decided how long that may take. + */ + it("gives a pull the registry's window rather than the node's", () => { + expect(asked('POST', '/images/create?fromImage=alpine&tag=3.20')).toBe(PULL_STALL_TIMEOUT_MS); + }); + + /** + * The grace a caller chose is added to the window rather than expected to fit + * inside it. Docker sends SIGTERM, waits `t` seconds and only then answers, so + * a five-minute stop bounded at one minute would report a Docker doing exactly + * what it was told as one that had stopped answering. + */ + it('adds the grace period a stop was told to wait', () => { + expect(asked('POST', '/containers/hopper/stop?t=10', { t: 10 })).toBe( + DOCKER_ANSWER_TIMEOUT_MS + 10_000, + ); + expect(asked('POST', '/containers/hopper/restart?t=300', { t: 300 })).toBe( + DOCKER_ANSWER_TIMEOUT_MS + 300_000, + ); + // Docker's own default when the caller names none, added rather than assumed + // to be covered. + expect(asked('POST', '/containers/hopper/stop?')).toBe(DOCKER_ANSWER_TIMEOUT_MS + 10_000); + }); +}); + +/** + * The rule against a Docker that accepts the connection and then says nothing. + * + * A real `DockerClient`, a real Dockerode, a real docker-modem and a real HTTP + * request over a real socket — with a server on the far end that answers + * nothing, or answers headers and then goes silent. No engine is needed and none + * would help: no Docker can be asked to stop answering on demand, and what is + * under test is what this client does when one has. + * + * The window is shortened by wrapping the client a second time. `boundEveryRequest` + * wraps whatever `dial` it finds, so a second pass with a fifty-millisecond table + * sits outside the production one and fires first; everything below the wrapper — + * dockerode, the modem, the socket — is exactly what runs in production. + */ +describe('a Docker that has stopped answering', () => { + /** Far shorter than the real window, and far longer than a local socket. */ + const WINDOW_MS = 50; + + let directory: string; + let server: Server; + let address: string; + let accepted: Socket[] = []; + + /** What the server does with a connection, set by each test. */ + let respond: (socket: Socket) => void = () => undefined; + + beforeEach(async () => { + // A named pipe on Windows and a Unix socket everywhere else — the same two + // forms `docker.socket` itself accepts. + directory = mkdtempSync(join(tmpdir(), 'hopper-docker-')); + address = + process.platform === 'win32' + ? `\\\\.\\pipe\\hopper-test-${randomUUID()}` + : join(directory, 'docker.sock'); + + accepted = []; + respond = () => undefined; + + server = createServer((socket) => { + accepted.push(socket); + // A connection that is never read from is one Node may close on its own; + // this keeps it open and mute, which is the whole scenario. + socket.on('data', () => respond(socket)); + socket.on('error', () => undefined); + }); + + await new Promise((resolve) => server.listen(address, resolve)); + }); + + afterEach(async () => { + accepted.forEach((socket) => socket.destroy()); + await new Promise((resolve) => server.close(() => resolve())); + rmSync(directory, { recursive: true, force: true }); + }); + + /** A client whose requests are bounded at {@link WINDOW_MS} rather than a minute. */ + function impatient(): DockerClient { + const client = makeClient(address); + + boundEveryRequest(client.api, { + timeoutFor: (request) => + // The exception list is the production one: only the window changes. + dockerRequestTimeout(request) === null ? null : WINDOW_MS, + }); + + return client; + } + + it('fails a question rather than waiting on it for ever', async () => { + const client = impatient(); + + await expect(client.api.getContainer('hopper-test').inspect()).rejects.toThrow( + DockerUnansweredError, + ); + }); + + // The message is read by an operator on a console, and "Docker did not answer" + // on its own leaves them nothing to look at. It names the request. + it('names the request it gave up on', async () => { + const client = impatient(); + + await expect(client.api.getContainer('hopper-test').start()).rejects.toThrow( + /POST \/containers\/hopper-test\/start/, + ); + }); + + /** + * Abandoned *and* closed. Docker may answer this in a minute, and a socket + * nobody is reading from would otherwise stay open for the life of the daemon + * — on a node where every call is timing out, a file descriptor leak on top of + * an outage. + */ + it('closes the socket it gave up on', async () => { + const client = impatient(); + + await expect(client.api.getContainer('hopper-test').inspect()).rejects.toThrow( + DockerUnansweredError, + ); + + await vi.waitFor(() => expect(accepted.some((socket) => socket.destroyed)).toBe(true)); + }); + + /** + * **The regression this whole mechanism had to avoid.** + * + * The daemon adopts running servers when it starts and streams their console + * and their statistics. A quiet Minecraft server sends nothing down either for + * hours by construction — a bound that reached the stream would take every + * adopted server's console offline on a timer, which is far worse than the + * hangs being fixed. So the deadline covers Docker answering and stops there: + * the headers arrive, the promise settles, and what does or does not come down + * the stream afterwards passes no deadline at all. + */ + it('leaves a stream that has gone quiet alone', async () => { + respond = (socket) => { + socket.write( + 'HTTP/1.1 200 OK\r\nContent-Type: application/json\r\nTransfer-Encoding: chunked\r\n\r\n', + ); + }; + + const client = impatient(); + const stream = await client.api.getContainer('hopper-test').stats({ stream: true }); + + let ended = false; + stream.on('end', () => (ended = true)); + stream.on('error', () => (ended = true)); + + // Twenty windows of a container saying nothing, which for a server that + // nobody is playing on is a perfectly ordinary evening. + await new Promise((resolve) => setTimeout(resolve, WINDOW_MS * 20)); + + expect(ended).toBe(false); + expect((stream as unknown as { destroyed?: boolean }).destroyed).not.toBe(true); + }); + + /** + * And the same for the wait, which is left unbounded by name. + * + * `container.wait()` on a *server* container is how the daemon learns the + * server exited. Bounding it would make every server that stays up longer than + * the window look like a crash. + */ + it('waits on a container ending for as long as it takes', async () => { + const client = impatient(); + + let settled = false; + const waiting = client.api + .getContainer('hopper-test') + .wait() + .then( + () => (settled = true), + () => (settled = true), + ); + + await new Promise((resolve) => setTimeout(resolve, WINDOW_MS * 20)); + + expect(settled).toBe(false); + + // Released here rather than left for the runner to notice: the socket is + // torn down in `afterEach`, and the rejection that follows has to have + // somewhere to land. + void waiting; + }); + + /** + * Unbounded is not uncancellable, and the difference is a file descriptor. + * + * The wait being exempt from the rule is what makes it the one request nothing + * in this daemon will ever close on its own — so a caller that walks away from + * one, which the installer's teardown deadline does on every stalled install, + * leaves a socket to the Docker daemon open for the life of the process. The + * caller's own `abortSignal` is the way out of that, and it only works because + * the wrapper hands the request through untouched on the unbounded path + * instead of building a new one around its own controller. + * + * Proved against a real socket, like everything else in this block, because + * the claim is about `docker-modem` and `http.request` rather than about a + * flag: the signal has to survive dockerode lifting it out of the options, + * the modem deleting it from the query string, and reach the request itself. + */ + it('closes a wait its caller has given up on', async () => { + const client = impatient(); + const abandon = new AbortController(); + + const waiting = client.api.getContainer('hopper-test').wait({ abortSignal: abandon.signal }); + + // The request is on the socket, and the far end is answering nothing. + await vi.waitFor(() => expect(accepted.length).toBeGreaterThan(0)); + + // Twenty windows of an unbounded request being ignored, which is the whole + // point of exempting it. + await new Promise((resolve) => setTimeout(resolve, WINDOW_MS * 20)); + + abandon.abort(); + + await expect(waiting).rejects.toThrow(); + await vi.waitFor(() => expect(accepted.some((socket) => socket.destroyed)).toBe(true)); + }); + + /** + * The attach handshake, which is the one request in `client.ts` the rule + * cannot reach: it is issued by hand rather than through dockerode, precisely + * so that no byte of dockerode's own options can end up in a server's stdin. + * It carries a bound of its own, and the console stream it hands back does + * not. + */ + it('gives up on an attach the socket never upgrades', async () => { + const client = impatient(); + + await expect(client.attachToContainer('hopper-test', WINDOW_MS)).rejects.toThrow( + DockerUnansweredError, + ); + }); +}); + +/** + * Docker turning up after the deadline has already answered for it. + * + * The rule abandons a request that has run out of window, and abandoning it does + * not stop it arriving: Docker may answer a minute later, and the abort issued + * alongside the give-up surfaces on the same path as a request error. Either + * way `docker-modem` calls back a second time, over a call this client has + * already reported as unanswered. + * + * Nothing downstream notices, which is exactly why this is asked here. Every + * caller in the daemon reaches these requests through dockerode's promise + * wrapper, and a promise settles once and ignores the rest — so a second + * callback carrying a real container inspection is invisible to all thirty-odd + * tests around it while being a caller acting on data it was told did not + * arrive. The guard is one line and its absence has no symptom, which is the + * combination that gets a line deleted by someone tidying up. + * + * Driven against `dial` directly rather than through a socket, because what is + * under test is the contract this wrapper offers its own caller — one callback, + * whatever Docker does — and a real engine cannot be asked to answer late. + */ +describe('a Docker that answers after the deadline', () => { + afterEach(() => { + vi.useRealTimers(); + }); + + /** The wrapper, over a `dial` that hands its callback to the test. */ + function wrapped(): { + dial: (request: DockerRequest, callback: (error: unknown, result?: unknown) => void) => void; + answerLate: (error: unknown, result?: unknown) => void; + } { + let late: ((error: unknown, result?: unknown) => void) | null = null; + + const docker = { + modem: { + dial: (_request: DockerRequest, callback: (error: unknown, result?: unknown) => void) => { + late = callback; + }, + }, + }; + + boundEveryRequest(docker as unknown as Parameters[0], { + timeoutFor: () => 50, + }); + + return { + dial: docker.modem.dial, + answerLate: (error, result) => late?.(error, result), + }; + } + + it('never calls a caller back a second time', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const modem = wrapped(); + const answers: unknown[] = []; + + modem.dial({ method: 'GET', path: '/containers/hopper-test/json?' }, (error, result) => + answers.push(error ?? result), + ); + + await vi.advanceTimersByTimeAsync(51); + + expect(answers).toHaveLength(1); + expect(answers[0]).toBeInstanceOf(DockerUnansweredError); + + // Docker gets round to it, with the answer nobody is waiting for any more. + modem.answerLate(null, { State: { Running: true } }); + // And the abort issued with the give-up, arriving as a request error. + modem.answerLate(new Error('The operation was aborted')); + + expect(answers).toHaveLength(1); + expect(answers[0]).toBeInstanceOf(DockerUnansweredError); + }); + + // The mirror image, and the one that says the guard is a guard rather than a + // switch: an answer that arrives inside the window is passed straight on, and + // the deadline that was hanging over it never speaks. + it('passes on an answer that arrived in time, and only that one', async () => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + + const modem = wrapped(); + const answers: unknown[] = []; + + modem.dial({ method: 'GET', path: '/containers/hopper-test/json?' }, (error, result) => + answers.push(error ?? result), + ); + + modem.answerLate(null, { State: { Running: true } }); + await vi.advanceTimersByTimeAsync(5_000); + + expect(answers).toEqual([{ State: { Running: true } }]); + }); +}); diff --git a/apps/daemon/src/docker/client.ts b/apps/daemon/src/docker/client.ts index c1f9340..039ef67 100644 --- a/apps/daemon/src/docker/client.ts +++ b/apps/daemon/src/docker/client.ts @@ -11,11 +11,310 @@ export interface DockerInfo { runningContainers: number; } +/** + * How long a pull may send nothing at all before it is abandoned. + * + * Two minutes, and unlike the installation's own deadline this one really can be + * measured on silence, because the thing being watched is Docker's progress + * stream rather than a shell script. Docker reports every chunk of every layer: + * a pull that is transferring at any speed whatsoever produces events several + * times a second, and two minutes without one is a registry that has stopped + * answering, not a slow link. + * + * Generous all the same, because the quiet stretches are real: extraction of a + * large layer reports at intervals, and a registry under load can take a while + * to answer the manifest request that opens the whole thing. + */ +export const PULL_STALL_TIMEOUT_MS = 120_000; + +/** + * How long Docker is given to answer one question about this node. + * + * A minute is far more than any of these need. Creating a container, inspecting + * one, starting, killing, removing, listing images: a Docker that is answering + * at all answers each of them in milliseconds. `stop` is the one that takes real + * time, and it takes exactly the grace period the caller asked for — which is + * why {@link dockerRequestTimeout} adds that grace on top of this rather than + * hoping it fits inside. + * + * Anything still outstanding after sixty seconds is not slow, it is a Docker + * that has stopped answering, and the honest thing to do with that is fail + * loudly. The alternative is what this daemon used to do: `install()` runs on + * the server's operation queue, so a single unbounded round trip there took that + * queue with it for ever — no start, no stop, no reinstall for that server until + * hopperd was restarted, and nothing in the panel to say why. + */ +export const DOCKER_ANSWER_TIMEOUT_MS = 60_000; + +/** + * A question Docker was asked and never answered. + * + * A type of its own rather than a plain `Error` because callers act on it: the + * installer says it on the console it knows the operator is watching, and the + * ownership reclaim reports a Docker fault rather than accusing a `chown` of + * having stood still. Everything else treats it as the failure it is. + */ +export class DockerUnansweredError extends Error { + constructor(message: string) { + super(message); + this.name = 'DockerUnansweredError'; + } +} + +/** + * One request, as docker-modem describes it to itself. + * + * Only the fields the rule below reads are declared. `abortSignal` is + * docker-modem's own option — it forwards it to `http.request` as `signal` — and + * is the one field written back rather than read. + */ +export interface DockerRequest { + path?: string; + method?: string; + /** The query options dockerode built, `t` among them for `stop`. */ + options?: Record; + abortSignal?: AbortSignal; +} + +type DialCallback = (error: unknown, result?: unknown) => void; +type Dial = (request: DockerRequest, callback: DialCallback) => void; + +/** + * The endpoints that answer when something happens rather than when asked. + * + * **`POST /containers/{id}/wait` is the whole list, and it has to be.** It is + * how the daemon learns a container ended: Docker holds the request open until + * it does, which for an installation may be hours and for a *server* is the + * entire time it is up. Bounding it would report every long-running server as a + * crash and every large install as a failure — the one regression worse than the + * hangs this rule exists to end. + * + * The streams are not in this list and do not need to be, which is the property + * that makes the rule safe rather than a lucky escape. See + * {@link boundEveryRequest}: what is bounded is Docker answering, and an attach, + * a `stats` stream or a pull's progress stream *is answered* the moment its + * headers arrive. What flows down it afterwards — nothing at all, for hours, on + * a quiet Minecraft server the daemon adopted at startup — passes no deadline of + * any kind. + */ +const LONG_POLL_ENDPOINTS = [/^\/containers\/[^/]+\/wait$/]; + +/** `POST /images/create`, the request that opens a pull. */ +const IMAGE_PULL_ENDPOINT = '/images/create'; + +/** The two endpoints whose duration the caller chooses, in seconds. */ +const GRACE_ENDPOINTS = [/^\/containers\/[^/]+\/(stop|restart)$/]; + +/** + * How long this request has, or `null` for one that is deliberately unbounded. + * + * Pure and exported so the rule can be read and tested as a rule, rather than + * inferred from the behaviour of a socket. + * + * Three cases, and the default is the one that matters: **anything not named + * here is bounded**. A Docker endpoint added to dockerode tomorrow, or one this + * daemon starts calling tomorrow, lands on {@link DOCKER_ANSWER_TIMEOUT_MS} + * without anybody remembering to arrange it. + * + * - {@link LONG_POLL_ENDPOINTS} are unbounded, because they answer when + * something happens rather than when asked. + * - A pull's own request gets {@link PULL_STALL_TIMEOUT_MS}. Docker does not + * write the response headers until the registry has answered the manifest + * request behind them, so this bound is the *registry's* silence, not this + * node's — and this file already decided how long that may last. Bounding it + * at a minute instead would start failing pulls from a slow registry that the + * progress stream, one line later, is content to wait two minutes for. + * - `stop` and `restart` carry a grace period the caller chose: Docker sends + * SIGTERM, waits `t` seconds, then SIGKILL, and only then answers. The grace + * is added to the window rather than expected to fit inside it, so that a + * caller which one day asks for a five-minute stop is not reported as a + * Docker that stopped answering after sixty seconds of doing exactly what it + * was told. + */ +export function dockerRequestTimeout(request: DockerRequest): number | null { + // Everything after the `?` is the query dockerode built; the endpoint is what + // says which question this is. + const endpoint = (request.path ?? '').split('?')[0] ?? ''; + + if (LONG_POLL_ENDPOINTS.some((pattern) => pattern.test(endpoint))) { + return null; + } + + if (endpoint === IMAGE_PULL_ENDPOINT) { + return PULL_STALL_TIMEOUT_MS; + } + + return DOCKER_ANSWER_TIMEOUT_MS + gracePeriodMs(endpoint, request.options); +} + +/** The seconds a `stop` or a `restart` was told to wait before it kills. */ +function gracePeriodMs(endpoint: string, options: Record | undefined): number { + if (!GRACE_ENDPOINTS.some((pattern) => pattern.test(endpoint))) { + return 0; + } + + const grace = options?.['t']; + + // Docker's own default is ten seconds when the caller names none, and it is + // added rather than assumed to be covered: the point of this function is that + // no bound here is ever a guess about how long Docker was asked to take. + return (typeof grace === 'number' && grace > 0 ? grace : 10) * 1000; +} + +/** + * Bounds every request this client makes, once, at the one place they all pass + * through. + * + * **The rule is applied here and not at the call sites, and that is the whole + * point of it.** Four successive reviews of the install path each found more + * unbounded round trips than the last — `container.wait`, then the pull's + * progress stream, then create/attach/start, then the ownership reclaim's four, + * then `remove`, the activity probe's `stats`, `listImages` and the pull's own + * request — and each was closed with a `Promise.race` of its own. That is not a + * bug list, it is the wrong shape: a codebase with no rule offers every new call + * a fresh chance to forget. A call added tomorrow is bounded now without its + * author having to know this comment exists. + * + * **`modem.dial` is that place.** Dockerode is a thin layer of URL building over + * docker-modem, and every one of its methods — on the client, on a container, on + * an image, on a network — ends in exactly one `dial` per HTTP request. Wrapping + * it covers the methods this daemon does not call yet, and covers a *composite* + * like `docker.run()` correctly into the bargain: it bounds each of the requests + * such a helper makes, where a wrapper over dockerode's own methods would have + * bounded the whole of it and reported any container that ran for a minute as a + * Docker fault. + * + * **What is bounded is Docker answering, never a stream.** The deadline covers + * the gap between the request leaving and docker-modem calling back, and for a + * streaming endpoint that callback comes with the response headers. So an attach + * to a server's console, a `stats` stream and a pull's progress stream are each + * bounded up to the moment Docker hands them over, and completely unbounded + * afterwards. That matters more than anything else here: the daemon adopts + * running servers when it starts and streams their console and their statistics, + * and a quiet Minecraft server sends nothing down its console for hours by + * construction. A bound that reached those streams would take every adopted + * server's console and stats offline on a timer, which is a far worse failure + * than the hangs being fixed. + * + * **This is why it is not Dockerode's own `timeout` option**, which was the + * obvious candidate. That option — and an HTTP agent timeout, and anything else + * built on `socket.setTimeout` — is an *inactivity* timeout on the socket, not a + * bound on the answer. It cannot tell a request Docker is ignoring from a stream + * Docker is deliberately holding open, so it would destroy exactly the three + * streams above, and `container.wait()` with them. It is also one figure for + * every request, with no way to say which ones are long-polls. + * + * **Losing the race abandons the call; it does not undo it.** The socket is + * closed — that is what the abort signal buys, and it is why this does not leak + * a connection per abandoned call — but a `createContainer` Docker was already + * acting on may still leave a container on the node. That is the right way + * round: one stray container an operator can see and `docker rm`, against a + * server whose every action hangs for ever with nothing to look at. + * + * Exported so the rule can be tested against a real Docker socket that never + * answers, and so the installer's tests can present a Docker that behaves as + * this one makes it behave. + */ +export function boundEveryRequest( + docker: Dockerode, + options: { + /** Overridden only by the tests, which cannot wait a minute to prove this. */ + timeoutFor?: (request: DockerRequest) => number | null; + /** Told about every abandoned call, for the log on the node. */ + onAbandoned?: (message: string) => void; + } = {}, +): void { + const timeoutFor = options.timeoutFor ?? dockerRequestTimeout; + + // The instance's own `dial`, not the prototype's: another Dockerode built + // anywhere else in this process — a test, a library — must not inherit a rule + // it never asked for. + const modem = docker.modem as unknown as { dial: Dial }; + const dial = modem.dial.bind(modem); + + modem.dial = (request, callback) => { + const timeoutMs = timeoutFor(request); + + if (timeoutMs === null) { + dial(request, callback); + return; + } + + const abandon = new AbortController(); + let settled = false; + + const timer = setTimeout(() => { + if (settled) { + return; + } + + settled = true; + + const message = unanswered(request, timeoutMs); + options.onAbandoned?.(message); + + // Closed rather than merely forgotten. Docker may still answer this in a + // minute, and a socket nobody is reading from would otherwise stay open + // for the life of the daemon — on a node where every call is timing out, + // that is a file descriptor leak on top of an outage. + abandon.abort(); + callback(new DockerUnansweredError(message)); + }, timeoutMs); + + // Never a reason for hopperd to stay alive: a daemon being shut down has + // stopped caring how this call ends. + timer.unref(); + + dial( + { ...request, abortSignal: alsoOn(request.abortSignal, abandon.signal) }, + (error, result) => { + // The deadline has already answered for this call. Docker turning up late + // — or the abort above surfacing as a request error — must not call back a + // second time. + if (settled) { + return; + } + + settled = true; + clearTimeout(timer); + callback(error, result); + }, + ); + }; +} + +/** + * The caller's own cancellation, if it had one, and ours. + * + * Nothing in this daemon passes a signal today. It is combined rather than + * overwritten so that the day something does, the deadline does not silently + * stop applying to that one call. + */ +function alsoOn(caller: AbortSignal | undefined, ours: AbortSignal): AbortSignal { + return caller === undefined ? ours : AbortSignal.any([caller, ours]); +} + +/** What an abandoned call is called, on a console and in a log. */ +function unanswered(request: DockerRequest, timeoutMs: number): string { + const endpoint = (request.path ?? '').split('?')[0] ?? ''; + + return ( + `Docker did not answer ${request.method ?? 'GET'} ${endpoint} within ` + + `${Math.round(timeoutMs / 1000)}s. This node's Docker is not answering: the request has been ` + + 'abandoned, and anything it had already begun may still be happening on this node.' + ); +} + /** * Access to the host machine's Docker daemon. * * The Docker socket is equivalent to root access: it is handled by this module * only, and is never mounted into a server container. + * + * Every question this class or its callers ask Docker is bounded — see + * {@link boundEveryRequest} for the rule, {@link LONG_POLL_ENDPOINTS} for the + * one call deliberately left out of it, and {@link attachToContainer} for the + * one request in this file the rule cannot reach. */ export class DockerClient { private readonly docker: Dockerode; @@ -27,6 +326,15 @@ export class DockerClient { // `socketPath` accepts a Unix socket (`/var/run/docker.sock`) as well as a // Windows named pipe (`//./pipe/docker_engine`) in development. this.docker = new Dockerode({ socketPath: config.docker.socket }); + + boundEveryRequest(this.docker, { + // Logged as well as thrown, because several callers swallow the throw on + // purpose — `containerExists` treats any failure as "no container", + // `explainExit` gives up on explaining, `removeIfExists` expects to fail — + // and a node whose Docker has stopped answering would otherwise show only + // its consequences. + onAbandoned: (message) => this.logger.warn({ socket: config.docker.socket }, message), + }); } get api(): Dockerode { @@ -115,17 +423,7 @@ export class DockerClient { try { const stream = await this.docker.pull(image); - await new Promise((resolve, reject) => { - this.docker.modem.followProgress( - stream, - (error: Error | null) => (error ? reject(error) : resolve()), - (event: { status?: string; progress?: string }) => { - if (onProgress && event.status) { - onProgress(event.progress ? `${event.status} ${event.progress}` : event.status); - } - }, - ); - }); + await this.followPull(stream, onProgress); } catch (error: unknown) { // Docker's "denied" says neither which image nor why. On an image absent // from a public registry it nearly always means it was never published — @@ -141,6 +439,97 @@ export class DockerClient { } } + /** + * Consumes a pull's progress stream, and gives up on one that has stopped. + * + * The request that opens the pull is bounded like every other question put to + * Docker; this bounds what comes down it afterwards, which no rule about + * answering could. `followProgress` wrapped in a bare promise has no timeout + * of any kind, and the shape of the failure is worth being exact about: a + * registry that accepts the connection and then stops sending never ends the + * stream, so the completion callback is never invoked and this promise never + * settles. The caller — an installation — is then blocked on a line that + * cannot return, which puts a server in `installing` for ever without any + * deadline further down ever being armed. It is the same hang as an unbounded + * `container.wait`, one line earlier. + * + * Bounded on the same principle as the installation itself: on **inactivity**, + * not on duration. A pull that is receiving layers is alive however big the + * image is, and a total-duration cap would break exactly the large images + * worth pulling. Every progress event pushes the deadline back, and Docker + * emits one per chunk of every layer — several a second on a transfer that is + * moving at all — so this needs no counters of its own to tell a slow pull + * from a dead one. + * + * The stream is destroyed on expiry rather than merely abandoned: the socket + * to the registry would otherwise stay open for the life of the daemon, and + * `followProgress` would still be holding a reference to it. + */ + private followPull( + stream: NodeJS.ReadableStream, + onProgress?: (line: string) => void, + ): Promise { + return new Promise((resolve, reject) => { + let timer: NodeJS.Timeout | null = null; + let settled = false; + + const settle = (error: Error | null): void => { + if (settled) { + return; + } + + settled = true; + + if (timer !== null) { + clearTimeout(timer); + timer = null; + } + + if (error) { + reject(error); + } else { + resolve(); + } + }; + + const extend = (): void => { + if (timer !== null) { + clearTimeout(timer); + } + + timer = setTimeout(() => { + (stream as NodeJS.ReadableStream & { destroy?: () => void }).destroy?.(); + settle( + new Error( + `the registry stopped sending after ${PULL_STALL_TIMEOUT_MS / 1000}s and the ` + + 'download was abandoned', + ), + ); + }, PULL_STALL_TIMEOUT_MS); + // Never a reason for hopperd to stay alive: a daemon being shut down + // mid-pull has stopped caring how the pull ends. + timer.unref(); + }; + + extend(); + + this.docker.modem.followProgress( + stream, + // Destroying the stream above makes this fire again with an error of its + // own; `settle` ignores it, so the console keeps the reason that came + // first rather than "premature close". + (error: Error | null) => settle(error), + (event: { status?: string; progress?: string }) => { + extend(); + + if (onProgress && event.status) { + onProgress(event.progress ? `${event.status} ${event.progress}` : event.status); + } + }, + ); + }); + } + /** * Attaches to a container's input/output stream, without going through * dockerode. @@ -162,8 +551,23 @@ export class DockerClient { * * So the upgrade request is issued here, with `Content-Length: 0`: no byte * precedes the stream, stdin is clean from the first second. + * + * **The one request in this file {@link boundEveryRequest} cannot reach**, for + * exactly that reason: it never touches dockerode, so it carries its own bound + * and this is it. The bound covers the handshake and nothing after it — the + * timer is cleared the moment Docker upgrades the connection, and the console + * stream it hands back is then as unbounded as every other stream here. + * + * Deliberately a timer of this file's own rather than `request.setTimeout`. + * That sets an *inactivity* timeout on the socket, and the socket survives the + * upgrade: a Minecraft server that says nothing for a minute would have had + * its console torn down by the very guard meant to stop the daemon hanging. */ - attachToContainer(containerName: string): Promise { + attachToContainer( + containerName: string, + /** Overridden only by the tests, which cannot wait a minute to prove this. */ + timeoutMs: number = DOCKER_ANSWER_TIMEOUT_MS, + ): Promise { const query = 'stream=1&stdin=1&stdout=1&stderr=1'; return new Promise((resolve, reject) => { @@ -178,12 +582,33 @@ export class DockerClient { }, }); - request.on('upgrade', (_response, socket: Duplex) => resolve(socket)); - request.on('error', reject); + const timer = setTimeout(() => { + // Destroyed with the reason, so the `error` handler below rejects with + // this rather than with the socket error the destruction produces. + request.destroy( + new DockerUnansweredError( + `Docker did not answer the attach to ${containerName} within ` + + `${Math.round(timeoutMs / 1000)}s. This node's Docker is not answering.`, + ), + ); + }, timeoutMs); + + timer.unref(); + + request.on('upgrade', (_response, socket: Duplex) => { + clearTimeout(timer); + resolve(socket); + }); + + request.on('error', (error) => { + clearTimeout(timer); + reject(error); + }); // Docker refuses the attach if the container does not exist: the answer // is then a real HTTP response, not an upgrade. request.on('response', (response) => { + clearTimeout(timer); reject( new Error( `Attach refused by Docker (HTTP ${response.statusCode ?? 0}) for ${containerName}.`, diff --git a/apps/daemon/src/server/disk-usage.spec.ts b/apps/daemon/src/server/disk-usage.spec.ts index 70bab64..57d9f5a 100644 --- a/apps/daemon/src/server/disk-usage.spec.ts +++ b/apps/daemon/src/server/disk-usage.spec.ts @@ -3,7 +3,7 @@ import { mkdir, mkdtemp, rm, symlink, writeFile } from 'node:fs/promises'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; import { afterEach, beforeEach, describe, expect, it } from 'vitest'; -import { directorySize } from './disk-usage.js'; +import { directorySize, formatBytes, freeSpaceBytes, usableSpace } from './disk-usage.js'; /** * Synchronous probe at module level: `it.runIf` is evaluated when the tests are @@ -80,3 +80,87 @@ describe('directorySize', () => { }, ); }); + +/** + * What the install preflight reads before it lets a download begin. + * + * The measurement has to be of the filesystem the volume is really on, which is + * why it takes a path rather than assuming the daemon's root: `dataDirectory` + * can sit on a different disk, and an operator who gave a server its own mount + * deserves that mount checked. + */ +describe('freeSpaceBytes', () => { + let sandbox: string; + + beforeEach(async () => { + sandbox = await mkdtemp(join(tmpdir(), 'hopper-free-')); + }); + + afterEach(async () => { + await rm(sandbox, { recursive: true, force: true }); + }); + + it('reads the free space of the filesystem a path is on', async () => { + const free = await freeSpaceBytes(sandbox); + + expect(free).not.toBeNull(); + // Any machine that can check out this repository has a megabyte spare; the + // figure itself is the host's business, not this test's. + expect(free).toBeGreaterThan(1024 * 1024); + }); + + // Not knowing must not be a refusal: an exotic filesystem `statfs` cannot + // describe would otherwise make every installation on that node impossible. + it('answers null rather than throwing when the question cannot be answered', async () => { + expect(await freeSpaceBytes(join(sandbox, 'never-created', 'deeper'))).toBeNull(); + }); +}); + +/** + * Which of the two free-block figures `statfs` offers is the one that gets + * spent. + * + * Asked of the answer rather than of a path, because no real filesystem can be + * made to demonstrate the difference on demand: on a machine that can check out + * this repository `bavail` and `bfree` are both simply large, so a test against + * a real directory passes whichever field the code reads. + */ +describe('usableSpace', () => { + /** + * `bfree` is every free block; `bavail` is every free block an unprivileged + * process may have. The difference is what the filesystem holds back for root + * — five percent of an ext4 by default, which on a 2 TB volume is a hundred + * gigabytes — and hopperd runs as root, so `bfree` really is space it can + * write into. Those blocks are the margin that keeps a full machine + * repairable, and spending them on a game server's install is how a full disk + * becomes an unrecoverable one. + */ + it('leaves the blocks a filesystem reserves for root out of the figure', () => { + expect(usableSpace({ bsize: 4096, bavail: 1_000, bfree: 1_250 })).toBe(4_096_000); + }); + + /** + * An answer arithmetic cannot use reads as not knowing rather than as a + * quantity. Handed to the preflight as free space, either of these would let + * an installation start on a node with nothing left. + */ + it.each([ + ['a product too large to be a number', { bsize: Number.MAX_VALUE, bavail: Number.MAX_VALUE }], + ['a negative count', { bsize: 4096, bavail: -1 }], + ])('answers null for %s', (_name, answer) => { + expect(usableSpace({ ...answer, bfree: answer.bavail })).toBeNull(); + }); +}); + +describe('formatBytes', () => { + it('scales to the unit an operator would use', () => { + expect(formatBytes(512)).toBe('512 B'); + expect(formatBytes(1024 ** 2)).toBe('1 MiB'); + expect(formatBytes(8 * 1024 ** 3)).toBe('8 GiB'); + expect(formatBytes(1024 ** 5)).toBe('1 PiB'); + }); + + it('keeps one decimal for a figure that is not round', () => { + expect(formatBytes(1536 * 1024 * 1024)).toBe('1.5 GiB'); + }); +}); diff --git a/apps/daemon/src/server/disk-usage.ts b/apps/daemon/src/server/disk-usage.ts index 5174a32..33731ff 100644 --- a/apps/daemon/src/server/disk-usage.ts +++ b/apps/daemon/src/server/disk-usage.ts @@ -1,4 +1,4 @@ -import { lstat, readdir } from 'node:fs/promises'; +import { lstat, readdir, statfs } from 'node:fs/promises'; import { join } from 'node:path'; /** @@ -55,3 +55,77 @@ export async function directorySize(root: string): Promise { return total; } + +/** + * The usable part of what `statfs` answered, or `null` if it answered nothing + * usable. + * + * **`bavail` and not `bfree`, and that choice is the whole content of this + * function.** The two differ by the blocks a filesystem reserves for root — five + * percent of an ext4 by default, which on a 2 TB volume is a hundred gigabytes — + * and hopperd runs as root, so `bfree` really is space it can write into. That + * is exactly why it must not: those blocks are the margin that keeps a full + * machine repairable, and an operator logging in to delete something needs the + * shell, the log and the package manager to still work. Spending them on a game + * server's install is how a full disk becomes an unrecoverable one. + * + * Separated from the `statfs` call below for the one reason that matters: no + * real filesystem can be made to demonstrate the difference on demand, so a test + * against a real path passes whichever field is read. Given the answer instead, + * a test can fail on the one-character change that gives a node's reserve away. + * + * `null` for an answer arithmetic cannot use. Some filesystems report block + * counts whose product overflows into `Infinity`, and a few report nonsense + * outright; handed to the preflight as free space, either would let an + * installation start on a node with nothing left, which is the one thing that + * check exists to prevent. + */ +export function usableSpace(stats: { + bavail: number; + bfree: number; + bsize: number; +}): number | null { + const free = stats.bavail * stats.bsize; + + return Number.isFinite(free) && free >= 0 ? free : null; +} + +/** + * Space left on the filesystem a path lives on. + * + * `null` rather than a throw when the question cannot be answered — an exotic + * filesystem, a path that has just gone. The caller decides what to do about not + * knowing, and refusing every installation on a node whose `statfs` returns + * something unexpected is not it. See {@link usableSpace} for which figure is + * read out of the answer, and why it is the smaller of the two on offer. + */ +export async function freeSpaceBytes(path: string): Promise { + try { + return usableSpace(await statfs(path)); + } catch { + return null; + } +} + +/** + * Bytes as an operator reads them. + * + * The panel has its own copy of this over `bigint`, and the two are deliberately + * not shared: this one exists to put figures in a console line the daemon writes + * at the moment it refuses something, and a shared helper would drag the panel's + * dependency graph into hopperd for eight lines of arithmetic. + */ +export function formatBytes(bytes: number): string { + const units = ['B', 'KiB', 'MiB', 'GiB', 'TiB', 'PiB']; + let value = Math.max(0, bytes); + let unit = 0; + + while (value >= 1024 && unit < units.length - 1) { + value /= 1024; + unit += 1; + } + + // One decimal, and none at all on a whole number: "1 GiB" reads as a limit + // somebody chose, "1.0 GiB" as a measurement that happened to land there. + return `${Number.isInteger(value) ? value : value.toFixed(1)} ${units[unit]}`; +} diff --git a/apps/daemon/src/server/installer.spec.ts b/apps/daemon/src/server/installer.spec.ts index 1671688..62b6595 100644 --- a/apps/daemon/src/server/installer.spec.ts +++ b/apps/daemon/src/server/installer.spec.ts @@ -1,13 +1,68 @@ +import { EventEmitter } from 'node:events'; +import { mkdir, mkdtemp, readdir, rm, writeFile } from 'node:fs/promises'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; import { serverConfigurationSchema, type ServerConfiguration } from '@hopper/shared'; import type Dockerode from 'dockerode'; -import { describe, expect, it } from 'vitest'; +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { DockerUnansweredError } from '../docker/client.js'; +import type { DockerClient } from '../docker/client.js'; import { + activitySamplePeriod, + ActivityWatchdog, + ContainerActivityProbe, + describeDuration, + describeStall, + diskRefusal, + dockerDeadline, installContainerName, installCreateOptions, installHostConfig, reclaimCreateOptions, reclaimHostConfig, + runInstallation, + INSTALL_FREE_SPACE_FLOOR_BYTES, } from './installer.js'; +import type * as DiskUsage from './disk-usage.js'; +import type { DockerStats } from './stats.js'; + +/** + * What Docker sends for a container that exists and is doing nothing. + * + * Present and constant, not empty. An empty body means the host keeps no + * such counter at all, which `activityCounters` answers `null` to — so a + * fake that sent one could never represent a container standing still, and + * a stall could never be observed. + */ +const IDLE_COUNTERS: DockerStats = { cpu_stats: { cpu_usage: { total_usage: 0 } } }; + +/** + * The one answer no real filesystem can be asked for. + * + * `freeSpaceBytes` returns `null` for a filesystem Node cannot describe, and the + * preflight's response to that — install anyway, and say so — is a decision + * about a case that cannot be arranged on the machine running these tests. Every + * other test in this file goes through to the real thing, which is why this is a + * hook rather than a mock: the disk assertions below measure real directories on + * a real disk, and a fake `statfs` would quietly stop them proving anything. + */ +const disk = vi.hoisted(() => ({ + freeSpaceBytes: null as ((path: string) => Promise) | null, +})); + +vi.mock('./disk-usage.js', async (importOriginal) => { + const actual = await importOriginal(); + + return { + ...actual, + freeSpaceBytes: (path: string) => + disk.freeSpaceBytes === null ? actual.freeSpaceBytes(path) : disk.freeSpaceBytes(path), + }; +}); + +afterEach(() => { + disk.freeSpaceBytes = null; +}); const GIB = 1024 ** 3; @@ -265,11 +320,19 @@ describe('installHostConfig', () => { }); }); - // The server container gets a 128 MiB RAM-backed /tmp so it cannot fill the - // host's disk. Applying that here would break every egg that stages a modpack - // download in /tmp, and the layer is discarded seconds later in any case. - it('leaves /tmp on the container layer, unlike the server container', () => { - expect(config.Tmpfs).toBeUndefined(); + // A 512 MiB tmpfs was mounted on /tmp for one release, meant to stop a server + // owner filling the node's disk through the URL variable an install script + // reads. It could not: `WorkingDir` is /mnt/server, a bind mount with no quota + // of any kind, so the same script fills the node by downloading there instead. + // What the ceiling did reach was `curl -o /tmp/pack.zip && unzip` — the shape + // half the catalogue is written in — and, because tmpfs pages are charged to + // the container's own memory cgroup, a small plan's install turned into an + // unexplained code 137. It is not coming back by accident. + describe('the scratch directory', () => { + it('imposes no ceiling on /tmp it cannot also impose on the volume', () => { + expect(config.Tmpfs).toBeUndefined(); + expect(Object.hasOwn(config, 'Tmpfs')).toBe(false); + }); }); }); @@ -395,3 +458,2440 @@ describe('container create options', () => { expect(options.Cmd).toEqual(['chown', '-R', '988:988', '/mnt/server']); }); }); + +/** + * The deadline is on **inactivity**, not on duration and not on output. + * + * A forty-gigabyte download pulling bytes down a wire is alive; a container that + * has moved no traffic, touched no disk, burned no CPU and printed nothing for a + * quarter of an hour is not. A cap on total duration cannot tell those apart — + * high enough for a real Steam depot it never fires, low enough to be useful it + * kills working installs. + * + * Nor can a cap on *output*, which is the correction these tests exist to pin + * down: every script in this repository's own catalogue downloads with + * `curl -sSL`, and `-s` suppresses the progress meter, so a working transfer is + * indistinguishable from a dead one by output alone. The window is therefore + * pushed back by output **or** by the container's counters, and the tests below + * prove both directions of both. + */ +describe('ActivityWatchdog', () => { + const WINDOW_MS = 60_000; + + /** Only what the watchdog touches, so the clock cannot affect anything else. */ + const useClock = (): void => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + }; + + it('never fires while something keeps happening, however long the install takes', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => expect.unreachable()); + watchdog.arm(); + + // Ten minutes of installing, in a window sized for one. A download that is + // working is not one to give up on, whatever the total comes to. + for (let sign = 0; sign < 10; sign += 1) { + vi.advanceTimersByTime(WINDOW_MS - 1_000); + watchdog.noteActivity(); + } + + expect(watchdog.expiry).toBeNull(); + }); + + it('fires once nothing has happened for the window', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => undefined); + watchdog.arm(); + + vi.advanceTimersByTime(30_000); + watchdog.noteActivity(); + watchdog.noteObservation(); + vi.advanceTimersByTime(WINDOW_MS); + + // The console says how long nothing happened, not merely that something + // timed out: 60s of stillness out of 90s of installing is a different story + // from 60s out of 60s, and the operator is the one who has to tell them + // apart. + expect(watchdog.expiry).toEqual({ + idleMs: WINDOW_MS, + elapsedMs: 90_000, + sawActivity: true, + observed: true, + }); + }); + + /** + * Looking at the container is not the same as the container doing something, + * and reading a successful sample as a sign of life would switch this deadline + * off: the probe polls four times a window at the very least, so every window + * would be pushed back by the act of measuring it. + */ + it('is not pushed back by a sample that merely came back', () => { + useClock(); + + let expiries = 0; + const watchdog = new ActivityWatchdog(WINDOW_MS, () => { + expiries += 1; + }); + + watchdog.arm(); + + // Four looks across the window, each one seeing a container that has not + // moved. It still fires on time. + for (let look = 0; look < 4; look += 1) { + vi.advanceTimersByTime(WINDOW_MS / 4); + watchdog.noteObservation(); + } + + expect(expiries).toBe(1); + expect(watchdog.expiry).toMatchObject({ observed: true, idleMs: WINDOW_MS }); + }); + + /** + * The distinction the ownership reclaim depends on entirely, since the probe + * is its only witness: a window in which every `stats` request failed is not + * evidence that the container stood still, and the verdict has to be able to + * say so. + */ + it('reports a window it could not see into as one it could not see into', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => undefined); + watchdog.arm(); + vi.advanceTimersByTime(WINDOW_MS); + + expect(watchdog.expiry).toMatchObject({ observed: false }); + }); + + /** + * Evidence does not carry over a window. A container watched perfectly well + * for an hour and then lost sight of for the window that expired is one this + * daemon cannot vouch for, and saying otherwise would put the operator back to + * looking at their install script. + */ + it('does not carry evidence from an earlier window into the one that expired', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => undefined); + watchdog.arm(); + + watchdog.noteObservation(); + vi.advanceTimersByTime(30_000); + // Movement starts a fresh window, and nothing has been seen in it. + watchdog.noteActivity(); + + vi.advanceTimersByTime(WINDOW_MS); + + expect(watchdog.expiry).toMatchObject({ sawActivity: true, observed: false }); + }); + + it('says so when the installation never did anything at all', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => undefined); + watchdog.arm(); + vi.advanceTimersByTime(WINDOW_MS); + + expect(watchdog.expiry).toMatchObject({ sawActivity: false, idleMs: WINDOW_MS }); + }); + + // A container being torn down produces both kinds of signal: the shell's dying + // words, and the traffic of its own removal. Neither must read as a reprieve + // for an installation whose verdict has already been passed and reported. + it('cannot be revived by anything arriving after it gave up', () => { + useClock(); + + let expiries = 0; + const watchdog = new ActivityWatchdog(WINDOW_MS, () => { + expiries += 1; + }); + + watchdog.arm(); + vi.advanceTimersByTime(WINDOW_MS); + + watchdog.noteActivity(); + vi.advanceTimersByTime(WINDOW_MS * 10); + + expect(expiries).toBe(1); + expect(watchdog.expiry).not.toBeNull(); + }); + + it('stops counting once the installation has ended', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => expect.unreachable()); + watchdog.arm(); + watchdog.disarm(); + + vi.advanceTimersByTime(WINDOW_MS * 10); + + expect(watchdog.expiry).toBeNull(); + }); + + /** + * And it stays stood down, which is a separate guarantee from never having + * fired. + * + * A deadline that stood down is one whose subject has finished, and the + * installation's own does exactly that before the ownership reclaim begins. + * Output keeps arriving across that line — a container's last words reach an + * attach stream that is still open, and Docker flushes what it buffered — so a + * `noteActivity` that re-armed on them would put the deadline back up over a + * container that had already exited, to fire in the middle of the `chown -R` + * after it and announce that a finished installation was being given up on. + */ + it('is not put back up by a sign of life arriving after it stood down', () => { + useClock(); + + const watchdog = new ActivityWatchdog(WINDOW_MS, () => expect.unreachable()); + watchdog.arm(); + watchdog.disarm(); + watchdog.noteActivity(); + + vi.advanceTimersByTime(WINDOW_MS * 10); + + expect(watchdog.expiry).toBeNull(); + }); + + it('puts a duration on the console in the units an operator reads', () => { + expect(describeDuration(45_000)).toBe('45s'); + expect(describeDuration(1_800_000)).toBe('30m 0s'); + expect(describeDuration(4_320_000)).toBe('1h 12m'); + }); + + // "Timed out" invites the reply "it was downloading, your window is too + // short". The three things being measured, named, do not — and network + // traffic is deliberately not among them, so the console must not claim it. + it('names what it measured, so the verdict can be argued with', () => { + const lines = describeStall( + { idleMs: WINDOW_MS, elapsedMs: 90_000, sawActivity: true, observed: true }, + WINDOW_MS, + ).join('\n'); + + expect(lines).toContain('no output, no CPU, no disk I/O'); + expect(lines).not.toContain('network'); + expect(lines).toContain('installInactivityTimeoutMs'); + }); + + /** + * And it refuses to name figures nobody read. + * + * A window in which not one counter sample came back leaves this daemon with + * no evidence of anything: printing "no CPU, no disk I/O" would be asserting + * two numbers it never obtained, and it sends the operator to their install + * script when the thing that needs looking at is the Docker daemon on the + * node. + */ + it("blames this node's Docker when it could not read the counters at all", () => { + const lines = describeStall( + { idleMs: WINDOW_MS, elapsedMs: 90_000, sawActivity: true, observed: false }, + WINDOW_MS, + ).join('\n'); + + expect(lines).not.toContain('no output, no CPU, no disk I/O'); + expect(lines).toContain('has not reported the install container'); + expect(lines).toContain('may well have been running perfectly'); + }); +}); + +/** + * Reading the container's counters, which is the half that makes the deadline + * survive contact with a real install script. + */ +describe('ContainerActivityProbe', () => { + const useClock = (): void => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + }; + + afterEach(() => { + vi.useRealTimers(); + }); + + /** A container whose counters are whatever the test queues up next. */ + function sampler(samples: DockerStats[]) { + const taken: number[] = []; + + return { + taken, + sample: (): Promise => { + const index = Math.min(taken.length, samples.length - 1); + taken.push(index); + return Promise.resolve(samples[index]!); + }, + }; + } + + const withCpu = (nanos: number): DockerStats => ({ + cpu_stats: { cpu_usage: { total_usage: nanos } }, + }); + + /** + * What the deadline is told, counted the way the deadline distinguishes it. + * + * `reports` is every sample that came back — the probe's answer to "could you + * look" — and `movements` the subset that had moved. A failed sample shows up + * as neither, which is the distinction the ownership reclaim rests on. + */ + function counting() { + const counts = { reports: 0, movements: 0 }; + + return { + counts, + onSample: (moved: boolean): void => { + counts.reports += 1; + + if (moved) { + counts.movements += 1; + } + }, + }; + } + + it('reports a container whose CPU counter has moved', async () => { + useClock(); + + const seen = counting(); + const feed = sampler([withCpu(1_000), withCpu(2_000)]); + const probe = new ContainerActivityProbe(feed.sample, seen.onSample, 5_000); + + probe.start(); + // The baseline is taken at once; only the second sample can show movement. + await vi.advanceTimersByTimeAsync(0); + expect(seen.counts.movements).toBe(0); + + await vi.advanceTimersByTimeAsync(5_000); + expect(seen.counts.movements).toBe(1); + + probe.stop(); + }); + + /** + * A container running nothing and writing nothing is the whole case: a + * repeated sample must never look like progress, or the deadline it feeds + * would never fire on anything. + * + * Counted rather than asserted from inside the callback, and that is the + * correction. This test used to pass `expect.unreachable()` as the callback, + * which the probe called inside a `try` with an empty `catch`, from a `poll` + * nobody awaited: the failure was swallowed twice over and the test could not + * fail however wrong the code became. + * + * Every one of those samples is still *reported*, and that is the second half + * of the guarantee: the deadline has to know it was looked at, or it cannot + * tell this container from one Docker refuses to describe. + */ + it('reports nothing while every counter stands still', async () => { + useClock(); + + const seen = counting(); + const probe = new ContainerActivityProbe( + sampler([withCpu(1_000)]).sample, + seen.onSample, + 5_000, + ); + + probe.start(); + await vi.advanceTimersByTimeAsync(60_000); + probe.stop(); + + expect(seen.counts.movements).toBe(0); + expect(seen.counts.reports).toBeGreaterThan(0); + }); + + // Each of the two covers a way of being busy the other misses: a download + // whose writes are still in the page cache has touched no disk, and a copy + // waiting on a slow one spends almost none of its time on a CPU. + it.each<[string, DockerStats]>([ + ['CPU', { cpu_stats: { cpu_usage: { total_usage: 5 } } }], + ['block I/O', { blkio_stats: { io_service_bytes_recursive: [{ op: 'read', value: 8 }] } }], + ])('reports movement on %s alone', async (_name, moved) => { + useClock(); + + const seen = counting(); + // The baseline has to be readable: an empty body means "this host keeps no + // such counter", so there would be nothing for the second sample to differ + // from and the movement could not be seen. + const feed = sampler([IDLE_COUNTERS, moved]); + const probe = new ContainerActivityProbe(feed.sample, seen.onSample, 5_000); + + probe.start(); + await vi.advanceTimersByTimeAsync(5_000); + probe.stop(); + + expect(seen.counts.movements).toBe(1); + }); + + /** + * The counter that is deliberately not read, at the level that reads them. + * + * `rx_bytes` climbing on its own is a container being flooded the bridge's + * broadcast ARP, or a socket sending keepalives to a mirror that stopped + * answering. Neither is work, and treating either as a sign of life is what + * kept a stalled install alive for ever on a busy node. + */ + it('reports nothing for a container whose only movement is on the wire', async () => { + useClock(); + + let received = 0; + const seen = counting(); + const probe = new ContainerActivityProbe( + () => + Promise.resolve({ networks: { eth0: { rx_bytes: (received += 9_000), tx_bytes: 60 } } }), + seen.onSample, + 5_000, + ); + + probe.start(); + await vi.advanceTimersByTimeAsync(60_000); + probe.stop(); + + expect(seen.counts.movements).toBe(0); + }); + + /** + * A Docker that will not answer must not be able to keep an install alive. + * Treating a failed sample as a sign of life would reintroduce the unbounded + * wait from the other side — a wedged daemon would be the thing holding the + * deadline open. + * + * **Nor is it evidence the container stood still**, which is the other half and + * the one the ownership reclaim depends on: nothing at all is reported, so a + * deadline whose only witness is this probe knows it was blind rather than + * believing it watched an idle container. + */ + it('says nothing at all about a sample it could not take', async () => { + useClock(); + + const seen = counting(); + const probe = new ContainerActivityProbe( + () => Promise.reject(new Error('Docker is not answering')), + seen.onSample, + 5_000, + ); + + probe.start(); + await vi.advanceTimersByTimeAsync(60_000); + probe.stop(); + + expect(seen.counts).toEqual({ reports: 0, movements: 0 }); + }); + + /** + * And it keeps sampling across one. + * + * A `stats` request Docker never answered used to leave this loop awaiting a + * promise that never settled: nothing was rescheduled, and one hiccup blinded + * the deadline for the rest of the installation. Every request `DockerClient` + * makes is bounded now, so a hung sample comes back as a rejection — and this + * pins the behaviour on that side of the boundary, that a rejection costs one + * sample and not the whole loop. + */ + it('carries on sampling after one that failed', async () => { + useClock(); + + let attempts = 0; + const seen = counting(); + const probe = new ContainerActivityProbe( + () => { + attempts += 1; + return attempts === 2 + ? Promise.reject(new Error('Docker did not answer')) + : Promise.resolve(withCpu(attempts * 1_000)); + }, + seen.onSample, + 5_000, + ); + + probe.start(); + await vi.advanceTimersByTimeAsync(15_000); + probe.stop(); + + expect(attempts).toBe(4); + // The baseline, the failure, and the two after it: three reports, and the + // last two moved. + expect(seen.counts).toEqual({ reports: 3, movements: 2 }); + }); + + /** + * The tolerance covers the **sample**, and stops there. + * + * Docker refusing to answer is this node's business and is swallowed on + * purpose. A movement callback that throws is a defect in this daemon, and one + * `catch` around both hid it completely — which is how the two tests above + * came to be written as `expect.unreachable()` callbacks that could not fail + * however wrong the probe became. Widening that `catch` back over the callback + * is a one-line change that restores exactly the old silence, so it is pinned + * here rather than left to the comment. + * + * Driven a poll at a time, because that is where the guarantee lives: the + * probe is not started, so nothing is rescheduled and the escape is the + * returned promise rather than an unhandled rejection landing wherever the + * runner happens to notice it. + */ + it('lets a movement callback that throws escape, instead of swallowing it', async () => { + const feed = sampler([withCpu(1_000), withCpu(2_000)]); + const probe = new ContainerActivityProbe( + feed.sample, + (moved) => { + if (moved) { + throw new Error('noteActivity is broken'); + } + }, + 5_000, + ); + + const poll = (probe as unknown as { poll: () => Promise }).poll.bind(probe); + + // The baseline can never report movement, so this callback stays quiet. + await expect(poll()).resolves.toBeUndefined(); + + await expect(poll()).rejects.toThrow('noteActivity is broken'); + }); + + /** + * Each sample is a round trip to the Docker socket, on a node that may be + * running an installation for every server on it. A second `start` opening a + * second sampling loop would double that for the life of the installation — + * and `stop` only ever cancels the timer it can see, so the surplus loop would + * outlive the container it was watching. + */ + it('does not open a second sampling loop when started twice', async () => { + useClock(); + + const feed = sampler([withCpu(1), withCpu(2), withCpu(3)]); + const probe = new ContainerActivityProbe(feed.sample, () => undefined, 5_000); + + probe.start(); + probe.start(); + await vi.advanceTimersByTimeAsync(5_000); + probe.stop(); + + // One baseline and one sample, not two of each. + expect(feed.taken.length).toBe(2); + }); + + it('stops sampling when told to', async () => { + useClock(); + + const feed = sampler([withCpu(1), withCpu(2), withCpu(3)]); + const probe = new ContainerActivityProbe(feed.sample, () => undefined, 5_000); + + probe.start(); + await vi.advanceTimersByTimeAsync(5_000); + + const taken = feed.taken.length; + probe.stop(); + await vi.advanceTimersByTimeAsync(60_000); + + expect(feed.taken.length).toBe(taken); + }); + + /** + * The period is a poll, so it has a resolution; the window is a deadline, so + * it has a meaning. A template naming a window comparable to the default + * period would otherwise be a coin toss on whether a sample landed inside it. + */ + it('samples often enough for whatever window a template chooses', () => { + expect(activitySamplePeriod(15 * 60_000)).toBe(15_000); + expect(activitySamplePeriod(20_000)).toBe(5_000); + // The shortest window the guarantee still holds for: four seconds, sampled + // every one, so three samples after the baseline land inside it. + expect(activitySamplePeriod(4_000)).toBe(1_000); + }); + + /** + * Below four seconds the floor wins and the guarantee does not hold, which is + * a decision rather than an oversight — the comment on `activitySamplePeriod` + * used to claim both at once. + * + * A two-second window would need a poll every half second: one round trip to + * the Docker socket twice a second, per installation, on a node that may be + * running one for every server on it — to measure something no install can be + * judged on anyway. A container that pauses for two seconds is a container + * between two syscalls, and a deadline that fires on that fires on healthy + * work whatever the sampling rate. So the polling stays affordable and the + * window is the thing that is wrong. + */ + it('will not poll faster than its floor for a window nothing could measure', () => { + expect(activitySamplePeriod(2_000)).toBe(1_000); + expect(activitySamplePeriod(1)).toBe(1_000); + }); +}); + +/** + * The bound on **Docker answering**, as opposed to the one on the container + * working. + * + * One of these objects bounds several calls in a row — a teardown and then the + * removal after it; a reclaim's create, its start and its own removal — so it + * has to survive having fired. That is what the first version could not do: it + * built one rejected promise for the whole of its life, and a promise that has + * rejected stays rejected, so after the deadline had fired once every later race + * against it was lost the instant it started. A single wedge anywhere in an + * installation then reported a perfectly healthy Docker as an unanswering one, + * for every bounded call that came after. + */ +describe('dockerDeadline', () => { + const TIMEOUT_MS = 60_000; + + const useClock = (): void => { + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + }; + + /** A Docker that has taken the request and gone quiet. */ + const unanswered = (): Promise => new Promise(() => undefined); + + /** A Docker that answers, eventually. */ + const answersIn = (ms: number): Promise => + new Promise((resolve) => { + setTimeout(() => resolve('answered'), ms); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it('does not fire before it is armed, however long the call takes', async () => { + useClock(); + + const deadline = dockerDeadline(TIMEOUT_MS, 'Docker did not answer.'); + let rejection: unknown = null; + deadline.reached.catch((error: unknown) => (rejection = error)); + + await vi.advanceTimersByTimeAsync(TIMEOUT_MS * 10); + + expect(rejection).toBeNull(); + }); + + it('stops bounding a call that came back', async () => { + useClock(); + + const deadline = dockerDeadline(TIMEOUT_MS, 'Docker did not answer.'); + let rejection: unknown = null; + deadline.reached.catch((error: unknown) => (rejection = error)); + + deadline.arm(); + deadline.disarm(); + + await vi.advanceTimersByTimeAsync(TIMEOUT_MS * 10); + + expect(rejection).toBeNull(); + }); + + /** + * The whole sequence a single-use deadline gets wrong: arm, expire, disarm, + * arm again — and the call under the second arming has to be allowed to + * succeed. + */ + it('bounds a second call after a first one has expired', async () => { + useClock(); + + const deadline = dockerDeadline(TIMEOUT_MS, 'Docker did not answer.'); + + // The expectation is attached before the clock moves, here and below, + // because a rejection nobody is listening to yet is one Node reports as + // unhandled — an error in the run that says nothing about the code. + deadline.arm(); + const first = expect(Promise.race([unanswered(), deadline.reached])).rejects.toThrow( + /Docker did not answer/, + ); + await vi.advanceTimersByTimeAsync(TIMEOUT_MS + 1); + await first; + deadline.disarm(); + + // The next call, against a Docker that answers in a second. Held over the + // spent promise this loses its race before Docker has said anything at all, + // and a node that is working is reported as one that has stopped. + // + // A call that answers *later* rather than one already resolved, because + // `Promise.race` settles in subscription order among promises that are + // already settled: an immediate answer would win against a rejected deadline + // whatever this function did, and the test would prove nothing. + deadline.arm(); + const second = expect(Promise.race([answersIn(1_000), deadline.reached])).resolves.toBe( + 'answered', + ); + await vi.advanceTimersByTimeAsync(1_000); + await second; + deadline.disarm(); + + // And still a deadline afterwards, rather than one that has quietly stopped + // being able to fire. + deadline.arm(); + const third = expect(Promise.race([unanswered(), deadline.reached])).rejects.toThrow( + /Docker did not answer/, + ); + await vi.advanceTimersByTimeAsync(TIMEOUT_MS + 1); + await third; + }); + + /** + * Each call gets the whole window rather than whatever the last one left of + * it. Arming used to return early while a timer was pending, so a teardown + * armed at the stall and a removal armed a minute later shared one clock — and + * the removal's bound could be anything from the full window down to nothing. + */ + it('gives each call its own clock', async () => { + useClock(); + + const deadline = dockerDeadline(TIMEOUT_MS, 'Docker did not answer.'); + + deadline.arm(); + await vi.advanceTimersByTimeAsync(TIMEOUT_MS - 1_000); + + // A second call, armed with a second left on the first arming's clock. + deadline.arm(); + const second = Promise.race([unanswered(), deadline.reached]); + let rejection: unknown = null; + second.catch((error: unknown) => (rejection = error)); + + await vi.advanceTimersByTimeAsync(2_000); + expect(rejection).toBeNull(); + + await vi.advanceTimersByTimeAsync(TIMEOUT_MS); + await expect(second).rejects.toThrow(/Docker did not answer/); + }); +}); + +/** + * There is no disk check anywhere in the daemon until this one. + * + * A depot larger than the node's free space fills the host disk, and that takes + * down every server on the machine — one of the standard ways to brick a node. + */ +describe('the disk preflight', () => { + const GIB_BYTES = 1024 ** 3; + + const refusalFor = (options: { + freeBytes: number; + reclaimableBytes?: number; + declaredBytes?: number; + }) => + diskRefusal({ + freeBytes: options.freeBytes, + reclaimableBytes: options.reclaimableBytes ?? 0, + declaredBytes: options.declaredBytes, + path: VOLUME, + }); + + it('says nothing when there is room', () => { + expect(refusalFor({ freeBytes: 80 * GIB_BYTES, declaredBytes: 40 * GIB_BYTES })).toBeNull(); + }); + + it('lets a template that says nothing install on any node with headroom', () => { + expect(refusalFor({ freeBytes: INSTALL_FREE_SPACE_FLOOR_BYTES })).toBeNull(); + }); + + // "Not enough disk space" leaves an operator to guess whether they need to + // free a gigabyte or forty, on which node, and off which filesystem. + it('names both figures and the filesystem they were read from', () => { + const refusal = refusalFor({ + freeBytes: 8 * GIB_BYTES, + declaredBytes: 40 * GIB_BYTES, + })?.lines.join('\n'); + + expect(refusal).toContain('8 GiB free on the filesystem holding'); + expect(refusal).toContain('40 GiB needed'); + expect(refusal).toContain(VOLUME); + expect(refusal).toContain('nothing has been changed'); + }); + + /** + * The half of the answer that is easy to leave out. `statfs` was given the + * volume's path, so what it measured is the filesystem the volume lives on — + * and an install script that stages its download in `/tmp` writes to the + * container's own layer, under Docker's storage, which is a *different* + * filesystem on every node whose operator has split the two. + * + * Docker's data root is deliberately not measured beside it: it is + * configurable and this daemon is not told where it is, and a refusal naming a + * figure read off the wrong disk is worse than one naming no figure at all. + */ + it.each([ + ['the floor', { freeBytes: 100 * 1024 * 1024 }], + ['a declared figure', { freeBytes: 8 * GIB_BYTES, declaredBytes: 40 * GIB_BYTES }], + ])( + 'says which filesystem it measured, and what it did not, when refusing on %s', + (_name, options) => { + const refusal = refusalFor(options)?.lines.join('\n'); + + expect(refusal).toContain(`The only filesystem measured is the one holding ${VOLUME}`); + expect(refusal).toContain('has not been checked'); + }, + ); + + it('explains the floor when no template named a figure', () => { + const refusal = refusalFor({ freeBytes: 100 * 1024 * 1024 })?.lines.join('\n'); + + expect(refusal).toContain('every server on it'); + expect(refusal).toContain('1 GiB needed'); + }); + + /** + * The attribution, which is the thing a refusal cannot get wrong. A template + * asking for less than the floor is refused *by the floor*, and saying "the + * figure comes from the template" there credits it with a number it never + * named — while suppressing the one sentence explaining where the number an + * operator is being asked to satisfy really came from. + */ + it('never credits a template with the floor it did not ask for', () => { + const refusal = refusalFor({ + freeBytes: 100 * 1024 * 1024, + declaredBytes: 200 * 1024 * 1024, + })?.lines.join('\n'); + + expect(refusal).not.toContain('comes from the template'); + expect(refusal).toContain('whatever it is installing'); + }); + + /** + * `build.diskBytes` is the obvious candidate and it is deliberately not an + * input here — the function cannot even see it. It is what the operator sells + * this server, not what its installation writes: a 50 GiB Minecraft plan that + * will use 900 MiB would start refusing to install on a node with 20 GiB free, + * which is every deliberately oversubscribed node in existence. The panel has + * already weighed that number once, at creation, against the node's declared + * capacity and the overallocation the operator chose. + */ + it('takes no notice of the server disk quota', () => { + expect(refusalFor({ freeBytes: 20 * GIB_BYTES })).toBeNull(); + }); + + /** + * A reinstall writes over what is already there, so those bytes count towards + * the requirement rather than against it. Demanding the whole figure as *free* + * space is how a 40 GiB Palworld server becomes impossible to reinstall on the + * node it is already installed on — a certain failure, traded for a possible + * one. + */ + describe('a reinstall over a volume that is already full of the game', () => { + it('counts what the volume holds towards the requirement', () => { + expect( + refusalFor({ + freeBytes: 5 * GIB_BYTES, + reclaimableBytes: 40 * GIB_BYTES, + declaredBytes: 40 * GIB_BYTES, + }), + ).toBeNull(); + }); + + // Where the shortfall is real, both halves of the sum are on the console: + // "45 GiB available" on a node with 5 GiB free is a figure nobody would + // believe without being told where the rest of it came from. + it('shows its working when the sum still falls short', () => { + const refusal = refusalFor({ + freeBytes: 5 * GIB_BYTES, + reclaimableBytes: 10 * GIB_BYTES, + declaredBytes: 40 * GIB_BYTES, + })?.lines.join('\n'); + + expect(refusal).toContain('5 GiB free'); + expect(refusal).toContain('10 GiB'); + expect(refusal).toContain('writes over'); + }); + + // The floor is the one figure the volume's contents cannot buy off. Those + // bytes are released as the new ones are written, file by file, so there is + // no moment at which the machine has them spare — and a node with nothing + // left is a node with nothing left whatever this one volume holds. + it('cannot buy its way under the floor with them', () => { + expect( + refusalFor({ + freeBytes: 100 * 1024 * 1024, + reclaimableBytes: 500 * GIB_BYTES, + declaredBytes: 40 * GIB_BYTES, + }), + ).not.toBeNull(); + }); + }); +}); + +/** + * The deadline and the preflight, wired to the thing they guard. + * + * Docker is faked; the filesystem is not, because the preflight has to measure a + * real one. + */ +describe('runInstallation', () => { + const WINDOW_MS = 60_000; + const workspaces: string[] = []; + + afterEach(async () => { + vi.useRealTimers(); + await Promise.all( + workspaces.splice(0).map((root) => rm(root, { recursive: true, force: true })), + ); + }); + + async function workspace(): Promise<{ volumePath: string; tmpPath: string }> { + const root = await mkdtemp(join(tmpdir(), 'hopper-install-')); + workspaces.push(root); + + return { volumePath: join(root, 'volume'), tmpPath: join(root, 'tmp') }; + } + + function installable(install: Record = {}): ServerConfiguration { + return serverConfigurationSchema.parse({ + uuid: UUID, + meta: { name: 'Survival' }, + invocation: 'java -jar server.jar', + allocations: { default: { ip: '0.0.0.0', port: 25565 } }, + build: { memoryBytes: 4 * GIB, swapBytes: 0, cpuPercent: 200, diskBytes: 10 * GIB }, + container: { image: 'eclipse-temurin:21-jre-noble' }, + stop: { type: 'command', value: 'stop' }, + install: { + containerImage: 'debian:bookworm-slim', + entrypoint: '/bin/bash', + script: 'echo installing', + ...install, + }, + }); + } + + /** + * How one of the fake's containers behaves. + * + * `stop` settles the wait with 137, as a real one does: the deadline firing + * has to be what ends the wait, or the test would prove nothing about a + * container being taken down. `wedged` takes that away — `stop`, `remove` and + * `wait` all stop answering together, which is what a broken overlay mount + * looks like from here. + * + * **A Docker that has stopped answering is presented the way `DockerClient` + * presents one, which is as a rejection rather than as a hang.** That is not a + * convenience: it is the boundary this file is on the far side of. Every + * request the client makes carries its own deadline — see `boundEveryRequest` + * — so an install container's `create`, `attach`, `start`, `stop` or `remove` + * that Docker ignores comes back to `runInstallation` as a + * {@link DockerUnansweredError} a minute later, and never as a promise that + * does not settle. The one call that really does hang is `wait`, because the + * client deliberately leaves it unbounded, and every `wedged` container below + * hangs on exactly that one. Whether the bound itself works is + * `client.spec.ts`'s question, asked of a real socket that never answers. + */ + interface FakeContainer { + wedged?: boolean; + /** + * A container Docker will not report the counters of, while answering + * everything else — the one input the ownership reclaim's deadline has. + */ + blind?: boolean; + failStart?: boolean; + /** + * A container that runs and exits perfectly well, and whose removal the + * node's Docker then refuses to answer — a wedged layer on an installation + * that otherwise worked. + */ + unremovable?: boolean; + /** + * A container Docker has already reaped: the removal answers 404, which is + * a race lost rather than a failure. + */ + gone?: boolean; + /** A wait that comes back without a `StatusCode` at all. */ + exitsWithNothing?: boolean; + /** + * A wait Docker answers with an error of its own — an API version that + * refuses the request, a proxy that mangles the body. Nothing to do with + * any deadline: none has fired, and the container may be running still. + */ + waitRefused?: boolean; + counters?: () => DockerStats; + /** + * The round trip this node's Docker takes and never answers, for the three + * that are Docker answering rather than a container working. + */ + unanswered?: 'create' | 'attach' | 'start'; + /** + * How long Docker takes to acknowledge the start, for the tests about what + * is covered while it thinks about it. Undefined is the ordinary case: an + * answer in the same turn. + */ + startsAfterMs?: number; + /** + * The code it exits with the moment it is started, or `null` for one the + * test settles itself. + */ + exitsWith?: number | null; + } + + /** How the fake's containers are named in the messages a wedged Docker sends. */ + + const SUBJECT = 'a-container'; + + /** + * A request this node's Docker takes and never answers, as `DockerClient` + * presents one. + * + * A rejection naming the endpoint, on the client's own deadline — never a + * promise that fails to settle, which is the shape this daemon no longer + * produces for anything but `container.wait()`. + */ + const unanswered = (request: string): Promise => + Promise.reject( + new DockerUnansweredError( + `Docker did not answer ${request} within 60s. This node's Docker is not answering: the ` + + 'request has been abandoned, and anything it had already begun may still be happening ' + + 'on this node.', + ), + ); + + function makeContainer(behaviour: FakeContainer, stream: EventEmitter) { + const calls = { + stops: 0, + removes: 0, + samples: 0, + grace: [] as unknown[], + /** Every `wait`, with the options it was given — the cancellation among them. */ + waits: [] as ({ abortSignal?: AbortSignal } | undefined)[], + }; + + let settle: (code: number) => void = () => undefined; + const exited = new Promise((resolve) => { + settle = resolve; + }); + + let announceStart: () => void = () => undefined; + const started = new Promise((resolve) => { + announceStart = resolve; + }); + + let announceAttach: () => void = () => undefined; + const attached = new Promise((resolve) => { + announceAttach = resolve; + }); + + /** + * What the container does once Docker says it is running. + * + * Deliberately not when it is *asked* to run: a start request Docker has not + * answered yet is a container that has not done anything, which is the whole + * subject of the ordering test below. + */ + const running = (): void => { + if (behaviour.exitsWith !== null && behaviour.exitsWith !== undefined) { + settle(behaviour.exitsWith); + } + }; + + const container = { + attach: () => { + announceAttach(); + return behaviour.unanswered === 'attach' + ? unanswered(`POST /containers/${SUBJECT}/attach`) + : Promise.resolve(stream); + }, + start: () => { + announceStart(); + + if (behaviour.unanswered === 'start') { + return unanswered(`POST /containers/${SUBJECT}/start`); + } + + if (behaviour.failStart) { + return Promise.reject(new Error('driver failed programming external connectivity')); + } + + if (behaviour.startsAfterMs === undefined) { + running(); + return Promise.resolve(); + } + + return new Promise((resolve) => { + setTimeout(() => { + running(); + resolve(); + }, behaviour.startsAfterMs); + }); + }, + // The one call the client leaves unbounded, so the one that can really + // hang: a wedged container's wait never settles. The options are kept + // because the cancellation is in them — a real `wait` this daemon walks + // away from without aborting is a socket to the Docker daemon that nothing + // will ever close, and the fake cannot show that by hanging. + wait: (waitOptions?: { abortSignal?: AbortSignal }) => { + calls.waits.push(waitOptions); + + if (behaviour.waitRefused) { + return Promise.reject( + new Error('(HTTP code 400) bad parameter - condition next-exit is not supported'), + ); + } + + return exited.then((StatusCode) => (behaviour.exitsWithNothing ? {} : { StatusCode })); + }, + stats: () => { + calls.samples += 1; + + // `blind` and `wedged` are separate on purpose: a broken overlay mount + // stops `stop`, `remove` and `wait` while `stats` answers perfectly, and + // the verdicts differ on exactly that. + return behaviour.blind + ? unanswered(`GET /containers/${SUBJECT}/stats`) + : // A container standing still still *reports*: the default is a + // counter that is present and constant, which is what a real + // Docker sends for an idle container. An empty body would mean + // something else entirely — a host that keeps no such counter — + // and `activityCounters` answers `null` to it, so a stall would + // never be observed and the deadline would never fire. + Promise.resolve(behaviour.counters?.() ?? IDLE_COUNTERS); + }, + stop: (stopOptions?: unknown) => { + calls.stops += 1; + calls.grace.push(stopOptions); + + if (behaviour.wedged) { + return unanswered(`POST /containers/${SUBJECT}/stop`); + } + + settle(137); + return Promise.resolve(); + }, + remove: () => { + calls.removes += 1; + + if (behaviour.gone) { + // Docker's own shape for it, `statusCode` and all, because that field + // is what `failureOf` reads to tell a lost race from a failure. + return Promise.reject( + Object.assign(new Error('(HTTP code 404) no such container'), { statusCode: 404 }), + ); + } + + if (calls.removes > 1) { + // **What a second `DELETE` for one container really gets**, and the + // reason the fake answers this rather than shrugging. A forced removal + // of a container carrying a modpack's layer takes real time on a real + // node, so a second request arriving behind it finds the first still + // running and is refused — and 409 is a code `failureOf` does not + // excuse, so it reaches the console as "it is still on this node" + // about a container that at that moment is being removed. Every + // stalled installation printed that line. A fake that accepted the + // duplicate quietly is how it went unnoticed. + return Promise.reject( + Object.assign( + new Error( + `(HTTP code 409) conflict - removal of container ${SUBJECT} is already in progress`, + ), + { statusCode: 409 }, + ), + ); + } + + return behaviour.wedged || behaviour.unremovable + ? unanswered(`DELETE /containers/${SUBJECT}`) + : Promise.resolve(); + }, + }; + + return { container, calls, started, attached, settle: (code: number) => settle(code) }; + } + + /** + * A Docker whose containers do exactly what the test tells them to. + * + * **Two** of them, because a successful installation runs two: the install + * container, and the `chown -R` that takes ownership of what it wrote. They + * are separate handles with separate call counts on purpose — one of the + * defects pinned down below is the install's deadline still counting while + * the second one runs, which a single shared container could not show. + * + * The reclaim exits 0 the moment it is started unless a test says otherwise, + * so every test that is not about it can ignore it entirely. + */ + function fakeDocker( + options: FakeContainer & { + /** + * The ownership reclaim's container: `never-created` for a Docker that + * takes the request and never answers, `refused` for one that answers with + * an error. + */ + reclaim?: FakeContainer | 'never-created' | 'refused'; + } = {}, + ) { + const created: Dockerode.ContainerCreateOptions[] = []; + + /** Whether the attach stream was closed, which no test could otherwise see. */ + const attachment = { destroyed: false }; + const stream = Object.assign(new EventEmitter(), { + destroy: () => { + attachment.destroyed = true; + }, + }); + + let announceRequest: () => void = () => undefined; + const requested = new Promise((resolve) => { + announceRequest = resolve; + }); + + const install = makeContainer({ ...options, exitsWith: null }, stream); + const reclaim = makeContainer( + { exitsWith: 0, ...(typeof options.reclaim === 'string' ? {} : options.reclaim) }, + stream, + ); + + const queue = [install.container, reclaim.container]; + + const docker = { + pullImage: () => Promise.resolve(), + api: { + createContainer: (createOptions: Dockerode.ContainerCreateOptions) => { + created.push(createOptions); + + if (created.length === 1) { + announceRequest(); + + if (options.unanswered === 'create') { + return unanswered('POST /containers/create'); + } + } + + if (created.length > 1) { + if (options.reclaim === 'never-created') { + return unanswered('POST /containers/create'); + } + + if (options.reclaim === 'refused') { + return Promise.reject(new Error('no such image: ghcr.io/pterodactyl/yolks:java_21')); + } + } + + const next = queue.shift(); + + if (!next) { + throw new Error('the fake was asked for a third container'); + } + + return Promise.resolve(next); + }, + getContainer: () => ({ + remove: () => Promise.reject(new Error('no such container')), + }), + }, + } as unknown as DockerClient; + + return { + docker, + created, + stream, + attachment, + calls: install.calls, + requested, + attached: install.attached, + started: install.started, + settle: install.settle, + reclaim, + }; + } + + it('stops and removes an install container that has stopped doing anything', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + await expect(running).rejects.toThrow(/did nothing for 1m 0s and was stopped/); + + // A deadline that gave up on *waiting* while leaving the container + // downloading would be worse than no deadline at all. + expect(fake.calls.stops).toBe(1); + expect(fake.calls.removes).toBeGreaterThanOrEqual(1); + + expect(lines.join('\n')).toContain('done nothing at all'); + expect(lines.join('\n')).toContain('installInactivityTimeoutMs'); + + // One container: the ownership reclaim belongs to an installation that + // succeeded. + expect(fake.created).toHaveLength(1); + }); + + /** + * **One removal, not two.** + * + * Two paths lead to the same `DELETE` here — `abandonContainer`, from the + * timer that gave up, and the ordinary teardown, the moment the wait came back + * — and for a while both took it. Docker refuses the loser of that race with + * 409 "removal already in progress", which `failureOf` does not excuse, so + * *every* stalled installation ended with a line saying the install container + * was still on the node, printed in the same breath as Docker was removing it. + * + * That is the worst kind of console line there is: it is not wrong about + * anything an operator can check later, it is wrong at the moment they read + * it, and the lesson they take from it is to stop believing the ones beside it + * — including "Docker would not stop the install container", which is how they + * would learn a modpack is still downloading into a volume nobody is watching. + * + * Excusing the 409 instead was the other way to silence it, and it was the + * wrong one: 409 is also what Docker answers when it refuses a removal for a + * reason worth printing, so excusing the code would have bought quiet on this + * path by going quiet on those too. The duplicate request is what was wrong, + * so the duplicate request is what went. + */ + it('removes an install container it gave up on exactly once', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + await expect(running).rejects.toThrow(/did nothing/); + + expect(fake.calls.removes).toBe(1); + + // And nothing on the console about a removal that failed, because none did. + expect(lines.join('\n')).not.toContain('would not remove'); + }); + + /** + * The socket the teardown used to walk away from. + * + * `container.wait()` is the one request `boundEveryRequest` deliberately + * leaves unbounded — it answers when the container ends, which for a *server* + * is its whole life — so when the teardown deadline wins the race, the wait it + * beat is abandoned and there is nothing else in the process that would ever + * close it. One socket to the Docker daemon per stalled installation, held + * until hopperd restarts, on the node that is by hypothesis already in + * trouble: exactly the leak the client's own deadline aborts its requests to + * avoid, arrived at through the one call the client cannot cover. + * + * What the daemon controls is the cancellation, which is what is asserted + * here. That `docker-modem` really tears the socket down when it is given one + * is asked of a real socket in `client.spec.ts`. + */ + it('closes the wait a teardown deadline walked away from', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ wedged: true }); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + + // The activity deadline gives up on a container that will never report an + // exit, and asks for a teardown a wedged Docker will not answer either. + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + expect(fake.calls.waits).toHaveLength(1); + const [waiting] = fake.calls.waits; + + // Not yet: the teardown deadline is a real window, and the container may + // still report an exit inside it. + expect(waiting?.abortSignal?.aborted).toBe(false); + + await vi.advanceTimersByTimeAsync(60_001); + + await expect(running).rejects.toThrow(/did not take the install container down/); + + expect(waiting?.abortSignal?.aborted).toBe(true); + }); + + /** + * The attach stream on a path where nothing else would close it. + * + * Docker holds this socket open for as long as anybody is on the end of it, + * and removing the container is what would normally close it — which on a + * wedged node is exactly the thing that did not happen. So the daemon closes + * it itself, from the `finally` that unwinds everything else this function + * armed. + */ + it('closes the attach stream even when the container is never removed', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ wedged: true }); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + expect(fake.attachment.destroyed).toBe(false); + + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + await vi.advanceTimersByTimeAsync(60_001); + + await expect(running).rejects.toThrow(/did not take the install container down/); + + expect(fake.attachment.destroyed).toBe(true); + }); + + /** + * A container's last words, on the path that throws before it can print them. + * + * Install scripts do not announce their failures in whole lines. `curl` writes + * `curl: (28) Operation timed out` with no trailing newline and the shell then + * hangs on whatever came next, so what the daemon is holding when the deadline + * fires is a partial line the {@link LineAssembler} is still waiting on. It is + * flushed from a `finally` for that reason: on this path the function is + * leaving through a throw, and the half-line it is holding is usually the only + * statement of why anything went wrong at all. + */ + it('prints what the container was part-way through saying when it gave up', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ wedged: true }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + + // No newline: the assembler holds this and emits nothing. + fake.stream.emit('data', Buffer.from('curl: (28) Operation timed out after 300000 ms')); + expect(lines.join('\n')).not.toContain('curl: (28)'); + + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + await vi.advanceTimersByTimeAsync(60_001); + + await expect(running).rejects.toThrow(/did not take the install container down/); + + expect(lines.join('\n')).toContain('curl: (28) Operation timed out'); + }); + + /** + * Nothing left ticking over a server whose installation is over. + * + * Three things are armed while an installation runs — the activity deadline, + * the counter probe and the teardown deadline — and each is stood down where + * it is finished with, which leaves the `finally` at the bottom covering the + * paths that never reach those lines. The teardown deadline is the one with no + * other symptom: it is armed from a timer, its rejection is already handled + * where it is created, and an arming left outstanding therefore produces + * nothing an assertion about output or exit codes could ever see. What it + * produces is a timer per stalled installation on a node running dozens. + */ + it('leaves nothing armed once a stalled installation is over', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + + // The deadline fires, the stop settles the wait, and the teardown deadline + // it armed a moment earlier is now an arming nobody is racing. + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + await expect(running).rejects.toThrow(/did nothing/); + + expect(vi.getTimerCount()).toBe(0); + }); + + it('never gives up on an installation that is still printing', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + + // Five windows' worth of downloading, and **not one complete line**: this is + // a carriage-return progress bar, which is how SteamCMD reports a depot. A + // deadline pushed back by assembled console lines rather than by the stream + // would see complete silence here and kill the download it exists to + // protect. + for (let chunk = 0; chunk < 5; chunk += 1) { + await vi.advanceTimersByTimeAsync(WINDOW_MS - 1_000); + fake.stream.emit('data', Buffer.from('\rUpdate state (0x61) downloading, progress: 41.62')); + } + + expect(fake.calls.stops).toBe(0); + + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + expect(fake.calls.stops).toBe(0); + }); + + /** + * The premise this whole guard nearly got wrong, proved end to end. + * + * Every install script in this repository downloads with `curl -sSL`, and `-s` + * suppresses the progress meter: a 2 GiB modpack on a slow uplink prints + * **nothing** from the first byte to the last. A deadline fed by output alone + * would kill it, and the window would then be exactly the total-duration cap + * the design set out to avoid, applied to the one step that legitimately takes + * hours. + */ + it('never gives up on a silent download whose container is doing the work', async () => { + const { volumePath, tmpPath } = await workspace(); + + let burned = 0; + let written = 0; + const fake = fakeDocker({ + // What a transfer looks like from the cgroup: every segment taken off the + // socket and put on a disk is CPU time charged to this container, and the + // writes reach the device eventually. + counters: () => ({ + cpu_stats: { cpu_usage: { total_usage: (burned += 30_000_000) } }, + blkio_stats: { + io_service_bytes_recursive: [{ op: 'write', value: (written += 4_000_000) }], + }, + }), + }); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + + // Ten windows of downloading and not one byte of output. + await vi.advanceTimersByTimeAsync(WINDOW_MS * 10); + + expect(fake.calls.stops).toBe(0); + expect(fake.calls.samples).toBeGreaterThan(1); + + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + }); + + /** + * And the other direction, which is what stops the counters from being a way + * of never firing: a container whose cgroup counters are frozen is not alive + * merely because its interface is still taking frames off the bridge. + * + * The rising `rx_bytes` is the point of the test. Every server on a node + * shares one bridge, a Linux bridge floods broadcast ARP to every port on it, + * and a `curl` still holding a socket to a mirror that went silent keeps + * sending TCP keepalives — so that counter climbs for a container that has + * stopped dead. While it was watched, this deadline never fired on a busy + * node: the original bug survived in the guard written to close it, on exactly + * the nodes where it cost the most. + */ + it('gives up on frozen cgroup counters however busy the interface looks', async () => { + const { volumePath, tmpPath } = await workspace(); + + let noise = 0; + const fake = fakeDocker({ + counters: () => ({ + cpu_stats: { cpu_usage: { total_usage: 5_000 } }, + blkio_stats: { io_service_bytes_recursive: [{ op: 'read', value: 8_192 }] }, + networks: { eth0: { rx_bytes: (noise += 1_500), tx_bytes: 120 } }, + }), + }); + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + await expect(running).rejects.toThrow(/did nothing/); + expect(fake.calls.stops).toBe(1); + }); + + /** + * The hang the deadline moved rather than removed. + * + * A wedged overlay mount makes `stop` fail, `remove` fail and + * `container.wait()` never return, all at once — so the daemon gave up on the + * install and then blocked for ever on the teardown, in the code written to + * stop it blocking for ever. A Docker that will not answer has to produce a + * failure, and one that names itself: the container may well still be running. + */ + it('fails rather than hangs when Docker will not take the container down', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ wedged: true }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + expect(fake.calls.stops).toBe(1); + + // Still waiting, because the teardown deadline has not come round yet: the + // bound is a real one and not merely an immediate give-up. + await vi.advanceTimersByTimeAsync(30_000); + + await vi.advanceTimersByTimeAsync(60_000); + + await expect(running).rejects.toThrow(/Docker did not take the install container down/); + + // And on the console, where the operator is already watching, rather than + // only in a status the panel renders afterwards. The container may well + // still be running on the node, which is not something to leave unsaid. + expect(lines.join('\n')).toContain('may still be running on it'); + }); + + /** + * The three round trips the rest of the guard cannot cover, once the bound + * over them has moved to where every bound now lives. + * + * Creating the container, attaching to its output and starting it are Docker + * answering, not a container working, and nothing armed in this file could + * unblock one: the activity deadline gives up by stopping and removing a + * container, and there is no container to stop until `createContainer` has + * come back. `DockerClient` bounds them along with every other request, so + * what is left to prove here is the half that is this file's own — that the + * failure fails the installation, and that it is said where whoever asked for + * it is already watching rather than only in the status the panel renders + * afterwards. `install()` holds the server's operation queue while it waits, + * so a failure that arrived only in hopperd's log would leave the operator + * with a spinner and no reason for it. + */ + it.each([ + ['create', 'requested', /\/containers\/create/], + ['attach', 'attached', /\/attach/], + ['start', 'started', /\/start/], + ] as const)( + 'fails and says so when Docker will not answer the %s', + async (call, signal, expected) => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ unanswered: call }); + const lines: string[] = []; + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + // The request reached the fake, which is what says the real filesystem + // work before it is done. + await fake[signal]; + + await expect(running).rejects.toThrow(expected); + + expect(lines.join('\n')).toContain("This node's Docker is not answering"); + expect(lines.join('\n')).toMatch(expected); + }, + ); + + /** + * The daemon's tmp, on the two failures that happen before anything owns the + * cleanup. + * + * The script is written into `tmp/install-` before the container is + * created, and the `finally` that removes it again only covers the block + * `createContainer` and `attach` sit *above*. So a Docker that refuses either + * of them — which is a Docker in trouble, and therefore a Docker that is about + * to be asked again — leaves that directory behind, and nothing ever comes + * back for it. Every retry against a wedged node leaves another, on the + * filesystem the node's own installations write into. + */ + it.each([ + ['create', 'requested'], + ['attach', 'attached'], + ] as const)( + 'leaves nothing in the daemon tmp when Docker refuses the %s', + async (call, signal) => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ unanswered: call }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake[signal]; + await expect(running).rejects.toThrow(DockerUnansweredError); + + // Not a vacuous assertion, and that is why it is written against the parent: + // `tmpPath` exists at all only because the daemon created `install-` + // underneath it, so a `readdir` that succeeds and finds nothing is the one + // reading that means the script directory was made and then cleared away. + await expect(readdir(tmpPath)).resolves.toEqual([]); + }, + ); + + /** + * The ordering of the two lines this guard turns on, pinned down. + * + * The deadline is armed **before** the container is told to run, so that a + * container is covered from the moment the request left rather than from + * whenever Docker got round to acknowledging it. Armed the other way round, a + * Docker taking half an hour over a start would hand the container that comes + * out of it a fresh window it has done nothing to earn — and the stretch + * nobody was watching is precisely the one where a node in trouble is at its + * slowest. + * + * The verdict is the one for a window nobody could see into, and that is right + * rather than incidental: there are no counters to read from a container + * Docker has not acknowledged the start of, so this daemon really has been + * unable to tell whether anything was happening — which is exactly what the + * message says. + */ + it('covers the container from the moment it was told to run', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ startsAfterMs: 30_000 }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: 20_000 }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + + // One window, entirely inside the stretch where Docker has the start request + // and has not answered it. Armed after the start, nothing has happened here + // at all. + await vi.advanceTimersByTimeAsync(20_001); + + expect(fake.calls.stops).toBe(1); + expect(lines.join('\n')).toContain('Giving up on it'); + + // Docker gets round to the start eventually, over a container the deadline + // has already given up on. + await vi.advanceTimersByTimeAsync(20_000); + + await expect(running).rejects.toThrow(/could not be watched at all/); + expect(lines.join('\n')).toContain('once in the last 20s'); + }); + + /** + * The deadline is armed before the container is started, so that one which + * comes up and does nothing is covered from the moment it was told to run. + * That leaves one hole to close: a `start` that fails outright must disarm it + * again, or a quarter of an hour later a server whose installation failed at + * once gets three console lines about standing still and a teardown of a + * container that never ran. + */ + it('disarms the deadline when the container never started', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ failStart: true }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await expect(running).rejects.toThrow(/external connectivity/); + + await vi.advanceTimersByTimeAsync(WINDOW_MS * 10); + + expect(fake.calls.stops).toBe(0); + expect(lines).toEqual([]); + }); + + /** + * The same bound on the ordinary path, where nothing has gone wrong until the + * very last round trip. + * + * A `remove` that never returns wedges the server's operation queue exactly as + * thoroughly after an installation that worked as after one that hung, and + * there is nothing armed at this point to notice: the activity deadline stood + * down when the container ended, which is the line above this one. The + * installation itself is not failed over it — the script ran and the files are + * there — but the container is still on the node, holding the name this + * server's next installation will ask for, so it is said out loud. + */ + it('does not hang when Docker will not remove a container that installed fine', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ unremovable: true }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await vi.advanceTimersByTimeAsync(60_001); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain('Docker would not remove the install container'); + expect(lines.join('\n')).toContain('safe to remove by hand'); + }); + + /** + * The successful installation that announced it was being given up on. + * + * The deadline used to stay armed across the ownership reclaim, and **nothing + * there can push it back**: the install container has been removed by then, so + * `stats` on it answers 404 and the probe contributes nothing, and its attach + * stream is closed, so no output arrives either. A `chown -R` over a modpack + * that outlives the window therefore printed "Giving up on it: the install + * container is being stopped and removed" over a container that had exited 0 + * minutes earlier — and then returned `{ successful: true }`. + */ + it('does not give up on an installation whose ownership reclaim outlives the window', async () => { + const { volumePath, tmpPath } = await workspace(); + + let walked = 0; + const fake = fakeDocker({ + reclaim: { + exitsWith: null, + // A `chown -R` over a full volume is slow and never still: a syscall per + // entry is CPU time on every one of them. + counters: () => ({ cpu_stats: { cpu_usage: { total_usage: (walked += 5_000_000) } } }), + }, + }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + await fake.reclaim.started; + + // The install container's last words, arriving after its wait returned — + // which happens, because the attach stream is still open and Docker flushes + // what it had buffered. The deadline stood down when the container ended, + // and this must not put it back up: it would then be watching the reclaim + // without a single thing able to push it back. + fake.stream.emit('data', Buffer.from('installation complete\n')); + + // Five windows of chowning, which is a real modpack on a real disk. + await vi.advanceTimersByTimeAsync(WINDOW_MS * 5); + + fake.reclaim.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).not.toContain('Giving up on it'); + expect(fake.calls.stops).toBe(0); + }); + + /** + * The reclaim is the statement immediately after the one this whole change set + * exists to guard, and it was the identical construct: a bare `waitForExit` + * with no deadline over it. `install()` is enqueued on the server's operation + * queue, so a `chown` that never returns wedges that queue **for ever** — no + * start, no stop, no reinstall for that server until hopperd is restarted. + * + * Bounded the same way and for the same reason: a `chown -R` moves CPU and + * block I/O continuously, so one that has moved neither for a whole window is + * not slow, it is stuck. + */ + it('gives up on an ownership reclaim that has stopped moving', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ + reclaim: { + exitsWith: null, + counters: () => ({ cpu_stats: { cpu_usage: { total_usage: 7 } } }), + }, + }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + await fake.reclaim.started; + + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + // The installation itself is not thrown away over it: the script ran, the + // files are there, and an hour's download is not worth discarding over a + // partial ownership walk. What the operator gets is the consequence, named. + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(fake.reclaim.calls.stops).toBe(1); + expect(lines.join('\n')).toContain('stood still'); + expect(lines.join('\n')).toContain('may not be able to write into its volume'); + + // Removed once, like the install container: this path had the same pair of + // concurrent `DELETE`s, and the 409 Docker answered the loser reached the + // console as a claim that a container still had this server's volume + // mounted — the one sentence in this message an operator would act on. + expect(fake.reclaim.calls.removes).toBe(1); + expect(lines.join('\n')).not.toContain('would not remove'); + }); + + /** + * And the round trips around it, which the activity deadline says nothing + * about: `createContainer` is Docker answering, not a container working, and + * it comes back from the client as a failure rather than as a hang. + * + * Given up on as a *reclaim*, though, and not as an installation — which is + * the half the code and the comment used to disagree about. By this point the + * install script has exited 0 and the files are on the disk: failing over the + * owner on them puts the server in `install_failed`, whose only way out is a + * reinstall that downloads the lot again against the same unanswering Docker. + * Nothing is recovered and an hour is thrown away. + */ + it('reports rather than fails when Docker will not create the reclaim container', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ reclaim: 'never-created' }); + const lines: string[] = []; + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain("This node's Docker is not answering"); + expect(lines.join('\n')).toContain('may not be able to write into its volume'); + }); + + /** + * The reclaim on a node whose Docker gives up entirely, which is where the one + * call the client cannot bound has to be caught by this file. + * + * A wedged layer makes `stop`, `remove` and `wait` all stop answering at once. + * The first two come back from the client as failures, said on the console. + * The third does not come back at all — `container.wait()` is deliberately + * unbounded, because it is how the daemon learns a container ended — so the + * activity deadline gives up on the `chown`, asks for a teardown, and then has + * to give up on the wait as well or hold this server's operation queue for + * ever behind a container that will never report an exit. + * + * Two failures reach the operator and they are different failures, which is + * why neither is allowed to overwrite the other: why the `chown` did not + * happen, and that a container with this server's volume mounted is still on + * the node. + */ + it('bounds the wait a teardown left behind, and says both failures', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ + reclaim: { + exitsWith: null, + wedged: true, + counters: () => ({ cpu_stats: { cpu_usage: { total_usage: 11 } } }), + }, + }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + await fake.reclaim.started; + + // The chown stands still for a window, so the deadline gives up on it and + // asks for a teardown the client reports as unanswered on the spot. + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + expect(fake.reclaim.calls.stops).toBe(1); + expect(lines.join('\n')).toContain('would not stop the ownership reclaim container'); + + // The wait is still outstanding: the bound over it is a real window and not + // an immediate give-up on a container that may yet report an exit. + await vi.advanceTimersByTimeAsync(30_000); + expect(lines.join('\n')).not.toContain('may not be able to write into its volume'); + + await vi.advanceTimersByTimeAsync(30_001); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain('did not answer about the ownership reclaim container'); + expect(lines.join('\n')).toContain('would not remove the ownership reclaim container'); + expect(lines.join('\n')).toContain('may not be able to write into its volume'); + + // And the wait that lost the race is closed rather than abandoned. It is + // outstanding against a container Docker will not answer about at all, and + // `wait` is the one request the client deliberately does not bound, so + // nothing else in this process would ever release its socket. + expect(fake.reclaim.calls.waits[0]?.abortSignal?.aborted).toBe(true); + }); + + /** + * The ownership reclaim's deadline has exactly one witness — there is no + * attach stream on a `chown -R` — so a `stats` request Docker will not answer + * is the difference between watching an idle container and watching nothing at + * all. + * + * It is still given up on, and the argument is the asymmetry rather than any + * evidence: a reclaim nobody can watch would hold this server's every later + * action, while giving up on one costs a console line over an installation + * that succeeds either way. What must not happen is the verdict claiming the + * `chown` stood still, which sends the operator to their volume when the thing + * to look at is the Docker daemon on the node. + */ + it("names this node's Docker when it could not watch the reclaim at all", async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ reclaim: { exitsWith: null, blind: true } }); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + await fake.reclaim.started; + + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain('no way to tell whether'); + expect(lines.join('\n')).not.toContain('stood still'); + expect(lines.join('\n')).toContain('may not be able to write into its volume'); + }); + + /** + * The verdict the docstring has always claimed, on the case it was written + * about: a `chown` that ran and refused. + * + * Reported and forgiven. The files are on the disk and their owner may be + * wrong, which is a reinstall away from being fixed and an hour of downloading + * away from being worth failing over. + */ + it('reports a chown that exited non-zero without failing the installation', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ reclaim: { exitsWith: 1 } }); + const lines: string[] = []; + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain('Taking ownership of the files failed (code 1)'); + }); + + /** + * The same verdict for a Docker that answers the reclaim with an error rather + * than with silence, which is the case the deadline never sees. + * + * This is the one that used to escape: a refused `createContainer` threw + * straight out of the reclaim and failed an installation that had finished, + * while a `chown` exiting non-zero — the same outcome for the volume — was + * reported and forgiven. The rule is now the one the docstring always claimed: + * no reclaim failure fails an installation whose files are already in place. + */ + it('does not throw away a finished installation when Docker refuses the reclaim', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ reclaim: 'refused' }); + const lines: string[] = []; + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain('no such image'); + expect(lines.join('\n')).toContain('may not be able to write into its volume'); + }); + + /** + * The grace period a container the deadline gave up on is given to go down. + * + * `stop` sends SIGTERM, waits, and only then sends SIGKILL, and the seconds in + * between are what lets a script that traps the signal unlink its half-written + * archive — a 12 GiB modpack tarball left in the volume is a node's free space + * gone until somebody notices. The figure is stated in a comment on + * `abandonContainer` and was passed by a line nothing checked, so dropping the + * argument altogether — which turns the graceful stop into whatever Docker's + * default happens to be — changed no test. + */ + it('gives a container it has given up on time to unlink what it was writing', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + const lines: string[] = []; + + vi.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout', 'Date'] }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + await vi.advanceTimersByTimeAsync(WINDOW_MS + 1); + + await expect(running).rejects.toThrow(/did nothing/); + + expect(fake.calls.grace).toEqual([{ t: 10 }]); + }); + + /** + * The two ways of not failing that Docker spells as errors. + * + * A container can exit and be reaped between the deadline firing and the + * `stop` reaching the socket, and Docker then answers 304 "already stopped" or + * 404 "already gone". Both are races this daemon genuinely loses, neither is + * worth a line on anybody's console, and printing one would teach an operator + * to ignore the lines beside it that do matter. + */ + it('says nothing about a container that had already gone', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ gone: true }); + const lines: string[] = []; + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).not.toContain('would not remove'); + }); + + /** + * A wait that comes back without a status code. + * + * `Container.wait()` is typed `any`, and the daemon reads `StatusCode` out of + * whatever arrives. A Docker that answers the wait with something else — an + * API version that renames the field, a proxy that rewrites the body — leaves + * that read `undefined`, and the choice recorded in `waitForExit` is that not + * knowing counts as a failure. The alternative is a server marked READY over + * an installation whose outcome nobody established, with no container behind + * it and no reinstall offered. + */ + it('treats a wait that named no exit code as a failed installation', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ exitsWithNothing: true }); + const lines: string[] = []; + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toEqual({ successful: false, exitCode: -1 }); + + // And no ownership reclaim: there is nothing to hand over when the install + // may not have run. + expect(fake.created).toHaveLength(1); + }); + + /** + * A wait that failed on its own account, rather than because this daemon tore + * its container down. + * + * The two are the same rejection from here and they mean opposite things. When + * the deadline has fired, a wait that rejects is reporting the teardown the + * daemon asked for — "no such container", after its own `remove` — and the + * reason worth telling anybody is the stall, not that; so it is swallowed and + * the stall verdict is thrown instead. When no deadline has fired, the same + * rejection is Docker refusing to say how an installation ended, and swallowing + * *that* returns `{ successful: false, exitCode: -1 }`: a server left in + * `install_failed` reading "code -1", over a container that may still be + * running, with nothing anywhere naming what went wrong. + */ + it('fails an installation whose wait Docker answered with an error', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker({ waitRefused: true }); + + const running = runInstallation(fake.docker, { + configuration: installable({ inactivityTimeoutMs: WINDOW_MS }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + + await expect(running).rejects.toThrow(/bad parameter/); + }); + + it('refuses a shortfall before any container exists', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + const lines: string[] = []; + + // A petabyte: no node passes this, and the test needs no mocked filesystem + // to prove the refusal. + await expect( + runInstallation(fake.docker, { + configuration: installable({ requiredDiskBytes: 1024 ** 5 }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }), + ).rejects.toThrow(/Not enough disk space/); + + // Refused before the image was pulled and before anything was created: + // a preflight that runs after a pull has already spent the disk it was + // checking for. + expect(fake.created).toEqual([]); + expect(lines.join('\n')).toContain('1 PiB needed'); + }); + + /** + * That the volume is really walked, and its size really reaches the decision. + * + * The arithmetic is proved against {@link diskRefusal} above, where both + * figures can be chosen; what cannot be arranged on a real filesystem is a + * free-space figure, so what is proved here is the wiring — a declared figure + * short of free space makes the daemon measure the volume, and what it + * measures is what the operator is shown. + */ + it('measures what the volume already holds before refusing a reinstall', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + const lines: string[] = []; + + await mkdir(volumePath, { recursive: true }); + await writeFile(join(volumePath, 'world.mca'), Buffer.alloc(4096)); + + await expect( + runInstallation(fake.docker, { + configuration: installable({ requiredDiskBytes: 1024 ** 5 }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }), + ).rejects.toThrow(/Not enough disk space/); + + expect(lines.join('\n')).toContain('4 KiB this server'); + expect(lines.join('\n')).toContain('writes over'); + }); + + /** + * **Not knowing is not a refusal**, which is the whole of what the preflight + * does with a filesystem it cannot measure. + * + * `statfs` fails on filesystems Node cannot describe — a network mount, an + * exotic union filesystem, a path that has just gone — and `freeSpaceBytes` + * answers `null` rather than throwing precisely so this decision is made here + * and made once. Refusing on it would take every server on such a node out of + * service, permanently and silently, over a check that has established + * nothing: no shortfall was measured, and the node may have terabytes free. + * That is a far larger failure than the one the guard exists to prevent, and + * it is unrecoverable from the panel, because a Reinstall runs the same check. + * + * Said out loud all the same. An installation that skipped its disk check is a + * surprising thing to have happened in silence, and on the day the node does + * fill up this line is the only record that nobody looked. + */ + it('installs anyway, and says so, when the free space cannot be read', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + const lines: string[] = []; + + // What `statfs` on a filesystem Node cannot describe comes back as. + disk.freeSpaceBytes = () => Promise.resolve(null); + + const running = runInstallation(fake.docker, { + // A template that declares a figure, so there is a requirement here that + // is genuinely going unchecked rather than one that was never asked. + configuration: installable({ requiredDiskBytes: 40 * GIB }), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: (line) => lines.push(line), + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + + expect(lines.join('\n')).toContain('Could not read the free space'); + expect(lines.join('\n')).toContain('installing anyway'); + // And no refusal wording, which is what a throw would have produced. + expect(lines.join('\n')).not.toContain('Not enough disk space'); + }); + + it('installs as it always has when the template declares neither guard', async () => { + const { volumePath, tmpPath } = await workspace(); + const fake = fakeDocker(); + + const running = runInstallation(fake.docker, { + configuration: installable(), + volumePath, + tmpPath, + ownership: { uid: 988, gid: 988 }, + networkName: 'hopper0', + onOutput: () => undefined, + }); + + await fake.started; + fake.settle(0); + + await expect(running).resolves.toMatchObject({ successful: true, exitCode: 0 }); + }); +}); diff --git a/apps/daemon/src/server/installer.ts b/apps/daemon/src/server/installer.ts index 3f67418..eef9990 100644 --- a/apps/daemon/src/server/installer.ts +++ b/apps/daemon/src/server/installer.ts @@ -3,10 +3,18 @@ import { join } from 'node:path'; import type { Duplex } from 'node:stream'; import type { ServerConfiguration } from '@hopper/shared'; import type Dockerode from 'dockerode'; +import { DOCKER_ANSWER_TIMEOUT_MS, DockerUnansweredError } from '../docker/client.js'; import type { DockerClient } from '../docker/client.js'; import { CPU_PERIOD_US, cpuQuotaFor, memorySwapFor } from '../docker/container-config.js'; import { LineAssembler } from './console-buffer.js'; +import { directorySize, formatBytes, freeSpaceBytes } from './disk-usage.js'; import { buildEnvironment } from './invocation.js'; +import { + activityCounters, + countersMoved, + type ActivityCounters, + type DockerStats, +} from './stats.js'; /** * Running a server's install script. @@ -210,22 +218,6 @@ function installCpuPercent(build: ServerConfiguration['build']): number { return Math.max(build.cpuPercent, INSTALL_CPU_FLOOR_PERCENT); } -/** - * Host configuration of the install container. - * - * Two deliberate departures from the server container's hardening, both because - * the container is a different animal: - * - * - **no `User`**: the whole point of this container is to run as root. Pinning - * it to the server's unprivileged uid would leave every `apt-get` and every - * write into a root-owned directory failing. - * - **no tmpfs on `/tmp`**: the server gets 128 MiB of RAM-backed `/tmp` so it - * cannot fill the host's disk. Applying that here would break the many eggs - * that stage a download in `/tmp` before moving it into the volume — a modpack - * is routinely larger than the whole tmpfs. The container's own layer is - * thrown away seconds later, and `nosuid` on a throwaway filesystem gains - * nothing against a process that is already root. - */ /** * Everything `createContainer` is given for the installation. * @@ -313,16 +305,691 @@ export function installHostConfig(options: { // in particular, a setuid binary it drops in the volume stays inert. SecurityOpt: ['no-new-privileges'], + // **No `Tmpfs` for `/tmp`, deliberately.** A 512 MiB RAM disk was mounted + // here for one release, on the argument that an install script reads its + // download URL out of a variable the server's own user edits and so could + // point an unbounded write at `/var/lib/docker`. The argument does not + // survive reading the rest of this function: `WorkingDir` is `/mnt/server`, + // a bind mount of the volume, and nothing enforces a quota on it — + // `build.diskBytes` is this daemon's own accounting, applied to the file + // manager and to SFTP, never to the kernel. The same script can `curl` two + // hundred gigabytes straight into the volume and fill the node exactly as + // before, so the tmpfs closed nothing. + // + // What it did close was the commonest egg shape there is — + // `curl -o /tmp/pack.zip … && unzip /tmp/pack.zip -d /mnt/server` — which + // worked on the container layer and then met a ceiling no template could + // declare and no operator could raise short of editing the install script. + // And because tmpfs pages are charged to the cgroup that dirties them, on a + // small plan it competed with the installer's own heap in the same `Memory` + // limit set above: a working install turned into an unexplained code 137. + // + // A real ceiling is a node-provisioning job — an XFS project quota, or a + // loopback image per volume — and it does not exist yet. `StorageOpt` is not + // it either: Docker refuses it on overlay2 unless the backing filesystem is + // XFS mounted with `pquota`, so on the ext4 root most nodes run it turns + // every installation on the node into a container that cannot be created. + // The free-space preflight `runInstallation` performs before creating this + // container is a check, not an enforcement, and is documented as one. + RestartPolicy: { Name: 'no' }, LogConfig: { Type: 'json-file', Config: { 'max-size': '5m', 'max-file': '1' } }, }; } +// --------------------------------------------------------------------------- +// The inactivity deadline +// --------------------------------------------------------------------------- + +/** + * How long an installation may do nothing at all before this daemon gives up on + * it, when its template names no figure of its own. + * + * A quarter of an hour, and the number is chosen to be *ignored* by anything + * that works rather than to be tight. What it exists for is a mirror that + * accepts the connection and then stops answering, which until now left the + * server in `installing` for ever because `container.wait()` was waited on with + * no bound at all. + * + * The figure is what it is because of what is being measured, and the two were + * settled together. This deadline was first written on **silence**, with half an + * hour behind it on the argument that no real install prints nothing for that + * long. The argument is false for this repository's own catalogue: every + * bundled script downloads with `curl -sSL` — see `packages/templates`, and the + * same idiom in the overwhelming majority of Pterodactyl eggs — and `-s` + * suppresses the progress meter, so the transfer emits not one byte from start + * to finish. A window on silence would therefore have been a *total-duration* + * cap, the very thing the design rejected, applied to the one step that + * legitimately takes hours: a 2 GiB modpack on a slow uplink is a working + * install it would have killed. + * + * So what is watched is what the container **does** — its output, but also the + * CPU the kernel charges it and the blocks it reads and writes, both counted + * against its own cgroup and nobody else's. A container pulling a depot down a + * wire is alive whether or not it says so: taking those bytes off the socket and + * putting them on a disk is work, and work is CPU time. One doing none of those + * three things is not slow, it is finished. Fifteen minutes of that is a very + * long time; the old thirty were padding for a silent-but-working download that + * now proves itself by the work it is doing. + * + * What is *not* watched is the container's network counters, and + * {@link ActivityCounters} records why at length: they count frames an interface + * accepted rather than work this container did, so on a node whose bridge floods + * ARP to every port they climb for a container that has stopped dead — which + * would leave this deadline never firing on exactly the busy nodes where an + * install that never ends does the most damage. + * + * A template that knows better says so — see `install.inactivityTimeoutMs`. + * This is the figure for the entire existing catalogue, every imported + * Pterodactyl egg, and everything else that has never had a deadline and must + * not start failing because one now exists. + * + * The deadline lives in this process and dies with it, deliberately. An + * installation the daemon was restarted out of is settled by + * `resolveOrphanedInstall` on the way back up — reported as failed, with its + * container removed — and is not resumed or re-adopted: nothing here could adopt + * the output stream of a container started by a process that no longer exists, + * so a "resumed" install would be one nobody is watching, which is the state + * this whole file exists to make impossible. + */ +export const INSTALL_INACTIVITY_DEFAULT_MS = 15 * 60_000; + +/** How long the container is given to go down once the deadline has fired. */ +const INSTALL_ABANDON_GRACE_SECONDS = 10; + +export interface StallReport { + /** How long the container had done nothing when the deadline fired. */ + idleMs: number; + /** How long the installation had been running by then. */ + elapsedMs: number; + /** False when the installation never did anything at all, from the start. */ + sawActivity: boolean; + /** + * Whether the container's counters could be read at all during the window + * that expired. + * + * The difference between "it did nothing" and "nobody could see whether it + * did anything", and the verdicts say which. False means every sample in the + * window failed — a Docker that stopped answering about this container — and + * a deadline that fires on that has no evidence the container was idle. It + * gives up all the same, because a container nobody can watch cannot be + * allowed to hold a server's operation queue for ever, but it names this + * node's Docker rather than accusing a script that may have been working + * perfectly. + */ + observed: boolean; +} + +/** + * A deadline on **inactivity**. + * + * Armed when the install container is about to run and pushed back by every sign + * of life it gives, so that an installation which is working is never killed + * however long it takes, and one that has stopped is given up on however little + * it has done. + * + * Two things push it back, and the second is the one that matters. Output is the + * obvious signal, and it is taken from the raw stream rather than from assembled + * console lines: SteamCMD renders its progress by rewriting one line with + * carriage returns, and {@link LineAssembler} emits nothing at all until a + * newline arrives, so a deadline counting lines would see a download printing + * `progress: 41.62 (…)` twice a second as perfectly silent. But most install + * scripts do not print during a transfer at all — `curl -sSL` is the universal + * idiom and `-s` means exactly that — so the second signal is the container's + * own counters, fed in by {@link ContainerActivityProbe}. + * + * The clock is injectable for the tests, which need to prove both directions — + * an install that is doing something is not killed, one that has stopped is — + * and cannot do that in real time against a window measured in minutes. + */ +export class ActivityWatchdog { + private timer: NodeJS.Timeout | null = null; + private startedAt = 0; + private lastActiveAt = 0; + private sawActivity = false; + /** Whether a counter sample has succeeded since the current window began. */ + private observed = false; + private report: StallReport | null = null; + + constructor( + private readonly windowMs: number, + private readonly onExpiry: (report: StallReport) => void, + private readonly now: () => number = Date.now, + ) {} + + /** What the deadline saw when it fired, or `null` while it has not. */ + get expiry(): StallReport | null { + return this.report; + } + + arm(): void { + this.startedAt = this.now(); + this.lastActiveAt = this.startedAt; + this.schedule(); + } + + /** + * Called for every byte the installation produces and every counter of its + * container that has moved. + */ + noteActivity(): void { + // Nothing to push back once the verdict has been passed: the container is + // already being torn down, and the dying words and last few cycles of its + // own teardown must not look like a reprieve. + // + // Two conditions keep it down and either alone would do it — this one, and + // the null timer the re-arm below is conditional on. The overlap is kept on + // purpose because the two are guarding different things: this one answers + // "has the verdict been passed", and the timer answers "is anybody still + // watching", which is also false for a deadline that merely stood down. The + // installation's own stands down while the ownership reclaim runs, and + // output keeps arriving across that line. + if (this.report !== null) { + return; + } + + this.sawActivity = true; + this.lastActiveAt = this.now(); + + if (this.timer !== null) { + this.schedule(); + } + } + + /** + * Called for every counter sample that came back, whether or not it moved. + * + * Deliberately **not** a sign of life: a container whose counters read exactly + * as they did fifteen seconds ago is standing still, and pushing the deadline + * back for having successfully looked at it would switch the deadline off. All + * this records is that the deadline has a witness — that when it fires, it is + * firing on stillness it saw rather than on a Docker it could not ask. + */ + noteObservation(): void { + if (this.report !== null) { + return; + } + + this.observed = true; + } + + disarm(): void { + if (this.timer !== null) { + clearTimeout(this.timer); + this.timer = null; + } + } + + /** + * A timeout re-armed on every sign of life, rather than an interval that polls + * a timestamp: the deadline then means exactly what it says instead of the + * window plus up to one polling period, and an installation that is doing + * nothing is not woken up for. + */ + private schedule(): void { + this.disarm(); + + // A fresh window has seen nothing yet. Evidence does not carry over: what + // the verdict has to be able to say is whether *this* window — the one that + // ended in silence — was one anybody could see into. + this.observed = false; + + this.timer = setTimeout(() => this.expire(), this.windowMs); + // This timer must never be the reason hopperd stays alive. A daemon being + // shut down mid-install has already stopped caring about the deadline. + this.timer.unref(); + } + + private expire(): void { + // The other half of the pair described in `noteActivity`: a fired timer is + // no longer a timer, and leaving the handle here would let a sign of life + // arriving during the teardown re-arm a deadline that has already spoken. + this.timer = null; + + const at = this.now(); + + this.report = { + idleMs: at - this.lastActiveAt, + elapsedMs: at - this.startedAt, + sawActivity: this.sawActivity, + observed: this.observed, + }; + + this.onExpiry(this.report); + } +} + +/** + * How often the install container's counters are read, at most. + * + * Fifteen seconds, and the reason it can be this lazy without ever mistaking a + * working container for a dead one is that {@link ActivityCounters} are + * cumulative. They only grow, so a difference between two samples is work that + * happened *somewhere* between them, whenever they were taken: a poll cannot + * miss activity, only learn of it late. Sampling rarely therefore costs + * promptness, never correctness — which is what makes the cost side worth + * minimising. Each sample is one round trip to the Docker socket, and this + * daemon may be running several installations at once on a node that is also + * running every server on it. + * + * Fifteen seconds is two orders of magnitude below the default window, so a live + * container gets some sixty chances to prove itself before the deadline. A + * container that is genuinely wedged trips it at the window exactly: a poll that + * hangs or fails resets nothing, so nothing about the sampling can *delay* the + * verdict. + * + * The one case the period could get wrong is a window short enough to be + * comparable to it — a template naming thirty seconds would otherwise be a coin + * toss on whether a sample landed inside it. So the period is also capped at a + * quarter of the window, which gives a container three chances to show movement + * inside one — the first sample is a baseline and can never show any — for every + * window of {@link ACTIVITY_SAMPLE_FLOOR_MS} × {@link ACTIVITY_SAMPLES_PER_WINDOW} + * or more. + * + * **Below four seconds the floor wins, and the guarantee does not hold.** That + * is the deliberate answer rather than an oversight, and the two sentences used + * to be written here as though both were true at once. A window of two seconds + * would need a poll every half-second — one round trip to the Docker socket + * twice a second, per installation, on a node that may be running one for every + * server on it — to measure something no install can be judged on anyway: a + * container that pauses for two seconds is a container between two syscalls, and + * a deadline that fires on that will fire on healthy work whatever the sampling + * rate. So the floor is kept and the window is the thing that is wrong. A + * template naming one this short is asking for a guard that cannot be built; the + * schema permits it because a positive integer is what the field is, and the + * daemon polls at its floor and lets the deadline mean what it can. + */ +const ACTIVITY_SAMPLE_PERIOD_MS = 15_000; +const ACTIVITY_SAMPLES_PER_WINDOW = 4; +const ACTIVITY_SAMPLE_FLOOR_MS = 1_000; + +export function activitySamplePeriod(windowMs: number): number { + return Math.max( + ACTIVITY_SAMPLE_FLOOR_MS, + Math.min(ACTIVITY_SAMPLE_PERIOD_MS, Math.floor(windowMs / ACTIVITY_SAMPLES_PER_WINDOW)), + ); +} + +/** + * Reads a container's counters on a period and reports when any of them moved. + * + * This is the half of the deadline that makes it a deadline on *work* rather + * than on chatter, and it is the half without which the whole guard would kill + * the installations it exists to protect — see + * {@link INSTALL_INACTIVITY_DEFAULT_MS} for why silence proves nothing here. + * + * The first sample establishes a baseline and can never report movement: these + * counters are cumulative over the container's whole life, so a non-zero first + * reading says only that something happened at some point, possibly before + * anybody was watching. + * + * **A sample that fails is neither activity nor stillness, and the callback says + * which it was.** Docker refusing says nothing about what the container is + * doing, and treating it as a sign of life would hand a wedged Docker the power + * to keep an install alive for ever — the failure mode this file exists to + * close, arrived at from the other side. But it is not evidence of idleness + * either, and reporting it as such is how a deadline whose only witness is this + * probe — the ownership reclaim has no output stream — comes to give up on a + * `chown` that was working perfectly. So `onSample` is called only for a sample + * that came back, and it is told whether the counters moved; a failure is + * reported by saying nothing at all, which the deadline reads as having been + * unable to look. + * + * A failure is otherwise swallowed rather than surfaced: it is not the install's + * fault and not the operator's problem, and the sampling carries straight on. + * That carrying-on is worth its own sentence, because it used not to: a `stats` + * request Docker never answered left this loop awaiting a promise that never + * settled, so nothing was ever rescheduled and one hiccup blinded the deadline + * for the rest of the installation. Every request `DockerClient` makes is now + * bounded, so a hung sample comes back as a rejection and the next one goes out + * a period later. + * + * The **sampling** is what that tolerance covers, and nothing else. What the + * callback then does is not this class's business and is deliberately outside + * the `catch` — see `poll` below. + * + * Each poll is scheduled only once the previous one has come back, so a slow + * Docker cannot queue up requests behind itself; the period is a gap between + * polls, not a rate. + */ +export class ContainerActivityProbe { + private timer: NodeJS.Timeout | null = null; + private previous: ActivityCounters | null = null; + private running = false; + + constructor( + private readonly sample: () => Promise, + private readonly onSample: (moved: boolean) => void, + private readonly periodMs: number, + ) {} + + start(): void { + if (this.running) { + return; + } + + this.running = true; + // The baseline is taken straight away rather than one period in, so the + // first sample that *could* show movement is one period away and not two. + void this.poll(); + } + + stop(): void { + this.running = false; + + if (this.timer !== null) { + clearTimeout(this.timer); + this.timer = null; + } + } + + private async poll(): Promise { + this.timer = null; + + /** `null` for a sample that never came back, so nothing is reported. */ + let moved: boolean | null = null; + + try { + const counters = activityCounters(await this.sample()); + const previous = this.previous; + + // A sample whose counters the host does not keep leaves `previous` alone + // and reports nothing — the same answer as a sample that never came back, + // because it carries the same amount of information. Overwriting + // `previous` with it would also discard the last reading that did mean + // something. + if (counters !== null) { + this.previous = counters; + moved = previous !== null && countersMoved(previous, counters); + } + } catch { + // See above: not knowing is neither a sign of life nor a sign of death, + // and the deadline is told nothing rather than told something false. + } + + try { + // Reported from **outside** the `catch` above, and the placement is the + // point rather than tidiness. A sample Docker would not give us and a + // callback that threw are different events with different owners — the + // first is this node's Docker and is deliberately tolerated, the second is + // a bug in this daemon — and one `catch` around both hid the second + // completely. It hid it in the tests too: the two that prove this probe + // reports *nothing* passed an `expect.unreachable()` as the callback, so + // they could not fail however wrong the code became. + // + // Nothing catches it here either. The callback feeds the deadline, which + // cannot throw; one that could would have a defect worth crashing on + // rather than a condition worth surviving. + if (moved !== null) { + this.onSample(moved); + } + } finally { + // Rescheduled from a `finally`, so that a callback which threw takes this + // daemon down loudly rather than stopping the sampling quietly. A probe + // that simply gave up here would leave the deadline with nothing left to + // push it back, and it would kill a working installation one window later + // for a reason nobody could see. + if (this.running) { + this.timer = setTimeout(() => void this.poll(), this.periodMs); + // Like the deadline's own timer, never a reason for hopperd to stay up. + this.timer.unref(); + } + } + } +} + +/** + * A duration as an operator reads it. + * + * "1800000ms" in a console line is a number nobody converts in their head + * before deciding whether it was long enough to be worth believing. + */ +export function describeDuration(milliseconds: number): string { + const total = Math.max(0, Math.round(milliseconds / 1000)); + const hours = Math.floor(total / 3600); + const minutes = Math.floor((total % 3600) / 60); + const seconds = total % 60; + + if (hours > 0) { + return `${hours}h ${minutes}m`; + } + + return minutes > 0 ? `${minutes}m ${seconds}s` : `${seconds}s`; +} + +/** + * What the console is told when the deadline fires. + * + * The three things are listed by name, every time, because the operator reading + * this has to be able to disbelieve it. "Timed out" invites the reply "it was + * downloading, your timeout is too short"; "no output, no CPU, no disk I/O" does + * not, and it also tells anybody sizing `installInactivityTimeoutMs` what the + * figure is actually measuring. + * + * Unless there was nothing to name, which is the branch below. A window in which + * not one counter sample came back is a window in which this daemon could not + * see the container at all, and "no CPU, no disk I/O" would then be a claim + * about figures nobody read. The installation is still stopped — a container + * nobody can watch cannot be left holding a server's operation queue — but the + * lines say so, and they point at this node's Docker rather than at a script + * that may have been working perfectly. The distinction is worth the branch + * because it decides where the operator looks next. + */ +export function describeStall(report: StallReport, windowMs: number): string[] { + if (!report.observed) { + return [ + `[Hopper] This node's Docker has not reported the install container's counters once in the ` + + `last ${describeDuration(report.idleMs)}, and the container has printed nothing either: ` + + 'there is no way to tell from here whether this installation is working.', + '[Hopper] Giving up on it: the install container is being stopped and removed.', + "[Hopper] This is this node's Docker rather than the installation — the script may well " + + 'have been running perfectly. Check that the Docker daemon on this node is healthy ' + + 'before reinstalling, because the same thing will happen again.', + ]; + } + + const idle = report.sawActivity + ? `This installation has done nothing for ${describeDuration(report.idleMs)} — no output, no ` + + `CPU, no disk I/O — having run for ${describeDuration(report.elapsedMs)}.` + : `This installation has done nothing at all in the ${describeDuration(report.elapsedMs)} ` + + 'since it started: no output, no CPU, no disk I/O.'; + + return [ + `[Hopper] ${idle}`, + '[Hopper] Giving up on it: the install container is being stopped and removed.', + '[Hopper] A download that is still running burns CPU on every packet it takes off the socket, ' + + 'even when it prints nothing, so this one is not running. If this installation genuinely ' + + `stands still for longer than ${describeDuration(windowMs)} — a script that sleeps while it ` + + 'waits on something — its template has to say so through installInactivityTimeoutMs.', + ]; +} + +// --------------------------------------------------------------------------- +// The disk preflight +// --------------------------------------------------------------------------- + +/** + * Free space no installation may start below, whatever it is installing. + * + * The floor exists because the interesting figure — how much this particular + * install is about to write — is knowable for a Steam depot and unknowable for a + * Minecraft server whose modpack URL is a variable. A template that knows + * declares `install.requiredDiskBytes`; everything else gets this, and this has + * one job: stop an installation from finishing off a node that is already nearly + * full. A gigabyte is far too little for a modpack and far more than a Paper jar + * needs, which is exactly the point — it refuses only where the *next* write of + * any size is the one that takes the machine down, and it cannot refuse a + * template that installs happily today on a node with room on it. + */ +export const INSTALL_FREE_SPACE_FLOOR_BYTES = 1024 ** 3; + +/** What is refused, and why, in the two forms each is needed in. */ +export interface DiskRefusal { + /** What the console is told, at length. */ + lines: string[]; + /** The one line the {@link InstallationError} carries. */ + reason: string; +} + +/** + * Which filesystem the figures came off, and — the useful half — which one they + * did not. + * + * `statfs` answers for the filesystem the path it was given lives on, and names + * nothing else. That is one filesystem out of the two an installation writes to: + * the volume is bind-mounted from here, but a script that stages its download in + * `/tmp` — `curl -o /tmp/pack.zip … && unzip`, the commonest egg shape there is — + * writes to the container's own layer, which lives under Docker's data root on + * whatever filesystem *that* is. On most nodes they are the same filesystem and + * this sentence costs a line; on a node where an operator deliberately gave the + * volumes a disk of their own, it is the difference between freeing space on the + * right disk and freeing it on the wrong one. + * + * Docker's data root is deliberately not measured alongside. It is configurable + * — `data-root` in `daemon.json` — and this daemon is not told where it is, so + * checking it would mean guessing at `/var/lib/docker` and reporting a figure for + * a filesystem that may have nothing to do with the one Docker uses. A refusal + * naming a number that is wrong is worse than one naming a number that is + * missing. + */ +function measuredOn(path: string): string { + return ( + `[Hopper] The only filesystem measured is the one holding ${path}. An install script that ` + + "stages its download in /tmp writes to the container's own layer instead, on whatever " + + "filesystem carries Docker's storage — where those are separate mounts on this node, that " + + 'one has not been checked.' + ); +} + +/** + * Whether there is room, and what to say when there is not. + * + * Pure, so the refusal's wording is testable without a full filesystem. A + * shortfall is refused rather than warned about: filling a node's disk is not + * this server's failure to have — `/var/lib/docker`, the other servers' volumes + * and the daemon's own logs are on that filesystem, and every server on the + * machine goes down together. The numbers are named because "not enough disk + * space" leaves an operator to guess whether they need to free a gigabyte or + * forty. + * + * **Two questions, answered against two different quantities**, and a refusal + * has to say which of them it failed. They were one question with one number + * once — the declared figure raised to the floor — and that was wrong twice + * over, so both halves are spelled out here. + * + * The **floor** is measured against free space alone. A node that is nearly full + * is nearly full whatever this one volume happens to hold, and the bytes an + * install is going to overwrite are not available in advance: they are released + * as the new ones are written, file by file, so there is no moment at which the + * machine has them spare. Crediting them here would let an installation start on + * a node with nothing left. + * + * The **declared figure** is measured against free space *plus what the volume + * already holds*, because nothing wipes that volume first — a reinstall writes + * over what is there. Demanding the whole requirement as free space is how a + * 40 GiB Palworld server becomes impossible to reinstall on the node it is + * already installed on, which is a certain failure traded away for a possible + * one. The trade is not free and is worth naming: a script that wrote 40 GiB + * *beside* the 40 GiB already there, rather than over it, would be let through + * and would fill the node. Install scripts replace what they installed — that is + * what an install script is — which is what makes the assumption the right way + * round rather than merely the convenient one. + * + * `build.diskBytes` is in neither, and its absence is the other decision worth + * recording. It is the obvious candidate — the server's own disk limit, sitting + * right there in the configuration — and it answers a different question: what + * the operator is willing to *sell* this server, not what its installation is + * about to write. A 50 GiB Minecraft plan that will use 900 MiB would refuse to + * install on a node with 20 GiB free, which is every deliberately oversubscribed + * node in existence; and the panel has already weighed that number once, at + * creation, against the node's declared capacity and the overallocation + * percentage the operator chose. Re-deciding it here would overrule an operator + * on their own machine, in the one code path they cannot see. It would not even + * bound what gets written — nothing enforces `diskBytes` during an installation, + * the quota being this daemon's own accounting over the file manager and SFTP — + * and `diskBytes` 0 means unlimited, which as a *requirement* reads either as + * "needs everything" or "needs nothing". + * + * Both questions are asked of **one** filesystem — the one the volume lives on — + * and every refusal says so out loud rather than leaving it to be inferred from a + * path. See {@link measuredOn} for what that leaves unmeasured and why it stays + * unmeasured. + */ +export function diskRefusal(options: { + freeBytes: number; + /** What the volume already holds, and a reinstall therefore writes over. */ + reclaimableBytes: number; + /** What the template says it downloads, or `undefined` if it did not say. */ + declaredBytes: number | undefined; + path: string; +}): DiskRefusal | null { + const { freeBytes, reclaimableBytes, declaredBytes, path } = options; + + const tail = + '[Hopper] Nothing has been started and nothing has been changed. Free space on this node, ' + + 'or create the server on another one.'; + + if (freeBytes < INSTALL_FREE_SPACE_FLOOR_BYTES) { + return { + lines: [ + `[Hopper] Not enough disk space to install: ${formatBytes(freeBytes)} free on the ` + + `filesystem holding ${path}, ${formatBytes(INSTALL_FREE_SPACE_FLOOR_BYTES)} needed.`, + `[Hopper] Hopper refuses any installation with less than ` + + `${formatBytes(INSTALL_FREE_SPACE_FLOOR_BYTES)} free, whatever it is installing and ` + + 'whatever this volume already holds: an install that fills a node takes down every ' + + 'server on it, not just this one.', + measuredOn(path), + tail, + ], + reason: + `Not enough disk space on this node: ${formatBytes(freeBytes)} free, ` + + `${formatBytes(INSTALL_FREE_SPACE_FLOOR_BYTES)} needed.`, + }; + } + + if (declaredBytes === undefined || freeBytes + reclaimableBytes >= declaredBytes) { + return null; + } + + // Named separately from the total, because "37 GiB available" on a node with + // 5 GiB free is a figure nobody would believe without being told where the + // rest of it comes from. + const held = + reclaimableBytes > 0 + ? `${formatBytes(freeBytes)} free on the filesystem holding ${path}, plus ` + + `${formatBytes(reclaimableBytes)} this server's volume already holds and the ` + + 'installation writes over' + : `${formatBytes(freeBytes)} free on the filesystem holding ${path}`; + + return { + lines: [ + `[Hopper] Not enough disk space to install: ${held}, ${formatBytes(declaredBytes)} needed.`, + '[Hopper] The figure comes from the template, which knows what it downloads.', + measuredOn(path), + tail, + ], + reason: + `Not enough disk space on this node: ${formatBytes(freeBytes + reclaimableBytes)} ` + + `available, ${formatBytes(declaredBytes)} needed.`, + }; +} + /** * Starts the installation and waits for it to finish. * - * @throws {InstallationError} if the template describes no installation, or if - * Docker refuses to create the container. + * @throws {InstallationError} if the template describes no installation, if the + * node has not the disk space for it, if the installation stands still for + * longer than its deadline, or if Docker will not take the container down + * afterwards. + * @throws {DockerUnansweredError} if Docker takes any of the requests this makes + * — creating the install container, attaching to its output, starting it, + * removing it — and does not answer within its own window. Thrown by + * `DockerClient` rather than by anything here, which is the point: see + * `boundEveryRequest`. + * + * Deliberately neither for a failed ownership reclaim, which is reported and + * never fatal — see {@link reclaimOwnership}, and `docs/security.md` for the + * other two failures that are reported without failing an installation. */ export async function runInstallation( docker: DockerClient, @@ -337,9 +1004,19 @@ export async function runInstallation( const scriptDirectory = join(tmpPath, `install-${configuration.uuid}`); - await mkdir(scriptDirectory, { recursive: true }); await mkdir(volumePath, { recursive: true }); + // Before the image is pulled and long before anything runs: a preflight that + // refuses after downloading a container image has already spent the disk it + // was checking for. The volume itself is the path measured, not the daemon's + // root — `system.dataDirectory` can sit on a different disk from + // `system.rootDirectory`, and an operator who gave one server its own mount + // deserves to have that mount checked rather than the one Hopper happens to + // be installed on. It exists by now, which is why the mkdir above moved up. + await assertDiskSpace({ install, volumePath, onOutput }); + + await mkdir(scriptDirectory, { recursive: true }); + // Template scripts are written on Linux; a CRLF slipped in by a Windows // editor would produce `/bin/bash^M: bad interpreter`, a message nobody ever // connects back to line endings. @@ -356,51 +1033,319 @@ export async function runInstallation( allocations: configuration.allocations, }); - const container = await docker.api.createContainer( - installCreateOptions({ - configuration, - install, - environment, - volumePath, - scriptDirectory, - networkName, - }), + /** + * Puts a Docker that has stopped answering where whoever asked for this + * installation is already looking. + * + * **It reports; it does not bound.** Every request `DockerClient` makes is + * bounded at the client — see `boundEveryRequest` there for why the rule lives + * in one place rather than at each of these call sites, which is what it used + * to do — so by the time anything arrives here the deadline has already been + * kept. What is left is a question of audience: the throw becomes a single + * `Installation failed:` line after the fact, while `onOutput` goes onto the + * install log the panel is streaming, among the lines that stopped arriving. + * + * Only a Docker that went quiet, deliberately. Every other way these calls can + * fail — an image that will not pull, a name already taken — already reaches + * the operator through the failure the installation reports, and echoing those + * here would print them twice. + */ + const announcing = async (work: Promise): Promise => { + try { + return await work; + } catch (error: unknown) { + if (error instanceof DockerUnansweredError) { + onOutput(`[Hopper] ${error.message}`); + } + + throw error; + } + }; + + let container: Dockerode.Container; + let stream: Duplex; + + try { + container = await announcing( + docker.api.createContainer( + installCreateOptions({ + configuration, + install, + environment, + volumePath, + scriptDirectory, + networkName, + }), + ), + ); + + stream = (await announcing( + container.attach({ stream: true, stdout: true, stderr: true }), + )) as unknown as Duplex; + } catch (error: unknown) { + // The script directory is removed by the `finally` at the bottom of this + // function, and neither of these two failures has entered its `try` yet. + // Without this, every installation a wedged Docker refused would leave a + // directory in the daemon's tmp that nothing ever comes back for. + await rm(scriptDirectory, { recursive: true, force: true }); + throw error; + } + + const windowMs = install.inactivityTimeoutMs ?? INSTALL_INACTIVITY_DEFAULT_MS; + const teardown = dockerDeadline( + DOCKER_ANSWER_TIMEOUT_MS, + `Docker did not take the install container down within ` + + `${describeDuration(DOCKER_ANSWER_TIMEOUT_MS)}. This node's Docker is not answering; the ` + + 'container may still be running on it.', ); - const stream = (await container.attach({ - stream: true, - stdout: true, - stderr: true, - })) as unknown as Duplex; + /** + * The teardown `abandonContainer` is carrying out, once the deadline has asked + * for one. + * + * Held on to for one reason: the removal near the bottom of this function has + * to be able to wait for a removal that is already under way rather than start + * a second one. Both used to run — that one the moment the wait came back, + * this one from a timer — so on **every** stall the install container was sent + * two concurrent `DELETE`s, and Docker refuses the loser with 409 "removal + * already in progress". {@link failureOf} does not excuse a 409, and should + * not: 409 is also how Docker refuses a removal for reasons worth printing. So + * what the console said, on every stall, was that the container was still on + * the node — in the same breath as Docker was removing it. A line reporting a + * failure that did not happen is precisely what teaches an operator to stop + * reading the lines that did. + * + * It starts as a promise that has already settled so that this is one variable + * rather than a promise beside a flag. Nothing ever awaits that first value: + * the only path that awaits this is the one where the deadline fired, and the + * deadline firing is the only thing that assigns it. + */ + let abandoning: Promise = Promise.resolve(); + + const watchdog = new ActivityWatchdog(windowMs, (report) => { + describeStall(report, windowMs).forEach(onOutput); + // Armed before the teardown is asked for, not after: the wait below is the + // thing this bounds, and it is blocked from this instant on a container that + // may never end. `stop` and `remove` need nothing from here — every request + // `DockerClient` makes carries its own deadline. + teardown.arm(); + // Not awaited *here*, because this runs from a timer and there is nobody to + // await it. What the teardown produces is the thing the wait below is + // blocked on — the container ending — and every way it can fail is reported + // from inside. + abandoning = abandonContainer(container, onOutput, 'install container'); + }); + + // A second signal, and the one that does the work. See + // `INSTALL_INACTIVITY_DEFAULT_MS`: the scripts in this repository download + // with `curl -sSL`, which prints nothing at all for the duration of a + // transfer, so a deadline fed only by the stream below would give a 2 GiB + // modpack the whole window to finish in. + // + // `one-shot` because this wants the counters as they stand, not a rate: with + // `stream: false` alone Docker holds the request open for a collection cycle + // to fill in `precpu_stats`, which is a field nothing here reads. + const probe = new ContainerActivityProbe( + () => container.stats({ stream: false, 'one-shot': true }), + (moved) => { + // Every sample that came back is a witness, whether or not it moved: the + // verdict has to be able to distinguish a container that stood still from + // one nobody could look at. Only movement pushes the deadline back. + watchdog.noteObservation(); + + if (moved) { + watchdog.noteActivity(); + } + }, + activitySamplePeriod(windowMs), + ); const assembler = new LineAssembler(); stream.on('data', (chunk: Buffer) => { - assembler.push(chunk.toString('utf8')).forEach(onOutput); + // Before the assembly, and this ordering is the feature. A progress bar + // rewriting one line with carriage returns — which is how SteamCMD reports a + // forty-gigabyte download — produces chunks here and no completed line at + // all, so a deadline pushed back by lines would kill the very install it was + // written for while it was working perfectly. + watchdog.noteActivity(); + + for (const line of assembler.push(chunk.toString('utf8'))) { + onOutput(line); + } }); - await container.start(); + // Armed before the start rather than after it, and the ordering is the whole + // of what this line buys: a container is covered from the moment it was told + // to run, which includes the stretch while Docker is still thinking about the + // request. Armed after, a `start` that took ten minutes to be acknowledged + // would hand the container that comes out of it a fresh window it has done + // nothing to earn. How long Docker itself may take over that request is a + // different question with a different figure, asked one line below. The probe + // goes the other way round: there are no counters to read from a container + // that has not been started. + watchdog.arm(); - const exitCode = await waitForExit(container); - assembler.flush().forEach(onOutput); + /** + * Closes the wait below when anything but the wait ends the race. + * + * Losing that race abandons a `container.wait()` that is still outstanding, + * and `wait` is the one request `boundEveryRequest` deliberately does not + * bound — so without this, nothing in the process would ever close it. One + * socket to the Docker daemon per stalled installation, held until hopperd is + * restarted, on precisely the node that is already in trouble. + */ + const abandonedWait = new AbortController(); - await container.remove({ force: true }).catch(() => undefined); - await rm(scriptDirectory, { recursive: true, force: true }); + try { + await announcing(container.start()); + probe.start(); - if (exitCode === 0) { - // The script ran as root: without taking ownership back, the server — - // which runs as UID 988 — could not write into any of the files just - // installed, and would fail on its first start with an incomprehensible - // permission error. - await reclaimOwnership(docker, { - image: install.containerImage, - volumePath, - ownership, - build: configuration.build, - onOutput, - }); - } + let exitCode: number; - return { successful: exitCode === 0, exitCode }; + try { + // Unbounded on the left, and that is the design: an installation proving + // itself alive may take hours. Bounded on the right from the moment the + // deadline fires, because `stop`, `remove` and `wait` all fail together on + // a wedged overlay mount, and waiting for that one out is the daemon + // hanging in the code written to stop it hanging. + exitCode = await Promise.race([ + waitForExit(container, abandonedWait.signal), + teardown.reached, + ]); + } catch (error: unknown) { + // A Docker that will not answer at all is this node's failure and is + // reported as one. Folding it into an exit code would describe a container + // that is very possibly still running as an installation that merely + // failed, and the operator would never go looking for it. + // + // Said on the install console as well as thrown, because the two land in + // different places: the throw becomes one `Installation failed:` line + // after the fact, while this appears where the operator is already + // watching, among the lines that stopped arriving. + if (error instanceof InstallationError || error instanceof DockerUnansweredError) { + onOutput(`[Hopper] ${error.message}`); + throw error; + } + + // A wait that failed because the deadline tore its container down is not a + // Docker fault, and reporting it as one would bury the reason under + // "no such container". + if (watchdog.expiry === null) { + throw error; + } + + exitCode = -1; + } finally { + // In the `finally` so that a container's last words reach the console even + // when this is on its way out through a throw: they are usually the reason. + assembler.flush().forEach(onOutput); + // Whichever side won, nothing here reads the wait's answer any more. On + // the side where the wait lost it is still open against a container that + // may never end, and this is the only thing left that could close it; on + // the side where it won there is no request to abort and this costs a + // function call. + abandonedWait.abort(); + } + + // Stood down **here**, the moment the container has finished, rather than + // left to the `finally` at the bottom. What follows this line is the + // ownership reclaim, which runs a second container for as long as a + // `chown -R` over a full volume takes — and across it nothing could push + // this deadline back: the install container is about to be removed, so its + // `stats` call answers 404 and the probe contributes nothing, and its attach + // stream is closed, so no output arrives either. Left armed, it fired in the + // middle of a **successful** installation, printed "Giving up on it: the + // install container is being stopped and removed" over a container that had + // already exited 0, and then returned `{ successful: true }`. The reclaim + // brings a deadline of its own; see {@link reclaimOwnership}. + watchdog.disarm(); + probe.stop(); + + // **Removed once, whichever path got here.** A deadline that fired means + // `abandonContainer` is already removing this container, so this waits for + // that removal instead of sending a second `DELETE` after it — see + // `abandoning` above for what the second one used to print. Waited on rather + // than merely skipped, because the removal that is happening reports its own + // failure, and that report belongs on the console before this installation + // is over rather than after it. + // + // On every other path the removal is this line, bounded by the client like + // every other question put to Docker and no longer raced here: a `remove` + // that never returns wedges the server's operation queue exactly as + // thoroughly after an installation that worked as after one that hung. + if (watchdog.expiry !== null) { + await abandoning; + } else { + const leftBehind = await failureOf(container.remove({ force: true })); + + if (leftBehind !== null) { + // Said rather than swallowed, which it used to be. The container holds a + // name this server's next installation will ask for, and the layer of a + // modpack it just unpacked; nobody comes back for it, and the operator + // finds out at the next reinstall if they are told nothing now. + onOutput( + `[Hopper] Docker would not remove the install container: ${leftBehind}. It is still on ` + + 'this node — `docker ps -a` on the node will say, and it is safe to remove by hand.', + ); + } + } + + const expiry = watchdog.expiry; + + if (expiry !== null) { + // Thrown rather than returned as a failed exit code, so the console says + // what happened instead of `Installation failed (code 137)` — a code the + // deadline produced itself, from a kill nobody but this daemon asked for. + // The state the server lands in is the same either way: `install_failed`, + // reported to the panel, with a Reinstall to retry from. + // + // What the reason names is not the same, and the operator acts on it. A + // deadline that fired without a single counter sample coming back saw + // nothing at all: saying the installation did nothing would send somebody + // looking at their install script when the thing to look at is the Docker + // daemon that stopped reporting on the container. + throw new InstallationError( + expiry.observed + ? `The installation did nothing for ${describeDuration(expiry.idleMs)} and was stopped.` + : `This installation could not be watched at all — this node's Docker reported no ` + + 'counters for its container and the container printed nothing — so it was stopped ' + + `after ${describeDuration(expiry.idleMs)}.`, + ); + } + + if (exitCode === 0) { + // The script ran as root: without taking ownership back, the server — + // which runs as UID 988 — could not write into any of the files just + // installed, and would fail on its first start with an incomprehensible + // permission error. + await reclaimOwnership(docker, { + image: install.containerImage, + volumePath, + ownership, + build: configuration.build, + onOutput, + windowMs, + }); + } + + return { successful: exitCode === 0, exitCode }; + } finally { + // Everything armed above is unwound here on the paths that do not reach the + // lines that unwind it themselves — a `container.start()` that throws used to + // leave the deadline armed on a container that never ran, producing an + // `abandonInstall` and three console lines a quarter of an hour after the + // failure, and the script directory behind it in the daemon's tmp with + // nothing that would ever come back for it. All three of these are + // idempotent, so the ordinary path standing them down early costs nothing + // here. + watchdog.disarm(); + probe.stop(); + teardown.disarm(); + // Docker keeps this socket open as long as anybody holds it, and on the + // paths where the container is never removed nobody else would close it. + stream.destroy(); + await rm(scriptDirectory, { recursive: true, force: true }); + } } /** @@ -409,12 +1354,303 @@ export async function runInstallation( * `Container.wait()` is typed `any` by dockerode: the typing is closed back * here rather than letting that value circulate. A missing code becomes -1, * which will be treated as a failure — the right default when in doubt. + * + * **The signal is required rather than optional, and that is the point of it.** + * Both callers race this against a deadline, and both used to abandon the loser + * without cancelling it. `wait` is the one request `boundEveryRequest` leaves + * unbounded — it answers when the container ends, which for a *server* is its + * whole life — so an abandoned one is a socket to the Docker daemon that nothing + * in this process will ever close again. Making the parameter mandatory is what + * stops a third caller being written that quietly leaks another. + * + * `docker-modem` forwards `abortSignal` to `http.request` as `signal`, and + * strips it back out of the query string, so this reaches the socket without + * reaching the URL. */ -async function waitForExit(container: { wait: () => Promise }): Promise { - const result = (await container.wait()) as { StatusCode?: unknown }; +async function waitForExit( + container: { wait: (options: { abortSignal: AbortSignal }) => Promise }, + abandoned: AbortSignal, +): Promise { + const result = (await container.wait({ abortSignal: abandoned })) as { StatusCode?: unknown }; return typeof result?.StatusCode === 'number' ? result.StatusCode : -1; } +/** + * Takes down a container the deadline has given up on. + * + * The stopping is the point. A deadline that gave up on *waiting* while leaving + * the container downloading would be worse than no deadline at all: the server + * would sit in `install_failed` — a state the panel refuses every action in — + * while the thing it was installing carried on writing into its volume and + * pulling on the node's network, with nothing left watching it and nothing left + * that would ever remove it. + * + * `stop` first, so a script that traps SIGTERM gets to unlink its half-written + * archive, and so `wait` returns an exit code rather than a rejection. Then a + * forced removal regardless of how that went: `stop` fails on a Docker that has + * stopped answering, and that is precisely the case where leaving the container + * behind matters most. + * + * Both calls come back either way. Neither is raced here, because both are + * requests to Docker and `DockerClient` bounds every one of those — a `stop` that + * would once have hung this function for the life of the daemon now rejects after + * a minute and is reported on the line below it. The grace period is added to + * that minute rather than eaten out of it, so the SIGTERM really does get its + * {@link INSTALL_ABANDON_GRACE_SECONDS}. + * + * Both failures are *said*, which they were not. Swallowing them silently is + * defensible for the control flow — there is nothing this function could do + * differently — and indefensible for the operator, because the outcome it hides + * is a container still running on their node, writing into a volume whose server + * now reads `install_failed`. A wedged overlay mount produces exactly that, and + * it produces it in the same breath as the hang {@link runInstallation} bounds + * separately: these two lines are how anyone finds out which of the two happened. + * + * **This is the only removal on the path it runs on, and both callers keep the + * promise it returns so that it stays that way.** They each have an ordinary + * teardown of their own that removes the container once the wait has come back, + * and for a while both fired: two concurrent `DELETE`s for one container, of + * which Docker refuses the second with 409 "removal already in progress" — a + * code {@link failureOf} does not excuse, and rightly, because 409 is also how + * Docker refuses removals for reasons worth printing. So the duplicate request + * is gone rather than the complaint about it, and what the console says about + * the removal is now what happened to the one removal there was. + * + * `subject` names the container in both lines because there are two of them now + * — the installation's and the ownership reclaim's — and "the container may + * still be running" is a sentence an operator has to be able to act on. + */ +async function abandonContainer( + container: Dockerode.Container, + onOutput: (line: string) => void, + subject: string, +): Promise { + const stopFailure = await failureOf(container.stop({ t: INSTALL_ABANDON_GRACE_SECONDS })); + + if (stopFailure !== null) { + onOutput(`[Hopper] Docker would not stop the ${subject}: ${stopFailure}`); + } + + const removeFailure = await failureOf(container.remove({ force: true })); + + if (removeFailure !== null) { + onOutput( + `[Hopper] Docker would not remove the ${subject} either: ${removeFailure}. It may ` + + 'still be running on this node — `docker ps` on the node will say, and it is safe to ' + + 'remove by hand.', + ); + } +} + +/** + * How a teardown failed, or `null` if it did not — including the two ways of not + * failing that Docker spells as errors. + * + * 304 is "already stopped" and 404 is "already gone", and both are races this + * function will genuinely lose: the container can exit of its own accord in the + * moment between the deadline firing and the `stop` reaching the socket. Neither + * is worth a line on somebody's console, and printing one would teach an + * operator to ignore the two lines above that do matter. + */ +async function failureOf(work: Promise): Promise { + try { + await work; + return null; + } catch (error: unknown) { + const status = (error as { statusCode?: unknown } | null)?.statusCode; + + if (status === 304 || status === 404) { + return null; + } + + return error instanceof Error ? error.message : String(error); + } +} + +export interface DockerDeadline { + /** + * Rejects once {@link arm} has been called and the timeout has passed. + * + * **Read afresh for every race, never held across one.** A deadline that has + * fired is spent, and the next {@link arm} puts a new promise here; a caller + * holding the old one is holding a promise that has already rejected, which + * would settle its race the instant it started whatever Docker did. + */ + readonly reached: Promise; + arm(): void; + disarm(): void; +} + +/** One arming's promise, and the handle that rejects it. */ +interface DeadlineAttempt { + promise: Promise; + fail: (error: Error) => void; + /** True once {@link fail} has been called: this attempt cannot be reused. */ + spent: boolean; +} + +/** + * A deadline for the one call `DockerClient` deliberately leaves unbounded. + * + * **There is exactly one thing this is still for**, and the shrinking is the + * point. Every request to Docker is now bounded once, at the client — see + * `boundEveryRequest` — so create, attach, start, stop, remove and the rest need + * nothing here and no longer have it. What the client cannot bound is + * `container.wait()`: it answers when the container ends, which for an + * installation may be hours and for a server is its whole life, and a timeout on + * it would report every long-running server as a crash. + * + * That leaves one gap, which is this: the moment this daemon has *decided* to + * kill a container, the wait stops being a wait for work and becomes a wait for + * a teardown. A wedged overlay mount makes `stop` fail, `remove` fail and `wait` + * never return, all at once — so without this the daemon hangs in precisely the + * code written to stop it hanging. Both callers therefore arm this only from + * the instant their activity deadline has given up. + * + * `message` is given in full by the caller because it is read by an operator on + * a console: it has to name which container and which question, and only the + * caller knows. + * + * **Reusable, and it was not.** One deadline object still bounds two waits in a + * row on the reclaim's path, and the first version of this built one rejected + * promise for the whole of its life. A rejected promise stays rejected: once the + * deadline had fired once, `arm` hung a fresh timer over a promise that had + * already settled, and every later `Promise.race` against `reached` lost + * immediately, on a Docker that was answering perfectly. So a single wedge + * anywhere in an installation poisoned every bounded call that came after it, + * and the failure it invented was a Docker fault reported against a healthy + * node. Each arming therefore gets an attempt of its own, and a spent one is + * replaced rather than re-used. + * + * `arm` restarts the clock even when a timer is already pending, for the same + * reason: what it promises is *this* call the whole window, not whatever an + * earlier arming happened to leave of it. + */ +export function dockerDeadline(timeoutMs: number, message: string): DockerDeadline { + let timer: NodeJS.Timeout | null = null; + let attempt: DeadlineAttempt | null = null; + + /** The deadline as it stands, replaced once it has rejected. */ + const live = (): DeadlineAttempt => { + if (attempt !== null && !attempt.spent) { + return attempt; + } + + let fail: (error: Error) => void = () => undefined; + const promise = new Promise((_, reject) => { + fail = reject; + }); + + // Handled the moment it exists, and only then raced. Nothing may reach this + // promise before a caller starts racing it, and a rejection with no handler + // attached is a process Node takes down — turning a bounded teardown into a + // daemon that dies, which is worse than the hang it replaces. + promise.catch(() => undefined); + + attempt = { promise, fail, spent: false }; + return attempt; + }; + + return { + get reached(): Promise { + return live().promise; + }, + arm(): void { + const current = live(); + + if (timer !== null) { + clearTimeout(timer); + } + + timer = setTimeout(() => { + timer = null; + // Marked before it rejects, so that the next read of `reached` — which + // may well come from the very handler this rejection is about to run — + // gets an attempt that can still be lost rather than one already lost. + current.spent = true; + current.fail(new InstallationError(message)); + }, timeoutMs); + timer.unref(); + }, + disarm(): void { + if (timer !== null) { + clearTimeout(timer); + timer = null; + } + }, + }; +} + +/** An error as the console lines below want it. */ +function messageOf(error: unknown): string { + return error instanceof Error ? error.message : String(error); +} + +/** + * Refuses an installation the node has not got the room for. + * + * The check is the daemon's and not the panel's because only the node knows what + * is left on its own disk: the panel accounts for what it has *promised*, which + * is a different number and deliberately allowed to exceed the machine. + * + * Not knowing is not a refusal. `statfs` can fail on a filesystem Node cannot + * describe, and refusing every installation on such a node would be a far larger + * failure than the one being guarded against — so it says so on the console and + * carries on, which leaves an operator something to search for if the disk does + * fill. + * + * The volume is measured only when the measurement can change the answer, and + * that is a deliberate piece of miserliness rather than a micro-optimisation. + * {@link directorySize} walks every file under the mount: on the modpack this + * guard exists for that is tens of thousands of `lstat` calls and takes seconds, + * paid before the operator sees a single line of their install. It is only ever + * the difference between refusing and allowing when free space alone is already + * short of what the template declared — so a first install onto an empty volume, + * and every install with room to spare, never pays it at all. + */ +async function assertDiskSpace(options: { + install: { requiredDiskBytes?: number }; + volumePath: string; + onOutput: (line: string) => void; +}): Promise { + const { install, volumePath, onOutput } = options; + + const freeBytes = await freeSpaceBytes(volumePath); + + if (freeBytes === null) { + onOutput( + `[Hopper] Could not read the free space on the filesystem holding ${volumePath}: ` + + 'installing anyway, without the usual check that this node has room for it.', + ); + return; + } + + const declaredBytes = install.requiredDiskBytes; + const shortOfDeclared = declaredBytes !== undefined && freeBytes < declaredBytes; + const reclaimableBytes = shortOfDeclared ? await directorySize(volumePath) : 0; + + const refusal = diskRefusal({ freeBytes, reclaimableBytes, declaredBytes, path: volumePath }); + + if (refusal === null) { + // An installation allowed through on space that is not free yet is a + // surprising thing to have happened silently, and the day it turns out to + // have been the wrong call this line is the only record of the decision. + if (shortOfDeclared) { + onOutput( + `[Hopper] Only ${formatBytes(freeBytes)} free on the filesystem holding ${volumePath}, ` + + `but this server's volume already holds ${formatBytes(reclaimableBytes)} that this ` + + 'installation writes over. Carrying on.', + ); + } + + return; + } + + refusal.lines.forEach(onOutput); + + throw new InstallationError(refusal.reason); +} + /** * `chown -R` needs three of Docker's fourteen capabilities, and no more. * @@ -521,6 +1757,85 @@ export function reclaimHostConfig(options: { }; } +/** How the reclaim container is named on the console, in both its failures. */ +const RECLAIM_SUBJECT = 'ownership reclaim container'; + +/** + * Hands the installed files back to the server's uid, under a deadline. + * + * **Bounded in every direction, which it was not.** This is the statement + * immediately after the one the whole inactivity deadline exists to guard, and + * until now it was the identical construct being eliminated: `createContainer`, + * `start()`, a bare `waitForExit(container)` and `remove()`, not one of them with + * a deadline of any kind. It matters more here than almost anywhere, because + * `install()` is enqueued on the server's operation queue — so a `chown -R` that + * never returns takes that queue with it **for ever**: no start, no stop, no + * reinstall for that server until hopperd is restarted, and nothing in the panel + * to say why. + * + * Three of those four are now bounded by nothing written here at all: they are + * requests to Docker, and `DockerClient` bounds every request it makes. What is + * left for this function to arrange is the fourth — the wait for the `chown` to + * finish — and a `chown -R` is exactly the shape the activity deadline suits. It + * is slow over a modpack — hundreds of thousands of entries — but it is never + * *still*: it walks the tree with a syscall per entry, which is CPU time on every + * one of them and block I/O on every directory that has to come off the disk. So + * it proves itself alive the same way an installation does, and a total-duration + * cap would have to be sized for the largest volume on the node, which is the + * mistake {@link INSTALL_INACTIVITY_DEFAULT_MS} was written to avoid. + * + * It is given the installation's own window. A template that says its install may + * stand still for an hour is describing this node's disks as much as its mirrors, + * and one figure an operator can reason about beats a second one they never knew + * they had. + * + * **The counters are this deadline's only witness, and that is why a failed + * sample is not stillness.** There is no attach stream on this container — a + * `chown -R` prints nothing until it fails, and a verbose one would print a + * million lines — so unlike the installation's, this deadline has no second + * signal to fall back on. A `stats` request that Docker will not answer therefore + * used to look exactly like a `chown` that had stopped, and gave up on a healthy + * one. Two things changed. A sample that *hangs* no longer blinds the probe for + * good, because the client bounds it and the next one goes out a period later, so + * a hiccup now costs nothing at all. And a window in which no sample at all came + * back is reported as what it is — see {@link StallReport.observed}. + * + * The container is still given up on in that case, and the argument for it is the + * asymmetry rather than any evidence: a reclaim nobody can watch would otherwise + * hold this server's operation queue for ever, while giving up on one costs a + * console line and files that may still belong to root, over an installation that + * succeeds either way. What changes is that the operator is told this node's + * Docker went quiet rather than told a `chown` stood still, because only one of + * those two sends them to the right place. + * + * **A reclaim that fails does not fail the installation, however it failed.** + * That is this function's contract and not a property of how it happens to be + * written: it returns nothing and cannot throw, which is why the work sits in + * {@link attemptReclaim} — a function whose failures are a return value. + * + * It was already so for a `chown` that exited non-zero and for one that stood + * still. It now holds for the third case too, which used to throw and take a + * finished installation down with it: a Docker that will not create the + * container, will not start it, or stops answering in the middle of it. The + * inconsistency was worth removing on its own — the same node-level fault failed + * the installation if it landed on `createContainer` and did not if it landed on + * the wait — but the direction it was resolved in is the deliberate part. + * + * By the time this runs the install script has exited 0: the files are on the + * disk, the download that took an hour is spent, and the only thing missing from + * them is an owner. Failing the installation over that puts the server in + * `install_failed`, a state the panel refuses every action in, and the only way + * out of it is a Reinstall that downloads the lot again — against a Docker that + * is, by hypothesis, not answering and will refuse that too. Nothing is + * recovered and an hour is thrown away. Reporting it instead costs one console + * line and leaves the files where they are, ready for the same repair to be run + * again when the node is healthy. + * + * What that trades away is worth naming: a server marked installed whose volume + * may still belong to root, which surfaces later as a process unable to write + * its own configuration. The line at the end is the only warning of it, which is + * why it names that consequence rather than the Docker call that produced it. + */ async function reclaimOwnership( docker: DockerClient, options: { @@ -529,21 +1844,219 @@ async function reclaimOwnership( ownership: { uid: number; gid: number }; build: ServerConfiguration['build']; onOutput: (line: string) => void; + /** The window the installation itself was given. */ + windowMs: number; }, ): Promise { - const container = await docker.api.createContainer(reclaimCreateOptions(options)); - - await container.start(); - const exitCode = await waitForExit(container); - await container.remove({ force: true }).catch(() => undefined); + const failure = await attemptReclaim(docker, options); - if (exitCode !== 0) { + if (failure !== null) { options.onOutput( - `[Hopper] Taking ownership of the files failed (code ${exitCode}). The server may not be able to write into its volume.`, + `[Hopper] Taking ownership of the files failed (${failure}). The server may not be able to ` + + 'write into its volume.', + ); + } +} + +/** + * The reclaim itself, reporting how it failed instead of throwing. + * + * `Promise` rather than `Promise` is the whole point: the + * verdict {@link reclaimOwnership} documents is enforced by the signature, so a + * later hand adding a fourth Docker call here cannot fail an installation whose + * files are already in place without first changing this return type. + */ +async function attemptReclaim( + docker: DockerClient, + options: { + image: string; + volumePath: string; + ownership: { uid: number; gid: number }; + build: ServerConfiguration['build']; + onOutput: (line: string) => void; + /** The window the installation itself was given. */ + windowMs: number; + }, +): Promise { + const { onOutput, windowMs } = options; + + // The one call in here the client cannot bound: `container.wait()` answers when + // the chown ends, and this is armed only once the activity deadline has decided + // it never will. See {@link dockerDeadline}. + const deadline = dockerDeadline( + DOCKER_ANSWER_TIMEOUT_MS, + `Docker did not answer about the ${RECLAIM_SUBJECT} within ` + + `${describeDuration(DOCKER_ANSWER_TIMEOUT_MS)}. This node's Docker is not answering.`, + ); + + /** What went wrong, in the shape the one message above wants. */ + let failure: string | null = null; + let created: Dockerode.Container | null = null; + + try { + // Nothing raced here any more. Both are requests to Docker, and every request + // `DockerClient` makes carries its own deadline — a Docker that takes the + // create and goes quiet rejects on its own after a minute, with a message + // that names the endpoint. + created = await docker.api.createContainer(reclaimCreateOptions(options)); + + await created.start(); + } catch (error: unknown) { + failure = messageOf(error); + } + + // A `const` because the closures below capture it, and because it is the one + // question that decides what is left to do: nothing was created, so there is + // nothing to watch, nothing to wait on and nothing to remove. + const container = created; + + if (container === null) { + return failure; + } + + if (failure !== null) { + // Created but never started. The chown has not run and cannot, so the wait + // below would block on a container that will never exit — but the container + // is on the node and is removed like any other. + return await removeReclaimContainer(container, onOutput, failure); + } + + /** The teardown the deadline asked for; see {@link runInstallation} for why. */ + let abandoning: Promise = Promise.resolve(); + + const watchdog = new ActivityWatchdog(windowMs, (report) => { + onOutput( + report.observed + ? `[Hopper] Taking ownership of the files has done nothing for ` + + `${describeDuration(report.idleMs)} — no CPU, no disk I/O. Giving up on it: the ` + + `${RECLAIM_SUBJECT} is being stopped and removed.` + : `[Hopper] This node's Docker has not reported the ${RECLAIM_SUBJECT}'s counters once ` + + `in the last ${describeDuration(report.idleMs)}, so there is no way to tell whether ` + + 'taking ownership of the files is working. Giving up on it: the container is being ' + + 'stopped and removed, because one nobody can watch cannot be left holding this ' + + "server's every later action.", ); + deadline.arm(); + abandoning = abandonContainer(container, onOutput, RECLAIM_SUBJECT); + }); + + const probe = new ContainerActivityProbe( + () => container.stats({ stream: false, 'one-shot': true }), + (moved) => { + // The only witness this deadline has: see the note on + // {@link reclaimOwnership} for why a sample that never came back must not + // be read as a `chown` standing still. + watchdog.noteObservation(); + + if (moved) { + watchdog.noteActivity(); + } + }, + activitySamplePeriod(windowMs), + ); + + watchdog.arm(); + probe.start(); + + const stalled = (report: StallReport): string => + report.observed + ? `it stood still for ${describeDuration(report.idleMs)} and was stopped` + : `its counters could not be read at all, so it was stopped after ` + + `${describeDuration(report.idleMs)} with no way to tell whether it was working`; + + /** As in {@link runInstallation}: the wait that loses this race is closed. */ + const abandonedWait = new AbortController(); + + try { + const exitCode = await Promise.race([ + waitForExit(container, abandonedWait.signal), + deadline.reached, + ]); + + // The deadline is read before the exit code, because on that path the code + // is one this daemon produced itself: the container was killed, and + // reporting 137 would describe the symptom rather than the decision. + if (watchdog.expiry !== null) { + failure = stalled(watchdog.expiry); + } else if (exitCode !== 0) { + failure = `code ${exitCode}`; + } + } catch (error: unknown) { + if (error instanceof InstallationError || error instanceof DockerUnansweredError) { + // A Docker that has stopped answering is named as such even when the + // deadline gave up first: "it stood still" describes the chown, and the + // operator's problem is one layer below that. + failure = error.message; + } else if (watchdog.expiry !== null) { + failure = stalled(watchdog.expiry); + } else { + failure = messageOf(error); + } + } finally { + watchdog.disarm(); + probe.stop(); + // The deadline is only ever armed by the watchdog above, and a `chown` that + // finished a second later leaves that arming outstanding. Harmless — its + // rejection is handled where it is created — but a timer nobody is waiting + // on is a thing to explain later rather than a thing to leave. + deadline.disarm(); + abandonedWait.abort(); + } + + // Removed once, exactly as in {@link runInstallation}: where the deadline gave + // up, `abandonContainer` is already removing this container and this waits for + // that removal rather than racing a second one against it. The docstring on + // `removeReclaimContainer` used to claim Docker answered 404 on this path; it + // answers 409, so every stalled reclaim ended on a console line saying a + // container still had this server's volume mounted when it did not. + if (watchdog.expiry !== null) { + await abandoning; + return failure; } + + return await removeReclaimContainer(container, onOutput, failure); } +/** + * Removes the reclaim container and passes the verdict through untouched. + * + * Bounded like every other request, by the client, so there is nothing to arm + * here. Never called on the path where the activity deadline gave up: + * `abandonContainer` owns the removal there, and its caller waits on that one + * rather than sending a second `DELETE` for Docker to refuse. + * + * A removal that fails does not become the reclaim's verdict: it is a second, + * separate thing to tell the operator — the container has the server's volume + * mounted — and overwriting `failure` with it would lose the reason the chown + * did not happen. + */ +async function removeReclaimContainer( + container: Dockerode.Container, + onOutput: (line: string) => void, + failure: string | null, +): Promise { + const leftBehind = await failureOf(container.remove({ force: true })); + + if (leftBehind !== null) { + onOutput( + `[Hopper] Docker would not remove the ${RECLAIM_SUBJECT}: ${leftBehind}. It has the ` + + "server's volume mounted, so it is worth clearing by hand before the server starts.", + ); + } + + return failure; +} + +/** + * Clears a container this server's previous installation left behind. + * + * The failure swallowed here is nearly always "no such container", which is the + * normal case and the reason there is a `catch` at all. A Docker that will not + * answer lands here too and is swallowed with it — deliberately, because there is + * nothing useful to say at this point that the `createContainer` two lines later + * will not say better and with the operator's attention. It is not lost either: + * `DockerClient` logs every request it abandons, on the node, with the endpoint. + */ async function removeIfExists(docker: DockerClient, name: string): Promise { try { await docker.api.getContainer(name).remove({ force: true }); diff --git a/apps/daemon/src/server/server-instance.spec.ts b/apps/daemon/src/server/server-instance.spec.ts index a184a35..ef01549 100644 --- a/apps/daemon/src/server/server-instance.spec.ts +++ b/apps/daemon/src/server/server-instance.spec.ts @@ -4,7 +4,7 @@ import { mkdtemp, rm } from 'node:fs/promises'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; import type { ServerConfiguration } from '@hopper/shared'; -import { describe, expect, it, vi } from 'vitest'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; import type { DockerClient } from '../docker/client.js'; import type { Logger } from '../logger.js'; import { decodePackets, encodePacket } from './rcon.js'; @@ -69,6 +69,16 @@ interface Fake { logs: ReturnType; removed: ReturnType; killed: ReturnType; + /** + * Every `createContainer` Docker was asked for. + * + * The only witness a test has that something was **not** started. A refusal + * that is meant to stop an installation before it touches the machine leaves + * exactly the same console lines and the same final state whether it refuses + * or merely complains — so the assertion that tells those apart is this spy + * having no calls. + */ + created: ReturnType; panel: { reportInstall: ReturnType; reportStatus: ReturnType }; /** The console stream, so a test can play the container's death itself. */ stream: EventEmitter; @@ -90,6 +100,11 @@ function instanceWith(options: { * `/var/lib`. */ volumesRoot?: string; + /** + * Where the install script would be written. Same reason as `volumesRoot`, + * for the one test that lets an installation get that far. + */ + tmpPath?: string; }): Fake { const logs = vi.fn((_options: { tail?: number }) => options.logsFails @@ -129,11 +144,22 @@ function instanceWith(options: { // the stop — is decided when the container's stream ends. const stream = new EventEmitter(); + // Rejects rather than returning a container, because no test here means to + // run one: what is worth recording is only *whether* it was asked for. The + // rejection lands where a real Docker refusal would, so a caller that reaches + // this point fails the way it would fail against a broken daemon. + const created = vi.fn(() => Promise.reject(new Error('this fake creates no containers'))); + const docker = { api: { getContainer: (name: string) => name.startsWith('hopper-install-') ? installContainer : container, + createContainer: created, }, + // Resolves silently: the pull is not what any of these tests is about, and + // leaving it undefined would abort every path that reaches Docker with a + // `TypeError` rather than at the step under test. + pullImage: vi.fn(() => Promise.resolve()), // Never emits on its own: the point here is the buffer's contents before a // single new byte arrives. attachToContainer: () => Promise.resolve(stream), @@ -151,7 +177,7 @@ function instanceWith(options: { logger, dataPath: '/var/lib/hopper/volumes', volumesRoot: options.volumesRoot ?? '/var/lib/hopper/volumes', - tmpPath: '/tmp', + tmpPath: options.tmpPath ?? '/tmp', ownership: { uid: 988, gid: 988 }, networkName: 'hopper0', panel, @@ -162,6 +188,7 @@ function instanceWith(options: { logs, removed, killed, + created, panel, stream, tail: () => logs.mock.calls[0]?.[0]?.tail, @@ -539,6 +566,86 @@ describe('an installation the daemon was restarted out of', () => { }); }); +/** + * An installation the node has not got the disk for. + * + * The refusal's wording lives in the installer and is tested there. What this + * proves is the half no pure function can: that **nothing ran**. + * + * It has to be asserted that way round, because every other observable is the + * same whether the shortfall is refused or merely complained about. The console + * lines are printed before the throw; the state lands at `install_failed` + * either way, since a Docker that will not create the container fails the + * installation just as thoroughly. An earlier version of this test asserted + * only those two, and downgrading the refusal to a warning — swapping the + * `throw` in the installer's preflight for a `return` — left it green while the + * install container went on to be created and to write into the volume the + * check had just said there was no room in. + * + * The state and the report are still worth asserting, for their own reason: a + * refusal that left the row at INSTALLING for ever is the failure this daemon + * has already been bitten by twice. + */ +describe('an installation refused for want of disk space', () => { + let volumes: string; + let scripts: string; + + beforeEach(async () => { + volumes = await mkdtemp(join(tmpdir(), 'hopper-install-refusal-')); + // Given a real directory rather than `/tmp`, so that a regression which + // lets the installation past the preflight writes its install script here + // and is cleaned up, instead of into whatever `/tmp` resolves to on the + // machine running the suite. + scripts = await mkdtemp(join(tmpdir(), 'hopper-install-scripts-')); + }); + + afterEach(async () => { + await rm(volumes, { recursive: true, force: true }); + await rm(scripts, { recursive: true, force: true }); + }); + + it('creates no container at all, and says why on the console', async () => { + const panel = { reportInstall: vi.fn(() => Promise.resolve()) }; + + const fake = instanceWith({ + running: false, + logs: '', + panel, + volumesRoot: volumes, + tmpPath: scripts, + configuration: { + ...startable(undefined), + // A petabyte: no node passes this, so the preflight refuses without any + // filesystem having to be faked. + install: { + containerImage: 'debian:bookworm-slim', + entrypoint: '/bin/bash', + script: 'echo installing', + requiredDiskBytes: 1024 ** 5, + }, + }, + }); + + await fake.instance.install(false); + + // The assertion the whole refusal exists for. Nothing was created, so + // nothing ran as root over the volume and nothing wrote a byte onto the + // filesystem this check has just called too full. + expect(fake.created).not.toHaveBeenCalled(); + + // The same ending as any other failed install: a state the panel shows and + // a report that moves the row out of INSTALLING, so Reinstall is there to + // retry from once the space has been freed. + expect(fake.instance.currentState).toBe('install_failed'); + expect(panel.reportInstall).toHaveBeenCalledWith(UUID, false); + + // And the numbers, because "not enough disk space" leaves an operator to + // guess whether they need to free a gigabyte or a thousand. + expect(consoleText(fake.instance)).toContain('1 PiB needed'); + expect(consoleText(fake.instance)).toContain('Free space on this node'); + }); +}); + describe('ServerInstance.reconcile', () => { it('recovers the console of a container that is already running', async () => { const fake = instanceWith({ diff --git a/apps/daemon/src/server/server-instance.ts b/apps/daemon/src/server/server-instance.ts index 74a400a..12bbb5b 100644 --- a/apps/daemon/src/server/server-instance.ts +++ b/apps/daemon/src/server/server-instance.ts @@ -833,6 +833,11 @@ export class ServerInstance extends EventEmitter { // Hand-rolled attach rather than dockerode's `container.attach()`: see the // comment on `DockerClient.attachToContainer`, which explains why the // library's version injects its own options into stdin. + // + // The handshake is bounded and the stream that comes out of it is not, which + // is the distinction that matters here: this daemon adopts running servers + // when it starts, and a quiet server prints nothing for hours. See + // `boundEveryRequest` for why no deadline anywhere reaches an open stream. const stream = await this.options.docker.attachToContainer(containerNameFor(this.uuid)); stream.on('data', (chunk: Buffer) => this.handleOutput(chunk)); @@ -958,6 +963,10 @@ export class ServerInstance extends EventEmitter { return; } + // Bounded up to the response and not past it, like the console stream above: + // Docker sends a sample a second while the container runs and stops sending + // the moment it does not, and a deadline over the stream itself would take + // the statistics of every idle server offline on a timer. const stream = await this.container().stats({ stream: true }); const assembler = new LineAssembler(); diff --git a/apps/daemon/src/server/stats.spec.ts b/apps/daemon/src/server/stats.spec.ts index ebe15da..5a22c31 100644 --- a/apps/daemon/src/server/stats.spec.ts +++ b/apps/daemon/src/server/stats.spec.ts @@ -1,8 +1,10 @@ import { describe, expect, it } from 'vitest'; import { + activityCounters, calculateCpuPercent, calculateMemoryBytes, calculateNetwork, + countersMoved, emptyUsage, type DockerStats, } from './stats.js'; @@ -176,3 +178,98 @@ describe('emptyUsage', () => { expect(usage.uptime).toBe(0); }); }); + +/** + * The two counters the install deadline is built on. + * + * They are read from the same samples the panel's resource graphs are drawn + * from, deliberately: the daemon already streams `docker stats`, and a second + * mechanism for asking the same question would be a second thing to keep true. + * + * Only the two, and the interfaces' byte counters are the ones left out. Those + * count frames an interface *accepted* inside the container's netns — broadcast + * ARP flooded across the bridge every server on the node shares, TCP keepalives + * on a socket to a mirror that stopped answering — rather than work this + * container did, so on a busy node they climb for a container that is doing + * nothing at all. A deadline pushed back by them never fires, which is the + * original bug wearing a hat. + */ +describe('activityCounters', () => { + it('adds every block operation together and counts the CPU time', () => { + const stats: DockerStats = { + cpu_stats: { cpu_usage: { total_usage: 1_500 } }, + blkio_stats: { + io_service_bytes_recursive: [ + { op: 'read', value: 4_096 }, + { op: 'write', value: 8_192 }, + ], + }, + }; + + expect(activityCounters(stats)).toEqual({ cpuNanos: 1_500, blockIoBytes: 12_288 }); + }); + + // The counter this deliberately cannot see. A container whose interface is + // taking the bridge's broadcast traffic and nothing else has done no work, and + // must read exactly as still as one with no interface at all. + it('takes no notice of what the interfaces received', () => { + // Interface traffic and nothing else reads as a host that accounts for + // neither counter, which is `null` — not as a container standing still. + expect( + activityCounters({ networks: { eth0: { rx_bytes: 4_000_000, tx_bytes: 12_000 } } }), + ).toBeNull(); + }); + + it('reads a host that keeps only one of the two', () => { + // Common on cgroup v2 without `io` accounting. Either counter alone is + // enough, and CPU alone carries every real installation. + expect(activityCounters({ cpu_stats: { cpu_usage: { total_usage: 42 } } })).toEqual({ + cpuNanos: 42, + blockIoBytes: 0, + }); + }); + + /** + * Docker really does send these empty, and on some cgroup v2 hosts sends + * `io_service_bytes_recursive` as `null` while its siblings are arrays. A + * throw here would be an exception inside a timer with nobody to catch it, and + * the deadline it feeds would stop being reset. + */ + it('survives a host that accounts for none of it', () => { + // `null` rather than a pair of zeroes, and the difference decides whether + // installations run on such a host at all. Folded to zero, every sample + // equals the last one for ever, the deadline reads perpetual stillness, and + // it kills every installation on the node however hard each is working. + expect(activityCounters({})).toBeNull(); + expect(activityCounters({ blkio_stats: { io_service_bytes_recursive: null } })).toBeNull(); + }); +}); + +describe('countersMoved', () => { + const still = { cpuNanos: 10, blockIoBytes: 30 }; + + it('sees nothing in two identical samples', () => { + expect(countersMoved(still, { ...still })).toBe(false); + }); + + // Each covers a way of being busy the other misses: a download whose writes + // are still in the page cache has touched no disk — under cgroup v1 the + // writeback is never charged to it at all — while a large copy waiting on a + // slow disk spends very little of its time on a CPU. + it.each([ + ['CPU', { cpuNanos: 11 }], + ['block I/O', { blockIoBytes: 31 }], + ])('sees movement in %s alone', (_name, moved) => { + expect(countersMoved(still, { ...still, ...moved })).toBe(true); + }); + + /** + * These counters only grow, so in practice "changed" and "increased" are the + * same test — but a counter that somehow went backwards would read as *no* + * activity under a `>` comparison, and the price of that mistake is a working + * installation killed. Any change at all is movement. + */ + it('counts a counter that went backwards as movement', () => { + expect(countersMoved(still, { ...still, blockIoBytes: 1 })).toBe(true); + }); +}); diff --git a/apps/daemon/src/server/stats.ts b/apps/daemon/src/server/stats.ts index 30c44f8..21ba995 100644 --- a/apps/daemon/src/server/stats.ts +++ b/apps/daemon/src/server/stats.ts @@ -22,6 +22,18 @@ export interface DockerStats { stats?: { cache?: number; inactive_file?: number }; }; networks?: Record; + /** + * Bytes the container's cgroup has read from and written to block devices. + * + * Read only by {@link activityCounters}, and declared with `null` in the union + * because Docker really does send it: the field is empty rather than absent on + * a host whose cgroup driver cannot account for I/O, and on some cgroup v2 + * configurations `io_service_bytes_recursive` is `null` while its siblings are + * arrays. Anything that reads it has to survive that. + */ + blkio_stats?: { + io_service_bytes_recursive?: { op?: string; value?: number }[] | null; + } | null; } /** @@ -89,6 +101,117 @@ export function calculateNetwork(stats: DockerStats): { rx: number; tx: number } ); } +/** + * The two cumulative counters that say whether a container is doing any work. + * + * Cumulative and not rates, which is the property the whole thing rests on: each + * of these only ever grows, so *any* difference between two samples is work that + * happened in between, whenever the samples were taken. A reader can therefore + * poll as rarely as it likes without ever missing activity — only without + * learning about it promptly — which is what makes a cheap poll a sound basis + * for a deadline. + * + * **Both are cgroup counters, and that is the rule for what belongs here**: the + * kernel charges them to this container because this container caused them. A + * third used to sit beside them — `networks[*].rx_bytes` and `tx_bytes` summed — + * and it had to go, because it is not that kind of number. Those are link-layer + * counters on the interfaces inside the container's network namespace: they + * count every frame the interface *accepted*, whoever sent it and whether or not + * anything in the container ever read it. Every server on a node shares one + * bridge, a Linux bridge floods broadcast ARP to every port on it, and a `curl` + * still holding a socket to a mirror that stopped answering keeps sending TCP + * keepalives, which are on by default. So on a busy node those counters climb + * for a container that is doing nothing whatsoever, the deadline they feed is + * pushed back for ever, and the installation that never ends survives — on + * precisely the nodes where it costs the most. Watching the network did not + * widen the deadline's coverage, it quietly switched the deadline off. + * + * **Coverage does not suffer for it, and the walk is worth writing down** since + * the loss looks like a hole. A transfer that is moving is not a passive thing: + * every segment has to be copied off the socket by a `read` in the container and + * put somewhere by a `write`, and both are charged to this cgroup as CPU time, + * in nanoseconds — orders of magnitude finer than what a single packet costs, so + * even a few kilobytes a second separates two samples taken fifteen seconds + * apart. A transfer that has stalled is a process blocked in the kernel waiting + * on a socket that says nothing; a task that is not scheduled is charged no CPU + * and issues no I/O, so both counters stand still for exactly as long as the + * stall lasts. That is the discrimination the deadline needs, and CPU time alone + * already makes it. + * + * Two rather than one because they are not redundant, and the download nobody + * thinks of is the demonstration: one whose writes sit in the page cache moves + * **no** block I/O for as long as the kernel holds them there — up to + * `dirty_expire_centisecs`, half a minute by default — and under cgroup v1 + * buffered writeback is never charged to the container at all, since the flusher + * thread does it. Block I/O alone would call that download dead. It earns its + * place the other way round, on the work that spends its time waiting on a disk + * rather than on a CPU: a large copy, an unpacking, the `chown -R` this daemon + * runs over a full volume after an install. + * + * The one shape neither counter sees is a script that is deliberately asleep — a + * `sleep 600` around a wait on some external job. That is not a gap: a container + * asleep is inactive by the definition this whole deadline is built on, and a + * template that knows its script idles says so through + * `install.inactivityTimeoutMs`. + * + * Absent fields read as 0 rather than as a break in the series, because 0 is + * what Docker means by them: no I/O accounted for on this host. That a whole + * counter reads 0 for the life of a container is fine — it simply never + * contributes a difference, and the other decides. + */ +export interface ActivityCounters { + /** Nanoseconds of CPU time the container's cgroup has been charged. */ + cpuNanos: number; + /** Bytes its cgroup has read from and written to block devices. */ + blockIoBytes: number; +} + +export function activityCounters(stats: DockerStats): ActivityCounters | null { + const blockIo = stats.blkio_stats?.io_service_bytes_recursive ?? []; + const cpuNanos = stats.cpu_stats?.cpu_usage?.total_usage; + + // `null`, not a pair of zeroes, when the host accounts for neither. + // + // Folding an absent counter to 0 makes "this host does not report CPU or + // block I/O" indistinguishable from "this container did nothing" — and the + // two are opposite answers. On such a host every sample would equal the last + // one for ever, `countersMoved` would report stillness for ever, and the + // deadline would kill every installation on the node however hard it was + // working. A sample the daemon cannot read is the same event as a sample it + // could not take: not knowing, which the watchdog is careful never to treat + // as knowing. + // + // Either one is enough. A host reporting only CPU is common on cgroup v2 + // without `io` accounting, and CPU alone carries every real install. + if (cpuNanos === undefined && blockIo.length === 0) { + return null; + } + + return { + cpuNanos: cpuNanos ?? 0, + // Every operation, not just Read and Write: `Sync`, `Async` and `Total` are + // the same bytes counted again on cgroup v1, and summing the lot double + // counts them. That is harmless here and deliberately not corrected for — + // this figure is never shown to anybody and never compared to a threshold, + // only to its own previous value, and a consistent over-count changes + // nothing about whether it moved. + blockIoBytes: blockIo.reduce((total, entry) => total + (entry?.value ?? 0), 0), + }; +} + +/** + * Whether anything happened between two samples. + * + * Inequality rather than "greater than". The counters only ever grow, so in + * practice the two are the same test — but a counter that somehow went backwards + * (a cgroup recreated under the container, a Docker bug) would read as *no* + * activity under `>`, and the cost of that mistake is a working installation + * killed. Any change at all is movement. + */ +export function countersMoved(before: ActivityCounters, after: ActivityCounters): boolean { + return before.cpuNanos !== after.cpuNanos || before.blockIoBytes !== after.blockIoBytes; +} + export function buildResourceUsage( stats: DockerStats, context: { state: ServerState; startedAt: number | null; diskBytes: number }, diff --git a/apps/panel/prisma/migrations/20260808000000_template_install_guards/migration.sql b/apps/panel/prisma/migrations/20260808000000_template_install_guards/migration.sql new file mode 100644 index 0000000..aa26364 --- /dev/null +++ b/apps/panel/prisma/migrations/20260808000000_template_install_guards/migration.sql @@ -0,0 +1,49 @@ +-- What a template says about its own installation, so a node can survive it. +-- +-- Both columns are nullable with no default and neither is backfilled, for the +-- same reason as `stopTimeoutSeconds` before them: NULL has to keep meaning +-- "this template did not say". A stored figure would be indistinguishable from +-- a template author's own decision, and the day either default is reconsidered +-- every row would be holding an opinion nobody expressed. + +-- How long the installation may do nothing at all before the daemon stops it. +-- +-- A deadline on inactivity, not on duration. `waitForExit` in the daemon was an +-- unbounded `container.wait()`, so an install that stalled on a dead mirror left +-- its server in `installing` for ever with nothing anywhere giving up. A cap on +-- total duration cannot replace this: set high enough for a forty-gigabyte Steam +-- depot it never fires, set low enough to be useful it kills working installs. +-- +-- Nor is it a deadline on *output*, which was this column's first name and was +-- wrong: `curl -sSL` — the idiom in every bundled script and in most imported +-- eggs — prints nothing whatsoever while it transfers, so a window on silence +-- would have been a total-duration cap on the one step that legitimately takes +-- hours. What the daemon watches is what the container *does*: the CPU the +-- kernel charges it and the blocks it reads and writes, both counted against its +-- own cgroup, as well as anything it prints. Its network counters are +-- deliberately not among them — those count frames an interface accepted, +-- including the ARP a Linux bridge floods to every port on it, so a stalled +-- install looked busy on exactly the crowded nodes where one that never ends +-- costs the most. +-- +-- NULL leaves the daemon's own generous window, which is what every template +-- and every imported Pterodactyl egg keeps. +ALTER TABLE "templates" ADD COLUMN "installInactivityTimeoutMs" INTEGER; + +-- How much free disk the installation needs, when the template knows. +-- +-- Checked before the install container is created, and a shortfall is refused: +-- a depot larger than the node's free space fills the host disk, and that takes +-- down every server on the machine. What the volume already holds counts towards +-- the figure, not against it — a reinstall writes over those files, and +-- demanding the whole requirement as *free* space would mean a 40 GiB server +-- could never be reinstalled on the node it already occupies. +-- +-- BIGINT, not INTEGER. A Steam depot goes past the 2 147 483 647 an INTEGER +-- stops at, and the symptom would be an insert rejected somewhere inside a +-- template import rather than anything an operator could act on. +-- +-- NULL is the ordinary case and is not a hole: a Minecraft server's size is +-- whatever modpack its variables point at, so most templates cannot answer, and +-- the daemon requires a floor of free space from every installation regardless. +ALTER TABLE "templates" ADD COLUMN "installRequiredDiskBytes" BIGINT; diff --git a/apps/panel/prisma/schema.prisma b/apps/panel/prisma/schema.prisma index 54ce339..25bcfb1 100644 --- a/apps/panel/prisma/schema.prisma +++ b/apps/panel/prisma/schema.prisma @@ -414,6 +414,42 @@ model Template { installEntrypoint String @default("/bin/bash") installScript String @default("") + /// Milliseconds the installation may do nothing at all before the daemon + /// stops it — no output, no CPU, no disk I/O. + /// + /// Nullable, meaning "this template did not say", and the daemon then applies + /// its own generous default. Not a total-duration cap: a Steam depot that + /// takes an hour of solid downloading is alive, and any duration large enough + /// to accommodate it would never fire on a stalled one. Not a cap on output + /// either — `curl -sSL` prints nothing at all while it transfers, which is how + /// nearly every install script downloads. + /// + /// The container's network counters are deliberately not among the three, and + /// this column used to say they were. They count frames an interface accepted + /// — including the ARP a Linux bridge floods to every port on it — rather than + /// work this container did, so watching them made a stalled install look busy + /// on exactly the crowded nodes where one that never ends costs the most. + installInactivityTimeoutMs Int? + + /// Bytes this installation is expected to write, when the template knows. + /// + /// `BigInt` and not `Int`: a Steam depot passes the four-billion mark that a + /// 32-bit column stops at, and the failure would be an insert rejected at the + /// far end of a template import rather than anything legible. + /// + /// Nullable, and the vast majority of templates keep a NULL: a Minecraft + /// server's size is whatever modpack its variables point at. The daemon then + /// asks only for its own floor of free space, and refuses nothing else. + /// + /// That floor is **not** the behaviour installations had before this column + /// existed. There was no disk check of any kind: an installation started + /// whatever the node had left, and a modpack larger than the free space filled + /// the machine and took every server on it down. So a NULL here is the weaker + /// of the two guards rather than the absence of one, and a node with under a + /// gigabyte free now refuses an installation it would once have accepted — + /// which is the point. + installRequiredDiskBytes BigInt? + /// UUID of the original Pterodactyl egg, to avoid double imports. importedFromEgg String? diff --git a/apps/panel/prisma/seed.ts b/apps/panel/prisma/seed.ts index 3652f72..cbb1905 100644 --- a/apps/panel/prisma/seed.ts +++ b/apps/panel/prisma/seed.ts @@ -122,6 +122,13 @@ async function seedTemplates(): Promise { installContainer: definition.installContainer, installEntrypoint: definition.installEntrypoint, installScript: definition.installScript, + // And the two install guards, kept in step by hand like the pair above. + // Missing one here is quieter still: a seeded instance would install with + // the daemon's default inactivity window and no declared disk requirement, + // and the difference only shows the day a template's own install stalls + // or fills a node. + installInactivityTimeoutMs: definition.installInactivityTimeoutMs ?? null, + installRequiredDiskBytes: definition.installRequiredDiskBytes ?? null, }; const variables = definition.variables.map((variable) => ({ diff --git a/apps/panel/src/modules/servers/server-configuration.service.spec.ts b/apps/panel/src/modules/servers/server-configuration.service.spec.ts index bf5349c..39652bf 100644 --- a/apps/panel/src/modules/servers/server-configuration.service.spec.ts +++ b/apps/panel/src/modules/servers/server-configuration.service.spec.ts @@ -3,6 +3,7 @@ import { describe, expect, it } from 'vitest'; import type { PrismaService } from '../../prisma/prisma.service.js'; import { ServerConfigurationService, + installGuards, parseReadiness, parseStop, parseStopCommand, @@ -210,6 +211,8 @@ function serverRow(template: Record, allocations?: Record { }); }); +/** + * What the daemon is told about surviving the installation itself. + * + * Both guards are new columns, and the case that has to be exactly right is the + * one every existing template is in: declaring neither, and producing the + * payload it has always produced. + */ +describe('ServerConfigurationService.build install', () => { + const UUID = '1b32d12d-7b10-443e-a259-6a31d67e28e6'; + + it('sends the install object unchanged for a template that declares neither guard', async () => { + const configuration = await serviceFor({}).build(UUID); + + // The keys are asserted rather than the value, because neither `toEqual` + // nor `JSON.stringify` can tell an absent key from one holding `undefined` + // — and "absent" is what the whole existing catalogue has to keep sending. + expect(Object.keys(configuration.install!)).toEqual(['containerImage', 'entrypoint', 'script']); + }); + + it('carries the inactivity window a template names', async () => { + const configuration = await serviceFor({ installInactivityTimeoutMs: 900_000 }).build(UUID); + + expect(configuration.install?.inactivityTimeoutMs).toBe(900_000); + }); + + it('carries a declared download size across the BigInt column', async () => { + // Forty gigabytes is past what an INTEGER column holds, which is why the + // column is a BigInt — and past what a JSON payload can carry as one, which + // is why it is converted here. + const configuration = await serviceFor({ + installRequiredDiskBytes: BigInt(40) * BigInt(1024) ** BigInt(3), + }).build(UUID); + + expect(configuration.install?.requiredDiskBytes).toBe(42_949_672_960); + }); +}); + +/** + * The keys are asserted, never the value. + * + * `toEqual({})` passes on `{ inactivityTimeoutMs: undefined }`, which is the one + * shape this function exists to avoid producing — so a version of it written + * with `inactivityTimeoutMs: template.installInactivityTimeoutMs ?? undefined`, + * emitting both keys always, would leave a `toEqual({})` test green while + * sending every existing template a payload it has never sent. `Object.keys` is + * what tells those apart, as it does for the allocation roles below. + */ +describe('installGuards', () => { + it('says nothing at all when the template declares nothing', () => { + expect( + Object.keys( + installGuards({ installInactivityTimeoutMs: null, installRequiredDiskBytes: null }), + ), + ).toEqual([]); + }); + + // A row read back without the columns — an older dump, a `select` written + // before they existed — must behave like a template that declared nothing, + // not emit a key holding `undefined`. + it('says nothing for columns that are not there at all', () => { + expect(Object.keys(installGuards({} as never))).toEqual([]); + }); + + // And the other half of the same rule: a template that *does* declare one + // guard sends that key and only that key. + it('sends only the guard the template named', () => { + const guards = installGuards({ + installInactivityTimeoutMs: 900_000, + installRequiredDiskBytes: null, + }); + + expect(Object.keys(guards)).toEqual(['inactivityTimeoutMs']); + expect(guards.inactivityTimeoutMs).toBe(900_000); + }); +}); + /** * The names the daemon matches a readiness `role` against. * diff --git a/apps/panel/src/modules/servers/server-configuration.service.ts b/apps/panel/src/modules/servers/server-configuration.service.ts index f44aa28..49a0fa4 100644 --- a/apps/panel/src/modules/servers/server-configuration.service.ts +++ b/apps/panel/src/modules/servers/server-configuration.service.ts @@ -117,6 +117,12 @@ export class ServerConfigurationService { containerImage: server.template.installContainer, entrypoint: server.template.installEntrypoint, script: server.template.installScript, + // Spread rather than `?? undefined`, so a template that declares + // neither guard produces the object it has always produced, key for + // key. Every server on every installation has one of these, and a + // payload that changes shape for all of them the day this ships is a + // change nobody can tell from a real one when they go looking. + ...installGuards(server.template), }, }; @@ -149,6 +155,40 @@ export class ServerConfigurationService { } } +/** + * What a template says about surviving its own installation. + * + * Two columns, both nullable, both meaning "this template did not say" when + * they are — and that is what has to reach the daemon, rather than a figure + * chosen here. The daemon owns the fallback for the inactivity window because + * the daemon is where the timer is armed and where the container's counters are + * read, and it owns the free-space floor because only the node knows what is + * left on its own disk. + * + * `installRequiredDiskBytes` is a `BigInt` column and the contract is a plain + * number: a depot measured in tens of gigabytes goes well past a 32-bit column + * and nowhere near the 9 petabytes a double counts exactly, so the conversion + * is safe in the direction it is made — and it is made here, once, rather than + * left for Zod to refuse at the end of a build nobody is watching. + */ +export function installGuards(template: { + installInactivityTimeoutMs: number | null; + installRequiredDiskBytes: bigint | null; +}): { inactivityTimeoutMs?: number; requiredDiskBytes?: number } { + // Tested by type rather than against `null`, so that a row read back without + // these columns — an older dump, a `select` written before they existed — + // says nothing rather than emitting a key holding `undefined`, which is the + // one shape this function exists to avoid producing. + return { + ...(typeof template.installInactivityTimeoutMs === 'number' + ? { inactivityTimeoutMs: template.installInactivityTimeoutMs } + : {}), + ...(typeof template.installRequiredDiskBytes === 'bigint' + ? { requiredDiskBytes: Number(template.installRequiredDiskBytes) } + : {}), + }; +} + /** * Decodes how a template says its servers are stopped. * diff --git a/apps/panel/src/modules/templates/template-sync.service.spec.ts b/apps/panel/src/modules/templates/template-sync.service.spec.ts index 77bc706..9a899c6 100644 --- a/apps/panel/src/modules/templates/template-sync.service.spec.ts +++ b/apps/panel/src/modules/templates/template-sync.service.spec.ts @@ -162,6 +162,35 @@ describe('TemplateSyncService.upsert', () => { expect(prisma.written[0]).toHaveProperty('stopTimeoutSeconds', null); }); + it('writes the two install guards', async () => { + // Neither is a figure the panel can supply on a template's behalf: the + // inactivity window belongs to the workload, and the disk requirement is + // something only whoever wrote the download knows. + const prisma = new RecordingPrisma(); + + await new TemplateSyncService(prisma.asService()).upsert( + definition({ installInactivityTimeoutMs: 900_000, installRequiredDiskBytes: 40 * 1024 ** 3 }), + ); + + expect(prisma.written[0]).toMatchObject({ + installInactivityTimeoutMs: 900_000, + installRequiredDiskBytes: 42_949_672_960, + }); + }); + + it('forgets install guards a definition has dropped', async () => { + // `undefined` means "leave the column alone" to Prisma, so without the + // explicit null a template whose author decided its install is allowed to + // take longer would go on being stopped by the window they removed. + const prisma = new RecordingPrisma(); + prisma.existing = { id: 7, modifiedByAdmin: false }; + + await new TemplateSyncService(prisma.asService()).upsert(definition()); + + expect(prisma.written[0]).toHaveProperty('installInactivityTimeoutMs', null); + expect(prisma.written[0]).toHaveProperty('installRequiredDiskBytes', null); + }); + it('leaves an administrator-edited template untouched', async () => { const prisma = new RecordingPrisma(); prisma.existing = { id: 7, modifiedByAdmin: true }; @@ -206,4 +235,16 @@ describe('the seed copy of the mapping', () => { // The string the structured field falls back to, still beside it. expect(mapping?.[1]).toMatch(/^\s*stopCommand:/m); }); + + it('writes the two install guards too', () => { + // Quieter again than the stop transport, which at least fails the first + // time somebody presses Stop. A seeded instance missing these installs with + // the daemon's default window and no declared disk requirement, and the + // difference only shows the day an install stalls or fills a node. + const seed = readFileSync(join(process.cwd(), 'prisma', 'seed.ts'), 'utf8'); + const mapping = /const data = \{(.*?)\n {4}\};/s.exec(seed); + + expect(mapping?.[1]).toMatch(/^\s*installInactivityTimeoutMs:/m); + expect(mapping?.[1]).toMatch(/^\s*installRequiredDiskBytes:/m); + }); }); diff --git a/apps/panel/src/modules/templates/template-sync.service.ts b/apps/panel/src/modules/templates/template-sync.service.ts index 435ecc5..bfdc274 100644 --- a/apps/panel/src/modules/templates/template-sync.service.ts +++ b/apps/panel/src/modules/templates/template-sync.service.ts @@ -132,6 +132,15 @@ export class TemplateSyncService { installContainer: definition.installContainer, installEntrypoint: definition.installEntrypoint, installScript: definition.installScript, + // The two install guards, and plain nulls for the same reason as + // `stopTimeoutSeconds` above: ordinary nullable columns, on which null + // says "this template names no figure" and the daemon supplies its own. + // Written on every sync rather than left undefined so that a template + // which *drops* a figure has the row forget it too — a stale inactivity + // window would go on stopping installations its author has decided are + // allowed to take longer. + installInactivityTimeoutMs: definition.installInactivityTimeoutMs ?? null, + installRequiredDiskBytes: definition.installRequiredDiskBytes ?? null, importedFromEgg: definition.importedFromEgg ?? null, }; } diff --git a/docs/security.md b/docs/security.md index 1f4dac0..01ff041 100644 --- a/docs/security.md +++ b/docs/security.md @@ -90,9 +90,108 @@ You have nothing to set for the following — it is the default behaviour: - **Short-lived console JWTs**, carrying the bearer's permissions, verified by the daemon — which also checks the origin of the WebSocket connection. - **Startup commands as templates**, never a concatenation handed to a shell. +- **A bounded install container**: the server's own memory limit, at least a whole core of CPU (its + own entitlement where that is more), a pids limit of its own — 512, rather than the server's, + since an operator who trimmed a small server's fork budget did not mean to forbid an unpacking + that runs `xargs -P` — never privileged, and `no-new-privileges` so nothing it drops in the + volume can gain more later. Docker's default capability set is dropped, and **seven are then + handed back**: `CHOWN`, `DAC_OVERRIDE`, `FOWNER`, `FSETID`, `KILL`, `SETUID` and `SETGID`. So + this container is deliberately **not** held as tightly as a server container, which keeps none of + the fourteen and does not run as root; an install script is a package manager unpacking as root + over a tree owned by the server's uid, which is precisely the work capabilities gate. What it + does not get is the part that matters: `MKNOD`, `NET_RAW`, `SETFCAP` and `AUDIT_WRITE` are gone, + so it cannot plant a device node in the volume, capture or forge frames on the bridge it shares + with every other server, write file capabilities onto a binary it leaves behind, or reach the + host's audit log. It is also the one container here whose environment a server's own user edits, + which is why that list is worth reading twice. +- **Installations that end**: the node's free space is checked before one starts and a shortfall + refused with both figures named — and with the filesystem they were read off named too, that + being the one the volume lives on rather than, necessarily, the one carrying Docker's storage. An + installation that stops making progress is torn down instead of holding a server in "installing" + for ever. Progress means what the container _does_ — the CPU the kernel charges it and the blocks + it reads and writes, both counted against its own cgroup, plus anything it prints — not whether + it is talking, because `curl -sSL` prints nothing at all while it downloads. Its network counters + are deliberately **not** watched: those count frames the interface accepted, including the + broadcast traffic a Linux bridge floods to every port on it, so watching them would make a + stalled install look busy on exactly the crowded nodes where one that never ends costs the most. +- **A Docker that stops answering fails loudly**, everywhere and by default. The daemon puts a + deadline on every request it makes to the Docker socket — one rule at the client rather than a + timer per call site, so a call added tomorrow is bounded without its author having to arrange it — + and abandons a request nothing has answered, closing the socket behind it. This matters most in + the install path, where `install` holds a server's operation queue: one unbounded round trip there + costs that server every later start, stop and reinstall until the daemon is restarted, with + nothing in the panel to say why. + + **Three things are deliberately outside it, and they are the same three every time.** The wait for + a container to _end_, taken up below. The streams — a server's console, its statistics, a pull's + progress — which are bounded up to the moment Docker hands them over and not one instant further, + because a quiet Minecraft server sends nothing down its console for hours by construction. And the + attach handshake, which is issued by hand rather than through the Docker library and so carries a + clock of its own. A pull's progress stream has a second guard instead: it + is abandoned when the registry stops sending, which is a bound on inactivity rather than duration, + since Docker reports progress per chunk of every layer. + + **The wait is the one to be exact about**, being the single exemption to a rule whose whole value + is that it has no others. The daemon asks it of two containers, both throwaway: the one that runs + the install script, and the one that hands the installed files back to the server's user. Nothing + waits that way on a **server** — a server's exit arrives as the end of its console stream, and its + cause from an `inspect` after the fact — so the call a clock would bound is an installation's, and + an install container still going after two hours is a Steam depot doing exactly what it was asked. + A cap on total duration is the one thing the install deadline above was built not to be. Nor is + the wait left unwatched for that: both call sites race it against that same deadline on activity, + so a container that stops doing anything is torn down and the wait abandoned with it. It is + bounded by progress rather than by the clock. The exemption itself is written against the + endpoint, which names no container, so it would cover a wait on a server too if anything here ever + asked for one — and that is the right way round, since bounding _that_ one really would report + every long-running server as a crash. + + **Four failures are reported without failing an installation**, and it is worth knowing which. + A failed ownership `chown`, because the files are already on the disk by then and the server may + simply need a reinstall before it can write into its own volume — and that holds however it + failed, a Docker that would not create or start the container it runs in included. A failed + _removal_ of the install container, for the same reason arrived at from the other end — the + installation worked, and what is left is a container on the node the console names so somebody + can clear it. A failed removal of the container the `chown` ran in, which is that same fault one + step later and is said as a line of its own rather than folded into the reclaim's verdict: + overwriting that verdict would lose the reason the ownership was never taken, and this container + is the one worth clearing first, since it still has the server's volume mounted. And a free-space + check that could not be made at all: a `statfs` the node cannot answer says so and installs + anyway, because refusing every installation on such a node would be a larger failure than the one + being guarded against. Read the disk check as a check: see below for what it is not. + - **An audit log** of every sensitive action, readable per server. - **Rate limiting** on authentication, on 2FA and on SFTP. +## What Hopper does not protect: the disk an installation writes + +**An install script can fill the node's disk, and nothing here stops it.** It runs as root with +`/mnt/server` bind-mounted from the host, and a bind mount carries no quota: `diskBytes` — the +server's disk limit — is the daemon's own accounting, applied to the file manager and to SFTP, and +the kernel knows nothing about it. A script that downloads two hundred gigabytes into `/mnt/server` +writes two hundred gigabytes, and a full node takes down every server on it, not only that one. + +This matters more than it looks, because install scripts routinely download from a URL held in a +**template variable** — and template variables are what a server's own user edits from the startup +page, under the `startup.update` permission alone. So the reach is not "an operator wrote a careless +egg"; it is "anyone with a server on the node". + +The free-space check that runs before an installation is a **preflight, not an enforcement**. It +refuses to start when the node is already short — which is the common accident, and worth refusing — +and then the script writes whatever it writes. There is deliberately no ceiling on `/tmp` either: one +was tried, and since the volume next to it has no ceiling it moved the problem rather than closing +it, while breaking every egg that stages a download in `/tmp`. + +A real quota is a **node-provisioning feature, and it does not exist yet** — an XFS project quota +per volume, or a loopback image per server, both decided when the node's storage is laid out rather +than by the panel. Until it does, an operator who wants a bound has one: put `system.dataDirectory` +on a filesystem of its own, so a runaway install fills that filesystem and not the one carrying +Docker's data root, the database and the daemon's logs. Watch its free space like any other. + +That bounds the common shape and not every shape, which is worth knowing before relying on it: a +script that stages its download in `/tmp` writes to the container's own layer, under Docker's data +root, and so lands on the filesystem the split was meant to protect. It is also the filesystem the +preflight above does **not** measure — that one reads the volume's, and says so when it refuses. + ## After an incident If you suspect credentials were stolen: diff --git a/docs/templates.md b/docs/templates.md index 43dbf0e..35362b6 100644 --- a/docs/templates.md +++ b/docs/templates.md @@ -360,6 +360,108 @@ Three rules learned from reading the existing scripts back: nothing. 3. Check what was downloaded — non-zero size, a checksum when the API publishes one. +#### Where a download goes, and what bounds it + +Nothing does. Neither `/tmp` nor `/mnt/server` carries a quota the kernel enforces: `/tmp` is the +container's own layer, which lives under Docker's data root on the host — `/var/lib/docker` unless +the operator moved it — and `/mnt/server` is a bind mount of the volume. The server's `diskBytes` limit is Hopper's accounting, applied to the file manager and to +SFTP — the install script is running as root under neither. A script that downloads two hundred +gigabytes writes two hundred gigabytes, and a full node takes every server on it down together. + +So the fourth rule is yours to keep: **download what you need and delete what you staged.** A modpack +archive unpacked into `/mnt/server` and then left next to its own contents doubles the server's real +footprint for no reason. + +Either directory works for staging, and `/tmp` is the tidier of the two: it goes away with the +container, so a failed install leaves nothing behind in the volume for the next one to trip over. It +is also the likelier of the two to run short — the container layer shares Docker's data root with +every image and every other container on the node, while `/mnt/server` may have been given a disk of +its own — so stage a very large download in `/mnt/server` and unpack it in place. + +A bounded `/tmp` was tried and removed. It could not close the hole, since the volume beside it has +no ceiling either, and it broke the commonest shape there is — `curl -o /tmp/pack.zip … && unzip` — +with a limit no template could declare. + +#### The inactivity deadline + +```ts +installInactivityTimeoutMs: 900_000, // optional — the daemon's own figure is 15 minutes +``` + +A deadline on **inactivity**, not on how long the installation takes. Nothing caps total duration: an +anonymous Steam depot takes an hour and is perfectly healthy throughout, and a cap large enough to +let it finish would never fire on anything, while one small enough to be useful would kill it. + +It is not a deadline on **output** either, and that distinction is the one to hold on to when sizing +the figure. Every script in this catalogue downloads with `curl -sSL`, and `-s` suppresses the +progress meter: a two-gigabyte transfer prints nothing at all from the first byte to the last. So +what Hopper watches is what the container _does_ — the CPU it burns, the blocks it reads and writes, +and its output. A container doing none of the three is not slow, it is finished. + +Those two counters are the kernel's own accounting for that container's cgroup, which is why a +silent download is never mistaken for a dead one: taking bytes off a socket and putting them on a +disk is work, and work is CPU time, however little of it a trickle costs. What is deliberately _not_ +watched is the container's network counters. They count frames its interface accepted rather than +work it did, and a node's servers all share one bridge — a bridge floods broadcast ARP to every port +on it — so a container that has stopped dead still shows traffic, and a deadline fed on that would +never fire on a busy node. + +The window is pushed back by any of the three. Output is taken from the raw stream rather than from +complete lines, so a progress bar rewriting one line with carriage returns counts too; the counters +are read from `docker stats` every fifteen seconds at the slowest, and every quarter of the window +wherever that is shorter — so a window under a minute is sampled more often than fifteen seconds, +down to a floor of one second. Below a four-second window the floor wins and the quarter stops +holding, which is a window too short to judge an installation on in any case. Reading the counters +rarely cannot miss activity, whatever the period works out at, because they only ever grow. + +When the window expires the install container is stopped and removed and the server lands in +`install_failed` with Reinstall available. What the console says depends on whether there was +anything to see. With at least one counter sample back inside that window it names what stood still +and for how long. With none at all it says that instead, and points at this node's Docker rather +than at the script — which may have been running perfectly, and which a stall message would have +sent its author combing through for nothing. + +Raise it for a script that genuinely idles — a wait on an external job, a licence check against a +slow endpoint, anything with a long `sleep` in it, since a sleeping container is doing nothing by +this definition and is meant to be. Lower it for a download that should never pause. Six hours is +the ceiling, and a template asking for more fails validation rather than being quietly capped. A +template that says nothing gets a quarter of an hour, which is chosen to be ignored by anything that +works. + +An older daemon ignores the field and waits for ever, as every daemon did before this existed. +Nothing is refused over it. + +#### How much disk the installation needs + +```ts +installRequiredDiskBytes: 40 * 1024 ** 3, // optional — only when the figure is knowable +``` + +Checked before the install container is created, and a shortfall is **refused** with both figures +named. A depot larger than the node's free space fills the host disk, and that takes down every +server on the machine. + +Checked against the free space on the volume's filesystem _plus what that volume already holds_, +because a reinstall writes over what is there — nothing wipes the volume first. Demanding the whole +requirement as free space would mean a 40 GiB server could never be reinstalled on the node it is +already installed on. The floor below is the exception: that one is measured against free space +alone, since a nearly full node is nearly full whatever a single volume holds. + +The volume's filesystem is the only one measured, and a refusal says so. A script that stages its +download in `/tmp` writes to the container layer instead, under Docker's storage — the same +filesystem on most nodes, a different one wherever an operator gave the volumes a disk of their own. +Declare what you download, and stage large downloads in `/mnt/server` where the check applies. + +Declare it when the size is knowable and large — a Steam depot's is on the store page. Leave it out +when it is not: a Minecraft server's size is whatever modpack the operator's variables point at, and +a guess here refuses installations that would have worked. Templates that say nothing still cannot +install onto a node with nothing left, because Hopper requires a floor of free space from every +installation. + +It is not the server's disk limit. That number is what the operator sells, weighed once already at +creation against the node's declared capacity and its overallocation setting; a 50 GiB plan that +will use 900 MiB has no business refusing to install on a node with 20 GiB free. + ## Configuration files `configFiles` describes the files Hopper patches at startup, so the server really listens on the diff --git a/packages/shared/src/contract/server-configuration.spec.ts b/packages/shared/src/contract/server-configuration.spec.ts index 7092b4d..1601050 100644 --- a/packages/shared/src/contract/server-configuration.spec.ts +++ b/packages/shared/src/contract/server-configuration.spec.ts @@ -266,6 +266,57 @@ describe('readiness deadlines', () => { }); }); +/** + * What a template says about surviving its own installation. + * + * Both fields are optional and both mean "this template did not say" when + * absent — the daemon owns the fallbacks, because the timer is armed there and + * only the node knows what is left on its own disk. + */ +describe('the install guards', () => { + const withInstall = (install: Record) => + serverConfigurationSchema.safeParse({ + ...MINIMAL, + install: { containerImage: 'debian:bookworm-slim', script: 'set -e', ...install }, + }); + + it('leaves an install that declares neither exactly as it was', () => { + // The whole bundled catalogue and every imported egg. No default is + // materialised here on purpose: a defaulted key would be written into the + // payload of every server on every installation, including the ones bound + // for a node whose daemon has never heard of the field. + const parsed = serverConfigurationSchema.parse({ + ...MINIMAL, + install: { containerImage: 'debian:bookworm-slim', script: 'set -e' }, + }); + + expect(JSON.stringify(parsed.install)).toBe( + '{"containerImage":"debian:bookworm-slim","entrypoint":"/bin/bash","script":"set -e"}', + ); + }); + + it('carries an inactivity window and a download size', () => { + const parsed = withInstall({ inactivityTimeoutMs: 900_000, requiredDiskBytes: 40 * 1024 ** 3 }); + + expect(parsed.success && parsed.data.install?.inactivityTimeoutMs).toBe(900_000); + expect(parsed.success && parsed.data.install?.requiredDiskBytes).toBe(42_949_672_960); + }); + + it.each([0, -1, 1.5, 7 * 3_600_000])( + 'refuses %s as an inactivity window', + (inactivityTimeoutMs) => { + // Zero and negatives are a deadline that has already expired. The ceiling + // is six hours: past that a deadline on doing *nothing* is not a deadline, + // and a template needing more is not slow, it is broken. + expect(withInstall({ inactivityTimeoutMs }).success).toBe(false); + }, + ); + + it('refuses a negative download size', () => { + expect(withInstall({ requiredDiskBytes: -1 }).success).toBe(false); + }); +}); + /** * A port that has a name. * diff --git a/packages/shared/src/contract/server-configuration.ts b/packages/shared/src/contract/server-configuration.ts index 45e3331..5f4b195 100644 --- a/packages/shared/src/contract/server-configuration.ts +++ b/packages/shared/src/contract/server-configuration.ts @@ -295,6 +295,83 @@ export const installConfigurationSchema = z.object({ containerImage: z.string().min(1), entrypoint: z.string().min(1).default('/bin/bash'), script: z.string(), + + /** + * How long the installation may **do nothing at all** before the daemon gives + * up on it. + * + * A deadline on inactivity, not on duration, and the distinction is the whole + * field. A forty-gigabyte Steam depot that is pulling bytes down a wire is + * alive — taking them off the socket is work, and work is CPU time charged to + * its cgroup; one whose container has burned no CPU, touched no disk and + * printed nothing for a quarter of an hour is not. A cap on total duration + * cannot tell those apart: set high enough to let a real depot finish it never + * fires on anything, and set low enough to be useful it kills the installs it + * was meant to protect. + * + * Inactivity and not silence, which is the correction worth recording because + * the mistake was made here first. Nearly every install script in existence + * downloads with `curl -sSL`, and `-s` suppresses the progress meter: the + * transfer emits not one byte of output from start to finish. A deadline on + * *output* would therefore have been a total-duration cap applied to precisely + * the step that legitimately takes hours — a 2 GiB modpack on a slow uplink is + * a working install it would have killed. What the daemon watches is what the + * container does; see `INSTALL_INACTIVITY_DEFAULT_MS` there. + * + * Optional, and deliberately without a default *here*. The daemon supplies one + * because that is where the timer is armed, and because a default materialised + * in this schema would be written into every configuration payload the panel + * sends, including the ones bound for a node whose daemon has never heard of + * the field. Absent therefore means "this template did not say", and the node + * running the install decides what that is worth. + * + * An older daemon strips the field, as Zod discards what it does not know, and + * goes on waiting for ever — which is exactly what it does today. That is a + * guard not applied, not a configuration misread, so nothing gates on it: no + * capability, no refusal, no server that cannot be placed on an older node + * over a timeout it would have been given. + */ + inactivityTimeoutMs: z + .number() + .int() + .positive() + .max(6 * 3_600_000) + .optional(), + + /** + * What this installation is expected to write, in bytes, when the template + * knows. + * + * Checked before the install container is created, and a shortfall is + * **refused**. Filling a node's disk is not one server's failure: + * `/var/lib/docker` and every other server's volume are on that filesystem, + * and the whole machine goes down with it. + * + * Checked against the free space on the volume's filesystem *plus what the + * volume already holds*, because nothing wipes it first: a reinstall writes + * over the files that are there, so their space counts towards the figure and + * not against it. Demanding the whole of it as free would mean a 40 GiB + * Palworld server could never be reinstalled on the node it is already + * installed on. + * + * Only a template can answer this, and only for some games. A Steam depot has + * a knowable size; a Minecraft server's is whatever modpack the operator's + * variables point at, so most templates say nothing and the daemon falls back + * to requiring a floor of headroom rather than inventing a figure. + * + * Deliberately **not** `build.diskBytes`. That number is a policy ceiling the + * operator sells, not a prediction: a 50 GiB Minecraft server that will use + * 900 MiB would start refusing to install on a node with 20 GiB free, and the + * panel has already weighed it once at creation, against the node's declared + * capacity and the overallocation percentage the operator chose. Reading it + * again here would overrule that decision from the far end of the wire. + * + * An older daemon strips this too and installs with no preflight at all, + * which is what every daemon did until now. Ungated for the same reason as + * the field above: a node that cannot honour a new guard is a node without + * the guard, not a node that misreads the configuration. + */ + requiredDiskBytes: z.number().int().nonnegative().optional(), }); export const serverConfigurationSchema = z.object({ diff --git a/packages/templates/src/definition.spec.ts b/packages/templates/src/definition.spec.ts index fd70502..eb320af 100644 --- a/packages/templates/src/definition.spec.ts +++ b/packages/templates/src/definition.spec.ts @@ -188,3 +188,49 @@ describe('templateDefinitionSchema stop', () => { expect(() => templateDefinitionSchema.parse({ ...MINIMAL, stopTimeoutSeconds: 601 })).toThrow(); }); }); + +/** + * What a template is allowed to say about its own installation. + * + * The same additive rule as the two above, and it matters more here than + * anywhere: an installation is the one operation a server cannot retry + * automatically, so a field that changes what a silent template means would + * turn working installs into failed ones on a catalogue nobody edited. + */ +describe('templateDefinitionSchema install guards', () => { + it('leaves a template that declares neither exactly as it was', () => { + const parsed = templateDefinitionSchema.parse(MINIMAL); + + // Undefined, not a figure: "this template did not say", which the daemon + // answers with its own generous window and its own floor of free space. + expect(parsed.installInactivityTimeoutMs).toBeUndefined(); + expect(parsed.installRequiredDiskBytes).toBeUndefined(); + }); + + it('keeps the figures a template chooses', () => { + const parsed = templateDefinitionSchema.parse({ + ...MINIMAL, + installInactivityTimeoutMs: 900_000, + installRequiredDiskBytes: 40 * 1024 ** 3, + }); + + expect(parsed.installInactivityTimeoutMs).toBe(900_000); + expect(parsed.installRequiredDiskBytes).toBe(42_949_672_960); + }); + + it('refuses figures the contract would not accept', () => { + // The same bounds as the contract's own fields, checked here so the mistake + // fails on the template that made it rather than on a node months later — + // where the symptom is an installation that stops itself for no reason a + // console line can explain. + expect(() => + templateDefinitionSchema.parse({ ...MINIMAL, installInactivityTimeoutMs: 0 }), + ).toThrow(); + expect(() => + templateDefinitionSchema.parse({ ...MINIMAL, installInactivityTimeoutMs: 7 * 3_600_000 }), + ).toThrow(); + expect(() => + templateDefinitionSchema.parse({ ...MINIMAL, installRequiredDiskBytes: -1 }), + ).toThrow(); + }); +}); diff --git a/packages/templates/src/definition.ts b/packages/templates/src/definition.ts index 22ba889..65aeec2 100644 --- a/packages/templates/src/definition.ts +++ b/packages/templates/src/definition.ts @@ -121,6 +121,65 @@ export const templateDefinitionSchema = z.object({ installEntrypoint: z.string().default('/bin/bash'), installScript: z.string().min(1), + /** + * How long this template's installation may **do nothing at all** before the + * daemon stops it. + * + * On inactivity, not on total duration, and a template author has to hold that + * distinction to pick a figure: an anonymous Steam depot takes an hour to + * download and is healthy throughout, so what is being sized here is the + * longest pause in the work, not the length of the install. + * + * Not on output either, which is the trap this field was nearly built into. + * The scripts in this very catalogue download with `curl -sSL`, and `-s` + * suppresses the progress meter: a two-gigabyte transfer prints nothing from + * beginning to end. So the daemon watches the CPU and the block I/O the kernel + * charges the container as well as its output — its network counters + * deliberately not, since those count frames the interface accepted rather + * than work it did — and a template author sizing this figure should be + * thinking about how long the work could plausibly stand completely still, not + * how long it could stay quiet. + * + * Optional, and a template that says nothing gets the daemon's own figure — + * a quarter of an hour, chosen to be ignored by anything that works. Raise it + * for a script that genuinely idles: a wait on an external job, a licence + * check that blocks on a slow endpoint. Lower it for a download that should + * never pause at all, and get told sooner. + * + * A node running a daemon that predates the field ignores it and waits for + * ever, which is what every node did until now. Nothing is refused over it. + */ + installInactivityTimeoutMs: z + .number() + .int() + .positive() + .max(6 * 3_600_000) + .optional(), + + /** + * How much free disk this template's installation needs, in bytes. + * + * The daemon checks it against the volume's filesystem before the install + * container is created, and **refuses** a shortfall — filling a node's disk + * takes down every server on the machine, not only this one. What the volume + * already holds counts towards the figure rather than against it, because a + * reinstall writes over those files; otherwise no large server could ever be + * reinstalled on the node it is already installed on. + * + * Declare it when the figure is knowable and large: a Steam depot has a size + * the store page states, and it is the whole reason this field exists. Leave + * it out when it is not — a Minecraft server's size is whatever modpack the + * operator's variables point at, and a guess here refuses installations that + * would have worked. A template that says nothing still cannot install onto a + * node with nothing left: the daemon requires a floor of headroom from + * everything. + * + * Not the server's disk limit, which is a different question the panel has + * already answered against the node's declared capacity. This is what the + * installation writes, and it is the template that knows. + */ + installRequiredDiskBytes: z.number().int().nonnegative().optional(), + variables: z.array(templateVariableDefinitionSchema).default([]), /** UUID of the original Pterodactyl egg, to avoid double imports. */