diff --git a/README.md b/README.md index cb4d10d9..5ca278f1 100644 --- a/README.md +++ b/README.md @@ -234,12 +234,16 @@ npm run dev # Production mode npm start + +# Production mode, several processes on one port (cluster mode) +npm run start:cluster ``` The server will be available at `http://localhost:{port}` using the port specified in the config. In the production servers listed above, the server always sits behind an NGINX server which manages SSL, security, rate limiting etc. See [nginx.md](nginx.md) for configuration advice, including -running several servers behind one front door. +running several servers behind one front door. To use more than one CPU core on one machine, see +[cluster.md](cluster.md): several server processes share one port and one client cache. ## Testing diff --git a/cluster.js b/cluster.js new file mode 100644 index 00000000..5983c175 --- /dev/null +++ b/cluster.js @@ -0,0 +1,212 @@ +#!/usr/bin/env node +// +// FHIRsmith in cluster mode: several server processes on one port. +// +// node cluster.js (npm run start:cluster) +// +// The number of processes comes from config.json "server": {"cluster": {"workers": N}} +// or the FHIRSMITH_WORKERS environment variable (which wins); default 2. Each worker +// is a complete server (server.js) with its own memory, library and expansion cache; +// Node's cluster module accepts connections on the port and hands them to the +// workers in turn, so any worker may receive any request. +// +// What has to be shared is shared on disk, in the data directory (see cluster.md): +// - the tx client resource cache ($cache-control) is the SQLite store; a configuration +// that asks for the memory store gets the SQLite one in cluster mode (tx.js). +// - logins, session-signing secrets, rate-limit counts and cross-process locks are in +// cluster-state.db (library/cluster-state.js). +// - background jobs (VSAC refresh, package crawler, XIG download, ...) run in one +// worker at a time, chosen by a lock file - see library/background-jobs.js; the +// other workers notice what it has written when they next use it. +// Statistics and the dashboard stay per worker. +// +// Memory is watched for the group, not per worker (library/memory-guard.js, +// library/cluster-memory.js): the primary measures the whole service and tells the +// workers; when the service stays over the limit, it drains and restarts the largest +// worker. +// +// Workers start one after another: each waits until the previous one is listening. +// The first start of a server on a data directory builds index databases next to +// the npm packages, and processes building them at the same time corrupt them. A +// worker that stops is started again (one at a time, backing off if it keeps +// failing to start). +// + +const cluster = require('cluster'); +const fs = require('fs'); +const path = require('path'); + +const DEFAULT_WORKERS = 2; +const SHUTDOWN_GRACE_MS = 30 * 1000; +const MAX_BACKOFF_MS = 60 * 1000; + +if (cluster.isPrimary) { + runPrimary(); +} else { + require(path.join(__dirname, 'server.js')); +} + +function log(msg) { + console.log(`${new Date().toISOString()} [cluster ${process.pid}] ${msg}`); +} + +function readConfig() { + const folders = require('./library/folder-setup'); + const file = folders.filePath('config.json'); + try { + return JSON.parse(fs.readFileSync(file, 'utf8')); + } catch (e) { + console.error(`cluster: failed to load configuration from ${file}: ${e.message}`); + process.exit(1); + } +} + +/** + * How many workers. + * @returns {number} + */ +function settings(config) { + const fromEnv = process.env.FHIRSMITH_WORKERS; + const configured = fromEnv !== undefined && fromEnv !== '' + ? Number(fromEnv) + : (config.server && config.server.cluster && config.server.cluster.workers) || DEFAULT_WORKERS; + if (!Number.isInteger(configured) || configured < 1) { + console.error(`cluster: the number of workers must be a whole number of at least 1 (got '${fromEnv ?? configured}')`); + process.exit(1); + } + if (configured > 1) { + const tx = config.modules && config.modules.tx; + if (tx && tx.enabled && !(tx.resourceCache && tx.resourceCache.store === 'sqlite')) { + log('modules.tx.resourceCache.store is not "sqlite": in cluster mode the workers use the shared SQLite store'); + } + } + return configured; +} + +function runPrimary() { + const config = readConfig(); + const n = settings(config); + log(`starting ${n} worker${n === 1 ? '' : 's'}, one at a time`); + // the memory of the whole service (one worker: it watches its own, as server.js does) + let memory = null; + if (n > 1) { + const { ClusterMemory } = require('./library/cluster-memory'); + memory = new ClusterMemory({ memory: (config.server && config.server.memory) || {}, log }); + log(memory.describe()); + memory.start(); + } + + const slots = new Map(); // worker.id -> slot number (1..n) + const queue = []; // slots waiting to start + const failures = new Map(); // slot -> consecutive failed starts + let starting = null; // the slot whose worker is starting + let stopping = false; + + const startNext = () => { + if (stopping || starting !== null || queue.length === 0) { + return; + } + const slot = queue.shift(); + starting = slot; + const worker = cluster.fork({ FHIRSMITH_CLUSTER_WORKER: String(slot), FHIRSMITH_CLUSTER_SIZE: String(n) }); + slots.set(worker.id, slot); + worker.startedAt = Date.now(); + if (memory) { + memory.add(worker); + } + log(`worker ${slot} (pid ${worker.process.pid}) starting`); + }; + + cluster.on('listening', (worker) => { + const slot = slots.get(worker.id); + worker.listening = true; + failures.delete(slot); + if (memory) { + memory.listening(worker); + } + log(`worker ${slot} (pid ${worker.process.pid}) listening after ${Math.round((Date.now() - worker.startedAt) / 1000)} s`); + if (starting === slot) { + starting = null; + } + startNext(); + }); + + cluster.on('exit', (worker, code, signal) => { + const slot = slots.get(worker.id); + slots.delete(worker.id); + if (memory) { + memory.remove(worker); + } + if (stopping) { + return; + } + const how = signal ? `signal ${signal}` : `code ${code}`; + if (starting === slot) { + starting = null; + } + let delay = 1000; + if (!worker.listening) { + // failed to start: back off, so a broken configuration doesn't spin + const f = (failures.get(slot) || 0) + 1; + failures.set(slot, f); + delay = Math.min(MAX_BACKOFF_MS, 1000 * 2 ** (f - 1)); + log(`worker ${slot} (pid ${worker.process.pid}) exited (${how}) before it was listening; starting it again in ${Math.round(delay / 1000)} s`); + } else if (worker.recycled) { + log(`worker ${slot} (pid ${worker.process.pid}) recycled for memory (${how}); starting it again`); + } else { + log(`worker ${slot} (pid ${worker.process.pid}) exited (${how}); starting it again`); + } + setTimeout(() => { + queue.push(slot); + startNext(); + }, delay); + startNext(); + }); + + const shutdown = (sig) => { + if (stopping) { + return; + } + stopping = true; + if (memory) { + memory.stop(); + } + log(`${sig}: stopping the workers`); + const workers = Object.values(cluster.workers || {}); + for (const w of workers) { + try { + w.process.kill('SIGTERM'); + } catch (e) { + // already gone + } + } + const done = () => Object.keys(cluster.workers || {}).length === 0; + const timer = setTimeout(() => { + for (const w of Object.values(cluster.workers || {})) { + log(`worker pid ${w.process.pid} did not stop within ${SHUTDOWN_GRACE_MS / 1000} s; killing it`); + try { + w.process.kill('SIGKILL'); + } catch (e) { + // already gone + } + } + process.exit(0); + }, SHUTDOWN_GRACE_MS); + timer.unref(); + const check = () => { + if (done()) { + log('all workers stopped'); + process.exit(0); + } + }; + cluster.on('exit', check); + check(); + }; + process.on('SIGTERM', () => shutdown('SIGTERM')); + process.on('SIGINT', () => shutdown('SIGINT')); + + for (let slot = 1; slot <= n; slot++) { + queue.push(slot); + } + startNext(); +} diff --git a/cluster.md b/cluster.md new file mode 100644 index 00000000..58c03fc6 --- /dev/null +++ b/cluster.md @@ -0,0 +1,294 @@ +# Running several FHIRsmith processes on one port (cluster mode) + +One Node.js process runs JavaScript on one CPU core. A terminology server under load from +several IG Publisher builds at once can use more than that. Cluster mode runs several +copies of the server on one machine, all on the same port, and Node hands each incoming +connection to the next copy. Clients see one server. + +```bash +npm run start:cluster # same as: node cluster.js +``` + +This is an alternative to [running several instances behind nginx](nginx.md#routing-to-multiple-servers), +where each instance has its own port and nginx routes cached requests back to the instance +that holds the cache. In cluster mode there is nothing to route: the cache is shared. + +* [Settings](#settings) +* [What is shared, and what is per worker](#what-is-shared-and-what-is-per-worker) +* [The shared resource cache](#the-shared-resource-cache) +* [Logins, rate limits, $closure tables](#logins-rate-limits-closure-tables) +* [Background jobs](#background-jobs) +* [Memory](#memory) +* [What stays per worker](#what-stays-per-worker) +* [Starting, stopping, restarting](#starting-stopping-restarting) + +Every configuration runs in cluster mode: nothing a single server can do is refused. + +## Settings + +In `config.json`: + +```json +{ + "server": { + "port": 3000, + "cluster": { "workers": 4 }, + "memory": { "recycleAfterSeconds": 60, "drainSeconds": 30 } + }, + "modules": { + "tx": { + "enabled": true, + "resourceCache": { + "store": "sqlite", + "maxBytes": 2147483648 + } + } + } +} +``` + +| Setting | Default | Meaning | +|---|---|---| +| `server.cluster.workers` | 2 | How many server processes. The `FHIRSMITH_WORKERS` environment variable overrides it. | +| `modules.tx.resourceCache.store` | `memory` | Where the `$cache-control` client caches are kept. Cluster mode always uses `sqlite`: with `memory` (or nothing) set, the workers use the SQLite store, and the log says so. | +| `modules.tx.resourceCache.path` | `/resource-cache.db` | The SQLite file. Relative paths are under the data directory. | +| `modules.tx.resourceCache.maxBytes` | none | A cap on the total size of the cached client resources (bytes of JSON). See [the size cap](#the-size-cap). | +| `modules.tx.resourceCache.touchIntervalSeconds` | 30 | How often, at most, a cache's "last used" time is written. | +| `server.sharedState` | off (on in cluster mode) | Keep logins, generated session secrets and rate-limit counts in `/cluster-state.db` with one process too, so logins survive a restart. See [below](#logins-rate-limits-closure-tables). | +| `server.backgroundJobs.lock` | off (on in cluster mode) | Turn the background-jobs lock on for separately started processes that share a data directory. | +| `server.backgroundJobs.lockFile` | `/background-jobs.lock` | The lock file. | +| `server.memory.limit` | the cgroup limit, else the machine's RAM | The memory limit, in bytes, of the **whole service** (all the workers together). See [Memory](#memory). | +| `server.memory.rejectFraction`, `abortFraction` | 0.85, 0.92 | Above these fractions of the limit, new requests are refused (503), and operations in the largest worker are aborted (422). | +| `server.memory.measure` | chosen | `cgroup` or `processes`: how the service's memory is measured. See [Memory](#memory). | +| `server.memory.recycleAfterSeconds` | 60 | How long the service may stay over the reject threshold before the largest worker is restarted. 0: never. | +| `server.memory.drainSeconds` | 30 | How long a worker being restarted has to finish its requests. | + +**The SQLite files must be on a local disk.** Never put the data directory (the resource +cache, `cluster-state.db`, the lock file) on a network filesystem (NFS, SMB/CIFS, or a +container volume backed by one). SQLite's file locking is not reliable there, and a lock +that fails corrupts the file and lets two processes run the same background job. + +## What is shared, and what is per worker + +| | Shared by all workers | Per worker | +|---|---|---| +| `$cache-control` client caches | yes (`resource-cache.db`) | | +| Logins (publisher, IPS, testing, token, registry) | yes (`cluster-state.db`, or the module's own database) | | +| Session-signing secrets, when none is configured | yes (`cluster-state.db`) | | +| Rate limits (logins, task actions, submissions, lookups, npm checks) | yes: counted for all workers together | | +| `$closure` tables and their per-table lock | yes (`closure.db`; the lock is a lease in `cluster-state.db`) | | +| Background jobs (VSAC refresh, crawlers, downloads, daily report) | run by one worker, chosen by the lock; the others pick up what it wrote | | +| Terminology content, packages, indexes | yes (the same files in the data directory) | each worker opens them | +| Memory guard | yes: the limit and the measure are the whole service's | | +| Expansion cache | | yes | +| FHIR validators (SHL, IPS) | | yes: one each, see [below](#what-stays-per-worker) | +| Statistics and the dashboard | | yes: each page shows the worker that served it | +| Request counts in the statistics database | each worker writes its own counts to the shared database | the "total" columns are each worker's own | + +Statistics and the dashboard stay per worker. Reloading the dashboard can show a different +worker each time; the uptime, request counts and task list on it are that worker's. The +daily report is sent by the worker that runs the background jobs; the request counts in it +come from the statistics database, which all the workers write to. + +## The shared resource cache + +With `"store": "sqlite"`, the `$cache-control` client caches live in one SQLite file that +every worker uses, so a cache started on one worker can be used, extended, checked and ended +from any other. It behaves like the memory store, with these differences: + +* **Caches survive a restart.** A client can carry on with its cache-id after the server + restarts. (With the memory store a restart loses every cache.) +* **"Last used" is written at most every 30 seconds per cache**, not on every request, so + that steady use of a cache costs reads, not writes. A cache can therefore look up to 30 + seconds more idle than it is, and expire up to 30 seconds early against a 30 minute + timeout. `$cache-control?mode=check` always resets the idle clock. +* **A request only loads the resources it uses.** Each request reads the list of what the + cache holds (type, URL, version) and builds a resource only when it uses it. Nothing about + a cache's contents is kept in memory between requests, so no worker can work from an + out-of-date copy. +* **If a write fails**, for example because the disk is full or another process held the + write lock for more than 5 seconds, it is tried once more; if that fails too, the request + gets HTTP 503 with `Retry-After`. Resources a client sent are never silently dropped. + +The idle timeout is `modules.tx.cacheTimeout` (minutes) as before. Any worker may run the +idle sweep; running it twice does nothing the second time. Caches that are dropped are +remembered (the last 1,000 per endpoint), so a later request carrying one of their ids is +told what happened to it: closed by the client, expired, cleared, or evicted. + +### The size cap + +`maxBytes` caps the total size of the client resources held (as JSON). When a write takes +the total over the cap, whole caches are dropped, least recently used first, until it is +under. The cache being written is never dropped by its own write. A client whose cache was +dropped gets `cache-id-unknown` with a message saying it was dropped to make room. The cap +covers the whole file (every endpoint). It also works with the memory store, where it covers +each endpoint separately. + +For scale: in the IG Publisher traffic recorded from build.fhir.org (2,817 cache sessions, +1,866 of which uploaded resources), a typical session held 11 resources and 118 KB; 1 in +10 held over 1.2 MB; the largest held 284 resources and 3.5 MB. + +## Logins, rate limits, $closure tables + +State that a single server keeps in memory and that has to be the same on every worker is +in `/cluster-state.db`, a SQLite file like the resource cache (WAL, a 5 second +`busy_timeout`, each change one `BEGIN IMMEDIATE` transaction): + +* **Logins.** The publisher, IPS and testing modules keep their sessions there, one table + each (the token and registry modules already kept theirs in their own databases). A user + who logs in through one worker is logged in on all of them, and logging out on one logs out + everywhere. Logins also survive a restart. +* **Session secrets.** A module with no `sessionSecret` configured signs its cookies with a + random secret. In cluster mode the first worker to start makes it and stores it, and the + others use the same one. Configuring `sessionSecret` is still better. +* **Rate limits.** Every limiter counts in one table, so a limit of 20 login attempts in 15 + minutes is 20 for the service, not 20 per worker. +* **Leases**: named locks across processes for work that waits on something. `$closure` + serialises each call on a table (read the table, work out what's new, write it): within a + worker by a queue, and across workers by a lease on the table, taken by the call at the head + of the worker's queue, within the same `lockTimeout`. A lease is renewed while it is held, + and lapses after 30 seconds if its process dies. `maxQueue` counts the calls waiting in each + worker. `maxTables` is checked in the same transaction that creates a table, so two workers + creating tables at once can't go over it together. + +With one process none of this file is used by default, and logins and rate limits are in +memory as before; a module with no `sessionSecret` makes up a new one each start, so logins +end with a restart. Set `"server": {"sharedState": true}` to have one process use +`cluster-state.db` as cluster mode does: logins then survive a restart, and a generated +secret is kept in the data directory. + +## Background jobs + +Some work happens on a timer rather than for a request, and writes files or databases that +all the workers share. In cluster mode exactly one worker does it: whichever holds the lock +in `/background-jobs.lock`. The holder renews the lock every minute. If it stops +renewing it (it crashed or hung), another worker takes it over after 3 minutes; if it shuts +down normally, it gives the lock up at once. Each job checks the lock each time its timer +fires, so the jobs move with the lock. + +| Job | In cluster mode | +|---|---| +| VSAC refresh (`tx`) | the lock holder refreshes; the other workers catch up by the database's generation (below) | +| Package crawler (`packages`), start-up crawl and schedule | lock holder only; it writes its status (running, runs, the log) to `packages/crawler-status.json`, which the other workers' status, log and stats pages read when it changes | +| XIG database download (`xig`), first download and nightly | lock holder only (an update asked of another worker runs there, under a lease, so two never download at once); the other workers notice the new file on their next request and reopen it | +| Registry crawl (`registry`) | the lock holder crawls and saves `registry-data.json` (written whole and renamed into place); the other workers load it on their next request after it changes | +| Publisher task queue (`publisher`) | lock holder only (but see [below](#what-cannot-run-in-cluster-mode)) | +| IPS document queue (`ips`) | lock holder only; it re-queues documents left half-processed when it starts running the queue | +| SHL cleanup (`shl`), TestReport retention (`testing`), `$closure` table pruning (`tx`), expired login sessions | lock holder only | +| npm audit, daily report | lock holder only | +| `$cache-control` idle sweep (`tx`) | every worker (it is safe to run more than once) | +| Expansion cache memory check, CodeSystem list refresh (`tx`) | every worker, for its own memory | +| Statistics sampling, log flushing, registry usage counts | every worker, for its own counts | + +**How the other workers catch up.** A worker that doesn't run a job finds out what the job +wrote when a request needs it, not on a timer, and the check is cheap enough to make on use: + +* **VSAC**: the VSAC database keeps a generation number. The worker that syncs adds one to it + in the same transaction that records the end of the sync (and after an operator resyncs one + value set). Each worker remembers the generation its value set list was loaded at. When a + request uses the VSAC value sets, the worker reads the generation (one read by primary key, + at most once a second) and reloads the list only if it has changed. The reload runs in the + background, and the list is replaced in one step when it is ready; the request that noticed + uses the list it has. A sync is therefore visible on every worker about a second after it + finishes. +* **XIG, registry, package crawler**: the job replaces a file whole, so the file's identity + (inode, size, modification time) is its version. A worker compares it with the version it + read (one `stat`, at most once a second, when a request reaches that module) and reads the + file again only when it differs. + +The lock can also be used without cluster mode, for separately started processes that share +a data directory: set `"server": {"backgroundJobs": {"lock": true}}` in each. The shared +logins, rate limits and leases then apply to them too. + +## Memory + +Every worker is a whole server: it loads the library and keeps its own expansion cache, so N +workers use roughly N times the memory of one. They run in one cgroup (the systemd unit, the +container), and the kernel's limit applies to all of them together. So in cluster mode the +memory guard works on the **whole service**: its limit is the service's, its measure is the +service's, and the workers act on it together. + +**The limit**: `server.memory.limit` if set (for the whole service), else the limit of the +cgroup the service runs in (`MemoryMax`, the container limit), else the machine's RAM. + +**The measure**: + +* **Linux, with a cgroup limit of the service's own** (`MemoryMax` on the unit or on a + `systemd-run --scope`, a container's limit): the cgroup's private memory, `anon` in + `memory.stat` (cgroup v1: `total_rss`). This is the memory the kernel can't take back. The + page cache (the terminology databases, the SQLite files) is left out: the kernel drops it + when it needs the room. Each worker reads it directly. +* **Anywhere else** (macOS, Windows, or Linux where the limit is only on an enclosing slice + shared with other services, or there is none): every worker sends the primary its RSS every + second; the primary adds them up (with its own) and sends each worker the total and the RSS + of each worker. A worker's own part is brought up to date between reports. + +`server.memory.measure` (`"cgroup"` or `"processes"`) forces one or the other. The start-up +log of the primary and of each worker says which is used. + +**What happens**: + +* Above `rejectFraction` (85%) of the limit, **every** worker refuses new requests with 503 and + `Retry-After`, as a single server does when it is itself over. +* Above `abortFraction` (92%), operations are aborted (422 too-costly) **only in the largest + worker** by RSS, or in a worker holding more than 1.5 times its share of the abort + threshold (the threshold divided by the number of workers). The largest worker is the one + most likely to hold the operation that took the service over, and aborting there frees the + most; the operations in the other workers carry on. Without this, one heavy request in one + worker would abort everyone's work. The 1.5 times share lets two heavy workers both abort in + the same round. A worker that is spared logs that the service is over but it is not the + largest. +* If the service stays above `rejectFraction` for `recycleAfterSeconds` (60), the primary + **recycles the largest worker**: it stops taking new connections (the primary hands them to + the other workers), closes its idle keep-alive connections and each busy one after its + response, finishes the requests it has for up to `drainSeconds` (30), and exits; it is + killed if it hasn't exited 10 seconds after that. cluster.js then starts it again. One + worker is recycled at a time, never while another is starting, and while the service stays + over, each further recycle waits twice as long as the last (up to 15 minutes), so a service + whose workers are simply too big for the limit is not restarted in a loop. + +Size the limit for the whole service: N workers' baseline (the library, the expansion +caches) plus what the requests need. With one process (`node server.js`, or one worker), the +guard measures that process's RSS against the limit, as it always has. + +## What stays per worker + +These keep state in each worker's memory, and are correct per worker: + +* **Statistics and the dashboard**: each page shows the worker that served it (above). +* **The expansion cache**: each worker caches its own expansions. +* **FHIR validators** (the SHL module's and the IPS module's): each worker runs its own + validator, because the validator service belongs to the process that started it. The first + worker uses the configured port; the others take free ports, and each writes its own tx log + (`-.log`). The validator jar is downloaded or updated by one worker at a time. + Each validator is a Java process in the service's cgroup: count N of them in the memory + limit. +* **The npm projector** (`npmprojector`): each worker watches the package folder and reloads + when it changes. `POST /_reload` reloads the worker that receives it; the others reload when + their watchers see the change. +* **Packages loaded into the IPS validator** for national profiles, and the IPS module's + extension lookups, are remembered per worker (each has its own validator). + +## Starting, stopping, restarting + +The workers start **one after another**: each starts when the one before it is listening. +The first start of FHIRsmith on a data directory builds index databases next to the npm +packages, and several processes building them at once corrupt them. Startup therefore takes +N times as long as for one process. + +A worker that exits is started again (one at a time). One that keeps failing to start is +retried with a growing delay, up to a minute between tries. A worker recycled for memory is +started again at once (see [Memory](#memory)). + +`SIGTERM` or `SIGINT` to the main process stops all the workers (each shuts down as the +single server does) and then exits; a worker that has not stopped after 30 seconds is +killed. Under systemd: + +```ini +[Service] +WorkingDirectory=/opt/fhirsmith +Environment=FHIRSMITH_DATA_DIR=/var/lib/fhirsmith +ExecStart=/usr/bin/node cluster.js +KillMode=mixed +MemoryMax=16G +``` diff --git a/config-template.json b/config-template.json index de2602ff..675ae893 100644 --- a/config-template.json +++ b/config-template.json @@ -10,6 +10,26 @@ // rejectFraction new requests get 503 + Retry-After; above abortFraction running operations // are aborted with 422 too-costly. Optional; these are the defaults. // "memory": { "rejectFraction": 0.85, "abortFraction": 0.92 } + // In cluster mode (node cluster.js) the limit and the measure are the whole service's: + // the cgroup's private memory on Linux when the service has a cgroup limit of its own, + // else the workers' RSS added up. Every worker refuses above rejectFraction; above + // abortFraction only the largest worker aborts its operations; if the service stays over + // rejectFraction for recycleAfterSeconds (0: never) the largest worker is drained (up to + // drainSeconds) and restarted. limit (bytes) overrides the cgroup's / the machine's; measure + // ("cgroup" | "processes") overrides the choice. See cluster.md. + // "memory": { "limit": 17179869184, "recycleAfterSeconds": 60, "drainSeconds": 30 } + // + // Cluster mode (node cluster.js): how many server processes share the port. The + // FHIRSMITH_WORKERS environment variable overrides it. See cluster.md. + // "cluster": { "workers": 4 }, + // Keep logins, generated session secrets (for modules with no sessionSecret) and rate-limit + // counts in /cluster-state.db rather than in memory, so logins survive a restart. + // Off by default for one process; always on in cluster mode. See cluster.md. + // "sharedState": true, + // Several separately started processes on one data directory: run the background jobs + // (crawlers, downloads, daily report...) in only one of them. On automatically in + // cluster mode. The lock file must be on a local disk. + // "backgroundJobs": { "lock": true, "lockFile": "background-jobs.lock" } }, // Usage statistics. Request counts are kept per module, per endpoint and per // operation, and written to a SQLite database every intervalMinutes so they @@ -258,6 +278,18 @@ // several instances can route cached requests back to the instance that holds the // cache. Leave unset for a single server. See nginx.md. // "instanceCode": "tx1", + // The $cache-control client caches. "memory" (the default) keeps them in this process. + // "sqlite" keeps them in one SQLite file that every process on the machine shares, + // which cluster mode needs and uses whatever this says (cluster.md); caches then also + // survive a restart. The file + // must be on a local disk, never a network filesystem. maxBytes caps the total size of + // the cached resources, dropping least recently used caches whole (default: no cap). + // "resourceCache": { + // "store": "sqlite", + // "path": "resource-cache.db", + // "maxBytes": 2147483648, + // "touchIntervalSeconds": 30 + // }, // The syndication feed (Terminology Syndication Feed IG) at /syndication. When // it is on, the packages, resource files and published binaries the library loads are // recorded in /terminology-cache/syndication as they load - only from the time it diff --git a/ips/ips.js b/ips/ips.js index f43d8f7d..50a00d03 100644 --- a/ips/ips.js +++ b/ips/ips.js @@ -46,6 +46,7 @@ const fs = require('fs'); const crypto = require('crypto'); const scripts = require('./scripts'); const rateLimit = require('express-rate-limit'); +const { rateLimitOptions } = require('../library/cluster-state'); const escape = require('escape-html'); const session = require('express-session'); const lusca = require('lusca'); @@ -372,13 +373,16 @@ class IpsModule { * this.session + a form parser + this.csrf. */ setupSession() { - if (!this.config.sessionSecret) { + const clusterState = require('../library/cluster-state'); + if (!this.config.sessionSecret && !clusterState.isShared()) { this.log.warn('ips: no sessionSecret configured - using a random one, so logins will not ' + 'survive a restart. Set modules.ips.sessionSecret.'); } this.session = session({ name: 'ips.sid', - secret: this.config.sessionSecret || crypto.randomBytes(64).toString('hex'), + // several processes: sessions and a generated secret are shared (library/cluster-state) + store: clusterState.sessionStore('ips'), + secret: clusterState.sessionSecret('ips', this.config.sessionSecret), resave: false, saveUninitialized: false, cookie: { @@ -403,13 +407,13 @@ class IpsModule { setupRootRoutes() { const r = this.router; const h = (name, fn) => (req, res) => this.handle(req, res, name, () => fn(req, res)); - const loginLimiter = rateLimit({ + const loginLimiter = rateLimit(rateLimitOptions('ips-login', { windowMs: 15 * 60 * 1000, limit: this.config.loginAttemptsPerWindow ?? 20, standardHeaders: 'draft-7', legacyHeaders: false, handler: (req, res) => this.sendLogin(req, res, 429, 'Too many login attempts - try again later') - }); + })); const admin = (req, res, next) => { const user = this.currentUser(req); if (!user) { @@ -469,13 +473,13 @@ class IpsModule { const rl = this.config.rateLimit || {}; // the editors' code lookups: many small requests, their own allowance const lookupMax = rl.lookupMax === undefined ? 600 : rl.lookupMax; - this.lookups = lookupMax > 0 ? [rateLimit({ + this.lookups = lookupMax > 0 ? [rateLimit(rateLimitOptions('ips-lookup', { windowMs: (rl.windowMinutes || 1) * 60 * 1000, limit: lookupMax, standardHeaders: 'draft-7', legacyHeaders: false, handler: (req, res) => res.status(429).json({ error: 'Too many lookups; try again later' }) - })] : []; + }))] : []; const admin = this.adminOnly; // the administrator, for the editor's fetches: JSON, not a redirect to the login page const adminJson = (req, res, next) => { @@ -547,7 +551,7 @@ class IpsModule { const max = rl.max === undefined ? 60 : rl.max; const posting = []; if (max > 0) { - posting.push(rateLimit({ + posting.push(rateLimit(rateLimitOptions('ips-submit', { windowMs: (rl.windowMinutes || 1) * 60 * 1000, limit: max, standardHeaders: 'draft-7', @@ -555,7 +559,7 @@ class IpsModule { handler: (req, res) => wantsHtml(req) ? htmlServer.sendErrorResponse(res, TEMPLATE, new Error('Too many documents submitted; try again later'), 429) : this.sendOutcome(res, 429, 'throttled', 'Too many documents submitted; try again later') - })); + }))); } // the project, from its code; 404 if there isn't one @@ -693,7 +697,8 @@ class IpsModule { timeout: cfg.timeout || 120000 }; this.log.info(`IPS module: starting the FHIR validator${localJar ? ` (${localJar})` : ''} on port ${settings.port} (tx ${settings.txServer}; ${settings.igs.join(', ')})`); - this.validatorStarting = this.validator.start(settings).then(() => { + // with several server processes, each runs its own validator (library/cluster-state) + this.validatorStarting = require('../library/cluster-state').startValidator(this.validator, settings, this.log).then(() => { this.log.info('IPS module: the FHIR validator is running'); }).catch(e => { this.log.error('IPS module: the FHIR validator failed to start: ' + e.message); @@ -868,10 +873,7 @@ class IpsModule { } setupQueue() { - const reset = this.store.resetProcessing(); - if (reset > 0) { - this.log.info(`IPS module: ${reset} documents were being processed at the last shutdown; queued again`); - } + this.resetStuckDocuments(); const cfg = this.config.processing || {}; if (cfg.enabled === false) { return; @@ -889,10 +891,37 @@ class IpsModule { * runs at once; a run that finds nothing is free. * @returns {Promise} how many documents were processed */ + /** + * Put documents that were being processed when the queue's runner stopped back in + * the queue. With several processes, only the one that runs the queue may do this + * (otherwise a process starting up would re-queue what the runner is working on), + * and it does it when it starts running the queue - including when it takes over + * from a runner that stopped. + */ + resetStuckDocuments() { + if (!this.store || !require('../library/background-jobs').isLeader()) { + this.queueReset = false; + return; + } + const reset = this.store.resetProcessing(); + if (reset > 0) { + this.log.info(`IPS module: ${reset} documents were being processed at the last shutdown; queued again`); + } + this.queueReset = true; + } + async processQueue() { if (this.processing || !this.store) { return 0; } + // with several processes, one of them works through the queue + if (!require('../library/background-jobs').isLeader()) { + this.queueReset = false; + return 0; + } + if (!this.queueReset) { + this.resetStuckDocuments(); + } // claimed before anything is awaited, so two timer ticks can never both get past here this.processing = true; let n = 0; diff --git a/library/background-jobs.js b/library/background-jobs.js new file mode 100644 index 00000000..e6216c41 --- /dev/null +++ b/library/background-jobs.js @@ -0,0 +1,198 @@ +// +// Which process runs the background jobs. +// +// A background job is work the server does on a timer rather than for a request, +// and that writes state other processes share: the VSAC refresh, the package +// crawler, the XIG download, the registry crawl, the publisher's task queue, the +// daily report, retention purges. With one server process they simply run. With +// several processes on one data directory (cluster mode, see cluster.js) each of +// them would run every job, so they would download, crawl and write the same files +// and databases at the same time, and send the daily report N times. +// +// So when more than one process may share the data directory, exactly one of them +// runs the jobs: whichever holds the lock. Every job asks backgroundJobs.isLeader() +// each time its timer fires (not once at start-up), so when the holder stops - it +// exits, crashes, or hangs - another process takes over at its next tick. +// +// The lock is a small SQLite file in the data directory (background-jobs.lock): a +// single row naming the holder, which the holder renews every minute. Another +// process may take the row over only when it hasn't been renewed for staleMs (3 +// minutes by default). Taking it over is one BEGIN IMMEDIATE transaction, so two +// processes can never both win. Like the resource cache, the file must be on a +// local disk. +// +// With no lock configured (a single server process, the default) isLeader() is +// always true and nothing is written. +// + +const os = require('os'); +const path = require('path'); +const fs = require('fs'); +const crypto = require('crypto'); + +const DEFAULT_STALE_MS = 3 * 60 * 1000; +const LOCK_NAME = 'background-jobs'; + +class BackgroundJobs { + constructor() { + this.enabled = false; + this.db = null; + this.file = null; + this.staleMs = DEFAULT_STALE_MS; + this.id = `${os.hostname()}:${process.pid}:${crypto.randomUUID()}`; + this.leading = false; + this.renewTimer = null; + this.log = null; + } + + /** + * Turn the lock on (or leave it off). + * @param {Object} options + * @param {boolean} options.enabled - true when several processes may share the data directory + * @param {string} [options.path] - the lock file (default /background-jobs.lock) + * @param {number} [options.staleMs] - how long the holder may go without renewing before another process may take over + * @param {Object} [options.log] - logger + */ + configure(options = {}) { + this.close(); + this.enabled = !!options.enabled; + this.log = options.log || null; + if (!this.enabled) { + return this; + } + this.staleMs = options.staleMs > 0 ? options.staleMs : DEFAULT_STALE_MS; + this.file = options.path || require('./folder-setup').filePath('background-jobs.lock'); + fs.mkdirSync(path.dirname(this.file), { recursive: true }); + const Database = require('better-sqlite3'); + this.db = new Database(this.file); + this.db.pragma('busy_timeout = 5000'); + this.db.pragma('journal_mode = WAL'); + this.db.transaction(() => { + this.db.exec(`CREATE TABLE IF NOT EXISTS holder ( + name TEXT PRIMARY KEY, holder TEXT NOT NULL, pid INTEGER, host TEXT, + since INTEGER NOT NULL, renewed INTEGER NOT NULL)`); + }).immediate(); + this.q = { + get: this.db.prepare('SELECT * FROM holder WHERE name = ?'), + put: this.db.prepare(`INSERT INTO holder (name, holder, pid, host, since, renewed) VALUES (@name, @holder, @pid, @host, @since, @renewed) + ON CONFLICT (name) DO UPDATE SET holder = excluded.holder, pid = excluded.pid, host = excluded.host, + since = excluded.since, renewed = excluded.renewed`), + release: this.db.prepare('DELETE FROM holder WHERE name = ? AND holder = ?') + }; + return this; + } + + /** + * Should this process run the background jobs right now? Always true without a + * lock. With one: true if this process holds the lock, or has just taken it over + * because its holder stopped renewing it. + * @returns {boolean} + */ + isLeader() { + if (!this.enabled) { + return true; + } + let leading = false; + try { + leading = this._acquire(Date.now()); + } catch (e) { + // can't tell: don't risk two processes running the jobs + this._info(`background jobs: could not check the lock (${e.message}); not running them this time`); + leading = false; + } + this._setLeading(leading); + return leading; + } + + _acquire(now) { + // the common case for a process that isn't the holder: a read, no write lock + const seen = this.q.get.get(LOCK_NAME); + if (seen && seen.holder !== this.id && seen.renewed >= now - this.staleMs) { + return false; + } + return this.db.transaction(() => { + const row = this.q.get.get(LOCK_NAME); + const mine = row && row.holder === this.id; + if (row && !mine && row.renewed >= now - this.staleMs) { + return false; + } + if (row && !mine) { + this._info(`background jobs: taking over from ${row.host} pid ${row.pid}, which last renewed the lock ${Math.round((now - row.renewed) / 1000)} s ago`); + } + this.q.put.run({ + name: LOCK_NAME, holder: this.id, pid: process.pid, host: os.hostname(), + since: mine ? row.since : now, renewed: now + }); + return true; + }).immediate(); + } + + _setLeading(leading) { + if (leading && !this.leading) { + this._info(`background jobs: this process (pid ${process.pid}) runs them`); + // renew well inside staleMs, so a busy but healthy holder keeps the lock + this.renewTimer = setInterval(() => { + try { + this._setLeading(this._acquire(Date.now())); + } catch (e) { + this._info(`background jobs: could not renew the lock: ${e.message}`); + } + }, Math.max(1000, Math.floor(this.staleMs / 3))); + if (this.renewTimer.unref) { + this.renewTimer.unref(); + } + } else if (!leading && this.leading) { + this._info(`background jobs: another process has taken them over`); + clearInterval(this.renewTimer); + this.renewTimer = null; + } + this.leading = leading; + } + + /** + * Who holds the lock (for status pages and logs). Null without a lock. + * @returns {{holder: string, pid: number, host: string, since: number, renewed: number, me: boolean}|null} + */ + holder() { + if (!this.enabled) { + return null; + } + const row = this.q.get.get(LOCK_NAME); + return row ? { holder: row.holder, pid: row.pid, host: row.host, since: row.since, renewed: row.renewed, me: row.holder === this.id } : null; + } + + _info(msg) { + if (this.log) { + this.log.info(msg); + } + } + + /** + * Give the lock up (on shutdown), so another process can take over at once + * rather than after staleMs. + */ + close() { + if (this.renewTimer) { + clearInterval(this.renewTimer); + this.renewTimer = null; + } + if (this.db) { + try { + if (this.leading) { + this.q.release.run(LOCK_NAME, this.id); + } + this.db.close(); + } catch (e) { + // best effort + } + this.db = null; + } + this.leading = false; + this.enabled = false; + } +} + +// one per process +const backgroundJobs = new BackgroundJobs(); +module.exports = backgroundJobs; +module.exports.BackgroundJobs = BackgroundJobs; diff --git a/library/cgroup-memory.js b/library/cgroup-memory.js index dd8b0ee2..b5d35997 100644 --- a/library/cgroup-memory.js +++ b/library/cgroup-memory.js @@ -110,4 +110,70 @@ function readCgroupMemoryLimit(opts = {}) { return { limit: 0, source: null }; } -module.exports = { readCgroupMemoryLimit }; +/** + * The directory of this process's own cgroup, and whether it is v2 or v1 (memory + * controller). null when there is none to be found (not Linux, or no /proc). + * @param {Object} [opts] - procFile, cgroupRoot (tests) + * @returns {{dir: string, version: 2|1}|null} + */ +function ownCgroupDir(opts = {}) { + const procFile = opts.procFile || '/proc/self/cgroup'; + const cgroupRoot = opts.cgroupRoot || '/sys/fs/cgroup'; + let lines; + try { + lines = fs.readFileSync(procFile, 'utf8').split('\n').filter(l => l.trim() !== ''); + } catch { + return null; + } + const v2 = lines.find(l => l.startsWith('0::')); + if (v2) { + const dir = path.join(cgroupRoot, path.posix.normalize(v2.substring(3) || '/')); + if (fs.existsSync(path.join(dir, 'memory.stat'))) { + return { dir, version: 2 }; + } + } + for (const l of lines) { + const parts = l.split(':'); + if (parts.length >= 3 && parts[1].split(',').includes('memory')) { + const dir = path.join(cgroupRoot, 'memory', path.posix.normalize(parts.slice(2).join(':') || '/')); + if (fs.existsSync(path.join(dir, 'memory.stat'))) { + return { dir, version: 1 }; + } + } + } + return null; +} + +/** + * The private memory of everything in a cgroup: what the kernel can't get back + * without killing a process (the page cache - the SQLite and terminology files - it can + * drop and read again, so that isn't counted). cgroup v2: memory.stat 'anon'. v1: + * 'total_rss' (this cgroup and those below it), else 'rss'. + * @param {{dir: string, version: 2|1}} cg - from ownCgroupDir + * @returns {number} bytes, or 0 if it can't be read + */ +function readCgroupAnon(cg) { + let text; + try { + text = fs.readFileSync(path.join(cg.dir, 'memory.stat'), 'utf8'); + } catch { + return 0; + } + const want = cg.version === 2 ? ['anon'] : ['total_rss', 'rss']; + const values = new Map(); + for (const line of text.split('\n')) { + const i = line.indexOf(' '); + if (i > 0) { + values.set(line.substring(0, i), Number(line.substring(i + 1))); + } + } + for (const key of want) { + const v = values.get(key); + if (Number.isFinite(v) && v >= 0) { + return v; + } + } + return 0; +} + +module.exports = { readCgroupMemoryLimit, ownCgroupDir, readCgroupAnon }; diff --git a/library/cluster-memory.js b/library/cluster-memory.js new file mode 100644 index 00000000..076667a7 --- /dev/null +++ b/library/cluster-memory.js @@ -0,0 +1,208 @@ +// +// Cluster mode, in the primary (cluster.js): the memory of the whole service. +// +// Every worker reports its RSS every second (library/memory-guard.js). Once a second +// the primary measures the group - the cgroup's private memory where the service has a +// cgroup of its own with a limit, else the sum of the workers' RSS and its own - and +// sends every worker the table of RSS per worker and the total. The workers use it to +// refuse new requests when the group is over the reject threshold, and to decide which of +// them aborts operations when it is over the abort threshold (memory-guard.js). +// +// If the group stays over the reject threshold (recycleAfterSeconds, default 60), no +// request is being served anywhere and aborting has not brought it back, so the primary +// recycles the largest worker: it asks it to drain - stop taking connections (the +// primary then gives them to the others), finish the requests it has (up to +// drainSeconds, default 30), and exit - and cluster.js starts it again. One worker at a +// time; while the group stays over, each further recycle waits twice as long as the one +// before (up to 15 minutes), so a service whose workers are simply too big for the limit +// doesn't restart them in a loop. +// + +const memoryGuard = require('./memory-guard'); +const { readCgroupAnon } = require('./cgroup-memory'); + +const DEFAULT_RECYCLE_AFTER_MS = 60 * 1000; +const DEFAULT_DRAIN_MS = 30 * 1000; +const MAX_RECYCLE_WAIT_MS = 15 * 60 * 1000; +// a drained worker that hasn't exited this long after its deadline is killed +const DRAIN_KILL_GRACE_MS = 10 * 1000; + +function gb(bytes) { + return (bytes / 1024 / 1024 / 1024).toFixed(2); +} + +class ClusterMemory { + /** + * @param {Object} opts + * @param {Object} [opts.memory] - config.server.memory + * @param {Function} opts.log - (message) => void + * @param {Function} [opts.now] - clock (tests) + * @param {Function} [opts.ownRss] - this process's RSS (tests) + * @param {Function} [opts.readGroup] - the cgroup measure (tests) + */ + constructor(opts = {}) { + const memory = opts.memory || {}; + const r = memoryGuard.resolveLimit(memory); + this.limit = r.limit; + this.source = r.source; + this.measure = r.measure; + this.cgroup = r.cgroup; + const frac = (v, d) => (typeof v === 'number' && v > 0 && v <= 1 ? v : d); + this.rejectAt = this.limit * frac(memory.rejectFraction, 0.85); + this.abortAt = this.limit * frac(memory.abortFraction, 0.92); + this.recycleAfterMs = memory.recycleAfterSeconds === 0 ? 0 + : (memory.recycleAfterSeconds > 0 ? memory.recycleAfterSeconds * 1000 : DEFAULT_RECYCLE_AFTER_MS); + this.drainMs = memory.drainSeconds > 0 ? memory.drainSeconds * 1000 : DEFAULT_DRAIN_MS; + this.log = opts.log || (() => {}); + this.now = opts.now || Date.now; + this.ownRss = opts.ownRss || (() => process.memoryUsage.rss()); + this.readGroup = opts.readGroup || (() => readCgroupAnon(this.cgroup)); + this.workers = new Map(); // pid -> { worker, rss, listening, draining } + this.overSince = 0; + this.recycles = 0; // recycles in the current spell over the threshold + this.lastTotal = 0; + this.timer = null; + } + + describe() { + return `memory: limit ${gb(this.limit)} GB for the service (from ${this.source}), measured as ` + + (this.measure === 'cgroup' ? `the cgroup's private memory (${this.cgroup.dir})` : 'the sum of the processes\' RSS') + + `; refuse above ${gb(this.rejectAt)} GB, abort in the largest worker above ${gb(this.abortAt)} GB` + + (this.recycleAfterMs ? `, recycle the largest after ${this.recycleAfterMs / 1000} s over ${gb(this.rejectAt)} GB` : ', no recycling'); + } + + start(interval = 1000) { + this.timer = setInterval(() => this.tick(), interval); + if (this.timer.unref) { + this.timer.unref(); + } + } + + stop() { + clearInterval(this.timer); + this.timer = null; + } + + /** A worker has been forked: listen for its reports. */ + add(worker) { + const entry = { worker, rss: 0, listening: false, draining: false, killTimer: null }; + this.workers.set(worker.process.pid, entry); + worker.on('message', (msg) => { + if (msg && msg.fhirsmith === 'memory-rss' && typeof msg.rss === 'number') { + entry.rss = msg.rss; + } + }); + } + + listening(worker) { + const e = this.workers.get(worker.process.pid); + if (e) { + e.listening = true; + } + } + + remove(worker) { + const e = this.workers.get(worker.process.pid); + if (e && e.killTimer) { + clearTimeout(e.killTimer); + } + this.workers.delete(worker.process.pid); + } + + /** The group's private memory now. */ + total() { + if (this.measure === 'cgroup') { + const v = this.readGroup(); + if (v > 0) { + return v; + } + } + let sum = this.ownRss(); + for (const e of this.workers.values()) { + sum += e.rss; + } + return sum; + } + + /** Once a second: measure, tell the workers, and recycle if the group stays over. */ + tick() { + const total = this.total(); + this.lastTotal = total; + const table = [...this.workers].map(([pid, e]) => [pid, e.rss]); + for (const e of this.workers.values()) { + try { + if (e.worker.isConnected()) { + e.worker.send({ fhirsmith: 'memory', total, workers: table }); + } + } catch { + // gone: its exit is handled elsewhere + } + } + this.checkRecycle(total); + } + + /** + * @returns {Object|null} the worker asked to drain, if one was + */ + checkRecycle(total) { + const now = this.now(); + if (total <= this.rejectAt) { + if (this.overSince) { + this.log(`memory: the service is back under ${gb(this.rejectAt)} GB (${gb(total)} GB)`); + } + this.overSince = 0; + this.recycles = 0; + return null; + } + if (!this.overSince) { + this.overSince = now; + this.log(`memory: the service is over ${gb(this.rejectAt)} GB (${gb(total)} GB of ${gb(this.limit)} GB); workers refuse new requests`); + } + if (!this.recycleAfterMs) { + return null; + } + const entries = [...this.workers.values()]; + // one at a time, and not while a worker is starting (it isn't serving yet) + if (entries.some(e => e.draining || !e.listening) || entries.length < 2) { + return null; + } + const wait = Math.min(this.recycleAfterMs * 2 ** this.recycles, MAX_RECYCLE_WAIT_MS); + if (now - this.overSince < wait) { + return null; + } + const largest = entries.reduce((a, b) => (b.rss > a.rss ? b : a)); + this.recycles++; + this.overSince = now; // the next one, if needed, waits from here + this.drain(largest, total, wait); + return largest.worker; + } + + drain(entry, total, waited) { + entry.draining = true; + const pid = entry.worker.process.pid; + this.log(`memory: the service has been over ${gb(this.rejectAt)} GB for ${Math.round(waited / 1000)} s ` + + `(${gb(total)} GB of ${gb(this.limit)} GB); recycling the largest worker, pid ${pid} (${gb(entry.rss)} GB): ` + + `it takes no new connections and has ${this.drainMs / 1000} s to finish its requests`); + entry.worker.recycled = true; + try { + entry.worker.send({ fhirsmith: 'drain', deadlineMs: this.drainMs }); + } catch { + // already going + } + entry.killTimer = setTimeout(() => { + if (!entry.worker.isDead()) { + this.log(`memory: worker pid ${pid} did not exit after draining; killing it`); + try { + entry.worker.process.kill('SIGKILL'); + } catch { + // gone + } + } + }, this.drainMs + DRAIN_KILL_GRACE_MS); + if (entry.killTimer.unref) { + entry.killTimer.unref(); + } + } +} + +module.exports = { ClusterMemory }; diff --git a/library/cluster-state.js b/library/cluster-state.js new file mode 100644 index 00000000..3f59f24e --- /dev/null +++ b/library/cluster-state.js @@ -0,0 +1,393 @@ +// +// State that the server processes on one data directory share: login sessions, +// session-signing secrets and rate-limit counters. +// +// With one server process (the default) none of this is used: each module keeps its +// logins and rate-limit counts in memory as before, and a module without a +// configured sessionSecret makes up a random one at start-up. A single process can +// opt in with "server": {"sharedState": true}: logins then survive a restart, and a +// generated secret is kept in the data directory. +// +// With several (cluster mode, or separately started processes with the +// background-jobs lock turned on - see library/background-jobs.js) any process may +// get any request, so a login made on one has to be found by the next, a cookie +// signed by one has to verify on another, and a rate limit has to count the +// requests that all of them saw. All three live in one SQLite file in the data +// directory, cluster-state.db: +// +// secrets name -> a random secret, made by whichever process asks first +// (INSERT OR IGNORE inside BEGIN IMMEDIATE, then read back: every +// process gets the same one). Used only when the module has no +// sessionSecret configured. +// sessions_ express-session sessions, one table per module (library/sqlite-session-store) +// rate_limits one row per limiter and client key: hits in the current window and +// when the window ends. Each increment is one BEGIN IMMEDIATE +// transaction, so two processes never both count from the same value. +// leases named locks held across processes for work that awaits (withLease): +// $closure's per-table lock, the FHIR validator download. A lease is a +// row with an expiry that the holder renews while it works, so one left +// by a process that died lapses on its own. +// +// As with the other shared files: WAL (readers don't wait for the writer), +// busy_timeout (a writer waits for another rather than failing), and the file must be +// on a local disk, never a network filesystem. +// + +const crypto = require('crypto'); +const fs = require('fs'); +const path = require('path'); + +const BUSY_TIMEOUT_MS = 5000; +const NAME = /^[A-Za-z0-9_-]{1,64}$/; + +let db = null; +let dbFile = null; +let override = null; // tests: force shared on or off +let optedIn = false; // server.sharedState + +/** + * Is state kept in cluster-state.db? True when several processes may share this data + * directory - cluster mode, or the background-jobs lock turned on for separately started + * processes - and when a single server asks for it (server.sharedState). + * @returns {boolean} + */ +function isShared() { + if (override !== null) { + return override; + } + return optedIn || require('./background-jobs').enabled; +} + +/** + * Called by server.js with the server settings. + * @param {{sharedState?: boolean}} [opts] - server.sharedState: keep logins, generated + * session secrets and rate-limit counts in cluster-state.db even with one process + */ +function configure(opts = {}) { + optedIn = opts.sharedState === true; +} + +function file() { + return dbFile || require('./folder-setup').filePath('cluster-state.db'); +} + +function open() { + if (db) { + return db; + } + const f = file(); + fs.mkdirSync(path.dirname(f), { recursive: true }); + const Database = require('better-sqlite3'); + const d = new Database(f, { timeout: BUSY_TIMEOUT_MS }); + d.pragma(`busy_timeout = ${BUSY_TIMEOUT_MS}`); + d.pragma('journal_mode = WAL'); + d.pragma('synchronous = NORMAL'); + d.transaction(() => { + d.exec(` + CREATE TABLE IF NOT EXISTS secrets (name TEXT PRIMARY KEY, value TEXT NOT NULL, created INTEGER NOT NULL); + CREATE TABLE IF NOT EXISTS rate_limits (key TEXT PRIMARY KEY, hits INTEGER NOT NULL, reset_at INTEGER NOT NULL); + CREATE INDEX IF NOT EXISTS rate_limits_reset ON rate_limits (reset_at); + CREATE TABLE IF NOT EXISTS leases (name TEXT PRIMARY KEY, holder TEXT NOT NULL, pid INTEGER, expires INTEGER NOT NULL); + `); + }).immediate(); + db = d; + return db; +} + +/** + * The secret a module signs its session cookies with. The configured one if there is + * one. Otherwise, with one process, a random one (logins then end when the server + * restarts, as they always have); with several, one random secret kept in + * cluster-state.db, so a cookie signed by one process verifies on all of them (and + * logins survive a restart). + * @param {string} name - the module (publisher, ips, testing, token, registry) + * @param {string} [configured] - the module's sessionSecret setting + * @returns {string} + */ +function sessionSecret(name, configured) { + if (configured) { + return configured; + } + if (!isShared()) { + return crypto.randomBytes(64).toString('hex'); + } + checkName(name); + const d = open(); + return d.transaction(() => { + d.prepare('INSERT OR IGNORE INTO secrets (name, value, created) VALUES (?, ?, ?)') + .run('session:' + name, crypto.randomBytes(64).toString('hex'), Date.now()); + return d.prepare('SELECT value FROM secrets WHERE name = ?').get('session:' + name).value; + }).immediate(); +} + +/** + * The express-session store for a module: undefined with one process (express-session + * then keeps sessions in memory, as before), else a SqliteSessionStore over its own + * table in cluster-state.db. + * @param {string} name - the module + * @returns {import('express-session').Store|undefined} + */ +function sessionStore(name) { + if (!isShared()) { + return undefined; + } + checkName(name); + const { SqliteSessionStore, betterSqlite } = require('./sqlite-session-store'); + return new SqliteSessionStore({ db: betterSqlite(open()), table: 'sessions_' + name.replace(/-/g, '_') }); +} + +/** + * An express-rate-limit store that counts in cluster-state.db, so that a limit holds for + * all the processes together rather than for each of them. + */ +class SharedRateLimitStore { + constructor(name) { + checkName(name); + this.prefix = name + ':'; + this.windowMs = 60 * 1000; + this.localKeys = false; + } + + init(options) { + this.windowMs = options.windowMs; + const d = open(); + this.q = { + get: d.prepare('SELECT hits, reset_at FROM rate_limits WHERE key = ?'), + put: d.prepare(`INSERT INTO rate_limits (key, hits, reset_at) VALUES (?, ?, ?) + ON CONFLICT (key) DO UPDATE SET hits = excluded.hits, reset_at = excluded.reset_at`), + dec: d.prepare('UPDATE rate_limits SET hits = max(hits - 1, 0) WHERE key = ? AND reset_at > ?'), + del: d.prepare('DELETE FROM rate_limits WHERE key = ?'), + delAll: d.prepare("DELETE FROM rate_limits WHERE key >= ? AND key < ?"), + sweep: d.prepare('DELETE FROM rate_limits WHERE reset_at <= ?') + }; + this.incTx = d.transaction((key) => { + const k = this.prefix + key; + const now = Date.now(); + const row = this.q.get.get(k); + let hits = 1; + let resetAt = now + this.windowMs; + if (row && row.reset_at > now) { + hits = row.hits + 1; + resetAt = row.reset_at; + } + this.q.put.run(k, hits, resetAt); + return { totalHits: hits, resetTime: new Date(resetAt) }; + }); + } + + async get(key) { + const row = this.q.get.get(this.prefix + key); + if (!row || row.reset_at <= Date.now()) { + return undefined; + } + return { totalHits: row.hits, resetTime: new Date(row.reset_at) }; + } + + async increment(key) { + return this.incTx.immediate(key); + } + + async decrement(key) { + this.q.dec.run(this.prefix + key, Date.now()); + } + + async resetKey(key) { + this.q.del.run(this.prefix + key); + } + + async resetAll() { + // every key of this limiter: [prefix, prefix + U+FFFF) + this.q.delAll.run(this.prefix, this.prefix + '￿'); + } + + /** Delete the counts whose window has ended (any process may; it is idempotent). */ + sweep() { + if (this.q) { + this.q.sweep.run(Date.now()); + } + } +} + +const stores = new Set(); +let sweepTimer = null; + +/** + * Options for express-rate-limit: the given ones, plus, when several processes share + * the data directory, a store in cluster-state.db named after the limiter. + * @param {string} name - unique per limiter, e.g. 'publisher-login' + * @param {Object} options - the express-rate-limit options + * @returns {Object} + */ +function rateLimitOptions(name, options) { + if (!isShared()) { + return options; + } + const store = new SharedRateLimitStore(name); + stores.add(store); + if (!sweepTimer) { + sweepTimer = setInterval(() => { + for (const s of stores) { + try { + s.sweep(); + } catch (e) { + // a busy database: next time + } + } + }, 10 * 60 * 1000); + if (sweepTimer.unref) { + sweepTimer.unref(); + } + } + return { ...options, store }; +} + +const DEFAULT_LEASE_TTL_MS = 30 * 1000; + +/** + * Run fn holding the named lease: no other process (or other call in this one) holds + * the same lease until fn settles. Waiting polls (5 ms, backing off to 100 ms); a lease + * whose holder stopped renewing it (the process died) lapses after ttlMs. fn may await + * as long as it likes: the lease is renewed every ttlMs / 3 while it runs. + * + * @param {string} name + * @param {Function} fn - async () => result + * @param {Object} [opts] + * @param {number} [opts.timeoutMs] - longest to wait; 0/absent = no limit. On timeout + * the error has .leaseTimeout = true + * @param {number} [opts.ttlMs=30000] + * @param {Function} [opts.waitFor] - (promise) => promise, wraps each wait (so a caller + * can stop waiting, e.g. when its client has gone) + * @returns {Promise<*>} what fn returns + */ +async function withLease(name, fn, opts = {}) { + const d = open(); + const ttl = opts.ttlMs > 0 ? opts.ttlMs : DEFAULT_LEASE_TTL_MS; + const holder = `${process.pid}:${crypto.randomUUID()}`; + const take = d.transaction(() => { + const now = Date.now(); + const row = d.prepare('SELECT holder, expires FROM leases WHERE name = ?').get(name); + if (row && row.expires > now) { + return false; + } + d.prepare(`INSERT INTO leases (name, holder, pid, expires) VALUES (?, ?, ?, ?) + ON CONFLICT (name) DO UPDATE SET holder = excluded.holder, pid = excluded.pid, expires = excluded.expires`) + .run(name, holder, process.pid, now + ttl); + return true; + }); + const started = Date.now(); + let pause = 5; + while (!take.immediate()) { + if (opts.timeoutMs && Date.now() - started >= opts.timeoutMs) { + const error = new Error(`timed out waiting for '${name}'`); + error.leaseTimeout = true; + throw error; + } + const sleep = new Promise(resolve => setTimeout(resolve, pause)); + await (opts.waitFor ? opts.waitFor(sleep) : sleep); + pause = Math.min(pause * 2, 100); + } + const renew = setInterval(() => { + try { + d.prepare('UPDATE leases SET expires = ? WHERE name = ? AND holder = ?').run(Date.now() + ttl, name, holder); + } catch (e) { + // busy: the next renewal is well inside the ttl + } + }, Math.max(100, Math.floor(ttl / 3))); + if (renew.unref) { + renew.unref(); + } + try { + return await fn(); + } finally { + clearInterval(renew); + try { + d.prepare('DELETE FROM leases WHERE name = ? AND holder = ?').run(name, holder); + } catch (e) { + // it lapses on its own after ttl + } + } +} + +/** + * Start a FHIR validator service (fhir-validator-wrapper) for a module. With one process, + * just validator.start(settings). With several, each runs its own validator, so: the + * first worker uses the configured port and every other one a free port the system + * gives it (two validators can't share a port); each writes its own tx log; and the jar + * is downloaded or updated by one process at a time, under a lease, since the download + * writes the jar in place. + * @param {Object} validator - a FhirValidator + * @param {Object} settings - what validator.start takes + * @param {Object} [log] + * @returns {Promise} + */ +async function startValidator(validator, settings, log) { + if (!isShared()) { + return validator.start(settings); + } + // a cluster worker other than the first; one process (server.sharedState, or separately + // started processes) keeps the configured port + const slot = Number(process.env.FHIRSMITH_CLUSTER_WORKER) || 0; + const s = { ...settings }; + if (slot > 1) { + s.port = await freePort(); + if (s.txLog) { + s.txLog = s.txLog.replace(/(\.[^./\\]*)?$/, `-${slot}$1`); + } + } + if (s.autoDownload !== false) { + await withLease('validator-jar', () => validator.ensureValidator({ skipUpdateCheck: !!s.skipUpdateCheck }), { ttlMs: 60 * 1000 }); + s.autoDownload = false; + } + if (log && s.port !== settings.port) { + log.info(`FHIR validator for this worker on port ${s.port} (the configured port ${settings.port} is the first worker's)`); + } + return validator.start(s); +} + +function freePort() { + return new Promise((resolve, reject) => { + const srv = require('net').createServer(); + srv.unref(); + srv.on('error', reject); + srv.listen(0, '127.0.0.1', () => { + const { port } = srv.address(); + srv.close(() => resolve(port)); + }); + }); +} + +function checkName(name) { + if (!NAME.test(name)) { + throw new Error('Invalid cluster state name: ' + name); + } +} + +/** Close the database (tests, shutdown). */ +function close() { + if (sweepTimer) { + clearInterval(sweepTimer); + sweepTimer = null; + } + stores.clear(); + if (db) { + try { + db.close(); + } catch (e) { + // best effort + } + db = null; + } +} + +/** + * For tests: use this file, and force sharing on or off (null: decide as the server does). + * @param {{file?: string, shared?: boolean|null}} opts + */ +function _configure(opts = {}) { + close(); + dbFile = opts.file || null; + override = opts.shared === undefined ? null : opts.shared; + optedIn = false; +} + +module.exports = { isShared, configure, sessionSecret, sessionStore, rateLimitOptions, SharedRateLimitStore, withLease, startValidator, close, _configure }; diff --git a/library/daily-report.js b/library/daily-report.js index 8ee441a8..1ec36823 100644 --- a/library/daily-report.js +++ b/library/daily-report.js @@ -160,7 +160,7 @@ class DailyReport { const state = this.readState(); // owed if a midnight has passed since the last report went out (a server // that has never reported waits for its first midnight) - if (state.sentAt && localDate(state.sentAt) !== localDate(now)) { + if (state.sentAt && localDate(state.sentAt) !== localDate(now) && require('./background-jobs').isLeader()) { this.log.info('Daily report: the server was down at midnight, sending it now'); void this.run(now); } @@ -171,6 +171,11 @@ class DailyReport { const delay = Math.max(1000, nextMidnight(now) - now); this.timer = setTimeout(() => { this.timer = null; + // With several processes, only the one running the background jobs sends it + if (!require('./background-jobs').isLeader()) { + this.schedule(); + return; + } // run() handles its own errors, so the promise never rejects void this.run().finally(() => this.schedule()); }, delay); diff --git a/library/memory-guard.js b/library/memory-guard.js index 232f488e..38c0cc11 100644 --- a/library/memory-guard.js +++ b/library/memory-guard.js @@ -2,6 +2,26 @@ * Process memory guard - the one place that decides how close to its memory limit the * server is, so the request gate (503) and the in-operation check (deadCheck, 422) agree. * + * One process (server.js): what follows, measured against the process's RSS. + * + * Cluster mode (cluster.js, more than one worker): the limit is the whole service's, + * and so is the measure - the workers share one cgroup, and one worker staying under a + * per-worker share does nothing for the group when another is far over it. The measure: + * - "cgroup": the private memory (memory.stat anon; v1 total_rss) of the cgroup the + * service runs in, read by each worker directly. Used on Linux when the service's + * own cgroup has a memory limit (MemoryMax on the unit or scope, a container limit). + * - "processes": the sum of every worker's RSS, which the primary collects over IPC + * and sends back to each worker every second (library/cluster-memory.js). Used + * everywhere else (macOS, Windows, a Linux service with no cgroup limit of its own). + * server.memory.measure ("cgroup" | "processes") forces one. The limit: server.memory.limit + * if set (for the group), else the cgroup limit, else the machine's RAM. + * - rejectFraction: every worker refuses new requests while the group is over it. + * - abortFraction: when the group is over it, running operations are aborted only in a + * worker that is the largest (by RSS), or holds more than 1.5 times its fair share + * (abortAt / workers). The others carry on: aborting their work frees little, and a + * single heavy worker would otherwise abort everyone's operations. If the group stays + * over, the primary drains and restarts the largest worker (cluster.js). + * * The limit is the cgroup limit the kernel will enforce (MemoryMax on the systemd unit, or * the container limit); with none, the machine's total RAM. Two thresholds, as fractions of * the limit, both measured against process RSS: @@ -17,9 +37,10 @@ */ const os = require('os'); +const path = require('path'); const v8 = require('v8'); const vm = require('vm'); -const { readCgroupMemoryLimit } = require('./cgroup-memory'); +const { readCgroupMemoryLimit, ownCgroupDir, readCgroupAnon } = require('./cgroup-memory'); const DEFAULT_REJECT_FRACTION = 0.85; const DEFAULT_ABORT_FRACTION = 0.92; @@ -34,6 +55,17 @@ const GC_INTERVAL_MS = 5000; // buffers), collecting frees little, and every full GC stops the process const GC_MAX_INTERVAL_MS = 60000; +// Cluster mode: a worker aborts operations only if it is the largest, or holds more than +// this many times its share of the abort threshold +const HEAVY_SHARE = 1.5; +// how often a worker tells the primary its RSS (and the primary tells the workers the group's) +const REPORT_MS = 1000; +// the group measure is read at most this often by the in-operation check +const GROUP_SAMPLE_MS = 100; +// one process: the in-operation check reuses a measure at most this old. It runs about ten +// times a request, and RSS moves little in 10 ms +const ABORT_SAMPLE_MS = 10; + const state = { limit: 0, source: null, @@ -42,23 +74,23 @@ const state = { rejectAt: 0, abortAt: 0, sampleTime: 0, - sampleRss: 0 + sampleRss: 0, // the last measure: this process's RSS, or in cluster mode the group's + // cluster mode (null: one process) + group: null }; -function fraction(v, dflt) { - return (typeof v === 'number' && v > 0 && v <= 1) ? v : dflt; -} - /** - * (Re)initialise. Called once at startup from server.js with config.server.memory; the module - * also self-initialises with defaults so code that loads without server.js (tests, tools) works. - * @param {object} [opts] - { rejectFraction, abortFraction, limit (bytes, for tests) } + * The limit to work against: the configured one, else the cgroup's, else the machine's RAM, + * and how the group is measured in cluster mode (see the header). Shared with the primary + * (library/cluster-memory.js), so both sides agree. + * @param {object} opts - config.server.memory + * @returns {{limit: number, source: string, measure: string, cgroup: Object|null}} */ -function configure(opts = {}) { +function resolveLimit(opts = {}) { let limit = opts.limit; let source = limit ? 'configured' : null; + const cg = readCgroupMemoryLimit(opts.cgroupOptions); if (!limit) { - const cg = readCgroupMemoryLimit(); limit = cg.limit; source = cg.source; } @@ -66,6 +98,31 @@ function configure(opts = {}) { limit = os.totalmem(); source = 'os.totalmem()'; } + // cgroup measure only for a cgroup that is the service's own: one with a limit set on it + const own = ownCgroupDir(opts.cgroupOptions); + const ownLimited = own && cg.source && path.dirname(cg.source) === own.dir; + let measure = opts.measure === 'cgroup' || opts.measure === 'processes' ? opts.measure : null; + if (!measure) { + measure = ownLimited && readCgroupAnon(own) > 0 ? 'cgroup' : 'processes'; + } + if (measure === 'cgroup' && !own) { + measure = 'processes'; + } + return { limit, source, measure, cgroup: measure === 'cgroup' ? own : null }; +} + +function fraction(v, dflt) { + return (typeof v === 'number' && v > 0 && v <= 1) ? v : dflt; +} + +/** + * (Re)initialise. Called once at startup from server.js with config.server.memory; the module + * also self-initialises with defaults so code that loads without server.js (tests, tools) works. + * @param {object} [opts] - { rejectFraction, abortFraction, limit (bytes, for tests) } + */ +function configure(opts = {}) { + stopGroup(); + const { limit, source, measure, cgroup } = resolveLimit(opts); state.limit = limit; state.source = source; state.rejectFraction = fraction(opts.rejectFraction, DEFAULT_REJECT_FRACTION); @@ -73,12 +130,147 @@ function configure(opts = {}) { state.rejectAt = limit * state.rejectFraction; state.abortAt = limit * state.abortFraction; state.sampleTime = 0; + // cluster mode: a worker of a cluster of more than one, or as a test asks + const size = opts.group ? opts.group.size : (clusterWorker() ? Number(process.env.FHIRSMITH_CLUSTER_SIZE) || 0 : 0); + if (size > 1) { + startGroup({ size, measure, cgroup, report: opts.group ? opts.group.report : undefined }); + } +} + +function clusterWorker() { + return typeof process.send === 'function' && require('cluster').isWorker; +} + +/** + * Cluster mode, in a worker: report this process's RSS to the primary every second, and + * take what the primary says about the group (every worker's RSS; in the "processes" + * measure, the group's total). + */ +function startGroup({ size, measure, cgroup, report }) { + const g = { + size, measure, cgroup, + workers: new Map(), // pid -> rss, as the primary last reported + total: 0, // the primary's measure of the group ("processes") + totalSelf: 0, // what that total counted for this process + spared: 0, + lastSpareLog: 0, + drainHandler: null, + report: report || ((msg) => { + if (process.connected) { + process.send(msg); + } + }) + }; + state.group = g; + const send = () => { + try { + g.report({ fhirsmith: 'memory-rss', rss: ownRss() }); + } catch { + // the primary has gone; it will take this worker with it + } + }; + if (!g.listener) { + g.listener = (msg) => handleMessage(msg); + process.on('message', g.listener); + } + send(); + g.timer = setInterval(send, REPORT_MS); + if (g.timer.unref) { + g.timer.unref(); + } } +function stopGroup() { + const g = state.group; + if (g) { + clearInterval(g.timer); + if (g.listener) { + process.removeListener('message', g.listener); + } + state.group = null; + } +} + +/** + * A message from the primary (cluster.js): {fhirsmith: 'memory', total, workers: [[pid, rss]...]}, + * or {fhirsmith: 'drain', deadlineMs}. Exported for tests. + */ +function handleMessage(msg) { + const g = state.group; + if (!g || !msg || typeof msg !== 'object') { + return; + } + if (msg.fhirsmith === 'memory') { + g.workers = new Map(msg.workers || []); + g.total = msg.total || 0; + g.totalSelf = g.workers.get(process.pid) || 0; + state.sampleTime = 0; // measure again with this + } else if (msg.fhirsmith === 'drain' && g.drainHandler) { + g.drainHandler(msg.deadlineMs); + } +} + +/** + * Cluster mode: what to do when the primary asks this worker to drain (stop taking + * connections, finish what it has, exit) so that it can be restarted. server.js sets it. + * @param {Function} fn - (deadlineMs) => void + */ +function onDrain(fn) { + if (state.group) { + state.group.drainHandler = fn; + } +} + +/** The group's private memory, now (cluster mode). */ +function groupMeasure() { + const g = state.group; + if (g.measure === 'cgroup') { + const v = readCgroupAnon(g.cgroup); + if (v > 0) { + return v; + } + } + // the primary's total, with this process's part brought up to date + const own = ownRss(); + return g.total > 0 ? Math.max(own, g.total - g.totalSelf + own) : own; +} + +/** + * Cluster mode: should this worker abort its operations when the group is over the abort + * threshold? Yes if it is the largest worker (by RSS; the primary's last report for the + * others, its own now), or holds more than HEAVY_SHARE times its share of the threshold. + * @param {number} own - this process's RSS + * @param {Map} workers - pid -> RSS of the workers (may include this one) + * @param {number} size - how many workers + * @param {number} abortAt - the group's abort threshold + * @param {number} [pid] - this process (ties go to the lower pid) + * @returns {boolean} + */ +function abortsHere(own, workers, size, abortAt, pid = process.pid) { + if (own > HEAVY_SHARE * abortAt / size) { + return true; + } + for (const [p, rss] of workers) { + if (p !== pid && (rss > own || (rss === own && p < pid))) { + return false; + } + } + return true; +} + +/** This process's memory, as the guard counts it (in cluster mode, its part of the group). */ +function ownRss() { + return process.memoryUsage.rss(); +} + +/** + * The measure the thresholds apply to: this process's RSS, or in cluster mode the group's + * private memory. A sample at most SAMPLE_MS old unless fresh. + */ function rss(fresh = false) { const now = Date.now(); if (fresh || now - state.sampleTime > SAMPLE_MS) { - state.sampleRss = process.memoryUsage.rss(); + state.sampleRss = state.group ? groupMeasure() : ownRss(); state.sampleTime = now; } return state.sampleRss; @@ -123,7 +315,9 @@ let lastAbortLog = 0; let abortLog = null; /** - * Current RSS in bytes if running operations should be aborted, else 0. Always a fresh read. + * Current RSS in bytes if running operations should be aborted, else 0. A measure at most + * ABORT_SAMPLE_MS old (in cluster mode, the group's measure at most GROUP_SAMPLE_MS old), or + * fresh if the sample was dropped (configure, a report from the primary). * A trip is written to the server log (at most once a minute, with a running count) - the * caller's own message only goes to the aborted operation's diagnostics. * @param {string} [place] - where the check was made, for the log @@ -132,10 +326,30 @@ function overAbortThreshold(place = 'unknown') { if (state.abortAt <= 0) { return 0; } - const r = rss(true); + const g = state.group; + // not a new measure on every check: the group measure reads a file (or adds up reports), + // and even RSS alone costs a few us, about ten times a request + const r = rss(Date.now() - state.sampleTime > (g ? GROUP_SAMPLE_MS : ABORT_SAMPLE_MS)); if (r <= state.abortAt) { return 0; } + if (g) { + const own = ownRss(); + if (!abortsHere(own, g.workers, g.size, state.abortAt)) { + g.spared++; + const now = Date.now(); + if (now - g.lastSpareLog > 60000) { + g.lastSpareLog = now; + let largest = 0; + for (const v of g.workers.values()) { + largest = Math.max(largest, v); + } + logWarn(`Memory critical: the service is at ${gb(r)} GB of ${gb(state.limit)} GB, but this worker ` + + `(${gb(own)} GB) is not the largest (${gb(largest)} GB): its operations carry on (${g.spared} checks so far)`); + } + return 0; + } + } aborts++; const now = Date.now(); if (now - lastAbortLog > 60000) { @@ -144,7 +358,9 @@ function overAbortThreshold(place = 'unknown') { if (!abortLog) { abortLog = require('./logger').getInstance().child({ module: 'memory' }); } - abortLog.warn(`Memory critical: ${gb(r)} GB of ${gb(state.limit)} GB - aborting running operations (at ${place}; ${aborts} aborted so far)`); + abortLog.warn(`Memory critical: ${gb(r)} GB of ${gb(state.limit)} GB` + + (g ? ` for the service (this worker ${gb(ownRss())} GB, the largest)` : '') + + ` - aborting running operations (at ${place}; ${aborts} aborted so far)`); } catch { // logging must never stop the abort } @@ -152,12 +368,25 @@ function overAbortThreshold(place = 'unknown') { return r; } +function logWarn(msg) { + try { + if (!abortLog) { + abortLog = require('./logger').getInstance().child({ module: 'memory' }); + } + abortLog.warn(msg); + } catch { + // logging must never get in the way + } +} + function gb(bytes) { return (bytes / 1024 / 1024 / 1024).toFixed(1); } function describe() { - return `Memory limit: ${gb(state.limit)} GB (from ${state.source}); ` + + const g = state.group; + return `Memory limit: ${gb(state.limit)} GB (from ${state.source})` + + (g ? ` for the whole service of ${g.size} workers, measured as ${g.measure === 'cgroup' ? 'the cgroup\'s private memory' : 'the sum of the workers\' RSS'}` : '') + '; ' + `new requests refused above ${gb(state.rejectAt)} GB (${Math.round(state.rejectFraction * 100)}%), ` + `operations aborted above ${gb(state.abortAt)} GB (${Math.round(state.abortFraction * 100)}%)`; } @@ -204,10 +433,12 @@ function middleware(opts = {}) { const before = state.sampleRss; const heap = heapUsed(); const gc = getGc(); - if (heap < before - state.rejectAt) { + // in cluster mode every worker refusing does this, so each need only free its share + const share = state.group ? state.group.size : 1; + if (heap < (before - state.rejectAt) / share) { gcWait = Math.min(gcWait * 2, gcMaxInterval); if (log) { - log.info(`Memory: no forced GC - the JS heap (${gb(heap)} GB) is less than the ${gb(before - state.rejectAt)} GB over the threshold; next look in ${secs(gcWait)}s`); + log.info(`Memory: no forced GC - the JS heap (${gb(heap)} GB) is less than ${share > 1 ? 'its share of ' : ''}the ${gb(before - state.rejectAt)} GB over the threshold; next look in ${secs(gcWait)}s`); } } else if (gc) { try { @@ -260,4 +491,7 @@ function middleware(opts = {}) { configure(); -module.exports = { configure, shouldReject, overAbortThreshold, describe, middleware, gb, getGc, _state: state }; +module.exports = { + configure, shouldReject, overAbortThreshold, describe, middleware, gb, getGc, onDrain, + resolveLimit, abortsHere, handleMessage, HEAVY_SHARE, REPORT_MS, _state: state +}; diff --git a/library/npm-audit.js b/library/npm-audit.js index c9f8a048..bd8a6be0 100644 --- a/library/npm-audit.js +++ b/library/npm-audit.js @@ -329,9 +329,12 @@ class NpmAudit { if (this.stats) { this.stats.addTask('npm audit', `${this.intervalHours} hr`); } - // run() handles its own errors, so the promise never rejects - const first = setTimeout(() => void this.run(), FIRST_RUN_DELAY_MS); - const repeat = setInterval(() => void this.run(), this.intervalHours * HOUR_MS); + // run() handles its own errors, so the promise never rejects. With several + // processes, only the one running the background jobs audits. + const backgroundJobs = require('./background-jobs'); + const tick = () => { if (backgroundJobs.isLeader()) { void this.run(); } }; + const first = setTimeout(tick, FIRST_RUN_DELAY_MS); + const repeat = setInterval(tick, this.intervalHours * HOUR_MS); for (const t of [first, repeat]) { if (t.unref) { t.unref(); diff --git a/library/sqlite-session-store.js b/library/sqlite-session-store.js index 1f9155e0..aa0f6e82 100644 --- a/library/sqlite-session-store.js +++ b/library/sqlite-session-store.js @@ -37,7 +37,12 @@ class SqliteSessionStore extends session.Store { .then(() => this.cleanup()); this.ready.catch(() => { /* reported by the first operation that waits on it */ }); const interval = options.cleanupIntervalMs > 0 ? options.cleanupIntervalMs : ONE_DAY_MS; - this.timer = setInterval(() => void this.cleanup().catch(() => {}), interval); + // expired sessions are deleted by whichever process runs the background jobs + this.timer = setInterval(() => { + if (require('./background-jobs').isLeader()) { + void this.cleanup().catch(() => {}); + } + }, interval); if (this.timer.unref) { this.timer.unref(); } diff --git a/nginx.md b/nginx.md index c242552f..bb09d3f0 100644 --- a/nginx.md +++ b/nginx.md @@ -248,6 +248,12 @@ That rules out DNS round-robin. Clients re-resolve the name and reconnect during so a long build drifts from one server to another. You need a single front door that routes each cached request back to the instance that owns the cache. +If the instances are on one machine, there is a simpler way: [cluster mode](cluster.md) runs +several processes on one port with the cache in a shared SQLite file, so any process can +serve any request and there is nothing to route. The rest of this section is for instances +on separate machines (each of which may itself run in cluster mode, with its own +`instanceCode`). + ### Instance codes Give each instance a short code in its config.json: diff --git a/package.json b/package.json index d306d5d9..e47714b5 100644 --- a/package.json +++ b/package.json @@ -9,6 +9,7 @@ }, "scripts": { "start": "node --expose-gc server.js", + "start:cluster": "node --expose-gc cluster.js", "dev": "node --expose-gc --watch server.js", "test": "jest", "test:watch": "jest --watch", diff --git a/packages/packages.js b/packages/packages.js index 178d10a6..74c2aee4 100644 --- a/packages/packages.js +++ b/packages/packages.js @@ -20,6 +20,7 @@ const {tokenMatches, tokenConfigured} = require("../library/request-token"); const pckLog = Logger.getInstance().child({ module: 'packages' }); const packagesOpenApi = require('./openapi'); const rateLimit = require('express-rate-limit'); +const { rateLimitOptions } = require('../library/cluster-state'); const { runNpmCheck, makeGetter } = require('./npm-check'); const npmCheckPage = require('./npm-check-page'); @@ -690,9 +691,12 @@ class PackagesModule { } async runCrawler() { + await this.followCrawlerStatus(true); this.totalRuns++; pckLog.info(`Running package crawler (run #${this.totalRuns})...`); this.crawlerRunning = true; + this.crawlingHere = true; + await this.saveCrawlerStatus(); try { try { this.lastCrawlerLog = await this.crawler.crawl(pckLog); @@ -712,6 +716,8 @@ class PackagesModule { } } finally { this.crawlerRunning = false; + this.crawlingHere = false; + await this.saveCrawlerStatus(); } } @@ -932,6 +938,10 @@ class PackagesModule { if (this.config.crawler && this.config.crawler.schedule) { this.stats.addTask("Package Crawler", describeCron(this.config.crawler.schedule)); this.crawlerJob = cron.schedule(this.config.crawler.schedule, async () => { + // with several processes, one of them crawls + if (!require('../library/background-jobs').isLeader()) { + return; + } pckLog.info('Starting scheduled package crawler...'); try { await this.runCrawler(); @@ -1039,10 +1049,82 @@ class PackagesModule { } } + /** + * With several processes on the data directory one of them runs the crawler, and the + * crawler's status (running, run count, when it last ran, its log) is what the status, + * log and stats pages show. The process that runs it writes the status to + * packages/crawler-status.json (renamed into place) when a run starts and ends; the + * others read it when a request reaches them and the file has changed since they last + * read it (checked at most once a second, one stat). With one process nothing is + * written: the status is in memory, as it always was. + */ + crawlerStatusFile() { + return folders.filePath('packages', 'crawler-status.json'); + } + + async saveCrawlerStatus() { + if (!require('../library/background-jobs').enabled) { + return; + } + try { + const file = this.crawlerStatusFile(); + const tmp = `${file}.${process.pid}.tmp`; + await fs.promises.mkdir(path.dirname(file), { recursive: true }); + await fs.promises.writeFile(tmp, JSON.stringify({ + totalRuns: this.totalRuns, lastRunTime: this.lastRunTime, + crawlerRunning: this.crawlerRunning, lastCrawlerLog: this.lastCrawlerLog + })); + await fs.promises.rename(tmp, file); + const st = await fs.promises.stat(file); + this.crawlerStatusVersion = `${st.ino}:${st.mtimeMs}`; + } catch (error) { + pckLog.warn(`Could not save the crawler status: ${error.message}`); + } + } + + /** + * Read the crawler status another process saved, if it has changed. + * @param {boolean} [now] - don't wait for the once-a-second check + */ + async followCrawlerStatus(now = false) { + if (!require('../library/background-jobs').enabled || this.crawlingHere) { + return; + } + const t = Date.now(); + if (!now && t - (this.crawlerStatusCheckedAt || 0) < 1000) { + return; + } + this.crawlerStatusCheckedAt = t; + try { + const file = this.crawlerStatusFile(); + const st = await fs.promises.stat(file); + const version = `${st.ino}:${st.mtimeMs}`; + if (version === this.crawlerStatusVersion) { + return; + } + const saved = JSON.parse(await fs.promises.readFile(file, 'utf8')); + if (this.crawlingHere) { + return; // started here meanwhile + } + this.crawlerStatusVersion = version; + this.totalRuns = saved.totalRuns || 0; + this.lastRunTime = saved.lastRunTime || null; + this.lastCrawlerLog = saved.lastCrawlerLog || {}; + this.crawlerRunning = !!saved.crawlerRunning; + } catch (error) { + // no status saved yet, or being replaced: next time + } + } + setupRoutes() { const searchParams = SEARCH_PARAMS; const updatesParams = UPDATES_PARAMS; + // with several processes: the crawler status the process running the crawler saved + this.router.use((req, res, next) => { + this.followCrawlerStatus().then(() => next(), () => next()); + }); + // OpenAPI description of this API: /openapi.json, /openapi.yaml, and /openapi (an HTML // reference for browsers, the JSON otherwise). Registered before /:id, which would // otherwise treat "openapi" as a package id. @@ -1100,14 +1182,14 @@ class PackagesModule { }); // GET /packages/npm-check - the npm registry protocol checks, against any registry - const npmCheckLimiter = rateLimit({ + const npmCheckLimiter = rateLimit(rateLimitOptions('packages-npm-check', { windowMs: 10 * 60 * 1000, limit: () => this.npmCheckConfig().runsPerWindow, skip: req => !req.query.registry, // only runs count, not the form standardHeaders: true, legacyHeaders: false, message: {error: 'Too many npm registry checks from this address; try again in a few minutes'} - }); + })); this.router.get('/npm-check', npmCheckLimiter, this.validateQueryParams(NPM_CHECK_PARAMS), async (req, res) => { const start = Date.now(); try { diff --git a/publisher/publisher.js b/publisher/publisher.js index 70c00d28..2a463075 100644 --- a/publisher/publisher.js +++ b/publisher/publisher.js @@ -9,7 +9,7 @@ const bcrypt = require('bcrypt'); const session = require('express-session'); const lusca = require('lusca'); const rateLimit = require('express-rate-limit'); -const crypto = require('crypto'); +const { rateLimitOptions } = require('../library/cluster-state'); const folders = require('../library/folder-setup'); const escape = require('escape-html'); const { requireSameOrigin } = require('../library/same-origin'); @@ -41,7 +41,8 @@ class PublisherModule { await this.initializeDatabase(); // Set up session middleware - use in-memory sessions or separate session db - if (!this.config.sessionSecret) { + const clusterState = require('../library/cluster-state'); + if (!this.config.sessionSecret && !clusterState.isShared()) { // Never fall back to a constant. This project is open source, so a fixed default // secret is a published signing key: anyone could mint themselves an admin session // on any deployment that forgot the setting, and nothing about the server would @@ -51,7 +52,9 @@ class PublisherModule { 'logins will not survive a restart. Set modules.publisher.sessionSecret.'); } this.router.use(session({ - secret: this.config.sessionSecret || crypto.randomBytes(64).toString('hex'), + // several processes: sessions and a generated secret are shared (library/cluster-state) + store: clusterState.sessionStore('publisher'), + secret: clusterState.sessionSecret('publisher', this.config.sessionSecret), resave: false, saveUninitialized: false, cookie: { @@ -68,7 +71,6 @@ class PublisherModule { httpOnly: true, maxAge: 24 * 60 * 60 * 1000 // 24 hours } - // Not using SQLiteStore to avoid the database conflict })); // every POST must come from one of our own pages - see library/same-origin.js @@ -113,6 +115,8 @@ class PublisherModule { return; } + // with several server processes, a write waits for another process's rather than failing + this.db.configure('busyTimeout', 5000); this.logger.info('Connected to SQLite database: ' + dbPath); this.createTables().then(resolve).catch(reject); }); @@ -331,32 +335,32 @@ class PublisherModule { // is the one unauthenticated route that runs bcrypt, and bcrypt.compare holds a libuv // threadpool thread (4 by default) for ~100ms - so without a limit a handful of // concurrent attempts stall every file operation the server wants to do. - const loginLimiter = rateLimit({ + const loginLimiter = rateLimit(rateLimitOptions('publisher-login', { windowMs: 15 * 60 * 1000, max: this.config.loginAttemptsPerWindow ?? 20, message: 'Too many login attempts, please try again later.', standardHeaders: true, legacyHeaders: false - }); + })); // Task actions delete build output from disk or queue new builds: a logged-in user can't // be allowed to hammer them either - const taskActionLimiter = rateLimit({ + const taskActionLimiter = rateLimit(rateLimitOptions('publisher-task-action', { windowMs: 60 * 1000, max: this.config.taskActionsPerMinute ?? 30, message: 'Too many task actions, please try again later.', standardHeaders: true, legacyHeaders: false - }); + })); // the task pages read build logs and QA output from disk - const taskReadLimiter = rateLimit({ + const taskReadLimiter = rateLimit(rateLimitOptions('publisher-task-read', { windowMs: 60 * 1000, max: this.config.taskReadsPerMinute ?? 300, message: 'Too many requests, please try again later.', standardHeaders: true, legacyHeaders: false - }); + })); this.router.get('/login', this.csrf, this.renderLogin.bind(this)); this.router.post('/login', loginLimiter, this.csrf, this.handleLogin.bind(this)); @@ -417,6 +421,8 @@ class PublisherModule { this.taskProcessor = setInterval(async () => { if (this.shutdownRequested) return; + // with several processes, only one of them works through the task queue + if (!this.isProcessing && !require('../library/background-jobs').isLeader()) return; if (this.isProcessing) { // A publication can legitimately run for longer than an hour (go-publish on a diff --git a/registry/auth.js b/registry/auth.js index 44ba7d4e..d0b6f094 100644 --- a/registry/auth.js +++ b/registry/auth.js @@ -26,6 +26,7 @@ const express = require('express'); const session = require('express-session'); const lusca = require('lusca'); const rateLimit = require('express-rate-limit'); +const { rateLimitOptions } = require('../library/cluster-state'); const { SqliteSessionStore, betterSqlite } = require('../library/sqlite-session-store'); // the requests already authenticated, and who they are (a promise) @@ -219,7 +220,7 @@ class RegistryAuth { if (limit === 0) { return (req, res, next) => next(); } - return rateLimit({ + return rateLimit(rateLimitOptions('registry-failed-auth', { windowMs: 15 * 60 * 1000, limit, standardHeaders: 'draft-7', @@ -230,7 +231,7 @@ class RegistryAuth { requestWasSuccessful: (req, res) => res.statusCode !== 401, skipSuccessfulRequests: true, handler: (req, res) => res.status(429).json({ error: 'too-many-requests', message: 'Too many requests with a token that is not valid for this registry; try again later' }) - }); + })); } /** @@ -381,7 +382,8 @@ class RegistryAuth { // ---- the pages: login, users, account ---- setupSession() { - if (!this.usersConfig.sessionSecret) { + const clusterState = require('../library/cluster-state'); + if (!this.usersConfig.sessionSecret && !clusterState.isShared()) { this.log.warn('Registry security: no users.sessionSecret configured - using a random one, so logins will not survive a restart'); } // sessions live in the auth database, so logins survive a restart (with a configured @@ -390,7 +392,8 @@ class RegistryAuth { this.session = session({ name: 'txreg.sid', store: this.sessionStore, - secret: this.usersConfig.sessionSecret || crypto.randomBytes(64).toString('hex'), + // several processes: a generated secret is shared (library/cluster-state) + secret: clusterState.sessionSecret('registry', this.usersConfig.sessionSecret), resave: false, saveUninitialized: false, cookie: { @@ -417,13 +420,13 @@ class RegistryAuth { return; } const r = router; - const loginLimiter = rateLimit({ + const loginLimiter = rateLimit(rateLimitOptions('registry-login', { windowMs: 15 * 60 * 1000, limit: this.usersConfig.loginAttemptsPerWindow ?? 20, standardHeaders: 'draft-7', legacyHeaders: false, handler: (req, res) => this.sendLogin(req, res, 429, 'Too many login attempts - try again later') - }); + })); const admin = (req, res, next) => { const user = this.currentUser(req); if (!user) { diff --git a/registry/registry.js b/registry/registry.js index edd9d9f1..875ee32c 100644 --- a/registry/registry.js +++ b/registry/registry.js @@ -57,6 +57,26 @@ function commonBaseUrl(urls) { return /^https?:\/\/[^/]+/.test(prefix) ? prefix : list[0]; } +// how often, at most, a request looks at whether another process has saved a crawl +const FOLLOW_CHECK_MS = 1000; + +/** inode, size and mtime of a file: different whenever it has been replaced. null if absent */ +async function fileVersion(file) { + try { + const st = await require('fs').promises.stat(file); + return `${st.ino}:${st.size}:${st.mtimeMs}`; + } catch (e) { + return null; + } +} + +async function writeAtomically(file, text) { + const fsp = require('fs').promises; + const tmp = `${file}.${process.pid}.tmp`; + await fsp.writeFile(tmp, text); + await fsp.rename(tmp, file); +} + class RegistryModule { constructor(stats) { this.router = express.Router(); @@ -146,7 +166,10 @@ class RegistryModule { async loadSavedData() { try { const fs = require('fs').promises; - const dataPath = folders.ensureFilePath('registry', 'registry-data.json'); // <-- CHANGE + const dataPath = this.dataFile(); + // which version of the file this is (see followSavedData): taken before reading, so a + // file replaced while it's being read is read again next time + this.loadedDataVersion = await fileVersion(dataPath); const data = await fs.readFile(dataPath, 'utf8'); const jsonData = JSON.parse(data); @@ -169,18 +192,49 @@ class RegistryModule { } } + /** Where the crawl is saved */ + dataFile() { + return folders.ensureFilePath('registry', 'registry-data.json'); + } + + /** + * With several processes on the data directory, one crawls and saves + * registry-data.json; the others notice on a request (at most one stat a second) that + * the file is a different version from the one they loaded - its inode changes, since + * it is renamed into place - and load it, in the background. + */ + followSavedData() { + if (!require('../library/background-jobs').enabled || this.crawlInProgress || this.followLoading) { + return; + } + const now = Date.now(); + if (now - (this.followCheckedAt || 0) < FOLLOW_CHECK_MS) { + return; + } + this.followCheckedAt = now; + this.followLoading = fileVersion(this.dataFile()).then((version) => { + if (version && version !== this.loadedDataVersion) { + this.logger.info('Registry data saved by another process; loading it'); + return this.loadSavedData(); + } + }).catch((err) => this.logger.error('Registry reload failed: ' + err.message)) + .finally(() => { this.followLoading = null; }); + } + /** * Save registry data to disk */ async saveData() { try { - const fs = require('fs').promises; - const dataPath = folders.ensureFilePath('registry', 'registry-data.json'); + const dataPath = this.dataFile(); const data = this.crawler.saveData(); - await fs.writeFile(dataPath, JSON.stringify(data, null, 2)); + // written whole and renamed into place: other processes read these files (followSavedData) const uptimePath = folders.ensureFilePath('registry', 'registry-uptime.json'); - await fs.writeFile(uptimePath, JSON.stringify(this.crawler.saveUptime())); + await writeAtomically(uptimePath, JSON.stringify(this.crawler.saveUptime())); + await writeAtomically(dataPath, JSON.stringify(data, null, 2)); + // this process has what it saved: no need to read it back + this.loadedDataVersion = await fileVersion(dataPath); this.logger.debug('Saved registry data to disk'); } catch (error) { this.logger.error('Failed to save registry data:', error); @@ -193,16 +247,21 @@ class RegistryModule { startPeriodicCrawl(intervalMinutes) { const intervalMs = intervalMinutes * 60 * 1000; + // With several processes, one of them crawls and saves; the others load what it saved + // when a request next reaches them (followSavedData) + const backgroundJobs = require('../library/background-jobs'); + const tick = () => { + if (backgroundJobs.isLeader()) { + this.performCrawl().catch((err) => this.logger.error('Registry crawl failed: ' + err.message)); + } + }; + // Run initial crawl after a short delay - setTimeout(() => { - this.performCrawl().catch((err) => this.logger.error('Registry crawl failed: ' + err.message)); - }, 5000); + setTimeout(tick, 5000); // Set up periodic crawling this.stats.addTask("TxRegistry", `${intervalMinutes} min`); - this.crawlInterval = setInterval(() => { - this.performCrawl().catch((err) => this.logger.error('Registry crawl failed: ' + err.message)); - }, intervalMs); + this.crawlInterval = setInterval(tick, intervalMs); this.logger.info(`Started periodic crawl every ${intervalMinutes} minutes`); } @@ -305,6 +364,12 @@ class RegistryModule { setupRoutes() { this.setupSecurityMiddleware(); + // with several processes: pick up a crawl another process has saved + this.router.use((req, res, next) => { + this.followSavedData(); + next(); + }); + // Attach API to all routes this.router.use((req, res, next) => { req.registryAPI = this.api; @@ -1886,4 +1951,6 @@ RegistryModule.RESOLVE_PARAMS = RESOLVE_PARAMS; RegistryModule.CHOOSE_SERVER_PARAMS = CHOOSE_SERVER_PARAMS; module.exports = RegistryModule; +module.exports.fileVersion = fileVersion; +module.exports.writeAtomically = writeAtomically; module.exports.commonBaseUrl = commonBaseUrl; \ No newline at end of file diff --git a/server.js b/server.js index cc724cd9..b32c9567 100644 --- a/server.js +++ b/server.js @@ -20,6 +20,8 @@ const { readCgroupMemoryLimit } = require('./library/cgroup-memory'); const memoryGuard = require('./library/memory-guard'); const { NpmAudit } = require('./library/npm-audit'); const Mailer = require('./library/mailer'); +const backgroundJobs = require('./library/background-jobs'); +const cluster = require('cluster'); const DailyReport = require('./library/daily-report'); // Load configuration BEFORE logger @@ -46,6 +48,20 @@ serverLog.info(`Node.js ${process.version} on ${os.type()} ${os.release()} (${os serverLog.info(`Memory: ${freeMemGB} GB free / ${totalMemGB} GB total`); memoryGuard.configure(config.server.memory || {}); serverLog.info(memoryGuard.describe()); +// Several processes on one data directory (cluster.js, or server.backgroundJobs.lock +// for separately started instances): only one of them runs the background jobs +backgroundJobs.configure({ + enabled: cluster.isWorker || !!(config.server.backgroundJobs && config.server.backgroundJobs.lock), + path: config.server.backgroundJobs && config.server.backgroundJobs.lockFile + ? path.resolve(folders.dataDir(), config.server.backgroundJobs.lockFile) : undefined, + log: Logger.getInstance().child({ module: 'background-jobs' }) +}); +// Logins, generated session secrets and rate limits in /cluster-state.db: always with +// several processes (above), and for one when server.sharedState is set +require('./library/cluster-state').configure({ sharedState: config.server.sharedState }); +if (cluster.isWorker) { + serverLog.info(`Cluster worker ${process.env.FHIRSMITH_CLUSTER_WORKER || '?'} of ${process.env.FHIRSMITH_CLUSTER_SIZE || '?'}; background jobs run in whichever worker holds ${backgroundJobs.file}`); +} serverLog.info(`Data directory: ${folders.dataDir()}`); serverLog.info(`========================================`); @@ -89,6 +105,16 @@ app.set('trust proxy', config.server.trustProxy ?? DEFAULT_TRUST_PROXY); const PORT = process.env.PORT || config.server.port || 3000; +// While draining (below), every response closes its connection, so a client on a +// keep-alive connection reconnects - to another worker +let draining = false; +app.use((req, res, next) => { + if (draining) { + res.setHeader('Connection', 'close'); + } + next(); +}); + // Middleware // Refuse new requests (503) while memory is near the limit - first, so a refused request // doesn't even have its body parsed. /dashboard stays reachable so the state can be seen. @@ -836,10 +862,11 @@ async function startServer() { }); // Start server - app.listen(PORT, () => { + httpServer = app.listen(PORT, () => { stats.markStarted(packageJson.version); serverLog.info(`=== Server running on http://localhost:${PORT} ===`); }); + memoryGuard.onDrain(drain); npmAudit.start(); dailyReport = new DailyReport(config.dailyReport, { log: Logger.getInstance().child({ module: 'daily-report' }), @@ -851,7 +878,7 @@ async function startServer() { serverId: config.hostName }); dailyReport.start(); - if (modules.packages && config.modules?.packages?.enabled) { + if (modules.packages && config.modules?.packages?.enabled && backgroundJobs.isLeader()) { modules.packages.startInitialCrawler(); } // Run usage tracker in background after startup @@ -875,6 +902,44 @@ async function startServer() { } } +/** + * Cluster mode: the primary asks this worker to drain, so that it can be restarted (the + * service has stayed over its memory limit and this is the largest worker - see + * library/cluster-memory.js). Stop taking connections (the primary gives new ones to the + * other workers), close idle keep-alive connections and close each busy one after its + * response, wait until every connection has closed (so every request in progress has + * been answered) or the deadline, then shut down as on SIGTERM; cluster.js starts a new + * worker in its place. + */ +let httpServer = null; +function drain(deadlineMs) { + if (draining || shuttingDown || !httpServer) { + return; + } + draining = true; + let finished = false; + const done = (why) => { + if (!finished) { + finished = true; + clearInterval(idle); + clearTimeout(timer); + serverLog.warn(why); + void shutdown(); + } + }; + httpServer.getConnections((err, n) => { + serverLog.warn(`Draining for a restart (memory): no new connections; ${err ? '?' : n} open, ` + + `up to ${Math.round(deadlineMs / 1000)} s for their requests to finish`); + }); + // the callback runs once the last connection has closed + httpServer.close(() => done('Drained: every connection has closed; restarting')); + httpServer.closeIdleConnections(); + const idle = setInterval(() => httpServer.closeIdleConnections(), 100); + const timer = setTimeout(() => { + httpServer.getConnections((err, n) => done(`Drain deadline reached with ${err ? '?' : n} connection(s) still open; restarting`)); + }, deadlineMs); +} + // Graceful shutdown: on Ctrl-C (SIGINT), and on SIGTERM - what systemd, docker stop and // kill send - so the modules can save what they hold (usage counts, crawl data) either way let shuttingDown = false; @@ -890,6 +955,7 @@ async function shutdown() { if (dailyReport) { dailyReport.stop(); } + backgroundJobs.close(); // Shutdown all modules for (const [moduleName, moduleInstance] of Object.entries(modules)) { diff --git a/shl/shl.js b/shl/shl.js index d820ffd8..e6637dab 100644 --- a/shl/shl.js +++ b/shl/shl.js @@ -275,6 +275,8 @@ class SHLModule { shlLog.error('Error opening SHL SQLite database at "'+dbPath+'":', err.message); reject(err); } else { + // with several server processes, a write waits for another process's rather than failing + this.db.configure('busyTimeout', 5000); shlLog.info('Connected to SHL SQLite database at "'+dbPath+'"'); // Check if tables already exist before creating them @@ -385,7 +387,8 @@ class SHLModule { const validatorJarPath = folders.filePath('bin', 'validator_cli.jar'); this.fhirValidator = new FhirValidator(validatorJarPath, shlLog); - await this.fhirValidator.start(validatorConfig); + // with several server processes, each runs its own validator (library/cluster-state) + await require('../library/cluster-state').startValidator(this.fhirValidator, validatorConfig, shlLog); shlLog.info('FHIR Validator started successfully'); } catch (error) { @@ -411,6 +414,10 @@ class SHLModule { startCleanupJob() { if (this.config.cleanup && this.config.cleanup.schedule) { this.cleanupJob = cron.schedule(this.config.cleanup.schedule, () => { + // with several processes, one of them cleans up + if (!require('../library/background-jobs').isLeader()) { + return; + } shlLog.info('Running scheduled cleanup of expired SHL entries...'); this.cleanupExpiredEntries(); }); diff --git a/testing/testing.js b/testing/testing.js index 1d90babb..f03cb637 100644 --- a/testing/testing.js +++ b/testing/testing.js @@ -34,6 +34,7 @@ const express = require('express'); const path = require('path'); const crypto = require('crypto'); const rateLimit = require('express-rate-limit'); +const { rateLimitOptions } = require('../library/cluster-state'); const escape = require('escape-html'); const session = require('express-session'); const lusca = require('lusca'); @@ -183,14 +184,17 @@ class TestingModule { * _csrf field, and the Origin check (library/same-origin). The cookie is also SameSite=Lax. */ setupSession() { - if (!this.config.sessionSecret) { + const clusterState = require('../library/cluster-state'); + if (!this.config.sessionSecret && !clusterState.isShared()) { // as for the publisher: never a constant secret, which would be a published signing key this.log.warn('testing: no sessionSecret configured - using a random one, so logins will not ' + 'survive a restart. Set modules.testing.sessionSecret.'); } this.session = session({ name: 'testing.sid', - secret: this.config.sessionSecret || crypto.randomBytes(64).toString('hex'), + // several processes: sessions and a generated secret are shared (library/cluster-state) + store: clusterState.sessionStore('testing'), + secret: clusterState.sessionSecret('testing', this.config.sessionSecret), resave: false, saveUninitialized: false, cookie: { @@ -220,13 +224,13 @@ class TestingModule { const max = rl.max === undefined ? 60 : rl.max; const posting = []; if (max > 0) { - posting.push(rateLimit({ + posting.push(rateLimit(rateLimitOptions('testing-submit', { windowMs: (rl.windowMinutes || 1) * 60 * 1000, limit: max, standardHeaders: 'draft-7', legacyHeaders: false, handler: (req, res) => this.sendOutcome(res, 429, 'throttled', 'Too many reports submitted; try again later') - })); + }))); } // RFC 8631: where to find the machine-readable description of this API @@ -281,8 +285,11 @@ class TestingModule { if (this.stats) { this.stats.addTask('TestReport retention', 'daily'); } - purge(); - this.retentionTimer = setInterval(purge, DAY_MS); + // with several processes, one of them purges + const backgroundJobs = require('../library/background-jobs'); + const tick = () => { if (backgroundJobs.isLeader()) { purge(); } }; + tick(); + this.retentionTimer = setInterval(tick, DAY_MS); this.retentionTimer.unref(); } @@ -625,13 +632,13 @@ class TestingModule { setupAdminRoutes() { const r = this.router; const form = express.urlencoded({ extended: false, limit: '64kb' }); - const loginLimiter = rateLimit({ + const loginLimiter = rateLimit(rateLimitOptions('testing-login', { windowMs: 15 * 60 * 1000, limit: this.config.loginAttemptsPerWindow ?? 20, standardHeaders: 'draft-7', legacyHeaders: false, handler: (req, res) => this.sendLogin(req, res, 429, 'Too many login attempts - try again later') - }); + })); // every form post must come from one of our own pages const sameOrigin = requireSameOrigin((req, res) => htmlServer.sendErrorResponse(res, TEMPLATE, new Error('Cross-site form posts are not accepted'), 403)); diff --git a/tests/library/background-jobs.test.js b/tests/library/background-jobs.test.js new file mode 100644 index 00000000..326fd08e --- /dev/null +++ b/tests/library/background-jobs.test.js @@ -0,0 +1,79 @@ +/** + * The background-jobs lock: with several processes on one data directory, exactly + * one runs the timed jobs, and another takes over when it stops. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const { BackgroundJobs } = require('../../library/background-jobs'); + +describe('background jobs lock', () => { + let dir; + let file; + const made = []; + const make = (opts = {}) => { + const b = new BackgroundJobs().configure({ enabled: true, path: file, ...opts }); + made.push(b); + return b; + }; + + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'background-jobs-')); + file = path.join(dir, 'background-jobs.lock'); + }); + afterEach(() => { + while (made.length) { + made.pop().close(); + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('without a lock (one process) every job runs', () => { + const b = new BackgroundJobs().configure({ enabled: false }); + expect(b.isLeader()).toBe(true); + expect(b.holder()).toBeNull(); + expect(fs.existsSync(file)).toBe(false); + }); + + test('exactly one of several processes runs the jobs, and keeps running them', () => { + const a = make(); + const b = make(); + const c = make(); + expect(a.isLeader()).toBe(true); + expect(b.isLeader()).toBe(false); + expect(c.isLeader()).toBe(false); + expect(a.isLeader()).toBe(true); + expect(b.isLeader()).toBe(false); + expect(a.holder().me).toBe(true); + expect(b.holder().me).toBe(false); + expect(b.holder().pid).toBe(process.pid); + }); + + test('when the holder shuts down, the next process to ask takes over at once', () => { + const a = make(); + const b = make(); + expect(a.isLeader()).toBe(true); + expect(b.isLeader()).toBe(false); + a.close(); + expect(b.isLeader()).toBe(true); + }); + + test('a holder that stops renewing (crashed or hung) is taken over after staleMs, not before', () => { + const a = make({ staleMs: 60000 }); + const b = make({ staleMs: 60000 }); + expect(a.isLeader()).toBe(true); + const lock = a.db; + lock.prepare('UPDATE holder SET renewed = ?').run(Date.now() - 30000); + expect(b.isLeader()).toBe(false); + lock.prepare('UPDATE holder SET renewed = ?').run(Date.now() - 61000); + expect(b.isLeader()).toBe(true); + // and the old holder learns it has lost it + expect(a.isLeader()).toBe(false); + }); + + test('if the lock cannot be read, the job is not run (never two at once)', () => { + const a = make(); + a.q.get = { get: () => { throw new Error('disk I/O error'); } }; + expect(a.isLeader()).toBe(false); + }); +}); diff --git a/tests/library/cluster-memory.test.js b/tests/library/cluster-memory.test.js new file mode 100644 index 00000000..44a42eee --- /dev/null +++ b/tests/library/cluster-memory.test.js @@ -0,0 +1,154 @@ +/** + * The primary's side of the group memory guard (library/cluster-memory.js): it measures the + * service, tells the workers, and recycles the largest worker when the service stays over + * the reject threshold - one at a time, never while one is starting, backing off. + */ +const EventEmitter = require('events'); +const { ClusterMemory } = require('../../library/cluster-memory'); + +const GB = 1024 * 1024 * 1024; + +function fakeWorker(pid) { + const w = new EventEmitter(); + w.process = { pid, kill: jest.fn() }; + w.sent = []; + w.send = (m) => w.sent.push(m); + w.isConnected = () => true; + w.isDead = () => false; + w.report = (rss) => w.emit('message', { fhirsmith: 'memory-rss', rss }); + return w; +} + +describe('ClusterMemory', () => { + let now; + let logs; + let cm; + const make = (memory = {}) => { + cm = new ClusterMemory({ + memory: { limit: 10 * GB, measure: 'processes', recycleAfterSeconds: 60, drainSeconds: 30, ...memory }, + log: (m) => logs.push(m), now: () => now, ownRss: () => 0.1 * GB + }); + return cm; + }; + const workers = (...rss) => rss.map((r, i) => { + const w = fakeWorker(1000 + i); + cm.add(w); + cm.listening(w); + w.report(r * GB); + return w; + }); + const drained = (ws) => ws.filter(w => w.sent.some(m => m.fhirsmith === 'drain')); + + beforeEach(() => { + now = 1000000; + logs = []; + }); + afterEach(() => { + for (const e of cm.workers.values()) { + clearTimeout(e.killTimer); + } + }); + + test('tells every worker each one\'s RSS and the total', () => { + make(); + const ws = workers(1, 2, 3); + cm.tick(); + const msg = ws[0].sent.find(m => m.fhirsmith === 'memory'); + expect(msg.total).toBeCloseTo(6.1 * GB); + expect(msg.workers).toEqual([[1000, 1 * GB], [1001, 2 * GB], [1002, 3 * GB]]); + expect(ws[2].sent.find(m => m.fhirsmith === 'memory')).toEqual(msg); + }); + + test('over the reject threshold for recycleAfterSeconds: the largest worker is drained', () => { + make(); + const ws = workers(2, 5, 2); // 9.1 GB > 8.5 + cm.tick(); + expect(drained(ws)).toHaveLength(0); + now += 59 * 1000; + cm.tick(); + expect(drained(ws)).toHaveLength(0); + now += 1000; + cm.tick(); + expect(drained(ws)).toEqual([ws[1]]); + expect(ws[1].sent.find(m => m.fhirsmith === 'drain')).toEqual({ fhirsmith: 'drain', deadlineMs: 30000 }); + expect(ws[1].recycled).toBe(true); + expect(logs.some(l => /recycling the largest worker, pid 1001/.test(l))).toBe(true); + }); + + test('back under before the time: nothing is recycled', () => { + make(); + const ws = workers(2, 5, 2); + cm.tick(); + now += 30 * 1000; + ws[1].report(3 * GB); + cm.tick(); + now += 60 * 1000; + cm.tick(); + expect(drained(ws)).toHaveLength(0); + }); + + test('one at a time, not while a worker is starting, and each further one waits twice as long', () => { + make(); + const ws = workers(2, 5, 2); + cm.tick(); + now += 60 * 1000; + cm.tick(); + expect(drained(ws)).toEqual([ws[1]]); + // still draining: nothing else + now += 60 * 1000; + cm.tick(); + expect(drained(ws)).toHaveLength(1); + // it exits and its replacement starts; still over (the others grew) + cm.remove(ws[1]); + const fresh = fakeWorker(2000); + cm.add(fresh); + fresh.report(1 * GB); + ws[0].report(4 * GB); + ws[2].report(4 * GB); + now += 120 * 1000; + cm.tick(); + expect(drained([...ws, fresh])).toHaveLength(1); // the new one isn't listening yet + cm.listening(fresh); + cm.tick(); // the wait is now 120 s from the last recycle, which was > 120 s ago + expect(drained([...ws, fresh])).toHaveLength(2); + // the third would wait 240 s + cm.remove(ws[0]); + const fresh2 = fakeWorker(2001); + cm.add(fresh2); + cm.listening(fresh2); + fresh2.report(1 * GB); + ws[2].report(8 * GB); + now += 200 * 1000; + cm.tick(); + expect(drained([ws[2]])).toHaveLength(0); + now += 40 * 1000; + cm.tick(); + expect(drained([ws[2]])).toHaveLength(1); + }); + + test('a drained worker that does not exit is killed after its deadline', () => { + jest.useFakeTimers(); + try { + make({ drainSeconds: 2 }); + const ws = workers(2, 5, 2); + cm.tick(); + now += 60 * 1000; + cm.tick(); + jest.advanceTimersByTime(11 * 1000); + expect(ws[1].process.kill).not.toHaveBeenCalled(); + jest.advanceTimersByTime(2 * 1000); + expect(ws[1].process.kill).toHaveBeenCalledWith('SIGKILL'); + } finally { + jest.useRealTimers(); + } + }); + + test('recycleAfterSeconds 0 turns recycling off', () => { + make({ recycleAfterSeconds: 0 }); + const ws = workers(2, 5, 2); + cm.tick(); + now += 3600 * 1000; + cm.tick(); + expect(drained(ws)).toHaveLength(0); + }); +}); diff --git a/tests/library/cluster-state.test.js b/tests/library/cluster-state.test.js new file mode 100644 index 00000000..01274b3e --- /dev/null +++ b/tests/library/cluster-state.test.js @@ -0,0 +1,249 @@ +/** + * State several server processes share (library/cluster-state.js): logins, the secret + * session cookies are signed with, rate limits, leases. The multi-process tests run two + * real processes on one data directory, each serving the testing module, the way + * cluster-mode workers do: a login made through one is used through the other. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const { fork } = require('child_process'); +const clusterState = require('../../library/cluster-state'); + +const CHILD = path.join(__dirname, '..', 'utils', 'cluster-state-child.js'); + +describe('with one process nothing is shared', () => { + beforeEach(() => clusterState._configure({ shared: false })); + afterEach(() => clusterState._configure()); + + test('memory sessions, a random secret, memory rate limits', () => { + expect(clusterState.isShared()).toBe(false); + expect(clusterState.sessionStore('publisher')).toBeUndefined(); + expect(clusterState.sessionSecret('publisher')).not.toBe(clusterState.sessionSecret('publisher')); + expect(clusterState.sessionSecret('publisher', 'configured')).toBe('configured'); + const opts = { windowMs: 1000, limit: 3 }; + expect(clusterState.rateLimitOptions('x', opts)).toBe(opts); + }); + + test('the server decides by whether the background-jobs lock is on', () => { + clusterState._configure(); + const bj = require('../../library/background-jobs'); + expect(clusterState.isShared()).toBe(bj.enabled); + }); +}); + +describe('server.sharedState: one process opts in', () => { + let dir; + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'cluster-state-opt-')); + }); + afterEach(() => { + clusterState._configure(); + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('off (the default): nothing shared; on: shared, and the secret is kept across a restart', () => { + clusterState._configure({ file: path.join(dir, 'cluster-state.db') }); + clusterState.configure({}); + expect(clusterState.isShared()).toBe(false); + expect(clusterState.sessionStore('testing')).toBeUndefined(); + expect(fs.existsSync(path.join(dir, 'cluster-state.db'))).toBe(false); + + clusterState.configure({ sharedState: true }); + expect(clusterState.isShared()).toBe(true); + expect(clusterState.sessionStore('testing')).toBeDefined(); + const secret = clusterState.sessionSecret('testing'); + // a restart: the database is closed and opened again + clusterState._configure({ file: path.join(dir, 'cluster-state.db') }); + clusterState.configure({ sharedState: true }); + expect(clusterState.sessionSecret('testing')).toBe(secret); + }); +}); + +describe('shared, in one process', () => { + let dir; + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'cluster-state-')); + clusterState._configure({ file: path.join(dir, 'cluster-state.db'), shared: true }); + }); + afterEach(() => { + clusterState._configure(); + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('the secret is made once and kept; a configured one wins', () => { + const s = clusterState.sessionSecret('ips'); + expect(s).toMatch(/^[0-9a-f]{128}$/); + expect(clusterState.sessionSecret('ips')).toBe(s); + expect(clusterState.sessionSecret('testing')).not.toBe(s); + expect(clusterState.sessionSecret('ips', 'mine')).toBe('mine'); + }); + + test('the rate limit store counts per key, within the window, and can go down', async () => { + const { store } = clusterState.rateLimitOptions('t', { windowMs: 200 }); + store.init({ windowMs: 200 }); + expect((await store.increment('a')).totalHits).toBe(1); + expect((await store.increment('a')).totalHits).toBe(2); + expect((await store.increment('b')).totalHits).toBe(1); + await store.decrement('a'); + expect((await store.get('a')).totalHits).toBe(1); + await new Promise(resolve => setTimeout(resolve, 250)); + expect(await store.get('a')).toBeUndefined(); + expect((await store.increment('a')).totalHits).toBe(1); + await store.resetAll(); + expect(await store.get('b')).toBeUndefined(); + }); + + test('a lease times out while another holds it, and lapses when its holder stops renewing', async () => { + let release; + const held = clusterState.withLease('x', () => new Promise(resolve => { release = resolve; }), { ttlMs: 300 }); + await new Promise(resolve => setTimeout(resolve, 20)); + await expect(clusterState.withLease('x', async () => 1, { timeoutMs: 100 })).rejects.toMatchObject({ leaseTimeout: true }); + release(); + await held; + expect(await clusterState.withLease('x', async () => 2, { timeoutMs: 100 })).toBe(2); + }); +}); + +describe('two processes on one data directory', () => { + let dir; + const children = []; + + const spawn = (mode = 'cluster') => { + const child = fork(CHILD, [dir, mode], { stdio: ['ignore', 'ignore', 'pipe', 'ipc'] }); + children.push(child); + let stderr = ''; + child.stderr.on('data', (d) => { stderr += d; }); + let seq = 0; + const waiting = new Map(); + let readyResolve; + let readyReject; + const ready = new Promise((resolve, reject) => { readyResolve = resolve; readyReject = reject; }); + child.on('exit', (code) => readyReject(new Error(`child exited (${code}): ${stderr}`))); + child.on('message', (m) => { + if (m.ready) { + readyResolve(m.ready); + } else { + waiting.get(m.seq)(m.result); + } + }); + const call = (op, args = {}) => new Promise(resolve => { + const s = ++seq; + waiting.set(s, resolve); + child.send({ seq: s, op, ...args }); + }); + const stop = () => new Promise(resolve => { + child.once('exit', resolve); + child.kill(); + }); + return ready.then(port => ({ port, call, stop, base: `http://127.0.0.1:${port}/testing` })); + }; + + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'cluster-state-mp-')); + }); + afterEach(async () => { + for (const c of children.splice(0)) { + if (c.exitCode === null && c.signalCode === null) { + await new Promise(resolve => { + c.once('exit', resolve); + c.kill(); + }); + } + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + // a browser: cookies kept by name, whichever process set them + const browser = () => { + const jar = new Map(); + const go = async (url, opts = {}) => { + const headers = { ...(opts.headers || {}) }; + if (jar.size) { + headers.cookie = [...jar].map(([k, v]) => `${k}=${v}`).join('; '); + } + const res = await fetch(url, { ...opts, headers, redirect: 'manual' }); + for (const c of res.headers.getSetCookie()) { + const [kv] = c.split(';'); + const i = kv.indexOf('='); + jar.set(kv.substring(0, i), kv.substring(i + 1)); + } + return { status: res.status, text: await res.text(), location: res.headers.get('location') }; + }; + const csrf = async (base) => (await go(`${base}/login`)).text.match(/name="_csrf" value="([^"]+)"/)[1]; + const post = async (base, url, data) => go(url, { + method: 'POST', + headers: { 'content-type': 'application/x-www-form-urlencoded', origin: new URL(base).origin }, + body: new URLSearchParams({ ...data, _csrf: await csrf(base) }).toString() + }); + return { go, post }; + }; + + test('a login made on one process is used, and ended, on the other', async () => { + const [a, b] = await Promise.all([spawn(), spawn()]); + expect(await a.call('secret')).toBe(await b.call('secret')); + + const me = browser(); + // the CSRF token comes from a page served by A; the login is posted to B + const csrfFromA = await me.go(`${a.base}/login`).then(r => r.text.match(/name="_csrf" value="([^"]+)"/)[1]); + const login = await me.go(`${b.base}/login`, { + method: 'POST', + headers: { 'content-type': 'application/x-www-form-urlencoded', origin: `http://127.0.0.1:${b.port}` }, + body: new URLSearchParams({ login: 'admin', password: 'admin-secret', _csrf: csrfFromA }).toString() + }); + expect(login.status).toBe(302); + // logged in on both + expect((await me.go(`${a.base}`)).text).toContain('Logged in as Administrator'); + expect((await me.go(`${b.base}`)).text).toContain('Logged in as Administrator'); + expect((await me.go(`${a.base}/admin/users`)).status).toBe(200); + // logged out on A: B no longer knows the session either + expect((await me.post(a.base, `${a.base}/logout`, {})).status).toBe(302); + expect((await me.go(`${b.base}/admin/users`)).status).toBe(302); + }); + + test('the login rate limit counts the attempts both processes saw', async () => { + const [a, b] = await Promise.all([spawn(), spawn()]); + const me = browser(); + const statuses = []; + // the limit is 5 per window: three wrong passwords at A, two at B, then the sixth is refused + for (const p of [a, a, a, b, b, b]) { + statuses.push((await me.post(p.base, `${p.base}/login`, { login: 'admin', password: 'wrong' })).status); + } + expect(statuses).toEqual([401, 401, 401, 401, 401, 429]); + }); + + // one process, stopped and started again: is the login still good? + const loginSurvivesRestart = async (mode) => { + const first = await spawn(mode); + const me = browser(); + const login = await me.post(first.base, `${first.base}/login`, { login: 'admin', password: 'admin-secret' }); + expect(login.status).toBe(302); + expect((await me.go(`${first.base}/admin/users`)).status).toBe(200); + await first.stop(); + const second = await spawn(mode); + return (await me.go(`${second.base}/admin/users`)).status === 200; + }; + + test('one process by default: a login ends with a restart (as on main)', async () => { + expect(await loginSurvivesRestart('off')).toBe(false); + expect(fs.existsSync(path.join(dir, 'cluster-state.db'))).toBe(false); + }); + + test('one process with server.sharedState: a login survives a restart', async () => { + expect(await loginSurvivesRestart('opt-in')).toBe(true); + }); + + test('a lease is held by one process at a time', async () => { + const [a, b] = await Promise.all([spawn(), spawn()]); + await Promise.all([a.call('lease', { times: 5, ms: 15 }), b.call('lease', { times: 5, ms: 15 })]); + const events = fs.readFileSync(path.join(dir, 'lease.log'), 'utf8').trim().split('\n').map(l => l.split(' ')); + expect(events).toHaveLength(20); + // in, out, in, out ... and each out is by the process that went in + for (let i = 0; i < events.length; i += 2) { + expect(events[i][1]).toBe('in'); + expect(events[i + 1][1]).toBe('out'); + expect(events[i + 1][0]).toBe(events[i][0]); + } + expect(new Set(events.map(e => e[0])).size).toBe(2); + }); +}); diff --git a/tests/library/memory-guard.test.js b/tests/library/memory-guard.test.js index c2da3984..9cc743f8 100644 --- a/tests/library/memory-guard.test.js +++ b/tests/library/memory-guard.test.js @@ -138,6 +138,40 @@ describe('memory-guard', () => { } }); + test('many checks inside 10 ms read RSS once; a dropped sample is measured again at once', () => { + let now = 1000000; + const nowSpy = jest.spyOn(Date, 'now').mockImplementation(() => now); + try { + setRss(9.5 * GB); + rssSpy.mockClear(); + for (let i = 0; i < 100; i++) { + now += 0.09; + expect(memoryGuard.overAbortThreshold('test')).toBe(9.5 * GB); + } + expect(rssSpy).toHaveBeenCalledTimes(1); + // a fall inside the 10 ms is not seen yet... + rssSpy.mockReturnValue(7 * GB); + expect(memoryGuard.overAbortThreshold('test')).toBe(9.5 * GB); + expect(rssSpy).toHaveBeenCalledTimes(1); + // ...but it is once the 10 ms have passed + now += 10; + expect(memoryGuard.overAbortThreshold('test')).toBe(0); + expect(rssSpy).toHaveBeenCalledTimes(2); + // configure drops the sample, and the next check reads afresh + rssSpy.mockReturnValue(9.5 * GB); + memoryGuard.configure({ limit: 10 * GB, rejectFraction: 0.8, abortFraction: 0.9 }); + expect(memoryGuard.overAbortThreshold('test')).toBe(9.5 * GB); + expect(rssSpy).toHaveBeenCalledTimes(3); + // as does any other drop (a report from the primary, in cluster mode) + rssSpy.mockReturnValue(7 * GB); + memoryGuard._state.sampleTime = 0; + expect(memoryGuard.overAbortThreshold('test')).toBe(0); + expect(rssSpy).toHaveBeenCalledTimes(4); + } finally { + nowSpy.mockRestore(); + } + }); + test('logs when refusing starts and when it stops', () => { const log = { info: jest.fn(), warn: jest.fn() }; const mw = memoryGuard.middleware({ log, gcInterval: 60000 }); @@ -149,3 +183,151 @@ describe('memory-guard', () => { expect(log.warn.mock.calls.some(c => /accepting requests again after \d+s \(1 refused\)/.test(c[0]))).toBe(true); }); }); + +// Cluster mode: the limit and the measure are the whole service's (several workers) +describe('memory-guard for a cluster of workers', () => { + let rssSpy; + const reports = []; + const PID = process.pid; + + const setOwn = (bytes) => { + rssSpy.mockReturnValue(bytes); + memoryGuard._state.sampleTime = 0; + }; + // what the primary says every second: each worker's RSS, and their total + const primarySays = (table) => { + const total = table.reduce((t, [, r]) => t + r, 0); + memoryGuard.handleMessage({ fhirsmith: 'memory', total, workers: table }); + }; + + beforeEach(() => { + reports.length = 0; + rssSpy = jest.spyOn(process.memoryUsage, 'rss'); + // 3 workers, a 10 GB limit for the group: refuse above 8.5, abort above 9.2 + memoryGuard.configure({ limit: 10 * GB, measure: 'processes', group: { size: 3, report: (m) => reports.push(m) } }); + }); + afterEach(() => { + rssSpy.mockRestore(); + memoryGuard.configure(); + }); + + test('reports its RSS to the primary', () => { + expect(reports[0]).toEqual({ fhirsmith: 'memory-rss', rss: expect.any(Number) }); + expect(memoryGuard.describe()).toMatch(/for the whole service of 3 workers, measured as the sum of the workers' RSS/); + }); + + test('every worker refuses when the group is over, though none is over a third', () => { + setOwn(2 * GB); + primarySays([[PID, 2 * GB], [PID + 1, 3.4 * GB], [PID + 2, 3.3 * GB]]); // 8.7 GB + expect(memoryGuard.shouldReject()).toBe(true); + primarySays([[PID, 2 * GB], [PID + 1, 3 * GB], [PID + 2, 3 * GB]]); // 8 GB + expect(memoryGuard.shouldReject()).toBe(false); + }); + + test('its own part of the total is brought up to date between reports', () => { + primarySays([[PID, 2 * GB], [PID + 1, 3 * GB], [PID + 2, 3 * GB]]); // 8 GB as reported + setOwn(2.6 * GB); // since then: +0.6 + expect(memoryGuard.shouldReject()).toBe(true); + }); + + test('over the abort threshold, only the largest worker aborts', () => { + // the group is at 9.5 GB; this worker is 5 GB of it, the largest + setOwn(5 * GB); + primarySays([[PID, 5 * GB], [PID + 1, 2.3 * GB], [PID + 2, 2.2 * GB]]); + expect(memoryGuard.overAbortThreshold('test')).toBe(9.5 * GB); + // the same group, but this worker is a small one: it carries on + setOwn(2.2 * GB); + primarySays([[PID, 2.2 * GB], [PID + 1, 5 * GB], [PID + 2, 2.3 * GB]]); + expect(memoryGuard.overAbortThreshold('test')).toBe(0); + // and under the threshold nobody aborts, largest or not + setOwn(5 * GB); + primarySays([[PID, 5 * GB], [PID + 1, 2 * GB], [PID + 2, 2 * GB]]); + expect(memoryGuard.overAbortThreshold('test')).toBe(0); + }); +}); + +describe('who aborts (abortsHere)', () => { + const GB2 = GB; + const at = 9.2 * GB2; // abort threshold of a 10 GB group + const w = (...pairs) => new Map(pairs); + + test('the largest worker does, the others don\'t', () => { + const table = w([1, 5 * GB2], [2, 2.3 * GB2], [3, 2.2 * GB2]); + expect(memoryGuard.abortsHere(5 * GB2, table, 3, at, 1)).toBe(true); + expect(memoryGuard.abortsHere(2.3 * GB2, table, 3, at, 2)).toBe(false); + expect(memoryGuard.abortsHere(2.2 * GB2, table, 3, at, 3)).toBe(false); + }); + + test('a worker well over its share aborts even if another is larger', () => { + // share of the threshold: 9.2 / 3 = 3.07 GB; 1.5 times that: 4.6 GB + const table = w([1, 4.7 * GB2], [2, 4.8 * GB2], [3, 0.3 * GB2]); + expect(memoryGuard.abortsHere(4.7 * GB2, table, 3, at, 1)).toBe(true); + expect(memoryGuard.abortsHere(4.8 * GB2, table, 3, at, 2)).toBe(true); + expect(memoryGuard.abortsHere(0.3 * GB2, table, 3, at, 3)).toBe(false); + }); + + test('a tie goes to one worker (the lower pid), and a worker the primary has not reported yet counts as alone', () => { + const table = w([1, 3 * GB2], [2, 3 * GB2]); + expect(memoryGuard.abortsHere(3 * GB2, table, 3, at, 1)).toBe(true); + expect(memoryGuard.abortsHere(3 * GB2, table, 3, at, 2)).toBe(false); + expect(memoryGuard.abortsHere(1 * GB2, new Map(), 3, at, 9)).toBe(true); + }); +}); + +describe('how the group is measured (resolveLimit)', () => { + const fs = require('fs'); + const os = require('os'); + const path = require('path'); + let dir; + let cgroupOptions; + const write = (rel, content) => { + const file = path.join(dir, 'sys', rel); + fs.mkdirSync(path.dirname(file), { recursive: true }); + fs.writeFileSync(file, content); + }; + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'memory-measure-')); + cgroupOptions = { procFile: path.join(dir, 'proc'), cgroupRoot: path.join(dir, 'sys') }; + }); + afterEach(() => fs.rmSync(dir, { recursive: true, force: true })); + + test('cgroup v2 with a limit on the service itself: its private memory (anon)', () => { + fs.writeFileSync(cgroupOptions.procFile, '0::/system.slice/fhirsmith.service\n'); + write('system.slice/fhirsmith.service/memory.max', String(16 * GB)); + write('system.slice/fhirsmith.service/memory.stat', `anon ${3 * GB}\nfile ${9 * GB}\n`); + const r = memoryGuard.resolveLimit({ cgroupOptions }); + expect(r).toMatchObject({ limit: 16 * GB, measure: 'cgroup' }); + expect(require('../../library/cgroup-memory').readCgroupAnon(r.cgroup)).toBe(3 * GB); // not the page cache + }); + + test('cgroup v1: total_rss of the service\'s memory cgroup', () => { + fs.writeFileSync(cgroupOptions.procFile, '5:memory:/fhirsmith\n'); + write('memory/fhirsmith/memory.limit_in_bytes', String(8 * GB)); + write('memory/fhirsmith/memory.stat', `cache 100\nrss ${1 * GB}\ntotal_rss ${2 * GB}\n`); + const r = memoryGuard.resolveLimit({ cgroupOptions }); + expect(r.measure).toBe('cgroup'); + expect(require('../../library/cgroup-memory').readCgroupAnon(r.cgroup)).toBe(2 * GB); + }); + + test('a limit only on an enclosing slice: the cgroup may hold other things, so the processes are added up', () => { + fs.writeFileSync(cgroupOptions.procFile, '0::/user.slice/session.scope\n'); + write('user.slice/memory.max', String(16 * GB)); + write('user.slice/session.scope/memory.max', 'max'); + write('user.slice/session.scope/memory.stat', `anon ${3 * GB}\n`); + expect(memoryGuard.resolveLimit({ cgroupOptions })).toMatchObject({ limit: 16 * GB, measure: 'processes' }); + }); + + test('no cgroup (macOS, Windows): the processes, against the configured limit or the machine', () => { + cgroupOptions.procFile = path.join(dir, 'missing'); + expect(memoryGuard.resolveLimit({ cgroupOptions })).toMatchObject({ limit: os.totalmem(), measure: 'processes' }); + expect(memoryGuard.resolveLimit({ cgroupOptions, limit: 4 * GB })).toMatchObject({ limit: 4 * GB, source: 'configured' }); + }); + + test('a configured limit wins over the cgroup\'s, and measure can be forced', () => { + fs.writeFileSync(cgroupOptions.procFile, '0::/svc\n'); + write('svc/memory.max', String(16 * GB)); + write('svc/memory.stat', `anon ${1 * GB}\n`); + expect(memoryGuard.resolveLimit({ cgroupOptions, limit: 6 * GB })).toMatchObject({ limit: 6 * GB, measure: 'cgroup' }); + expect(memoryGuard.resolveLimit({ cgroupOptions, measure: 'processes' }).measure).toBe('processes'); + }); +}); diff --git a/tests/server/cluster-memory-guard.test.js b/tests/server/cluster-memory-guard.test.js new file mode 100644 index 00000000..7b382d56 --- /dev/null +++ b/tests/server/cluster-memory-guard.test.js @@ -0,0 +1,152 @@ +/** + * The memory guard for a cluster, for real: cluster.js with two workers and a 900 MB + * limit for the whole service, measured by adding up the processes' RSS (the measure + * used where the service has no cgroup of its own - so this runs anywhere). One worker + * is made heavy: + * - with the service over the reject threshold, both workers refuse new requests (503); + * - over the abort threshold, the heavy worker's operations abort (422) and the light + * one's carry on; + * - kept over (8 s here), the heavy worker is drained and restarted, and the service recovers. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const http = require('http'); +const { spawn } = require('child_process'); + +const ROOT = path.join(__dirname, '..', '..'); +const PORT = 19687; +const MB = 1024 * 1024; +const sleep = (ms) => new Promise(resolve => setTimeout(resolve, ms)); + +function get(p) { + return new Promise((resolve, reject) => { + http.get(`http://127.0.0.1:${PORT}${p}`, { agent: false }, (res) => { + let text = ''; + res.on('data', d => { text += d; }); + res.on('end', () => { + let json = null; + try { + json = JSON.parse(text); + } catch { + // not JSON + } + resolve({ status: res.statusCode, pid: Number(res.headers['x-served-by']), json }); + }); + }).on('error', reject); + }); +} + +// Send a request to one worker. The primary hands new connections to the two workers in +// turn, so once a no-op request has been answered by the other worker, the next goes to +// this one +async function to(pid, p) { + for (let i = 0; i < 10; i++) { + const probe = await get('/__mem/whoami'); + if (probe.pid !== pid) { + const r = await get(p); + if (r.pid === pid) { + return r; + } + } + } + throw new Error(`could not reach pid ${pid} for ${p}`); +} + +describe('memory guard in cluster mode', () => { + let dir; + let proc; + let output = ''; + const workerPids = () => [...output.matchAll(/worker \d \(pid (\d+)\) listening/g)].map(m => Number(m[1])); + + beforeAll(async () => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'cluster-memory-')); + fs.writeFileSync(path.join(dir, 'config.json'), JSON.stringify({ + server: { + port: PORT, + cluster: { workers: 2 }, + memory: { limit: 900 * MB, measure: 'processes', recycleAfterSeconds: 8, drainSeconds: 3 } + }, + stats: { enabled: false }, + npmAudit: { enabled: false }, + logging: { console: { level: 'info' }, file: { level: 'warn' } }, + modules: { testing: { enabled: true } } + })); + proc = spawn(process.execPath, ['--require', path.join(__dirname, '..', 'utils', 'memory-test-routes.js'), 'cluster.js'], { + cwd: ROOT, env: { ...process.env, FHIRSMITH_DATA_DIR: dir }, stdio: ['ignore', 'pipe', 'pipe'] + }); + proc.stdout.on('data', d => { output += d; }); + proc.stderr.on('data', d => { output += d; }); + for (let i = 0; i < 600 && workerPids().length < 2; i++) { + await sleep(100); + } + expect(workerPids()).toHaveLength(2); + await sleep(1500); // the first reports + }, 90000); + + afterAll(async () => { + if (proc && proc.exitCode === null) { + await new Promise(resolve => { + proc.once('exit', resolve); + proc.kill('SIGTERM'); + }); + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('refuse in every worker, abort only in the heavy one, then recycle it', async () => { + expect(output).toMatch(/memory: limit 0\.88 GB for the service \(from configured\), measured as the sum of the processes' RSS/); + const [a, b] = workerPids(); + + // A keeps 300 MB: the service is now ~0.6 GB, under the reject threshold (765 MB) + expect((await to(a, '/__mem/leak?mb=300')).status).toBe(200); + await sleep(2500); + expect((await get('/testing')).status).toBe(200); + const state = (await to(b, '/__mem/state')).json; + expect(state.measured).toBeLessThan(state.rejectAt); + + // A fills enough for a while to take the service to 96% of the limit: over reject and + // abort (828 MB). (How much that is depends on how a process is measured.) + const fill = Math.ceil((0.96 * 900 * MB - state.measured) / MB / 10) * 10; + const filling = to(a, `/__mem/fill?mb=${fill}&hold=4000`); + await sleep(3000); + const refusedA = await to(a, '/testing'); + const refusedB = await to(b, '/testing'); + expect([refusedA.status, refusedB.status]).toEqual([503, 503]); + const checkA = await to(a, '/__mem/check'); + const checkB = await to(b, '/__mem/check'); + expect(checkA.json.aborts).toBe(true); // the largest + expect(checkB.json.aborts).toBe(false); // carries on + await filling; + await sleep(2500); + expect((await get('/testing')).status).toBe(200); + + // an operation in A that grows until the guard says stop: aborted (422) part way + const heavy = await to(a, '/__mem/heavy?mb=600'); + expect(heavy.status).toBe(422); + expect(heavy.json.atMb).toBeLessThan(600); + + // A keeps enough to stay over: after 8 s it is drained and restarted + const now = (await to(b, '/__mem/state')).json; + await to(a, `/__mem/leak?mb=${Math.ceil((now.rejectAt - now.measured) / MB / 10) * 10 + 120}`); // well over: a GC must not bring it back under + for (let i = 0; i < 300 && !/recycled for memory/.test(output); i++) { + await sleep(100); + } + expect(output).toMatch(new RegExp(`recycling the largest worker, pid ${a}`)); + expect(output).toMatch(new RegExp(`worker \\d \\(pid ${a}\\) recycled for memory`)); + for (let i = 0; i < 300 && workerPids().length < 3; i++) { + await sleep(100); + } + const c = workerPids()[2]; + expect(c).not.toBe(a); + await sleep(2500); + const after = new Set(); + for (let i = 0; i < 6; i++) { + const r = await get('/testing'); + expect(r.status).toBe(200); + after.add(r.pid); + } + expect([...after].sort()).toEqual([b, c].sort()); + expect(output).toMatch(/the service is back under/); + }, 120000); +}); diff --git a/tests/server/cluster-mode.test.js b/tests/server/cluster-mode.test.js new file mode 100644 index 00000000..a33763b9 --- /dev/null +++ b/tests/server/cluster-mode.test.js @@ -0,0 +1,107 @@ +/** + * cluster.js for real: two workers on one port, with modules that keep logins (testing, + * publisher) and the tx resource cache configured with the memory store - none of + * which it refuses any more. Every request goes on a new connection, so the workers + * take turns; a login made through one is used through both. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const http = require('http'); +const { spawn } = require('child_process'); + +const ROOT = path.join(__dirname, '..', '..'); +const PORT = 19688; + +function request(method, url, { headers = {}, body } = {}) { + return new Promise((resolve, reject) => { + const req = http.request(url, { method, headers, agent: false }, (res) => { + let text = ''; + res.setEncoding('utf8'); + res.on('data', d => { text += d; }); + res.on('end', () => resolve({ status: res.statusCode, headers: res.headers, text })); + }); + req.on('error', reject); + if (body) { + req.write(body); + } + req.end(); + }); +} + +describe('cluster mode', () => { + let dir; + let proc; + let output = ''; + + beforeAll(async () => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'cluster-mode-')); + fs.writeFileSync(path.join(dir, 'config.json'), JSON.stringify({ + server: { port: PORT, cluster: { workers: 2 } }, + stats: { enabled: false }, + npmAudit: { enabled: false }, + logging: { console: { level: 'info' }, file: { level: 'warn' } }, + modules: { + testing: { enabled: true, adminPassword: 'admin-secret', cookieSecure: false }, + publisher: { enabled: true, cookieSecure: false, database: 'publisher.db', workspaceRoot: path.join(dir, 'ws') } + } + })); + proc = spawn(process.execPath, ['--require', path.join(__dirname, '..', 'utils', 'served-by.js'), 'cluster.js'], { + cwd: ROOT, env: { ...process.env, FHIRSMITH_DATA_DIR: dir }, stdio: ['ignore', 'pipe', 'pipe'] + }); + proc.stdout.on('data', d => { output += d; }); + proc.stderr.on('data', d => { output += d; }); + await new Promise((resolve, reject) => { + const t = setInterval(() => { + if ((output.match(/listening after/g) || []).length >= 2) { + clearInterval(t); + resolve(); + } else if (proc.exitCode !== null) { + clearInterval(t); + reject(new Error('cluster.js exited:\n' + output)); + } + }, 100); + }); + }, 60000); + + afterAll(async () => { + if (proc && proc.exitCode === null) { + await new Promise(resolve => { + proc.once('exit', resolve); + proc.kill('SIGTERM'); + }); + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('starts both workers; nothing is refused', () => { + expect(output).not.toMatch(/can't run in more than one worker/); + expect(output).toMatch(/worker 2 \(pid \d+\) listening/); + }); + + test('a login made through one worker is used through both', async () => { + const base = `http://127.0.0.1:${PORT}/testing`; + let cookie = ''; + const keep = (res) => { + const set = res.headers['set-cookie']; + if (set) { + cookie = set.map(c => c.split(';')[0]).join('; '); + } + return res; + }; + const page = keep(await request('GET', `${base}/login`)); + const csrf = page.text.match(/name="_csrf" value="([^"]+)"/)[1]; + const login = keep(await request('POST', `${base}/login`, { + headers: { cookie, origin: `http://127.0.0.1:${PORT}`, 'content-type': 'application/x-www-form-urlencoded' }, + body: new URLSearchParams({ login: 'admin', password: 'admin-secret', _csrf: csrf }).toString() + })); + expect(login.status).toBe(302); + const servedBy = new Set([page.headers['x-served-by'], login.headers['x-served-by']]); + for (let i = 0; i < 6; i++) { + const res = await request('GET', `${base}/admin/users`, { headers: { cookie } }); + expect(res.status).toBe(200); + servedBy.add(res.headers['x-served-by']); + } + expect(servedBy.size).toBe(2); + }); +}); diff --git a/tests/server/follow-shared-files.test.js b/tests/server/follow-shared-files.test.js new file mode 100644 index 00000000..b1fb47bf --- /dev/null +++ b/tests/server/follow-shared-files.test.js @@ -0,0 +1,108 @@ +/** + * Background jobs whose results the other cluster-mode workers read from a file: the + * registry crawl (registry-data.json) and the package crawler's status + * (packages/crawler-status.json). The process that runs the job writes the file whole + * and renames it into place; the others look (one stat, at most once a second) when a + * request reaches them, and read it only when it has changed. Two module instances on + * one file stand in for two workers. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const backgroundJobs = require('../../library/background-jobs'); +const RegistryModule = require('../../registry/registry'); +const PackagesModule = require('../../packages/packages'); + +const quiet = { info() {}, warn() {}, error() {}, debug() {} }; +const sleep = (ms) => new Promise(resolve => setTimeout(resolve, ms)); + +let dir; +beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'follow-')); + backgroundJobs.configure({ enabled: true, path: path.join(dir, 'background-jobs.lock') }); +}); +afterEach(() => { + backgroundJobs.close(); + fs.rmSync(dir, { recursive: true, force: true }); +}); + +describe('registry crawl data', () => { + const reader = (file) => { + const r = Object.create(RegistryModule.prototype); + r.dataFile = () => file; + r.logger = quiet; + r.loads = 0; + r.loadSavedData = async function () { + this.loads++; + this.loadedDataVersion = await RegistryModule.fileVersion(file); + }; + return r; + }; + const settle = (r) => r.followLoading || Promise.resolve(); + + test('loaded once when another process saves a crawl, not otherwise', async () => { + const file = path.join(dir, 'registry-data.json'); + await RegistryModule.writeAtomically(file, '{"v":1}'); + const r = reader(file); + await r.loadSavedData(); + expect(r.loads).toBe(1); + + r.followSavedData(); + await settle(r); + expect(r.loads).toBe(1); // unchanged: no reload + + await RegistryModule.writeAtomically(file, '{"v":2}'); + r.followSavedData(); // within the second: doesn't look + await settle(r); + expect(r.loads).toBe(1); + await sleep(1050); + r.followSavedData(); + await settle(r); + expect(r.loads).toBe(2); + }); + + test('with one process (no lock) nothing is looked at', async () => { + backgroundJobs.close(); + const file = path.join(dir, 'registry-data.json'); + await RegistryModule.writeAtomically(file, '{}'); + const r = reader(file); + r.followSavedData(); + await settle(r); + expect(r.loads).toBe(0); + }); +}); + +describe('package crawler status', () => { + const make = () => { + const m = new PackagesModule({ addTask() {}, task() {}, countRequest() {} }); + m.crawlerStatusFile = () => path.join(dir, 'crawler-status.json'); + return m; + }; + + test('the other process shows the run in progress, then its result', async () => { + const runner = make(); + const other = make(); + let seenWhileRunning = null; + runner.crawler = { + crawl: async () => { + await other.followCrawlerStatus(true); + seenWhileRunning = { running: other.crawlerRunning, runs: other.totalRuns }; + return { feeds: [{ url: 'http://example.org/feed', items: [1, 2] }] }; + } + }; + await runner.runCrawler(); + expect(seenWhileRunning).toEqual({ running: true, runs: 1 }); + + await other.followCrawlerStatus(true); + expect(other.crawlerRunning).toBe(false); + expect(other.totalRuns).toBe(1); + expect(other.lastRunTime).toBe(runner.lastRunTime); + expect(other.lastCrawlerLog.feeds).toHaveLength(1); + + // the next run, from whichever process holds the lock then, counts on from 1 + other.crawler = { crawl: async () => ({ feeds: [] }) }; + await other.runCrawler(); + await runner.followCrawlerStatus(true); + expect(runner.totalRuns).toBe(2); + }); +}); diff --git a/tests/tx/cache-control.test.js b/tests/tx/cache-control.test.js index d5573dbf..6ef0a08c 100644 --- a/tests/tx/cache-control.test.js +++ b/tests/tx/cache-control.test.js @@ -462,6 +462,14 @@ describe('$cache-control routing (scaffolding)', () => { const text = (((res.body.issue || [])[0] || {}).details || {}).text || ''; expect(text).toMatch(/never issued by this server/i); expect(text).not.toMatch(/expired/i); + // the memory store loses its caches when the server restarts, so that is offered as a + // reason; the shared SQLite store keeps them, so it isn't + if (process.env.FHIRSMITH_TEST_RESOURCE_CACHE === 'sqlite') { + expect(text).not.toMatch(/restarted/i); + expect(text).toMatch(/survive a restart/i); + } else { + expect(text).toMatch(/restarted/i); + } }); // A cache-id whose prefix names another instance got here through a routing diff --git a/tests/tx/closure-multiprocess.test.js b/tests/tx/closure-multiprocess.test.js new file mode 100644 index 00000000..d60b29ba --- /dev/null +++ b/tests/tx/closure-multiprocess.test.js @@ -0,0 +1,81 @@ +/** + * $closure tables used by two processes at once, as cluster-mode workers use them. Each + * call reads the table, yields, and writes the next version; the per-table lock has to + * hold across processes, or one process's write is lost under the other's. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const { fork } = require('child_process'); + +const CHILD = path.join(__dirname, '..', 'utils', 'closure-child.js'); + +describe('closure tables across processes', () => { + let dir; + const children = []; + + const spawn = (crossProcess) => { + const child = fork(CHILD, [dir, crossProcess ? '1' : '0'], { stdio: ['ignore', 'ignore', 'inherit', 'ipc'] }); + children.push(child); + let seq = 0; + const waiting = new Map(); + let readyResolve; + const ready = new Promise(resolve => { readyResolve = resolve; }); + child.on('message', (m) => { + if (m.ready) { + readyResolve(); + return; + } + const w = waiting.get(m.seq); + if (m.error) { + w.reject(new Error(m.error)); + } else { + w.resolve(m.result); + } + }); + const call = (op, args = {}) => new Promise((resolve, reject) => { + const s = ++seq; + waiting.set(s, { resolve, reject }); + child.send({ seq: s, op, ...args }); + }); + return ready.then(() => ({ call })); + }; + + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'closure-mp-')); + }); + afterEach(async () => { + for (const c of children.splice(0)) { + if (c.exitCode === null && c.signalCode === null) { + await new Promise(resolve => { + c.once('exit', resolve); + c.kill(); + }); + } + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('with the cross-process lock, no add is lost', async () => { + const [a, b] = await Promise.all([spawn(true), spawn(true)]); + await a.call('create', { name: 't1' }); + await Promise.all([a.call('adds', { name: 't1', times: 10, ms: 10 }), b.call('adds', { name: 't1', times: 10, ms: 10 })]); + expect(await a.call('version', { name: 't1' })).toEqual({ version: 20, concepts: 20 }); + }); + + test('without it (one process per database, as before), adds from two processes are lost', async () => { + const [a, b] = await Promise.all([spawn(false), spawn(false)]); + await a.call('create', { name: 't1' }); + // two processes both read version n, and both write n + 1: the second write fails on the + // unique (table, version)... or overwrites; either way the version count falls short + const results = await Promise.allSettled([a.call('adds', { name: 't1', times: 10, ms: 10 }), b.call('adds', { name: 't1', times: 10, ms: 10 })]); + const v = await a.call('version', { name: 't1' }); + expect(results.some(r => r.status === 'rejected') || v.version < 20).toBe(true); + }); + + test('the table limit holds when two processes create tables at once', async () => { + const [a, b] = await Promise.all([spawn(true), spawn(true)]); + const made = await Promise.all(Array.from({ length: 10 }, (_, i) => (i % 2 ? a : b).call('create', { name: `t${i}`, max: 5 }))); + expect(made.filter(Boolean)).toHaveLength(5); + }); +}); diff --git a/tests/tx/resource-cache-multiprocess.test.js b/tests/tx/resource-cache-multiprocess.test.js new file mode 100644 index 00000000..552bcb9d --- /dev/null +++ b/tests/tx/resource-cache-multiprocess.test.js @@ -0,0 +1,134 @@ +/** + * The shared SQLite resource cache across processes: what cluster mode relies on. + * Two real processes open the same file; a cache started in one is used and ended + * in the other, and survives a process restart. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const { fork } = require('child_process'); + +const CHILD = path.join(__dirname, '..', 'utils', 'resource-cache-child.js'); + +function startProcess(file) { + const child = fork(CHILD, [file], { stdio: ['ignore', 'ignore', 'inherit', 'ipc'] }); + let seq = 0; + const waiting = new Map(); + let readyResolve; + const ready = new Promise(resolve => { readyResolve = resolve; }); + child.on('message', (m) => { + if (m.ready) { + readyResolve(m.ready); + return; + } + const w = waiting.get(m.seq); + waiting.delete(m.seq); + if (m.error) { + w.reject(new Error(m.error)); + } else { + w.resolve(m.result); + } + }); + const call = (op, args = {}) => new Promise((resolve, reject) => { + const s = ++seq; + waiting.set(s, { resolve, reject }); + child.send({ seq: s, op, ...args }); + }); + const stop = () => new Promise(resolve => { + child.once('exit', resolve); + child.kill(); + }); + return { ready, call, stop, pid: child.pid }; +} + +const cs = (url, version, codes) => ({ + resourceType: 'CodeSystem', url, version, status: 'active', content: 'complete', + concept: codes.map(code => ({ code, display: code.toUpperCase() })) +}); + +describe('shared SQLite resource cache across processes', () => { + let dir; + let file; + const running = []; + + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'resource-cache-mp-')); + file = path.join(dir, 'resource-cache.db'); + }); + + afterEach(async () => { + while (running.length) { + await running.pop().stop(); + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + const spawn = async () => { + const p = startProcess(file); + running.push(p); + await p.ready; + return p; + }; + + test('A starts a cache and adds resources, B reads them, B ends it, A sees the tombstone', async () => { + const a = await spawn(); + const b = await spawn(); + expect(a.pid).not.toBe(b.pid); + + const id = await a.call('start', { resources: [cs('http://example.org/one', '1', ['a', 'b'])] }); + await a.call('add', { id, resources: [cs('http://example.org/two', '2', ['x', 'y', 'z'])] }); + + expect(await b.call('has', { id })).toBe(true); + expect(await b.call('get', { id })).toEqual([ + { cls: 'CodeSystem', url: 'http://example.org/one', version: '1', fhirVersion: 'R4', concepts: 2 }, + { cls: 'CodeSystem', url: 'http://example.org/two', version: '2', fhirVersion: 'R4', concepts: 3 } + ]); + + // B adds too, and A sees it + await b.call('add', { id, resources: [cs('http://example.org/three', '3', ['q'])] }); + expect((await a.call('get', { id })).map(r => r.url)).toEqual( + ['http://example.org/one', 'http://example.org/two', 'http://example.org/three']); + + await b.call('end', { id }); + expect(await a.call('has', { id })).toBe(false); + expect(await a.call('get', { id })).toEqual([]); + const d = await a.call('describe', { id }); + expect(d.messageId).toBe('CACHE_ID_CLOSED'); + expect(d.params[0]).toBe(id); + }); + + test('the idle sweep run by either process is seen by both, and running it twice is harmless', async () => { + const a = await spawn(); + const b = await spawn(); + const id = await a.call('start', { resources: [cs('http://example.org/one', '1', ['a'])] }); + // prune with a negative max age: everything counts as idle + await b.call('prune', { maxAge: -1000 }); + await a.call('prune', { maxAge: -1000 }); + expect(await a.call('has', { id })).toBe(false); + expect((await a.call('describe', { id })).messageId).toBe('CACHE_ID_EXPIRED'); + expect((await b.call('describe', { id })).messageId).toBe('CACHE_ID_EXPIRED'); + }); + + test('a cache survives a process restart', async () => { + const a = await spawn(); + const id = await a.call('start', { resources: [cs('http://example.org/one', '1', ['a', 'b'])], sealed: true }); + await running.pop().stop(); + + const again = await spawn(); + expect(await again.call('has', { id })).toBe(true); + expect((await again.call('get', { id })).map(r => r.url)).toEqual(['http://example.org/one']); + }); + + test('many writes from two processes at once all land', async () => { + const a = await spawn(); + const b = await spawn(); + const id = await a.call('start', {}); + const writes = []; + for (let i = 0; i < 50; i++) { + writes.push(a.call('add', { id, resources: [cs(`http://example.org/a${i}`, '1', ['c'])] })); + writes.push(b.call('add', { id, resources: [cs(`http://example.org/b${i}`, '1', ['c'])] })); + } + await Promise.all(writes); + expect(await a.call('get', { id })).toHaveLength(100); + }); +}); diff --git a/tests/tx/resource-cache-settings.test.js b/tests/tx/resource-cache-settings.test.js new file mode 100644 index 00000000..3e61c305 --- /dev/null +++ b/tests/tx/resource-cache-settings.test.js @@ -0,0 +1,41 @@ +/** + * Which client resource cache store an endpoint gets: what is configured, except that + * in cluster mode (cluster.js sets FHIRSMITH_CLUSTER_SIZE for its workers) the memory + * store, which only works in one process, becomes the shared SQLite one. + */ +const TXModule = require('../../tx/tx'); + +const settings = (resourceCache) => TXModule.prototype.resourceCacheSettings.call({ config: { resourceCache } }); + +describe('resource cache settings', () => { + const saved = process.env.FHIRSMITH_CLUSTER_SIZE; + afterEach(() => { + if (saved === undefined) { + delete process.env.FHIRSMITH_CLUSTER_SIZE; + } else { + process.env.FHIRSMITH_CLUSTER_SIZE = saved; + } + }); + + test('one process: memory unless sqlite is asked for', () => { + delete process.env.FHIRSMITH_CLUSTER_SIZE; + expect(settings(undefined)).toMatchObject({ store: 'memory', path: null, switched: false }); + expect(settings({ store: 'memory' })).toMatchObject({ store: 'memory', switched: false }); + expect(settings({ store: 'sqlite' })).toMatchObject({ store: 'sqlite', switched: false }); + }); + + test('a cluster of one worker is one process', () => { + process.env.FHIRSMITH_CLUSTER_SIZE = '1'; + expect(settings({ store: 'memory' })).toMatchObject({ store: 'memory', switched: false }); + }); + + test('cluster mode: the memory store (asked for, or by default) becomes sqlite', () => { + process.env.FHIRSMITH_CLUSTER_SIZE = '3'; + const s = settings({ store: 'memory' }); + expect(s).toMatchObject({ store: 'sqlite', switched: true }); + expect(s.path).toMatch(/resource-cache\.db$/); + expect(settings(undefined)).toMatchObject({ store: 'sqlite', switched: true }); + expect(settings({ store: 'sqlite' })).toMatchObject({ store: 'sqlite', switched: false }); + expect(() => settings({ store: 'redis' })).toThrow(/not valid/); + }); +}); diff --git a/tests/tx/resource-cache.test.js b/tests/tx/resource-cache.test.js index 35844394..6cf02040 100644 --- a/tests/tx/resource-cache.test.js +++ b/tests/tx/resource-cache.test.js @@ -4,9 +4,16 @@ * ResourceCache backs the cache-id protocol: resources sent under a cache-id on one * request must be retrievable on later requests with the same cache-id, and kept * isolated between different cache-ids. + * + * Every test here runs against both stores - the in-process memory store and the + * shared SQLite store - because they are one interface with one set of semantics. */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); const { ResourceCache, formatDuration } = require('../../tx/operation-context'); +const { SqliteResourceCache } = require('../../tx/resource-cache-sqlite'); const CS = (url, version) => ({ resourceType: 'CodeSystem', url, version }); const VS = (url, version) => ({ resourceType: 'ValueSet', url, version }); @@ -14,11 +21,50 @@ const VS = (url, version) => ({ resourceType: 'ValueSet', url, version }); // A resource that reports a concept count, like the real wrapper classes do. const sized = (resource, n) => ({ ...resource, conceptCount: () => n }); -describe('ResourceCache', () => { +const tmpDir = fs.mkdtempSync(path.join(os.tmpdir(), 'resource-cache-test-')); +let fileNo = 0; +const opened = []; +afterAll(() => { + for (const c of opened) { + c.close(); + } + fs.rmSync(tmpDir, { recursive: true, force: true }); +}); + +// How each store is made, and how a test makes an entry look idle +const STORES = [ + { + name: 'memory', + unknownId: 'CACHE_ID_UNKNOWN', + make: (opts = {}) => new ResourceCache(null, opts.maxTombstones || 1000, opts), + setLastUsed: (cache, id, when) => { cache.cache.get(id).lastUsed = when; } + }, + { + name: 'sqlite', + // caches survive a restart here, so the message doesn't offer one as the reason + unknownId: 'CACHE_ID_UNKNOWN_SHARED', + make: (opts = {}) => { + const c = new SqliteResourceCache(null, { + path: path.join(tmpDir, `cache-${++fileNo}.db`), + scope: '/r4', + touchIntervalMs: 0, + ...opts + }); + opened.push(c); + return c; + }, + setLastUsed: (cache, id, when) => { + cache.db.prepare('UPDATE sessions SET last_used = ? WHERE scope = ? AND cache_id = ?').run(when, cache.scope, id); + } + } +]; + +describe.each(STORES)('ResourceCache ($name store)', (store) => { let cache; + const setLastUsed = (id, when) => store.setLastUsed(cache, id, when); beforeEach(() => { - cache = new ResourceCache(null); + cache = store.make(); }); describe('get / has on empty cache', () => { @@ -129,7 +175,7 @@ describe('ResourceCache', () => { test('removes entries older than maxAge but keeps fresh ones', () => { cache.add('old', [CS('http://old', '1')]); // Force the entry to look stale. - cache.cache.get('old').lastUsed = Date.now() - 10000; + setLastUsed('old', Date.now() - 10000); cache.add('fresh', [CS('http://fresh', '1')]); cache.prune(5000); // maxAge 5s @@ -140,7 +186,7 @@ describe('ResourceCache', () => { test('get() refreshes lastUsed so an active entry is not pruned', () => { cache.add('c1', [CS('http://a', '1')]); - cache.cache.get('c1').lastUsed = Date.now() - 10000; + setLastUsed('c1', Date.now() - 10000); cache.get('c1'); // touch -> refreshes lastUsed cache.prune(5000); expect(cache.has('c1')).toBe(true); @@ -151,10 +197,10 @@ describe('ResourceCache', () => { // the whole point: "you closed it yourself" and "it sat idle for 31 minutes" send // an investigator to completely different places (see issue #279). describe('tombstones (why a cache-id is gone)', () => { - test('an id that was never issued has no tombstone and reports CACHE_ID_UNKNOWN', () => { + test('an id that was never issued has no tombstone and reports CACHE_ID_UNKNOWN (memory) or CACHE_ID_UNKNOWN_SHARED', () => { const d = cache.describeMissing('never-seen'); expect(cache.tombstone('never-seen')).toBeNull(); - expect(d.messageId).toBe('CACHE_ID_UNKNOWN'); + expect(d.messageId).toBe(store.unknownId); expect(d.params).toEqual(['never-seen']); }); @@ -171,7 +217,7 @@ describe('ResourceCache', () => { test('prune() records the expiry with the measured idle time, not the timeout', () => { cache.add('c1', [CS('http://a', '1')]); - cache.cache.get('c1').lastUsed = Date.now() - 10 * 60 * 1000; // idle 10 min + setLastUsed('c1', Date.now() - 10 * 60 * 1000); // idle 10 min cache.prune(5 * 60 * 1000); // timeout 5 min - the sweep is late, as it is in production const t = cache.tombstone('c1'); @@ -209,7 +255,7 @@ describe('ResourceCache', () => { test('the latest fate wins when an id dies twice', () => { cache.set('c1', [CS('http://a', '1')]); - cache.cache.get('c1').lastUsed = Date.now() - 10000; + setLastUsed('c1', Date.now() - 10000); cache.prune(5000); expect(cache.tombstone('c1').reason).toBe('expired'); @@ -219,7 +265,7 @@ describe('ResourceCache', () => { }); test('tombstones are bounded: the oldest are evicted, never unbounded growth', () => { - const small = new ResourceCache(null, 3); + const small = store.make({ maxTombstones: 3 }); for (const id of ['a', 'b', 'c', 'd', 'e']) { small.set(id, [CS('http://' + id, '1')]); small.clear(id); @@ -229,13 +275,13 @@ describe('ResourceCache', () => { expect(small.tombstone('b')).toBeNull(); // evicted expect(small.tombstone('e')).not.toBeNull(); // newest kept // An evicted tombstone degrades to "never issued" rather than lying. - expect(small.describeMissing('a').messageId).toBe('CACHE_ID_UNKNOWN'); + expect(small.describeMissing('a').messageId).toBe(store.unknownId); }); test('closing an id the server never had leaves no tombstone', () => { cache.clear('not-mine'); expect(cache.tombstone('not-mine')).toBeNull(); - expect(cache.describeMissing('not-mine').messageId).toBe('CACHE_ID_UNKNOWN'); + expect(cache.describeMissing('not-mine').messageId).toBe(store.unknownId); }); }); @@ -297,12 +343,12 @@ describe('ResourceCache', () => { test('an unrecorded id with our own prefix is plain unknown (e.g. issued before a restart)', () => { cache.setInstanceCode('tx1'); - expect(cache.describeMissing('tx1.abc').messageId).toBe('CACHE_ID_UNKNOWN'); + expect(cache.describeMissing('tx1.abc').messageId).toBe(store.unknownId); }); test('an unprefixed id on a named server is plain unknown', () => { cache.setInstanceCode('tx1'); - expect(cache.describeMissing('abc').messageId).toBe('CACHE_ID_UNKNOWN'); + expect(cache.describeMissing('abc').messageId).toBe(store.unknownId); }); test('a tombstone wins over the prefix check', () => { @@ -320,7 +366,7 @@ describe('ResourceCache', () => { describe('status / touch (mode=check)', () => { test('status reports a live cache without touching it', () => { cache.set('c1', [CS('http://a', '1'), VS('http://b', '1')], true); - cache.cache.get('c1').lastUsed = Date.now() - 90 * 1000; + setLastUsed('c1', Date.now() - 90 * 1000); const s = cache.status('c1'); expect(s.exists).toBe(true); @@ -338,7 +384,7 @@ describe('ResourceCache', () => { test('touch resets the idle clock and saves the cache from the next prune', () => { cache.add('c1', [CS('http://a', '1')]); - cache.cache.get('c1').lastUsed = Date.now() - 10000; + setLastUsed('c1', Date.now() - 10000); expect(cache.touch('c1')).toBe(true); expect(cache.status('c1').idleMs).toBeLessThan(1000); @@ -431,7 +477,7 @@ describe('ResourceCache', () => { test('prune subtracts evicted entries', () => { cache.add('old', [sized(CS('http://old', '1'), 7)]); - cache.cache.get('old').lastUsed = Date.now() - 10000; + setLastUsed('old', Date.now() - 10000); cache.add('fresh', [sized(CS('http://fresh', '1'), 4)]); cache.prune(5000); expect(cache.conceptCount()).toBe(4); @@ -466,4 +512,347 @@ describe('ResourceCache', () => { expect(cache.maxConceptCount()).toBe(20); }); }); + + describe('sealed and unsealed', () => { + test('set() records whether the cache is sealed; add() keeps an unsealed cache unsealed', () => { + cache.set('open', [CS('http://a', '1')], false); + cache.set('shut', [CS('http://a', '1')], true); + expect(cache.isSealed('open')).toBe(false); + expect(cache.isSealed('shut')).toBe(true); + expect(cache.isSealed('nope')).toBe(false); + cache.add('open', [VS('http://v', '1')]); + expect(cache.isSealed('open')).toBe(false); + expect(cache.get('open').map(r => r.url)).toEqual(['http://a', 'http://v']); + }); + + test('an empty cache made by set() exists', () => { + cache.set('empty', [], true); + expect(cache.has('empty')).toBe(true); + expect(cache.get('empty')).toEqual([]); + expect(cache.status('empty').resources).toBe(0); + }); + + test('order is kept, and a replacement keeps its place', () => { + cache.add('c1', [CS('http://a', '1'), CS('http://b', '1'), CS('http://c', '1')]); + cache.add('c1', [{ ...CS('http://b', '1'), title: 'new b' }, CS('http://d', '1')]); + const got = cache.get('c1'); + expect(got.map(r => r.url)).toEqual(['http://a', 'http://b', 'http://c', 'http://d']); + expect(got[1].title).toBe('new b'); + }); + }); + + describe('resources are marked as cached', () => { + test('get() returns resources with a non-enumerable isCached marker', () => { + cache.add('c1', [CS('http://a', '1')]); + const [r] = cache.get('c1'); + expect(r.isCached).toBe(true); + expect(Object.keys(r)).not.toContain('isCached'); + expect(JSON.stringify(r)).not.toContain('isCached'); + }); + }); + + // A cap on the total size of what the cache holds: when a write takes it over, whole + // caches are dropped, least recently used first, and remembered as `evicted`. + describe('size cap (maxBytes)', () => { + const big = (url, n) => ({ ...CS(url, '1'), description: 'x'.repeat(n) }); + + test('drops the least recently used caches, never the one being written', () => { + cache = store.make({ maxBytes: 2500 }); + cache.set('a', [big('http://a', 1000)]); + cache.set('b', [big('http://b', 1000)]); + setLastUsed('a', Date.now() - 60000); + setLastUsed('b', Date.now() - 30000); + cache.set('c', [big('http://c', 1000)]); // over the cap: 'a' is the oldest + expect(cache.has('a')).toBe(false); + expect(cache.has('b')).toBe(true); + expect(cache.has('c')).toBe(true); + expect(cache.byteCount()).toBeLessThanOrEqual(2500); + + const t = cache.tombstone('a'); + expect(t.reason).toBe('evicted'); + expect(t.maxBytes).toBe(2500); + expect(t.idleMs).toBeGreaterThanOrEqual(60000); + const d = cache.describeMissing('a'); + expect(d.messageId).toBe('CACHE_ID_EVICTED'); + expect(d.params[0]).toBe('a'); + expect(d.params[2]).toBe('2 KB'); + expect(d.params[3]).toBe('60 seconds'); + }); + + test('growing a cache with add() can evict others too', () => { + cache = store.make({ maxBytes: 2500 }); + cache.set('a', [big('http://a', 1000)]); + setLastUsed('a', Date.now() - 60000); + cache.set('b', [big('http://b', 1000)]); + cache.add('b', [big('http://b2', 1000)]); + expect(cache.has('a')).toBe(false); + expect(cache.tombstone('a').reason).toBe('evicted'); + expect(cache.get('b')).toHaveLength(2); + }); + + test('a single cache bigger than the cap is kept (there is nothing else to drop)', () => { + cache = store.make({ maxBytes: 500 }); + cache.set('a', [big('http://a', 1000)]); + expect(cache.has('a')).toBe(true); + }); + + test('no cap, nothing is dropped', () => { + for (let i = 0; i < 20; i++) { + cache.set('c' + i, [big('http://c' + i, 1000)]); + } + expect(cache.size()).toBe(20); + }); + }); +}); + +// Behaviour that only the shared SQLite store has. +describe('SqliteResourceCache', () => { + const { CodeSystem } = require('../../tx/library/codesystem'); + const ValueSet = require('../../tx/library/valueset'); + const make = (opts = {}) => { + const c = new SqliteResourceCache(null, { path: path.join(tmpDir, `only-${++fileNo}.db`), scope: '/r4', ...opts }); + opened.push(c); + return c; + }; + const lastUsedOf = (c, id) => c.db.prepare('SELECT last_used FROM sessions WHERE scope = ? AND cache_id = ?').get(c.scope, id).last_used; + + test('wrappers come back as wrappers, with the FHIR version they arrived in', () => { + const c = make(); + const cs = new CodeSystem({ + resourceType: 'CodeSystem', url: 'http://example.org/cs', version: '1', status: 'active', content: 'complete', + concept: [{ code: 'a', display: 'A' }, { code: 'b', display: 'B', concept: [{ code: 'b1' }] }] + }, 'R4'); + const vs = new ValueSet({ + resourceType: 'ValueSet', url: 'http://example.org/vs', status: 'active', + compose: { include: [{ system: 'http://example.org/cs', filter: [{ property: 'concept', op: 'is-a', value: 'b' }] }] } + }, 'R3'); + c.set('c1', [cs, vs]); + const [cs2, vs2] = c.get('c1'); + expect(cs2).toBeInstanceOf(CodeSystem); + expect(vs2).toBeInstanceOf(ValueSet); + expect(cs2.fhirVersion).toBe('R4'); + expect(vs2.fhirVersion).toBe('R3'); + expect(cs2.jsonObj).toEqual(cs.jsonObj); + expect(vs2.jsonObj).toEqual(vs.jsonObj); + expect(cs2.conceptCount()).toBe(3); + expect(c.conceptCountFor('c1')).toBe(3); + expect(cs2.isCached).toBe(true); + // a fresh object every time: nothing is shared between requests + expect(c.get('c1')[0]).not.toBe(cs2); + }); + + describe('a request only loads the resources it uses', () => { + const { ConceptMap } = require('../../tx/library/conceptmap'); + const { ExpansionCache } = require('../../tx/operation-context'); + const mkCs = (url, version, extra = {}) => new CodeSystem({ + resourceType: 'CodeSystem', url, version, status: 'active', content: 'complete', + concept: [{ code: 'a', display: 'A' }], ...extra + }, 'R4'); + const countLoads = (c) => { + const orig = c.q.content; + const counter = { n: 0 }; + c.q.content = { get: (...args) => { counter.n++; return orig.get(...args); } }; + return counter; + }; + + test('looking through the cache by url, version and type loads nothing', () => { + const c = make(); + c.set('c1', [mkCs('http://x/a', '1'), mkCs('http://x/b', '2'), mkCs('http://x/sup', '1', { content: 'supplement', supplements: 'http://x/a' })]); + const loads = countLoads(c); + const got = c.get('c1'); + expect(got.map(r => r.url)).toEqual(['http://x/a', 'http://x/b', 'http://x/sup']); + expect(got.map(r => r.version)).toEqual(['1', '2', '1']); + expect(got.map(r => r.vurl)).toEqual(['http://x/a|1', 'http://x/b|2', 'http://x/sup|1']); + expect(got.every(r => r.resourceType === 'CodeSystem' && r instanceof CodeSystem)).toBe(true); + expect(got.some(r => r instanceof ConceptMap)).toBe(false); + expect(got.map(r => r.supplementsUrl)).toEqual([undefined, undefined, 'http://x/a']); + expect(got[2].isGlobalSupplement()).toBe(false); + expect(got.every(r => r.isCached === true)).toBe(true); + expect(loads.n).toBe(0); + + // using one loads that one only, once + expect(got[1].content).toBe('complete'); + expect(got[1].jsonObj.concept[0].code).toBe('a'); + expect(got[1].conceptCount()).toBe(1); + expect(loads.n).toBe(1); + }); + + test('a loaded stand-in behaves like the wrapper it stands for', () => { + const c = make(); + const original = mkCs('http://x/a', '1'); + c.set('c1', [original]); + const [r] = c.get('c1'); + expect(r.jsonObj).toEqual(original.jsonObj); + expect(r.fhirVersion).toBe('R4'); + expect(r.versionAlgorithm()).toEqual(original.versionAlgorithm()); + expect(JSON.parse(JSON.stringify(r)).jsonObj).toEqual(original.jsonObj); + r.sourcePackage = 'p'; + expect(r.sourcePackage).toBe('p'); + }); + + test('the expansion cache key is the same as for the resources built eagerly', () => { + const c = make(); + const resources = [mkCs('http://x/a', '1'), new ValueSet({ resourceType: 'ValueSet', url: 'http://x/vs', status: 'active', + compose: { include: [{ system: 'http://x/a' }] } }, 'R4')]; + c.set('c1', resources); + const ec = new ExpansionCache(null); + const vs = { resourceType: 'ValueSet', url: 'http://x/vs' }; + const loads = countLoads(c); + const lazyKey = ec.computeKey(vs, null, c.get('c1')); + expect(loads.n).toBe(0); + const eager = c.q.resources.all('/r4', 'c1').map(row => c._build(row)); + expect(ec.computeKey(vs, null, eager)).toBe(lazyKey); + expect(ec.computeKey(vs, null, resources)).toBe(lazyKey); + }); + + test('a resource that has gone by the time it is used fails like a dead cache-id', () => { + const c = make(); + c.set('c1', [mkCs('http://x/a', '1')]); + const [r] = c.get('c1'); + c.clear('c1'); + let err = null; + try { + void r.jsonObj; + } catch (e) { + err = e; + } + expect(err).not.toBeNull(); + expect(err.statusCode).toBe(404); + expect(err.issueCode).toBe('cache-id-unknown'); + expect(err.message).toMatch(/was closed while this request was using it/); + }); + }); + + test('endpoints share the file but not caches', () => { + const file = path.join(tmpDir, `scopes-${++fileNo}.db`); + const r4 = new SqliteResourceCache(null, { path: file, scope: '/r4' }); + const r5 = new SqliteResourceCache(null, { path: file, scope: '/r5' }); + opened.push(r4, r5); + r4.set('c1', [CS('http://a', '1')]); + expect(r4.has('c1')).toBe(true); + expect(r5.has('c1')).toBe(false); + expect(r5.get('c1')).toEqual([]); + r4.clear('c1'); + expect(r5.tombstone('c1')).toBeNull(); + }); + + test('last_used is refreshed at most once per touch interval', () => { + const c = make({ touchIntervalMs: 30000 }); + c.set('c1', [CS('http://a', '1')]); + const t0 = Date.now() - 10000; + c.db.prepare('UPDATE sessions SET last_used = ?').run(t0); + c.get('c1'); + expect(lastUsedOf(c, 'c1')).toBe(t0); // 10 s ago: within the interval, not written + c.add('c1', [CS('http://a', '1')]); // same content again: no write either + expect(lastUsedOf(c, 'c1')).toBe(t0); + + const t1 = Date.now() - 31000; + c.db.prepare('UPDATE sessions SET last_used = ?').run(t1); + c.get('c1'); + expect(lastUsedOf(c, 'c1')).toBeGreaterThan(Date.now() - 2000); // past the interval: refreshed + }); + + test('an explicit touch (mode=check) is not throttled', () => { + const c = make({ touchIntervalMs: 30000 }); + c.set('c1', [CS('http://a', '1')]); + c.db.prepare('UPDATE sessions SET last_used = ?').run(Date.now() - 10000); + expect(c.touch('c1')).toBe(true); + expect(c.status('c1').idleMs).toBeLessThan(1000); + }); + + test('a failed last_used refresh is ignored', () => { + const c = make({ touchIntervalMs: 0 }); + c.set('c1', [CS('http://a', '1')]); + const orig = c.q.touch; + c.q.touch = { run: () => { throw Object.assign(new Error('database is locked'), { code: 'SQLITE_BUSY' }); } }; + try { + expect(c.get('c1')).toHaveLength(1); + expect(c.touch('c1')).toBe(true); + } finally { + c.q.touch = orig; + } + }); + + test('a failed write of uploaded resources is retried once, then answered 503 - never dropped silently', () => { + const c = make(); + c.set('c1', [CS('http://a', '1')]); + const orig = c.q.upsertResource; + let calls = 0; + c.q.upsertResource = { run: () => { calls++; throw Object.assign(new Error('database is locked'), { code: 'SQLITE_BUSY' }); } }; + let err = null; + try { + c.add('c1', [CS('http://b', '1')]); + } catch (e) { + err = e; + } finally { + c.q.upsertResource = orig; + } + expect(calls).toBe(2); + expect(err).not.toBeNull(); + expect(err.statusCode).toBe(503); + expect(err.msgId).toBe('CACHE_WRITE_FAILED'); + // the failed transaction changed nothing + expect(c.get('c1').map(r => r.url)).toEqual(['http://a']); + }); + + test('one failure then success: the retry saves the resources', () => { + const c = make(); + c.set('c1', []); + const orig = c.q.upsertResource; + let calls = 0; + c.q.upsertResource = { run: (row) => { if (++calls === 1) { throw Object.assign(new Error('busy'), { code: 'SQLITE_BUSY' }); } return orig.run(row); } }; + try { + c.add('c1', [CS('http://b', '1')]); + } finally { + c.q.upsertResource = orig; + } + expect(c.get('c1').map(r => r.url)).toEqual(['http://b']); + }); + + test('add() does not bring back a cache that has been closed', () => { + const c = make(); + c.set('c1', [CS('http://a', '1')]); + c.clear('c1'); + c.add('c1', [CS('http://b', '1')]); + expect(c.has('c1')).toBe(false); + expect(c.tombstone('c1').reason).toBe('closed'); + }); + + test('the size cap covers every endpoint in the file', () => { + const file = path.join(tmpDir, `cap-${++fileNo}.db`); + const r4 = new SqliteResourceCache(null, { path: file, scope: '/r4', maxBytes: 2500 }); + const r5 = new SqliteResourceCache(null, { path: file, scope: '/r5', maxBytes: 2500 }); + opened.push(r4, r5); + r4.set('a', [{ ...CS('http://a', '1'), description: 'x'.repeat(1000) }]); + r4.db.prepare('UPDATE sessions SET last_used = ?').run(Date.now() - 60000); + r5.set('b', [{ ...CS('http://b', '1'), description: 'x'.repeat(1000) }]); + r5.set('c', [{ ...CS('http://c', '1'), description: 'x'.repeat(1000) }]); + expect(r4.has('a')).toBe(false); + expect(r4.tombstone('a').reason).toBe('evicted'); + expect(r5.has('b')).toBe(true); + }); + + test('a cache survives a restart (closing and reopening the file)', () => { + const file = path.join(tmpDir, `restart-${++fileNo}.db`); + const before = new SqliteResourceCache(null, { path: file, scope: '/r4' }); + before.set('c1', [CS('http://a', '1')], true); + before.set('c2', []); + before.clear('c2'); + before.close(); + + const after = new SqliteResourceCache(null, { path: file, scope: '/r4' }); + opened.push(after); + expect(after.has('c1')).toBe(true); + expect(after.isSealed('c1')).toBe(true); + expect(after.get('c1').map(r => r.url)).toEqual(['http://a']); + expect(after.describeMissing('c2').messageId).toBe('CACHE_ID_CLOSED'); + }); + + test('a file from a different schema version is refused, not misread', () => { + const file = path.join(tmpDir, `schema-${++fileNo}.db`); + const c = new SqliteResourceCache(null, { path: file, scope: '/r4' }); + c.db.prepare("UPDATE meta SET value = '999' WHERE key = 'schema'").run(); + c.close(); + expect(() => new SqliteResourceCache(null, { path: file, scope: '/r4' })).toThrow(/schema version 999/); + }); }); diff --git a/tests/tx/setup.js b/tests/tx/setup.js index b40c4273..966ddac9 100644 --- a/tests/tx/setup.js +++ b/tests/tx/setup.js @@ -43,6 +43,15 @@ async function getTestApp() { ] }; + // FHIRSMITH_TEST_RESOURCE_CACHE=sqlite runs the same tests against the shared + // SQLite resource cache (cluster mode's store) instead of the memory one + if (process.env.FHIRSMITH_TEST_RESOURCE_CACHE === 'sqlite') { + const os = require('os'); + const fs = require('fs'); + const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'tx-resource-cache-')); + config.resourceCache = { store: 'sqlite', path: path.join(dir, 'resource-cache.db') }; + } + await txModule.initialize(config, app); initialized = true; diff --git a/tests/tx/vsac-generation.test.js b/tests/tx/vsac-generation.test.js new file mode 100644 index 00000000..8148b100 --- /dev/null +++ b/tests/tx/vsac-generation.test.js @@ -0,0 +1,125 @@ +/** + * VSAC in cluster mode: one process syncs, the others catch up by the database's + * generation counter. The sync bumps the generation in the same transaction that + * records the run; another process compares it with the generation it loaded when a + * request uses the value sets (at most once a second), and reloads only when it differs. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const { fork } = require('child_process'); + +const CHILD = path.join(__dirname, '..', 'utils', 'vsac-child.js'); +const sleep = (ms) => new Promise(resolve => setTimeout(resolve, ms)); + +const vs = (id, version) => ({ + resourceType: 'ValueSet', id, url: `http://cts.nlm.nih.gov/fhir/ValueSet/${id}`, version, status: 'active', + compose: { include: [{ system: 'http://loinc.org', concept: [{ code: '1-8' }] }] } +}); + +describe('VSAC value sets across processes', () => { + let dir; + const children = []; + + const spawn = () => { + const child = fork(CHILD, [], { env: { ...process.env, FHIRSMITH_DATA_DIR: dir }, stdio: ['ignore', 'inherit', 'inherit', 'ipc'] }); + children.push(child); + let seq = 0; + const waiting = new Map(); + let readyResolve; + const ready = new Promise(resolve => { readyResolve = resolve; }); + child.on('message', (m) => { + if (m.ready) { + readyResolve(); + return; + } + const w = waiting.get(m.seq); + if (m.error) { + w.reject(new Error(m.error)); + } else { + w.resolve(m.result); + } + }); + const call = (op, args = {}) => new Promise((resolve, reject) => { + const s = ++seq; + waiting.set(s, { resolve, reject }); + child.send({ seq: s, op, ...args }); + }); + return ready.then(() => ({ call })); + }; + + beforeEach(() => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'vsac-gen-')); + }); + afterEach(async () => { + for (const c of children.splice(0)) { + if (c.exitCode === null && c.signalCode === null) { + await new Promise(resolve => { + c.once('exit', resolve); + c.kill(); + }); + } + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('the other process picks up a sync on use, once, and only after it', async () => { + // A starts first and holds the background-jobs lock: its first sync (of an empty VSAC) + // takes the generation to 1 + const a = await spawn(); + expect(await a.call('init')).toEqual({ leader: true }); + const b = await spawn(); + expect(await b.call('init')).toEqual({ leader: false }); + expect(await b.call('catchUpNow')).toBe(1); + + const url = 'http://cts.nlm.nih.gov/fhir/ValueSet/one'; + expect(await b.call('fetch', { url, version: '20250101' })).toBeNull(); + + // A syncs: VSAC now has the value set + expect(await a.call('sync', { valueSets: [vs('one', '20250101')] })).toBe(2); + expect(await a.call('fetch', { url, version: '20250101' })).toBe('20250101'); + + // B notices on use: within a second or so (the check is throttled, and the reload runs + // in the background, so the request that notices still has the old list) + const before = await b.call('counts'); + let seen = null; + const t0 = Date.now(); + while (Date.now() - t0 < 5000 && !(seen = await b.call('fetch', { url, version: '20250101' }))) { + await sleep(50); + } + expect(seen).toBe('20250101'); + expect(Date.now() - t0).toBeLessThan(2500); + // B is at the new generation, having reloaded once + expect(await b.call('catchUpNow')).toBe(2); + const after = await b.call('counts'); + expect(after.loaded).toBe(2); + expect(after.reloads - before.reloads).toBe(1); + + // nothing changes: many uses over 1.5 s cost at most two generation reads, and no reload + const quiet = await b.call('counts'); + const t1 = Date.now(); + let uses = 0; + while (Date.now() - t1 < 1500) { + await b.call('fetch', { url, version: '20250101' }); + uses++; + } + const end = await b.call('counts'); + expect(uses).toBeGreaterThan(20); + expect(end.generationReads - quiet.generationReads).toBeLessThanOrEqual(2); + expect(end.reloads).toBe(quiet.reloads); + }); + + test('a resync of one value set reaches the other process too', async () => { + const a = await spawn(); + await a.call('init'); + const b = await spawn(); + await b.call('init'); + await a.call('sync', { valueSets: [vs('one', '1')] }); + expect(await b.call('catchUpNow')).toBe(2); + // the operator resyncs it on A (the /info form), and VSAC has a new version + const url = 'http://cts.nlm.nih.gov/fhir/ValueSet/one'; + expect(await a.call('resync', { url, valueSets: [vs('one', '1'), vs('one', '2')] })).toBe(3); + expect(await b.call('catchUpNow')).toBe(3); + expect(await b.call('fetch', { url: 'http://cts.nlm.nih.gov/fhir/ValueSet/one', version: '2' })).toBe('2'); + }); +}); diff --git a/tests/utils/closure-child.js b/tests/utils/closure-child.js new file mode 100644 index 00000000..898c4bdd --- /dev/null +++ b/tests/utils/closure-child.js @@ -0,0 +1,37 @@ +// A separate process using a $closure database, for tests/tx/closure-multiprocess.test.js: +// what two cluster-mode workers do to one closure table at the same time. +// node closure-child.js +const path = require('path'); +const dir = process.argv[2]; +const clusterState = require('../../library/cluster-state'); +clusterState._configure({ file: path.join(dir, 'cluster-state.db'), shared: true }); +const { ClosureStore } = require('../../tx/closure/closure-store'); + +const store = new ClosureStore({ database: path.join(dir, 'closure.db') }, null, { crossProcess: process.argv[3] === '1' }); +store.open(); + +process.on('message', async (msg) => { + try { + let result; + if (msg.op === 'create') { + result = store.createTable(msg.name, [], msg.max) !== null; + } else if (msg.op === 'adds') { + // the read-compute-write of a $closure call: read the table, yield, write the next version + for (let i = 0; i < msg.times; i++) { + await store.withLock(msg.name, async () => { + const table = store.getTable(msg.name); + await new Promise(resolve => setTimeout(resolve, msg.ms)); + store.recordAdd(table, [{ key: 'k', system: 'http://example.org', code: `${process.pid}-${i}` }], []); + }, { timeoutMs: 30000 }); + } + result = true; + } else if (msg.op === 'version') { + const t = store.getTable(msg.name); + result = { version: t.version, concepts: store.conceptCount(t.id) }; + } + process.send({ seq: msg.seq, result }); + } catch (e) { + process.send({ seq: msg.seq, error: e.message }); + } +}); +process.send({ ready: true }); diff --git a/tests/utils/cluster-state-child.js b/tests/utils/cluster-state-child.js new file mode 100644 index 00000000..899b5f23 --- /dev/null +++ b/tests/utils/cluster-state-child.js @@ -0,0 +1,57 @@ +// A separate server process for tests/library/cluster-state.test.js: the testing +// module (logins, CSRF, a login rate limit) over a data directory it shares with +// other copies of itself, as cluster-mode workers do. Also runs leases on request. +// node cluster-state-child.js [cluster | opt-in | off] +// cluster: as a cluster-mode worker; opt-in: one server with server.sharedState; +// off: one server as by default (logins in memory) +const path = require('path'); +const fs = require('fs'); +const express = require('express'); + +const dir = process.argv[2]; +const mode = process.argv[3] || 'cluster'; +const clusterState = require('../../library/cluster-state'); +if (mode === 'cluster') { + clusterState._configure({ file: path.join(dir, 'cluster-state.db'), shared: true }); +} else { + // decided as the server decides: no background-jobs lock in this process + clusterState._configure({ file: path.join(dir, 'cluster-state.db') }); + clusterState.configure({ sharedState: mode === 'opt-in' }); +} + +const quietLog = { info() {}, warn() {}, error() {}, debug() {} }; +require('../../library/html-server').useLog(quietLog); +const TestingModule = require('../../testing/testing'); + +(async () => { + const stats = { countRequest() {}, addTask() {}, task() {}, taskDone() {}, taskError() {} }; + const mod = new TestingModule(stats, quietLog); + await mod.initialize({ + database: path.join(dir, 'testing.db'), adminPassword: 'admin-secret', cookieSecure: false, + rateLimit: { max: 0 }, loginAttemptsPerWindow: 5 + }); + const app = express(); + app.set('trust proxy', 'loopback'); + app.use('/testing', mod.router); + const server = app.listen(0, '127.0.0.1', () => process.send({ ready: server.address().port })); + + process.on('message', async (msg) => { + if (msg.op === 'lease') { + // hold the lease for msg.ms, recording when it was held + const log = path.join(dir, 'lease.log'); + for (let i = 0; i < msg.times; i++) { + await clusterState.withLease('shared-thing', async () => { + fs.appendFileSync(log, `${process.pid} in ${Date.now()}\n`); + await new Promise(resolve => setTimeout(resolve, msg.ms)); + fs.appendFileSync(log, `${process.pid} out ${Date.now()}\n`); + }); + } + process.send({ seq: msg.seq, result: true }); + } else if (msg.op === 'secret') { + process.send({ seq: msg.seq, result: clusterState.sessionSecret('testing') }); + } + }); +})().catch(e => { + console.error(e); + process.exit(1); +}); diff --git a/tests/utils/memory-test-routes.js b/tests/utils/memory-test-routes.js new file mode 100644 index 00000000..dfd6bea5 --- /dev/null +++ b/tests/utils/memory-test-routes.js @@ -0,0 +1,92 @@ +// Preloaded (node --require) into the cluster-mode memory test servers. Adds routes, in +// front of the app, that use memory the way a heavy operation does: +// /__mem/leak?mb=N keep N MB (until the process ends) +// /__mem/heavy?mb=N&hold=ms allocate up to N MB, 10 MB at a time, asking the memory guard +// after each step what deadCheck asks it (overAbortThreshold): +// 422 if it says abort; else hold the memory for hold ms, free it, 200 +// /__mem/fill?mb=N&hold=ms the same, without asking: holds N MB for hold ms +// /__mem/check what overAbortThreshold says in this worker now +// /__mem/whoami nothing (which worker answered) +// /__mem/state what the guard measures now, and its thresholds +// Every response carries X-Served-By: . +const http = require('http'); +const path = require('path'); +const memoryGuard = require(path.join(__dirname, '..', '..', 'library', 'memory-guard')); + +const kept = []; +// Buffers are freed by a full GC; an operation's memory (JS objects) goes with the next +// GC its own allocation brings on. Freeing here collects at once, as that would +const collect = () => { + const gc = memoryGuard.getGc(); + if (gc) { + gc(); + } +}; +const sleep = (ms) => new Promise(resolve => setTimeout(resolve, ms)); +const MB = 1024 * 1024; + +function reply(res, status, body) { + res.writeHead(status, { 'Content-Type': 'application/json', 'X-Served-By': String(process.pid) }); + res.end(JSON.stringify({ pid: process.pid, rss: process.memoryUsage.rss(), ...body })); +} + +async function handle(req, res) { + const u = new URL(req.url, 'http://x'); + const mb = Number(u.searchParams.get('mb')) || 0; + const hold = Number(u.searchParams.get('hold')) || 0; + switch (u.pathname) { + case '/__mem/leak': + for (let i = 0; i < mb; i += 10) { + kept.push(Buffer.alloc(10 * MB, 1)); + } + return reply(res, 200, { kept: kept.length * 10 }); + case '/__mem/heavy': + case '/__mem/fill': { + const ask = u.pathname === '/__mem/heavy'; + let held = []; + for (let i = 0; i < mb; i += 10) { + held.push(Buffer.alloc(10 * MB, 1)); + await sleep(30); + const over = ask ? memoryGuard.overAbortThreshold('memory-test') : 0; + if (over) { + held = null; + collect(); + return reply(res, 422, { aborted: true, atMb: i + 10, group: over }); + } + } + await sleep(hold); + held = null; + collect(); + return reply(res, 200, { aborted: false }); + } + case '/__mem/whoami': + return reply(res, 200, {}); + case '/__mem/check': + return reply(res, 200, { aborts: memoryGuard.overAbortThreshold('memory-probe') > 0 }); + case '/__mem/state': + // what the guard measures now (this process's reading, or the group's in cluster mode) + memoryGuard._state.sampleTime = 0; + memoryGuard.shouldReject(); + return reply(res, 200, { measured: memoryGuard._state.sampleRss, rejectAt: memoryGuard._state.rejectAt, abortAt: memoryGuard._state.abortAt }); + default: + return reply(res, 404, {}); + } +} + +const emit = http.Server.prototype.emit; +http.Server.prototype.emit = function (event, req, res, ...rest) { + if (event === 'request' && req.url.startsWith('/__mem/')) { + void handle(req, res); + return true; + } + if (event === 'request') { + const writeHead = res.writeHead; + res.writeHead = function (...args) { + if (!this.headersSent) { + this.setHeader('X-Served-By', String(process.pid)); + } + return writeHead.apply(this, args); + }; + } + return emit.call(this, event, req, res, ...rest); +}; diff --git a/tests/utils/resource-cache-child.js b/tests/utils/resource-cache-child.js new file mode 100644 index 00000000..1a4c416d --- /dev/null +++ b/tests/utils/resource-cache-child.js @@ -0,0 +1,48 @@ +// A separate process using the shared SQLite resource cache, driven over IPC by +// tests/tx/resource-cache-multiprocess.test.js. Each message names a method of the +// cache and its arguments; the reply is the result (or the error). +const { SqliteResourceCache } = require('../../tx/resource-cache-sqlite'); +const { CodeSystem } = require('../../tx/library/codesystem'); + +const cache = new SqliteResourceCache(null, { path: process.argv[2], scope: '/r4' }); + +process.on('message', (msg) => { + try { + let result; + switch (msg.op) { + case 'start': { + const id = cache.newCacheId(); + cache.set(id, (msg.resources || []).map(r => new CodeSystem(r, 'R4')), !!msg.sealed); + result = id; + break; + } + case 'add': + cache.add(msg.id, msg.resources.map(r => new CodeSystem(r, 'R4'))); + result = true; + break; + case 'get': + result = cache.get(msg.id).map(r => ({ cls: r.constructor.name, url: r.url, version: r.version, fhirVersion: r.fhirVersion, concepts: r.conceptCount() })); + break; + case 'has': + result = cache.has(msg.id); + break; + case 'end': + cache.clear(msg.id); + result = true; + break; + case 'describe': + result = cache.describeMissing(msg.id); + break; + case 'prune': + cache.prune(msg.maxAge); + result = true; + break; + default: + throw new Error('unknown op ' + msg.op); + } + process.send({ seq: msg.seq, result }); + } catch (e) { + process.send({ seq: msg.seq, error: e.message }); + } +}); +process.send({ ready: process.pid }); diff --git a/tests/utils/served-by.js b/tests/utils/served-by.js new file mode 100644 index 00000000..e6ee2713 --- /dev/null +++ b/tests/utils/served-by.js @@ -0,0 +1,10 @@ +// Preloaded (node --require) into cluster-mode test servers: every response says which +// process served it, in X-Served-By. +const http = require('http'); +const writeHead = http.ServerResponse.prototype.writeHead; +http.ServerResponse.prototype.writeHead = function (...args) { + if (!this.headersSent) { + this.setHeader('X-Served-By', String(process.pid)); + } + return writeHead.apply(this, args); +}; diff --git a/tests/utils/vsac-child.js b/tests/utils/vsac-child.js new file mode 100644 index 00000000..9f4ac978 --- /dev/null +++ b/tests/utils/vsac-child.js @@ -0,0 +1,79 @@ +// A server process with the VSAC value set provider, for tests/tx/vsac-generation.test.js. +// Its "VSAC" is a list of value sets the test sends: the provider's real refresh runs +// against it (_fetchBundle answers from the list), so a sync writes the database and +// bumps its generation exactly as a real one does. +// FHIRSMITH_DATA_DIR= node vsac-child.js +const path = require('path'); +const folders = require('../../library/folder-setup'); +const backgroundJobs = require('../../library/background-jobs'); +backgroundJobs.configure({ enabled: true, path: path.join(folders.dataDir(), 'background-jobs.lock') }); +const { VSACValueSetProvider } = require('../../tx/vs/vs-vsac'); + +const stats = { addTask() {}, task() {}, taskDone() {}, taskError() {} }; +const provider = new VSACValueSetProvider({ apiKey: 'test' }, stats); +provider.log = { error() {} }; +let upstream = []; +provider._scanLastUpdated = async () => 0; +provider._fetchBundle = async (url) => { + const m = /[?&]url=([^&]+)/.exec(url); + const list = m ? upstream.filter(vs => vs.url === decodeURIComponent(m[1])) : upstream; + return { resourceType: 'Bundle', total: list.length, entry: list.map(resource => ({ resource })), link: [] }; +}; +// count the generation reads, to show the check is throttled +let generationReads = 0; +const getGeneration = provider.database.getGeneration.bind(provider.database); +provider.database.getGeneration = async () => { + generationReads++; + return getGeneration(); +}; +// what the provider does when the generation has moved: reload its value set list (or, +// where the value sets are read from the database per request, recount them) +let reloads = 0; +const reloadName = typeof provider._reloadMap === 'function' ? '_reloadMap' : '_recount'; +const reload = provider[reloadName].bind(provider); +provider[reloadName] = async () => { + reloads++; + return reload(); +}; +const origLog = console.log; +console.log = () => {}; + +process.on('message', async (msg) => { + try { + let result; + switch (msg.op) { + case 'init': + await provider.initialize(); + result = { leader: backgroundJobs.isLeader() }; + break; + case 'sync': + upstream = msg.valueSets; + await provider.refreshValueSets(); + result = await provider.database.getGeneration(); + break; + case 'resync': + upstream = msg.valueSets; + await provider.resyncValueSet(msg.url); + result = await provider.database.getGeneration(); + break; + case 'fetch': { + const vs = await provider.fetchValueSet(msg.url, msg.version || ''); + result = vs ? vs.version : null; + break; + } + case 'catchUpNow': + provider.generationCheckedAt = 0; + await provider.catchUp(true); + result = provider.loadedGeneration; + break; + case 'counts': + result = { generationReads, reloads, loaded: provider.loadedGeneration }; + break; + } + process.send({ seq: msg.seq, result }); + } catch (e) { + origLog(e); + process.send({ seq: msg.seq, error: e.message }); + } +}); +process.send({ ready: true }); diff --git a/tests/utils/xig-child.js b/tests/utils/xig-child.js new file mode 100644 index 00000000..34c567ef --- /dev/null +++ b/tests/utils/xig-child.js @@ -0,0 +1,35 @@ +// A server process with the XIG module's database, for tests/xig/xig-follow.test.js. +// FHIRSMITH_DATA_DIR= node xig-child.js +const path = require('path'); +const folders = require('../../library/folder-setup'); +require('../../library/background-jobs').configure({ enabled: true, path: path.join(folders.dataDir(), 'background-jobs.lock') }); +require('../../library/html-server').useLog({ info() {}, warn() {}, error() {}, debug() {} }); +const xig = require('../../xig/xig'); + +process.on('message', async (msg) => { + try { + let result; + switch (msg.op) { + case 'open': + await xig._initializeDatabase(); + result = xig._openedInode(); + break; + case 'use': + // what a request does on its way in + xig._followDatabaseFile(); + result = xig._openedInode(); + break; + case 'inode': + result = xig._openedInode(); + break; + case 'update': + await xig.updateXigDatabase(); + result = true; + break; + } + process.send({ seq: msg.seq, result }); + } catch (e) { + process.send({ seq: msg.seq, error: e.message }); + } +}); +process.send({ ready: true }); diff --git a/tests/xig/xig-follow.test.js b/tests/xig/xig-follow.test.js new file mode 100644 index 00000000..16edfb0a --- /dev/null +++ b/tests/xig/xig-follow.test.js @@ -0,0 +1,117 @@ +/** + * XIG in cluster mode: one process downloads a new database and renames it over the + * old file; another notices on its next request (at most one stat a second) that the + * file is a different one, and opens it. An update asked of one process while another + * is updating is skipped, not run twice over the same temporary file. + */ +const fs = require('fs'); +const os = require('os'); +const path = require('path'); +const { fork } = require('child_process'); +const Database = require('better-sqlite3'); +const clusterState = require('../../library/cluster-state'); + +const CHILD = path.join(__dirname, '..', 'utils', 'xig-child.js'); +const sleep = (ms) => new Promise(resolve => setTimeout(resolve, ms)); + +describe('XIG database followed across processes', () => { + let dir; + let child; + let call; + + const makeDb = (file) => { + const db = new Database(file); + db.exec('CREATE TABLE Resources (id INTEGER)'); + db.close(); + }; + + beforeEach(async () => { + dir = fs.mkdtempSync(path.join(os.tmpdir(), 'xig-follow-')); + fs.mkdirSync(path.join(dir, 'xig')); + makeDb(path.join(dir, 'xig', 'xig.db')); + child = fork(CHILD, [], { env: { ...process.env, FHIRSMITH_DATA_DIR: dir }, stdio: ['ignore', 'ignore', 'ignore', 'ipc'] }); + let seq = 0; + const waiting = new Map(); + let readyResolve; + const ready = new Promise(resolve => { readyResolve = resolve; }); + child.on('message', (m) => { + if (m.ready) { + readyResolve(); + return; + } + const w = waiting.get(m.seq); + if (m.error) { + w.reject(new Error(m.error)); + } else { + w.resolve(m.result); + } + }); + call = (op) => new Promise((resolve, reject) => { + const s = ++seq; + waiting.set(s, { resolve, reject }); + child.send({ seq: s, op }); + }); + await ready; + }); + + afterEach(async () => { + clusterState._configure(); + if (child.exitCode === null) { + await new Promise(resolve => { + child.once('exit', resolve); + child.kill(); + }); + } + fs.rmSync(dir, { recursive: true, force: true }); + }); + + test('a replaced file is opened on the next request, after one stat', async () => { + const first = await call('open'); + expect(first).toBe(fs.statSync(path.join(dir, 'xig', 'xig.db')).ino); + // another process downloads and renames a new file over it + makeDb(path.join(dir, 'xig', 'new.db')); + fs.renameSync(path.join(dir, 'xig', 'new.db'), path.join(dir, 'xig', 'xig.db')); + const second = fs.statSync(path.join(dir, 'xig', 'xig.db')).ino; + expect(second).not.toBe(first); + + await call('use'); + let now = first; + for (let i = 0; i < 40 && now !== second; i++) { + await sleep(50); + now = await call('inode'); + } + expect(now).toBe(second); + + // replaced again straight away: requests within the second don't look + makeDb(path.join(dir, 'xig', 'new.db')); + fs.renameSync(path.join(dir, 'xig', 'new.db'), path.join(dir, 'xig', 'xig.db')); + const third = fs.statSync(path.join(dir, 'xig', 'xig.db')).ino; + await call('use'); + await sleep(100); + expect(await call('inode')).toBe(second); + await sleep(1000); + await call('use'); + for (let i = 0; i < 40 && now !== third; i++) { + await sleep(50); + now = await call('inode'); + } + expect(now).toBe(third); + }); + + test('an update is skipped while another process holds the update lease', async () => { + await call('open'); + const before = await call('inode'); + clusterState._configure({ file: path.join(dir, 'cluster-state.db'), shared: true }); + let release; + const held = clusterState.withLease('xig-update', () => new Promise(resolve => { release = resolve; })); + await sleep(20); + // returns at once, downloads nothing + const t0 = Date.now(); + await call('update'); + expect(Date.now() - t0).toBeLessThan(2000); + expect(fs.existsSync(path.join(dir, 'xig', 'xig.db.tmp'))).toBe(false); + expect(await call('inode')).toBe(before); + release(); + await held; + }); +}); diff --git a/token/token.js b/token/token.js index ca2fdff5..69ee7e46 100644 --- a/token/token.js +++ b/token/token.js @@ -16,6 +16,7 @@ const GoogleStrategy = require('passport-google-oauth20').Strategy; const FacebookStrategy = require('passport-facebook').Strategy; const GitHubStrategy = require('passport-github2').Strategy; const rateLimit = require('express-rate-limit'); +const { rateLimitOptions } = require('../library/cluster-state'); const lusca = require('lusca'); const folders = require('../library/folder-setup'); const { SqliteSessionStore } = require('../library/sqlite-session-store'); @@ -72,6 +73,9 @@ class TokenModule { reject(err); return; } + // with several server processes, a write (a session, a login) waits for another + // process's rather than failing + this.db.configure('busyTimeout', 5000); // Create tables this.db.serialize(() => { @@ -160,7 +164,8 @@ class TokenModule { const sessionConfig = { store: this.sessionStore, - secret: this.config.sessionSecret || crypto.randomBytes(64).toString('hex'), + // several processes: a generated secret is shared (library/cluster-state) + secret: require('../library/cluster-state').sessionSecret('token', this.config.sessionSecret), name: 'fhir.token.sid', // Don't use default session name resave: false, saveUninitialized: false, @@ -201,7 +206,7 @@ class TokenModule { })); // Rate limiting - const authLimiter = rateLimit({ + const authLimiter = rateLimit(rateLimitOptions('token-auth', { windowMs: 15 * 60 * 1000, // 15 minutes max: 5, // 5 attempts per window message: 'Too many authentication attempts, please try again later.', @@ -211,15 +216,15 @@ class TokenModule { // Skip rate limiting for successful authentications return req.user && req.isAuthenticated(); } - }); + })); - const apiLimiter = rateLimit({ + const apiLimiter = rateLimit(rateLimitOptions('token-api', { windowMs: 15 * 60 * 1000, // 15 minutes max: 100, // 100 requests per window for API calls message: 'Too many API requests, please try again later.', standardHeaders: true, legacyHeaders: false - }); + })); // Apply rate limiting to specific routes this.router.use('/auth', authLimiter); diff --git a/translations/Messages.properties b/translations/Messages.properties index 3f10c049..d02953b4 100644 --- a/translations/Messages.properties +++ b/translations/Messages.properties @@ -1116,9 +1116,11 @@ Unable_to_resolve_system__value_set_has_no_includes_or_expansion = The System UR UNABLE_TO_RESOLVE_SYSTEM_SYSTEM_IS_INDETERMINATE = The code system {1} referred to from value set {0} has a grammar, and the code might be valid in it Unable_to_resolve_value_Set_ = A definition for the value Set ''{0}'' could not be found CACHE_ID_UNKNOWN = The cache ''{0}'' was never issued by this server, and this server has no record of it ever existing. Caches are created with $cache-control?mode=start, and a cache-id is only valid on the server instance and endpoint that issued it - either it was issued somewhere else, or this server has restarted since it was issued +CACHE_ID_UNKNOWN_SHARED = The cache ''{0}'' was never issued by this server for this endpoint, and this server has no record of it ever existing. Caches are created with $cache-control?mode=start, and a cache-id is only valid on the server and endpoint that issued it. This server keeps its caches on disk, where they survive a restart CACHE_ID_CLOSED = The cache ''{0}'' was closed {1} ago by the client, using $cache-control?mode=end (it had been open for {2}). It did not expire and it was not idle: something in the client released this cache while this request was still using it CACHE_ID_EXPIRED = The cache ''{0}'' expired: it went {1} without being used, and this server closes caches that have been idle for more than {2} (this one was dropped {3} ago). Every request that uses a cache resets its idle clock, so a client that keeps using a cache will not see this CACHE_ID_CLEARED = The cache ''{0}'' was dropped {1} ago, when this server cleared all of its caches +CACHE_ID_EVICTED = The cache ''{0}'' was dropped {1} ago to make room: this server holds at most {2} of client resources across all caches, and when it is full it drops the caches that have gone longest without being used (this one had been idle for {3}). Start a new cache and send the resources again CACHE_ID_OTHER_INSTANCE = The cache ''{0}'' was issued by the server instance ''{1}'', but this is instance ''{2}''. A cache only exists on the instance that issued it, so this request reached the wrong server: either the proxy in front of these servers is not routing on the cache-id, or instance ''{1}'' is unavailable CACHE_ID_OTHER_INSTANCE_UNNAMED = The cache ''{0}'' was issued by the server instance ''{1}'', but this server has no instance code, so it cannot have issued it. A cache only exists on the instance that issued it, so this request reached the wrong server: either the proxy in front of these servers is not routing on the cache-id, or instance ''{1}'' is unavailable CLOSURE_NOT_SUPPORTED = This server does not support $closure (it has to be turned on by the administrator) diff --git a/tx/closure/closure-store.js b/tx/closure/closure-store.js index d4f76dfe..68f19608 100644 --- a/tx/closure/closure-store.js +++ b/tx/closure/closure-store.js @@ -20,7 +20,11 @@ // better-sqlite3 on purpose: every write is synchronous, so a write transaction can never // be interleaved with another request's. The only thing that needs a lock is the span of // one $closure call on one table - read the table, compute (which awaits, and yields), -// write - and that is the per-table lock below. +// write - and that is the per-table lock below. Within a process it is a queue of +// promises; when several server processes share the database (cluster mode), the call +// at the head of a process's queue also takes a lease on the table in the shared +// cluster-state database (library/cluster-state withLease), so calls on one table from +// different processes take turns too. // // Synchronous also means every statement blocks the event loop while it runs, so nothing // here reads or writes an unbounded amount in one go: reads that can be large are paged @@ -41,12 +45,16 @@ class ClosureStore { * @param {Object} config - modules.tx.closure * @param {Object} [log] */ - constructor(config, log) { + constructor(config, log, options = {}) { this.config = config || {}; this.log = log || console; this.db = null; this.path = ClosureStore.resolvePath(this.config); this.locks = new Map(); // table name -> { tail: Promise, count: holder + waiters } + // other processes use this database too: lock tables across processes as well + // (default: when the server says the data directory is shared) + this.crossProcess = options.crossProcess !== undefined ? !!options.crossProcess + : (this.path !== ':memory:' && require('../../library/cluster-state').isShared()); } /** @@ -184,6 +192,9 @@ class ClosureStore { * @param {Function} [opts.waitFor] - (promise) => promise; wraps the wait (the worker * uses OperationContext.waitFor, so the wait isn't charged to the compute deadline and * a disconnected client stops waiting) + * The queue bound is per process. Across processes (crossProcess), the call at the head + * of this process's queue then waits for the table's lease, within the same timeout. + * * @throws {Error} with .closureBusy = 'queue' | 'timeout' when the lock isn't got */ async withLock(name, fn, opts = {}) { @@ -205,6 +216,7 @@ class ClosureStore { let timer = null; let acquired = false; + const started = Date.now(); try { let wait = prior; if (opts.timeoutMs) { @@ -218,6 +230,13 @@ class ClosureStore { } await (opts.waitFor ? opts.waitFor(wait) : wait); acquired = true; + if (timer) { + clearTimeout(timer); + timer = null; + } + if (this.crossProcess) { + return await this.withLease(name, fn, opts, started); + } return await fn(); } finally { if (timer) { @@ -235,6 +254,27 @@ class ClosureStore { } } + /** + * The cross-process half of withLock: the table's lease in the shared cluster-state + * database, waited for within what is left of opts.timeoutMs. + */ + async withLease(name, fn, opts, started) { + let timeoutMs = 0; + if (opts.timeoutMs) { + timeoutMs = Math.max(1, opts.timeoutMs - (Date.now() - started)); + } + try { + return await require('../../library/cluster-state').withLease('closure:' + name, fn, { timeoutMs, waitFor: opts.waitFor }); + } catch (error) { + if (error.leaseTimeout) { + const busy = new Error(`timed out waiting for closure table '${name}'`); + busy.closureBusy = 'timeout'; + throw busy; + } + throw error; + } + } + /** * @param {string} name * @returns {{id, name, version, created, last_used}|null} @@ -269,21 +309,26 @@ class ClosureStore { * whether that's allowed). Its parameters are fixed here, for the life of the table. * @param {string} name * @param {Array} params - Parameters.parameter entries that configure the table - * @returns {Object} the new table row + * @param {number} [maxTables] - if given, and the table is new, and there are already this + * many: nothing is created, and the result is null. Checked in the same transaction as + * the insert, so processes creating tables at the same time can't go over it together + * @returns {Object|null} the new table row */ - createTable(name, params) { + createTable(name, params, maxTables) { const now = new Date().toISOString(); const tx = this.db.transaction(() => { const existing = this.stmt.getTable.get(name); if (existing) { this.stmt.deleteTable.run(existing.id); + } else if (maxTables !== undefined && this.stmt.countTables.get().n >= maxTables) { + return null; } const info = this.stmt.insertTable.run(name, now, now); const id = info.lastInsertRowid; params.forEach((p, i) => this.stmt.insertParam.run(id, i, p.name, JSON.stringify(p))); return this.stmt.getTable.get(name); }); - return tx(); + return tx.immediate(); } /** diff --git a/tx/library/codesystem.js b/tx/library/codesystem.js index 31b543a3..07a868eb 100644 --- a/tx/library/codesystem.js +++ b/tx/library/codesystem.js @@ -739,6 +739,15 @@ class CodeSystem extends CanonicalResource { return (this.jsonObj.property || []).find(x => x.code == code && x.uri == uri); } + /** + * The canonical of the code system this one supplements (CodeSystem.supplements), + * or undefined if it isn't a supplement. + * @returns {string|undefined} + */ + get supplementsUrl() { + return this.jsonObj.supplements; + } + isSupplementFor(url, version) { if (this.jsonObj.content !== 'supplement') { return false; diff --git a/tx/operation-context.js b/tx/operation-context.js index 29837db6..cf82def8 100644 --- a/tx/operation-context.js +++ b/tx/operation-context.js @@ -77,14 +77,48 @@ class TimeTracker { /** - * Thread-safe resource cache for tx-resource parameters - * Stores resources by cache-id for reuse across requests + * Render a byte count for a human: "512 KB", "3.4 MB", "2 GB". + * @param {number} bytes + * @returns {string} + */ +function formatBytes(bytes) { + if (bytes === null || bytes === undefined || !isFinite(bytes) || bytes < 0) { + return 'an unknown size'; + } + if (bytes < 1024 * 1024) { + return `${Math.max(1, Math.round(bytes / 1024))} KB`; + } + if (bytes < 1024 * 1024 * 1024) { + return `${(bytes / (1024 * 1024)).toFixed(1).replace(/\.0$/, '')} MB`; + } + return `${(bytes / (1024 * 1024 * 1024)).toFixed(1).replace(/\.0$/, '')} GB`; +} + +/** + * Resource cache for the cache-id protocol ($cache-control): resources a client + * supplies under a cache-id are kept for use by its later requests. + * + * This class keeps them in this process's memory (resourceCache.store = "memory", + * the default). SqliteResourceCache (resource-cache-sqlite.js) is the same + * interface over one SQLite file shared by every process on the machine, for + * running several server processes on one port. */ class ResourceCache { logCacheOps = false; - constructor(stats, maxTombstones = 1000) { + /** + * @param {Object} stats - server stats (may be null) + * @param {number} [maxTombstones=1000] - how many dead cache-ids to remember + * @param {Object} [options] + * @param {number} [options.maxBytes=0] - cap on the total size (JSON bytes) of the + * resources held; when a change takes the total over it, whole caches are dropped, + * least recently used first (tombstone reason `evicted`). 0 = no cap. + */ + constructor(stats, maxTombstones = 1000, options = {}) { this.stats = stats; + this.maxBytes = options.maxBytes > 0 ? options.maxBytes : 0; + // Running total of resource bytes, only maintained when there is a cap + this.totalBytes = 0; this.cache = new Map(); this.locks = new Map(); // For thread-safety with async operations this.log = Logger.getInstance().child({module: 'tx-cache'}); @@ -185,10 +219,11 @@ class ResourceCache { * * @param {string} cacheId - The cache identifier * @param {Object} entry - The entry being removed (for its timings) - * @param {'closed'|'expired'|'cleared'} reason - How it went away: + * @param {'closed'|'expired'|'cleared'|'evicted'} reason - How it went away: * `closed` = the client released it with $cache-control?mode=end; * `expired` = it went unused for longer than the idle timeout; - * `cleared` = the server dropped every cache at once. + * `cleared` = the server dropped every cache at once; + * `evicted` = dropped to keep the cache under its size cap (maxBytes). * @param {Object} [extra] - Reason-specific detail (e.g. idleMs, maxAgeMs) */ _recordTombstone(cacheId, entry, reason, extra = {}) { @@ -255,6 +290,11 @@ class ResourceCache { messageId: 'CACHE_ID_EXPIRED', params: [cacheId, formatDuration(t.idleMs), formatDuration(t.maxAgeMs), ago] }; + case 'evicted': + return { + messageId: 'CACHE_ID_EVICTED', + params: [cacheId, ago, formatBytes(t.maxBytes), formatDuration(t.idleMs)] + }; default: return { messageId: 'CACHE_ID_CLEARED', params: [cacheId, ago] }; } @@ -400,7 +440,7 @@ class ResourceCache { } } - const entry = this.cache.get(cacheId) || { resources: [], createdAt: Date.now(), lastUsed: Date.now(), concepts: 0 }; + const entry = this.cache.get(cacheId) || { resources: [], createdAt: Date.now(), lastUsed: Date.now(), concepts: 0, bytes: 0, sizes: new Map() }; // Merge resources, avoiding duplicates by url+version. Keep the entry's concept // subtotal and the cache-wide total in step with each insertion/replacement. @@ -414,6 +454,7 @@ class ResourceCache { entry.resources[existingIndex] = resource; entry.concepts += delta; this.totalConcepts += delta; + this._sizeResource(entry, key, resource); if (this.logCacheOps) { this.log.info(`cache-id '${cacheId}': replaced ${key}`); } @@ -421,6 +462,7 @@ class ResourceCache { entry.resources.push(resource); entry.concepts += newConcepts; this.totalConcepts += newConcepts; + this._sizeResource(entry, key, resource); if (this.logCacheOps) { this.log.info(`cache-id '${cacheId}': added ${key}`); } @@ -430,6 +472,66 @@ class ResourceCache { entry.lastUsed = Date.now(); this.cache.set(cacheId, entry); this._trackMax(); + this._enforceMaxBytes(cacheId); + } + + /** + * Record the size of a resource in an entry (only when there is a size cap: it + * costs a JSON serialisation, and without a cap nothing needs the number). + */ + _sizeResource(entry, key, resource) { + if (!this.maxBytes) { + return; + } + if (!entry.sizes) { + entry.sizes = new Map(); + entry.bytes = 0; + } + const bytes = ResourceCache.byteSize(resource); + const old = entry.sizes.get(key) || 0; + entry.sizes.set(key, bytes); + entry.bytes += bytes - old; + this.totalBytes += bytes - old; + } + + /** + * Size of a resource as the cache counts it: the length of its JSON (the + * wrapper's jsonObj, or the object itself). + * @param {Object} resource + * @returns {number} + */ + static byteSize(resource) { + if (!resource) { + return 0; + } + const json = JSON.stringify(resource.jsonObj || resource); + return json ? Buffer.byteLength(json) : 0; + } + + /** + * If the cache is over its size cap, drop whole caches, least recently used + * first, until it isn't. The cache that was just written is never dropped by its + * own write: the client is in the middle of using it. + * @param {string} keepId - the cache-id being written + */ + _enforceMaxBytes(keepId) { + if (!this.maxBytes || this.totalBytes <= this.maxBytes) { + return; + } + const victims = [...this.cache.entries()] + .filter(([id]) => id !== keepId) + .sort((a, b) => a[1].lastUsed - b[1].lastUsed); + const now = Date.now(); + for (const [id, entry] of victims) { + if (this.totalBytes <= this.maxBytes) { + break; + } + this.totalConcepts -= entry.concepts || 0; + this.totalBytes -= entry.bytes || 0; + this._recordTombstone(id, entry, 'evicted', { idleMs: now - entry.lastUsed, maxBytes: this.maxBytes }); + this.cache.delete(id); + this.log.info(`cache-id '${id}': evicted (cache over its ${formatBytes(this.maxBytes)} cap; idle ${formatDuration(now - entry.lastUsed)})`); + } } /** @@ -456,22 +558,30 @@ class ResourceCache { const existing = this.cache.get(cacheId); if (existing) { this.totalConcepts -= existing.concepts || 0; + this.totalBytes -= existing.bytes || 0; } let concepts = 0; for (const resource of resources) { concepts += this._conceptsOf(resource); } this.totalConcepts += concepts; - this.cache.set(cacheId, { + const entry = { resources: [...resources], createdAt: existing ? existing.createdAt : Date.now(), lastUsed: Date.now(), concepts, + bytes: 0, + sizes: new Map(), sealed: !!sealed - }); + }; + for (const resource of resources) { + this._sizeResource(entry, this._resourceKey(resource), resource); + } + this.cache.set(cacheId, entry); // This id is alive again, so any record of its previous death is now wrong. this.tombstones.delete(cacheId); this._trackMax(); + this._enforceMaxBytes(cacheId); } /** @@ -486,6 +596,7 @@ class ResourceCache { const entry = this.cache.get(cacheId); if (entry) { this.totalConcepts -= entry.concepts || 0; + this.totalBytes -= entry.bytes || 0; this._recordTombstone(cacheId, entry, 'closed'); if (this.logCacheOps) { this.log.info(`cache-id '${cacheId}': closed by client after ${formatDuration(Date.now() - entry.createdAt)} (held ${entry.resources.length} resource(s))`); @@ -503,6 +614,7 @@ class ResourceCache { } this.cache.clear(); this.totalConcepts = 0; + this.totalBytes = 0; } /** @@ -520,6 +632,7 @@ class ResourceCache { if (idleMs > maxAge) { i++; this.totalConcepts -= entry.concepts || 0; + this.totalBytes -= entry.bytes || 0; // Record the *measured* idle time, not the configured timeout: the sweep // runs periodically, so a cache can sit dead for up to one sweep interval // past the timeout, and only the measured figure lets a client line the @@ -579,6 +692,20 @@ class ResourceCache { return entry ? (entry.concepts || 0) : 0; } + /** + * Total JSON bytes held (only tracked when there is a size cap; 0 otherwise). + * @returns {number} + */ + byteCount() { + return this.totalBytes; + } + + /** + * Release whatever the store holds open (nothing, for the memory store). + */ + close() { + } + /** * Generate a key for a resource based on url and version * @param {Object} resource - The resource @@ -651,6 +778,11 @@ class ExpansionCache { if (additionalResources && additionalResources.length > 0) { const resourceHashes = additionalResources .map(r => { + // A resource from the shared resource cache carries the hash of its stored + // content, computed the same way, so it doesn't have to be loaded to be hashed + if (typeof r.cacheContentHash === 'string') { + return r.cacheContentHash; + } // Get the JSON object from wrapper or use directly const json = r.jsonObj || r; // Create a content hash for this resource @@ -1212,6 +1344,7 @@ module.exports = { ExpansionParamsVersionRuleMode, TimeTracker, ResourceCache, + formatBytes, ExpansionCache, isDebugging, debugLog, diff --git a/tx/resource-cache-sqlite.js b/tx/resource-cache-sqlite.js new file mode 100644 index 00000000..c169193e --- /dev/null +++ b/tx/resource-cache-sqlite.js @@ -0,0 +1,774 @@ +// +// SqliteResourceCache - the $cache-control resource cache kept in one SQLite file +// that every server process on the machine shares. +// +// Why: in cluster mode several processes listen on one port and any of them may +// receive any request, so a cache started on one process must be usable from all of +// them. The memory store (ResourceCache) can't do that. This class is the same +// interface with the same semantics, over a file: +// +// - Nothing about a cache's contents is held in memory between requests. Each use +// reads the rows; there is no per-process copy that could go stale when another +// process changes the cache. +// - A request only pays for the resources it uses. get() reads the list of what the +// cache holds (type, url, version - not the content) and returns a stand-in for +// each CodeSystem / ValueSet / ConceptMap that answers those from the list; the +// first time a request touches anything else on one, its JSON is read and the +// real wrapper built (see lazyResource). Most requests look up a handful of +// resources by url in a cache of tens or hundreds. +// - Every write is one short BEGIN IMMEDIATE transaction; WAL mode lets readers +// carry on while one process writes; busy_timeout makes a writer wait for another +// rather than fail. +// - last_used is refreshed at most every touchIntervalMs (default 30 s) per cache, +// not on every read, so steady use of a cache is reads only. +// - The idle sweep (prune) and the size cap (maxBytes) move the caches they drop to +// tombstones in the same transaction, so whichever process asks about a dead +// cache-id later is told what happened to it. Any process may sweep; a sweep that +// finds nothing to do (because another process just did it) does nothing. +// +// The file must be on a local disk. SQLite's locking is not reliable on network +// filesystems (NFS, SMB, most container volume drivers backed by them), and a +// broken lock there corrupts the file. +// + +const fs = require('fs'); +const path = require('path'); +const crypto = require('crypto'); +const Database = require('better-sqlite3'); +const { ResourceCache, formatDuration, formatBytes } = require('./operation-context'); +const { Issue } = require('./library/operation-outcome'); + +const SCHEMA_VERSION = 2; +const DEFAULT_TOUCH_INTERVAL_MS = 30 * 1000; +const DEFAULT_BUSY_TIMEOUT_MS = 5000; + +// One connection per file per process, shared by the endpoints (each has its own scope) +const connections = new Map(); // absolute path -> { db, refs } + +function openDatabase(file, busyTimeoutMs) { + const abs = path.resolve(file); + const existing = connections.get(abs); + if (existing) { + existing.refs++; + return existing.db; + } + fs.mkdirSync(path.dirname(abs), { recursive: true }); + const db = new Database(abs); + // busy_timeout first: switching to WAL and creating the tables need locks that + // another process starting at the same moment may hold + db.pragma(`busy_timeout = ${busyTimeoutMs}`); + db.pragma('journal_mode = WAL'); + // NORMAL is safe with WAL (no corruption); a power cut can lose the last + // transactions, which for a cache of client resources is acceptable + db.pragma('synchronous = NORMAL'); + db.transaction(() => { + db.exec(` + CREATE TABLE IF NOT EXISTS meta (key TEXT PRIMARY KEY, value TEXT); + CREATE TABLE IF NOT EXISTS sessions ( + scope TEXT NOT NULL, + cache_id TEXT NOT NULL, + created_at INTEGER NOT NULL, + last_used INTEGER NOT NULL, + sealed INTEGER NOT NULL DEFAULT 0, + concepts INTEGER NOT NULL DEFAULT 0, + resources INTEGER NOT NULL DEFAULT 0, + bytes INTEGER NOT NULL DEFAULT 0, + version INTEGER NOT NULL DEFAULT 0, + PRIMARY KEY (scope, cache_id) + ); + CREATE INDEX IF NOT EXISTS sessions_last_used ON sessions (last_used); + CREATE TABLE IF NOT EXISTS resources ( + id INTEGER PRIMARY KEY, + scope TEXT NOT NULL, + cache_id TEXT NOT NULL, + key TEXT NOT NULL, + resource_type TEXT, + url TEXT, + version TEXT, + fhir_version TEXT, + kind TEXT NOT NULL, + hash TEXT NOT NULL, + json TEXT NOT NULL, + bytes INTEGER NOT NULL, + concepts INTEGER NOT NULL DEFAULT 0, + supplements TEXT, + global_supplement INTEGER, + UNIQUE (scope, cache_id, key) + ); + CREATE TABLE IF NOT EXISTS tombstones ( + scope TEXT NOT NULL, + cache_id TEXT NOT NULL, + reason TEXT NOT NULL, + at INTEGER NOT NULL, + created_at INTEGER, + last_used INTEGER, + idle_ms INTEGER, + max_age_ms INTEGER, + max_bytes INTEGER, + PRIMARY KEY (scope, cache_id) + ); + `); + const row = db.prepare("SELECT value FROM meta WHERE key = 'schema'").get(); + if (!row) { + db.prepare("INSERT INTO meta (key, value) VALUES ('schema', ?)").run(String(SCHEMA_VERSION)); + } else if (row.value !== String(SCHEMA_VERSION)) { + throw new Error(`Resource cache ${abs} has schema version ${row.value}; this server uses ${SCHEMA_VERSION}. Delete the file (it only holds client caches) and restart`); + } + }).immediate(); + connections.set(abs, { db, refs: 1 }); + return db; +} + +function releaseDatabase(file) { + const abs = path.resolve(file); + const c = connections.get(abs); + if (!c) { + return; + } + c.refs--; + if (c.refs <= 0) { + connections.delete(abs); + try { + c.db.close(); + } catch (e) { + // closing is best effort + } + } +} + +// The wrapper classes are loaded on first use: they pull in a good deal of the server +let wrappers = null; +function wrapperClass(resourceType) { + if (!wrappers) { + wrappers = { + CodeSystem: require('./library/codesystem').CodeSystem, + ValueSet: require('./library/valueset'), + ConceptMap: require('./library/conceptmap').ConceptMap + }; + } + return wrappers[resourceType] || null; +} + +/** + * Content hash of a resource's JSON, as the expansion cache computes it (first 16 + * hex characters of a SHA-256), so the two can share it. + * @param {string} json + * @returns {string} + */ +function contentHash(json) { + return crypto.createHash('sha256').update(json).digest('hex').substring(0, 16); +} + +// Read from the index row, without building the resource: what callers check while +// looking through the cache for the one they want (see TerminologyWorker +// findInAdditionalResources, listVersions, loadSupplements; ExpansionCache.computeKey) +const INDEX_PROPERTIES = new Set(['url', 'version', 'vurl', 'versionedUrl', 'resourceType', 'fhirType', + 'supplementsUrl', 'cacheContentHash', 'isCached', 'isGlobalSupplement']); + +/** + * A stand-in for a cached CodeSystem / ValueSet / ConceptMap that is only built + * when it is used. It is an instance of the wrapper class (instanceof works), and + * answers url, version, resourceType and the like from the index row. Touching + * anything else - jsonObj, a method, any other property - loads the JSON and builds + * the real wrapper, once; from then on everything goes to that wrapper, and methods + * run on it directly (bound), so a resource that is used costs the same as one + * built eagerly, and one that isn't costs nothing. + * + * @param {Function} Cls - the wrapper class + * @param {Object} row - index row: key, resource_type, url, version, supplements, global_supplement, hash + * @param {Function} load - () => the real wrapper (reads the JSON) + */ +function lazyResource(Cls, row, load) { + let real = null; + const bound = new Map(); + const target = Object.create(Cls.prototype); + const url = row.url === null ? undefined : row.url; + const version = row.version === null ? undefined : row.version; + const index = { + url, + version, + vurl: version ? url + '|' + version : url, + versionedUrl: version ? url + '|' + version : url, + resourceType: row.resource_type, + fhirType: row.resource_type, + supplementsUrl: row.supplements === null ? undefined : row.supplements, + cacheContentHash: row.hash, + isCached: true, + // CodeSystem.isGlobalSupplement(), worked out when it was stored (null: not known) + isGlobalSupplement: row.global_supplement === null || row.global_supplement === undefined + ? undefined : () => row.global_supplement === 1 + }; + const materialise = () => { + if (!real) { + real = load(); + } + return real; + }; + return new Proxy(target, { + get(t, prop) { + if (prop === 'cacheContentHash') { + return row.hash; + } + if (!real && INDEX_PROPERTIES.has(prop) && index[prop] !== undefined) { + return index[prop]; + } + if (!real && INDEX_PROPERTIES.has(prop) && prop !== 'isGlobalSupplement') { + return undefined; + } + const r = materialise(); + const v = Reflect.get(r, prop, r); + if (typeof v === 'function' && prop !== 'constructor') { + let b = bound.get(prop); + if (!b || b.fn !== v) { + b = { fn: v, bound: v.bind(r) }; + bound.set(prop, b); + } + return b.bound; + } + return v; + }, + set(t, prop, value) { + return Reflect.set(materialise(), prop, value); + }, + has(t, prop) { + return Reflect.has(materialise(), prop); + }, + deleteProperty(t, prop) { + return Reflect.deleteProperty(materialise(), prop); + }, + defineProperty(t, prop, desc) { + return Reflect.defineProperty(materialise(), prop, desc); + }, + ownKeys() { + return Reflect.ownKeys(materialise()); + }, + getOwnPropertyDescriptor(t, prop) { + const d = Reflect.getOwnPropertyDescriptor(materialise(), prop); + if (d) { + d.configurable = true; // a proxy may not report a non-configurable property its target lacks + } + return d; + } + }); +} + +function markCached(resource) { + if (resource && typeof resource === 'object') { + // the same non-enumerable marker the memory store sets (see ResourceCache.add) + Object.defineProperty(resource, 'isCached', { value: true, enumerable: false, configurable: true, writable: true }); + } +} + +class SqliteResourceCache extends ResourceCache { + /** + * @param {Object} stats - server stats (may be null) + * @param {Object} options + * @param {string} options.path - the SQLite file (local disk only) + * @param {string} [options.scope=''] - which endpoint's caches these are; endpoints + * share the file but not caches + * @param {number} [options.maxTombstones=1000] + * @param {number} [options.maxBytes=0] - size cap for the whole file, 0 = none + * @param {number} [options.touchIntervalMs=30000] - least time between last_used refreshes + * @param {number} [options.busyTimeoutMs=5000] + */ + constructor(stats, options = {}) { + super(stats, options.maxTombstones || 1000, { maxBytes: options.maxBytes }); + if (!options.path) { + throw new Error('SqliteResourceCache needs a path'); + } + this.path = path.resolve(options.path); + this.scope = options.scope || ''; + this.touchIntervalMs = options.touchIntervalMs >= 0 ? options.touchIntervalMs : DEFAULT_TOUCH_INTERVAL_MS; + this.db = openDatabase(this.path, options.busyTimeoutMs || DEFAULT_BUSY_TIMEOUT_MS); + this.closed = false; + this._prepare(); + } + + _prepare() { + const db = this.db; + this.q = { + session: db.prepare('SELECT * FROM sessions WHERE scope = ? AND cache_id = ?'), + sessionExists: db.prepare('SELECT 1 FROM sessions WHERE scope = ? AND cache_id = ?'), + sealed: db.prepare('SELECT sealed FROM sessions WHERE scope = ? AND cache_id = ?'), + resources: db.prepare('SELECT key, resource_type, fhir_version, kind, hash, json FROM resources WHERE scope = ? AND cache_id = ? ORDER BY id'), + // the index: everything but the content (and the content only of what isn't a wrapper) + index: db.prepare(`SELECT key, resource_type, url, version, supplements, global_supplement, fhir_version, kind, hash, + CASE WHEN kind = 'wrapper' THEN NULL ELSE json END AS json + FROM resources WHERE scope = ? AND cache_id = ? ORDER BY id`), + content: db.prepare('SELECT json, fhir_version, hash FROM resources WHERE scope = ? AND cache_id = ? AND key = ?'), + resourceHash: db.prepare('SELECT hash, concepts FROM resources WHERE scope = ? AND cache_id = ? AND key = ?'), + touch: db.prepare('UPDATE sessions SET last_used = ? WHERE scope = ? AND cache_id = ? AND last_used < ?'), + insertSession: db.prepare('INSERT INTO sessions (scope, cache_id, created_at, last_used, sealed) VALUES (?, ?, ?, ?, ?)'), + upsertResource: db.prepare(` + INSERT INTO resources (scope, cache_id, key, resource_type, url, version, supplements, global_supplement, fhir_version, kind, hash, json, bytes, concepts) + VALUES (@scope, @cacheId, @key, @resourceType, @url, @version, @supplements, @globalSupplement, @fhirVersion, @kind, @hash, @json, @bytes, @concepts) + ON CONFLICT (scope, cache_id, key) DO UPDATE SET + resource_type = excluded.resource_type, url = excluded.url, version = excluded.version, supplements = excluded.supplements, + global_supplement = excluded.global_supplement, + fhir_version = excluded.fhir_version, kind = excluded.kind, hash = excluded.hash, + json = excluded.json, bytes = excluded.bytes, concepts = excluded.concepts`), + totals: db.prepare(` + UPDATE sessions SET + concepts = (SELECT COALESCE(SUM(concepts), 0) FROM resources r WHERE r.scope = sessions.scope AND r.cache_id = sessions.cache_id), + bytes = (SELECT COALESCE(SUM(bytes), 0) FROM resources r WHERE r.scope = sessions.scope AND r.cache_id = sessions.cache_id), + resources = (SELECT COUNT(*) FROM resources r WHERE r.scope = sessions.scope AND r.cache_id = sessions.cache_id), + last_used = ?, version = version + 1 + WHERE scope = ? AND cache_id = ?`), + deleteResources: db.prepare('DELETE FROM resources WHERE scope = ? AND cache_id = ?'), + deleteSession: db.prepare('DELETE FROM sessions WHERE scope = ? AND cache_id = ?'), + tombstone: db.prepare('SELECT * FROM tombstones WHERE scope = ? AND cache_id = ?'), + insertTombstone: db.prepare(` + INSERT OR REPLACE INTO tombstones (scope, cache_id, reason, at, created_at, last_used, idle_ms, max_age_ms, max_bytes) + VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?)`), + deleteTombstone: db.prepare('DELETE FROM tombstones WHERE scope = ? AND cache_id = ?'), + trimTombstones: db.prepare(` + DELETE FROM tombstones WHERE scope = ? AND rowid NOT IN + (SELECT rowid FROM tombstones WHERE scope = ? ORDER BY rowid DESC LIMIT ?)`), + tombstoneCount: db.prepare('SELECT COUNT(*) AS n FROM tombstones WHERE scope = ?'), + expired: db.prepare('SELECT * FROM sessions WHERE scope = ? AND last_used < ?'), + allSessions: db.prepare('SELECT * FROM sessions WHERE scope = ?'), + scopeTotals: db.prepare('SELECT COUNT(*) AS n, COALESCE(SUM(concepts), 0) AS concepts, COALESCE(SUM(bytes), 0) AS bytes FROM sessions WHERE scope = ?'), + fileBytes: db.prepare('SELECT COALESCE(SUM(bytes), 0) AS bytes FROM sessions'), + lru: db.prepare('SELECT * FROM sessions WHERE NOT (scope = ? AND cache_id = ?) ORDER BY last_used, created_at LIMIT 16') + }; + } + + // ---------- reads ---------- + + status(cacheId) { + const s = this.q.session.get(this.scope, cacheId); + if (!s) { + return { exists: false }; + } + const now = Date.now(); + return { + exists: true, + sealed: !!s.sealed, + resources: s.resources, + concepts: s.concepts || 0, + idleMs: Math.max(0, now - s.last_used), + ageMs: s.created_at ? now - s.created_at : null, + timeoutMs: this.idleTimeoutMs + }; + } + + has(cacheId) { + return !!this.q.sessionExists.get(this.scope, cacheId); + } + + isSealed(cacheId) { + const s = this.q.sealed.get(this.scope, cacheId); + return s ? !!s.sealed : false; + } + + /** + * The resources held under a cache-id: a fresh set of objects every call, nothing + * shared with other requests. Wrappers are stand-ins that are only built when the + * request uses them (see lazyResource). The session row and the index are read in + * one read transaction, so a concurrent write by another process is seen entirely + * or not at all. + */ + get(cacheId) { + let session = null; + let rows = []; + this.db.transaction(() => { + session = this.q.session.get(this.scope, cacheId); + if (session) { + rows = this.q.index.all(this.scope, cacheId); + } + }).deferred(); + if (!session) { + if (this.logCacheOps) { + this.log.info(`cache-id '${cacheId}': miss (no entry)`); + } + return []; + } + this._maybeTouch(cacheId, session.last_used); + const result = rows.map(r => this._hydrate({ ...r, cacheId })); + if (this.logCacheOps) { + this.log.info(`cache-id '${cacheId}': hit, returning ${result.length} resource(s): ${rows.map(r => r.key).join(', ')}`); + } + return result; + } + + /** + * Rebuild one stored resource. Wrappers (CodeSystem / ValueSet / ConceptMap) are + * stored in their internal R5 form, so they are rebuilt as R5 and then given back + * the FHIR version they arrived in. + */ + _hydrate(row) { + if (row.kind === 'wrapper' && row.json === null) { + const Cls = wrapperClass(row.resource_type); + if (Cls) { + const cacheId = row.cacheId; + return lazyResource(Cls, row, () => this._loadWrapper(Cls, cacheId, row)); + } + } + return this._build(row); + } + + /** + * Build the real wrapper behind a stand-in. If the resource is no longer there + * (the client ended the cache, or it expired or was evicted, while this request + * was using it), the request fails the way a request on a dead cache-id does. + */ + _loadWrapper(Cls, cacheId, row) { + const c = this.q.content.get(this.scope, cacheId, row.key); + if (!c) { + const t = this.tombstone(cacheId); + throw new Issue('error', 'not-found', null, 'CACHE_ID_GONE_DURING_REQUEST', + `The cache '${cacheId}' ${t ? 'was ' + t.reason : 'went away'} while this request was using it, so ${row.key.replace(/\|/g, ' ')} is no longer available`, + 'cache-id-unknown', 404); + } + return this._build({ kind: 'wrapper', resource_type: row.resource_type, fhir_version: c.fhir_version, json: c.json }); + } + + _build(row) { + const json = JSON.parse(row.json); + let resource = json; + if (row.kind === 'wrapper') { + const Cls = wrapperClass(row.resource_type); + if (Cls) { + resource = new Cls(json, 'R5'); + resource.fhirVersion = row.fhir_version || 'R5'; + } + } + markCached(resource); + return resource; + } + + /** + * As for the memory store, except for an id with no record at all: the memory + * store's message offers a restart as one explanation, and caches here survive a + * restart, so this one doesn't (CACHE_ID_UNKNOWN_SHARED). + */ + describeMissing(cacheId) { + const d = super.describeMissing(cacheId); + return d.messageId === 'CACHE_ID_UNKNOWN' ? { ...d, messageId: 'CACHE_ID_UNKNOWN_SHARED' } : d; + } + + tombstone(cacheId) { + const t = this.q.tombstone.get(this.scope, cacheId); + if (!t) { + return null; + } + return { + reason: t.reason, + at: t.at, + createdAt: t.created_at, + lastUsed: t.last_used, + idleMs: t.idle_ms, + maxAgeMs: t.max_age_ms, + maxBytes: t.max_bytes + }; + } + + tombstoneCount() { + return this.q.tombstoneCount.get(this.scope).n; + } + + size() { + return this.q.scopeTotals.get(this.scope).n; + } + + conceptCount() { + return this.q.scopeTotals.get(this.scope).concepts; + } + + conceptCountFor(cacheId) { + const s = this.q.session.get(this.scope, cacheId); + return s ? (s.concepts || 0) : 0; + } + + /** + * Bytes held across the whole file (every endpoint): that is what maxBytes caps. + */ + byteCount() { + return this.q.fileBytes.get().bytes; + } + + // High-water marks are this process's view (what it saw after its own writes) + _trackMax() { + try { + const t = this.q.scopeTotals.get(this.scope); + if (t.concepts > this.maxConcepts) { + this.maxConcepts = t.concepts; + } + if (t.n > this.maxSizeValue) { + this.maxSizeValue = t.n; + } + } catch (e) { + // statistics only + } + } + + // ---------- writes ---------- + + /** + * Run a write transaction (BEGIN IMMEDIATE). If it fails it is tried once more; + * if that fails too, the request gets a 503 (the tx router adds Retry-After), so + * the client knows to retry rather than carrying on without its resources. + */ + _write(what, fn) { + const tx = this.db.transaction(fn); + try { + return tx.immediate(); + } catch (first) { + this.log.warn(`resource cache: ${what} failed (${first.code || first.message}); retrying once`); + try { + return tx.immediate(); + } catch (second) { + this.log.error(`resource cache: ${what} failed twice: ${second.message}`); + throw new Issue('error', 'transient', null, 'CACHE_WRITE_FAILED', + `The server could not save to its resource cache just now (${what}: ${second.code || second.message}). Nothing was changed; try the request again`, + null, 503); + } + } + } + + /** + * Refresh last_used, at most once per touchIntervalMs: a cache in steady use + * then costs reads, not a write per request. A failed refresh is ignored - the + * worst it can do is let a cache look idle up to one interval sooner. + */ + _maybeTouch(cacheId, lastUsed) { + const now = Date.now(); + if (now - lastUsed < this.touchIntervalMs) { + return; + } + try { + this.db.transaction(() => { + this.q.touch.run(now, this.scope, cacheId, now - this.touchIntervalMs); + }).immediate(); + } catch (e) { + // ignored, see above + } + } + + touch(cacheId) { + if (!this.has(cacheId)) { + return false; + } + try { + // an explicit keepalive ($cache-control?mode=check) is not throttled + const now = Date.now(); + this.db.transaction(() => { + this.q.touch.run(now, this.scope, cacheId, now); + }).immediate(); + } catch (e) { + // a failed refresh is ignored: the cache is still there + } + if (this.logCacheOps) { + this.log.info(`cache-id '${cacheId}': touched (idle clock reset)`); + } + return true; + } + + /** + * The row to store for a resource. Wrappers are stored as their (R5) jsonObj plus + * the FHIR version they came in as; anything else is stored as itself. + */ + _row(cacheId, resource) { + const isWrapper = resource && typeof resource.jsonObj === 'object' && resource.jsonObj !== null + && !!wrapperClass(resource.resourceType); + const json = JSON.stringify(isWrapper ? resource.jsonObj : resource); + return { + scope: this.scope, + cacheId, + key: this._resourceKey(resource), + resourceType: resource.resourceType || null, + url: resource.url ?? null, + version: resource.version ?? null, + supplements: isWrapper && typeof resource.jsonObj.supplements === 'string' ? resource.jsonObj.supplements : null, + globalSupplement: isWrapper && typeof resource.isGlobalSupplement === 'function' ? this._globalSupplement(resource) : null, + fhirVersion: isWrapper ? (resource.fhirVersion || 'R5') : null, + kind: isWrapper ? 'wrapper' : 'plain', + hash: contentHash(json), + json, + bytes: Buffer.byteLength(json), + concepts: this._conceptsOf(resource) + }; + } + + _globalSupplement(resource) { + try { + return resource.isGlobalSupplement() ? 1 : 0; + } catch (e) { + return null; // not known: the stand-in loads the resource to ask it + } + } + + add(cacheId, resources) { + if (!resources || resources.length === 0) return; + resources = resources.filter(r => !!r); + for (const resource of resources) { + markCached(resource); + } + // the last copy of a key wins, as it would in the memory store + const byKey = new Map(); + for (const resource of resources) { + const row = this._row(cacheId, resource); + byKey.delete(row.key); + byKey.set(row.key, row); + } + const rows = [...byKey.values()]; + + // Most requests re-send resources the cache already has, unchanged. Check + // that with reads first, so they don't take the write lock at all. + const session = this.q.session.get(this.scope, cacheId); + if (session) { + const changed = rows.some(r => { + const existing = this.q.resourceHash.get(this.scope, cacheId, r.key); + return !existing || existing.hash !== r.hash || existing.concepts !== r.concepts; + }); + if (!changed) { + this._maybeTouch(cacheId, session.last_used); + return; + } + } + + this._write('add', () => { + const now = Date.now(); + if (!this.q.sessionExists.get(this.scope, cacheId)) { + if (this.q.tombstone.get(this.scope, cacheId)) { + // Ended or expired (by another process) between the caller's check and + // now: don't bring it back from the dead. + this.log.info(`cache-id '${cacheId}': not adding ${rows.length} resource(s), the cache is gone`); + return; + } + this.q.insertSession.run(this.scope, cacheId, now, now, 0); + } + for (const row of rows) { + this.q.upsertResource.run(row); + if (this.logCacheOps) { + this.log.info(`cache-id '${cacheId}': stored ${row.key}`); + } + } + this.q.totals.run(now, this.scope, cacheId); + this._enforceMaxBytesTx(cacheId, now); + }); + this._trackMax(); + } + + set(cacheId, resources, sealed = false) { + resources = (resources || []).filter(r => !!r); + if (this.logCacheOps) { + this.log.info(`cache-id '${cacheId}': set (replace all, sealed=${!!sealed}) with ${resources.length} resource(s): ${resources.map(r => this._resourceKey(r)).join(', ')}`); + } + for (const resource of resources) { + markCached(resource); + } + const rows = resources.map(r => this._row(cacheId, r)); + this._write('start', () => { + const now = Date.now(); + const existing = this.q.session.get(this.scope, cacheId); + this.q.deleteResources.run(this.scope, cacheId); + this.q.deleteSession.run(this.scope, cacheId); + this.q.insertSession.run(this.scope, cacheId, existing ? existing.created_at : now, now, sealed ? 1 : 0); + for (const row of rows) { + this.q.upsertResource.run(row); + } + this.q.totals.run(now, this.scope, cacheId); + // alive again, so any record of an earlier death is now wrong + this.q.deleteTombstone.run(this.scope, cacheId); + this._enforceMaxBytesTx(cacheId, now); + }); + this._trackMax(); + } + + /** Move a session to the tombstones (inside a write transaction). */ + _bury(session, reason, now, extra = {}) { + this.q.insertTombstone.run(session.scope, session.cache_id, reason, now, session.created_at, session.last_used, + extra.idleMs ?? null, extra.maxAgeMs ?? null, extra.maxBytes ?? null); + this.q.deleteResources.run(session.scope, session.cache_id); + this.q.deleteSession.run(session.scope, session.cache_id); + this.q.trimTombstones.run(session.scope, session.scope, this.maxTombstones); + } + + /** + * The size cap covers the whole file (all endpoints): drop the least recently + * used caches until the file is under it. Never the cache being written. + */ + _enforceMaxBytesTx(keepId, now) { + if (!this.maxBytes) { + return; + } + let total = this.q.fileBytes.get().bytes; + while (total > this.maxBytes) { + const victims = this.q.lru.all(this.scope, keepId); + if (victims.length === 0) { + return; + } + for (const v of victims) { + if (total <= this.maxBytes) { + break; + } + const idleMs = now - v.last_used; + this._bury(v, 'evicted', now, { idleMs, maxBytes: this.maxBytes }); + total -= v.bytes; + this.log.info(`cache-id '${v.cache_id}': evicted (cache over its ${formatBytes(this.maxBytes)} cap; idle ${formatDuration(idleMs)})`); + } + } + } + + clear(cacheId) { + this._write('end', () => { + const s = this.q.session.get(this.scope, cacheId); + if (s) { + this._bury(s, 'closed', Date.now()); + if (this.logCacheOps) { + this.log.info(`cache-id '${cacheId}': closed by client after ${formatDuration(Date.now() - s.created_at)} (held ${s.resources} resource(s))`); + } + } + }); + } + + clearAll() { + this._write('clear all', () => { + const now = Date.now(); + for (const s of this.q.allSessions.all(this.scope)) { + this._bury(s, 'cleared', now); + } + }); + } + + /** + * The idle sweep. One transaction: every session idle for longer than maxAge is + * tombstoned and deleted. Idempotent, so it doesn't matter which process runs + * it, or how many do. + */ + prune(maxAge = 3600000) { + if (this.stats) { + this.stats.task('Client Cache', 'Pruning'); + } + let n = 0; + try { + this.db.transaction(() => { + const now = Date.now(); + for (const s of this.q.expired.all(this.scope, now - maxAge)) { + const idleMs = now - s.last_used; + this._bury(s, 'expired', now, { idleMs, maxAgeMs: maxAge }); + n++; + if (this.logCacheOps) { + this.log.info(`cache-id '${s.cache_id}': expired after ${formatDuration(idleMs)} idle (timeout ${formatDuration(maxAge)})`); + } + } + }).immediate(); + } catch (e) { + // the next sweep will pick them up + this.log.error(`resource cache: idle sweep failed: ${e.message}`); + } + if (this.stats) { + this.stats.taskDone('Client Cache', `Pruned ${n} of ${n + this.size()} entries`); + } + } + + close() { + if (!this.closed) { + this.closed = true; + releaseDatabase(this.path); + } + } +} + +module.exports = { SqliteResourceCache, contentHash }; diff --git a/tx/tx.js b/tx/tx.js index 09d5ec42..24700332 100644 --- a/tx/tx.js +++ b/tx/tx.js @@ -15,6 +15,8 @@ const fs = require('fs'); const Logger = require('../library/logger'); const { Library } = require('./library'); const { OperationContext, ResourceCache, ExpansionCache, debugLog} = require('./operation-context'); +const { SqliteResourceCache } = require('./resource-cache-sqlite'); +const folders = require('../library/folder-setup'); const { LanguageDefinitions } = require('../library/languages'); const { I18nSupport } = require('../library/i18nsupport'); const { CodeSystemXML } = require('./xml/codesystem-xml'); @@ -218,8 +220,16 @@ class TXModule { this.log.error(`closure: pruning failed: ${error.message}`); } }; - void prune(); // errors are logged inside - this.timers.push(setInterval(() => void prune(), 24 * 60 * 60 * 1000)); + // errors are logged inside; with several processes, one of them prunes + const backgroundJobs = require('../library/background-jobs'); + if (backgroundJobs.isLeader()) { + void prune(); + } + this.timers.push(setInterval(() => { + if (backgroundJobs.isLeader()) { + void prune(); + } + }, 24 * 60 * 60 * 1000)); } } @@ -306,7 +316,7 @@ class TXModule { path: endpointPath, fhirVersion, context: context || null, - resourceCache: new ResourceCache(this.stats), + resourceCache: this.createResourceCache(endpointPath), expansionCache: new ExpansionCache(this.stats, expansionCacheSize, expansionCacheMemoryThreshold) }; // Create the provider once for this endpoint @@ -353,6 +363,20 @@ class TXModule { this.log.info(`Expansion cache for ${endpointPath}: max ${expansionCacheSize} entries, no memory threshold`); } + // A 503 means "try again later": say when. The resource cache answers 503 when it + // can't save uploaded resources (see SqliteResourceCache._write); anything else + // that already set Retry-After keeps its own value. + router.use((req, res, next) => { + const status = res.status; + res.status = function (code) { + if (code === 503 && !this.headersSent && !this.getHeader('Retry-After')) { + this.setHeader('Retry-After', '5'); + } + return status.call(this, code); + }; + next(); + }); + // Middleware to attach provider, context, and timing to request, and wrap res.json for HTML router.use((req, res, next) => { // Increment request count @@ -1380,6 +1404,62 @@ class TXModule { return `${counts.total.toLocaleString('en-US')} requests were served${where}: ${list}.`; } + /** + * The settings for the client resource cache ($cache-control), from + * config.resourceCache: {store: "memory" | "sqlite", path, maxBytes, touchIntervalSeconds}. + * "memory" (the default) keeps each endpoint's caches in this process. "sqlite" keeps + * them in one SQLite file that every process on the machine shares - needed when + * several processes serve one port (cluster mode), since any of them may get any + * request. The file must be on a local disk, never a network filesystem. + * @returns {{store: string, path: string|null, maxBytes: number, touchIntervalMs: number}} + */ + resourceCacheSettings() { + const rc = (this.config && this.config.resourceCache) || {}; + let store = rc.store || 'memory'; + if (store !== 'memory' && store !== 'sqlite') { + throw new Error(`tx resourceCache.store '${store}' is not valid: use "memory" or "sqlite"`); + } + // In cluster mode (cluster.js sets FHIRSMITH_CLUSTER_SIZE for its workers) the memory + // store can't work - a cache-id would only be known to the worker that issued it - so + // the shared store is used whatever the setting says + let switched = false; + if (store === 'memory' && Number(process.env.FHIRSMITH_CLUSTER_SIZE) > 1) { + store = 'sqlite'; + switched = true; + } + const maxBytes = Number(rc.maxBytes) > 0 ? Number(rc.maxBytes) : 0; + const touchIntervalMs = rc.touchIntervalSeconds !== undefined ? Number(rc.touchIntervalSeconds) * 1000 : 30 * 1000; + const file = store === 'sqlite' + ? (rc.path ? path.resolve(folders.dataDir(), rc.path) : folders.filePath('resource-cache.db')) + : null; + return { store, path: file, maxBytes, touchIntervalMs, switched }; + } + + /** + * Make an endpoint's client resource cache (see resourceCacheSettings). + * @param {string} endpointPath - e.g. /r4: endpoints share the file but not caches + * @returns {ResourceCache} + */ + createResourceCache(endpointPath) { + const settings = this.resourceCacheSettings(); + if (settings.switched && !this.resourceCacheSwitchLogged) { + this.resourceCacheSwitchLogged = true; + this.log.info(`Resource cache: resourceCache.store is "memory", which only works in one process; ` + + `in cluster mode the workers share the SQLite store (${settings.path}) instead`); + } + if (settings.store === 'sqlite') { + this.log.info(`Resource cache for ${endpointPath}: shared SQLite file ${settings.path}` + + (settings.maxBytes ? `, capped at ${settings.maxBytes} bytes` : '')); + return new SqliteResourceCache(this.stats, { + path: settings.path, + scope: endpointPath, + maxBytes: settings.maxBytes, + touchIntervalMs: settings.touchIntervalMs + }); + } + return new ResourceCache(this.stats, 1000, { maxBytes: settings.maxBytes }); + } + /** * Shutdown the module */ @@ -1389,6 +1469,11 @@ class TXModule { clearInterval(timer); } this.timers = []; + for (const ep of this.endpoints || []) { + if (ep.resourceCache) { + ep.resourceCache.close(); + } + } if (this.syndicationStore) { // let an induction in progress finish, so the store isn't left with a half-copied file await this.syndicationStore.whenIdle(); diff --git a/tx/vs/vs-database.js b/tx/vs/vs-database.js index 5ebeae88..0f2dcdd4 100644 --- a/tx/vs/vs-database.js +++ b/tx/vs/vs-database.js @@ -6,6 +6,12 @@ const ValueSet = require("../library/valueset"); // Settings key written once a package cache has been fully populated (see isComplete) const CACHE_COMPLETE_KEY = 'cache-complete'; +// A counter in vsac_settings, bumped in the same transaction that records the end of a +// sync (or a resync of one value set). A process that loaded the value set list at +// generation n knows it is up to date while the counter still says n - which is how +// cluster-mode workers that don't run the sync notice that the one that does has +// finished one (see VSACValueSetProvider.catchUp) +const GENERATION_KEY = 'generation'; // Columns that can be returned directly without parsing JSON const INDEXED_COLUMNS = ['id', 'url', 'version', 'date', 'description', 'name', 'publisher', 'status', 'title']; @@ -76,6 +82,9 @@ class ValueSetDatabase { }); return (async () => { + // several server processes read this database while one writes it (cluster mode): + // WAL lets the readers carry on during a write + await all("PRAGMA journal_mode = WAL"); const cols = await all("PRAGMA table_info(valuesets)"); const hasDateFirstSeen = cols.some(c => c.name === 'date_first_seen'); const hasContentHash = cols.some(c => c.name === 'content_hash'); @@ -205,6 +214,8 @@ class ValueSetDatabase { reject(new Error(`Failed to open database for writing: ${err.message}`)); return; } + // wait for another process's write rather than failing at once + this._writeDb.configure('busyTimeout', 5000); this._migrateIfNeeded(this._writeDb).then(resolve).catch(reject); }); }); @@ -403,18 +414,58 @@ class ValueSetDatabase { * @param {number} totalFetched - Total value sets fetched * @param {number} totalNew - Number of new value sets found * @param {number} [totalUpdated=0] - Number of existing value sets whose content changed - * @returns {Promise} + * @returns {Promise} the new generation (see getGeneration) */ async finishRun(id, totalFetched, totalNew, totalUpdated = 0) { + return this._withGenerationBump( + `UPDATE vsac_runs SET finished_at = strftime('%s','now'), status = 'ok', + total_fetched = ?, total_new = ?, total_updated = ? WHERE id = ?`, + [totalFetched, totalNew, totalUpdated, id]); + } + + /** + * The generation: how many times the value sets have been changed by a sync (or a + * resync) that finished. 0 for a database no sync has finished on. One read by + * primary key. + * @returns {Promise} + */ + async getGeneration() { + const value = await this.getSetting(GENERATION_KEY); + return value === null ? 0 : Number(value); + } + + /** + * Bump the generation on its own (after writing value sets outside a sync run). + * @returns {Promise} the new generation + */ + async bumpGeneration() { + return this._withGenerationBump(null, []); + } + + /** + * Run one statement (or none) and add one to the generation, in one BEGIN IMMEDIATE + * transaction, so that a reader never sees the run recorded without the bump. + * @returns {Promise} the new generation + * @private + */ + async _withGenerationBump(sql, params) { const db = await this._getWriteConnection(); - return new Promise((resolve, reject) => { - db.run( - `UPDATE vsac_runs SET finished_at = strftime('%s','now'), status = 'ok', - total_fetched = ?, total_new = ?, total_updated = ? WHERE id = ?`, - [totalFetched, totalNew, totalUpdated, id], - err => err ? reject(err) : resolve() - ); - }); + const run = (q, p = []) => new Promise((resolve, reject) => db.run(q, p, err => err ? reject(err) : resolve())); + const get = (q, p = []) => new Promise((resolve, reject) => db.get(q, p, (err, row) => err ? reject(err) : resolve(row))); + await run('BEGIN IMMEDIATE'); + try { + if (sql) { + await run(sql, params); + } + await run(`INSERT INTO vsac_settings (key, value) VALUES (?, '1') + ON CONFLICT(key) DO UPDATE SET value = CAST(value AS INTEGER) + 1`, [GENERATION_KEY]); + const row = await get('SELECT value FROM vsac_settings WHERE key = ?', [GENERATION_KEY]); + await run('COMMIT'); + return Number(row.value); + } catch (error) { + await run('ROLLBACK').catch(() => {}); + throw error; + } } /** @@ -441,18 +492,15 @@ class ValueSetDatabase { * Record a failed VSAC sync run * @param {number} id - The run ID from startRun() * @param {string} errorMessage - The error message - * @returns {Promise} + * @returns {Promise} the new generation */ async failRun(id, errorMessage) { - const db = await this._getWriteConnection(); - return new Promise((resolve, reject) => { - db.run( - `UPDATE vsac_runs SET finished_at = strftime('%s','now'), status = 'error', - error_message = ? WHERE id = ?`, - [errorMessage, id], - err => err ? reject(err) : resolve() - ); - }); + // what the run wrote before it failed is in the database: bump the generation, so + // every process picks it up + return this._withGenerationBump( + `UPDATE vsac_runs SET finished_at = strftime('%s','now'), status = 'error', + error_message = ? WHERE id = ?`, + [errorMessage, id]); } /** diff --git a/tx/vs/vs-vsac.js b/tx/vs/vs-vsac.js index 337a3573..735f472c 100644 --- a/tx/vs/vs-vsac.js +++ b/tx/vs/vs-vsac.js @@ -5,12 +5,17 @@ const { AbstractValueSetProvider } = require('./vs-api'); const { ValueSetDatabase } = require('./vs-database'); const { VersionUtilities } = require('../../library/version-utilities'); const folders = require('../../library/folder-setup'); +const backgroundJobs = require('../../library/background-jobs'); const {debugLog} = require("../operation-context"); const { applyIdPrefix, stripIdPrefix } = require("../library/resource-ids"); // Persisted watermark for the phase-1b _lastUpdated scan. const VSAC_LAST_UPDATED_KEY = 'vsac_last_updated_date'; +// A process that doesn't run the sync looks at the database's generation (one indexed +// read) at most this often, when a request uses the value sets - see catchUp +const GENERATION_CHECK_MS = 1000; + // Canonical URL prefix for VSAC value sets, so operators can enter a bare OID. const VSAC_VALUESET_URL_PREFIX = 'http://cts.nlm.nih.gov/fhir/ValueSet/'; @@ -58,6 +63,10 @@ class VSACValueSetProvider extends AbstractValueSetProvider { this.refreshTimer = null; this.isRefreshing = false; this.lastRefresh = null; + // the database generation the map was loaded at, and when it was last compared + this.loadedGeneration = null; + this.generationCheckedAt = 0; + this.catchingUp = null; // HTTP client with authentication - manually create Basic auth header const authString = Buffer.from(`apikey:${this.apiKey}`).toString('base64'); @@ -98,7 +107,8 @@ class VSACValueSetProvider extends AbstractValueSetProvider { // connection. Just load existing data. await this._reloadMap(); } - if (this.SYNC_AT_START_UP || this.valueSetMap.size == 0) { + // With several processes, one of them syncs; the others read what it wrote + if ((this.SYNC_AT_START_UP || this.valueSetMap.size == 0) && backgroundJobs.isLeader()) { await this.refreshValueSets(); } // Start periodic refresh @@ -116,9 +126,13 @@ class VSACValueSetProvider extends AbstractValueSetProvider { } const intervalMs = this.refreshIntervalHours * 60 * 60 * 1000; + // with several processes, one of them refreshes; the others pick up what it wrote + // when they next use the value sets (catchUp), not on a timer this.refreshTimer = setInterval(async () => { try { - await this.refreshValueSets(); + if (backgroundJobs.isLeader()) { + await this.refreshValueSets(); + } } catch (error) { debugLog(error); this.log.error(error, 'Error during scheduled refresh:'); @@ -235,9 +249,6 @@ class VSACValueSetProvider extends AbstractValueSetProvider { tracking.count++; } - // Reload map with fresh data - await this._reloadMap(); - // Commit the _lastUpdated watermark only now that phase 2 has durably // written everything. Hold it back if any URL was permanently dropped, so // those URLs are re-scanned next run (never advance past un-applied @@ -255,7 +266,10 @@ class VSACValueSetProvider extends AbstractValueSetProvider { this.stats.taskDone('VSAC Sync', msg); console.log(msg); + // the run is recorded and the generation bumped in one transaction; then this process + // reloads (at the new generation), and the others see the bump when they next look await this.database.finishRun(runId, tracking.totalFetched, tracking.totalNew, tracking.totalUpdated); + await this._reloadMap(); } catch (error) { debugLog(error, 'Error during VSAC refresh:'); this.stats.taskError('VSAC Sync', `Error (${error.message})`); @@ -428,6 +442,10 @@ class VSACValueSetProvider extends AbstractValueSetProvider { * @private */ async _reloadMap() { + // the generation first: if a sync finishes while the map is loading, the map is + // recorded as older than it may be, and the next check loads it again (never the + // other way round) + const generation = await this.database.getGeneration(); const newMap = await this.database.loadAllValueSets(this.sourcePackage()); for (const vs of newMap.values()) { if (vs.jsonObj.compose) { @@ -448,6 +466,45 @@ class VSACValueSetProvider extends AbstractValueSetProvider { } // Atomic replacement of the map this.valueSetMap = newMap; + this.loadedGeneration = generation; + this.generationCheckedAt = Date.now(); + } + + /** + * Pick up value sets another process has written. Called when a request uses the value + * sets; at most once every GENERATION_CHECK_MS it reads the database's generation (one + * read by primary key), and when that differs from the generation the map was loaded at, + * reloads the map. The reload runs in the background: requests meanwhile use the map + * they have, and it is replaced in one step when the new one is ready. + * @param {boolean} [wait] - wait for the check (and any reload) to finish (tests) + * @returns {Promise} + */ + async catchUp(wait = false) { + if (!this.initialized || this.isRefreshing) { + return; + } + const now = Date.now(); + if (this.catchingUp || now - this.generationCheckedAt < GENERATION_CHECK_MS) { + if (wait && this.catchingUp) { + await this.catchingUp; + } + return; + } + this.generationCheckedAt = now; + this.catchingUp = (async () => { + const generation = await this.database.getGeneration(); + if (generation !== this.loadedGeneration) { + console.log(`VSAC: the value sets are at generation ${generation}, this process has ${this.loadedGeneration}; reloading`); + await this._reloadMap(); + } + })().catch((error) => { + debugLog(error, 'VSAC: catching up with the database failed'); + }).finally(() => { + this.catchingUp = null; + }); + if (wait) { + await this.catchingUp; + } } /** @@ -458,6 +515,7 @@ class VSACValueSetProvider extends AbstractValueSetProvider { */ async fetchValueSet(url, version) { await this.initialize(); + await this.catchUp(); this._validateFetchParams(url, version); // Try exact match first: url|version @@ -490,6 +548,7 @@ class VSACValueSetProvider extends AbstractValueSetProvider { } async fetchValueSetById(id) { + await this.catchUp(); // the map is keyed by the value set's own id (and its url); the value set itself // carries the prefixed id, which is how a url key that happens to match is excluded const vs = this.valueSetMap.get(stripIdPrefix(id, this.spaceId)); @@ -502,6 +561,7 @@ class VSACValueSetProvider extends AbstractValueSetProvider { */ async searchValueSets(searchParams, elements) { await this.initialize(); + await this.catchUp(); this._validateSearchParams(searchParams); if (searchParams.length === 0) { @@ -731,6 +791,8 @@ class VSACValueSetProvider extends AbstractValueSetProvider { async resyncValueSet(url) { const tracking = { totalFetched: 0, totalNew: 0, totalUpdated: 0, count: 0, newCount: 0 }; await this.processContentAndHistory(url, tracking, 1); + // every process, not just this one, should see it + await this.database.bumpGeneration(); await this._reloadMap(); return tracking.totalFetched; } diff --git a/tx/workers/closure.js b/tx/workers/closure.js index b2ef1fb7..809b2bfa 100644 --- a/tx/workers/closure.js +++ b/tx/workers/closure.js @@ -219,7 +219,11 @@ class ClosureWorker extends TerminologyWorker { if (!table && this.store.tableCount() >= max) { throw this.closureIssue('too-costly', 'CLOSURE_TOO_MANY_TABLES', [String(max)], 'too-costly', 422); } - table = this.store.createTable(name, config); + table = this.store.createTable(name, config, max); + if (!table) { + // another process created tables in the meantime + throw this.closureIssue('too-costly', 'CLOSURE_TOO_MANY_TABLES', [String(max)], 'too-costly', 422); + } this.log.info(`closure table '${name}' ${reset ? 'reset' : 'created'}`); if (concepts.length === 0) { return await this.buildConceptMap(name, table.version, [], fhirVersion); diff --git a/tx/workers/worker.js b/tx/workers/worker.js index 8f9f3cfd..9226913b 100644 --- a/tx/workers/worker.js +++ b/tx/workers/worker.js @@ -354,42 +354,48 @@ class TerminologyWorker { if (resource.resourceType === 'CodeSystem' && resource instanceof CodeSystem) { const cs = resource; // Check if this code system supplements the target URL - const supplementsUrl = cs.jsonObj.supplements; + // (supplementsUrl rather than jsonObj.supplements: a resource from the shared + // resource cache answers it without being loaded - see resource-cache-sqlite.js) + const supplementsUrl = cs.supplementsUrl; if (!supplementsUrl) { continue; } - // we consider either global supplements or specified supplements - if (!(cs.isGlobalSupplement() || (statedSupplements && (statedSupplements.has(cs.url) || statedSupplements.has(cs.vurl))))) { - continue; - } - if (this.hasSupplement(cs, supplements)) { - continue; - } - // Handle exact URL match (no version specified in supplements field) + // Does it supplement this code system (and version)? Checked first because it + // needs only the canonical: isGlobalSupplement() reads the whole resource, which + // for a resource from the shared resource cache means loading it. + let applies = false; if (supplementsUrl === url) { - supplements.push(cs); - continue; - } - - // Handle versioned URL (format: url|version) - if (supplementsUrl.startsWith(`${url}|`)) { + // exact URL match (no version specified in supplements field) + applies = true; + } else if (supplementsUrl.startsWith(`${url}|`)) { + // versioned URL (format: url|version) if (!version) { // No version specified in search, include all supplements for this URL - supplements.push(cs); + applies = true; } else { // Version specified, check if it matches the tail of supplements URL const supplementsVersion = supplementsUrl.substring(`${url}|`.length); // not every code system's versions are semver (SNOMED CT's are URIs, ICF's are dates): // versionMatches throws on those, so match by the version's own algorithm, as // CodeSystem.isSupplementFor does for the server's own supplements - if (supplementsVersion === version || VersionUtilities.versionMatchesByAlgorithm(supplementsVersion, version, - VersionUtilities.guessVersionAlgorithmFromVersion(version))) { - supplements.push(cs); - } + applies = supplementsVersion === version || VersionUtilities.versionMatchesByAlgorithm(supplementsVersion, version, + VersionUtilities.guessVersionAlgorithmFromVersion(version)); } } + if (!applies) { + continue; + } + + // we consider either global supplements or specified supplements + if (!(cs.isGlobalSupplement() || (statedSupplements && (statedSupplements.has(cs.url) || statedSupplements.has(cs.vurl))))) { + continue; + } + if (this.hasSupplement(cs, supplements)) { + continue; + } + supplements.push(cs); } } diff --git a/xig/xig.js b/xig/xig.js index 395b4cd8..b1b7fef5 100644 --- a/xig/xig.js +++ b/xig/xig.js @@ -19,6 +19,7 @@ const escape = require('escape-html'); const Logger = require('../library/logger'); const {describeCron} = require("../library/cron-utilities"); +const backgroundJobs = require('../library/background-jobs'); const {tokenMatches, tokenConfigured} = require('../library/request-token'); const xigLog = Logger.getInstance().child({ module: 'xig' }); @@ -2005,6 +2006,51 @@ async function loadConfigCache() { } } +// The file the open database was opened from (its inode), so a process can tell when +// another process has replaced it (see followDatabaseFile) +let xigDbInode = null; + +// how often, at most, a request looks at whether the file has been replaced +const FOLLOW_CHECK_MS = 1000; +let followCheckedAt = 0; +let followReopening = false; + +/** + * When several processes share the data directory, only one downloads the XIG + * database; it replaces the file by renaming a new one over it, so the file's inode + * is its version. The others still have the old file open, so when a request + * reaches them (at most once a second) they compare the file's inode with the one + * they opened, and if it differs open the new file. The check is one stat; the + * reopen happens in the background, and requests use the open database until then. + */ +function followDatabaseFile() { + if (!backgroundJobs.enabled || updateInProgress || followReopening) { + return; + } + const now = Date.now(); + if (now - followCheckedAt < FOLLOW_CHECK_MS) { + return; + } + followCheckedAt = now; + fs.stat(XIG_DB_PATH, (err, st) => { + if (err || !st.ino || st.ino === xigDbInode || updateInProgress || followReopening) { + return; + } + followReopening = true; + xigLog.info('XIG database file replaced by another process; reopening it'); + const reopen = () => initializeDatabase() + .catch((e) => xigLog.error('XIG database reopen failed: ' + e.message)) + .finally(() => { followReopening = false; }); + if (xigDb) { + const old = xigDb; + xigDb = null; + old.close(() => void reopen()); + } else { + void reopen(); + } + }); +} + function initializeDatabase() { return new Promise((resolve, reject) => { if (!fs.existsSync(XIG_DB_PATH)) { @@ -2012,6 +2058,11 @@ function initializeDatabase() { resolve(); return; } + try { + xigDbInode = fs.statSync(XIG_DB_PATH).ino; + } catch (e) { + xigDbInode = null; + } xigDb = new sqlite3.Database(XIG_DB_PATH, sqlite3.OPEN_READONLY, async (err) => { if (err) { @@ -2031,7 +2082,29 @@ function initializeDatabase() { }); } +/** + * Download a new XIG database and switch to it. With several processes (the nightly + * job runs in one of them, but the update page can be posted to any) only one may + * download at a time: they write the same temporary file. Another process's update in + * progress is treated like one in this process. + */ async function updateXigDatabase() { + const clusterState = require('../library/cluster-state'); + if (!clusterState.isShared()) { + return updateXigDatabaseHere(); + } + try { + return await clusterState.withLease('xig-update', () => updateXigDatabaseHere(), { timeoutMs: 1, ttlMs: 60 * 1000 }); + } catch (error) { + if (error.leaseTimeout) { + xigLog.warn('Update already in progress in another process, skipping'); + return; + } + throw error; + } +} + +async function updateXigDatabaseHere() { if (updateInProgress) { xigLog.warn('Update already in progress, skipping'); return; @@ -2132,6 +2205,11 @@ function trackRequest(req, res, next) { } router.use(trackRequest); +// with several processes: open the database file another process has downloaded +router.use((req, res, next) => { + followDatabaseFile(); + next(); +}); // Statistics functions function getDatabaseTableCounts() { @@ -3226,13 +3304,13 @@ async function initializeXigModule(stats, xigConfig) { await initializeDatabase(); - if (!fs.existsSync(XIG_DB_PATH)) { + // With several processes, one of them downloads; the others follow the file + if (!fs.existsSync(XIG_DB_PATH) && backgroundJobs.isLeader()) { xigLog.info('No existing XIG database found, triggering initial download'); setTimeout(() => { updateXigDatabase().catch((err) => xigLog.error('XIG database update failed: ' + err.message)); }, 5000); } - if (globalStats) { globalStats.addTask('XIG Download', describeCron('0 2 * * *')); } @@ -3240,6 +3318,9 @@ async function initializeXigModule(stats, xigConfig) { // Note: This assumes we're called only when XIG is enabled if (xigConfig?.autoUpdate !== false) { cron.schedule('0 2 * * *', () => { + if (!backgroundJobs.isLeader()) { + return; + } updateXigDatabase().catch((err) => xigLog.error('XIG database update failed: ' + err.message)); }); } @@ -3302,6 +3383,10 @@ function shutdown() { // Export everything module.exports = { router, + // for tests: following a file another process has replaced + _followDatabaseFile: followDatabaseFile, + _initializeDatabase: initializeDatabase, + _openedInode: () => xigDbInode, setXigSettings, updateXigDatabase, getDatabaseInfo,