diff --git a/CHANGELOG.md b/CHANGELOG.md index c7371952..03a7b872 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,40 @@ All notable changes to the Health Intersections Node Server will be documented i The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [0.11.1] - 2026-07-30 + +### Added + +- Cooperative yielding for long terminology operations: after every 25ms of continuous compute the + operation yields the event loop (`checkAndYield`), so a heavy $expand can no longer stall every + other request on the server. Operations whose client has disconnected are aborted at their next + yield point instead of computing a response nobody will read +- The operation time limit is now configurable (`operationTimeLimit`, seconds) and defaults to 20s + (below common client timeouts, so clients see the too-costly OperationOutcome rather than a + socket timeout), and is measured against compute time consumed rather than wall-clock, so + concurrent operations time-sharing the event loop don't abort each other +- The Node Blocking chart on the status page now shows the worst single event-loop stall per + window as well as the mean + +### Fixed + +- fix whole-code-system SNOMED CT expansions blocking the server for 30 seconds and then failing: + the hierarchy walk read a non-existent `.code` property, so every concept was treated as a + duplicate of the first and no expansion size guard could ever stop the walk. This is what caused + the rash of client timeouts on tx.fhir.org after the 0.11.0 upgrade +- the hierarchy walk now visits each concept once rather than once per path to it (SNOMED CT is a + poly-hierarchy: the old walk made ~15.8M visits for ~520k concepts) +- restore the up-front too-costly refusal for expansions that cannot fit the expansion limit (the + totalCount size guard was silently dead - method read as a property); expansions with a + count/offset window inside the limit still succeed as partial, unclosed expansions +- re-enable the CPT 1000-code expansion cap (same method-read-as-property bug) +- fix parameter misalignment in the no-details expansion path (19 arguments passed to a + 20-parameter function) + +### Tx Conformance Statement + +FHIRsmith passed all 2729 HL7 terminology service tests (modes tx.fhir.org+omop+general+snomed, tests v1.9.2, runner v6.9.12) + ## [0.11.0] - 2026-mm-dd ### Added diff --git a/stats.js b/stats.js index f450b295..d5b0607d 100644 --- a/stats.js +++ b/stats.js @@ -37,6 +37,10 @@ class ServerStats { const requestsPerMin = minutesSinceStart > 0 ? requestsDelta / minutesSinceStart : 0; const loopDelay = this.eventLoopMonitor.mean / 1e6; + // Worst single stall in the window - the mean dilutes a multi-second + // event-loop block into noise; the max is what shows request-freezing + // stalls (see the 2026-07-30 tx.fhir.org incident). + const loopMax = this.eventLoopMonitor.max / 1e6; // Two distinct caches: the expansion cache (count entries) and the client // (resource) cache (count concepts held - a sense of how much it's carrying). let expansionItems = 0; @@ -50,7 +54,7 @@ class ServerStats { } } - this.history.push({time: now, mem: currentMem - this.startMem, rpm: requestsPerMin, tat: requestsTat, block: loopDelay, expansion: expansionItems, clientConcepts: clientConcepts}); + this.history.push({time: now, mem: currentMem - this.startMem, rpm: requestsPerMin, tat: requestsTat, block: loopDelay, blockMax: loopMax, expansion: expansionItems, clientConcepts: clientConcepts}); this.eventLoopMonitor.reset(); this.requestCountSnapshot = combinedCount; diff --git a/tests/tx/expand-snomed-whole.test.js b/tests/tx/expand-snomed-whole.test.js new file mode 100644 index 00000000..998748b8 --- /dev/null +++ b/tests/tx/expand-snomed-whole.test.js @@ -0,0 +1,173 @@ +/** + * Whole-code-system SNOMED CT expansion tests + * + * Regression tests for the 0.11.0 tx.fhir.org incident: expanding a value set + * that includes all of SNOMED CT (e.g. http://hl7.org/fhir/ValueSet/questionnaire-answers) + * walked every *path* of the SNOMED poly-hierarchy with `context.code` undefined + * for every concept, so the expansion collapsed onto a single map key, no size + * guard could ever fire, and each request blocked the event loop for the full + * 30-second deadCheck limit - timing out every other request on the server. + * + * These tests expand an include-all-of-SNOMED value set against the committed + * SNOMED test subset and pin the fixed behaviour: + * - enumeration returns real, distinct codes (not undefined) + * - the expansion is marked unclosed (grammar system) + * - a count/offset window inside the limit succeeds as a partial expansion + * - an expansion that cannot fit the limit is refused as too-costly up front + */ + +const fs = require('fs'); +const path = require('path'); +const express = require('express'); +const cors = require('cors'); +const request = require('supertest'); +const TXModule = require('../../tx/tx'); +const folders = require('../../library/folder-setup'); + +const SNOMED_URI = 'http://snomed.info/sct'; + +// The whole point of these tests is that expansion terminates promptly; if any +// of them takes anywhere near this long, the walk is broken again. +jest.setTimeout(60000); + +function allOfSnomedValueSet() { + return { + resourceType: 'ValueSet', + url: 'http://example.org/fhir/ValueSet/all-of-snomed', + status: 'active', + compose: { + include: [{ system: SNOMED_URI }] + } + }; +} + +function expandRequest(app, params = [], headers = {}) { + let req = request(app) + .post('/tx/r5/ValueSet/$expand') + .set('Accept', 'application/json') + .set('Content-Type', 'application/json'); + for (const [k, v] of Object.entries(headers)) { + req = req.set(k, v); + } + return req.send({ + resourceType: 'Parameters', + parameter: [ + { name: 'valueSet', resource: allOfSnomedValueSet() }, + ...params + ] + }); +} + +function hasUnclosedExtension(expansion) { + return (expansion.extension || []).some( + e => e.url === 'http://hl7.org/fhir/StructureDefinition/valueset-unclosed'); +} + +describe('Whole-code-system SNOMED expansion', () => { + let app; + let txModule; + + beforeAll(async () => { + // The library resolves source files against the terminology cache folder; + // put the committed test subset there under the name the fixture uses. + const committed = path.resolve(__dirname, '../../tx/data/snomed-testing.cache'); + const cacheFolder = folders.subDir('terminology-cache'); + const target = path.join(cacheFolder, 'snomed-testing.cache'); + if (!fs.existsSync(target)) { + fs.copyFileSync(committed, target); + } + + app = express(); + app.use(cors()); + app.use(express.json()); + app.use(express.urlencoded({ extended: true })); + + txModule = new TXModule(); + await txModule.initialize({ + librarySource: path.join(__dirname, 'fixtures', 'test-library-snomed.yaml'), + endpoints: [ + { path: '/tx/r5', fhirVersion: '5.0', context: null } + ] + }, app); + }, 60000); + + afterAll(async () => { + if (txModule) { + await txModule.shutdown(); + } + }); + + test('count=10 returns 10 real, distinct codes and is marked unclosed', async () => { + const response = await expandRequest(app, [{ name: 'count', valueInteger: 10 }]); + + expect(response.status).toBe(200); + expect(response.body.resourceType).toBe('ValueSet'); + const expansion = response.body.expansion; + expect(expansion).toBeDefined(); + expect(expansion.contains).toHaveLength(10); + + const codes = new Set(); + for (const c of expansion.contains) { + // Before the fix every entry had code undefined (context.code on a + // SnomedExpressionContext), which collapsed the expansion to one entry. + expect(typeof c.code).toBe('string'); + expect(c.code).toMatch(/^\d+$/); + expect(c.system).toBe(SNOMED_URI); + expect(c.display).toBeTruthy(); + codes.add(c.code); + } + expect(codes.size).toBe(10); + + // SNOMED is a grammar system: an enumeration of its precoordinated concepts + // is inherently incomplete, so the expansion must be marked unclosed. + expect(hasUnclosedExtension(expansion)).toBe(true); + }); + + test('full enumeration of the subset returns every concept exactly once', async () => { + const response = await expandRequest(app, []); + + expect(response.status).toBe(200); + const expansion = response.body.expansion; + expect(expansion).toBeDefined(); + + // The committed subset holds ~2k concepts - comfortably under the test + // limit, so the whole thing enumerates. Every code must be real and, with + // the visited-set fix, appear exactly once even though the subset is a + // poly-hierarchy (the old walk visited concepts once per path to them). + const codes = new Set(); + for (const c of expansion.contains) { + expect(typeof c.code).toBe('string'); + expect(c.code).toMatch(/^\d+$/); + codes.add(c.code); + } + expect(codes.size).toBe(expansion.contains.length); + expect(codes.size).toBeGreaterThan(1000); + expect(hasUnclosedExtension(expansion)).toBe(true); + }); + + test('a count window inside a small limit succeeds as a partial expansion', async () => { + // Client-supplied threshold of 50 << subset size: enumeration must stop at + // the limit and return the requested window rather than walking on. + const response = await expandRequest(app, [{ name: 'count', valueInteger: 10 }], + { 'x-too-costly-threshold': '50' }); + + expect(response.status).toBe(200); + const expansion = response.body.expansion; + expect(expansion.contains).toHaveLength(10); + for (const c of expansion.contains) { + expect(typeof c.code).toBe('string'); + expect(c.code).toMatch(/^\d+$/); + } + }); + + test('an expansion that cannot fit the limit is refused as too-costly', async () => { + // No count, threshold below the subset size: enumeration could only ever + // end in too-costly at the limit, so the request must be refused up front + // (this used to be dead code - cs.totalCount read a method as a property). + const response = await expandRequest(app, [], { 'x-too-costly-threshold': '50' }); + + expect(response.status).toBe(422); + expect(response.body.resourceType).toBe('OperationOutcome'); + expect(response.body.issue[0].code).toBe('too-costly'); + }); +}); diff --git a/tests/tx/fixtures/test-library-snomed.yaml b/tests/tx/fixtures/test-library-snomed.yaml new file mode 100644 index 00000000..d8c056e1 --- /dev/null +++ b/tests/tx/fixtures/test-library-snomed.yaml @@ -0,0 +1,9 @@ +# Test library for whole-code-system SNOMED expansion tests - loads the +# committed SNOMED test subset (copied into the terminology cache by the test's +# beforeAll) alongside the automatic R5 core loading. + +base: + url: https://storage.googleapis.com/tx-fhir-org + +sources: + - snomed:snomed-testing.cache diff --git a/tests/tx/operation-context-yield.test.js b/tests/tx/operation-context-yield.test.js new file mode 100644 index 00000000..620b3555 --- /dev/null +++ b/tests/tx/operation-context-yield.test.js @@ -0,0 +1,159 @@ +/** + * OperationContext checkAndYield tests + * + * checkAndYield is the cooperative-multitasking primitive added after the + * 2026-07-30 tx.fhir.org incident: long terminology operations run on the one + * Node event loop, and without yielding, a single heavy $expand blocks every + * other request (including /metadata) for its full duration. These tests pin: + * - compute is sliced: the event loop gets turns during a long computation + * - the operation deadline is charged against compute time, not wall-clock, + * so concurrent operations time-sharing the loop don't abort each other + * - a compute overrun still aborts with too-costly + * - an operation whose client has disconnected aborts at its next yield + */ + +const path = require('path'); +const { OperationContext } = require('../../tx/operation-context'); +const { LanguageDefinitions } = require('../../library/languages'); +const { I18nSupport } = require('../../library/i18nsupport'); + +jest.setTimeout(30000); + +let i18n; + +beforeAll(async () => { + const langDefs = await LanguageDefinitions.fromFiles(path.resolve(__dirname, '../../tx/data')); + i18n = new I18nSupport(path.resolve(__dirname, '../../translations'), langDefs); + await i18n.load(); +}); + +function makeContext(timeLimitSeconds) { + return new OperationContext('en', i18n, null, timeLimitSeconds); +} + +/** Burn CPU synchronously for ms milliseconds. */ +function spin(ms) { + const end = performance.now() + ms; + while (performance.now() < end) { /* burn */ } +} + +describe('OperationContext.checkAndYield', () => { + + test('lets the event loop run during a long computation', async () => { + const ctx = makeContext(30); + let ticks = 0; + const interval = setInterval(() => ticks++, 5); + try { + // Control: synchronous compute starves the timer - no callback can run + // between here and the assertion because nothing yields. + const before = ticks; + spin(120); + expect(ticks).toBe(before); + + // The same amount of compute interleaved with checkAndYield gives the + // event loop turns, so the timer fires while we "work". + const start = performance.now(); + while (performance.now() - start < 120) { + spin(5); + await ctx.checkAndYield('test-loop'); + } + expect(ticks).toBeGreaterThan(before); + } finally { + clearInterval(interval); + } + }); + + test('deadline is charged against compute time, not wall-clock', async () => { + // Two operations time-sharing the loop: each does ~250ms of compute, so + // together they take >=500ms of wall time - but each op's own budget is + // only charged for its slices. Under the old wall-clock deadline, ops + // running concurrently would move each other toward abort; under the + // compute deadline they don't. + const budgetSeconds = 10; + const ctxA = makeContext(budgetSeconds); + const ctxB = makeContext(budgetSeconds); + + async function work(ctx, computeMs) { + const sliceMs = 5; + for (let done = 0; done < computeMs; done += sliceMs) { + spin(sliceMs); + await ctx.checkAndYield('shared-loop'); + } + // Snapshot at completion: computeElapsed includes the currently-open + // slice, so reading it later (while the other op still runs) would + // overstate this op's charge. + return ctx.computeElapsed(); + } + + const wallStart = performance.now(); + const [computeA, computeB] = await Promise.all([work(ctxA, 250), work(ctxB, 250)]); + const wall = performance.now() - wallStart; + + // Both ran to completion; total wall time covers both ops' compute... + expect(wall).toBeGreaterThanOrEqual(450); + // ...but each op was only charged (roughly) its own compute, not the time + // it spent suspended while the other op held the loop. + expect(computeA).toBeLessThan(wall - 100); + expect(computeB).toBeLessThan(wall - 100); + expect(computeA).toBeGreaterThanOrEqual(200); + expect(computeB).toBeGreaterThanOrEqual(200); + }); + + test('a compute overrun still aborts with too-costly', async () => { + const ctx = makeContext(0.15); // 150ms compute budget + let error = null; + try { + const guard = performance.now() + 10000; // never loop forever on failure + while (performance.now() < guard) { + spin(5); + await ctx.checkAndYield('overrun-loop'); + } + } catch (e) { + error = e; + } + expect(error).not.toBeNull(); + expect(error.cause).toBe('too-costly'); + expect(error.msgId).toMatch(/exceeded time limit/); + expect(error.abandoned).toBeUndefined(); + }); + + test('aborts at the next yield when the client has disconnected', async () => { + const ctx = makeContext(30); + ctx.markClientGone(); + let error = null; + try { + const guard = performance.now() + 10000; + while (performance.now() < guard) { + spin(5); + await ctx.checkAndYield('abandoned-loop'); + } + } catch (e) { + error = e; + } + expect(error).not.toBeNull(); + expect(error.abandoned).toBe(true); + expect(error.msgId).toMatch(/client disconnected/); + }); + + test('copy() shares the compute budget with sub-operations', async () => { + const ctx = makeContext(0.15); // 150ms shared budget + let error = null; + try { + const guard = performance.now() + 10000; + while (performance.now() < guard) { + // Alternate compute between the parent and a copy (as batch processing + // does per entry): the budget must be drawn down jointly, so the batch + // as a whole is bounded, not each entry separately. + const sub = ctx.copy(); + spin(5); + await ctx.checkAndYield('parent-loop'); + spin(5); + await sub.checkAndYield('sub-loop'); + } + } catch (e) { + error = e; + } + expect(error).not.toBeNull(); + expect(error.cause).toBe('too-costly'); + }); +}); diff --git a/tx/html/home-metrics.liquid b/tx/html/home-metrics.liquid index 8816b4d9..2eac7394 100644 --- a/tx/html/home-metrics.liquid +++ b/tx/html/home-metrics.liquid @@ -221,23 +221,38 @@ data: { labels: historyData.map(d => formatTime(d.time)), datasets: [{ + label: 'mean', data: historyData.map(d => d.block), borderColor: '#2845a7', backgroundColor: 'rgba(40, 69, 167, 0.1)', fill: true, tension: 0.3, pointRadius: 2 + }, { + // Worst single event-loop stall in the window: the mean dilutes a + // multi-second block into noise, so this is the line that shows + // request-freezing stalls. + label: 'max', + data: historyData.map(d => d.blockMax), + borderColor: '#a72828', + fill: false, + tension: 0.3, + pointRadius: 2 }] }, options: { ...chartOptions, + plugins: { + ...chartOptions.plugins, + legend: { display: true } + }, scales: { ...chartOptions.scales, y: { ...chartOptions.scales.y, title: { display: true, - text: 'points' + text: 'ms' } } } diff --git a/tx/operation-context.js b/tx/operation-context.js index 1f9ae16b..ef3458ab 100644 --- a/tx/operation-context.js +++ b/tx/operation-context.js @@ -556,6 +556,15 @@ const MEMORY_LIMIT = readMemoryLimit(); const MEMORY_FRACTION = 0.98; const MEMORY_THRESHOLD = MEMORY_LIMIT > 0 ? MEMORY_LIMIT * MEMORY_FRACTION : 0; // 90% of cgroup limit const CHECK_FREQUENCY = 100; +// How long an operation may compute without yielding the event loop (ms). +// Node runs all JS on one thread: while a long operation executes, no other +// request is serviced - awaiting in-memory promises does not help, because +// resolved promises only bounce through the microtask queue, which runs before +// I/O. checkAndYield() awaits a real setImmediate every YIELD_INTERVAL ms of +// compute, so pending I/O (new connections, /metadata, timers) runs between +// slices and one heavy $expand can no longer time out every other client. +const YIELD_INTERVAL = 25; +const { setImmediate: yieldToEventLoop } = require('timers/promises'); class OperationContext { // Shared counter across all instances — only check RSS every CHECK_FREQUENCY calls @@ -584,6 +593,24 @@ class OperationContext { // Shared by reference with copy()'d contexts so a sub-operation's // providers are cleaned up by the parent request's closeProviders(). this._openProviders = []; + // Compute-time accounting for the deadline and for yielding. One object, + // shared by reference with copy()'d contexts, so an operation and its + // sub-operations (e.g. batch entries) draw down a single budget: + // - compute: ms of compute consumed in completed slices + // - sliceStart: when the current compute slice began + // - lastYield: when we last gave the event loop a turn + // - clientGone: set when the client disconnects before the response is sent + // The deadline is measured in COMPUTE time, not wall-clock: once operations + // time-share the event loop, wall-clock deadlines make concurrency itself + // cause aborts (N ops each take N x as long), which turns client retries + // into a failure amplifier. An operation that waited is not too costly; + // one that consumed its compute budget is. + this._clock = { + compute: 0, + sliceStart: this.startTime, + lastYield: this.startTime, + clientGone: false + }; this.timeTracker.step('tx-op'); } @@ -616,6 +643,8 @@ class OperationContext { // Share the same provider-cleanup list so providers opened by the copy // are released when the parent operation ends. newContext._openProviders = this._openProviders; + // Share the compute clock: sub-operations spend the parent's budget. + newContext._clock = this._clock; return newContext; } @@ -646,8 +675,10 @@ class OperationContext { } OperationContext._checkCounter = 0; - // Time check - const elapsed = performance.now() - this.startTime; + // Time check - against compute time consumed, not wall clock (see _clock in + // the constructor). For operations that never yield the two are identical, + // so this changes nothing for paths that don't use checkAndYield(). + const elapsed = this.computeElapsed(); if (elapsed > this.timeLimit) { const timeInSeconds = Math.round(this.timeLimit / 1000); this.log(`Operation took too long @ ${place} (${this.constructor.name})`); @@ -674,6 +705,64 @@ class OperationContext { return false; } + /** + * Compute time this operation has consumed (ms): completed slices plus the + * slice currently executing. Equals wall-clock elapsed for operations that + * never yield. + * @returns {number} + */ + computeElapsed() { + return this._clock.compute + (performance.now() - this._clock.sliceStart); + } + + /** + * Mark that the client for this operation disconnected before the response + * was sent. The operation is aborted at its next yield point - there is no + * one left to send the result to. (Wired up by the request middleware from + * the response 'close' event.) + */ + markClientGone() { + this._clock.clientGone = true; + } + + /** + * deadCheck plus cooperative yielding: call this (awaited) from long-running + * loops in async code. Runs the normal deadCheck, and after every + * YIELD_INTERVAL ms of continuous compute awaits a real setImmediate so the + * event loop can service pending I/O - other requests keep getting answered + * while this operation works. On resuming from a yield, aborts if the client + * has disconnected in the meantime. + * + * Sync call sites keep using deadCheck(); the async loops that surround them + * yield on their behalf, which caps unbroken compute at one loop iteration. + * + * @param {string} place - Location identifier for debugging + */ + async checkAndYield(place = 'unknown') { + this.deadCheck(place); + if (this.debugging) { + return; + } + const now = performance.now(); + if (now - this._clock.lastYield >= YIELD_INTERVAL) { + // Close off this compute slice before suspending, so time spent waiting + // for our next turn is not charged against the deadline. + this._clock.compute += now - this._clock.sliceStart; + await yieldToEventLoop(); + const resumed = performance.now(); + this._clock.sliceStart = resumed; + this._clock.lastYield = resumed; + if (this._clock.clientGone) { + this.log(`Operation abandoned @ ${place}: client disconnected`); + const error = new Issue("error", "too-costly", null, + `Operation abandoned at ${place}: the client disconnected before the response was ready`); + error.abandoned = true; + error.diagnostics = this.diagnostics(); + throw error; + } + } + } + unSeeAll() { this.contexts = []; } diff --git a/tx/tx.js b/tx/tx.js index 3f829031..edffdade 100644 --- a/tx/tx.js +++ b/tx/tx.js @@ -291,9 +291,15 @@ class TXModule { // Get Accept-Language header for language preferences const acceptLanguage = req.get('Accept-Language') || 'en'; - // Create operation context with language, ID, time limit, and caches + // Create operation context with language, ID, time limit, and caches. + // The time limit is a compute-time budget (see OperationContext._clock) + // and is configurable (config.operationTimeLimit, seconds). The default + // sits deliberately under common client timeouts (okhttp reads give up at + // 10-30s): if the server's limit is >= the client's, the client hangs up + // first and the carefully-built too-costly OperationOutcome is written to + // a socket nobody is reading. const opContext = new OperationContext( - acceptLanguage, this.i18n, requestId, 30, + acceptLanguage, this.i18n, requestId, this.config.operationTimeLimit ?? 20, endpointInfo.resourceCache, endpointInfo.expansionCache ); opContext.usageTracker = this.usageTracker; @@ -325,6 +331,16 @@ class TXModule { res.on('finish', releaseProviders); res.on('close', releaseProviders); + // If the connection closes before the response was completed, the client + // has given up (timeout, cancelled build, dropped connection). Mark the + // operation so it aborts at its next yield point instead of computing a + // response nobody will read. + res.on('close', () => { + if (!res.writableEnded) { + opContext.markClientGone(); + } + }); + // Add X-Request-Id header to response res.setHeader('X-Request-Id', requestId); diff --git a/tx/workers/expand.js b/tx/workers/expand.js index dc1fc013..c740f34f 100644 --- a/tx/workers/expand.js +++ b/tx/workers/expand.js @@ -314,14 +314,20 @@ class ValueSetExpander { return null; } - if (cs != null && cs.expandLimitation > 0) { - let cnt = this.csCounter.get(cs.system); + // expandLimitation() caps how many codes a single code system may contribute + // (e.g. CPT limits enumeration to 1000 codes by agreement with the AMA). + // NB: expandLimitation and system are methods - reading them as properties + // (cs.expandLimitation > 0) compares the function object and is always false, + // which silently disabled this cap. + const expandLimit = cs != null ? cs.expandLimitation() : 0; + if (expandLimit > 0) { + let cnt = this.csCounter.get(cs.system()); if (cnt == null) { cnt = new ValueSetCounter(); - this.csCounter.set(cs.system, cnt); + this.csCounter.set(cs.system(), cnt); } cnt.increment(); - if (cnt.count > cs.expandLimitation) { + if (cnt.count > expandLimit) { return null; } } @@ -566,7 +572,7 @@ class ValueSetExpander { this.checkResourceCanonicalStatus(expansion, vs, this.valueSet); for (const c of vs.expansion.contains || []) { - this.worker.deadCheck('importValueSet'); + await this.worker.checkAndYield('importValueSet'); count += await this.importValueSetItem(null, c, imports, offset); } return count; @@ -574,7 +580,7 @@ class ValueSetExpander { async importValueSetItem(p, c, imports, offset) { let count = 0; - this.worker.deadCheck('importValueSetItem'); + await this.worker.checkAndYield('importValueSetItem'); const s = this.keyC(c); if (this.passesImports(imports, c.system, c.code, offset) && !this.map.has(s) && !this.isExcluded(c.system, c.version, c.code)) { count++; @@ -588,7 +594,7 @@ class ValueSetExpander { this.map.set(s, c); } for (const cc of c.contains || []) { - this.worker.deadCheck('importValueSetItem'); + await this.worker.checkAndYield('importValueSetItem'); count += await this.importValueSetItem(c, cc, imports, offset); } return count; @@ -610,11 +616,11 @@ class ValueSetExpander { } async checkSource(cset, exp, filter, srcURL, ts, vsInfo , source) { - this.worker.deadCheck('checkSource'); + await this.worker.checkAndYield('checkSource'); Extensions.checkNoModifiers(cset, 'ValueSetExpander.checkSource', 'set', srcURL); let imp = false; for (const u of cset.valueSet || []) { - this.worker.deadCheck('checkSource'); + await this.worker.checkAndYield('checkSource'); const s = this.worker.pinValueSet(u); await this.checkCanExpandValueSet(s, '', source); imp = true; @@ -663,8 +669,21 @@ class ValueSetExpander { } else if (filter.isNull) { // The unclosed marking for a grammar code system is added by // processCodes (the actual expansion); checkSource only guards size. - if (!imp && this.count !== 0 && this.limitCount > 0 && cs.totalCount > this.limitCount) { - throw new Issue("error", "too-costly", null, 'VALUESET_TOO_COSTLY', this.worker.i18n.translate('VALUESET_TOO_COSTLY', this.params.httpLanguages, [srcURL, '>' + this.limitCount]), null, 422).withDiagnostics(this.worker.opContext.diagnostics()); + // Refuse up-front only when enumeration could not succeed anyway: + // count=0 is answered by counting (no enumeration), and a count/offset + // window that fits inside limitCount is answered by partial + // enumeration (includeCode stops at limitCount). Otherwise the walk + // would only ever end in VALUESET_TOO_COSTLY at limitCount codes - + // throw the same error now without doing the work. + // NB: totalCount is a method - as a property read (cs.totalCount) the + // comparison was against the function object, always false, so this + // guard was silently dead. + if (!imp && this.count !== 0 && this.limitCount > 0 && await cs.totalCount() > this.limitCount + && !(this.count > 0 && this.count + Math.max(this.offset, 0) <= this.limitCount)) { + // Report the versioned url (vurl), matching the message the + // enumeration path produces when it hits the same limit - this + // guard is just that refusal moved earlier. + throw new Issue("error", "too-costly", null, 'VALUESET_TOO_COSTLY', this.worker.i18n.translate('VALUESET_TOO_COSTLY', this.params.httpLanguages, [source && source.vurl ? source.vurl : srcURL, '>' + this.limitCount]), null, 422).withDiagnostics(this.worker.opContext.diagnostics()); } } } @@ -684,7 +703,7 @@ class ValueSetExpander { } async includeCodes(cset, path, vsSrc, compose, filter, expansion, excludeInactive, notClosed) { - this.worker.deadCheck('processCodes#1'); + await this.worker.checkAndYield('processCodes#1'); const valueSets = []; Extensions.checkNoModifiers(cset, 'ValueSetExpander.processCodes', 'set', vsSrc.vurl); @@ -695,7 +714,7 @@ class ValueSetExpander { if (!cset.system) { for (const u of cset.valueSet) { - this.worker.deadCheck('processCodes#2'); + await this.worker.checkAndYield('processCodes#2'); const s = this.worker.pinValueSet(u); this.worker.opContext.log('import value set ' + s); let vs = await this.worker.findValueSet(s, '', vsSrc); @@ -722,7 +741,7 @@ class ValueSetExpander { this.addParamUri(expansion, 'used-codesystem', sv); for (const u of cset.valueSet || []) { - this.worker.deadCheck('processCodes#2'); + await this.worker.checkAndYield('processCodes#2'); const s = this.worker.pinValueSet(u); this.worker.opContext.log('import value set ' + s); let vs = await this.worker.findValueSet(s, '', vsSrc); @@ -774,11 +793,14 @@ class ValueSetExpander { } let tcount = 0; + // One visited set across all roots: in a poly-hierarchy the walks + // from different roots can reach the same concepts. + const visited = new Set(); let c = await cs.nextContext(iter); while (c) { - this.worker.deadCheck('processCodes#3a'); + await this.worker.checkAndYield('processCodes#3a'); if (await this.passesFilters(cs, c, prep, filters, 0)) { - tcount += await this.includeCodeAndDescendants(cs, c, expansion, valueSets, null, excludeInactive, vsSrc.vurl); + tcount += await this.includeCodeAndDescendants(cs, c, expansion, valueSets, null, excludeInactive, vsSrc.vurl, visited); } c = await cs.nextContext(iter); } @@ -800,7 +822,7 @@ class ValueSetExpander { this.noTotal(); this.worker.opContext.log('iterate filters'); while (await cs.filterMore(ctxt, set[0])) { - this.worker.deadCheck('processCodes#4'); + await this.worker.checkAndYield('processCodes#4'); const c = await cs.filterConcept(ctxt, set[0]); if (await this.passesFilters(cs, c, prep, set, 1)) { const cds = new Designations(this.worker.i18n.languageDefinitions); @@ -830,7 +852,7 @@ class ValueSetExpander { const cds = new Designations(this.worker.i18n.languageDefinitions); for (const cc of cset.concept) { - this.worker.deadCheck('processCodes#3'); + await this.worker.checkAndYield('processCodes#3'); cds.clear(); Extensions.checkNoModifiers(cc, 'ValueSetExpander.processCodes', 'set concept reference', vsSrc.vurl); const cctxt = await cs.locate(cc.code, this.allAltCodes); @@ -875,7 +897,7 @@ class ValueSetExpander { } for (let i = 0; i < fcl.length; i++) { - this.worker.deadCheck('processCodes#4a'); + await this.worker.checkAndYield('processCodes#4a'); const fc = fcl[i]; if (!fc.value) { throw new Issue('error', 'invalid', path + ".filter[" + i + "]", 'UNABLE_TO_HANDLE_SYSTEM_FILTER_WITH_NO_VALUE', this.worker.i18n.translate('UNABLE_TO_HANDLE_SYSTEM_FILTER_WITH_NO_VALUE', this.params.httpLanguages, [cs.system(), fc.property, fc.op]), 'vs-invalid', 400); @@ -895,7 +917,7 @@ class ValueSetExpander { this.addToTotal(0); const cds = new Designations(this.worker.i18n.languageDefinitions); while (await cs.filterMore(prep, fset[0])) { - this.worker.deadCheck('processCodes#5'); + await this.worker.checkAndYield('processCodes#5'); const c = await cs.filterConcept(prep, fset[0]); const ok = (!this.params.activeOnly || !await cs.isInactive(c)) && (await this.passesFilters(cs, c, prep, fset, 1)); if (ok) { @@ -944,7 +966,7 @@ class ValueSetExpander { } async excludeCodes(cset, path, vsSrc, filter, expansion, excludeInactive, notClosed) { - this.worker.deadCheck('processCodes#1'); + await this.worker.checkAndYield('processCodes#1'); const valueSets = []; Extensions.checkNoModifiers(cset, 'ValueSetExpander.processCodes', 'set', vsSrc.vurl); @@ -958,7 +980,7 @@ class ValueSetExpander { this.noTotal(); for (const u of cset.valueSet) { const s = this.worker.pinValueSet(u); - this.worker.deadCheck('processCodes#2'); + await this.worker.checkAndYield('processCodes#2'); let vs = await this.worker.findValueSet(s, '', vsSrc); const ivs = new ImportedValueSet(await this.expandValueSet(s, '', vs, filter, notClosed)); this.checkResourceCanonicalStatus(expansion, ivs.valueSet, this.valueSet); @@ -984,7 +1006,7 @@ class ValueSetExpander { this.addParamUri(expansion, 'used-codesystem', sv); for (const u of cset.valueSet || []) { - this.worker.deadCheck('processCodes#3'); + await this.worker.checkAndYield('processCodes#3'); const s = this.worker.pinValueSet(u); this.worker.opContext.log('import value set ' + s); let vs = await this.worker.findValueSet(s, '', vsSrc); @@ -1007,7 +1029,7 @@ class ValueSetExpander { if (iter) { let c = await cs.nextContext(iter); while (c) { - this.worker.deadCheck('processCodes#3aa'); + await this.worker.checkAndYield('processCodes#3aa'); this.excludeCode(cs, cs.system(), cs.version(), await cs.code(c), expansion, valueSets, vsSrc.url); c = await cs.nextContext(iter); } @@ -1031,7 +1053,7 @@ class ValueSetExpander { if (iter) { let c = await cs.nextContext(iter); while (c) { - this.worker.deadCheck('processCodes#3a'); + await this.worker.checkAndYield('processCodes#3a'); if (await this.passesFilters(cs, c, prep, filters, 0)) { this.excludeCode(cs, cs.system(), cs.version(), await cs.code(c), expansion, valueSets, vsSrc.url); } @@ -1045,7 +1067,7 @@ class ValueSetExpander { this.worker.opContext.log('iterate concepts'); const cds = new Designations(this.worker.i18n.languageDefinitions); for (const cc of cset.concept) { - this.worker.deadCheck('processCodes#3'); + await this.worker.checkAndYield('processCodes#3'); cds.clear(); Extensions.checkNoModifiers(cc, 'ValueSetExpander.processCodes', 'set concept reference', vsSrc.vurl); const cctxt = await cs.locate(cc.code, this.allAltCodes); @@ -1076,7 +1098,7 @@ class ValueSetExpander { let first = true; for (let fc of cset.filter) { - this.worker.deadCheck('processCodes#4a'); + await this.worker.checkAndYield('processCodes#4a'); Extensions.checkNoModifiers(fc, 'ValueSetExpander.processCodes', 'filter', vsSrc.vurl); await cs.filter(prep, first, fc.property, fc.op, fc.value, vsSrc.isCached ? fc : null); first = false; @@ -1089,7 +1111,7 @@ class ValueSetExpander { } //let count = 0; while (await cs.filterMore(prep, fset[0])) { - this.worker.deadCheck('processCodes#5'); + await this.worker.checkAndYield('processCodes#5'); const c = await cs.filterConcept(prep, fset[0]); const ok = (!this.params.activeOnly || !await cs.isInactive(c)) && (await this.passesFilters(cs, c, prep, fset, 1)); if (ok) { @@ -1105,9 +1127,30 @@ class ValueSetExpander { } } - async includeCodeAndDescendants(cs, context, expansion, imports, parent, excludeInactive, srcUrl) { + async includeCodeAndDescendants(cs, context, expansion, imports, parent, excludeInactive, srcUrl, visited = null) { let result = 0; - this.worker.deadCheck('processCodeAndDescendants'); + await this.worker.checkAndYield('processCodeAndDescendants'); + + // In a poly-hierarchy (e.g. SNOMED CT) a concept is reachable through every + // one of its parents; without a visited set the recursion walks every *path* + // rather than every *node* - for the full SNOMED International edition that + // is ~15.8M visits for ~520k concepts, which is what turned an aborted + // expansion into a 30-second event-loop stall. Reaching a concept a second + // time means it has multiple parents, so (as when includeCode detects a + // duplicate) the expansion cannot be represented as a tree. + if (visited == null) { + visited = new Set(); + } + // NB: contexts do not reliably carry a .code property (SnomedExpressionContext + // does not) - cs.code(context) is the accessor. Reading context.code here + // used to yield undefined for every SNOMED concept, collapsing the whole + // expansion onto one map key so no size guard could ever fire. + const code = await cs.code(context); + if (visited.has(code)) { + this.canBeHierarchy = false; + return 0; + } + visited.add(code); if (expansion) { const vs = this.canonical(await cs.system(), await cs.version()); @@ -1123,12 +1166,12 @@ class ValueSetExpander { const cds = new Designations(this.worker.i18n.languageDefinitions); let t; if (this.noDetails) { - t = await this.includeCode(cs, null, await cs.system(), await cs.version(), context.code, await cs.isAbstract(context), await cs.isInactive(context), null, null, null, - null, expansion, imports, null, null, null, null, excludeInactive, srcUrl); + t = await this.includeCode(cs, null, await cs.system(), await cs.version(), code, await cs.isAbstract(context), await cs.isInactive(context), null, null, null, + null, null, expansion, imports, null, null, null, null, excludeInactive, srcUrl); } else { await this.listDisplaysFromProvider(cds, cs, context); - t = await this.includeCode(cs, parent, await cs.system(), await cs.version(), context.code, await cs.isAbstract(context), await cs.isInactive(context), await cs.isDeprecated(context), await cs.getStatus(context), cds, await cs.definition(context), + t = await this.includeCode(cs, parent, await cs.system(), await cs.version(), code, await cs.isAbstract(context), await cs.isInactive(context), await cs.isDeprecated(context), await cs.getStatus(context), cds, await cs.definition(context), await cs.itemWeight(context), expansion, imports, await cs.extensions(context), null, await cs.properties(context), null, excludeInactive, srcUrl); } if (t != null) { @@ -1145,16 +1188,29 @@ class ValueSetExpander { if (iter) { let c = await cs.nextContext(iter); while (c) { - this.worker.deadCheck('processCodeAndDescendants#3'); - result += await this.includeCodeAndDescendants(cs, c, expansion, imports, n, excludeInactive, srcUrl); + await this.worker.checkAndYield('processCodeAndDescendants#3'); + result += await this.includeCodeAndDescendants(cs, c, expansion, imports, n, excludeInactive, srcUrl, visited); c = await cs.nextContext(iter); } } return result; } - async excludeCodeAndDescendants(cs, context, expansion, imports, excludeInactive, srcUrl) { - this.worker.deadCheck('processCodeAndDescendants'); + async excludeCodeAndDescendants(cs, context, expansion, imports, excludeInactive, srcUrl, visited = null) { + await this.worker.checkAndYield('processCodeAndDescendants'); + + // Same visited-set protection as includeCodeAndDescendants: walk nodes, not + // paths (see that method for why), and same accessor fix - context.code is + // not reliably present, and passing the raw context as the code produced + // useless "[object Object]" exclusion keys. + if (visited == null) { + visited = new Set(); + } + const code = await cs.code(context); + if (visited.has(code)) { + return; + } + visited.add(code); if (expansion) { const vs = this.canonical(await cs.system(), await cs.version()); @@ -1168,15 +1224,15 @@ class ValueSetExpander { if ((!this.params.excludeNotForUI || !await cs.isAbstract(context)) && (!this.params.activeOnly || !await cs.isInactive(context))) { const cds = new Designations(this.worker.i18n.languageDefinitions); await this.listDisplaysFromProvider(cds, cs, context); - this.worker.deadCheck('processCodeAndDescendants#2'); - this.excludeCode(cs, await cs.system(), await cs.version(), context, expansion, imports, srcUrl); + await this.worker.checkAndYield('processCodeAndDescendants#2'); + this.excludeCode(cs, await cs.system(), await cs.version(), code, expansion, imports, srcUrl); } const iter = await cs.iterator(context); let c = await cs.nextContext(iter); while (c) { - this.worker.deadCheck('processCodeAndDescendants#3'); - await this.excludeCodeAndDescendants(cs, c, expansion, imports, excludeInactive, srcUrl); + await this.worker.checkAndYield('processCodeAndDescendants#3'); + await this.excludeCodeAndDescendants(cs, c, expansion, imports, excludeInactive, srcUrl, visited); c = await cs.nextContext(iter); } } @@ -1187,11 +1243,11 @@ class ValueSetExpander { this.doingVersion = false; const ts = new Map(); for (const c of source.jsonObj.compose.include || []) { - this.worker.deadCheck('handleCompose#2'); + await this.worker.checkAndYield('handleCompose#2'); await this.checkSource(c, expansion, filter, source.url, ts, vsInfo, source); } for (const c of source.jsonObj.compose.exclude || []) { - this.worker.deadCheck('handleCompose#3'); + await this.worker.checkAndYield('handleCompose#3'); this.hasExclusions = true; await this.checkSource(c, expansion, filter, source.url, ts, null, source); } @@ -1205,7 +1261,7 @@ class ValueSetExpander { let i = 0; for (const c of source.jsonObj.compose.exclude || []) { - this.worker.deadCheck('handleCompose#4'); + await this.worker.checkAndYield('handleCompose#4'); await this.excludeCodes(c, "ValueSet.compose.exclude[" + i + "]", source, filter, expansion, this.excludeInactives(source), notClosed); } @@ -1218,7 +1274,7 @@ class ValueSetExpander { return 0; }); for (const c of includes) { - this.worker.deadCheck('handleCompose#5'); + await this.worker.checkAndYield('handleCompose#5'); await this.includeCodes(c, "ValueSet.compose.include[" + i + "]", source, source.jsonObj.compose, filter, expansion, this.excludeInactives(source), notClosed); i++; } @@ -1346,7 +1402,7 @@ class ValueSetExpander { } this.worker.opContext.log('start working'); - this.worker.deadCheck('expand'); + await this.worker.checkAndYield('expand'); let notClosed = { value : false}; @@ -1433,7 +1489,7 @@ class ValueSetExpander { let t = 0; let o = 0; for (let i = 0; i < list.length; i++) { - this.worker.deadCheck('expand#1'); + await this.worker.checkAndYield('expand#1'); const c = list[i]; if (this.map.has(this.keyC(c))) { o++; diff --git a/tx/workers/worker.js b/tx/workers/worker.js index 74d89699..4de4a06b 100644 --- a/tx/workers/worker.js +++ b/tx/workers/worker.js @@ -75,6 +75,15 @@ class TerminologyWorker { this.opContext.deadCheck(place); } + /** + * deadCheck plus a cooperative event-loop yield (see OperationContext.checkAndYield). + * Use this (awaited) from long-running loops in async code. + * @param {string} place - Location identifier for debugging + */ + async checkAndYield(place = 'unknown') { + await this.opContext.checkAndYield(place); + } + /** * Add cost diagnostics to an error * @param {TooCostlyError} e - The error to enhance