From 42c0d2b51ca0d5fdb8cb42cb24a712d5f8a1f401 Mon Sep 17 00:00:00 2001 From: aaldersondev Date: Fri, 7 Aug 2026 23:17:27 +0200 Subject: [PATCH] feat(daemon): an installation that downloads for an hour, and one that has stopped MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Palworld cannot be shipped until an installation can survive a Steam depot, and two things stood in the way. `waitForExit` was a bare `container.wait()` with no bound at all, so an install that stalled on a dead mirror left the server in `installing` for ever and nothing gave up. And there was no disk check anywhere in the daemon: a depot larger than the node's free space filled the host disk, which takes down every server on that machine. **The deadline measures inactivity, and inactivity is what the container does rather than what it says.** The first cut watched output. That premise is false here: every bundled install script downloads with `curl -sSL`, and `-s` suppresses the progress meter, so the transfer emits nothing at all from beginning to end — a two-gigabyte modpack on a slow uplink is a working install that a silence window would have killed. The second cut added network counters, which was worse in a subtler way. `stats.networks[*].rx_bytes` is a link-layer interface counter: every server on a node shares one bridge, a bridge floods broadcast ARP to every port, and curl keeps TCP keepalives on. A stalled install kept looking alive on exactly the busy nodes where an endless one costs most. What is watched is what the kernel charges the container's own cgroup — CPU time and block I/O — plus its output. A transfer that is moving burns CPU on every packet it takes off the socket; one that is blocked on a dead socket burns none and issues no I/O. A host that keeps neither counter reports nothing rather than zero, because "this host does not measure it" and "this container did nothing" are opposite answers and folding them together would kill every install on such a node. **Docker is bounded once, at the client.** Four successive reviews each found more unbounded round trips — the pull's progress stream, then create, attach and start, then the reclaim's four, then `removeIfExists`, the stats sample, `listImages`. Bounding them one `Promise.race` at a time was the wrong shape: with no rule, every call is a fresh chance to forget. `DockerClient` now wraps its own `modem.dial`, the one seam every dockerode method passes through, so a call added tomorrow is bounded without its author knowing the rule exists. The exceptions are named and tested: the wait for a container to end, and the streams, which are held open by design and whose deadline covers only the answer. Space is checked before the image is pulled, against the volume's own filesystem, and a shortfall is refused rather than warned about — with the numbers and the filesystem named. A reinstall counts what the volume already holds towards the requirement, since nothing wipes it first; without that a forty-gigabyte server could never be reinstalled. Deliberately not here: resuming an install a daemon restart interrupted, and real disk quotas. Those are node-provisioning features that Steam merely exposes. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01QL3QL3ReEa9Sk68mxJW6Fu --- apps/daemon/src/docker/client.spec.ts | 508 +++- apps/daemon/src/docker/client.ts | 453 ++- apps/daemon/src/server/disk-usage.spec.ts | 86 +- apps/daemon/src/server/disk-usage.ts | 76 +- apps/daemon/src/server/installer.spec.ts | 2512 ++++++++++++++++- apps/daemon/src/server/installer.ts | 1637 ++++++++++- .../daemon/src/server/server-instance.spec.ts | 111 +- apps/daemon/src/server/server-instance.ts | 9 + apps/daemon/src/server/stats.spec.ts | 97 + apps/daemon/src/server/stats.ts | 123 + .../migration.sql | 49 + apps/panel/prisma/schema.prisma | 36 + apps/panel/prisma/seed.ts | 7 + .../server-configuration.service.spec.ts | 79 + .../servers/server-configuration.service.ts | 40 + .../templates/template-sync.service.spec.ts | 41 + .../templates/template-sync.service.ts | 9 + docs/security.md | 99 + docs/templates.md | 102 + .../src/contract/server-configuration.spec.ts | 51 + .../src/contract/server-configuration.ts | 77 + packages/templates/src/definition.spec.ts | 46 + packages/templates/src/definition.ts | 59 + 23 files changed, 6217 insertions(+), 90 deletions(-) create mode 100644 apps/panel/prisma/migrations/20260808000000_template_install_guards/migration.sql 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. */