diff --git a/middleware/src/index.ts b/middleware/src/index.ts index 2fe2073e..536fa893 100644 --- a/middleware/src/index.ts +++ b/middleware/src/index.ts @@ -250,6 +250,7 @@ import { retryErroredPlugins, runLegacyBootstrap, } from './plugins/bootstrap.js'; +import { warmPatternWorker } from './plugins/setupFieldPattern.js'; import { BuiltInPackageStore } from './plugins/builtInPackageStore.js'; import { LocalDevPackageStore } from './plugins/localDevPackageStore.js'; import { FileSecretVault, resolveMasterKey } from './secrets/fileVault.js'; @@ -4424,6 +4425,12 @@ async function main(): Promise { // IPv4 (legacy + local dev) clients are served. Default `0.0.0.0` would // miss IPv6-only Fly-internal traffic — Stolperfalle #4 in // memory/feedback-fly-operational. + // Boot the setup-field pattern worker now, so the first operator to save a + // plugin credential does not pay thread creation inside their request's + // match budget (#607). Fire-and-forget: the worker is created on demand + // anyway, this only moves the cost off the critical path. + void warmPatternWorker(); + const server = app.listen(config.PORT, config.HOST, () => { console.log(`[middleware] listening on [${config.HOST}]:${config.PORT}`); console.log(`[middleware] skills dir: ${config.SKILLS_DIR}`); diff --git a/middleware/src/plugins/setupFieldPattern.ts b/middleware/src/plugins/setupFieldPattern.ts index 26a9461e..cdb45b2b 100644 --- a/middleware/src/plugins/setupFieldPattern.ts +++ b/middleware/src/plugins/setupFieldPattern.ts @@ -83,11 +83,38 @@ export const MAX_PATTERN_SOURCE_LENGTH = 512; export const MAX_PATTERN_INPUT_LENGTH = 8192; /** - * Wall-clock budget for one match, enforced by terminating the worker. Setup - * writes are rare and admin-only, so a generous bound costs nothing; a sane - * credential pattern completes in microseconds. + * Wall-clock budget for one match, enforced by terminating the worker. The + * clock starts when the worker has ACKNOWLEDGED it is ready to take work (see + * {@link ensureWorker}), so this bounds regex execution plus one IPC round + * trip — not thread creation and not module evaluation. + * + * WHY 250 AND NOT 50. The budget is not what protects the event loop; the + * worker boundary is. A runaway regex burns a thread that nothing else is + * waiting on, so the only thing this number really bounds is how long ONE + * admin-only setup write waits before giving up. Making it tight buys no + * safety and costs correctness: the first revision used 50 ms while the + * measured IPC floor alone was 4-36 ms on an idle machine, so a loaded host + * rejected valid values with no regex work to speak of (#607). 250 ms leaves + * an order of magnitude of headroom over the floor and is still imperceptible + * on a form submit. + */ +export const PATTERN_MATCH_BUDGET_MS = 250; + +/** + * How many times in a row a pattern must overrun before it is reported to the + * operator as unusable. + * + * An overrun is evidence about ONE execution — the host may simply have been + * busy — whereas {@link getPatternProblems} is a durable statement about the + * PATTERN. Conflating the two let a single unlucky match permanently label a + * healthy pattern "format check could not be applied" for the life of the + * process (#607). A genuinely hostile pattern overruns every time and trips + * this within three writes; a valid one recovers and resets the count. + * + * The individual write still fails CLOSED on the very first overrun. Only the + * durable verdict waits for corroboration. */ -export const PATTERN_MATCH_BUDGET_MS = 50; +export const PATTERN_OVERRUN_STRIKES = 3; /** Deepest group nesting the allowlist accepts (root counts as depth 0). */ const MAX_GROUP_DEPTH = 2; @@ -102,7 +129,8 @@ const MAX_GROUP_DEPTH = 2; * the `+` form the allowlist has always accepted, not a new one. (V8 compiles * counted repetition with a counter rather than unrolling it, so a huge bound * is not a compile-time blowup either: `^a{100000,}$` compiles AND matches a - * 100k subject in 0.43 ms.) The load-bearing bound is the 50 ms worker budget. + * 100k subject in 0.43 ms.) The load-bearing bound is the worker budget, see + * {@link PATTERN_MATCH_BUDGET_MS}. * * The cap is kept because it is free and it keeps an untrusted manifest from * naming an arbitrary number, and it is kept at 100 rather than raised because @@ -477,10 +505,34 @@ function compileUncached(source: string, context: string): CacheEntry { } } -/** Test-only: clears the compile cache and problem registry. */ +/** + * Consecutive budget overruns per `context|pattern`, reset by any completed + * match. See {@link PATTERN_OVERRUN_STRIKES}. + */ +const overrunStrikes = new Map(); + +/** + * Record one overrun. Returns true once the pattern has overrun + * {@link PATTERN_OVERRUN_STRIKES} times in a row — i.e. once it is fair to + * call the PATTERN broken rather than blaming a busy host. + */ +function noteOverrun(context: string, pattern: string): boolean { + const key = `${context}|${pattern}`; + const strikes = (overrunStrikes.get(key) ?? 0) + 1; + overrunStrikes.set(key, strikes); + return strikes >= PATTERN_OVERRUN_STRIKES; +} + +/** Any completed match clears the pattern's strike count. */ +function clearOverrunStrikes(context: string, pattern: string): void { + overrunStrikes.delete(`${context}|${pattern}`); +} + +/** Test-only: clears the compile cache, problem registry and strike counts. */ export function resetSetupPatternCache(): void { compiled.clear(); problems.length = 0; + overrunStrikes.clear(); } // --------------------------------------------------------------------------- @@ -505,6 +557,14 @@ parentPort.on('message', (msg) => { } parentPort.postMessage({ id: msg.id, matched, error }); }); +// Readiness HANDSHAKE — the whole point of #607. The 'online' event fires when +// the THREAD starts, which is well before this module has been evaluated and +// the listener above exists. Under tsx the gap is the loader re-running, which +// measured 84-212 ms; on a cold start it measured ~838 ms. Anything that waits +// on 'online' therefore charges module evaluation to the match budget and +// rejects valid values. This message is the only trustworthy "I can take work +// now" signal, so it is what the parent waits for. +parentPort.postMessage({ ready: true }); `; interface WorkerReply { @@ -513,6 +573,19 @@ interface WorkerReply { readonly error: string | null; } +/** Sent once by the worker when its message handler is installed. */ +interface WorkerHandshake { + readonly ready: true; +} + +function isHandshake(raw: unknown): raw is WorkerHandshake { + return ( + typeof raw === 'object' && + raw !== null && + (raw as { ready?: unknown }).ready === true + ); +} + let worker: Worker | null = null; let workerReady: Promise | null = null; let requestId = 0; @@ -525,17 +598,35 @@ function ensureWorker(): { w: Worker; ready: Promise } { return { w: worker, ready: workerReady }; } const w = new Worker(WORKER_SOURCE, { eval: true }); - // Starts REF'd so thread boot cannot be starved by an otherwise-idle event - // loop, then unrefs itself: an idle pattern worker must never be the reason - // the process (or a test run) refuses to exit. + // Readiness waits for the worker's own handshake, NOT for 'online' — see + // WORKER_SOURCE. The boot timeout resolves anyway rather than rejecting: a + // worker that never handshakes still degrades to an overrun on the first + // match, which is the same fail-closed path a wedged regex takes, instead of + // turning a broken thread pool into a 500. const ready = new Promise((resolve) => { - const boot = setTimeout(resolve, WORKER_BOOT_TIMEOUT_MS); - boot.unref(); - w.once('online', () => { + // The worker stays REF'd until it has handshaked. Unref'ing earlier (on + // 'online', as an intermediate revision did) is a deadlock: nothing else + // holds the event loop open while we await the handshake, so on an + // otherwise-idle loop node settles and the promise never resolves. That + // surfaced as "Promise resolution is still pending but the event loop has + // already resolved" across the whole suite on node 22. + const settle = (): void => { clearTimeout(boot); + w.off('message', onHandshake); + // Past this point an IDLE pattern worker must never be the reason the + // process (or a test run) refuses to exit. An in-flight match is held + // open by its own budget timer, not by the worker handle. w.unref(); resolve(); - }); + }; + const boot = setTimeout(settle, WORKER_BOOT_TIMEOUT_MS); + boot.unref(); + const onHandshake = (raw: unknown): void => { + if (!isHandshake(raw)) return; + settle(); + }; + w.on('message', onHandshake); + w.once('error', settle); }); const drop = (): void => { if (worker === w) { @@ -552,57 +643,89 @@ function ensureWorker(): { w: Worker; ready: Promise } { export type MatchOutcome = 'match' | 'no-match' | 'overrun'; +/** + * Internal outcome. `'timeout'` is evidence about the PATTERN (it burned the + * budget); `'worker-failed'` is evidence about the WORKER (it died, or never + * came up) and says nothing about the regex at all. Both surface publicly as + * `'overrun'`, but only the first is worth a retry decision — see + * {@link matchWithBudget}. + */ +type RunOutcome = MatchOutcome | 'timeout' | 'worker-failed'; + +/** One attempt, on whatever worker is current. Never throws. */ +async function runOnce(regex: RegExp, value: string): Promise { + const { w, ready } = ensureWorker(); + await ready; + const id = (requestId += 1); + return await new Promise((resolve) => { + let settled = false; + const finish = (outcome: RunOutcome): void => { + if (settled) return; + settled = true; + clearTimeout(timer); + w.off('message', onMessage); + w.off('error', onFailure); + w.off('exit', onFailure); + resolve(outcome); + }; + // The clock starts HERE, after `await ready` — i.e. after the worker's + // handshake — so it measures the match, not the thread's birth. + const timer = setTimeout(() => { + finish('timeout'); + if (worker === w) { + worker = null; + workerReady = null; + } + void w.terminate(); + }, PATTERN_MATCH_BUDGET_MS); + const onMessage = (raw: unknown): void => { + if (isHandshake(raw)) return; // late handshake from a warm-up race + const reply = raw as WorkerReply | null; + if (!reply || reply.id !== id) return; + if (reply.error !== null) { + // The pattern did not compile inside the worker. That is a property of + // the pattern, so it counts as a pattern-side failure. + finish('timeout'); + return; + } + finish(reply.matched ? 'match' : 'no-match'); + }; + const onFailure = (): void => { + finish('worker-failed'); + }; + w.on('message', onMessage); + w.on('error', onFailure); + w.on('exit', onFailure); + w.postMessage({ id, source: regex.source, flags: regex.flags, value }); + }); +} + /** * Run `regex` against `value` in a worker under {@link PATTERN_MATCH_BUDGET_MS}. * * Returns `'overrun'` when the budget expired (the worker is terminated and * discarded — a wedged regex cannot be interrupted any other way), when the - * worker died, or when the pattern failed to compile inside the worker. + * worker could not be kept alive, or when the pattern failed to compile inside + * the worker. + * + * A dead worker is retried ONCE on a fresh thread. That is not leniency toward + * runaway patterns — a budget expiry is never retried, so a hostile pattern + * still costs exactly one budget — it only stops an unrelated thread death + * (the previous caller's terminate landing on this caller's worker) from being + * reported as "your value is invalid". */ export async function matchWithBudget( regex: RegExp, value: string, ): Promise { const run = async (): Promise => { - const { w, ready } = ensureWorker(); - await ready; - const id = (requestId += 1); - return await new Promise((resolve) => { - let settled = false; - const finish = (outcome: MatchOutcome): void => { - if (settled) return; - settled = true; - clearTimeout(timer); - w.off('message', onMessage); - w.off('error', onFailure); - w.off('exit', onFailure); - resolve(outcome); - }; - const timer = setTimeout(() => { - finish('overrun'); - if (worker === w) { - worker = null; - workerReady = null; - } - void w.terminate(); - }, PATTERN_MATCH_BUDGET_MS); - const onMessage = (raw: unknown): void => { - const reply = raw as WorkerReply | null; - if (!reply || reply.id !== id) return; - if (reply.error !== null) { - finish('overrun'); - return; - } - finish(reply.matched ? 'match' : 'no-match'); - }; - const onFailure = (): void => { - finish('overrun'); - }; - w.on('message', onMessage); - w.on('error', onFailure); - w.on('exit', onFailure); - w.postMessage({ id, source: regex.source, flags: regex.flags, value }); - }); + let outcome = await runOnce(regex, value); + if (outcome === 'worker-failed') { + outcome = await runOnce(regex, value); + } + return outcome === 'timeout' || outcome === 'worker-failed' + ? 'overrun' + : outcome; }; const result = queue.then(run, run); @@ -613,6 +736,22 @@ export async function matchWithBudget( return await result; } +/** + * Boot the pattern worker ahead of any request. Optional but wired into + * middleware startup: without it the FIRST operator to save a credential pays + * thread creation, which measured ~838 ms (#607). Idempotent, never throws, + * and cheap to skip — the worker is created on demand regardless. + */ +export async function warmPatternWorker(): Promise { + try { + const { ready } = ensureWorker(); + await ready; + } catch { + // A pattern worker that refuses to boot must not take startup with it; the + // on-demand path will retry and fail closed per write if it stays broken. + } +} + /** Test/shutdown seam: terminate the pooled worker. */ export async function shutdownPatternWorker(): Promise { const w = worker; @@ -725,19 +864,32 @@ export async function checkSetupFieldPattern( const outcome = await matchWithBudget(regex, value); if (outcome === 'overrun') { - // The pattern (not the value) is the problem, but we cannot prove the value - // is acceptable, so fail CLOSED for this write and make the pattern - // diagnosable. The operator sees the field's generic "wrong format" copy. + // We cannot prove the value is acceptable, so this WRITE fails closed and + // the operator sees the field's generic "wrong format" copy — unchanged. + // + // The durable verdict is a separate question. One overrun does not prove + // the pattern is broken; it may just be a busy host losing a race with the + // budget. Only a run of them earns an entry in the problems registry, + // because that entry is what tells the operator the field is permanently + // unchecked (#607). + const proven = noteOverrun(context, field.pattern); console.error( `[setup] pattern match exceeded ${PATTERN_MATCH_BUDGET_MS}ms for ${context}; ` + - `treating the value as a violation. pattern=${JSON.stringify(field.pattern)}`, - ); - recordProblem( - context, - field.pattern, - `match exceeded the ${PATTERN_MATCH_BUDGET_MS}ms execution budget`, + `treating the value as a violation. pattern=${JSON.stringify(field.pattern)}` + + (proven + ? ` — ${String(PATTERN_OVERRUN_STRIKES)} consecutive overruns, marking the pattern unusable.` + : ''), ); + if (proven) { + recordProblem( + context, + field.pattern, + `match exceeded the ${String(PATTERN_MATCH_BUDGET_MS)}ms execution budget ` + + `${String(PATTERN_OVERRUN_STRIKES)} times in a row`, + ); + } return violation; } + clearOverrunStrikes(context, field.pattern); return outcome === 'match' ? null : violation; } diff --git a/middleware/test/setupFieldPatternValidation.test.ts b/middleware/test/setupFieldPatternValidation.test.ts index 9ef4c19a..d0bea672 100644 --- a/middleware/test/setupFieldPatternValidation.test.ts +++ b/middleware/test/setupFieldPatternValidation.test.ts @@ -23,6 +23,7 @@ import { resetSetupPatternCache, screenPatternSource, shutdownPatternWorker, + warmPatternWorker, MAX_PATTERN_INPUT_LENGTH, } from '../src/plugins/setupFieldPattern.js'; @@ -796,3 +797,168 @@ describe('OM-17 / F4 — server anchoring matches HTML `pattern=` semantics', () ); }); }); + +/** + * #607 — the budget has to bound the MATCH, not the worker's birth. + * + * The shipped first revision started its clock at dispatch and waited only for + * the worker's `'online'` event. `'online'` fires when the THREAD starts, which + * is well before the worker module has been evaluated — so module evaluation + * was charged to the match budget. Measured on a cold process: 838 ms for a + * trivial email pattern. Under `node --import tsx` — which is exactly how this + * suite runs — every call overran, because the worker re-runs tsx's loader. + * + * That is the point of running these assertions here rather than in a + * hand-driven script: if the handshake regresses, the tsx path breaks first and + * these tests are the ones that notice. + */ +describe('#607 — the match budget must not include worker startup', () => { + beforeEach(() => { + resetSetupPatternCache(); + }); + + after(async () => { + await shutdownPatternWorker(); + }); + + it('a trivial match on a COLD worker stays well inside the budget', async () => { + // Force a genuinely cold worker: this is the 838 ms case. + await shutdownPatternWorker(); + const field = { + key: 'gw_subject_default', + pattern: '^[^@\\s]+@[^@\\s]+\\.[A-Za-z]{2,63}$', + }; + const started = Date.now(); + const violation = await checkSetupFieldPattern( + field, + 'assistant@te-printline.de', + ); + const elapsed = Date.now() - started; + + assert.equal(violation, null, 'a valid address was rejected on a cold worker'); + // The whole call may legitimately take longer than the budget — it includes + // thread creation. What must NOT happen is the value being rejected, or the + // pattern being blamed, because of that startup cost. + assert.deepEqual( + getPatternProblems(), + [], + `a healthy pattern was marked unusable after a ${String(elapsed)}ms cold start`, + ); + }); + + it('warmPatternWorker is idempotent and leaves the worker usable', async () => { + await shutdownPatternWorker(); + await warmPatternWorker(); + await warmPatternWorker(); + assert.equal(await matchWithBudget(/^a+$/, 'aaa'), 'match'); + }); + + it('repeated cold starts never reject a valid value', async () => { + const field = { key: 'k', pattern: '^[a-z]+@[a-z]+\\.[a-z]{2,63}$' }; + for (let i = 0; i < 3; i += 1) { + await shutdownPatternWorker(); + assert.equal( + await checkSetupFieldPattern(field, 'ops@example.de'), + null, + `cold start #${String(i + 1)} rejected a valid value`, + ); + } + assert.deepEqual(getPatternProblems(), []); + }); +}); + +/** + * #607 — an overrun is evidence about ONE execution, not about the pattern. + * + * `getPatternProblems()` is what surfaces "this field declares a format check + * that could not be applied" to the operator, for the life of the process. The + * first revision wrote into it on the very first overrun, so a single unlucky + * match permanently mislabelled a healthy pattern. The write still fails closed + * immediately; only the durable verdict now waits for corroboration. + */ +describe('#607 — one overrun must not permanently blame the pattern', () => { + beforeEach(() => { + resetSetupPatternCache(); + }); + + after(async () => { + await shutdownPatternWorker(); + }); + + /** + * Passes the allowlist — deliberately. Every quantifier sits on a bare + * character class, so no "quantified group containing a quantifier" rule + * fires; the cost comes from four adjacent unbounded runs splitting a + * non-matching subject every possible way. This is precisely the shape the + * allowlist cannot catch and the execution bound must. + * + * Calibrated by measurement on node 22, first call in a fresh process: + * + * 'a'*100 + '!' → 10 ms 'abcd' → 0 ms + * 'a'*200 + '!' → 125 ms + * 'a'*400 + '!' → 1604 ms + * + * SLOW_SUBJECT sits an order of magnitude past the 250 ms budget so the + * overrun is not a race, and FAST_SUBJECT completes immediately — the SAME + * pattern, which is what makes the reset test meaningful (strikes are keyed + * by context AND pattern). + * + * A NOTE ON MEASURING THIS, because it cost a round: V8 caches compiled + * regexes by source, so timing a subject AFTER another subject has already + * run the same source reports the warm number. An earlier revision of this + * test picked a subject that measured 0.011 ms that way and was 2152 ms on a + * cold first call. Always measure the first call in a fresh process. + */ + const SLOW_PATTERN = '^[a-z]+[a-z]+[a-z]+[a-z]+$'; + const SLOW_SUBJECT = `${'a'.repeat(500)}!`; + const FAST_SUBJECT = 'abcd'; + + it('the allowlist really does accept this pattern (so the bound is what stops it)', () => { + assert.equal(screenPatternSource(SLOW_PATTERN), null); + }); + + it('the first overrun rejects the write but does NOT record a problem', async () => { + const field = { key: 'slow', pattern: SLOW_PATTERN }; + const violation = await checkSetupFieldPattern(field, SLOW_SUBJECT); + assert.equal(violation?.field, 'slow', 'the write must still fail closed'); + assert.deepEqual( + getPatternProblems(), + [], + 'a single overrun must not mark the pattern unusable', + ); + }); + + it('three consecutive overruns do record a problem', async () => { + const field = { key: 'slow', pattern: SLOW_PATTERN }; + for (let i = 0; i < 3; i += 1) { + await checkSetupFieldPattern(field, SLOW_SUBJECT); + } + const problems = getPatternProblems(); + assert.equal(problems.length, 1, 'the pattern should now be reported'); + assert.equal(problems[0]?.context, 'slow'); + assert.match(String(problems[0]?.reason), /times in a row/); + }); + + it('a completed match resets the strike count', async () => { + const slow = { key: 'slow', pattern: SLOW_PATTERN }; + // Two strikes... + await checkSetupFieldPattern(slow, SLOW_SUBJECT); + await checkSetupFieldPattern(slow, SLOW_SUBJECT); + // ...then a value the SAME pattern disposes of immediately, proving the + // pattern was never the problem. + assert.equal( + await checkSetupFieldPattern(slow, FAST_SUBJECT), + null, + 'expected a clean match, not an overrun', + ); + assert.deepEqual( + getPatternProblems(), + [], + 'the run was broken by a completed match', + ); + // A third slow value is therefore only strike one again — without the + // reset this call would be the third and would record a problem. + await checkSetupFieldPattern(slow, SLOW_SUBJECT); + assert.deepEqual(getPatternProblems(), []); + }); +});