diff --git a/DESIGN.md b/DESIGN.md index 53c1ac3cd7..c56bc8d749 100644 --- a/DESIGN.md +++ b/DESIGN.md @@ -887,6 +887,176 @@ schema. Per-peer failures never reject: they come back as `{status: 'failed', re in `response.replicated[]`, and `message` still reads as success (same contract as drop_schema), so operators must inspect the array for per-node outcomes. +## Root config watchers must read synchronously (`config/readConfigFileSync.ts`) + +`atomicWriteFile()` swaps the config file in with `renameSync` and, on Windows, retries the +`EPERM`/`EACCES`/`EBUSY` a still-open destination handle produces — blocking the calling thread in +`Atomics.wait`. The handle that blocks it belongs to the _process_, not to the thread that opened +it: measured on `windows-latest`/Node 24 (harper#2313), a single Node **read** descriptor on the +destination fails the rename, while `fs.watch` and chokidar's own handles do not. +`set_configuration` reaches that loop from a live request thread, and every worker runs root config +watchers over the same file, so an **async** read in a watcher is unsatisfiable by construction: +libuv opens the descriptor on the threadpool but closes it from JS, which cannot run while the same +thread is blocked in the retry loop. The worker then deadlocks against its own +watcher and burns the entire budget before failing (harper#2191, reproduced by the Windows +integration job). Both root watchers — `RootConfigWatcher.handleChange` and an `OptionsWatcher` +explicitly identified as a root-config watcher — therefore go through `readConfigFileSync()`, which +holds no descriptor across a yield. A component's own config remains asynchronous even if the +component names it `harper-config.yaml` or `harperdb-config.yaml`. Do not "modernize" root-config +reads back to `fsPromises.readFile`. + +Three constraints follow from it. The reader gates its retry to win32 (`isSharingViolation`); the +writer does not (`configUtils`' `isRetryableRenameError`, same three codes, any platform). That +asymmetry is deliberate: a misclassified read falls through to the timer ladder below and still +recovers, a rename has nothing to fall through to, and `process.platform` does not answer the +question that matters — whether this filesystem can replace an open file. A Linux worker whose +rootPath sits on WSL drvfs, a CIFS/SMB mount, or a Docker Desktop bind mount reports `linux` and +still returns these codes transiently. + +The reader's 500ms budget is one deadline **per path shared by all callers on the thread**, not per +call — a worker holds one `OptionsWatcher` per root-declared plugin (10+ on a stock install, +`TRUSTED_RESOURCE_PLUGINS`) over the same file, all reacting to a single change event, so a per-call +budget would serialize into N x 500ms of blocked event loop whenever a writer's lock outlives it. + +Both watchers parse through `parseConfigFile()` (`config/parseConfigFile.ts`) rather than calling +`yaml.parse` directly: yaml's `prettyErrors` frames the offending source lines into the error's +`message`, and the root config holds credentials, so a parse failure would otherwise ship that +frame to the component log (`OptionsWatcher` → `Scope`) or the config log. + +And a lock that outlives even that emits no new watcher event when it clears, so both watchers hand +the failure to `ConfigReadRetry` (`config/configReadRetry.ts`) rather than going stale: retrying from +a timer holds no descriptor either, so it cannot re-enter the deadlock. A ladder rung passes +`waitForLock: false` — the ladder already owns the retry, and letting each rung re-enter the +blocking budget would multiply one lock incident into a stall per rung. The ladder is bounded by +wall clock and its backoff is derived from elapsed time rather than from how many times it was +armed, because watcher callbacks and timer callbacks share one entry point: a rename burst delivers +several chokidar events in milliseconds and would otherwise both spend the ladder and push the next +rung out to the maximum before the writer has let go. + +### An empty read is a writer mid-write, not an empty config + +A non-atomic writer — an operator's editor, a shell redirect, anything that is not +`atomicWriteFile()`'s temp-file-and-rename — truncates the config before it writes it, and the +synchronous read is fast enough to land in that window where the async read never was. chokidar +throttles change events per path for 50ms and _drops_ the throttled ones, so the event carrying the +content is routinely discarded as a duplicate of the truncate's: an empty read that is discarded is +the last read that config gets, and the thread holds the pre-truncate value indefinitely +(`RootConfigWatcher`) or reports the scope as removed (`OptionsWatcher`). Both therefore hand an +empty read to `ConfigReadRetry`, the same ladder a lock takes and for the same reason — there is no +further event to re-read on. `OptionsWatcher` applies it on both read paths, not only the +synchronous one: the asynchronous read is far less likely to land in a truncate window, but the +consequence there is a spurious `remove` that tears the scope down. + +A read that _parses_ to nothing is the same event and takes the same ladder: a truncated document, +a lone `\n` and a file of nothing but comments all yield `null` from the parser rather than +throwing. `OptionsWatcher` judges that on the file's own parse, **before** `overlayRootEnvConfig`, +which returns a non-null object whenever a config env var is set — the norm in containers — and +would otherwise launder a half-written file into a valid-looking env-only config and wipe the +file's own options. + +Past the ladder the emptiness is believed, and what that costs depends on whether the scope has +settled: a worker still booting starts on the defaults, while one already running keeps the config +it has and only warns. The asymmetry is deliberate in both halves — a running worker must not let a +truncate window that outlived the ladder reset every scope, and a booting one must not hold +`Scope.ready` open waiting for a file that is genuinely empty — but it does mean an operator who +empties `harper-config.yaml` at runtime gets divergence between workers until the next restart. + +### `ready` means the watcher is armed + +`RootConfigWatcher.ready` is a startup barrier — `harper_logger`'s `updateLogSettings()` attaches +its `change` listener only after awaiting it — so it has to mean "watching", not merely "the first +read landed". The synchronous read would otherwise emit `ready` from inside chokidar's initial `add` +dispatch, and on darwin FSEvents has not armed its stream at that point: a write in that window is +dropped with no later event to recover it (the async read used to defer past it by a threadpool +round-trip, which is why this surfaced only when the read went synchronous). Measured on the +harper#2191 review head, writing that far after `ready`: 0ms is lost, 5ms and beyond is delivered. + +So `ready` is gated on chokidar's own `ready` — its initial scan has established the native +watches by then — plus a darwin-only grace over that measurement for the kernel-side warm-up +chokidar cannot observe. Neither half is sufficient alone: chokidar's event still lands inside the +warm-up, and a bare timer could elapse before the scan has created any watch. Config read before +that gate opens is staged into `#config`, re-read once the gate opens — a write that landed while +the watch was unarmed produced no event, so nothing else would ever deliver it — and then handed to +`ready` itself rather than to a `change` that would precede it. + +`OptionsWatcher` shares the gate (`ArmGate`, `config/watcherArming.ts`) because it has the same +unarmed window and, for the root config, many more of them: `componentLoader` gives every +`TRUSTED_RESOURCE_PLUGINS` entry its own root-config `OptionsWatcher`, and those read synchronously. +It shares the arming **re-read**, which is what recovers the otherwise-undeliverable write, but not +the barrier: its `ready` still goes out on the first read, so it means "the config has been read", +not "armed". The difference is only ordering, because unlike `harper_logger` its consumer (`Scope`) +attaches `change`/`remove`/`ready` listeners in its constructor, before any read — so a write made +in the unarmed window reaches the scope as a post-`ready` `change` (and, for a plugin that doesn't +handle its own options, a restart) rather than being lost. Holding `OptionsWatcher.ready` behind +arming as well would need every terminal outcome to open a second barrier, per scope, with a boot +hang as the failure mode; the ordering is not worth that. + +Whether a scope is configured is tracked separately from its value, because neither truthiness nor +`!== undefined` can answer it: `myPlugin:` with no body is a configured scope whose value is `null`, +and a boot that found no config of its own holds `DEFAULT_CONFIG[name]` — a value the watcher gave +itself. Reading either as "the file supplied this" costs a restart: for the six scopes +`DEFAULT_CONFIG` names, the next read of an unchanged file looks like the block being deleted, and +filling in an empty block looks like the unconfigured → configured transition `Scope` answers by +restarting rather than the `change` it is. + +What the arming re-read must _not_ do is report a deletion. Its job is the write no event carried; +a file that is gone is chokidar's `unlink` to report, and answering the re-read's `ENOENT` with +`remove` announces it ahead of the event that would confirm it — where there is a grace, ahead of +chokidar having finished tearing the watch down, so a config recreated on the strength of that +early `remove` lands in a window where its `add` is not observed at all and the scope keeps the +defaults with nothing further coming. Settling a barrier that has nothing applied yet is still the +arming re-read's job: an absent file at boot is the install window, not a deletion. + +### Every terminal read outcome settles the barrier + +Both barriers — `RootConfigWatcher.ready` and, through `Scope`, `OptionsWatcher.ready` — are +awaited with no timeout, so a read that ends without a config must still settle them or the worker +hangs at boot rather than failing. Every terminal outcome therefore boots on defaults and logs what +failed: a read the ladder could not complete, a file still empty when the ladder is spent, and a +file that will not parse. Only a config that parses is a config; the alternative, failing the boot +closed on an unreadable file, is a different policy than the one `OptionsWatcher` already applies to +its ENOENT and read-failure paths, and the two watchers must not disagree about it. A file that +becomes readable later still arrives, as a `change`. + +A missing file is not one of those outcomes to wait on: `ENOENT` is not a sharing violation, so +neither watcher takes the retry ladder for it. `OptionsWatcher` has always settled it at once as +the install window, and `RootConfigWatcher` does the same rather than spending the whole read +budget inside `harper_logger.start()` on every boot that has no config file — an env-var-only +deployment, or a rootPath mounted empty. Neither is a deletion an outcome to wait on. `OptionsWatcher.#handleUnlink` cancels the ladder — +the deletion settles what a pending read was retrying — so when that read had not produced a config +yet, the ladder it cancels was the only thing left to settle `ready`. Before the first `ready` there +is also nothing to remove and nothing to hear it: `Scope` is still inside `await scope.ready`, so a +`remove` there asks for a restart of a component that never booted. A deletion in the boot window +therefore settles the barrier on the defaults, exactly as the ENOENT read path does; only a deletion +after `ready` reports `remove`. A watcher error is terminal for the barrier too, and +settling it is what removes the `error` listener `once(this, 'ready')` attached — so reporting the +failure afterwards has to check for a listener rather than assume one, or an unlistened `error` +throws out of chokidar's dispatch and takes the worker down over a fault it just decided to survive. + +What a scope does about a config that arrives late is the other half of settling early. +`OptionsWatcher.ready` is not once-per-watcher: it fires whenever a scope goes from having no +config of its own to having one, which is both the recreated-config-file path and a scope that +booted while the file was unreadable. Nothing downstream re-runs on it — `componentLoader` is long +past its `await scope.ready` — so `Scope` answers a repeat `ready` the same way it answers `remove`, +by requesting a restart. Without that, one worker keeps serving the defaults while every worker +that read the file cleanly serves the operator's config. + +Arming is a terminal outcome of its own: chokidar reports a scan that found no file by emitting +`ready` and nothing else, so `RootConfigWatcher` always re-reads when the gate opens rather than +publishing what an earlier read staged — a missing config file takes the ladder and settles on the +defaults instead of holding the barrier open. That fallback must also discard the staged value: +the arming re-read is authoritative precisely because a write in the unarmed window may have +superseded it, including by replacing the file with an unusable or missing one. A watcher scan error +also settles the barrier, but preserves a successfully staged value because no read superseded it. +`close()` settles the barrier as well. + +What settles the barrier is not the same as what the settled value may be _used_ as. A read that +carried no config settles it carrying nothing — not `{}`, which is a configuration that a consumer +cannot tell apart from one the file really held, and `updateLogger` reads an absent `rotation` as +rotation off and an absent `console` as console off. `updateLogSettings()` therefore keeps what +`initLogSettings()` established until a real config arrives, rather than silently turning logging +off on the very boot that could not read its configuration. + ## Config is composed and memoized before any component runs (`config/configUtils.ts`) `getConfigObj()` composes the config once per thread (module-level memo) at its first call, which @@ -1648,30 +1818,6 @@ paths are relative to `cwd` and reads stay on the configured `component.director that degrades to polling stays there for its lifetime, so a caller with no polling story of its own (`resources/blob.ts`) needs one — there it polls `readMore` on the existing no-progress deadline. -## No descriptor on the root config may outlive a turn (`config/configUtils.ts`, `config/RootConfigWatcher.ts`, `components/OptionsWatcher.ts`) - -`atomicWriteFile` replaces `harper-config.yaml` by rename-over and retries `EPERM`/`EACCES` with a -synchronous `Atomics.wait`. On Windows a rename over an open destination fails, and a descriptor -belongs to the process, not the thread — measured on `windows-latest`/Node 24: a single Node read -descriptor on the destination blocks it, while `fs.watch` and chokidar handles do not. - -That makes the retry unable to outlast a holder on the _calling_ thread, because the sleep blocks -the event loop whose turn would close it: the holder's lifetime becomes exactly the retry budget -and every attempt fails. This is why widening the budget (#1714, #2036) never fixed the -`set_configuration` 500s it was aimed at, and why both root-config watchers read with -`readFileSync`. Any future `fsPromises.readFile` of this file reintroduces harper#2313 — the rule -is unenforced by anything but this note and the comment on `atomicWriteFile`. - -The synchronous read then sees writers mid-write, which promise-based reads mostly skipped. A read -that is unusable — empty, or parsing to anything but an object — is retried by `PartialReadRetry` -(`utility/watcherFallback.ts`) rather than adopted, because chokidar may emit nothing further for -that write. Completeness is judged on the file's own parse, _before_ `overlayRootEnvConfig`, which -returns a non-null object whenever a config env var is set and would otherwise launder a -half-written file into a valid-looking env-only config. Its three outcomes are distinct and each -one matters: a usable read withdraws the file's give-up report and restores the budget; giving up -restores the budget (the write that repairs the file can itself be read mid-write) but leaves the -report standing, since it is shared with every other watcher of that file; closing is terminal. - ## Query-plan range estimation blends statistical estimates by confidence (`search.ts`) `estimateCondition` estimates range comparators (`starts_with`/`prefix`, the `between` family, diff --git a/components/OptionsWatcher.ts b/components/OptionsWatcher.ts index 2430bced56..5633d12107 100644 --- a/components/OptionsWatcher.ts +++ b/components/OptionsWatcher.ts @@ -1,24 +1,24 @@ import { type Logger } from '../utility/logging/logger.ts'; import { loggerWithTag } from '../utility/logging/harper_logger.ts'; import { EventEmitter, once } from 'events'; -import yaml from 'yaml'; import { type FSWatcher } from 'chokidar'; import { readFile } from 'node:fs/promises'; -import { readFileSync } from 'node:fs'; import { isDeepStrictEqual } from 'util'; import { DEFAULT_CONFIG } from './DEFAULT_CONFIG.ts'; import { cloneDeep } from 'lodash'; import { POLLING_FALLBACK_OPTIONS, - PartialReadRetry, claimLostNativeWatchError, guardedWatch, - isPartialReadError, isWatcherExhaustionError, warnWatcherFallback, } from '../utility/watcherFallback.ts'; import { resolveWatchTarget } from '../utility/watchPath.ts'; import { overlayRootEnvConfig, isRootConfigFilename } from '../config/harperConfigEnvVars.ts'; +import { readConfigFileSync } from '../config/readConfigFileSync.ts'; +import { parseConfigFile } from '../config/parseConfigFile.ts'; +import { ConfigReadRetry } from '../config/configReadRetry.ts'; +import { ArmGate } from '../config/watcherArming.ts'; export interface Config { [key: string]: ConfigValue; @@ -99,13 +99,22 @@ export class OptionsWatcher extends EventEmitter { #scopedConfig?: ConfigValue; #rootConfig?: Config; #isRootConfig: boolean; + #synchronousRead: boolean; + #readRetry: ConfigReadRetry = new ConfigReadRetry(); + #armGate: ArmGate = new ArmGate(); #name: string; #logger: Logger; #usingPolling: boolean; #closed: boolean; #openCount: number = 0; + #readCount: number = 0; + #readSequence: number = 0; + #appliedSequence: number = 0; + #scopeConfigured: boolean = false; + #armAbsence?: NodeJS.Immediate; + #readyEmitted: boolean = false; + #envComposeError: unknown; #pendingReads: Set> = new Set(); - #partialRead: PartialReadRetry; ready: Promise; constructor(name: string, filePath: string, logger?: Logger, isRootConfig?: boolean) { @@ -114,11 +123,12 @@ export class OptionsWatcher extends EventEmitter { this.#filePath = filePath; const watchTarget = resolveWatchTarget(filePath); this.#watchPath = watchTarget.path; - this.#partialRead = new PartialReadRetry(filePath); // Root-config watchers must see runtime env config (HARPER_SET_CONFIG et al.) // even when it hasn't been flushed to disk yet — see #handleChange (#1618). // Application scopes watch their own config.yaml and are never overlaid. - this.#isRootConfig = isRootConfig ?? isRootConfigFilename(filePath); + const rootConfigFile = isRootConfigFilename(filePath); + this.#isRootConfig = isRootConfig ?? rootConfigFile; + this.#synchronousRead = this.#isRootConfig; this.#logger = logger || loggerWithTag(name); this.#usingPolling = watchTarget.mustPoll; this.#closed = false; @@ -127,7 +137,7 @@ export class OptionsWatcher extends EventEmitter { } #openWatcher() { - this.#openCount++; + const generation = ++this.#openCount; this.#watcher = guardedWatch(this.#watchPath, { persistent: false, ...(this.#usingPolling ? POLLING_FALLBACK_OPTIONS : {}), @@ -136,65 +146,121 @@ export class OptionsWatcher extends EventEmitter { .on('change', this.#handleChange.bind(this)) .on('error', this.#handleError.bind(this)) .on('unlink', this.#handleUnlink.bind(this)) - .on('ready', this.#handleChange.bind(this)); + // Generation-bound: `#armGate.reset()` runs before the failed watcher is closed, so a + // `ready` still queued on it would arm the gate on the replacement's behalf and the + // replacement's own `ready` would then be a no-op — leaving its scan window unre-read. + .on('ready', () => this.#handleArmed(generation)); + } + + // Every root-declared plugin gets its own root-config watcher and each reads synchronously, so + // each has the unarmed window DESIGN.md's "`ready` means the watcher is armed" describes. The + // write that lands in it is reported by no event, so only this re-read can deliver it. + #handleArmed(generation: number) { + if (this.#closed || generation !== this.#openCount) return; + this.#armGate.arm(() => this.#read(true, true)); } - // Root config only: see the descriptor-lifetime invariant on atomicWriteFile (DESIGN.md). #handleChange() { - if (this.#isRootConfig) { - this.#applyRead(() => readFileSync(this.#filePath, 'utf-8')); + this.#read(true); + } + + // While `ready` is outstanding the ladder is the only thing that can settle it, so its timer has + // to keep the thread alive; afterwards it must not, or a config file nobody is reading would + // hold a worker open. + #schedule(): boolean { + return this.#readRetry.schedule(() => this.#read(false), !this.#readyEmitted); + } + + #read(waitForLock: boolean, arming: boolean = false) { + // A queued chokidar callback can still land after close(), and by then removeAllListeners() + // has run — emitting into an EventEmitter with no 'error' listener would throw out of it. + if (this.#closed) return; + this.#readCount++; + if (this.#synchronousRead) { + try { + let contents: string; + try { + contents = readConfigFileSync(this.#filePath, waitForLock); + } catch (error) { + this.#handleReadError(error, arming); + return; + } + this.#applyContents(contents); + } catch (error) { + // A listener of what `#applyContents` emitted may have closed the watcher, after + // which `emit('error')` has no listener left and would throw out of here. + if (!this.#closed) this.#surfaceFailure(error); + } return; } + + // The `#closed` check above cannot cover the completion: close() may land while this read is + // in flight, and by then its retry state is cancelled and its listeners are gone. Nothing + // orders these against each other either — chokidar does not await one read before starting + // the next — so an older one completing last would put the file's previous contents back + // with no event left to correct it. + const sequence = ++this.#readSequence; + // `<=`, not `<`: a deletion supersedes the reads already in flight without being a read of + // its own, and says so by claiming the sequence they were issued under. + const outranked = () => this.#closed || sequence <= this.#appliedSequence; const read: Promise = readFile(this.#filePath, 'utf-8') - .then((contents) => this.#applyRead(() => contents)) - .catch((error) => this.#recoverOrReport(error)) + .then( + (contents) => { + if (outranked()) return; + this.#appliedSequence = sequence; + this.#applyContents(contents); + }, + (error) => { + if (outranked()) return; + this.#appliedSequence = sequence; + this.#handleReadError(error, arming); + } + ) + .catch((error) => { + if (!this.#closed) this.#surfaceFailure(error); + }) .finally(() => { this.#pendingReads.delete(read); }); this.#pendingReads.add(read); } - #applyRead(read: () => string) { + #applyContents(contents: string) { + // An empty read is a writer's truncate window, not an emptied config, and falling through + // would emit `remove` — see DESIGN.md, "An empty read is a writer mid-write, not an empty + // config". Both read paths can land in that window; only the synchronous one is likely to. + if (!contents) { + if (this.#schedule()) return; + // Past the ladder the file is empty rather than mid-write, and an empty file carries no + // scope: keep what is already applied instead of reading it as a removal, and settle the + // boot barrier on the defaults rather than leaving `Scope.ready` pending forever. + this.#logger.warn?.(`Configuration file ${this.#filePath} is empty.`); + this.#settleUnconfigured(); + return; + } let parsed; try { - parsed = yaml.parse(read()); + parsed = parseConfigFile(contents, this.#filePath); } catch (error) { - // A read or parse that fails while the file is being replaced is the same event as an - // incomplete one, and #handleReadError's ENOENT arm would answer it with a `remove` - // that restarts the scope. Re-read first; only an exhausted budget means it is real. - this.#recoverOrReport(error); - return; + // A prefix of the document is as much a mid-write read as an empty one, and the event + // carrying the rest is the one chokidar throttles away — same ladder, same reason. Past it + // the file really is malformed, which `#read` routes to `#surfaceFailure`. + if (!this.#closed && this.#schedule()) return; + throw error; } - // Tested on the file's own parse, before any env overlay: `''`, `'\n'` and a truncated - // document all parse to null, and an env-configured deployment would otherwise overlay - // one into a valid-looking object and adopt it. A file that is still unusable once the - // budget is spent is taken at face value, so emptying one still reaches `remove`. + // Judged on the file's own parse, before the overlay below: a truncated document, a lone + // `\n` and a file of nothing but comments all parse to `null` rather than throwing, and + // `overlayRootEnvConfig` turns any of them into a non-null object whenever a config env var + // is set — the norm in containers — so overlaying first would launder a half-written file + // into a valid-looking env-only config and wipe the file's own options. Past the ladder it + // is an empty file, which `#applyContents` already keeps rather than reads as a removal. if (!parsed || typeof parsed !== 'object') { - if (this.#partialRead.schedule(() => this.#handleChange())) return; - this.#partialRead.gaveUp(); - } else { - this.#partialRead.settled(); - } - try { - this.#applyParsed(this.#overlayEnvConfig(parsed)); - } catch (error) { - // Applying is past the point where an incomplete file could explain a failure, so a - // listener's throw keeps the error route rather than being retried. - this.emit('error', error); + if (this.#schedule()) return; + this.#logger.warn?.(`Configuration file ${this.#filePath} is empty.`); + this.#settleUnconfigured(); + return; } - } - - #recoverOrReport(error: unknown) { - if (!isPartialReadError(error)) return this.#handleReadError(error); - if (this.#partialRead.schedule(() => this.#handleChange())) return; - // Same give-up as the unusable-parse case, so the budget is restored for the repair: the - // write that fixes the file can itself be read mid-write. The error still takes the - // scope's own route. - this.#partialRead.gaveUp(error); - this.#handleReadError(error); - } - - #overlayEnvConfig(parsed: unknown) { + this.#readRetry.reset(); // The on-disk root config is not guaranteed to include runtime env config at // boot: the file flush races component loading, so a scope's boot-time reads // (e.g. an `enabled` gate in handleApplication) could observe pre-env values @@ -202,36 +268,43 @@ export class OptionsWatcher extends EventEmitter { // config onto EVERY root-config read so scope.options matches the resolved // view (#1618). Non-root scopes and the no-env-vars case are untouched // (overlayRootEnvConfig is a no-op there). - return this.#isRootConfig ? overlayRootEnvConfig(parsed) : parsed; - } - - #applyParsed(parsed: unknown) { - this.#rootConfig = parsed && typeof parsed === 'object' ? (parsed as Config) : undefined; + if (this.#isRootConfig) { + try { + parsed = overlayRootEnvConfig(parsed); + } catch (error) { + this.#envComposeError = error; + if (this.#readyEmitted) this.#reportEnvComposeFailure(); + else this.#settleUnconfigured(); + return; + } + } + this.#rootConfig = parsed && typeof parsed === 'object' ? parsed : undefined; // If the extension is in the config file if (this.#rootConfig && this.#name in this.#rootConfig) { - // If a config object does not exist - if (!this.#scopedConfig) { - // set it - this.#scopedConfig = this.#rootConfig[this.#name]; - // and emit a ready event - this.emit('ready', this.#scopedConfig); - } else { - // Otherwise, merge the new config with the old config - this.#merge(this.#rootConfig[this.#name], this.#scopedConfig); - } + this.#applyScopedConfig(this.#rootConfig[this.#name]); } else { // Otherwise, if the extension is not in the config file // This means the plugin was removed from the config file - if (this.#scopedConfig) { - // and a config exists, remove it + // Presence, not truthiness: `myPlugin:` with nothing under it is a configured scope, and + // deleting that block has to reach `Scope` as a removal like any other. + if (this.#scopeConfigured) { + this.#scopeConfigured = false; this.#scopedConfig = undefined; - this.emit('remove'); + this.#emitRemove(); + } + // The scope may be added back later, but this read is still a terminal outcome: with + // nothing ever applied, neither branch above emits, and `Scope.ready` would stay pending + // for a config that read perfectly well. The read succeeded, so only the scope falls back + // to its default — `#settleUnconfigured`'s full reset would discard the root config this + // very read produced. + if (!this.#readyEmitted) { + this.#scopedConfig = cloneDeep(DEFAULT_CONFIG[this.#name]); + this.#emitReady(this.#scopedConfig); } - // Otherwise do nothing - the user may add the config back in later } } - #handleReadError(error: unknown) { + #handleReadError(error: unknown, arming: boolean = false) { // If the config file does not exist if (error instanceof Error && 'code' in error && error.code === 'ENOENT') { // A readFile ENOENT here is the install window (file not written yet) or a @@ -241,19 +314,99 @@ export class OptionsWatcher extends EventEmitter { // through to the original ENOENT handling with #rootConfig untouched, so a // first boot still emits `ready` (not `remove`, which nothing consumes at // boot → `ready` would hang forever). + // A ladder armed by an earlier empty read is spent here, and every other terminal path + // clears its deadline; leaving it armed costs the next mid-write read its whole budget. + this.#readRetry.reset(); if (this.#applyEnvOnlyConfig()) return; // And a config already exists, reset it to the default if (this.#rootConfig) { + // The arm gate's job is the *write* that landed while the watch was unarmed, and + // answering its ENOENT with a removal reports the deletion ahead of the `unlink` + // that would confirm it — on a platform with an arming grace, ahead of chokidar + // having finished its own teardown, so a config recreated on the strength of that + // early `remove` lands where its `add` is not observed at all. It cannot simply be + // dropped either: the unarmed window is exactly where an `unlink` can go missing. + // So it goes back to the loop once, and chokidar's own `unlink` cancels it. + if (arming) { + this.#deferAbsenceCheck(); + return; + } this.#resetConfig(); - this.emit('remove'); + this.#emitRemove(); } else { // Otherwise, if no config exists, then just set to default and emit ready this.#resetConfig(); - this.emit('ready'); + this.#emitReady(); } + this.#reportEnvComposeFailure(); + return; + } + // A failure that outlives the read emits no new watcher event when it clears, so without + // this the scope would hold a stale config until the next write. Both read paths: an + // application config on SMB or under an editor's replacement returns a transient + // EBUSY/EIO just the same, and only the read for it blocks — the ladder never does. + if (!this.#closed && this.#schedule()) return; + this.#surfaceFailure(error); + } + + // A failure before anything has been applied is the boot window, where `error` alone strands the + // component: `Scope` logs it and componentLoader waits on `Scope.ready` with no timeout. Fall + // back to the defaults exactly as the ENOENT branch above does — and emit `ready` first, since + // `error` settles the `once(..., 'ready')` promises both of them await. + #surfaceFailure(error: unknown) { + this.#settleUnconfigured(); + this.#emitError(error); + } + + // Settling the barrier removes the `error` listener `once(this, 'ready')` attached, and an emit + // with none left throws the error back at the caller — here, chokidar's dispatch or a retry + // timer, where nothing can absorb it. A consumer that throws is no different. + #emitError(error: unknown) { + if (this.listenerCount('error') === 0) { + this.#logger.error?.(`The configuration for '${this.#name}' at ${this.#filePath} could not be read`, error); + return; + } + try { + this.emit('error', error); + } catch (listenerError) { + this.#logger.error?.('A configuration error listener failed', listenerError); + } + } + + #emitRemove() { + try { + this.emit('remove'); + } catch (error) { + this.#logger.error?.('A configuration removal listener failed', error); + } + } + + // `#readyEmitted`, not the config's truthiness: a scope absent from a config that read fine + // leaves `#rootConfig` set with no `ready` behind it, and a later failure would return here + // with `Scope.ready` still pending. + #settleUnconfigured() { + if (this.#readyEmitted) return; + // A file the watcher cannot use does not unset env config, exactly as on the ENOENT path + // (#1618) — but the barrier still has to settle, including when composing that env config is + // itself what failed. + if (this.#applyEnvOnlyConfig()) { + if (!this.#readyEmitted) this.#emitReady(this.#scopedConfig); return; } - this.emit('error', error); + this.#resetConfig(); + this.#emitReady(this.#scopedConfig); + this.#reportEnvComposeFailure(); + } + + #emitReady(...args: [ConfigValue?]) { + this.#readyEmitted = true; + try { + this.emit('ready', ...args); + } catch (error) { + // The failure paths emit `ready` from a ladder timer and from chokidar's error dispatch, + // where a throwing listener is an uncaught exception that takes the worker down. + this.#logger.error?.('A configuration listener failed', error); + } } #handleError(error: unknown) { @@ -267,6 +420,9 @@ export class OptionsWatcher extends EventEmitter { if (!this.#usingPolling) { warnWatcherFallback(this.#filePath); this.#usingPolling = true; + // The generation that just failed no longer speaks for the watch; the replacement arms + // on its own scan, and re-reads then as the first one did. + this.#armGate.reset(); // Start close() from a microtask, not directly here, so a synchronous throw // can't escape this 'error' listener as an uncaught exception. Promise.resolve() @@ -278,13 +434,35 @@ export class OptionsWatcher extends EventEmitter { if (!this.#closed) this.#openWatcher(); }) .catch((error) => this.#logger.error?.(`Could not reopen the ${this.#filePath} watch on polling:`, error)); + } else { + // Already polling — the replacement failed too, or the watch was polling from + // construction (`mustPoll`) and never had a fallback to take. Either way the branch + // above reopens only once, so no read will ever run: settle the barrier rather than + // leave `Scope.ready` pending forever. + this.#settleUnconfigured(); } return; } - this.emit('error', new OptionsWatcherConfigFileError(this.#filePath, error)); + // Terminal for this scope: `componentLoader` awaits `Scope.ready` with no timeout, and an + // `error` emitted while it is pending rejects that barrier instead of settling it — the + // asymmetry with `RootConfigWatcher.handleError` the boot-barrier contract cannot afford. + const watcherError = new OptionsWatcherConfigFileError(this.#filePath, error); + this.#settleUnconfigured(); + this.#emitError(watcherError); } #handleUnlink(path: string) { + // The deletion settles what a pending read was retrying, and a rung landing after this + // would find ENOENT and emit a second `remove` at consumers that treat it as teardown. + // Same for the arming re-read's deferred absence check: this is the event it was waiting on. + // Cancelling the ladder covers the rung not yet armed; a rung already in flight on the + // asynchronous path is outranked instead, or its ENOENT would report the same deletion again + // — after the settle below, as a `remove` that asks `Scope` to restart a scope that just + // booted on the defaults. + this.#readRetry.reset(); + this.#appliedSequence = this.#readSequence; + if (this.#armAbsence) clearImmediate(this.#armAbsence); + this.#armAbsence = undefined; // A real deletion still leaves env-var config in force: an env-defined scope must // survive it exactly as on the ENOENT read path — same fallback, same error routing // (#1618, #1726 review). @@ -298,43 +476,97 @@ export class OptionsWatcher extends EventEmitter { `Configuration file ${path} was deleted. Reverting to default configuration. Recreate it to restore the options watcher.` ); this.#resetConfig(); - this.emit('remove'); + // Before the first `ready` there is nothing to remove and nothing to hear it: `Scope.ready` + // is still pending, so a `remove` here asks for a restart of a scope that never booted while + // the `#readRetry.reset()` above cancelled the only thing left to settle the barrier. Same + // ruling as the ENOENT read path, which already boots on the defaults rather than reporting + // a removal `ready` would then wait behind forever. + if (this.#readyEmitted) this.#emitRemove(); + else this.#emitReady(this.#scopedConfig); + this.#reportEnvComposeFailure(); } /** * Shared fallback for the ENOENT read path and `#handleUnlink`: when config env vars - * define this scope, apply the env-only overlay (first application → `ready`; already - * configured → `merge`, never reset). Returns true when the event was handled — + * define this scope, apply the env-only overlay (first source application → `ready`; + * already configured → `merge`, never reset). Returns true when the event was handled — * including the malformed-env case, which routes to `error` like the file-read path * rather than an unhandled rejection. Returns false (root config untouched) when this * is not a root config or the env config does not provide the scope, so callers keep * their own reset semantics. */ #applyEnvOnlyConfig(): boolean { + this.#envComposeError = undefined; if (!this.#isRootConfig) return false; let composed: Config | undefined; try { composed = overlayRootEnvConfig(undefined) as Config | undefined; } catch (composeError) { - this.emit('error', composeError); - return true; + // Env config that cannot be composed is not env config: `false` puts every caller on the + // path it already takes when there is none, so the barrier still settles on the defaults + // and a deletion still emits `remove`. The failure is held for `#reportEnvComposeFailure`, + // which callers run *after* settling — an `error` emitted first settles + // `once(this, 'ready')` by rejection instead. + this.#envComposeError = composeError; + return false; } if (!composed || !(this.#name in composed)) return false; this.#rootConfig = composed; - if (!this.#scopedConfig) { - this.#scopedConfig = composed[this.#name]; - this.emit('ready', this.#scopedConfig); - } else { - this.#merge(composed[this.#name], this.#scopedConfig); - } + this.#applyScopedConfig(composed[this.#name]); return true; } + #reportEnvComposeFailure() { + if (this.#envComposeError === undefined) return; + const error = this.#envComposeError; + this.#envComposeError = undefined; + this.#emitError(error); + } + + // A scope with no source config takes `ready`, one with a prior source value takes the granular `change` + // events `#merge` derives. `ready` is emitted more than once: a scope can go back to having no + // config of its own — see `Scope.#handleOptionsWatcherReady` for what a repeat means there. + #applyScopedConfig(next: ConfigValue) { + if (!this.#scopeConfigured) { + this.#scopeConfigured = true; + this.#scopedConfig = next; + this.#emitReady(this.#scopedConfig); + return; + } + if (this.#scopedConfig) { + return this.#merge(next, this.#scopedConfig); + } + // A falsy scope value is still a configured scope — `myPlugin:` with nothing under it is + // the idiomatic "enable with defaults" — and `#merge` cannot diff from one, because + // `#setValue` needs a value to walk. Re-reading it is not a transition (every ladder rung + // and rename-burst re-read would otherwise look like one), but *filling it in* is a change + // like any other, not the unconfigured → configured `ready` that `Scope` answers with a + // restart. + if (isDeepStrictEqual(next, this.#scopedConfig)) return; + this.#scopedConfig = next; + this.#emitChange([], next); + } + + // Cloned, never aliased: `#merge` writes into `#scopedConfig` in place, so a scope that starts + // on the defaults and is then configured would otherwise write the app's values into the + // module-level `DEFAULT_CONFIG` every later reset hands out. And not configured: the six scopes + // `DEFAULT_CONFIG` names would otherwise have the next read of an unchanged file look like the + // block being deleted. #resetConfig() { - this.#rootConfig = DEFAULT_CONFIG; + this.#scopeConfigured = false; + this.#rootConfig = cloneDeep(DEFAULT_CONFIG); this.#scopedConfig = this.#rootConfig[this.#name]; } + #deferAbsenceCheck() { + if (this.#armAbsence) return; + this.#armAbsence = setImmediate(() => { + this.#armAbsence = undefined; + if (!this.#closed) this.#read(true); + }); + this.#armAbsence.unref?.(); + } + /** * This merge algorithm is best thought off as a diff and overwrite. * The new config object will completely overwrite the old config object, @@ -429,7 +661,7 @@ export class OptionsWatcher extends EventEmitter { if (keys.length === 0) { this.#scopedConfig = value; - this.emit('change', keys, value, this.#scopedConfig); + this.#emitChange(keys, value); return; } @@ -449,15 +681,19 @@ export class OptionsWatcher extends EventEmitter { obj[keys[keys.length - 1]] = value; - this.emit('change', keys, value, this.#scopedConfig); + this.#emitChange(keys, value); } - // Test-only: run the change handler directly, since the read's timing relative to its caller - // is the behaviour under test and a chokidar event cannot be observed at that granularity. - // Resolves once the read has landed, which for the root config has already happened. - _handleChangeForTests(): Promise { - this.#handleChange(); - return Promise.allSettled([...this.#pendingReads]); + // `#merge` runs inside chokidar's own dispatch on the unlink and env-fallback paths, where a + // plugin's `change` handler throwing would leave the worker with an uncaught exception on a + // config event the watcher had just decided to survive. It still reaches consumers as `error` + // — a listener fault is not a read fault, which is why it must not reach `#handleReadError`. + #emitChange(keys: string[], value: ConfigValue) { + try { + this.emit('change', keys, value, this.#scopedConfig); + } catch (error) { + this.#emitError(error); + } } // Test-only: simulate the underlying chokidar watcher emitting an error. @@ -467,26 +703,44 @@ export class OptionsWatcher extends EventEmitter { this.#handleError(error); } - // Test-only: whether the watcher has fallen back to polling. get _usingPollingForTests(): boolean { return this.#usingPolling; } - // Test-only: number of times the underlying watcher has been (re)opened. - // Used to assert that a close()-during-fallback race didn't install a - // replacement watcher. + // Used to assert that a close()-during-fallback race didn't install a replacement watcher. get _openCountForTests(): number { return this.#openCount; } + // Distinguishes a ladder rung from a watcher event. + get _readCountForTests(): number { + return this.#readCount; + } + + get _armedForTests(): boolean { + return this.#armGate.armed; + } + + // Test-only: read now, rather than at whatever granularity a chokidar event would arrive. + _refreshForTests(arming: boolean = false): Promise { + this.#read(true, arming); + return Promise.allSettled([...this.#pendingReads]); + } + /** * Closes the underlying file watcher and drains any pending config-file reads. * Emits `close` synchronously, removes all listeners, then returns a Promise that * resolves once the chokidar watcher has fully stopped and all in-flight reads settle. */ close(): Promise { + // Terminal like every other outcome, and `Scope.ready` has no timeout. Before `#closed` and + // through `#emitReady`, so a listener that throws cannot skip the teardown below it. + this.#settleUnconfigured(); this.#closed = true; - this.#partialRead.cancel(); + this.#readRetry.cancel(); + this.#armGate.cancel(); + if (this.#armAbsence) clearImmediate(this.#armAbsence); + this.#armAbsence = undefined; const pendingReads = [...this.#pendingReads]; const watcherClose = Promise.resolve(this.#watcher.close()).catch(() => {}); diff --git a/components/Scope.ts b/components/Scope.ts index dcf998d86f..ea3a3737f1 100644 --- a/components/Scope.ts +++ b/components/Scope.ts @@ -69,6 +69,7 @@ export class Scope extends EventEmitter { #deployEndHandler: (name: string) => void; #deployInFlight: boolean = false; #restartRequestedDuringDeploy: boolean = false; + #optionsReady: boolean = false; applicationScope?: ApplicationScope; options: OptionsWatcher; @@ -253,7 +254,21 @@ export class Scope extends EventEmitter { // We could make the user call `await scope.ready()` in their `handleApplication` function, but that could lead to the same issue and it'd // be harder for the user to understand why. + // A second `ready` means the scope had no config of its own and now does — a config file + // that was unreadable when this worker booted, or one recreated after deletion. Re-emitting + // reaches nobody: componentLoader is long past its `await scope.ready`, so the component is + // running on the defaults until something restarts it. Same recovery as the `remove` + // listener, and the same convention — a plugin with its own `ready` handler owns it. + const started = this.#optionsReady; + this.#optionsReady = true; + const restartNeeded = started && this.listenerCount('ready') === 0; + this.emit('ready'); + + if (restartNeeded) { + this.#logger.debug?.('Options arrived after the scope started, requesting restart'); + this.requestRestart(); + } } #handleError(error: unknown): void { diff --git a/config/RootConfigWatcher.ts b/config/RootConfigWatcher.ts index d440ea08a8..c9b3e933f4 100644 --- a/config/RootConfigWatcher.ts +++ b/config/RootConfigWatcher.ts @@ -1,19 +1,30 @@ import { FSWatcher } from 'chokidar'; -import { readFileSync } from 'node:fs'; import { getConfigFilePath } from './configUtils.ts'; +import { readConfigFileSync } from './readConfigFileSync.ts'; import { EventEmitter, once } from 'node:events'; -import { parse } from 'yaml'; +import { parseConfigFile } from './parseConfigFile.ts'; import { POLLING_FALLBACK_OPTIONS, - PartialReadRetry, claimLostNativeWatchError, guardedWatch, - isPartialReadError, isWatcherExhaustionError, warnWatcherFallback, - warnWatcherListenerError, } from '../utility/watcherFallback.ts'; import { resolveWatchTarget } from '../utility/watchPath.ts'; +import { errorForLog, loggerWithTag } from '../utility/logging/harper_logger.ts'; +import { ConfigReadRetry } from './configReadRetry.ts'; +import { ArmGate } from './watcherArming.ts'; + +function isMissingFile(error: unknown): boolean { + return !!error && typeof error === 'object' && (error as NodeJS.ErrnoException).code === 'ENOENT'; +} + +// `harper_logger` imports this module at its own bottom to break their cycle, so a tagged logger +// built at module scope would run `loggerWithTag()` before `mainLogger` is initialized. +let taggedLogger: ReturnType | undefined; +function logger() { + return (taggedLogger ??= loggerWithTag('config-watcher')); +} export class RootConfigWatcher extends EventEmitter { #configFilePath: string; @@ -23,7 +34,15 @@ export class RootConfigWatcher extends EventEmitter { #usingPolling: boolean; #closed: boolean; #openCount: number = 0; - #partialRead: PartialReadRetry; + #readCount: number = 0; + #readRetry: ConfigReadRetry = new ConfigReadRetry(); + #armGate: ArmGate = new ArmGate(); + // The gate above is chokidar's scan finishing; this is the barrier's gate. A terminal outcome + // opens it without claiming the watch is armed, so the arming re-read still runs afterwards. + #barrierOpen: boolean = false; + #configLoaded: boolean = false; + #readyStaged: boolean = false; + #readyEmitted: boolean = false; ready: Promise; constructor() { @@ -31,7 +50,6 @@ export class RootConfigWatcher extends EventEmitter { this.#configFilePath = getConfigFilePath(); const watchTarget = resolveWatchTarget(this.#configFilePath); this.#watchPath = watchTarget.path; - this.#partialRead = new PartialReadRetry(this.#configFilePath); this.#usingPolling = watchTarget.mustPoll; this.#closed = false; this.ready = once(this, 'ready'); @@ -39,14 +57,57 @@ export class RootConfigWatcher extends EventEmitter { } #openWatcher() { - this.#openCount++; + const generation = ++this.#openCount; this.#watcher = guardedWatch(this.#watchPath, { persistent: false, ...(this.#usingPolling ? POLLING_FALLBACK_OPTIONS : {}), }) .on('add', this.handleChange.bind(this)) .on('change', this.handleChange.bind(this)) - .on('error', this.handleError.bind(this)); + .on('error', this.handleError.bind(this)) + // Generation-bound: `#armGate.reset()` runs before the failed watcher is closed, so a + // `ready` still queued on it would arm the gate on the replacement's behalf and the + // replacement's own `ready` would then be a no-op — leaving its scan window unre-read. + .on('ready', () => this.#handleArmed(generation)); + } + + #handleArmed(generation: number) { + if (this.#closed || generation !== this.#openCount) return; + this.#armGate.arm(() => this.#markArmed()); + } + + #markArmed() { + this.#barrierOpen = true; + // A write that landed while the watch was unarmed was never reported, and a scan that found + // no file at all reported nothing either, so arming always re-reads rather than publishing + // what an earlier read staged — or, with no file, staying pending forever. + this.#read(true); + // A read that armed the ladder settles `ready` itself, with the newer config. + if (!this.#readRetry.pending) this.#emitReady(); + } + + #emitReady() { + if (this.#readyEmitted || !this.#barrierOpen || !this.#readyStaged || this.#closed) return; + this.#readyEmitted = true; + try { + this.emit('ready', this.#config); + } catch (error) { + logger().warn('A Harper configuration listener failed', errorForLog(error)); + } + } + + // `harper_logger.start()` awaits `ready` with no timeout, so every terminal outcome has to + // settle the barrier. A failed read discards an earlier staged value, but a watcher error keeps + // it because no later read superseded it. No config is represented by `undefined`, not `{}`: + // an empty object is a configuration that turns logging off. + #stageBootFallback(discardStaged = true) { + if (this.#readyEmitted) return; + if (discardStaged) { + this.#config = undefined; + this.#configLoaded = false; + } + this.#readyStaged = true; + this.#emitReady(); } // Test-only: simulate the underlying chokidar watcher emitting an error. @@ -56,17 +117,26 @@ export class RootConfigWatcher extends EventEmitter { this.handleError(error); } - // Test-only: whether the watcher has fallen back to polling. get _usingPollingForTests(): boolean { return this.#usingPolling; } - // Test-only: number of times the underlying watcher has been (re)opened. get _openCountForTests(): number { return this.#openCount; } + // Distinguishes a ladder rung from a watcher event. + get _readCountForTests(): number { + return this.#readCount; + } + + get _armedForTests(): boolean { + return this.#armGate.armed; + } + handleError(error: unknown) { + // A queued chokidar error can land after close(), which has dropped every listener. + if (this.#closed) return; // See EntryHandler.#handleWatcherError: a lost native watch handle is benign // and must not be surfaced to consumers as a config-watch failure. if (claimLostNativeWatchError(error)) return; @@ -77,6 +147,9 @@ export class RootConfigWatcher extends EventEmitter { if (!this.#usingPolling) { warnWatcherFallback(this.#configFilePath); this.#usingPolling = true; + // The generation that just failed no longer speaks for the watch; the replacement + // arms on its own scan, and re-reads then as the first one did. + this.#armGate.reset(); // Start close() from a microtask, not directly here, so a synchronous throw // can't escape this 'error' listener as an uncaught exception. Promise.resolve() @@ -87,55 +160,136 @@ export class RootConfigWatcher extends EventEmitter { .then(() => { if (!this.#closed) this.#openWatcher(); }) - .catch((error) => console.error(`Could not reopen the ${this.#configFilePath} watch on polling:`, error)); + .catch((error) => + logger().warn(`Could not reopen the ${this.#configFilePath} watch on polling`, errorForLog(error)) + ); + } else { + // Already polling — the replacement failed too, or the watch was polling from + // construction (`mustPoll`) and never had a fallback to take. Either way the branch + // above reopens only once, so this is the watch's terminal outcome and the barrier + // has to settle or `harper_logger.start()` awaits it forever. + this.#barrierOpen = true; + this.#stageBootFallback(false); } return; } - this.emit('error', error); + // chokidar may never reach its own `ready` after a scan error, and nothing else would + // settle the barrier: the error is this read's terminal outcome. The scan is not over + // though, so the arm gate stays closed and a later `ready` still takes the arming re-read. + this.#barrierOpen = true; + this.#stageBootFallback(false); + // Settling the barrier removed the `error` listener `once(this, 'ready')` attached, and an + // emit with none left throws the error back into chokidar's dispatch — as does a consumer + // that throws from its own handler. + if (this.listenerCount('error') === 0) { + logger().warn(`The Harper configuration watcher at ${this.#configFilePath} failed`, errorForLog(error)); + return; + } + try { + this.emit('error', error); + } catch (listenerError) { + logger().warn('A Harper configuration error listener failed', errorForLog(listenerError)); + } } - // See the descriptor-lifetime invariant on atomicWriteFile (DESIGN.md). handleChange() { + this.#read(true); + } + + // `harper_logger.start()` awaits `ready` with no timeout and the ladder may be the only thing + // left to settle it, so until then its timer keeps the thread alive rather than letting it + // drain and exit mid-boot. + #schedule(): boolean { + return this.#readRetry.schedule(() => this.#read(false), !this.#readyEmitted); + } + + #read(waitForLock: boolean) { + // A queued chokidar callback can still land after close(), which has already discarded the + // config and dropped every listener. + if (this.#closed) return; + this.#readCount++; + let data: string; + try { + data = readConfigFileSync(this.#configFilePath, waitForLock); + } catch (error) { + // A missing file is not a lock — `readConfigFileSync` does not retry it either, and + // `OptionsWatcher` settles it immediately as the install window. Taking the ladder here + // would disagree with that and cost `harper_logger.start()` the whole budget on every + // boot that has no config file (an env-var-only deployment, an empty mounted rootPath). + if (!isMissingFile(error) && this.#schedule()) return; + // A ladder armed by an earlier empty read is spent by the time a rung lands on ENOENT, + // and every other terminal path clears its deadline. + this.#readRetry.reset(); + logger().warn( + `Unable to read the Harper configuration file at ${this.#configFilePath}` + + (this.#configLoaded ? ', continuing with the previously loaded configuration' : '; none has been loaded yet'), + errorForLog(error) + ); + this.#stageBootFallback(); + return; + } + // See DESIGN.md, "An empty read is a writer mid-write, not an empty config". + if (!data) { + if (this.#schedule()) return; + logger().warn(`The Harper configuration file at ${this.#configFilePath} is empty`); + this.#stageBootFallback(); + return; + } let config; - // Only the read and parse are guarded: a listener that throws must not be mistaken for a - // half-written file and replayed. try { - config = parse(readFileSync(this.#configFilePath, 'utf-8')); + config = parseConfigFile(data, this.#configFilePath); } catch (error) { - // A missing file needs no re-read; anything else may be the file being replaced. - if (isPartialReadError(error)) this.#scheduleReread(error); + // A read taken mid-write is untrustworthy, not only an empty one: the writer's first + // `write(2)` can land a prefix of the document, and the event carrying the rest is the one + // chokidar throttles away. So an unparseable read rides out the same ladder as an empty + // one, and only a read that parses releases it. + if (this.#schedule()) return; + logger().warn((error as Error).message); + this.#stageBootFallback(); return; } - // A snapshot that does not parse to an object is the other shape a half-written file - // takes: `''`, `'\n'` and a truncated document all yield null, and adopting that would - // hand every consumer a config with nothing in it. + // The third shape a mid-write read takes, and the only one that parses: a truncated + // document, a lone `\n`, a file that is nothing but comments all yield `null` rather than + // throwing, and adopting one hands every consumer a config with nothing in it. Same ladder + // as the two above, and past it the file is empty rather than mid-write. if (!config || typeof config !== 'object') { - this.#scheduleReread(); + if (this.#schedule()) return; + logger().warn(`The Harper configuration file at ${this.#configFilePath} is empty`); + this.#stageBootFallback(); + return; + } + this.#readRetry.reset(); + + // Before `ready` goes out there is no prior state to have changed *since*. + this.#configLoaded = true; + this.#readyStaged = true; + if (!this.#readyEmitted) { + this.#config = config; + this.#emitReady(); return; } - this.#partialRead.settled(); try { - if (!this.#config) { - this.#config = config; - this.emit('ready', this.#config); - return; - } this.emit('change', (this.#config = config)); } catch (error) { - warnWatcherListenerError(this.#configFilePath, error); + logger().warn('A Harper configuration change listener failed', errorForLog(error)); } } - #scheduleReread(error?: unknown) { - if (this.#partialRead.schedule(() => this.handleChange())) return; - this.#partialRead.gaveUp(error); - } - close() { + // Closing is a terminal outcome too: leaving `ready` pending would hang anything still + // awaiting the barrier. Through `#emitReady`, so a listener that throws cannot skip the + // teardown below it and leave the watcher and its arm timer running. + this.#barrierOpen = true; + this.#readyStaged = true; + this.#emitReady(); this.#closed = true; - this.#partialRead.cancel(); - this.#watcher.close(); + this.#readRetry.cancel(); + this.#armGate.cancel(); + // chokidar's close() is a promise; an unhandled teardown rejection would reach Node as one, + // on the path whose whole job is to stop caring about this watcher. Same shape as the + // exhaustion-recovery close above, and as `OptionsWatcher.close`. + Promise.resolve(this.#watcher.close()).catch(() => {}); this.#config = undefined; this.emit('close'); this.removeAllListeners(); diff --git a/config/configReadRetry.ts b/config/configReadRetry.ts new file mode 100644 index 0000000000..3200292c56 --- /dev/null +++ b/config/configReadRetry.ts @@ -0,0 +1,45 @@ +// Why a lock that outlives the reader's budget is retried from a timer, and why both the bound and +// the backoff are wall clock rather than an attempt count: see "Root config watchers must read +// synchronously" in DESIGN.md (harper#2191). +const RETRY_BUDGET_MS = 3_100; +const INITIAL_DELAY_MS = 100; +const MAX_DELAY_MS = 1_600; + +export class ConfigReadRetry { + #timer?: NodeJS.Timeout; + #deadline?: number; + + // `holdEventLoop` is for a caller whose boot barrier this ladder is the only thing left to + // settle: an unref'd timer would let the thread drain and exit mid-boot instead. + schedule(retry: () => void, holdEventLoop: boolean = false): boolean { + this.cancel(); + const now = performance.now(); + this.#deadline ??= now + RETRY_BUDGET_MS; + const remainingMs = this.#deadline - now; + if (remainingMs <= 0) { + this.reset(); + return false; + } + const elapsedMs = RETRY_BUDGET_MS - remainingMs; + const delayMs = Math.min(Math.max(elapsedMs, INITIAL_DELAY_MS), MAX_DELAY_MS, remainingMs); + this.#timer = setTimeout(retry, delayMs); + if (!holdEventLoop) this.#timer.unref(); + return true; + } + + get pending(): boolean { + return this.#timer !== undefined; + } + + reset(): void { + this.cancel(); + this.#deadline = undefined; + } + + cancel(): void { + if (this.#timer) { + clearTimeout(this.#timer); + this.#timer = undefined; + } + } +} diff --git a/config/configUtils.ts b/config/configUtils.ts index 6257d3f108..3c4ee8cc74 100644 --- a/config/configUtils.ts +++ b/config/configUtils.ts @@ -87,22 +87,56 @@ export function getConfigPath(param: string) { return path.resolve(rootPath, value); } -// Write atomically via temp file + rename so readers don't observe a truncated/empty file. -// Temp path includes randomness so two worker threads in the same process (same pid) writing -// in the same millisecond can't collide on the temp name and then race the rename. -// +// Write atomically via a randomized temp file + rename so readers do not observe partial content +// and concurrent workers, which share process.pid, do not collide on a temp path. // Windows has no POSIX-style "replace an open file" semantics: rename() fails with -// EPERM/EACCES while another descriptor is open on the destination. The sleep below blocks the -// calling thread, so this can only ride out a holder that releases without needing that -// thread's event loop. A holder on the calling thread would live exactly as long as the budget, -// which is why config readers must not keep a descriptor on this file open across an event-loop -// turn (RootConfigWatcher.handleChange, OptionsWatcher#handleChange). -const RENAME_RETRY_MAX_ATTEMPTS = 12; +// EPERM/EACCES/EBUSY while another worker or AV holds the destination open. Root config watchers use +// readConfigFileSync so this blocking retry cannot wait on a read owned by its own worker. +// The budget is the wall-clock window of the 12-attempt schedule it replaced +// (10+20+40+80+160+320+500*6), so it stays a deadline rather than an attempt count without +// widening the stall: this loop blocks the calling worker's event loop, and `set_configuration` +// reaches it from a live request thread. +const RENAME_RETRY_BUDGET_MS = 3_630; +// Secondary guard only: stops a degenerate zero-delay option set from spinning the whole budget. +const RENAME_RETRY_MAX_ATTEMPTS = 25; const RENAME_RETRY_INITIAL_DELAY_MS = 10; const RENAME_RETRY_MAX_DELAY_MS = 500; -// Never notified; exists only so Atomics.wait can time out (a synchronous, CPU-idle sleep). +// Never notified; Atomics.wait uses this only as a CPU-idle synchronous sleep. const renameRetrySleepBuffer = new Int32Array(new SharedArrayBuffer(4)); +// Classified by code alone rather than gated to win32 like the read side: `process.platform` does +// not answer whether this filesystem can replace an open file — WSL drvfs, CIFS/SMB and Docker +// Desktop bind mounts all report `linux` and return these codes transiently. +function isRetryableRenameError(code: string): boolean { + return code === 'EPERM' || code === 'EACCES' || code === 'EBUSY'; +} + +type RenameRetryOptions = { + retryBudgetMs?: number; + maxRetries?: number; + initialDelayMs?: number; + maxDelayMs?: number; +}; + +type AtomicWriteOptions = RenameRetryOptions & { + skipIfUnchanged?: boolean; +}; + +function validateRenameRetryOptions({ retryBudgetMs, maxRetries, initialDelayMs, maxDelayMs }: RenameRetryOptions) { + const invalidOption = + !Number.isFinite(retryBudgetMs) || + retryBudgetMs < 0 || + (!Number.isFinite(maxRetries) && maxRetries !== Infinity) || + maxRetries < 0 || + !Number.isFinite(initialDelayMs) || + initialDelayMs < 0 || + !Number.isFinite(maxDelayMs) || + maxDelayMs < 0; + if (invalidOption) { + throw new RangeError('rename retry options must be non-negative numbers'); + } +} + // Linux has no libuv mapping for EDQUOT, so a quota-exhausted write surfaces as // `Unknown system error -122` with an unusable `code`; the numeric errno is the portable signal // (EDQUOT is 122 on Linux, 69 on macOS). @@ -137,12 +171,15 @@ export function atomicWriteFile( filePath, content, { + retryBudgetMs = RENAME_RETRY_BUDGET_MS, maxRetries = RENAME_RETRY_MAX_ATTEMPTS, initialDelayMs = RENAME_RETRY_INITIAL_DELAY_MS, maxDelayMs = RENAME_RETRY_MAX_DELAY_MS, skipIfUnchanged = false, - } = {} + }: AtomicWriteOptions = {} ) { + // Before the temp write, so an option set that can never rename leaves no file behind. + validateRenameRetryOptions({ retryBudgetMs, maxRetries, initialDelayMs, maxDelayMs }); // Opt-in: skipping means no mtime bump, so no watcher event. Only callers that re-derive the // same file every boot want that. if (skipIfUnchanged && matchesFileContent(filePath, content)) return false; @@ -155,8 +192,10 @@ export function atomicWriteFile( throw err; } try { - renameWithRetry(tempPath, filePath, { maxRetries, initialDelayMs, maxDelayMs }); + renameWithRetry(tempPath, filePath, { retryBudgetMs, maxRetries, initialDelayMs, maxDelayMs }); } catch (err) { + // The temp name carries fresh randomness on every call, so a spent budget would otherwise + // leave a file nothing else will ever collect. removeTempFile(tempPath); throw err; } @@ -167,35 +206,48 @@ export function renameWithRetry( fromPath, toPath, { + retryBudgetMs = RENAME_RETRY_BUDGET_MS, maxRetries = RENAME_RETRY_MAX_ATTEMPTS, initialDelayMs = RENAME_RETRY_INITIAL_DELAY_MS, maxDelayMs = RENAME_RETRY_MAX_DELAY_MS, - } = {} + }: RenameRetryOptions = {} ) { + validateRenameRetryOptions({ retryBudgetMs, maxRetries, initialDelayMs, maxDelayMs }); let retries = maxRetries; let delayMs = initialDelayMs; + let retryDeadline; + let finalAttempt = false; let attempts = 0; - const startedAt = Date.now(); + const startedAt = performance.now(); while (true) { try { attempts++; fs.renameSync(fromPath, toPath); return; } catch (err) { - if (retries > 0 && (err.code === 'EPERM' || err.code === 'EACCES')) { + if (!finalAttempt && retries > 0 && isRetryableRenameError(err.code)) { retries--; - // Sleep synchronously (all call sites are sync) to allow the holder to close the - // file. Atomics.wait yields the thread to the OS instead of spinning the CPU, - // which is what makes a multi-second worst-case budget affordable. - if (delayMs > 0) Atomics.wait(renameRetrySleepBuffer, 0, 0, delayMs); - delayMs = Math.min(delayMs * 2, maxDelayMs); - continue; + if (retryDeadline === undefined) { + retryDeadline = performance.now() + retryBudgetMs; + } + const remainingBudgetMs = retryDeadline - performance.now(); + if (remainingBudgetMs > 0) { + // Sleep synchronously (all call sites are sync) to allow the holder to close the + // file. Atomics.wait yields the thread to the OS instead of spinning the CPU, + // which is what makes a multi-second worst-case budget affordable. + const sleepMs = Math.min(delayMs, remainingBudgetMs); + finalAttempt = sleepMs === remainingBudgetMs; + if (sleepMs > 0) Atomics.wait(renameRetrySleepBuffer, 0, 0, sleepMs); + delayMs = Math.min(Math.max(delayMs * 2, RENAME_RETRY_INITIAL_DELAY_MS), maxDelayMs); + continue; + } } - // Attempts and elapsed distinguish a holder that never released from one that lost - // a race, and neither survives on the rethrown error. - if (err.code === 'EPERM' || err.code === 'EACCES') { + // Whether the budget was spent or the code was never retryable is the difference + // between a holder that never released and a one-off failure, and neither survives on + // the rethrown error. + if (isRetryableRenameError(err.code)) { logger.warn( - `Could not replace ${toPath}: ${err.code} after ${attempts} attempts over ${Date.now() - startedAt}ms` + `Could not replace ${toPath}: ${err.code} after ${attempts} attempts over ${Math.round(performance.now() - startedAt)}ms` ); } throw err; diff --git a/config/parseConfigFile.ts b/config/parseConfigFile.ts new file mode 100644 index 0000000000..47ab0dedc9 --- /dev/null +++ b/config/parseConfigFile.ts @@ -0,0 +1,34 @@ +import { parse } from 'yaml'; + +// yaml's prettyErrors frames the offending source lines into `message`, and a config file holds +// credentials. Neither the cause nor the original stack is carried for the same reason. +export class ConfigParseError extends Error { + constructor(filePath: string, error: unknown) { + const { name, code, linePos } = (error ?? {}) as { + name?: string; + code?: string; + linePos?: { line: number; col: number }[]; + }; + const at = linePos?.[0] ? ` at line ${linePos[0].line}, column ${linePos[0].col}` : ''; + super(`Unable to parse the Harper configuration file at ${filePath}: ${code ?? name ?? 'parse failure'}${at}`); + this.name = 'ConfigParseError'; + } +} + +export function parseConfigFile(contents: string, filePath: string): any { + try { + // yaml routes warnings through `process.emitWarning` rather than a throw, so a framed + // warning would reach stderr with the config's own source lines in it, around this scrub. + return parse(contents, { logLevel: 'error' }); + } catch (error) { + // Only yaml's own parse errors frame the source into `message`. Anything else is a fault in + // the parser, where the message is the whole of the debugging context. + if (!isYamlParseError(error)) throw error; + throw new ConfigParseError(filePath, error); + } +} + +function isYamlParseError(error: unknown): boolean { + const { name, linePos } = (error ?? {}) as { name?: string; linePos?: unknown }; + return linePos !== undefined || name === 'YAMLParseError'; +} diff --git a/config/readConfigFileSync.ts b/config/readConfigFileSync.ts new file mode 100644 index 0000000000..e1841a71a6 --- /dev/null +++ b/config/readConfigFileSync.ts @@ -0,0 +1,44 @@ +import { readFileSync } from 'node:fs'; + +// Why root config reads must not be async, and why this budget is shared rather than per call: +// see "Root config watchers must read synchronously" in DESIGN.md (harper#2191). +const READ_RETRY_BUDGET_MS = 500; +const READ_RETRY_INITIAL_DELAY_MS = 10; +const READ_RETRY_MAX_DELAY_MS = 100; +const readRetrySleepBuffer = new Int32Array(new SharedArrayBuffer(4)); +const retryDeadlines = new Map(); + +// A caller that already owns a retry ladder passes `waitForLock` false, so one lock costs one +// blocking window in total rather than one per rung. +export function readConfigFileSync(filePath: string, waitForLock: boolean = true): string { + let delayMs = READ_RETRY_INITIAL_DELAY_MS; + while (true) { + try { + const contents = readFileSync(filePath, 'utf-8'); + retryDeadlines.delete(filePath); + return contents; + } catch (error) { + const remainingBudgetMs = waitForLock && isSharingViolation(error) ? remainingRetryBudgetMs(filePath) : 0; + if (remainingBudgetMs <= 0) throw error; + Atomics.wait(readRetrySleepBuffer, 0, 0, Math.min(delayMs, remainingBudgetMs)); + delayMs = Math.min(delayMs * 2, READ_RETRY_MAX_DELAY_MS); + } + } +} + +function isSharingViolation(error: unknown): boolean { + if (process.platform !== 'win32') return false; + const code = (error as { code?: string } | null)?.code; + return code === 'EPERM' || code === 'EACCES' || code === 'EBUSY'; +} + +function remainingRetryBudgetMs(filePath: string): number { + const now = performance.now(); + let deadline = retryDeadlines.get(filePath); + // A deadline more than one budget past its expiry belongs to an earlier burst, not this one. + if (deadline === undefined || now - deadline > READ_RETRY_BUDGET_MS) { + deadline = now + READ_RETRY_BUDGET_MS; + retryDeadlines.set(filePath, deadline); + } + return deadline - now; +} diff --git a/config/watcherArming.ts b/config/watcherArming.ts new file mode 100644 index 0000000000..5daed11651 --- /dev/null +++ b/config/watcherArming.ts @@ -0,0 +1,59 @@ +// See DESIGN.md, "`ready` means the watcher is armed". Platform is a parameter so a test on any +// host can pin the darwin value, rather than only observing its own. +export function armGraceMs(platform: string = process.platform): number { + return platform === 'darwin' ? 20 : 0; +} + +const ARM_GRACE_MS = armGraceMs(); + +/** + * The gate a config watcher opens when its chokidar watcher is really watching: the initial scan + * has finished *and* the platform's kernel-side warm-up has had its grace. Shared by + * `RootConfigWatcher` and `OptionsWatcher` because both read the config synchronously, which is + * what exposes the unarmed window in the first place. + */ +export class ArmGate { + #armed: boolean = false; + #timer: NodeJS.Timeout | undefined; + #graceMs: number; + + // Taken as an argument, not read from the module constant, so the timer branch below is + // reachable from a host whose own platform has no grace — unit tests are ubuntu-only. + constructor(graceMs: number = ARM_GRACE_MS) { + this.#graceMs = graceMs; + } + + get armed(): boolean { + return this.#armed; + } + + // Synchronous where the platform needs no grace, so a watcher with no warm-up to wait out + // keeps reading inside chokidar's own dispatch. + arm(onArmed: () => void): void { + if (this.#armed || this.#timer) return; + if (!this.#graceMs) { + this.#armed = true; + onArmed(); + return; + } + this.#timer = setTimeout(() => { + this.#timer = undefined; + this.#armed = true; + onArmed(); + }, this.#graceMs); + } + + // Drops a grace still counting down, for a watcher that is closing. + cancel(): void { + clearTimeout(this.#timer); + this.#timer = undefined; + } + + // A replacement watcher has its own scan and its own unarmed window, so the gate arms again + // with it: for a file that is *absent* when the replacement scans, chokidar reports `ready` and + // nothing else, and the arming re-read is the only thing that would notice. + reset(): void { + this.cancel(); + this.#armed = false; + } +} diff --git a/unitTests/components/OptionsWatcher-envOverlay.test.js b/unitTests/components/OptionsWatcher-envOverlay.test.js index fbcd94f2f4..02131aca2d 100644 --- a/unitTests/components/OptionsWatcher-envOverlay.test.js +++ b/unitTests/components/OptionsWatcher-envOverlay.test.js @@ -14,6 +14,8 @@ const { join } = require('node:path'); const { tmpdir } = require('node:os'); const { mkdtempSync, writeFileSync, rmSync } = require('node:fs'); const { stringify } = require('yaml'); +const { DEFAULT_CONFIG } = require('#src/components/DEFAULT_CONFIG'); +const { waitFor } = require('../waitFor'); const NAME = 'modelsGateway'; const ENV_KEYS = ['HARPER_SET_CONFIG', 'HARPER_CONFIG', 'HARPER_DEFAULT_CONFIG']; @@ -100,6 +102,103 @@ describe('OptionsWatcher env-config overlay (#1618)', () => { assert.strictEqual(config, undefined); }); + // Env config is file-independent, so the terminal outcomes that settle the boot barrier on the + // defaults must not discard it either — the same invariant as the ENOENT read path. + it('keeps env config when the watcher itself fails', async () => { + const filePath = join(dir, 'harper-config.yaml'); + writeFileSync(filePath, stringify({ http: { port: 9926 } })); + process.env.HARPER_SET_CONFIG = JSON.stringify({ [NAME]: { enabled: true } }); + + watcher = new OptionsWatcher(NAME, filePath); + watcher.on('error', () => {}); + watcher._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + const [config] = await watcher.ready; + assert.deepStrictEqual(config, { enabled: true }); + }); + + // Env config that cannot be composed is not env config: the barrier still has to settle on the + // defaults, not on `undefined` and not by rejection, or componentLoader waits on it forever. + it('settles on the defaults when the env config itself cannot be composed and there is no file', async () => { + const filePath = join(dir, 'harper-config.yaml'); + process.env.HARPER_SET_CONFIG = '{not json'; + + watcher = new OptionsWatcher(NAME, filePath); + const errors = []; + watcher.on('error', (error) => errors.push(error)); + + const [config] = await watcher.ready; + assert.strictEqual(config, undefined, 'a scope with no defaults settles carrying nothing'); + assert.deepStrictEqual(watcher.getRoot(), DEFAULT_CONFIG); + assert.strictEqual(errors.length, 1, 'the compose failure must still be surfaced'); + }); + + it('settles on the defaults when the env config cannot be composed and the file is empty', async () => { + const filePath = join(dir, 'harper-config.yaml'); + writeFileSync(filePath, ''); + process.env.HARPER_SET_CONFIG = '{not json'; + + watcher = new OptionsWatcher(NAME, filePath); + watcher.on('error', () => {}); + + await watcher.ready; + assert.deepStrictEqual(watcher.getRoot(), DEFAULT_CONFIG, 'not undefined — a scope reading it would throw'); + }).timeout(10000); + + it('reports a malformed env config once when the root file is otherwise valid', async () => { + const filePath = join(dir, 'harper-config.yaml'); + writeFileSync(filePath, stringify({ [NAME]: { enabled: false } })); + process.env.HARPER_SET_CONFIG = '{not json'; + + watcher = new OptionsWatcher(NAME, filePath); + const errors = []; + watcher.on('error', (error) => errors.push(error)); + + await watcher.ready; + assert.strictEqual(errors.length, 1, 'the malformed env config is surfaced once'); + assert.deepStrictEqual(watcher.getRoot(), DEFAULT_CONFIG); + }); + + it('reports a malformed env config after the watcher is ready', async () => { + const filePath = join(dir, 'harper-config.yaml'); + writeFileSync(filePath, stringify({ [NAME]: { enabled: false } })); + + watcher = new OptionsWatcher(NAME, filePath); + await watcher.ready; + const errors = []; + watcher.on('error', (error) => errors.push(error)); + + process.env.HARPER_SET_CONFIG = '{not json'; + writeFileSync(filePath, stringify({ [NAME]: { enabled: true } })); + await watcher._refreshForTests(); + + assert.strictEqual(errors.length, 1, 'the malformed env config is surfaced after ready'); + assert.strictEqual(watcher.get(['enabled']), false, 'the malformed overlay does not replace the last valid config'); + }); + + // `#handleUnlink` runs inside chokidar's own dispatch, and the env-only fallback merges — so a + // plugin's own `change` handler throwing would take the worker down on a config deletion the + // watcher had just decided to survive. + it('does not let a throwing change listener escape the env-only unlink fallback', async () => { + const filePath = join(dir, 'harper-config.yaml'); + writeFileSync(filePath, stringify({ [NAME]: { enabled: false, fromFile: 1 } })); + process.env.HARPER_SET_CONFIG = JSON.stringify({ [NAME]: { enabled: true } }); + + watcher = new OptionsWatcher(NAME, filePath); + await watcher.ready; + assert.strictEqual(watcher.get(['fromFile']), 1); + + let changes = 0; + watcher.on('change', () => { + changes++; + throw new Error('listener boom'); + }); + rmSync(filePath); + + await waitFor(() => changes > 0, { message: 'the env-only fallback never merged' }); + assert.strictEqual(watcher.get(['enabled']), true, 'env config survives the deletion'); + }).timeout(10000); + it('overlays env config onto the legacy root config filename (harperdb-config.yaml)', async () => { const filePath = join(dir, 'harperdb-config.yaml'); writeFileSync(filePath, stringify({ [NAME]: { enabled: false } })); @@ -180,4 +279,28 @@ describe('OptionsWatcher env-config resilience (#1726 review)', () => { assert.strictEqual(watcher.get(['enabled']), true, 'env value must remain in effect'); assert.strictEqual(watcher.get(['fileOnly']), undefined, 'file-contributed value goes away with the file'); }); + it('does not let the env overlay launder a root config that parses to nothing', async () => { + // `overlayRootEnvConfig` turns any parse into a non-null object whenever a config env var + // is set, so completeness has to be judged on the file's own parse — otherwise a truncated + // write that yields `null` is adopted as an env-only config and the file's options go away. + const filePath = join(dir, 'harper-config.yaml'); + writeFileSync(filePath, stringify({ [NAME]: { enabled: false, fileOnly: 1 } })); + process.env.HARPER_SET_CONFIG = JSON.stringify({ [NAME]: { enabled: true } }); + + watcher = new OptionsWatcher(NAME, filePath); + await watcher.ready; + assert.strictEqual(watcher.get(['fileOnly']), 1); + + let removed = false; + watcher.on('remove', () => { + removed = true; + }); + // A lone newline reads fine and parses to null — the shape of a mid-write read that no + // `catch` sees. + writeFileSync(filePath, '\n'); + await watcher._refreshForTests(); + + assert.strictEqual(removed, false, 'a mid-write read must not read as the scope being removed'); + assert.strictEqual(watcher.get(['fileOnly']), 1, 'the file-contributed value must survive'); + }); }); diff --git a/unitTests/components/OptionsWatcher.test.js b/unitTests/components/OptionsWatcher.test.js index 68007dd01b..ff63399663 100644 --- a/unitTests/components/OptionsWatcher.test.js +++ b/unitTests/components/OptionsWatcher.test.js @@ -4,8 +4,9 @@ const { EventEmitter, once } = require('node:events'); const assert = require('node:assert'); const { join } = require('node:path'); const { tmpdir } = require('node:os'); -const { mkdtempSync, writeFileSync, rmSync } = require('node:fs'); +const { mkdtempSync, writeFileSync, rmSync, chmodSync, readFileSync } = require('node:fs'); const { writeFile, rm } = require('node:fs/promises'); +const { setTimeout: delay } = require('node:timers/promises'); const { stringify } = require('yaml'); const { spy } = require('sinon'); const chokidar = require('chokidar'); @@ -176,6 +177,689 @@ describe('OptionsWatcher', () => { await teardown({ fixture, options }); }); + it('finishes root config reads before its change callback returns', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + + const updated = { ...CONFIG, [NAME]: { ...OPTIONS, str: 'updated' } }; + writeFileSync(configFilePath, stringify(updated), 'utf-8'); + options._refreshForTests(); + + assert.equal(options.get(['str']), 'updated', 'root watcher must not leave a same-thread read in flight'); + await teardown({ fixture, options }); + }); + + // `: [1, 2` is what a prefix of `: [1, 2, 3]` looks like on disk mid-write: it does + // not parse, and the event carrying the rest of the document is the one chokidar throttles away. + it('rides out an unparseable read on the retry ladder', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + await options.ready; + + const before = options._readCountForTests; + writeFileSync(configFilePath, `${NAME}: [1, 2`, 'utf-8'); + options._refreshForTests(); + + for (let waited = 0; waited < 3000 && options._readCountForTests - before < 3; waited += 50) await delay(50); + + assert.ok( + options._readCountForTests - before >= 3, + `the ladder attempted ${options._readCountForTests - before} reads after the unparseable read` + ); + assert.deepEqual(options.getAll(), OPTIONS, 'a mid-write prefix must not replace the scope config'); + + await teardown({ fixture, options }); + }).timeout(10000); + + // `once(this, 'ready')` turns an `error` emitted before `ready` into a rejection, and + // `componentLoader` awaits `Scope.ready` — so a failing watcher used to fail the component load + // rather than settle it onto the defaults the way every read outcome does. + it('settles ready when the watcher itself fails', async () => { + const { fixture, configFilePath } = createFixture(); + const options = new OptionsWatcher(NAME, configFilePath); + const errorSpy = spy(); + options.on('error', errorSpy); + + options._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + await options.ready; + assert.equal(errorSpy.callCount, 1, 'the watcher error must still reach consumers'); + + await teardown({ fixture, options }); + }); + + // `componentLoader` builds scopes from a memoized view of the config, so a block removed under a + // booting worker leaves a read that parses perfectly and simply has nothing for this scope. + it('settles ready when the config that read fine no longer carries this scope', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify({ somethingElse: true }), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + + await options.ready; + + await teardown({ fixture, options }); + }).timeout(5000); + + it('keeps the config a scope-less read produced instead of falling back to the defaults', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'config.yaml'); + writeFileSync(configFilePath, stringify({ somethingElse: true }), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + + await options.ready; + assert.deepEqual(options.getRoot(), { somethingElse: true }); + + await teardown({ fixture, options }); + }).timeout(5000); + + it('does not let a throwing error listener escape the failure path', async () => { + const { fixture, configFilePath } = createFixture(); + const options = new OptionsWatcher(NAME, configFilePath); + options.on('error', () => { + throw new Error('listener boom'); + }); + + options._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + await teardown({ fixture, options }); + }); + + it('emits remove when a scope declared with no body is deleted', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify({ [NAME]: null }), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + await options.ready; + assert.strictEqual(options.getAll(), null, '`myPlugin:` with no body is a configured scope'); + + const removed = once(options, 'remove'); + writeFileSync(configFilePath, stringify({ somethingElse: true }), 'utf-8'); + options._refreshForTests(); + await removed; + + await teardown({ fixture, options }); + }).timeout(5000); + + // The failure paths emit `ready` from a retry timer and from chokidar's error dispatch, where a + // throwing listener is an uncaught exception rather than something a caller can absorb. + it('does not let a throwing ready listener escape the failure path', async () => { + const { fixture, configFilePath } = createFixture(); + const options = new OptionsWatcher(NAME, configFilePath); + options.on('ready', () => { + throw new Error('listener boom'); + }); + options.on('error', () => {}); + + options._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + await teardown({ fixture, options }); + }); + + it('re-reads the root config when the watcher arms', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + await options.ready; + + for (let waited = 0; waited < 3000 && !options._armedForTests; waited += 50) await delay(50); + assert.equal(options._armedForTests, true, 'the watcher must arm once chokidar has finished its scan'); + // A write landing in the unarmed window is reported by no event, so the arming re-read is the + // only thing that can deliver it — arming must read rather than trust the scan's read. + assert.ok(options._readCountForTests >= 2, `arming must re-read (${options._readCountForTests} reads)`); + + await teardown({ fixture, options }); + }); + + // Where the platform has an arming grace (darwin), the re-read lands a beat after `ready`, and + // a deletion in between used to reach the scope as a `remove` before chokidar had reported — + // or finished processing — the unlink itself. A consumer acting on that early `remove` recreates + // the file inside chokidar's own teardown window, where the `add` is not observed at all, and + // the scope keeps the defaults with no further event coming (harper#2191 review). + it('does not read a missing file as a deletion when the re-read came from arming', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + await options.ready; + + let removed = false; + options.on('remove', () => { + removed = true; + }); + rmSync(configFilePath); + // Asserted before yielding, so chokidar's own `unlink` — which is what may legitimately + // report this deletion — cannot have run yet. + options._refreshForTests(true); + + assert.equal(removed, false, 'the arm gate exists to catch a write, not to report a deletion'); + assert.equal(options.get(['str']), 'foo', 'the applied config must survive the arming re-read'); + + await teardown({ fixture, options }); + }); + + it('still reads a missing file as a deletion on an ordinary re-read', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath); + await options.ready; + + let removed = false; + options.on('remove', () => { + removed = true; + }); + rmSync(configFilePath); + options._refreshForTests(); + + assert.equal(removed, true, 'an ENOENT read outside the arm gate is still the install/removal path'); + + await teardown({ fixture, options }); + }); + + // A mode-000 file denies the read the way a Windows sharing violation does without stubbing + // node:fs, which AGENTS.md forbids. It has to be the file and not its directory: chokidar + // cannot watch an unreadable directory and synthesizes an `unlink` when it tries. chmod leaves + // mtime alone, so no watcher event fires for the lock or its release and a retry is provably + // the only thing that can read the file again. Root ignores the mode and Windows has no POSIX + // modes, so those hosts skip. + function denyReads(filePath) { + chmodSync(filePath, 0o000); + try { + readFileSync(filePath, 'utf-8'); + chmodSync(filePath, 0o644); + return false; + } catch { + return true; + } + } + + it('keeps the previous options through a denied read and applies the file once it clears', async function () { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + if (!denyReads(configFilePath)) { + await teardown({ fixture, options }); + return this.skip(); + } + + chmodSync(configFilePath, 0o644); + const errors = []; + options.on('error', (error) => errors.push(error)); + + // Written and locked in one synchronous block, so the watcher event this write queues is + // already denied by the time it runs and the new contents sit on disk unreachable. Which + // path delivers them after the unlock is not observable here — chokidar reports a chmod as + // a change of its own — so this asserts the invariant, and configReadRetry.test.js proves + // the ladder that upholds it when no event follows. + const updated = { ...CONFIG, [NAME]: { ...OPTIONS, str: 'unlocked' } }; + writeFileSync(configFilePath, stringify(updated), 'utf-8'); + chmodSync(configFilePath, 0o000); + + await delay(300); + assert.deepEqual(errors, [], 'a denied read must be retried before it is surfaced'); + assert.equal(options.get(['str']), 'foo', 'a denied read must leave the previous options in place'); + + chmodSync(configFilePath, 0o644); + for (let waited = 0; waited < 2500 && options.get(['str']) !== 'unlocked'; waited += 50) await delay(50); + + assert.equal(options.get(['str']), 'unlocked', 'a lock that clears must leave the options current'); + assert.deepEqual(errors, [], 'a lock that clears within the ladder must never surface'); + await teardown({ fixture, options }); + }); + + it('retries a denied application-config read instead of settling the scope on the defaults', async function () { + // Application configs read asynchronously so a stalled component-config volume cannot block + // the thread — which is a reason not to *block*, not a reason for a transient failure to be + // terminal. Nothing emits a second watcher event when it clears. + const fixture = mkdtempSync(getFixtureName()); + const appConfigPath = join(fixture, 'config.yaml'); + writeFileSync(appConfigPath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, appConfigPath, undefined, false); + await options.ready; + if (!denyReads(appConfigPath)) { + await teardown({ fixture, options }); + return this.skip(); + } + + const errors = []; + options.on('error', (error) => errors.push(error)); + + // The file stays locked, so chokidar reports nothing further — chmod leaves mtime alone — + // and every read past the first can only have come from a ladder rung. + const before = options._readCountForTests; + await options._refreshForTests(); + for (let waited = 0; waited < 3000 && options._readCountForTests - before < 3; waited += 50) await delay(50); + + assert.ok( + options._readCountForTests - before >= 3, + `the ladder attempted ${options._readCountForTests - before} reads while the lock held` + ); + assert.deepEqual(errors, [], 'a denied read must be retried before it is surfaced'); + assert.equal(options.get(['str']), 'foo', 'a denied read must leave the previous options in place'); + + chmodSync(appConfigPath, 0o644); + await teardown({ fixture, options }); + }); + + // `DEFAULT_CONFIG` names six scopes, and a boot that finds none of its own config hands the + // scope that scope's defaults. Read as a value the file supplied, the next read of the very + // same file looks like the block being deleted — a `remove`, and through `Scope` a restart, on + // a config that never changed. + it('does not report a removal for the defaults it booted on', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify({ http: { port: 9926 } }), 'utf-8'); + const options = new OptionsWatcher('graphqlSchema', configFilePath, undefined, true); + await options.ready; + assert.equal(options.get(['files']), DEFAULT_CONFIG.graphqlSchema.files, 'the boot falls back to the defaults'); + + let removed = false; + options.on('remove', () => { + removed = true; + }); + await options._refreshForTests(); + await options._refreshForTests(); + + assert.equal(removed, false, 'the defaults are not a configuration that can be removed'); + await teardown({ fixture, options }); + }); + + it('reports a truthy config arrival and its later removal after boot fallback', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify({ http: { port: 9926 } }), 'utf-8'); + const options = new OptionsWatcher('graphqlSchema', configFilePath, undefined, true); + await options.ready; + + let arrived; + let changed = 0; + options.on('ready', (value) => { + arrived = value; + }); + options.on('change', () => changed++); + writeFileSync(configFilePath, stringify({ graphqlSchema: DEFAULT_CONFIG.graphqlSchema }), 'utf-8'); + await options._refreshForTests(); + assert.deepEqual(arrived, DEFAULT_CONFIG.graphqlSchema, 'a truthy fallback must not mask the config arrival'); + assert.equal(changed, 0, 'the first source config is an arrival, not a merge'); + + const removed = once(options, 'remove'); + writeFileSync(configFilePath, stringify({ http: { port: 9926 } }), 'utf-8'); + await options._refreshForTests(); + await removed; + + await teardown({ fixture, options }); + }); + + // A scope declared with no body is configured and falsy. Filling it in is a change; only the + // unconfigured → configured transition is a `ready`, which `Scope` answers with a restart. + it('delivers a filled-in falsy scope as a change, not a second ready', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, `${NAME}:\n`, 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + const [value] = await options.ready; + assert.strictEqual(value, null, 'a scope declared with no body is configured as null'); + + let readyAgain = 0; + options.on('ready', () => readyAgain++); + const changed = once(options, 'change'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + await changed; + + assert.equal(readyAgain, 0, 'filling in a configured scope is not the unconfigured transition'); + assert.equal(options.get(['str']), 'foo', 'the filled-in value must be applied'); + await teardown({ fixture, options }); + }); + + // The other half of not reporting a deletion from the arming re-read: the unarmed window is + // exactly where an `unlink` can go missing, so an absence it observes cannot just be dropped. + it('still reports an absence the arming re-read observed, once the loop has had its turn', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + + // Armed first, so the watcher's own arming re-read is already spent and cannot be mistaken + // for the re-check below. + for (let waited = 0; waited < 3000 && !options._armedForTests; waited += 10) await delay(10); + + const removed = once(options, 'remove'); + rmSync(configFilePath); + options._refreshForTests(true); + // Captured synchronously, so only the re-check the arming read queued can move it: one + // check-phase turn later, ahead of anything chokidar can deliver (which needs a poll-phase + // turn first), and `#handleUnlink` does not read at all. + const afterArming = options._readCountForTests; + await new Promise((resolve) => setImmediate(resolve)); + + assert.ok( + options._readCountForTests > afterArming, + 'the absence the arming re-read saw must be re-checked, not dropped' + ); + await removed; + assert.equal(options.get(['str']), undefined, 'the scope must fall back to its defaults'); + await teardown({ fixture, options }); + }); + + // `Scope.ready` has no timeout, so a shutdown mid-ladder must not strand `componentLoader`. + it('settles ready when it is closed mid-ladder', async function () { + this.timeout(2000); + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + // Empty, so the ladder is still running and `ready` is nowhere near its own settle. + writeFileSync(configFilePath, '', 'utf-8'); + + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + await options.close(); + await options.ready; + + rmSync(fixture, { recursive: true, force: true }); + }); + + it('still becomes ready when the config cannot be applied at boot', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, `${NAME}:\n str: [unclosed\n`, 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + const errors = []; + options.on('error', (error) => errors.push(error)); + + // componentLoader awaits this with no timeout and nothing consumes `error`, so a failure + // that leaves `ready` unemitted hangs the boot instead of surfacing. + await options.ready; + + assert.equal(errors.length, 1, 'the failure must still surface'); + assert.deepEqual(options.getAll(), DEFAULT_CONFIG[NAME], 'boot falls back to the defaults'); + await teardown({ fixture, options }); + }); + + it('re-reads from the ladder while the file stays locked, with no watcher event to help', async function () { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + if (!denyReads(configFilePath)) { + await teardown({ fixture, options }); + return this.skip(); + } + + options.on('error', () => {}); + const before = options._readCountForTests; + options._refreshForTests(); + + // Nothing touches the file for the rest of the case, so chokidar has nothing to report: any + // further read attempt came from a ladder rung. + for (let waited = 0; waited < 3000 && options._readCountForTests - before < 3; waited += 50) await delay(50); + + assert.ok( + options._readCountForTests - before >= 3, + `the ladder attempted ${options._readCountForTests - before} reads while the lock held` + ); + chmodSync(configFilePath, 0o644); + await teardown({ fixture, options }); + }); + + it('surfaces a denied root config read once the retry ladder is spent', async function () { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + if (!denyReads(configFilePath)) { + await teardown({ fixture, options }); + return this.skip(); + } + + const errored = once(options, 'error'); + options._refreshForTests(); + const [error] = await errored; + + assert.equal(error.code, 'EACCES', 'a lock that outlives the ladder must not be swallowed'); + chmodSync(configFilePath, 0o644); + await teardown({ fixture, options }); + }); + + it('does not read a writer truncate window as a removed config', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + + let removed = false; + options.on('remove', () => { + removed = true; + }); + writeFileSync(configFilePath, '', 'utf-8'); + options._refreshForTests(); + + assert.equal(removed, false, 'an empty read must not read as a deleted scope'); + assert.equal(options.get(['str']), 'foo', 'the loaded options must survive a truncate window'); + await teardown({ fixture, options }); + }); + + it('does not write an applied config into the shared defaults', async function () { + // `.mocharc.json` sets `timeout: 0`, so a lost event here wedges the whole run rather than + // failing this case. + this.timeout(10_000); + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify({ graphqlSchema: { files: 'a.graphql' } }), 'utf-8'); + const options = new OptionsWatcher('graphqlSchema', configFilePath, undefined, true); + await options.ready; + + const removed = once(options, 'remove'); + rmSync(configFilePath); + await removed; + const fallbackRoot = options.getRoot(); + assert.notStrictEqual(fallbackRoot, DEFAULT_CONFIG, 'a reset must clone the root defaults'); + assert.notStrictEqual( + fallbackRoot.graphqlSchema, + DEFAULT_CONFIG.graphqlSchema, + 'a reset must clone nested scope defaults' + ); + + // `await removed` resumes as a microtask of chokidar's own `unlink` dispatch, so the + // recreate below lands while chokidar is still tearing that watch down and its `add` is not + // reliably reported — on darwin every run, on Linux CI under load. `should continue to watch + // if file is removed and recreated` is where that delivery is asserted; what this case is + // about is the reapplied config, so it drives the read itself rather than racing the watcher. + const ready = once(options, 'ready'); + writeFileSync(configFilePath, stringify({ graphqlSchema: { files: 'custom.graphql' } }), 'utf-8'); + await options._refreshForTests(); + const [arrived] = await ready; + + assert.equal(arrived.files, 'custom.graphql', 'the recreated source config must arrive as ready'); + assert.equal(options.get(['files']), 'custom.graphql', 'the scope must apply its own config'); + assert.equal(DEFAULT_CONFIG.graphqlSchema.files, '*.graphql', 'the shared defaults must survive it'); + await teardown({ fixture, options }); + }); + + // componentLoader awaits `Scope.ready` with no timeout, so a file that is still empty when the + // ladder is spent has to settle on the defaults rather than strand the component. + it('becomes ready on the defaults when the config file stays empty', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, '', 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + await options.ready; + + assert.equal(options.get(['str']), undefined, 'an empty config carries no scoped options'); + await teardown({ fixture, options }); + }).timeout(10000); + + // A deletion inside the boot window cancels the ladder that was the only thing left to settle + // `ready`, so `#handleUnlink` has to settle the barrier itself: `remove` reaches a `Scope` whose + // own `ready` is still pending, which asks for a restart of a component that never booted. + it('settles ready when the file is deleted before any read had a config to give', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, '', 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + // Waited out so the arming re-read is not what settles the barrier. The ladder's rungs then + // back off with the elapsed budget, so waiting on its own read count — rather than on a wall + // clock a loaded runner would overrun — leaves the next rung far enough away that chokidar's + // `unlink`, held back by its own atomic-write window, observes the deletion first. That + // ordering is the boot hang: the ladder was the only thing left to settle `ready`, and + // `#handleUnlink` cancels it. + for (let waited = 0; waited < 3000 && !options._armedForTests; waited += 20) await delay(20); + assert.equal(options._armedForTests, true, 'the watcher must arm once chokidar has finished its scan'); + const events = []; + for (const event of ['ready', 'remove']) options.on(event, () => events.push(event)); + for (let waited = 0; waited < 3000 && options._readCountForTests < 6 && !events.length; waited += 20) + await delay(20); + assert.deepEqual(events, [], 'the ladder must still be the only thing the barrier is waiting on'); + rmSync(configFilePath, { force: true }); + + const [value] = await options.ready; + assert.strictEqual(value, undefined, 'a scope the defaults do not name settles carrying nothing'); + assert.deepEqual(events, ['ready'], 'a deletion in the boot window settles the barrier, it does not remove'); + await teardown({ fixture, options }); + }).timeout(10000); + + // `myPlugin:` with nothing under it is a configured scope whose value happens to be falsy, and + // `Scope` turns a repeat `ready` into a restart request — so a re-read of it must not look like + // the unconfigured → configured transition. + it('does not re-emit ready when a falsy scope value is read again', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, `${NAME}:\n`, 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + const [value] = await options.ready; + assert.strictEqual(value, null, 'a scope declared with no body is configured as null'); + + let readyAgain = 0; + options.on('ready', () => readyAgain++); + options._refreshForTests(); + options._refreshForTests(); + + assert.equal(readyAgain, 0, 're-reading the same falsy value is not a transition'); + await teardown({ fixture, options }); + }); + + // A scope that booted unconfigured is in the same state as one whose config file was deleted: + // `ready` is how the watcher says it has config again, and `Scope` re-initializes on each one. + it('delivers a scope that arrives after the boot fallback as a ready', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, '', 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + + // A file still empty when the ladder is spent settles `ready` on the defaults, which do + // not name this scope. + await options.ready; + assert.equal(options.get(['str']), undefined, 'the fallback carries no scoped options'); + + const readyAgain = once(options, 'ready'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const [value] = await readyAgain; + + assert.equal(value.str, 'foo', 'the second ready must carry the config that arrived'); + assert.equal(options.get(['str']), 'foo', 'the scope must apply the config that arrived'); + await teardown({ fixture, options }); + }).timeout(10000); + + it('does not read a writer truncate window as a removed config on the async read path', async () => { + const { fixture, configFilePath, options } = await setup(); + + let removed = false; + options.on('remove', () => { + removed = true; + }); + writeFileSync(configFilePath, '', 'utf-8'); + options._refreshForTests(); + await delay(50); + + assert.equal(removed, false, 'an empty read must not read as a deleted scope'); + assert.equal(options.get(['str']), 'foo', 'the loaded options must survive a truncate window'); + await teardown({ fixture, options }); + }); + + it('does not surface the source lines yaml frames into a parse failure', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + + const errored = once(options, 'error'); + writeFileSync(configFilePath, `${NAME}:\n str: [unclosed\n password: hunter2\n`, 'utf-8'); + options._refreshForTests(); + const [error] = await errored; + + // The scope logs whatever is emitted here, and a config file holds credentials. + assert.ok(!error.message.includes('hunter2'), `the emitted parse error framed the config: ${error.message}`); + assert.ok(/line \d+, column \d+/.test(error.message), 'the emitted parse error must locate the failure'); + assert.equal(options.get(['str']), 'foo', 'a parse failure keeps the last valid options'); + await teardown({ fixture, options }); + }); + + it('does not treat an ENOENT from a change listener as a missing config file', async () => { + const fixture = mkdtempSync(getFixtureName()); + const configFilePath = join(fixture, 'harper-config.yaml'); + writeFileSync(configFilePath, stringify(CONFIG), 'utf-8'); + const options = new OptionsWatcher(NAME, configFilePath, undefined, true); + await options.ready; + + const listenerError = Object.assign(new Error('listener file missing'), { code: 'ENOENT' }); + let emittedError; + options.on('error', (error) => { + emittedError = error; + }); + let removed = false; + options.on('remove', () => { + removed = true; + }); + options.on('change', () => { + throw listenerError; + }); + + writeFileSync(configFilePath, stringify({ ...CONFIG, [NAME]: { ...OPTIONS, str: 'updated' } }), 'utf-8'); + options._refreshForTests(); + + assert.equal(emittedError, listenerError); + assert.equal(removed, false, 'listener errors must not reset the scope'); + await teardown({ fixture, options }); + }); + + it('does not treat an ENOENT from a change listener as a missing config file on the async read path', async () => { + const { fixture, configFilePath, options } = await setup(); + + const listenerError = Object.assign(new Error('listener file missing'), { code: 'ENOENT' }); + let removed = false; + options.on('remove', () => { + removed = true; + }); + options.on('change', () => { + throw listenerError; + }); + + const errored = once(options, 'error'); + await writeFile(configFilePath, stringify({ ...CONFIG, [NAME]: { ...OPTIONS, str: 'updated' } }), 'utf-8'); + const [emitted] = await errored; + + assert.equal(emitted, listenerError); + assert.equal(removed, false, 'listener errors must not reset the scope'); + await teardown({ fixture, options }); + }); + it('should continue to watch if file is removed and recreated', async () => { // Detecting file removal and recreation can take some time so increase the timeout this.timeout = 3000; @@ -614,16 +1298,29 @@ describe('OptionsWatcher', () => { const expected = { jsResource: { files: 'foo.js' } }; + // The scope booted on its own truthy default, which leaves it *unconfigured*, so the file + // arriving is the unconfigured → configured transition `#applyScopedConfig` reports as a + // second `ready` — not the merge a scope with a prior source value would take. + let changed = 0; + const countChanges = () => changed++; + options.on('change', countChanges); await assertEvent( options, - 'change', + 'ready', () => writeFile(configFilePath, stringify(expected), 'utf-8'), - (changeSpy) => { - assert.equal(changeSpy.callCount, 1); + (readySpy) => { + assert.equal(readySpy.callCount, 1); + assert.deepEqual( + readySpy.getCall(0).args, + [expected[name]], + 'the arrival must carry the config that was written' + ); + assert.equal(changed, 0, 'a truthy boot fallback is not a prior source value to merge against'); assert.deepEqual(options.getRoot(), expected, 'should return the updated config after writing a new file'); assert.deepEqual(options.getAll(), expected[name], 'should return the configuration after file recreation'); } ); + options.removeListener('change', countChanges); await assertEvent( options, diff --git a/unitTests/components/Scope.test.js b/unitTests/components/Scope.test.js index 2c335eaa23..43b76639e0 100644 --- a/unitTests/components/Scope.test.js +++ b/unitTests/components/Scope.test.js @@ -251,6 +251,30 @@ describe('Scope', () => { await scope.close(); }); + it('should call requestRestart when a truthy-default scope receives its source config', async () => { + // A config file still empty when the read ladder is spent settles `Scope.ready` on the + // defaults, so componentLoader runs handleApplication with no config of this scope's own. + // The operator's config landing afterwards reaches nothing on its own: componentLoader is + // long past its await, and the arrival is a `ready`, not the `change` the files/urlPath + // listener watches. + writeFileSync(this.configFilePath, ''); + const scopeName = 'static'; + + const scope = new Scope(this.appName, scopeName, this.directory, this.configFilePath, this.resources, this.server); + + await scope.ready; + + assert.equal(restartNeeded(), false, 'requestRestart should not be called yet'); + + await writeFile(this.configFilePath, stringify({ [scopeName]: { files: 'alternate/**' } })); + + await waitFor(() => restartNeeded()); + + assert.equal(restartNeeded(), true, 'requestRestart should be called when the config arrives'); + + await scope.close(); + }).timeout(10000); + it('should NOT call requestRestart on block removal when the plugin handles remove itself', async () => { writeFileSync(this.configFilePath, stringify({ [this.pluginName]: { enabled: true } })); diff --git a/unitTests/config/configReadHandleLifetime.test.js b/unitTests/config/configReadHandleLifetime.test.js index 7b5525cbf2..7474bf2f48 100644 --- a/unitTests/config/configReadHandleLifetime.test.js +++ b/unitTests/config/configReadHandleLifetime.test.js @@ -4,7 +4,6 @@ const { tmpdir } = require('node:os'); const { mkdtempSync, writeFileSync, rmSync, mkdirSync } = require('node:fs'); const { once } = require('node:events'); const { waitFor } = require('../waitFor'); -const { isPartialReadWarned, clearPartialReadWarning } = require('#src/utility/watcherFallback'); const { stringify } = require('yaml'); const { RootConfigWatcher } = require('#src/config/RootConfigWatcher'); const { OptionsWatcher } = require('#src/components/OptionsWatcher'); @@ -122,7 +121,7 @@ describe('root config read handle lifetime', () => { // transient replace-under-us failures Windows produces; the change must not be dropped. rmSync(configFilePath); mkdirSync(configFilePath); - watcher._handleChangeForTests(); + watcher._refreshForTests(); assert.deepStrictEqual(errors, [], 'a recoverable read failure must not surface as an error'); rmSync(configFilePath, { recursive: true }); @@ -135,19 +134,20 @@ describe('root config read handle lifetime', () => { const watcher = new OptionsWatcher('test-component', configFilePath, undefined, true); openWatchers.push(watcher); await watcher.ready; - watcher.on('error', () => {}); + const errors = []; + watcher.on('error', (error) => errors.push(error)); - // An unreadable file drains the budget on its own: each re-read fails and arms the next. - clearPartialReadWarning(configFilePath); + // An unreadable file drains the budget on its own: each re-read fails and arms the next, + // and the scope's `error` is what the exhausted ladder falls through to. rmSync(configFilePath); mkdirSync(configFilePath); - await watcher._handleChangeForTests(); - await waitFor(() => isPartialReadWarned(configFilePath), { message: 'the error path never gave up' }); + await watcher._refreshForTests(); + await waitFor(() => errors.length > 0, { timeout: 10_000, message: 'the error path never gave up' }); // The repair can be observed mid-write too, so the budget has to be back. rmSync(configFilePath, { recursive: true }); writeFileSync(configFilePath, ''); - await watcher._handleChangeForTests(); + await watcher._refreshForTests(); assert.strictEqual(watcher.get(['enabled']), true, 'the half-written repair must not be adopted'); writeFileSync(configFilePath, stringify({ 'test-component': { enabled: false } })); @@ -161,7 +161,7 @@ describe('root config read handle lifetime', () => { await watcher.ready; writeFileSync(configFilePath, stringify({ 'test-component': { enabled: false } })); - watcher._handleChangeForTests(); + watcher._refreshForTests(); assert.strictEqual(watcher.get(['enabled']), false); }); @@ -178,7 +178,7 @@ describe('root config read handle lifetime', () => { writeFileSync(appConfigPath, ''); // Awaited, or the assertions below would also pass against a build with no partial-read // handling at all on this path, having asserted on a read that had not happened. - await watcher._handleChangeForTests(); + await watcher._refreshForTests(); assert.deepStrictEqual(removes, [], 'a half-written read must not read as the scope being removed'); assert.strictEqual(watcher.get(['enabled']), true); @@ -211,41 +211,18 @@ describe('root config read handle lifetime', () => { const removes = []; watcher.on('remove', () => removes.push(true)); writeFileSync(configFilePath, ''); - await watcher._handleChangeForTests(); + await watcher._refreshForTests(); assert.deepStrictEqual(removes, [], 'the env overlay must not stand in for the half-written file'); assert.strictEqual(watcher.get(['enabled']), true); }); - it('OptionsWatcher reports a file it gave up on once, not once per scope', async () => { - clearPartialReadWarning(configFilePath); - // Both scopes must be present in the file, or their `ready` never fires. - writeFileSync( - configFilePath, - stringify({ 'test-component': { enabled: true }, 'other-component': { enabled: true } }) - ); - const watchers = ['test-component', 'other-component'].map((name) => { - const watcher = new OptionsWatcher(name, configFilePath, undefined, true); - openWatchers.push(watcher); - return watcher; - }); - await Promise.all(watchers.map((watcher) => watcher.ready)); - - writeFileSync(configFilePath, ''); - for (const watcher of watchers) { - // Drive each watcher past its own retry budget, as a real unusable file would. - for (let attempt = 0; attempt <= 12; attempt++) await watcher._handleChangeForTests(); - await waitFor(() => isPartialReadWarned(configFilePath), { message: 'the give-up was never reported' }); - } - // The per-file gate that suppresses the duplicate report is pinned directly in - // unitTests/utility/partialReadRetry.test.js; this covers both scopes reaching it at all. - assert.strictEqual(isPartialReadWarned(configFilePath), true); - }); - it('OptionsWatcher still reads an application config without blocking', async () => { // Application configs are written in place, never by rename-over, so they must keep the - // non-blocking read — a slow or stalled component-config volume must not stall the thread. - const appConfigPath = join(fixture, 'config.yaml'); + // non-blocking read — including when the component uses a root-style config filename. + const appDirectory = join(fixture, 'application'); + mkdirSync(appDirectory); + const appConfigPath = join(appDirectory, HARPER_CONFIG_FILE); writeFileSync(appConfigPath, stringify({ 'test-component': { enabled: true } })); const watcher = new OptionsWatcher('test-component', appConfigPath, undefined, false); openWatchers.push(watcher); @@ -253,7 +230,7 @@ describe('root config read handle lifetime', () => { writeFileSync(appConfigPath, stringify({ 'test-component': { enabled: false } })); const changed = once(watcher, 'change'); - watcher._handleChangeForTests(); + watcher._refreshForTests(); assert.strictEqual(watcher.get(['enabled']), true, 'application config reads must not be synchronous'); await changed; diff --git a/unitTests/config/configReadRetry.test.js b/unitTests/config/configReadRetry.test.js new file mode 100644 index 0000000000..2692b3df61 --- /dev/null +++ b/unitTests/config/configReadRetry.test.js @@ -0,0 +1,91 @@ +'use strict'; + +const assert = require('node:assert'); +const { setTimeout: delay } = require('node:timers/promises'); +const { ConfigReadRetry } = require('#src/config/configReadRetry'); +const { waitFor } = require('../waitFor'); + +const RETRY_BUDGET_MS = 3_100; +const INITIAL_DELAY_MS = 100; + +describe('ConfigReadRetry', () => { + it('arms a retry and reports that it did', async () => { + const retry = new ConfigReadRetry(); + let fired = 0; + + assert.equal( + retry.schedule(() => fired++), + true + ); + assert.equal(fired, 0, 'the retry must not run inline'); + + await waitFor(() => fired === 1, { message: 'the armed retry never ran' }); + retry.cancel(); + }); + + it('does not push the next attempt out when a burst of events arrives at once', async () => { + const retry = new ConfigReadRetry(); + let fired = 0; + + // One atomic rename can deliver add + change + change within a millisecond; every one of + // them enters the same failing read path. Advancing the backoff per call rather than per + // elapsed millisecond would strand the caller at the maximum delay while the file is + // already readable again. + for (let i = 0; i < 8; i++) retry.schedule(() => fired++); + + await waitFor(() => fired > 0, { message: 'a burst must still arm a retry, and promptly' }); + // The burst armed one timer, not eight; nothing else can raise the count. + await delay(INITIAL_DELAY_MS); + assert.equal(fired, 1, 'a burst must arm exactly one retry'); + retry.cancel(); + }); + + it('reports the budget spent instead of retrying forever', async () => { + const retry = new ConfigReadRetry(); + const startedAt = performance.now(); + let scheduled = 0; + + while (retry.schedule(() => {})) { + scheduled++; + // Stand in for the timer so the ladder walks its whole budget without waiting on it. + await delay(0); + if (performance.now() - startedAt > RETRY_BUDGET_MS * 2) break; + } + + assert.ok(scheduled > 1, `the ladder gave up after ${scheduled} attempts`); + assert.ok( + performance.now() - startedAt >= RETRY_BUDGET_MS * 0.9, + 'the ladder must be bounded by wall clock, not by how often it is called' + ); + retry.cancel(); + }); + + it('starts a fresh budget once the caller has been told the ladder is spent', async () => { + const retry = new ConfigReadRetry(); + while (retry.schedule(() => {})) await delay(0); + + // Reporting the budget spent ends that ladder, so the next event — a later write, not this + // burst — gets its own full budget rather than inheriting an exhausted one. + const startedAt = performance.now(); + let scheduled = 0; + while (retry.schedule(() => {})) { + scheduled++; + await delay(0); + if (performance.now() - startedAt > RETRY_BUDGET_MS * 2) break; + } + + assert.ok(scheduled > 1, `the second ladder gave up after ${scheduled} attempts`); + assert.ok(performance.now() - startedAt >= RETRY_BUDGET_MS * 0.9, 'the second ladder must get a full budget'); + retry.cancel(); + }); + + it('cancel leaves no timer behind', async () => { + const retry = new ConfigReadRetry(); + let fired = 0; + retry.schedule(() => fired++); + retry.cancel(); + + await delay(INITIAL_DELAY_MS * 3); + assert.equal(fired, 0); + }); +}); diff --git a/unitTests/config/configUtils.test.js b/unitTests/config/configUtils.test.js index c47910a369..8313559ee7 100644 --- a/unitTests/config/configUtils.test.js +++ b/unitTests/config/configUtils.test.js @@ -156,11 +156,19 @@ describe('Test configUtils module', () => { const ATOMIC_TEST_DIR = path.join(DIRNAME, 'yaml'); const ATOMIC_TEST_PATH = path.join(ATOMIC_TEST_DIR, 'atomic-write-test.yaml'); + let originalPlatform; + const setPlatform = (value) => Object.defineProperty(process, 'platform', { value, configurable: true }); + before(() => { fs.ensureDirSync(ATOMIC_TEST_DIR); }); + beforeEach(() => { + originalPlatform = Object.getOwnPropertyDescriptor(process, 'platform'); + }); + afterEach(() => { + Object.defineProperty(process, 'platform', originalPlatform); try { fs.unlinkSync(ATOMIC_TEST_PATH); } catch {} @@ -211,13 +219,26 @@ describe('Test configUtils module', () => { expect(stragglers).to.be.empty; }); - it('generates a unique temp path even when pid and timestamp are identical', () => { - // Worker threads share process.pid, and worker arrivals cluster within the - // same millisecond — a pid+timestamp scheme would collide. Pin Date.now() - // so this test fails if uniqueness ever stops depending on randomness. + // A partial write leaves the temp file behind, and its name carries fresh randomness on every + // call, so nothing else would ever collect it. + it('removes the temp file when the write itself fails part-way', () => { + const realWriteFileSync = fs.writeFileSync; + const writeStub = sandbox.stub(fs, 'writeFileSync').callsFake((target) => { + realWriteFileSync(target, ''); + throw Object.assign(new Error('ENOSPC: no space left on device, write'), { code: 'ENOSPC' }); + }); + try { + expect(() => atomicWriteFile(ATOMIC_TEST_PATH, 'content')).to.throw(/ENOSPC/); + const tempPath = writeStub.firstCall.args[0]; + expect(fs.existsSync(tempPath)).to.be.false; + } finally { + writeStub.restore(); + } + }); + + it('generates a unique temp path for each write', () => { const writeStub = sandbox.stub(fs, 'writeFileSync'); const renameStub = sandbox.stub(fs, 'renameSync'); - const dateStub = sandbox.stub(Date, 'now').returns(1234567890); try { const tempPaths = new Set(); for (let i = 0; i < 100; i++) { @@ -228,13 +249,10 @@ describe('Test configUtils module', () => { } finally { writeStub.restore(); renameStub.restore(); - dateStub.restore(); } }); - it('retries the rename on a transient Windows EPERM/EACCES and succeeds once the holder releases the file', () => { - // Simulates a sibling worker's RootConfigWatcher (or AV) briefly holding the - // destination open for read: renameSync fails a couple of times, then succeeds. + it('retries transient Windows rename errors and succeeds once the holder releases the file', () => { const renameStub = sandbox.stub(fs, 'renameSync'); const epermError = Object.assign(new Error('EPERM: operation not permitted, rename'), { code: 'EPERM' }); const eaccesError = Object.assign(new Error('EACCES: permission denied, rename'), { code: 'EACCES' }); @@ -242,26 +260,60 @@ describe('Test configUtils module', () => { renameStub.onCall(1).throws(eaccesError); renameStub.onCall(2).returns(undefined); try { - atomicWriteFile(ATOMIC_TEST_PATH, 'content'); + atomicWriteFile(ATOMIC_TEST_PATH, 'content', { + retryBudgetMs: 60_000, + initialDelayMs: 0, + }); + expect(renameStub.callCount).to.equal(3); + } finally { + renameStub.restore(); + } + }); + + it('preserves the explicit retry-count limit', () => { + const renameStub = sandbox.stub(fs, 'renameSync'); + const epermError = Object.assign(new Error('EPERM: operation not permitted, rename'), { code: 'EPERM' }); + renameStub.throws(epermError); + try { + expect(() => + atomicWriteFile(ATOMIC_TEST_PATH, 'content', { + retryBudgetMs: 60_000, + maxRetries: 2, + initialDelayMs: 0, + }) + ).to.throw(epermError); expect(renameStub.callCount).to.equal(3); } finally { renameStub.restore(); } }); - it('gives up after exhausting retries on a persistent EPERM, cleans up the temp file, and rethrows', () => { + it('rejects invalid retry options', () => { + expect(() => atomicWriteFile(ATOMIC_TEST_PATH, 'content', { initialDelayMs: Number.NaN })).to.throw( + RangeError, + 'rename retry options must be non-negative numbers' + ); + expect(() => atomicWriteFile(ATOMIC_TEST_PATH, 'content', { retryBudgetMs: Infinity })).to.throw( + RangeError, + 'rename retry options must be non-negative numbers' + ); + }); + + it('gives up after the retry budget expires on a persistent EPERM, cleans up the temp file, and rethrows', () => { const renameStub = sandbox.stub(fs, 'renameSync'); const epermError = Object.assign(new Error('EPERM: operation not permitted, rename'), { code: 'EPERM' }); renameStub.throws(epermError); try { - // Use the default retry count (unspecified maxRetries) so this exercises the real - // production budget, but override the delay to ~0 so the backoff doesn't burn real - // wall-clock time (default backoff would take ~3.6s for a persistent failure). - expect(() => atomicWriteFile(ATOMIC_TEST_PATH, 'content', { initialDelayMs: 0, maxDelayMs: 0 })).to.throw( - epermError - ); - // 1 initial attempt + 12 retries (the production default maxRetries) - expect(renameStub.callCount).to.equal(13); + const startedAt = performance.now(); + expect(() => + atomicWriteFile(ATOMIC_TEST_PATH, 'content', { + retryBudgetMs: 50, + }) + ).to.throw(epermError); + const elapsedMs = performance.now() - startedAt; + expect(renameStub.callCount).to.be.at.least(2); + expect(elapsedMs).to.be.at.least(50); + expect(elapsedMs).to.be.below(1_000); const stragglers = fs .readdirSync(ATOMIC_TEST_DIR) .filter((e) => e.startsWith('atomic-write-test.yaml.') && e.endsWith('.tmp')); @@ -271,6 +323,28 @@ describe('Test configUtils module', () => { } }); + // Every case above overrides `retryBudgetMs`, so the shipped default's own loop never runs: + // widening it to effectively unbounded leaves them all green, and the value that actually + // governs `set_configuration` on Windows would ship unwatched. The bound is spelled out + // rather than read back from the module, or the assertion would move with the regression. + it('gives up on the shipped default budget, not on an unbounded one', function () { + this.timeout(30_000); + // The window the 12-attempt schedule it replaced spanned: 10+20+40+80+160+320+500*6. + const expectedBudgetMs = 3_630; + const renameStub = sandbox.stub(fs, 'renameSync'); + const epermError = Object.assign(new Error('EPERM: operation not permitted, rename'), { code: 'EPERM' }); + renameStub.throws(epermError); + try { + const startedAt = performance.now(); + expect(() => atomicWriteFile(ATOMIC_TEST_PATH, 'content')).to.throw(epermError); + const elapsedMs = performance.now() - startedAt; + expect(elapsedMs, 'the default budget was shortened').to.be.at.least(expectedBudgetMs * 0.8); + expect(elapsedMs, 'the default budget was widened').to.be.below(expectedBudgetMs * 2); + } finally { + renameStub.restore(); + } + }); + it('does not retry on a non-permission rename error', () => { const renameStub = sandbox.stub(fs, 'renameSync'); const enoentError = Object.assign(new Error('ENOENT: no such file or directory, rename'), { code: 'ENOENT' }); @@ -282,6 +356,22 @@ describe('Test configUtils module', () => { renameStub.restore(); } }); + + for (const code of ['EPERM', 'EACCES', 'EBUSY']) { + it(`retries ${code}, whatever the platform reports`, () => { + setPlatform('linux'); + const renameStub = sandbox.stub(fs, 'renameSync'); + const error = Object.assign(new Error(`${code}: rename`), { code }); + renameStub.onFirstCall().throws(error); + renameStub.onSecondCall().returns(undefined); + try { + atomicWriteFile(ATOMIC_TEST_PATH, 'content', { initialDelayMs: 0 }); + expect(renameStub.callCount).to.equal(2); + } finally { + renameStub.restore(); + } + }); + } }); describe('Test ensureConfigKeysPresent function', () => { diff --git a/unitTests/config/parseConfigFile.test.js b/unitTests/config/parseConfigFile.test.js new file mode 100644 index 0000000000..7f567e7ecb --- /dev/null +++ b/unitTests/config/parseConfigFile.test.js @@ -0,0 +1,55 @@ +'use strict'; + +const assert = require('node:assert'); +const { ConfigParseError, parseConfigFile } = require('#src/config/parseConfigFile'); + +describe('parseConfigFile', () => { + it('parses a config file', () => { + assert.deepEqual(parseConfigFile('foo: bar\n', '/tmp/harperdb-config.yaml'), { foo: 'bar' }); + }); + + it('lets a parser fault through with its own message', () => { + assert.throws(() => parseConfigFile(42, '/tmp/harperdb-config.yaml'), { + name: 'TypeError', + message: /source is not a string/, + }); + }); + + // yaml reports a warning through `process.emitWarning`, not a throw, so it goes around + // `ConfigParseError` entirely — and its framed message would put config source on stderr. + it('does not warn a config file onto stderr', async () => { + const warnings = []; + // Only yaml's own — an unrelated deprecation warning in the same window is not this test's. + const onWarning = (warning) => warning.name === 'YAMLWarning' && warnings.push(warning); + process.on('warning', onWarning); + try { + parseConfigFile('%FOO bar\n---\nauthentication:\n password: hunter2\n', '/tmp/harperdb-config.yaml'); + // `process.emitWarning` reports on the next tick. + await new Promise((resolve) => setImmediate(resolve)); + } finally { + process.off('warning', onWarning); + } + + assert.deepEqual( + warnings.map((warning) => warning.name), + [], + `the parser warned about the config file: ${warnings.map((warning) => warning.message).join('; ')}` + ); + }); + + it('reports where a malformed file failed without repeating its contents', () => { + const contents = 'authentication:\n operationTokenTimeout: [unclosed\n password: hunter2\n'; + + assert.throws( + () => parseConfigFile(contents, '/tmp/harperdb-config.yaml'), + (error) => { + assert.ok(error instanceof ConfigParseError); + assert.ok(!error.message.includes('hunter2'), `the parse error framed the source: ${error.message}`); + assert.ok(error.message.includes('/tmp/harperdb-config.yaml'), 'names the file that failed'); + assert.ok(/line \d+, column \d+/.test(error.message), 'locates the failure'); + assert.equal(error.cause, undefined, 'a cause would carry the framed message back into the log'); + return true; + } + ); + }); +}); diff --git a/unitTests/config/readConfigFileSync.test.js b/unitTests/config/readConfigFileSync.test.js new file mode 100644 index 0000000000..9675d67483 --- /dev/null +++ b/unitTests/config/readConfigFileSync.test.js @@ -0,0 +1,147 @@ +'use strict'; + +const assert = require('node:assert'); +const { chmodSync, mkdtempSync, readFileSync, rmSync, writeFileSync } = require('node:fs'); +const { spawn } = require('node:child_process'); +const { tmpdir } = require('node:os'); +const { join } = require('node:path'); +const { readConfigFileSync } = require('#src/config/readConfigFileSync'); + +const READ_RETRY_BUDGET_MS = 500; +const CONTENTS = 'rootPath: /tmp/hdb'; + +// A real mode-000 file is the only way to make readFileSync fail the way a Windows sharing +// violation does without stubbing node:fs, which AGENTS.md forbids. Root ignores the mode, and +// Windows has no POSIX modes at all, so the whole suite opts out where the lock cannot be taken. +function canDenyReads(filePath) { + chmodSync(filePath, 0o000); + try { + readFileSync(filePath, 'utf-8'); + return false; + } catch { + return true; + } finally { + chmodSync(filePath, 0o644); + } +} + +describe('readConfigFileSync', () => { + let fixture; + let originalPlatform; + + beforeEach(() => { + fixture = mkdtempSync(join(tmpdir(), 'harper.unit-test.read-config-sync-')); + originalPlatform = Object.getOwnPropertyDescriptor(process, 'platform'); + }); + + afterEach(() => { + Object.defineProperty(process, 'platform', originalPlatform); + rmSync(fixture, { recursive: true, force: true }); + }); + + const setPlatform = (value) => Object.defineProperty(process, 'platform', { value, configurable: true }); + + // The retry deadline is shared per path, so a case that must start with a fresh budget needs a + // path no earlier case has poisoned. + const lockedConfig = (name) => { + const filePath = join(fixture, `${name}.yaml`); + writeFileSync(filePath, CONTENTS); + if (!canDenyReads(filePath)) return undefined; + chmodSync(filePath, 0o000); + return filePath; + }; + + it('returns the file contents', () => { + const filePath = join(fixture, 'present.yaml'); + writeFileSync(filePath, CONTENTS); + assert.equal(readConfigFileSync(filePath), CONTENTS); + }); + + it('rethrows a missing file without retrying', () => { + setPlatform('win32'); + const startedAt = performance.now(); + assert.throws(() => readConfigFileSync(join(fixture, 'absent.yaml')), { code: 'ENOENT' }); + assert.ok(performance.now() - startedAt < READ_RETRY_BUDGET_MS, 'a missing file must fail immediately'); + }); + + it('does not retry a denied read off Windows, where the permission failure is real', function () { + setPlatform('linux'); + const filePath = lockedConfig('no-retry'); + if (!filePath) return this.skip(); + + const startedAt = performance.now(); + assert.throws(() => readConfigFileSync(filePath), { code: 'EACCES' }); + assert.ok(performance.now() - startedAt < READ_RETRY_BUDGET_MS / 2, 'POSIX must fail fast'); + }); + + it('retries a denied read on Windows and returns once the writer releases the file', function () { + const filePath = lockedConfig('retry'); + if (!filePath) return this.skip(); + setPlatform('win32'); + + // The retry loop never yields, so the release has to come from another process. + const release = spawn('sh', ['-c', `sleep 0.15; chmod 644 '${filePath}'`], { stdio: 'ignore' }); + release.on('error', () => chmodSync(filePath, 0o644)); + release.unref(); + + assert.equal(readConfigFileSync(filePath), CONTENTS); + }); + + it('gives up at the retry deadline and rethrows', function () { + const filePath = lockedConfig('persistent'); + if (!filePath) return this.skip(); + setPlatform('win32'); + + const startedAt = performance.now(); + assert.throws(() => readConfigFileSync(filePath), { code: 'EACCES' }); + const elapsedMs = performance.now() - startedAt; + + assert.ok(elapsedMs >= READ_RETRY_BUDGET_MS * 0.8, `gave up after ${elapsedMs}ms`); + assert.ok(elapsedMs < READ_RETRY_BUDGET_MS * 4, `overran the budget: ${elapsedMs}ms`); + }); + + it('takes a single attempt when the caller owns the retry, so a ladder rung costs no stall', function () { + const filePath = lockedConfig('single-attempt'); + if (!filePath) return this.skip(); + setPlatform('win32'); + + const startedAt = performance.now(); + assert.throws(() => readConfigFileSync(filePath, false), { code: 'EACCES' }); + const elapsedMs = performance.now() - startedAt; + + assert.ok(elapsedMs < READ_RETRY_BUDGET_MS / 2, `a non-waiting read blocked for ${elapsedMs}ms`); + }); + + it('shares one deadline across callers reading the same path, so a burst costs one budget', function () { + const filePath = lockedConfig('shared'); + if (!filePath) return this.skip(); + setPlatform('win32'); + + assert.throws(() => readConfigFileSync(filePath), { code: 'EACCES' }); + + // A sibling watcher reacting to the same change event must not spend a second budget on + // the calling worker's event loop. + const startedAt = performance.now(); + assert.throws(() => readConfigFileSync(filePath), { code: 'EACCES' }); + const elapsedMs = performance.now() - startedAt; + + assert.ok(elapsedMs < READ_RETRY_BUDGET_MS / 2, `the sibling read blocked for ${elapsedMs}ms`); + }); + + it('starts a fresh budget once a read succeeds', function () { + const filePath = lockedConfig('recovered'); + if (!filePath) return this.skip(); + setPlatform('win32'); + + assert.throws(() => readConfigFileSync(filePath), { code: 'EACCES' }); + chmodSync(filePath, 0o644); + assert.equal(readConfigFileSync(filePath), CONTENTS); + chmodSync(filePath, 0o000); + + const startedAt = performance.now(); + assert.throws(() => readConfigFileSync(filePath), { code: 'EACCES' }); + const elapsedMs = performance.now() - startedAt; + + assert.ok(elapsedMs >= READ_RETRY_BUDGET_MS * 0.8, `the exhausted deadline outlived the read: ${elapsedMs}ms`); + }); +}); diff --git a/unitTests/config/rootConfigWatcher.test.js b/unitTests/config/rootConfigWatcher.test.js index 8e1726cd9b..2a02d5fe84 100644 --- a/unitTests/config/rootConfigWatcher.test.js +++ b/unitTests/config/rootConfigWatcher.test.js @@ -3,8 +3,9 @@ const { RootConfigWatcher } = require('#src/config/RootConfigWatcher'); const { tmpdir } = require('node:os'); const { once } = require('node:events'); const { join } = require('node:path'); -const { writeFileSync, mkdtempSync, rmSync, renameSync } = require('node:fs'); +const { writeFileSync, mkdtempSync, rmSync, renameSync, chmodSync, readFileSync } = require('node:fs'); const { writeFile } = require('node:fs/promises'); +const { setTimeout: delay } = require('node:timers/promises'); const { replace, fake, restore, spy } = require('sinon'); const chokidar = require('chokidar'); const configUtils = require('#src/config/configUtils'); @@ -15,6 +16,10 @@ const { stringify } = require('yaml'); describe('RootConfigWatcher', function () { this.timeout(30000); + // `this` inside an `it(function () {...})` is mocha's Context, not the object beforeEach writes + // the fixture onto; cases that need this.skip() read the fixture through here instead. + const suite = this; + beforeEach(() => { this.fixture = mkdtempSync(join(tmpdir(), 'harper.unit-test.root-config-watcher-')); this.configFilePath = join(this.fixture, 'config.yaml'); @@ -43,12 +48,10 @@ describe('RootConfigWatcher', function () { expected.foo = 'baz'; - // Subscribe before writing: the watcher re-reads the root config synchronously, so the - // change event can be emitted before this writer's own await resolves. - const changed = once(configWatcher, 'change'); + const change = once(configWatcher, 'change'); await writeFile(this.configFilePath, stringify(expected)); - const [updated] = await changed; + const [updated] = await change; assert.deepEqual(updated, expected, 'RootConfigWatcher should emit a change event with the updated config'); @@ -65,6 +68,50 @@ describe('RootConfigWatcher', function () { ); }); + it('does not resolve ready before the watcher is armed', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + + assert.equal(configWatcher._armedForTests, false, 'a freshly constructed watcher is not armed'); + await configWatcher.ready; + + // Callers take `ready` as "watching" and write immediately after it; see DESIGN.md, + // "`ready` means the watcher is armed". + assert.equal(configWatcher._armedForTests, true, 'ready must not resolve before the watcher is armed'); + + configWatcher.close(); + }); + + it('does not publish config staged before an arming fallback', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'staged' })); + const configWatcher = new RootConfigWatcher(); + + configWatcher.handleChange(); + assert.deepEqual(configWatcher.config, { foo: 'staged' }, 'the pre-arm read must stage the first config'); + rmSync(this.configFilePath); + + const [value] = await configWatcher.ready; + + assert.strictEqual(value, undefined, 'an arming fallback must not publish the superseded staged config'); + assert.strictEqual(configWatcher.config, undefined, 'the watcher must settle without a loaded config'); + configWatcher.close(); + }); + + it('keeps config staged before a watcher error settles ready', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'staged' })); + const configWatcher = new RootConfigWatcher(); + + configWatcher.handleChange(); + assert.deepEqual(configWatcher.config, { foo: 'staged' }, 'the pre-arm read must stage the first config'); + configWatcher._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + const [value] = await configWatcher.ready; + + assert.deepEqual(value, { foo: 'staged' }, 'a watcher error must settle with the successfully staged config'); + assert.deepEqual(configWatcher.config, { foo: 'staged' }, 'the watcher must retain the loaded config'); + configWatcher.close(); + }); + it('should detect changes written via temp-file + rename (atomic write)', async () => { const initial = { foo: 'bar' }; writeFileSync(this.configFilePath, stringify(initial)); @@ -76,14 +123,215 @@ describe('RootConfigWatcher', function () { const updated = { foo: 'baz' }; const tempPath = `${this.configFilePath}.${process.pid}.${Date.now()}.tmp`; writeFileSync(tempPath, stringify(updated)); + const change = once(configWatcher, 'change'); renameSync(tempPath, this.configFilePath); - const [changeValue] = await once(configWatcher, 'change'); + const [changeValue] = await change; assert.deepEqual(changeValue, updated, 'watcher should fire change after atomic rename'); configWatcher.close(); }); + it('finishes reading the config before its change callback returns', async () => { + const initial = { foo: 'bar' }; + writeFileSync(this.configFilePath, stringify(initial)); + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + const updated = { foo: 'baz' }; + writeFileSync(this.configFilePath, stringify(updated)); + configWatcher.handleChange(); + + assert.deepEqual(configWatcher.config, updated, 'watcher must not leave a same-thread read in flight'); + configWatcher.close(); + }); + + // `harper_logger.start()` awaits this promise with no timeout, so every terminal read outcome + // has to settle it. + it('resolves ready for a config that parses to nothing', async () => { + writeFileSync(this.configFilePath, '# nothing but a comment\n'); + const configWatcher = new RootConfigWatcher(); + + const [value] = await configWatcher.ready; + + assert.strictEqual(value, undefined, 'a config that parses to nothing must still settle the boot barrier'); + configWatcher.close(); + }).timeout(5000); + + it('resolves ready on an empty config once the retry ladder is spent', async () => { + writeFileSync(this.configFilePath, ''); + const configWatcher = new RootConfigWatcher(); + + const [value] = await configWatcher.ready; + + assert.strictEqual(value, undefined, 'a file that stays empty must settle the barrier carrying no config'); + configWatcher.close(); + }).timeout(10000); + + // chokidar's initial scan finds nothing to report, so arming is the only place that can tell + // this apart from a watcher that has simply not read yet. A missing file is not a lock, so it + // must settle at once rather than spend the ladder — `harper_logger.start()` waits on this. + it('resolves ready when there is no config file to read', async () => { + const configWatcher = new RootConfigWatcher(); + + const [value] = await configWatcher.ready; + + assert.strictEqual(value, undefined, 'a missing config file must still settle the boot barrier'); + assert.equal(configWatcher._readCountForTests, 1, 'ENOENT must not take the retry ladder'); + configWatcher.close(); + }).timeout(10000); + + it('settles ready when the watcher is closed before it arms', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + + configWatcher.close(); + + await configWatcher.ready; + }); + + it('resolves ready for a config that cannot be parsed', async () => { + writeFileSync(this.configFilePath, 'foo: [unclosed\n'); + const configWatcher = new RootConfigWatcher(); + + const [value] = await configWatcher.ready; + + assert.strictEqual(value, undefined, 'an unparseable config must settle the barrier carrying no config'); + + // A parse failure is terminal for that read, but the watcher still has to deliver the file + // once an operator fixes it. + const change = once(configWatcher, 'change'); + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const [updated] = await change; + + assert.deepEqual(updated, { foo: 'bar' }, 'a repaired config must arrive as a change'); + configWatcher.close(); + }).timeout(10000); + + it('treats an empty read as a writer mid-write, not an empty config', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + // A non-atomic writer truncates before it writes; a read landing in between sees nothing. + // chokidar throttles the change event that carries the content as a duplicate of the + // truncate's, so discarding the empty read strands the config on the stale value. + const before = configWatcher._readCountForTests; + writeFileSync(this.configFilePath, ''); + configWatcher.handleChange(); + assert.deepEqual(configWatcher.config, { foo: 'bar' }, 'an empty read must not clear the loaded config'); + + // Nothing touches the file again, so chokidar has only the truncate to report: the reads + // beyond that one came from ladder rungs. + for (let waited = 0; waited < 3000 && configWatcher._readCountForTests - before < 4; waited += 50) await delay(50); + assert.ok( + configWatcher._readCountForTests - before >= 4, + `the ladder attempted ${configWatcher._readCountForTests - before} reads after the empty read` + ); + + const change = once(configWatcher, 'change'); + writeFileSync(this.configFilePath, stringify({ foo: 'baz' })); + const [updated] = await change; + assert.deepEqual(updated, { foo: 'baz' }, 'the content the writer went on to write must still arrive'); + + configWatcher.close(); + }); + + it('ignores a watcher callback that lands after close()', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + configWatcher.close(); + writeFileSync(this.configFilePath, stringify({ foo: 'baz' })); + configWatcher.handleChange(); + + assert.equal(configWatcher.config, undefined, 'a closed watcher must not read or repopulate its config'); + }); + + // A mode-000 file denies the watcher's read the way a Windows sharing violation does without + // stubbing node:fs, which AGENTS.md forbids. It has to be the file and not its directory: + // chokidar cannot watch an unreadable directory. Root ignores the mode and Windows has no POSIX + // modes, so those hosts skip. + const denyReads = (filePath) => { + chmodSync(filePath, 0o000); + try { + readFileSync(filePath, 'utf-8'); + chmodSync(filePath, 0o644); + return false; + } catch { + return true; + } + }; + + it('retries a failed config read until it succeeds, without waiting for another change event', async function () { + writeFileSync(suite.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + const firstChange = once(configWatcher, 'change'); + writeFileSync(suite.configFilePath, stringify({ foo: 'baz' })); + await firstChange; + + if (!denyReads(suite.configFilePath)) { + configWatcher.close(); + return this.skip(); + } + + configWatcher.handleChange(); + assert.deepEqual(configWatcher.config, { foo: 'baz' }, 'a failed read must keep the previous config'); + + const change = once(configWatcher, 'change'); + chmodSync(suite.configFilePath, 0o644); + const [updated] = await change; + + // chokidar reports the unlocking chmod as a change of its own, so this asserts that the + // config comes back, not which path delivered it; configReadRetry.test.js covers the ladder. + assert.deepEqual(updated, { foo: 'baz' }, 'a read denied once must not leave the config stale'); + configWatcher.close(); + }); + + it('cancels a pending read retry on close', async function () { + writeFileSync(suite.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + if (!denyReads(suite.configFilePath)) { + configWatcher.close(); + return this.skip(); + } + + configWatcher.handleChange(); + configWatcher.close(); + chmodSync(suite.configFilePath, 0o644); + + // close() clears the config, so a retry that outlived it would reload and set it again. + await delay(400); + assert.equal(configWatcher.config, undefined, 'close() must not leave a retry timer behind'); + }); + + // A truncated write usually leaves a *prefix* on disk, and `foo: [1, 2` is what a prefix of + // `foo: [1, 2, 3]` looks like: unparseable, with the event carrying the rest of the document + // throttled away by chokidar as a duplicate. + it('rides out an unparseable read on the same ladder as an empty one', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + const before = configWatcher._readCountForTests; + writeFileSync(this.configFilePath, 'foo: [1, 2'); + configWatcher.handleChange(); + + for (let waited = 0; waited < 3000 && configWatcher._readCountForTests - before < 3; waited += 50) await delay(50); + + assert.ok( + configWatcher._readCountForTests - before >= 3, + `the ladder attempted ${configWatcher._readCountForTests - before} reads after the unparseable read` + ); + assert.deepEqual(configWatcher.config, { foo: 'bar' }, 'a mid-write prefix must not replace the config'); + configWatcher.close(); + }).timeout(10000); + describe('polling fallback on watcher exhaustion', () => { // harper#488: when ENOSPC/EMFILE fires on the underlying chokidar // watcher, the RootConfigWatcher should swap to a polling watcher @@ -109,8 +357,9 @@ describe('RootConfigWatcher', function () { // Polling watcher should pick up subsequent writes; default polling // interval is 1s, so allow up to ~3s for the change event. const updated = { foo: 'after-fallback' }; + const change = once(configWatcher, 'change'); await writeFile(this.configFilePath, stringify(updated)); - const [changeValue] = await once(configWatcher, 'change'); + const [changeValue] = await change; assert.deepEqual(changeValue, updated, 'polling watcher should fire change'); configWatcher.close(); @@ -133,6 +382,39 @@ describe('RootConfigWatcher', function () { configWatcher.close(); }); + // `once(this, 'ready')` is what usually absorbs an `error`, and settling the barrier is + // what removes it — so the production shape has no listener at all by the time a scan + // error is reported, and an unlistened `error` throws out of chokidar's dispatch. + it('does not throw a scan error at an emitter no one is listening to', async () => { + const configWatcher = new RootConfigWatcher(); + await configWatcher.ready; + + configWatcher._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + configWatcher.close(); + }).timeout(10000); + + // A scan error is terminal for the barrier — chokidar may never emit its own `ready` after + // one — but it is not the scan finishing, so the arming re-read still has to happen. + it('settles ready on a scan error without giving up the arming re-read', async () => { + writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); + const configWatcher = new RootConfigWatcher(); + + configWatcher._simulateWatcherErrorForTests(Object.assign(new Error('boom'), { code: 'EACCES' })); + + await configWatcher.ready; + assert.equal(configWatcher._armedForTests, false, 'a scan error is not the scan finishing'); + + // The write that the unarmed window swallows is exactly what the arming re-read exists + // to recover, so it must still arrive with no further watcher event. + writeFileSync(this.configFilePath, stringify({ foo: 'armed' })); + for (let waited = 0; waited < 3000 && !configWatcher._armedForTests; waited += 50) await delay(50); + + assert.equal(configWatcher._armedForTests, true, 'the watcher must still arm after a scan error'); + assert.deepEqual(configWatcher.config, { foo: 'armed' }, 'arming must still re-read'); + configWatcher.close(); + }).timeout(5000); + it('swallows additional exhaustion errors during recovery', async () => { writeFileSync(this.configFilePath, stringify({ foo: 'bar' })); const configWatcher = new RootConfigWatcher(); diff --git a/unitTests/config/watcherArming.test.js b/unitTests/config/watcherArming.test.js new file mode 100644 index 0000000000..6cdfb946cc --- /dev/null +++ b/unitTests/config/watcherArming.test.js @@ -0,0 +1,123 @@ +const { ArmGate, armGraceMs } = require('#src/config/watcherArming'); +const assert = require('node:assert'); +const { setTimeout: delay } = require('node:timers/promises'); + +// The grace itself is platform-derived (darwin only), so a case can assert when the callback runs +// relative to `arm()` only by waiting for it. +async function waitForArmed(gate) { + for (let waited = 0; waited < 3000 && !gate.armed; waited += 5) await delay(5); + return gate.armed; +} + +describe('armGraceMs', () => { + // The gate cases below observe only the grace of the host they run on, so on Linux CI they are + // all satisfied by a grace of 0 — which is exactly the regression worth catching, since darwin + // is the platform that needs one at all. Pinned per platform so the measurement is asserted + // from any host. See DESIGN.md, "`ready` means the watcher is armed", for where the value came + // from: writing 0ms after `ready` loses the write, 5ms and beyond delivers it. + it("gives darwin a grace over chokidar's own ready, and no other platform one", () => { + assert.ok(armGraceMs('darwin') >= 5, `darwin must keep a grace (got ${armGraceMs('darwin')}ms)`); + for (const platform of ['linux', 'win32', 'freebsd']) { + assert.equal(armGraceMs(platform), 0, `${platform} arms inside chokidar's own ready dispatch`); + } + }); + + it('derives the process default from this platform', () => { + assert.equal(armGraceMs(), armGraceMs(process.platform)); + }); +}); + +describe('ArmGate', () => { + it('runs the arming callback once and reports itself armed', async () => { + const gate = new ArmGate(); + let armings = 0; + + assert.equal(gate.armed, false, 'a fresh gate is not armed'); + gate.arm(() => armings++); + assert.equal(await waitForArmed(gate), true, 'the gate must arm'); + assert.equal(armings, 1, 'the arming callback must run exactly once'); + }); + + it('ignores a repeat arm, from a second scan or a replacement watcher', async () => { + const gate = new ArmGate(); + let armings = 0; + + gate.arm(() => armings++); + await waitForArmed(gate); + gate.arm(() => armings++); + await delay(50); + + assert.equal(armings, 1, 'only the first arm may re-read'); + }); + + it('cancels a grace that is still counting down, and never un-arms one that is not', async () => { + const pending = new ArmGate(); + let armings = 0; + pending.arm(() => armings++); + pending.cancel(); + await delay(50); + // Where there is no grace the callback has already run inside `arm`; where there is one, + // cancelling it before it elapses is the watcher generation being torn down. + assert.equal(armings, pending.armed ? 1 : 0, 'a cancelled grace must not arm the gate'); + + const armed = new ArmGate(); + armed.arm(() => {}); + await waitForArmed(armed); + armed.cancel(); + assert.equal(armed.armed, true, 'cancel must not un-arm a gate that has already armed'); + }); +}); + +// Unit tests run on ubuntu only, where `armGraceMs()` is 0, so every case above takes the +// synchronous branch and a regression in the timer one ships green on the platform that needs it. +describe('ArmGate with a grace', () => { + it('defers arming until the grace elapses', async () => { + const gate = new ArmGate(20); + let armings = 0; + + gate.arm(() => armings++); + assert.equal(gate.armed, false, 'the gate must not arm inside `arm()` when it has a grace'); + assert.equal(armings, 0, 'the re-read must wait out the warm-up chokidar cannot report'); + + assert.equal(await waitForArmed(gate), true, 'the grace must arm the gate'); + assert.equal(armings, 1, 'the arming callback must run exactly once'); + }); + + it('drops a grace cancelled before it elapses, and never arms after', async () => { + const gate = new ArmGate(20); + let armings = 0; + + gate.arm(() => armings++); + gate.cancel(); + await delay(60); + + assert.equal(gate.armed, false, 'a cancelled grace must leave the gate unarmed'); + assert.equal(armings, 0, 'a torn-down generation must not re-read'); + }); + + it('lets a replacement watcher arm again after reset', async () => { + const gate = new ArmGate(20); + let armings = 0; + + gate.arm(() => armings++); + await waitForArmed(gate); + gate.reset(); + assert.equal(gate.armed, false, 'reset must open the gate for the replacement generation'); + + gate.arm(() => armings++); + assert.equal(await waitForArmed(gate), true, 'the replacement must arm on its own scan'); + assert.equal(armings, 2, 'the replacement re-reads as the first generation did'); + }); + + it('drops a grace still pending when the generation is replaced', async () => { + const gate = new ArmGate(20); + let armings = 0; + + gate.arm(() => armings++); + gate.reset(); + await delay(60); + + assert.equal(armings, 0, 'the replaced generation must not arm the gate for its successor'); + assert.equal(gate.armed, false, 'the replacement has not scanned yet'); + }); +}); diff --git a/unitTests/utility/logging/harper_logger.test.js b/unitTests/utility/logging/harper_logger.test.js index b21f3c312e..bc49db84c5 100644 --- a/unitTests/utility/logging/harper_logger.test.js +++ b/unitTests/utility/logging/harper_logger.test.js @@ -2230,4 +2230,24 @@ describe('Test harper_logger module', () => { assert.ok(lines.join('\n').includes('Error: origin fetch failed')); }); }); + + describe('Test applyLogSettings function (harper#2191)', () => { + const { _applyLogSettingsForTests, getLogFilePath } = harperLoggerModule; + + it('does not throw on a component key declared with no body', () => { + // `myComponent:` with nothing under it parses to null, and this runs from the root + // config's async `change` listener, where the TypeError escapes as an unhandled + // rejection rather than as a listener fault the watcher contains. + assert.doesNotThrow(() => _applyLogSettingsForTests({ noBody: null })); + }); + + it('leaves the established settings alone when the barrier settles carrying no config', () => { + // A read that ends with nothing settles the barrier too, and `updateLogger` reads an + // absent `rotation`/`console` as off — so applying it would disable logging on the one + // boot that could not read its config. + const established = getLogFilePath(); + _applyLogSettingsForTests(undefined); + assert.equal(getLogFilePath(), established, 'a config-less settle must not reconfigure logging'); + }); + }); }); diff --git a/unitTests/utility/partialReadRetry.test.js b/unitTests/utility/partialReadRetry.test.js deleted file mode 100644 index e28d1cb395..0000000000 --- a/unitTests/utility/partialReadRetry.test.js +++ /dev/null @@ -1,159 +0,0 @@ -const assert = require('node:assert'); -const { - PartialReadRetry, - warnPartialReadGaveUp, - isPartialReadWarned, - clearPartialReadWarning, - describeReadFailure, -} = require('#src/utility/watcherFallback'); -const { parse } = require('yaml'); -const { waitFor } = require('../waitFor'); - -// The retry is a timer, so "it fired" is a condition to wait for; "it fired only once" is a -// non-event, which is the one case AGENTS.md reserves a fixed settle for. -const settle = () => new Promise((resolve) => setTimeout(resolve, 100)); - -describe('describeReadFailure', () => { - it('reports where a config file failed to parse, never what it contains', () => { - let description; - try { - parse('operationsApi:\n password: hunter2-super-secret\n port: [unclosed\n'); - assert.fail('the fixture must not parse'); - } catch (error) { - description = describeReadFailure(error); - } - - // The parser's own message quotes the offending source lines, which is why it is not used. - assert.match(description, /line \d+, column \d+/); - assert.doesNotMatch(description, /hunter2|password|unclosed/); - }); - - it('reports a read error by its code', () => { - assert.strictEqual(describeReadFailure(Object.assign(new Error('nope'), { code: 'EACCES' })), 'EACCES'); - }); -}); - -describe('PartialReadRetry', () => { - it('re-reads once for a burst of unusable reads, not once per event', async () => { - const retry = new PartialReadRetry('/nonexistent/config.yaml'); - let rereads = 0; - - assert.strictEqual( - retry.schedule(() => rereads++), - true - ); - assert.strictEqual( - retry.schedule(() => rereads++), - true, - 'a second event joins the armed re-read' - ); - - await waitFor(() => rereads > 0, { message: 'the re-read never fired' }); - await settle(); - assert.strictEqual(rereads, 1); - }); - - it('cancels an armed re-read once a usable read arrives, so it cannot replay', async () => { - const retry = new PartialReadRetry('/nonexistent/config.yaml'); - let rereads = 0; - - retry.schedule(() => rereads++); - retry.settled(); - - await settle(); - assert.strictEqual(rereads, 0); - }); - - it('reports exhaustion so the caller can fall back to its own error handling', async () => { - const retry = new PartialReadRetry('/nonexistent/config.yaml'); - let rereads = 0; - // Re-arm only after each timer has actually fired, so this counts budget rather than - // racing the timer that is still armed (schedule() reports true for both). - for (let attempt = 1; retry.schedule(() => rereads++); attempt++) { - assert.ok(attempt <= 50, 'the budget must be bounded'); - await waitFor(() => rereads === attempt, { message: `re-read ${attempt} never fired` }); - } - - assert.ok(rereads > 0, 'the budget must allow at least one re-read'); - assert.strictEqual( - retry.schedule(() => rereads++), - false - ); - - // A usable read restores the budget for the next incident. - retry.settled(); - assert.strictEqual( - retry.schedule(() => rereads++), - true - ); - }); - - it('re-arms the give-up warning once the file recovers', async () => { - const retry = new PartialReadRetry('/nonexistent/recovering.yaml'); - // The warning is throttled per file so one bad config cannot produce one line per scope, - // but a file that recovers and later breaks again is a new incident. - warnPartialReadGaveUp('/nonexistent/recovering.yaml'); - assert.strictEqual(isPartialReadWarned('/nonexistent/recovering.yaml'), true); - - retry.settled(); - assert.strictEqual(isPartialReadWarned('/nonexistent/recovering.yaml'), false); - }); - - it('keeps the report standing when it gives up, and withdraws it only on recovery', async () => { - // The gate is shared per file, so treating a give-up like a recovery would let each of the - // N scopes watching one root config report the same file in turn. - const path = '/nonexistent/shared.yaml'; - clearPartialReadWarning(path); - const retry = new PartialReadRetry(path); - - assert.strictEqual(retry.gaveUp(), true, 'the first give-up is the one that reports'); - assert.strictEqual( - new PartialReadRetry(path).gaveUp(), - false, - 'another scope giving up on the same file must be suppressed, not reported again' - ); - - retry.settled(); - assert.strictEqual(isPartialReadWarned(path), false, 'a usable read is what withdraws the report'); - assert.strictEqual(new PartialReadRetry(path).gaveUp(), true, 'so the next incident reports again'); - }); - - it('restores the budget when it gives up, so a later repair is not missed', async () => { - // The repair can itself be observed mid-write, which is the case the retry exists for — a - // watcher left with no budget would drop it and chokidar may emit nothing further. - const retry = new PartialReadRetry('/nonexistent/repaired.yaml'); - let rereads = 0; - for (let attempt = 1; retry.schedule(() => rereads++); attempt++) { - assert.ok(attempt <= 50, 'the budget must be bounded'); - await waitFor(() => rereads === attempt, { message: `re-read ${attempt} never fired` }); - } - retry.gaveUp(); - - assert.strictEqual( - retry.schedule(() => rereads++), - true, - 'the next incident needs its own budget' - ); - }); - - it('stops re-reading after close', async () => { - const retry = new PartialReadRetry('/nonexistent/config.yaml'); - let rereads = 0; - - retry.schedule(() => rereads++); - retry.cancel(); - - await settle(); - assert.strictEqual(rereads, 0); - assert.strictEqual( - retry.schedule(() => rereads++), - false - ); - // Close is terminal: giving up restores the budget, and must not do so after close. - assert.strictEqual(retry.gaveUp(), false); - assert.strictEqual( - retry.schedule(() => rereads++), - false - ); - }); -}); diff --git a/utility/logging/harper_logger.ts b/utility/logging/harper_logger.ts index db6206afbd..c247db85a9 100644 --- a/utility/logging/harper_logger.ts +++ b/utility/logging/harper_logger.ts @@ -174,7 +174,19 @@ async function updateLogSettings() { // TODO: Any way to differentiate changes that we can and can't handle? rootConfig.on('change', updateLogSettings); } - let rootConfigObject = rootConfig.config; + applyLogSettings(rootConfig.config); +} + +// Separate from the watcher wiring above because the watcher it builds reads a process-wide path, +// which leaves no way to exercise these settings against a given config. +function applyLogSettings(rootConfigObject: any) { + // `ready` settles on every terminal read outcome, including ones that carry no config at all — + // see DESIGN.md, "Every terminal read outcome settles the barrier". Applying that as settings + // would not be "the defaults": `updateLogger` reads an absent `rotation` as rotation off and an + // absent `console` as console off, so an unreadable config would silently disable logging. + // What `initLogSettings()` established at startup stands until a real config arrives, which + // is why the watcher settles those outcomes with no config rather than an empty one. + if (!rootConfigObject || typeof rootConfigObject !== 'object') return; const logOptions = rootConfigObject.logging ?? {}; // Resolve relative paths against rootPath from the same config const rootPath = rootConfigObject.rootPath; @@ -197,7 +209,9 @@ async function updateLogSettings() { for (const name in rootConfigObject) { // we now scan each component to see if it has logging individual configured const component = rootConfigObject[name]; - if (component.logging) { + // `myComponent:` with nothing under it parses to null, and an async listener's TypeError + // escapes the watcher's emit guard as an unhandled rejection. + if (component?.logging) { updateLogger(mainLogger.forComponent(name), component.logging, name); } else if (mainLogger.hasComponent(name)) { const componentLogger = mainLogger.forComponent(name); @@ -399,6 +413,8 @@ module.exports = { // we can start using the RootConfigWatcher start: updateLogSettings, startOnMainThread: updateLogSettings, + // Test-only: applies a config without the process-wide watcher `updateLogSettings` builds. + _applyLogSettingsForTests: applyLogSettings, errorToString, errorForLog, inspectForLog, diff --git a/utility/watcherFallback.ts b/utility/watcherFallback.ts index 3639c1c788..a9c10779dd 100644 --- a/utility/watcherFallback.ts +++ b/utility/watcherFallback.ts @@ -11,7 +11,6 @@ import { loggerWithTag } from './logging/harper_logger.ts'; // One-time process-wide warning so a thundering herd of failing watchers doesn't // produce hundreds of identical log lines. let exhaustionWarned = false; -const partialReadWarned = new Set(); const fallbackLogger = loggerWithTag('watcher'); @@ -221,124 +220,3 @@ export function guardedWatch(paths: string | string[], options?: ChokidarOptions export function _lostNativeWatchCountForTests(): number { return lostNativeWatchCount; } - -/** - * A config file replaced in place (truncate, then write) can be read back empty or - * half-written, and chokidar may emit nothing further for that write — so a watcher that - * simply drops the unusable read would serve stale config until something else touched the - * file. Re-read on a later turn instead, bounded so a genuinely empty or corrupt file cannot - * spin. Callers read synchronously, so the descriptor still never outlives a single turn. - */ -const PARTIAL_READ_REREAD_DELAY_MS = 20; -const PARTIAL_READ_MAX_REREADS = 10; - -export class PartialReadRetry { - #filePath: string; - #timer?: ReturnType; - #remaining: number = PARTIAL_READ_MAX_REREADS; - #closed = false; - - constructor(filePath: string) { - this.#filePath = filePath; - } - - /** False once the budget is spent, so the caller can fall back to its own error handling. */ - schedule(reread: () => void): boolean { - if (this.#closed) return false; - if (this.#timer) return true; - if (this.#remaining <= 0) return false; - this.#remaining--; - this.#timer = setTimeout(() => { - this.#timer = undefined; - reread(); - }, PARTIAL_READ_REREAD_DELAY_MS); - this.#timer.unref?.(); - return true; - } - - /** A usable read arrived, so any re-read still armed for the previous one would duplicate it. */ - settled() { - if (this.#timer) clearTimeout(this.#timer); - this.#timer = undefined; - this.#remaining = PARTIAL_READ_MAX_REREADS; - // The file recovered, so the next time it breaks is a new incident and has to be reported - // again rather than silenced by the warning it emitted weeks ago. - partialReadWarned.delete(this.#filePath); - } - - /** - * The budget is spent. Distinct from `settled()` in that the report stands — the file has not - * recovered, and it is shared with every other watcher of it. The budget itself is restored, - * because the next event may be the repair, and that repair can be observed mid-write too. - * Returns whether this give-up was the one reported. - */ - gaveUp(error?: unknown): boolean { - if (this.#closed) return false; - this.#remaining = PARTIAL_READ_MAX_REREADS; - return warnPartialReadGaveUp(this.#filePath, error); - } - - /** Terminal: the watcher is closing, so nothing may re-arm the re-read or report on it. */ - cancel() { - if (this.#timer) clearTimeout(this.#timer); - this.#timer = undefined; - this.#closed = true; - } -} - -/** - * ENOENT is excluded not because it cannot be transient, but because it already has an answer: - * `OptionsWatcher` routes it to `remove` (env-only fallback at boot, then removal), and - * `RootConfigWatcher` keeps its last config rather than tearing down core features on a file - * that may just be mid-replace. Re-reading would only delay a decision already made. - */ -export function isPartialReadError(error: unknown): boolean { - return !(typeof error === 'object' && error !== null && (error as { code?: string }).code === 'ENOENT'); -} - -/** - * A watcher that exhausts its re-read budget serves stale config from then on, so the give-up - * has to be visible — otherwise the only symptom is a config change that silently did nothing. - * Warned once per file: every root-config scope watches the same one and would otherwise report - * a single bad file once each, on every event. - */ -export function warnPartialReadGaveUp(filePath: string, error?: unknown): boolean { - if (partialReadWarned.has(filePath)) return false; - partialReadWarned.add(filePath); - // The cause matters to whoever has to fix it: a file that never parses is a typo to correct, - // while one that reads empty is a writer that never finished. Report the kind and position - // only — a YAML parse error's message quotes the offending source, and this file holds - // credentials. - const cause = error ? `: ${describeReadFailure(error)}` : ' that were empty or incomplete'; - fallbackLogger.warn(`Gave up re-reading ${filePath} after ${PARTIAL_READ_MAX_REREADS} unusable reads${cause}`); - return true; -} - -/** - * The kind and position of a failed config read, never its content: a YAML parse error's message - * quotes the offending source lines, and these files hold credentials. - */ -export function describeReadFailure(error: unknown): string { - if (typeof error !== 'object' || error === null) return 'unusable'; - const { name, code, linePos } = error as { name?: string; code?: string; linePos?: { line: number; col: number }[] }; - const at = linePos?.[0] ? ` at line ${linePos[0].line}, column ${linePos[0].col}` : ''; - return `${code ?? name ?? 'unusable'}${at}`; -} - -/** Test-only: whether a give-up warning for this file is currently suppressed as a duplicate. */ -export function isPartialReadWarned(filePath: string): boolean { - return partialReadWarned.has(filePath); -} - -/** Test-only: forget that this file was reported, so a suite can start from a known state. */ -export function clearPartialReadWarning(filePath: string) { - partialReadWarned.delete(filePath); -} - -/** - * A listener that throws while applying new config is a bug in that listener, not evidence the - * file was half-written — the watcher's own state is already updated, so it keeps going. - */ -export function warnWatcherListenerError(filePath: string, error: unknown) { - fallbackLogger.warn(`Error applying a configuration change from ${filePath}`, error); -}