diff --git a/server/src/modules/lifecycle.js b/server/src/modules/lifecycle.js new file mode 100644 index 0000000..f6f837a --- /dev/null +++ b/server/src/modules/lifecycle.js @@ -0,0 +1,208 @@ +// ── Module lifecycle dispatch ────────────────────────────────────────────── +// +// Phase 2, PR 5 of docs/website/MODULE_SYSTEM.md §2.7. Normative contract: +// docs/website/MODULE_API.md §2.5 (the hooks and when they run) and §4.4 +// (failure is a state), plus MODULE_SYSTEM.md §2.4 (what a boot does to +// `installed_modules`). +// +// This is the database half of the loader, and it is a separate file for the +// same reason modules/schema.js is: `scripts/routeManifest.js` and +// `swagger/swagger.js` both require app.js with the pool pointed at a dead port, +// so loader.js may not reach the database. Everything here runs from server.js, +// after ensureSchema() has proved the database is up. +// +// The two halves meet at exactly one place — `loader.setState()` — so the +// in-memory record that the §4.5 dispatch guard reads and the row the admin +// panel reads are moved together and cannot disagree. +// +// Two properties this file exists to keep: +// +// 1. **A module's boot failure costs that module and nothing else** (§4.4). +// Its routes stay mounted and answer 503; the site comes up; the next +// module boots as if nothing happened. +// 2. **The row is a record of what happened, never the source of truth for +// what is mounted** (§2.4). Nothing here mounts, unmounts or re-scans. It +// reads the outcome of a scan that already happened and writes it down. + +const log = require('../utils/logger')('modules') + +// §2.5: shutdown races the process being killed, so a module that will not let +// go is logged and skipped rather than allowed to hang the exit. `onBoot` has no +// such budget on purpose — it delays the listener binding, which is the feature. +const SHUTDOWN_BUDGET_MS = 5000 + +/** + * Run one database call for one module without letting it become everyone's + * failure. Returns null on failure, having logged it. + * + * The boot path is the whole reason this exists. A row that will not update is + * bad — the admin panel shows the wrong thing — but it is strictly less bad than + * a site that will not start, and it must not stop the modules after it from + * booting. + */ +async function safe(what, fn) { + try { + return await fn() + } catch (err) { + log.error(`module bookkeeping failed: ${what}`, { error: err.message }) + return null + } +} + +/** + * Reconcile `installed_modules` with what the loader found, then run every + * surviving module's `onBoot`. + * + * Called once from server.js, after `ensureSchema()` (so a module's own tables + * exist) and `seedDefaults()`, and **before the HTTP listener binds** — a module + * that must not serve traffic until it has warmed a cache gets that for free + * (§2.5). + * + * The order of the four steps is the whole design: + * + * 1. `beginBoot()` clears the last boot's outcomes, so what is on display + * afterwards is what THIS boot did. `disabled` rows are left alone: that is + * an operator decision, not an outcome (§2.4). + * 2. Every module on the volume gets a row, written with null provenance if it + * does not have one — a directory placed on the volume by hand is a + * supported install (§2.4/§2.5), and without a row it could never be + * disabled or shown as failed. + * 3. Rows with no directory are marked failed, because step 1 has just reset + * them to `enabled` and a row claiming to be enabled for a module that is + * not there is the one state that is simply untrue. (A plain uninstall + * leaves `disabled`, which step 1 never touches, so this only catches a + * directory deleted by hand.) + * 4. The outcome each module already carries — disabled by the operator, + * failed during load or schema replay, or ready — is written down, and only + * then is `onBoot` dispatched. + * + * Never throws. @param {object} [deps] injection seam for tests. + */ +async function boot({ modules, model } = {}) { + /* eslint-disable global-require */ + const loader = modules || require('./loader') + const rows = model || require('../model/modules/modules.model') + /* eslint-enable global-require */ + + // Not an error, and the same guard replayFragments carries: a process that + // never required app.js has no scan to reconcile against, and writing rows + // from an empty list would mark every installed module as missing. + if (!loader.isLoaded()) { + log.info('no module scan in this process — skipping module boot') + return + } + + const scanned = loader.list() + + await safe('resetting last boot\'s outcomes', () => rows.beginBoot()) + + for (const m of scanned) { + await safe(`recording module "${m.id}"`, () => rows.recordInstalled({ + id: m.id, + name: m.name, + version: m.version, + // Null provenance is what a hand-placed directory looks like. An install + // performed through the admin panel (§2.5, a later phase) writes the row + // with its source and hash first; this refresh deliberately does not + // overwrite either, because recordInstalled leaves what it is not given. + })) + } + + const stored = (await safe('reading module rows', () => rows.list())) || [] + const onVolume = new Set(scanned.map((m) => m.id)) + + for (const row of stored) { + if (onVolume.has(row.id) || row.state === 'disabled') continue + await safe(`marking module "${row.id}" missing`, () => rows.markStartupFailed(row.id, { + stage: 'require', + reason: 'module directory not present on the volume', + })) + } + + const disabled = new Set(stored.filter((r) => r.state === 'disabled').map((r) => r.id)) + + for (const m of scanned) { + // The operator's switch wins over everything, including a failure. Its + // routes 404 from here on (§4.5 — the leg that was unreachable until this + // PR), it is not booted, and its failure is not re-recorded: overwriting a + // deliberate `disabled` with an outcome would silently re-enable it on the + // next boot. + if (disabled.has(m.id)) { + loader.setState(m.id, 'disabled') + continue + } + if (m.state === 'startup_failed') { + // Already failed in load() or the schema replay — both of which ran before + // the database was available to write it down. This is where it lands. + await safe(`recording failure for "${m.id}"`, () => rows.markStartupFailed(m.id, { + stage: m.stage, + reason: m.reason, + })) + } + } + + for (const { id, hook, ctx } of loader.bootable()) { + try { + // Awaited without a timeout, deliberately (§2.5): a slow onBoot delays the + // listener, which is the contract's promise to a module that must warm up + // before it serves. Core's own boot steps are awaited the same way. + if (hook) await hook(ctx) + loader.setState(id, 'started') + await safe(`marking module "${id}" started`, () => rows.markStarted(id)) + log.info(`module "${id}" started`) + } catch (err) { + // §4.4's second column: the routes are already mounted, so they stay + // mounted and answer 503. A module that failed to warm up serving + // half-initialised data is worse than one that says it is down. + loader.setState(id, 'startup_failed', { stage: 'boot', reason: err.message }) + await safe(`recording boot failure for "${id}"`, () => rows.markStartupFailed(id, { + stage: 'boot', + reason: err.message, + })) + log.error(`module "${id}" onBoot failed — its routes will answer 503`, { + reason: err.message, + }) + } + } +} + +/** Reject if `fn`'s promise has not settled within `ms`. */ +function withBudget(fn, ms) { + let timer + const budget = new Promise((_, reject) => { + timer = setTimeout(() => reject(new Error(`onShutdown exceeded its ${ms}ms budget`)), ms) + }) + return Promise.race([Promise.resolve().then(fn), budget]).finally(() => clearTimeout(timer)) +} + +/** + * Run every started module's `onShutdown`, in reverse registration order. + * + * Called from server.js's signal handler before anything core owns is closed, so + * a module still has a working database pool and push dispatcher to flush + * through. Reverse order is the mirror of boot order: a module that booted after + * another may be holding something the earlier one handed it. + * + * Never throws, and never hangs: each hook gets `SHUTDOWN_BUDGET_MS`, after + * which it is logged and abandoned. Abandoned, not cancelled — nothing can stop + * a promise that is still running — but the process is exiting anyway, and the + * alternative is a shard host where `systemctl stop` hangs until SIGKILL. + */ +async function shutdown({ modules, budgetMs = SHUTDOWN_BUDGET_MS } = {}) { + // eslint-disable-next-line global-require + const loader = modules || require('./loader') + if (!loader.isLoaded()) return + + for (const { id, hook } of loader.shutdownHooks()) { + try { + await withBudget(hook, budgetMs) + log.info(`module "${id}" shut down`) + } catch (err) { + log.warn(`module "${id}" onShutdown failed or timed out — continuing`, { + error: err.message, + }) + } + } +} + +module.exports = { boot, shutdown, SHUTDOWN_BUDGET_MS } diff --git a/server/src/modules/loader.js b/server/src/modules/loader.js index d223959..bbc3aa1 100644 --- a/server/src/modules/loader.js +++ b/server/src/modules/loader.js @@ -18,15 +18,19 @@ // boot (§4.4). // // What is deliberately NOT here yet, each landing with the PR that first calls -// it (§2.7): the three de-entanglement registries (PR 4), boot/shutdown hook -// dispatch and the `installed_modules` reconcile (PR 5), GET -// /api/v1/public/modules and the client chunk's static mount (PRs 6-7). Until -// PR 5 the state a module carries is in memory only. +// it (§2.7): GET /api/v1/public/modules and the client chunk's static mount +// (PRs 6-7). // // PR 3 added the fragment half of the schema story: this file VALIDATES a // fragment (statement by statement, at load time, before anything is mounted) // and publishes it through `fragments()`. Replaying it needs a database, so it // belongs to modules/schema.js, which utils/db.js calls after core's schema. +// +// PR 5 added the lifecycle hooks a module registers here (`onBoot`/`onShutdown`) +// and the failure STAGE carried beside every reason. Dispatching those hooks and +// reconciling `installed_modules` need a database, so they live in +// modules/lifecycle.js for the same reason schema.js is a separate file: this one +// stays require-able against a dead pool. const fs = require('fs') const path = require('path') @@ -145,11 +149,10 @@ function buildApi(record) { if (record.called.has(name)) throw new Error(`${name}() called twice`) record.called.add(name) } - // PR 5 brings the boot hooks. They throw rather than no-op: an accepting stub - // would let a module believe it had registered something and fail silently at - // the far end. - const notYet = (name, pr) => () => { - throw new Error(`${name}: not available until phase 2 PR ${pr}`) + const hook = (name) => (fn) => { + once(name) + if (typeof fn !== 'function') throw new Error(`${name}: expected a function`) + record.hooks[name] = fn } return { registerRoutes(mounts) { @@ -180,13 +183,34 @@ function buildApi(record) { record.staged.registerNotificationStreams(streams) }, registerAnnounceLeg: record.staged.registerAnnounceLeg, - onBoot: notYet('onBoot', 5), - onShutdown: notYet('onShutdown', 5), + // The two lifecycle hooks (§2.5). Registered here, dispatched from + // lifecycle.js — this file runs with no database and the hooks run with one. + // Both are optional: a module with no warm-up and nothing to close simply + // never calls them. + onBoot: hook('onBoot'), + onShutdown: hook('onShutdown'), } } // ── Validation ───────────────────────────────────────────────────────────── +/** + * Throw with the §4.3 step that failed attached. + * + * `installed_modules.failure_stage` exists so the admin panel can say *where* a + * module broke and not only what the message was, and the model enumerates the + * eight stages (`FAILURE_STAGES`). The steps that share one function — a + * manifest read that also checks `coreApi`, the mounts and the slots — cannot be + * told apart by position in load(), so they carry their own label; everything + * else is inferred from how far load() had got. An untagged error is recorded + * against the step that was running, never guessed at. + */ +function fail(stage, message) { + const err = new Error(message) + err.stage = stage + throw err +} + // Table names a module may create despite not carrying its own id as a prefix. // // module-uo's twenty-seven tables predate the module system by two years, and @@ -305,42 +329,42 @@ function readManifest(dir, id, tierRouters) { for (const key of Object.keys(manifest)) { // Rejected, not ignored: a typo'd key must be a loud failure rather than a // silently inert setting the operator believes they configured. - if (!MANIFEST_KEYS.has(key)) throw new Error(`unknown key "${key}" in module.json`) + if (!MANIFEST_KEYS.has(key)) fail('manifest', `unknown key "${key}" in module.json`) } - if (!ID.test(manifest.id || '')) throw new Error(`invalid id "${manifest.id}"`) - if (manifest.id !== id) throw new Error(`id "${manifest.id}" does not match directory "${id}"`) - if (!manifest.version) throw new Error('missing version') - if (!manifest.coreApi) throw new Error('missing coreApi') + if (!ID.test(manifest.id || '')) fail('manifest', `invalid id "${manifest.id}"`) + if (manifest.id !== id) fail('manifest', `id "${manifest.id}" does not match directory "${id}"`) + if (!manifest.version) fail('manifest', 'missing version') + if (!manifest.coreApi) fail('core_api', 'missing coreApi') if (!semver.satisfies(MODULE_API_VERSION, manifest.coreApi)) { - throw new Error(`needs core API ${manifest.coreApi}, this core is ${MODULE_API_VERSION}`) + fail('core_api', `needs core API ${manifest.coreApi}, this core is ${MODULE_API_VERSION}`) } for (const [tier, prefixes] of Object.entries(manifest.mounts || {})) { - if (!TIERS.includes(tier)) throw new Error(`unknown tier "${tier}" in mounts`) + if (!TIERS.includes(tier)) fail('mounts', `unknown tier "${tier}" in mounts`) for (const prefix of prefixes) { - if (!PREFIX.test(prefix)) throw new Error(`bad prefix "${prefix}" in mounts.${tier}`) + if (!PREFIX.test(prefix)) fail('mounts', `bad prefix "${prefix}" in mounts.${tier}`) if (ownedByCore(tierRouters[tier], prefix)) { - throw new Error(`prefix ${tier}${prefix} is owned by core`) + fail('mounts', `prefix ${tier}${prefix} is owned by core`) } for (const other of modules.values()) { if ((other.manifest.mounts?.[tier] || []).includes(prefix)) { - throw new Error(`prefix ${tier}${prefix} already registered by module "${other.id}"`) + fail('mounts', `prefix ${tier}${prefix} already registered by module "${other.id}"`) } } } } for (const slot of manifest.extensions || []) { - if (!registries.hasSlot(slot)) throw new Error(`unknown extension slot "${slot}"`) + if (!registries.hasSlot(slot)) fail('extensions', `unknown extension slot "${slot}"`) } if (manifest.schema && !manifest.purge) { // A module that can create tables and cannot drop them leaves an operator // with orphaned data and no supported way to remove it. - throw new Error('declares schema but no purge') + fail('schema', 'declares schema but no purge') } if (manifest.purge && !fs.existsSync(path.join(dir, manifest.purge))) { - throw new Error(`purge file "${manifest.purge}" is missing`) + fail('schema', `purge file "${manifest.purge}" is missing`) } return manifest } @@ -409,20 +433,34 @@ function load(tierRouters) { staged: registries.stage(id), tables: new Set(), called: new Set(), + hooks: { onBoot: null, onShutdown: null }, + ctx: null, state: 'installed', + stage: null, reason: null, } + // How far load() has got, so an untagged throw is recorded against the step + // that was actually running (§4.3's steps 5-7). The steps before it label + // themselves, because readManifest covers four of them in one pass. + let stage = 'manifest' try { record.manifest = readManifest(dir, id, tierRouters) + stage = 'schema' record.tables = tablesOf(dir, record.manifest) checkTableNames(id, record.tables) if (record.manifest.server) { const entry = path.join(dir, record.manifest.server) + stage = 'require' // eslint-disable-next-line global-require, import/no-dynamic-require const register = require(entry) if (typeof register !== 'function') throw new Error(`${record.manifest.server} does not export a function`) - register(buildCtx(id, dir), buildApi(record)) + stage = 'register' + // Kept on the record, not discarded after register(): §2.5 hands the + // same ctx to onBoot, and building a second one would be a second frozen + // object claiming to be the same handle. + record.ctx = buildCtx(id, dir) + register(record.ctx, buildApi(record)) checkDeclared(record) } record.state = 'registered' @@ -434,10 +472,14 @@ function load(tierRouters) { // A failure here is BEFORE any route was mounted, so this module's routes // and nav are simply absent and the site comes up without it (§4.4). record.state = 'startup_failed' + record.stage = err.stage || stage record.reason = err.message record.manifest = record.manifest || { id, version: 'unknown' } modules.set(id, record) - log.error(`module "${id}" failed to load — continuing without it`, { reason: err.message }) + log.error(`module "${id}" failed to load — continuing without it`, { + stage: record.stage, + reason: err.message, + }) } } @@ -455,6 +497,7 @@ function load(tierRouters) { registries.apply(record.staged.staged) } catch (err) { record.state = 'startup_failed' + record.stage = 'register' record.reason = err.message log.error(`module "${record.id}" failed to register — continuing without it`, { reason: err.message, @@ -502,20 +545,25 @@ const RECORD_STATES = new Set(['registered', 'started', 'disabled', 'startup_fai * Move a loaded module to a new state — the POST-mount transitions. * * Called by whoever ran the step that failed or the step that succeeded, because - * only they can know: PR 3's `ensureSchema()` replays the fragments, PR 5's boot - * dispatch runs `onBoot` and reconciles `installed_modules` (whose `disabled` - * rows are what first make the guard's 404 leg reachable). + * only they can know: `ensureSchema()` replays the fragments (PR 3), and + * lifecycle.js runs `onBoot` and reconciles `installed_modules` (whose `disabled` + * rows are what make the guard's 404 leg reachable). + * + * The stage travels with the reason and is cleared by every non-failing move, + * for the same reason the database columns are (§2.4): a running module must + * never be able to show a stale failure. * * Unknown ids are ignored rather than thrown on: a module can be absent from the * volume and still have a row, and a caller on the boot path must not turn that * into everyone's failure. */ -function setState(id, state, reason = null) { +function setState(id, state, { stage = null, reason = null } = {}) { if (!RECORD_STATES.has(state)) throw new Error(`unknown module state "${state}"`) const record = modules.get(id) if (!record) return record.state = state - record.reason = reason + record.stage = state === 'startup_failed' ? stage : null + record.reason = state === 'startup_failed' ? reason : null } // ── Introspection ────────────────────────────────────────────────────────── @@ -550,11 +598,48 @@ function list() { name: r.manifest.name || r.id, version: r.manifest.version, state: r.state, + stage: r.stage, reason: r.reason, capabilities: r.manifest.capabilities || [], })) } +/** + * The modules that are ready to be booted, with their hook, in scan order. + * + * `registered` only — the state a module holds between a clean load and its + * `onBoot`. One that failed validation or schema replay is not going to run, and + * one already `started` has run. A module with no `onBoot` is still listed: it + * has nothing to warm up, but it still has to reach `started` so the admin panel + * and `installed_modules` agree with the guard about what is serving. + * + * @returns {{id: string, hook: Function|null, ctx: object|null}[]} + */ +function bootable() { + assertLoaded('bootable') + return [...modules.values()] + .filter((r) => r.state === 'registered') + .map((r) => ({ id: r.id, hook: r.hooks.onBoot, ctx: r.ctx })) +} + +/** + * The shutdown hooks to run, in REVERSE registration order (§2.5). + * + * `started` only. A module whose `onBoot` threw is mid-way through a warm-up it + * never finished, and calling its `onShutdown` would hand it a half-built world + * to tear down — the one thing worse than not closing cleanly. Reverse order is + * the same reasoning applied between modules rather than within one. + * + * @returns {{id: string, hook: Function}[]} + */ +function shutdownHooks() { + assertLoaded('shutdownHooks') + return [...modules.values()] + .filter((r) => r.state === 'started' && r.hooks.onShutdown) + .map((r) => ({ id: r.id, hook: r.hooks.onShutdown })) + .reverse() +} + /** * Every schema fragment waiting to be replayed, in scan order. * @@ -575,4 +660,4 @@ function fragments() { /** Absolute path of the modules directory. */ const dir = () => MODULES_DIR -module.exports = { load, list, setState, fragments, isLoaded, dir } +module.exports = { load, list, setState, fragments, bootable, shutdownHooks, isLoaded, dir } diff --git a/server/src/modules/schema.js b/server/src/modules/schema.js index 13b59d0..b1df79c 100644 --- a/server/src/modules/schema.js +++ b/server/src/modules/schema.js @@ -73,7 +73,7 @@ async function replayFragments({ query, modules } = {}) { } log.info(`schema ensured for module "${id}"`, { statements: statements.length }) } catch (err) { - loader.setState(id, 'startup_failed', err.message) + loader.setState(id, 'startup_failed', { stage: 'schema', reason: err.message }) log.error(`module "${id}" schema fragment failed — its routes will answer 503`, { reason: err.message, }) diff --git a/server/src/server.js b/server/src/server.js index e6e7afa..8055468 100644 --- a/server/src/server.js +++ b/server/src/server.js @@ -17,6 +17,7 @@ const mobileAuthBridge = require('./model/mobileAuthBridge/mobileAuthBridge.mode const shardAtlas = require('./model/shardAtlas/shardAtlas.model') const shardClilocs = require('./model/shardClilocs/shardClilocs.model') const shardMarket = require('./model/shardMarket/shardMarket.model') +const moduleLifecycle = require('./modules/lifecycle') const createLogger = require('./utils/logger') const { evaluateBotInternalKey } = require('./utils/botInternalKey') const brand = require('./config/brand') @@ -109,6 +110,15 @@ async function start() { const mode = await settings.get('site_mode') log.info(`site mode: ${String(mode || 'live').toUpperCase()}`) + // Reconcile installed_modules with what the loader found on the volume at + // require time, then run each module's onBoot (MODULE_API.md §2.5). Placed + // after core's own boot work and BEFORE the listener binds, for both reasons + // the contract gives: a module's warm-up may depend on core being up, and a + // module that must not serve traffic until it has warmed a cache gets that + // guarantee only if nothing is listening yet. Never throws — a module that + // fails here keeps its URLs and answers 503. + await moduleLifecycle.boot() + const server = http.createServer(app) server.listen(PORT, HOST, () => { log.info(`listening on http://${HOST}:${PORT} (API at /api/v1, health at /api/health)`) @@ -174,6 +184,12 @@ function setupShutdown(server, internalServer) { if (closing) return closing = true log.warn(`${signal} received — shutting down gracefully`) + // Modules first, while everything they were handed still works: the database + // pool, the push dispatcher and the SSE fan-out are all still open here, and + // a module's onShutdown is the only chance it gets to flush through them + // (MODULE_API.md §2.5). Each hook is budgeted, so one that will not let go + // costs five seconds rather than the whole shutdown. + await moduleLifecycle.shutdown() botScore.stopSweeper() // stop the bot-store cleanup interval announceWorker.stop() // stop the news-announcement dispatcher poller uoLinkSocket.stop() // close the uo-link WS ingest client diff --git a/server/test/moduleLifecycle.test.js b/server/test/moduleLifecycle.test.js new file mode 100644 index 0000000..b741548 --- /dev/null +++ b/server/test/moduleLifecycle.test.js @@ -0,0 +1,376 @@ +// ── Boot and shutdown dispatch ───────────────────────────────────────────── +// +// Phase 2, PR 5. The contract is MODULE_API.md §2.5 (when the hooks run, in what +// order, with what budget), §4.4 (a failure after mounting is a 503, not a +// crash), §4.5 (a disabled module is guarded, never unmounted) and +// MODULE_SYSTEM.md §2.4 (what a boot does to installed_modules). +// +// The property under test throughout, as in moduleLoader.test.js and +// moduleSchema.test.js: **the failing module fails alone.** A hook that throws, +// a hook that hangs, a row that will not write — none of them may cost the site +// its boot or the next module its start. +// +// No database is involved: `boot()` takes the model as an injectable dependency +// for exactly the reason `replayFragments` takes its query, and the fake below +// records every call so the ORDER of the reconcile can be asserted — which is +// the whole design, not an implementation detail. +process.env.DB_HOST = '127.0.0.1' +process.env.DB_PORT = '59999' + +const fs = require('fs') +const os = require('os') +const path = require('path') + +const { test, beforeEach, after } = require('node:test') +const assert = require('node:assert/strict') + +const express = require('express') + +const db = require('../src/utils/db') +const registries = require('../src/modules/registries') +const lifecycle = require('../src/modules/lifecycle') +const { startApp } = require('./_helper') + +after(() => db.close()) + +let tmpRoot + +const emptyTiers = () => ({ + public: express.Router(), + admin: express.Router(), + player: express.Router(), +}) + +function freshLoader(dir, tiers = emptyTiers()) { + process.env.MODULES_DIR = dir + registries._reset() + delete require.cache[require.resolve('../src/modules/loader')] + // eslint-disable-next-line global-require + const loader = require('../src/modules/loader') + loader.load(tiers) + return loader +} + +/** + * A module whose hooks report themselves into a file. + * + * A file rather than a shared array because the module is `require`d from disk + * and cannot close over anything this file owns — the same trick the ctx probe + * in moduleLoader.test.js uses. + */ +function writeModule(id, { boot, shutdown, mounts, log: logFile } = {}) { + const dir = path.join(tmpRoot, id) + fs.mkdirSync(dir, { recursive: true }) + fs.writeFileSync(path.join(dir, 'module.json'), JSON.stringify({ + id, + name: `Module ${id}`, + version: '1.2.3', + coreApi: '^1.0.0', + server: 'index.js', + ...(mounts === undefined ? {} : { mounts }), + })) + const note = logFile + ? `const note = (what) => require('fs').appendFileSync(${JSON.stringify(logFile)}, what + '\\n')` + : 'const note = () => {}' + const register = mounts === undefined ? '' : ` + const r = ctx.express.Router() + r.get('/', (req, res) => res.json({ ok: true })) + api.registerRoutes({ public: { '${(mounts.public || [])[0]}': r } })` + // `boot: ''` means "registers a hook that does nothing", which is a different + // module from one that registers no hook at all — hence the undefined check + // rather than a truthiness test. + fs.writeFileSync(path.join(dir, 'index.js'), `${note} + module.exports = (ctx, api) => {${register} + ${boot === undefined ? '' : `api.onBoot(async (c) => { note('boot:${id}' + (c && c.moduleId === '${id}' ? ':ctx' : ':NOCTX')); ${boot} })`} + ${shutdown === undefined ? '' : `api.onShutdown(async () => { note('shutdown:${id}'); ${shutdown} })`} + }`) + return dir +} + +/** An in-memory stand-in for model/modules/modules.model.js. */ +function fakeModel(seed = []) { + const rows = new Map(seed.map((r) => [r.id, { failureStage: null, failureReason: null, ...r }])) + const calls = [] + const model = { + rows, + calls, + async beginBoot() { + calls.push('beginBoot') + for (const row of rows.values()) { + if (row.state === 'disabled') continue + Object.assign(row, { state: 'enabled', failureStage: null, failureReason: null }) + } + }, + async recordInstalled({ id, name, version }) { + calls.push(`recordInstalled:${id}`) + const row = rows.get(id) + // Metadata is refreshed; state is deliberately left alone (§2.4). + if (row) Object.assign(row, { name, version }) + else rows.set(id, { id, name, version, state: 'installed', failureStage: null, failureReason: null }) + }, + async list() { + calls.push('list') + return [...rows.values()] + }, + async markStarted(id) { + calls.push(`markStarted:${id}`) + Object.assign(rows.get(id), { state: 'started', failureStage: null, failureReason: null }) + }, + async markStartupFailed(id, { stage, reason }) { + calls.push(`markStartupFailed:${id}`) + const row = rows.get(id) + // The model's own softening, reproduced because tests below depend on it: + // a disabled row is a no-op, or an outcome would overwrite the operator's + // decision and silently re-enable the module next boot. + if (!row || row.state === 'disabled') return + Object.assign(row, { state: 'startup_failed', failureStage: stage, failureReason: reason }) + }, + } + return model +} + +const stateOf = (loader, id) => loader.list().find((m) => m.id === id) +const noted = (file) => (fs.existsSync(file) ? fs.readFileSync(file, 'utf8').trim().split('\n') : []) + +beforeEach(() => { + tmpRoot = fs.mkdtempSync(path.join(os.tmpdir(), 'rg-lifecycle-')) +}) + +// ── The happy path ───────────────────────────────────────────────────────── + +test('every module is recorded, booted with its ctx and marked started, in scan order', async () => { + const file = path.join(tmpRoot, 'log.txt') + writeModule('aaa', { boot: '', log: file }) + writeModule('bbb', { boot: '', log: file }) + const loader = freshLoader(tmpRoot) + const model = fakeModel() + + await lifecycle.boot({ modules: loader, model }) + + // The reconcile order IS the design (§2.4): clear the last boot's outcomes + // first, so what is on display afterwards is what this boot did. + assert.equal(model.calls[0], 'beginBoot') + assert.deepEqual(model.calls.slice(1, 3), ['recordInstalled:aaa', 'recordInstalled:bbb']) + assert.deepEqual(noted(file), ['boot:aaa:ctx', 'boot:bbb:ctx']) + assert.equal(stateOf(loader, 'aaa').state, 'started') + assert.equal(model.rows.get('bbb').state, 'started') + // §2.4's metadata refresh: the row carries what the admin screen shows. + assert.equal(model.rows.get('aaa').name, 'Module aaa') + assert.equal(model.rows.get('aaa').version, '1.2.3') +}) + +test('a hand-placed directory gets a row with no provenance', async () => { + // §2.5 keeps a directory dropped on the volume by hand a supported install. + // Without a row it could never be disabled, and nothing could report it. + writeModule('byhand', { boot: '' }) + const model = fakeModel() + + await lifecycle.boot({ modules: freshLoader(tmpRoot), model }) + + const row = model.rows.get('byhand') + assert.equal(row.state, 'started') + assert.equal(row.source ?? null, null) + assert.equal(row.sha256 ?? null, null) +}) + +test('a module with no onBoot still reaches started', async () => { + writeModule('quiet', {}) + const loader = freshLoader(tmpRoot) + const model = fakeModel() + + await lifecycle.boot({ modules: loader, model }) + + // Nothing to warm up is not the same as never having started: the guard lets + // its routes through, so the row has to agree that it is serving. + assert.equal(stateOf(loader, 'quiet').state, 'started') + assert.equal(model.rows.get('quiet').state, 'started') +}) + +// ── Failure is a state ───────────────────────────────────────────────────── + +test('an onBoot that throws fails its own module and no one else', async () => { + const file = path.join(tmpRoot, 'log.txt') + writeModule('aaa', { boot: '', log: file }) + writeModule('bbb', { boot: 'throw new Error("cache warm-up failed")', log: file }) + writeModule('ccc', { boot: '', log: file }) + const loader = freshLoader(tmpRoot) + const model = fakeModel() + + await lifecycle.boot({ modules: loader, model }) + + assert.equal(stateOf(loader, 'bbb').state, 'startup_failed') + assert.equal(stateOf(loader, 'bbb').stage, 'boot') + assert.match(stateOf(loader, 'bbb').reason, /cache warm-up failed/) + assert.equal(model.rows.get('bbb').failureStage, 'boot') + // The one that matters: the module AFTER the failure still booted. + assert.deepEqual(noted(file), ['boot:aaa:ctx', 'boot:bbb:ctx', 'boot:ccc:ctx']) + assert.equal(stateOf(loader, 'ccc').state, 'started') +}) + +test('a module whose onBoot failed keeps its URLs and answers 503', async () => { + // §4.4's right-hand column, reached by the real mechanism rather than a + // hand-moved state: routes.manifest.json must not depend on whether a boot + // hook happened to succeed on the machine that generated it. + writeModule('svc', { boot: 'throw new Error("no")', mounts: { public: ['/widgets'] } }) + const tiers = emptyTiers() + const loader = freshLoader(tmpRoot, tiers) + const app = await startApp((a) => a.use('/public', tiers.public)) + + try { + assert.equal((await fetch(`${app.url}/public/widgets`)).status, 200) + await lifecycle.boot({ modules: loader, model: fakeModel() }) + assert.equal((await fetch(`${app.url}/public/widgets`)).status, 503) + } finally { + await app.close() + } +}) + +test('a failure from load or schema replay is written down with its stage', async () => { + // Both happen before the database is reachable — load() at require time, the + // replay inside ensureSchema — so the boot reconcile is where they land. + writeModule('bad', {}) + fs.writeFileSync(path.join(tmpRoot, 'bad', 'module.json'), JSON.stringify({ + id: 'bad', name: 'bad', version: '1.0.0', coreApi: '^99.0.0', + })) + const loader = freshLoader(tmpRoot) + const model = fakeModel() + + await lifecycle.boot({ modules: loader, model }) + + const row = model.rows.get('bad') + assert.equal(row.state, 'startup_failed') + assert.equal(row.failureStage, 'core_api') + assert.match(row.failureReason, /needs core API \^99\.0\.0/) +}) + +// ── The operator's switch ────────────────────────────────────────────────── + +test('a disabled row guards the module, skips its hook and is not overwritten', async () => { + const file = path.join(tmpRoot, 'log.txt') + writeModule('off', { boot: '', shutdown: '', mounts: { public: ['/widgets'] }, log: file }) + const tiers = emptyTiers() + const loader = freshLoader(tmpRoot, tiers) + const model = fakeModel([{ id: 'off', name: 'Module off', version: '1.2.3', state: 'disabled' }]) + const app = await startApp((a) => a.use('/public', tiers.public)) + + try { + await lifecycle.boot({ modules: loader, model }) + + // §4.5's 404 leg, unreachable until this reconcile existed: mounted and + // guarded, never unmounted, so the URL surface stays a property of the + // volume rather than of a database row. + assert.equal((await fetch(`${app.url}/public/widgets`)).status, 404) + assert.equal(stateOf(loader, 'off').state, 'disabled') + assert.deepEqual(noted(file), [], 'a disabled module must not be booted') + // Still disabled: an outcome must never overwrite a decision, or the next + // boot would silently switch it back on. + assert.equal(model.rows.get('off').state, 'disabled') + // And nothing to tear down, because it never started. + await lifecycle.shutdown({ modules: loader }) + assert.deepEqual(noted(file), []) + } finally { + await app.close() + } +}) + +test('a row whose directory is gone is marked failed rather than left claiming enabled', async () => { + writeModule('here', { boot: '' }) + const model = fakeModel([ + { id: 'here', name: 'Module here', version: '1.2.3', state: 'started' }, + { id: 'gone', name: 'Module gone', version: '0.9.0', state: 'started' }, + // An uninstall leaves `disabled`, which beginBoot never touches — so this + // one is not an anomaly and must be left exactly as the operator left it. + { id: 'uninstalled', name: 'Module uninstalled', version: '0.1.0', state: 'disabled' }, + ]) + + await lifecycle.boot({ modules: freshLoader(tmpRoot), model }) + + assert.equal(model.rows.get('here').state, 'started') + assert.equal(model.rows.get('gone').state, 'startup_failed') + assert.match(model.rows.get('gone').failureReason, /not present on the volume/) + assert.equal(model.rows.get('uninstalled').state, 'disabled') +}) + +// ── The site comes up regardless ─────────────────────────────────────────── + +test('a database that will not take the bookkeeping still boots the modules', async () => { + // A row that will not update is bad — the admin panel shows the wrong thing — + // but it is strictly less bad than a site that will not start. + const file = path.join(tmpRoot, 'log.txt') + writeModule('aaa', { boot: '', log: file }) + const loader = freshLoader(tmpRoot) + const model = fakeModel() + for (const name of ['beginBoot', 'recordInstalled', 'list', 'markStarted']) { + model[name] = async () => { throw new Error('ER_LOCK_WAIT_TIMEOUT') } + } + + await assert.doesNotReject(() => lifecycle.boot({ modules: loader, model })) + + assert.deepEqual(noted(file), ['boot:aaa:ctx']) + assert.equal(stateOf(loader, 'aaa').state, 'started') +}) + +test('a process that never scanned writes nothing at all', async () => { + // `npm run seed` is exactly this: it calls ensureSchema() without ever + // requiring app.js. Reconciling against an empty scan would mark every + // installed module as missing from the volume. + process.env.MODULES_DIR = tmpRoot + delete require.cache[require.resolve('../src/modules/loader')] + // eslint-disable-next-line global-require + const unscanned = require('../src/modules/loader') + const model = fakeModel([{ id: 'real', name: 'Module real', version: '1.0.0', state: 'started' }]) + + await lifecycle.boot({ modules: unscanned, model }) + + assert.deepEqual(model.calls, []) + assert.equal(model.rows.get('real').state, 'started') +}) + +// ── Shutdown ─────────────────────────────────────────────────────────────── + +test('shutdown runs started modules in reverse order and skips the rest', async () => { + const file = path.join(tmpRoot, 'log.txt') + writeModule('aaa', { boot: '', shutdown: '', log: file }) + writeModule('bbb', { boot: 'throw new Error("no")', shutdown: '', log: file }) + writeModule('ccc', { boot: '', shutdown: '', log: file }) + const loader = freshLoader(tmpRoot) + + await lifecycle.boot({ modules: loader, model: fakeModel() }) + fs.writeFileSync(file, '') // only the shutdown half is under test + await lifecycle.shutdown({ modules: loader }) + + // Reverse of boot order, and `bbb` absent: its onBoot threw, so it has a + // half-built world that its onShutdown was never written to tear down. + assert.deepEqual(noted(file), ['shutdown:ccc', 'shutdown:aaa']) +}) + +test('a hook that hangs costs its budget, not the shutdown', async () => { + const file = path.join(tmpRoot, 'log.txt') + writeModule('aaa', { boot: '', shutdown: '', log: file }) + writeModule('zzz', { boot: '', shutdown: 'await new Promise(() => {})', log: file }) + const loader = freshLoader(tmpRoot) + + await lifecycle.boot({ modules: loader, model: fakeModel() }) + fs.writeFileSync(file, '') + + const started = Date.now() + await lifecycle.shutdown({ modules: loader, budgetMs: 50 }) + + // zzz never returns; it is abandoned and aaa still gets its turn. The + // alternative is a host where `systemctl stop` hangs until SIGKILL. + assert.deepEqual(noted(file), ['shutdown:zzz', 'shutdown:aaa']) + assert.ok(Date.now() - started < 2000, 'shutdown must not wait on a hung hook') +}) + +test('a hook that throws does not stop the ones behind it', async () => { + const file = path.join(tmpRoot, 'log.txt') + writeModule('aaa', { boot: '', shutdown: '', log: file }) + writeModule('zzz', { boot: '', shutdown: 'throw new Error("close failed")', log: file }) + const loader = freshLoader(tmpRoot) + + await lifecycle.boot({ modules: loader, model: fakeModel() }) + fs.writeFileSync(file, '') + + await assert.doesNotReject(() => lifecycle.shutdown({ modules: loader })) + assert.deepEqual(noted(file), ['shutdown:zzz', 'shutdown:aaa']) +}) diff --git a/server/test/moduleLoader.test.js b/server/test/moduleLoader.test.js index dd5b09f..70e234f 100644 --- a/server/test/moduleLoader.test.js +++ b/server/test/moduleLoader.test.js @@ -437,9 +437,10 @@ test('a registered module answers on its prefix; a failed one is simply absent', test('a module that fails AFTER mounting keeps its URLs and answers 503', async () => { // The right-hand column of §4.4, and the reason routes.manifest.json can be // generated off a dead database: the URL surface must not depend on whether a - // boot step succeeded on the generating machine. PR 3 (schema replay) and PR 5 - // (onBoot) are the two things that will trip this in real life; here the state - // is moved by hand, because the loader is the thing under test. + // boot step succeeded on the generating machine. The schema replay and onBoot + // are the two things that trip this in real life (moduleSchema.test.js and + // moduleLifecycle.test.js cover both); here the state is moved by hand, + // because the loader is the thing under test. writeModule('later', oneRoute('/widgets')) const tiers = emptyTiers() @@ -451,18 +452,23 @@ test('a module that fails AFTER mounting keeps its URLs and answers 503', async assert.equal(stateOf(loader, 'later').state, 'registered') - loader.setState('later', 'startup_failed', 'schema fragment blew up') + loader.setState('later', 'startup_failed', { stage: 'schema', reason: 'schema fragment blew up' }) assert.equal((await fetch(`${app.url}/public/widgets`)).status, 503) assert.equal(stateOf(loader, 'later').reason, 'schema fragment blew up') + assert.equal(stateOf(loader, 'later').stage, 'schema') - // The 404 leg becomes reachable for real in PR 5, when the boot reconcile - // reads a `disabled` row out of installed_modules. A disabled module is - // mounted and guarded, never unmounted (§4.5) — same reason as the 503. + // The 404 leg is reached for real by the boot reconcile, when it finds a + // `disabled` row in installed_modules. A disabled module is mounted and + // guarded, never unmounted (§4.5) — same reason as the 503. loader.setState('later', 'disabled') assert.equal((await fetch(`${app.url}/public/widgets`)).status, 404) loader.setState('later', 'started') assert.equal((await fetch(`${app.url}/public/widgets`)).status, 200) + // Every non-failing move clears the failure, so a running module can never + // show the reason it failed two boots ago (§2.4). + assert.equal(stateOf(loader, 'later').reason, null) + assert.equal(stateOf(loader, 'later').stage, null) } finally { await app.close() } @@ -506,19 +512,79 @@ test('ctx exposes exactly the documented surface, and is frozen', () => { assert.equal(probe.mutable, false, 'ctx members must be frozen') }) -test('the register calls PR 5 owns throw rather than silently accepting', () => { - // An accepting no-op would let a module believe it had registered a boot hook - // and fail silently at the far end. - for (const [call, pr] of [ - ['onBoot', 5], - ['onShutdown', 5], +// ── Lifecycle hooks ──────────────────────────────────────────────────────── + +test('a lifecycle hook must be a function, and may be registered once', () => { + // Both are register-time failures, so they cost the module its mount entirely + // rather than surfacing at boot — the far end of a hook that was never really + // registered is a module that silently never warms up. + for (const [body, expected] of [ + ['api.onBoot("later")', /onBoot: expected a function/], + ['api.onShutdown("later")', /onShutdown: expected a function/], + ['api.onBoot(() => {}); api.onBoot(() => {})', /onBoot\(\) called twice/], ]) { tmpRoot = fs.mkdtempSync(path.join(os.tmpdir(), 'rg-modules-')) - writeModule('early', { server: `module.exports = (ctx, api) => api.${call}(() => {})` }) - assert.match( - stateOf(freshLoader(tmpRoot), 'early').reason, - new RegExp(`${call}: not available until phase 2 PR ${pr}`), - ) + writeModule('hooked', { server: `module.exports = (ctx, api) => { ${body} }` }) + const state = stateOf(freshLoader(tmpRoot), 'hooked') + assert.match(state.reason, expected) + assert.equal(state.stage, 'register') + } +}) + +test('a module with no hooks is bootable, and offers nothing to shut down', () => { + writeModule('quiet', oneRoute('/widgets')) + const loader = freshLoader(tmpRoot) + + // Listed with a null hook rather than filtered out: it still has to reach + // `started`, or the admin panel and the dispatch guard would disagree about + // whether it is serving. + assert.deepEqual(loader.bootable().map((b) => b.id), ['quiet']) + assert.equal(loader.bootable()[0].hook, null) + assert.deepEqual(loader.shutdownHooks(), []) +}) + +test('shutdown hooks come back in reverse order, and only for started modules', () => { + const hook = 'module.exports = (ctx, api) => api.onShutdown(async () => {})' + writeModule('aaa', { server: hook }) + writeModule('bbb', { server: hook }) + writeModule('ccc', { server: hook }) + const loader = freshLoader(tmpRoot) + + // Nothing has started yet, so there is nothing to tear down. + assert.deepEqual(loader.shutdownHooks(), []) + + loader.setState('aaa', 'started') + loader.setState('bbb', 'startup_failed', { stage: 'boot', reason: 'never warmed up' }) + loader.setState('ccc', 'started') + + // Reverse registration order (§2.5), and `bbb` is absent: a module whose + // onBoot threw is mid-way through a warm-up it never finished, and handing it + // a half-built world to tear down is worse than not closing cleanly. + assert.deepEqual(loader.shutdownHooks().map((h) => h.id), ['ccc', 'aaa']) +}) + +// ── Failure stages ───────────────────────────────────────────────────────── + +test('a failure is recorded against the §4.3 step that produced it', () => { + // installed_modules.failure_stage exists so the admin panel can say WHERE a + // module broke. The four steps readManifest covers in one pass have to label + // themselves; the rest are inferred from how far load() had got. + const cases = [ + ['a-manifest', { manifest: { nonsense: true } }, 'manifest'], + ['b-coreapi', { manifest: { coreApi: '^99.0.0' } }, 'core_api'], + ['c-mounts', { manifest: { mounts: { public: ['/bad prefix'] } } }, 'mounts'], + ['d-slots', { manifest: { extensions: ['no.such.slot'] } }, 'extensions'], + ['e-schema', { schema: 'DELETE FROM x;' }, 'schema'], + ['f-require', { server: 'throw new Error("boom")' }, 'require'], + ['g-register', { server: 'module.exports = (ctx, api) => { throw new Error("nope") }' }, 'register'], + ] + for (const [id, spec] of cases) writeModule(id, spec) + const loader = freshLoader(tmpRoot) + + for (const [id, , stage] of cases) { + const state = stateOf(loader, id) + assert.equal(state.state, 'startup_failed', `${id} should have failed`) + assert.equal(state.stage, stage, `${id} should have failed at "${stage}"`) } })