From 9744c520753b1f4537779a1991fd1db7716b6617 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Mon, 17 Aug 2026 15:46:26 +0200 Subject: [PATCH 01/13] fix(project): Cancel pending settle timer before watcher recovery On Windows, a settle timer callback firing into a closed ReadDirectoryChangesW handle after recovery causes an access violation (0xC0000005). Cancel any pending timer before tearing down the subscriptions; it is re-armed by the first event on the new set. Extract the timer-cancel and subscription-drain logic shared by #recoverWatcher and destroy into #cancelSettleTimer and #drainSubscriptions helpers to remove the duplication. --- .../lib/graph/ProjectDefinitionWatcher.js | 30 ++++++++++----- .../lib/graph/ProjectDefinitionWatcher.js | 38 +++++++++++++++++++ 2 files changed, 58 insertions(+), 10 deletions(-) diff --git a/packages/project/lib/graph/ProjectDefinitionWatcher.js b/packages/project/lib/graph/ProjectDefinitionWatcher.js index d9a13549128..ad710ecda01 100644 --- a/packages/project/lib/graph/ProjectDefinitionWatcher.js +++ b/packages/project/lib/graph/ProjectDefinitionWatcher.js @@ -230,13 +230,13 @@ class ProjectDefinitionWatcher extends EventEmitter { } try { + this.#cancelSettleTimer(); + // Tear down the current subscriptions and re-subscribe the same watch set. The include // set (#watchedFiles / #watchDirs) is unchanged; only the OS-level handles are renewed. // Teardown failures are ignored here: the handles are discarded either way, and the // re-subscribe below is what decides whether recovery succeeded. - const subscriptions = this.#subscriptions; - this.#subscriptions = []; - await drainSubscriptions(subscriptions); + await this.#drainSubscriptions(); if (this.#destroyed) { return; } @@ -259,19 +259,29 @@ class ProjectDefinitionWatcher extends EventEmitter { */ async destroy() { this.#destroyed = true; + this.#cancelSettleTimer(); + const failures = await this.#drainSubscriptions(); + if (failures.length) { + const err = new AggregateError(failures, "Failed to unsubscribe one or more definition watchers"); + this.emit("error", err); + } + } + + // Cancels a pending settle timer, if any. Safe to call when no timer is armed. + #cancelSettleTimer() { if (this.#settleTimer) { clearTimeout(this.#settleTimer); this.#settleTimer = null; } - // Drain the subscriptions list first so a second destroy() is a no-op and a partial failure - // cannot leave stale handles to be unsubscribed twice. + } + + // Snapshots and clears the subscriptions list before draining it, so a second drain (a second + // destroy(), or a destroy() racing recovery) is a no-op and a partial failure cannot leave stale + // handles to be unsubscribed twice. Returns the unsubscribe failures for callers that report them. + async #drainSubscriptions() { const subscriptions = this.#subscriptions; this.#subscriptions = []; - const failures = await drainSubscriptions(subscriptions); - if (failures.length) { - const err = new AggregateError(failures, "Failed to unsubscribe one or more definition watchers"); - this.emit("error", err); - } + return drainSubscriptions(subscriptions); } } diff --git a/packages/project/test/lib/graph/ProjectDefinitionWatcher.js b/packages/project/test/lib/graph/ProjectDefinitionWatcher.js index ebf385a03df..15469eb36e8 100644 --- a/packages/project/test/lib/graph/ProjectDefinitionWatcher.js +++ b/packages/project/test/lib/graph/ProjectDefinitionWatcher.js @@ -454,6 +454,44 @@ test.serial("recovery: a watcher error tears down and re-subscribes", async (t) await watcher.destroy(); }); +test.serial("recovery: pending settle timer is cancelled before teardown", async (t) => { + const sub1 = createMockSubscription(); + const sub2 = createMockSubscription(); + let cb; + subscribeStub.onFirstCall().callsFake(async (_dir, callback) => { + cb = callback; + return sub1; + }); + subscribeStub.onSecondCall().resolves(sub2); + + const graph = createGraph({name: "root", rootPath: fixturePath("/app")}); + const watcher = await ProjectDefinitionWatcher.create({graph}); + const ui5YamlPath = fixtureFile("/app", "ui5.yaml"); + + const emitted = []; + watcher.on("definitionChanged", (e) => emitted.push(e)); + + const clock = sinon.useFakeTimers(); + // Open a burst so the settle timer is armed. + cb(null, [{type: "update", path: ui5YamlPath}]); + clock.tick(100); + + // Watcher error fires while the timer is still pending. + cb(new Error("Failed to read changes")); + + // Restore real timers before awaiting recovery so async callbacks can proceed. + clock.restore(); + await new Promise((resolve) => setImmediate(resolve)); + + // The old subscription is torn down and a new one created. + t.true(sub1.unsubscribe.calledOnce, "old subscription torn down"); + t.is(subscribeStub.callCount, 2, "re-subscribed after recovery"); + + t.is(emitted.length, 0, "cancelled settle timer does not fire into the closed watcher handle"); + + await watcher.destroy(); +}); + test.serial("recovery: loop protection escalates to error after the max attempts", async (t) => { const subs = []; subscribeStub.callsFake(async () => { From d3f5cdb560d74e9a991a67dffe2163f317755f36 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 10:51:32 +0200 Subject: [PATCH 02/13] fix(server): Serialize destroy() teardown against in-flight swap via exclusive lock Introduce #lockTail / #runExclusive so destroy()'s field teardown and #swap never run concurrently. destroy() fires its synchronous head (state flip, abort, timer/relay cleanup) immediately, then queues teardown behind any in-flight swap; the swap therefore always finishes adopting #stack / #definitionWatcher before destroy reads and nulls them, closing the race that orphaned a @parcel/watcher subscription and the node:sqlite database on Windows. Adds two regression tests: one for the concurrent-swap leak and one confirming destroy() unblocks promptly when a recovery is parked in the settle wait. --- packages/server/lib/serve/Supervisor.js | 79 +++++++++++------ .../test/lib/server/serve/Supervisor.js | 85 +++++++++++++++++++ 2 files changed, 140 insertions(+), 24 deletions(-) diff --git a/packages/server/lib/serve/Supervisor.js b/packages/server/lib/serve/Supervisor.js index af4834aa33a..6f0249d65d6 100644 --- a/packages/server/lib/serve/Supervisor.js +++ b/packages/server/lib/serve/Supervisor.js @@ -125,6 +125,15 @@ class Supervisor extends EventEmitter { #recoveryTimer = null; #destroyAbortController = new AbortController(); + // Serializes the swap body against destroy()'s teardown so the two never run concurrently. Both + // #swap() (via reinitialize) and destroy()'s field teardown acquire it; each waits out the other. + // This is what lets #swap read/mutate #stack and #definitionWatcher across its awaits without a + // concurrent destroy() tearing them down mid-flight — the source of the orphaned native handles + // (a @parcel/watcher subscription, the node:sqlite database) that kept the process alive on Windows. + // Distinct from #reinitInProgress, which only collapses overlapping reinitialize() calls; destroy() + // acquires this lock directly, never through reinitialize(), so the #init error path cannot deadlock. + #lockTail = Promise.resolve(); + // Stable reference handed to every stack buildApp() builds. Closes over the supervisor instance // (not a per-stack value), so the surviving stack's serveBuildError reads the current // #degradedError on each request even though it was assembled before the failed swap. @@ -169,6 +178,16 @@ class Supervisor extends EventEmitter { buildServer.resumeReaders(); } + // Runs `fn` only after every previously-queued exclusive operation has settled, serializing the + // swap body against destroy teardown. The stored tail swallows the outcome so a rejected `fn` (a + // failed swap) cannot wedge the lock for the next waiter; the returned promise still surfaces `fn`'s + // real result or rejection to its own caller. + #runExclusive(fn) { + const run = this.#lockTail.then(fn, fn); + this.#lockTail = run.then(() => {}, () => {}); + return run; + } + constructor(config, error, graphFactory, projectWatcher) { super(); this.#config = config; @@ -289,6 +308,12 @@ class Supervisor extends EventEmitter { // Suspending rejects those requests fast instead. Reads #stack.buildServer live, so it always // targets the current stack; the suspend is lifted via #liftSuspend on both #swap outcomes. watcher.on("definitionChanging", () => { + // A watcher can still emit between destroy()'s synchronous state flip and its teardown + // awaiting the watcher's own destroy(). Bail: teardown has nulled (or is about to null) + // #stack, and the suspend/budget work below is pointless on a server being torn down. + if (this.#state === STATE.DESTROYED) { + return; + } // A real definition change supersedes any pending self-scheduled recovery and restores a // full recovery budget: the user just acted, so the next attempt should not be denied by an // allowance spent on the previous branch. @@ -350,7 +375,7 @@ class Supervisor extends EventEmitter { try { do { this.#reinitQueued = false; - await this.#swap(); + await this.#runExclusive(() => this.#swap()); } while (this.#reinitQueued && this.#state !== STATE.DESTROYED); } finally { this.#reinitInProgress = false; @@ -502,11 +527,6 @@ class Supervisor extends EventEmitter { this.#scheduleDegradedRecovery(); return; } - if (this.#state === STATE.DESTROYED) { - // Destroyed while building: discard the new stack instead of adopting it. - await newStack.buildServer.destroy(); - return; - } // Swap: retarget the dispatcher, move live-reload to the new BuildServer, notify clients. this.#setState(STATE.HEALTHY); this.#stack = newStack; @@ -521,7 +541,9 @@ class Supervisor extends EventEmitter { this.#sourcesChangedRelay.emit("sourcesChanged"); // Re-target the definition watcher to the new graph: the project set or their roots may // have changed. A create failure here must not crash the swap: keep serving and log, so the - // old watcher keeps driving re-inits. + // old watcher keeps driving re-inits. destroy() cannot interleave here: it acquires the same + // exclusive lock this swap holds, so its teardown runs only after this swap returns and then + // tears down whatever this swap adopted as #stack / #definitionWatcher. const oldWatcher = this.#definitionWatcher; this.#definitionWatcher = null; try { @@ -551,17 +573,16 @@ class Supervisor extends EventEmitter { * @returns {Promise} Resolves once teardown completes */ async destroy() { - // Move to the terminal state synchronously, before the first await, so an in-flight #swap or a - // late definitionChanged sees DESTROYED at its next guard and adopts nothing. + // Synchronous head: runs before any await and before the lock is acquired, so an in-flight + // #swap or a late definitionChanged/recovery-timer sees DESTROYED at its next guard, and the + // abort unblocks a recovery settle wait immediately rather than after its full window. this.#setState(STATE.DESTROYED); this.#destroyAbortController.abort(); - // Stop the definition watcher early so a late event cannot start a re-init mid-teardown. - // The reinitialize() DESTROYED guard already no-ops such an event; this is defensive. - const definitionWatcher = this.#definitionWatcher; - this.#definitionWatcher = null; + this.#clearRecoveryTimer(); this.#liveReloadHandle?.close(); this.#detachRelay(); - this.#clearRecoveryTimer(); + // Stop accepting new requests now, before waiting out any in-flight swap. Awaited last so the + // returned promise resolves only once the socket is fully closed. const httpClosed = new Promise((resolve) => { if (!this.#httpServer) { resolve(); @@ -569,16 +590,26 @@ class Supervisor extends EventEmitter { } this.#httpServer.close(() => resolve()); }); - try { - await definitionWatcher?.destroy(); - } catch (err) { - log.verbose(`Error while destroying definition watcher: ${err?.message ?? err}`); - } - try { - await this.#stack?.buildServer.destroy(); - } catch (err) { - log.verbose(`Error while destroying BuildServer: ${err?.message ?? err}`); - } + + // Teardown of the swappable fields runs under the same exclusive lock as #swap, so it never + // races a swap mid-flight. By the time it runs, any in-flight swap has settled and + // #definitionWatcher / #stack point at whatever that swap adopted — read once, torn down once. + await this.#runExclusive(async () => { + const definitionWatcher = this.#definitionWatcher; + this.#definitionWatcher = null; + const stack = this.#stack; + this.#stack = null; + try { + await definitionWatcher?.destroy(); + } catch (err) { + log.verbose(`Error while destroying definition watcher: ${err?.message ?? err}`); + } + try { + await stack?.buildServer.destroy(); + } catch (err) { + log.verbose(`Error while destroying BuildServer: ${err?.message ?? err}`); + } + }); await httpClosed; } } diff --git a/packages/server/test/lib/server/serve/Supervisor.js b/packages/server/test/lib/server/serve/Supervisor.js index 55b9dbe70d9..54484e002ba 100644 --- a/packages/server/test/lib/server/serve/Supervisor.js +++ b/packages/server/test/lib/server/serve/Supervisor.js @@ -419,6 +419,91 @@ test("destroy() closes the socket even when BuildServer.destroy() rejects", asyn t.true(httpServer.close.calledOnce, "socket is closed despite the BuildServer destroy rejection"); }); +test("destroy() during a swap serializes behind it and leaks no watcher or stack", async (t) => { + // Regression for the Windows `Failed to exit` leak: destroy() used to tear down #definitionWatcher + // and #stack while an in-flight #swap was still mutating them, orphaning a freshly-armed watcher + // (and the old stack's native handles). Serializing #swap and destroy teardown through one lock + // means teardown runs only after the swap settles, then owns whatever the swap adopted. Here + // destroy() is fired (not awaited) while the swap is parked mid-build, so its synchronous head runs + // during the swap and its teardown queues behind it. + const stack1 = createStack(); + const stack2 = createStack(); + const createdWatchers = []; + const buildGate = Promise.withResolvers(); + const ref = {}; + let buildCalls = 0; + const {mocks, projectWatcher} = createMocks({ + buildAppImpl: async () => { + buildCalls++; + if (buildCalls === 1) { + return stack1; // initial build + } + // Park the swap's build so destroy() can land while the swap is in flight. + ref.destroyPromise = ref.supervisor.destroy(); + await buildGate.promise; + return stack2; + }, + definitionWatcherCreate: async () => { + const watcher = new EventEmitter(); + watcher.destroy = sinon.stub().resolves(); + createdWatchers.push(watcher); + return watcher; + }, + }); + const graphFactory = sinon.stub().resolves({}); + const {default: Supervisor} = await importSupervisor(mocks, projectWatcher); + + ref.supervisor = await Supervisor.create({}, baseConfig, undefined, graphFactory); + const reinit = ref.supervisor.reinitialize(); + // Let the swap reach its parked build and fire destroy()'s synchronous head, then release it. + await waitFor(() => Boolean(ref.destroyPromise)); + buildGate.resolve(); + await reinit; + await ref.destroyPromise; + + // The swap adopted stack2 + a re-targeted watcher; destroy's teardown then owned and released them, + // and the swap itself tore down the old stack + old watcher. Nothing is left live. + t.true(createdWatchers.every((w) => w.destroy.calledOnce), "every armed watcher is torn down, none leaked"); + t.true(stack1.buildServer.destroy.calledOnce, "the old stack is torn down"); + t.true(stack2.buildServer.destroy.calledOnce, "the stack adopted mid-swap is torn down, not leaked"); +}); + +test("destroy() during a recovery settle aborts the wait instead of blocking on it", async (t) => { + // destroy()'s synchronous head aborts the shared AbortController before it acquires the teardown + // lock. A degraded recovery parked in #waitForProjectGraphSettled must observe that abort and + // reject promptly (code ABORT_ERR), so destroy() does not block for the full settle window. + const stack1 = createStack(); + let buildCalls = 0; + const graph = createGraph(["/app"]); + const graphFactory = sinon.stub().resolves(graph); + const {mocks, projectWatcher, waitForProjectGraphSettled} = createMocks({ + buildAppImpl: async () => { + buildCalls++; + if (buildCalls === 1) { + return stack1; // initial build + } + throw new Error("invalid ui5.yaml"); // first reinit fails -> degraded, recovery follows + }, + }); + // A settle that honors the signal: it resolves only when the signal aborts, and then rejects with + // ABORT_ERR, mirroring the real waitForProjectGraphSettled. + waitForProjectGraphSettled.callsFake((graphs, {signal}) => new Promise((resolve, reject) => { + signal.addEventListener("abort", + () => reject(Object.assign(new Error("aborted"), {code: "ABORT_ERR"})), {once: true}); + })); + const {default: Supervisor} = await importSupervisor(mocks, projectWatcher); + const supervisor = await Supervisor.create(graph, baseConfig, undefined, graphFactory); + + await supervisor.reinitialize(); + t.is(buildCalls, 2, "the first reinitialize failed and left the stack degraded"); + + // Drive the recovery swap so it parks in the settle wait, then destroy() while it is parked. + const recovery = supervisor.reinitialize(); + await waitFor(() => waitForProjectGraphSettled.called); + await t.notThrowsAsync(supervisor.destroy(), "destroy() resolves without waiting the settle window"); + await recovery; +}); + test("reinitialize() warns and no-ops when no graphFactory was provided", async (t) => { const stack = createStack(); const {mocks, projectWatcher, buildApp} = createMocks({stacks: [stack]}); From 0efe503ff65ac894e8625dc7f8eed6c5a8277371 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 12:49:38 +0200 Subject: [PATCH 03/13] test(server): Suppress intentional log output in unit tests Tests that exercise error and build paths leaked log lines into the test output because @ui5/logger writes to process.stderr whenever its process events have no listener attached, obscuring real failures. Attach no-op listeners to every logger event with a stderr fallback via an AVA --import setup module, and stub the raw stderr password prompt in the sslUtil test through file-level hooks. --- packages/server/ava.config.js | 9 ++++++++- packages/server/test/lib/server/sslUtil.js | 12 ++++++++++++ packages/server/test/utils/suppressLog.js | 14 ++++++++++++++ 3 files changed, 34 insertions(+), 1 deletion(-) create mode 100644 packages/server/test/utils/suppressLog.js diff --git a/packages/server/ava.config.js b/packages/server/ava.config.js index 64c839940ec..6ee496a53fd 100644 --- a/packages/server/ava.config.js +++ b/packages/server/ava.config.js @@ -1,3 +1,10 @@ import avaCommonConfig from "../../ava.common.config.js"; -export default avaCommonConfig; +export default { + ...avaCommonConfig, + nodeArguments: [ + ...avaCommonConfig.nodeArguments, + "--import", + "./test/utils/suppressLog.js" + ] +}; diff --git a/packages/server/test/lib/server/sslUtil.js b/packages/server/test/lib/server/sslUtil.js index cb151365172..25417a99b83 100644 --- a/packages/server/test/lib/server/sslUtil.js +++ b/packages/server/test/lib/server/sslUtil.js @@ -17,6 +17,18 @@ function fileExists(filePath) { }); } +// Certificate creation prints a "please enter your root password" prompt straight +// to stderr (not via @ui5/logger). No test asserts on stderr, so silence it once for +// the whole file. A file-level hook (rather than beforeEach) avoids concurrent tests +// racing to stub the same global process.stderr. +let stderrWriteStub; +test.before(() => { + stderrWriteStub = sinon.stub(process.stderr, "write"); +}); +test.after.always(() => { + stderrWriteStub.restore(); +}); + test.beforeEach(async (t) => { t.context.yesno = sinon.stub(); t.context.devcertSanscache = sinon.stub(); diff --git a/packages/server/test/utils/suppressLog.js b/packages/server/test/utils/suppressLog.js new file mode 100644 index 00000000000..c05cd4ee547 --- /dev/null +++ b/packages/server/test/utils/suppressLog.js @@ -0,0 +1,14 @@ +// @ui5/logger writes messages straight to process.stderr whenever the corresponding +// process event has no listener attached (see the fallback branches in the loggers +// under @ui5/logger/lib/loggers). Several server tests intentionally exercise error +// and build paths whose logs would otherwise clutter the test output and obscure real +// failures. Attaching a no-op listener to each event with a stderr fallback routes +// those messages to the (ignored) event instead. +for (const event of [ + "ui5.log", // Logger#_emitOrLog + "ui5.build-status", // loggers/Build + "ui5.project-build-status", // loggers/ProjectBuild + "ui5.serve-status", // loggers/Serve +]) { + process.on(event, () => {}); +} From 00f5ddd912781e581d479df3a014b05296c7956e Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 12:55:59 +0200 Subject: [PATCH 04/13] test(server): Add native-crash pinpointing probes for reinitialize.js MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The reinitialize.js test exits with 0xC0000005 (access violation) on Windows, a native crash in the forked AVA worker rather than a JS test failure. Add standalone probes that drive each native subsystem the test exercises in isolation — node:sqlite (single and overlapping WAL+mmap handles), the @parcel/watcher subscribe/unsubscribe cycle, and the full serve/reinitialize/ close lifecycle without AVA — so the crash origin can be attributed on Windows before changing the teardown logic further. See test/probes/README.md. --- packages/server/test/probes/README.md | 58 +++++++++++++++++++ packages/server/test/probes/probe-parcel.mjs | 38 ++++++++++++ packages/server/test/probes/probe-serve.mjs | 52 +++++++++++++++++ .../test/probes/probe-sqlite-reopen.mjs | 33 +++++++++++ packages/server/test/probes/probe-sqlite.mjs | 29 ++++++++++ 5 files changed, 210 insertions(+) create mode 100644 packages/server/test/probes/README.md create mode 100644 packages/server/test/probes/probe-parcel.mjs create mode 100644 packages/server/test/probes/probe-serve.mjs create mode 100644 packages/server/test/probes/probe-sqlite-reopen.mjs create mode 100644 packages/server/test/probes/probe-sqlite.mjs diff --git a/packages/server/test/probes/README.md b/packages/server/test/probes/README.md new file mode 100644 index 00000000000..cb9e692ce98 --- /dev/null +++ b/packages/server/test/probes/README.md @@ -0,0 +1,58 @@ +# Windows `0xC0000005` pinpointing kit for `reinitialize.js` + +`test/lib/server/reinitialize.js` exits with `3221225477` (`0xC0000005`, an **access +violation**) on Windows. That is a native crash in the AVA worker **child process** +(AVA runs each test file in a forked process — `workerThreads: false`), not a JS-level +test failure. The two native subsystems this test drives are: + +- **`@parcel/watcher`** — the source watcher (`WatchHandler`) and the definition watcher + (`ProjectDefinitionWatcher`). On Windows it runs a background `ReadDirectoryChangesW` + thread; a watch thread outliving `unsubscribe()` or racing process exit is a classic + `0xC0000005` source. +- **`node:sqlite`** (`BuildCacheStorage`) — opened with `PRAGMA journal_mode=WAL` and + `PRAGMA mmap_size=268435456`. Closing a memory-mapped WAL database, or letting the + process exit while pages are still mapped, can access-violate on Windows. + +The branch already serialized `destroy()` against the in-flight swap and cancelled the +settle timer, yet the crash persists — which points at native teardown / process exit +rather than a JS race. + +Run these probes on the Windows machine (from `packages/server`) and report the exit +code of each. `echo %ERRORLEVEL%` after each in cmd, or `$LASTEXITCODE` in PowerShell. +`3221225477` = the crash; `0` = clean. + +``` +node test/probes/probe-sqlite.mjs # node:sqlite open/write/close, single handle +node test/probes/probe-sqlite-reopen.mjs # two overlapping handles on one WAL+mmap db (the swap pattern) +node test/probes/probe-parcel.mjs # @parcel/watcher subscribe/event/unsubscribe +node test/probes/probe-serve.mjs # full serve() -> reinitialize() -> close(), no AVA +``` + +`probe-serve.mjs` prints staged markers (`serving` / `reinitialized` / `closed` / +`settled`). Note the last line printed before a crash: + +- crash **before** `closed` → teardown while JS still running. +- `closed` + `settled` printed, crash **after** → exit-time native handle not released. +- exit 0 → the isolated lifecycle is clean; the trigger needs the AVA worker environment. + +## Which probe crashed → where it originates + +| Crashes | Clean | Origin | +|---|---|---| +| `probe-sqlite` | — | `node:sqlite` close (WAL checkpoint / mmap unmap) — single handle is enough | +| `probe-sqlite-reopen` | `probe-sqlite` | overlapping handles on one WAL+mmap db (the reinitialize swap) | +| `probe-parcel` | sqlite probes | `@parcel/watcher` native teardown / watch thread vs. exit | +| `probe-serve` | all component probes | interaction only visible in the full lifecycle | +| none | all | needs the AVA worker env (supertest sockets, `--loader`, concurrent files) | + +## Bisecting the AVA subtests + +`reinitialize.js` has three serial subtests. Run each alone to see which crashes: + +``` +npx ava test/lib/server/reinitialize.js -m "reinitialize() keeps the port bound*" +npx ava test/lib/server/reinitialize.js -m "editing ui5.yaml triggers*" +npx ava test/lib/server/reinitialize.js -m "reinitialize() without a graphFactory*" +``` + +Delete this directory once the origin is confirmed. diff --git a/packages/server/test/probes/probe-parcel.mjs b/packages/server/test/probes/probe-parcel.mjs new file mode 100644 index 00000000000..976d9c99fd7 --- /dev/null +++ b/packages/server/test/probes/probe-parcel.mjs @@ -0,0 +1,38 @@ +// Probe C — @parcel/watcher subscribe/unsubscribe native teardown in isolation. +// +// Subscribes to a directory, triggers an event, unsubscribes, then lets the process exit. +// If this crashes with 0xC0000005 on Windows, the origin is the @parcel/watcher native +// binding (a background ReadDirectoryChangesW thread outliving unsubscribe / racing exit), +// independent of node:sqlite and the swap logic. +// +// Run from packages/project: node ../server/test/tmp/probe-parcel.mjs +import path from "node:path"; +import fs from "node:fs/promises"; +import {fileURLToPath} from "node:url"; + +const here = path.dirname(fileURLToPath(import.meta.url)); +const {subscribe} = await import(path.resolve(here, "../../../project/lib/build/helpers/fileWatcher.js")); + +const dir = path.resolve(here, `probe-parcel-${process.pid}`); +await fs.mkdir(dir, {recursive: true}); +console.log(`[probe-parcel] subscribing to ${dir}`); + +let eventCount = 0; +const sub = await subscribe(dir, (err, events) => { + if (err) { + console.error(`[probe-parcel] watcher error: ${err.message}`); + return; + } + eventCount += events.length; +}); + +// Produce a change so the native watch thread is actively delivering. +await fs.writeFile(path.join(dir, "file.txt"), "hello"); +await new Promise((r) => setTimeout(r, 300)); +await fs.writeFile(path.join(dir, "file.txt"), "world"); +await new Promise((r) => setTimeout(r, 300)); +console.log(`[probe-parcel] observed ${eventCount} event(s)`); + +console.log(`[probe-parcel] unsubscribing`); +await sub.unsubscribe(); +console.log(`[probe-parcel] unsubscribed OK — process exiting`); diff --git a/packages/server/test/probes/probe-serve.mjs b/packages/server/test/probes/probe-serve.mjs new file mode 100644 index 00000000000..deeabd0be6f --- /dev/null +++ b/packages/server/test/probes/probe-serve.mjs @@ -0,0 +1,52 @@ +// Probe D — Full serve() -> reinitialize() -> close() lifecycle, standalone (no AVA). +// +// Mirrors the first subtest of reinitialize.js against the real graph + BuildServer + +// Supervisor, but as a plain Node process so the exit code is attributable to this flow +// alone (AVA is not in the picture). After close() resolves it prints a marker, waits +// briefly, then exits. +// +// - If it crashes 0xC0000005 BEFORE "[probe-serve] closed" -> the crash is during +// destroy()/teardown while JS is still running. +// - If it prints "[probe-serve] closed" and "[probe-serve] settled" and THEN the +// process crashes on exit -> the crash is at process exit with a native handle +// (parcel watch thread / sqlite mmap) not fully released. +// - Exit 0 clean -> the isolated lifecycle does not reproduce it; the trigger needs +// the AVA worker environment (e.g. supertest sockets, the loader, concurrent files). +// +// Run from packages/server: node test/probes/probe-serve.mjs +import path from "node:path"; +import {fileURLToPath} from "node:url"; + +process.env.NODE_ENV = "test"; +const here = path.dirname(fileURLToPath(import.meta.url)); +const serverRoot = path.resolve(here, "..", ".."); +process.chdir(serverRoot); // so ./test/fixtures/application.a resolves like the test + +const {serve} = await import(path.resolve(serverRoot, "lib/server.js")); +const {graphFromPackageDependencies} = await import("@ui5/project/graph"); +const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); + +const buildGraph = () => graphFromPackageDependencies({cwd: "./test/fixtures/application.a"}); + +const ui5DataDir = path.resolve("test", "tmp", "buildcache", `probe-serve-${process.pid}`); +console.log(`[probe-serve] serving (ui5DataDir=${ui5DataDir})`); +const graph = await buildGraph(); +const server = await serve(graph, { + port: 3399, // fixed port; changePortIfInUse bumps it if busy + changePortIfInUse: true, + liveReload: false, + ui5DataDir, +}, undefined, buildGraph, projectWatcher); +console.log(`[probe-serve] listening on ${server.port}`); + +console.log(`[probe-serve] reinitialize`); +await server.reinitialize(); +console.log(`[probe-serve] reinitialized`); + +await new Promise((resolve) => server.close(resolve)); +console.log(`[probe-serve] closed`); + +// Hold the process open briefly so an exit-time native crash is clearly separated from +// the in-flight teardown above. +await new Promise((r) => setTimeout(r, 1000)); +console.log(`[probe-serve] settled — process exiting`); diff --git a/packages/server/test/probes/probe-sqlite-reopen.mjs b/packages/server/test/probes/probe-sqlite-reopen.mjs new file mode 100644 index 00000000000..9e9e933a81c --- /dev/null +++ b/packages/server/test/probes/probe-sqlite-reopen.mjs @@ -0,0 +1,33 @@ +// Probe B — node:sqlite reopen/refcount pattern of a reinitialize() swap. +// +// A reinitialize() opens a SECOND handle on the same cache dir before the first is +// closed (refcount 1 -> 2), then closes the first (2 -> 1), later the second (1 -> 0). +// Two DatabaseSync handles onto the same WAL+mmap file, overlapping, then both closed. +// If this crashes but probe-sqlite does not, the origin is concurrent handles onto the +// same mmapped WAL DB on Windows. +// +// Run from packages/project: node ../server/test/tmp/probe-sqlite-reopen.mjs +import path from "node:path"; +import {fileURLToPath} from "node:url"; + +const here = path.dirname(fileURLToPath(import.meta.url)); +const {default: BuildCacheStorage} = + await import(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js")); + +const dbDir = path.resolve(here, `probe-sqlite-reopen-${process.pid}`); +console.log(`[probe-reopen] open #1 ${dbDir}`); +const a = new BuildCacheStorage(dbDir); +a.transaction(() => a.putContent("sha512-a", Buffer.alloc(4096, 1))); + +console.log(`[probe-reopen] open #2 (overlapping) same dir`); +const b = new BuildCacheStorage(dbDir); +console.log(`[probe-reopen] #2 reads #1's row: ${b.hasContent("sha512-a")}`); +b.transaction(() => b.putContent("sha512-b", Buffer.alloc(4096, 2))); + +console.log(`[probe-reopen] close #1 (swap: old stack torn down)`); +a.close(); +console.log(`[probe-reopen] #2 still serving: ${b.hasContent("sha512-a")} / ${b.hasContent("sha512-b")}`); + +console.log(`[probe-reopen] close #2 (server.close)`); +b.close(); +console.log(`[probe-reopen] both closed OK — process exiting`); diff --git a/packages/server/test/probes/probe-sqlite.mjs b/packages/server/test/probes/probe-sqlite.mjs new file mode 100644 index 00000000000..d3e23643824 --- /dev/null +++ b/packages/server/test/probes/probe-sqlite.mjs @@ -0,0 +1,29 @@ +// Probe A — node:sqlite (BuildCacheStorage) native teardown in isolation. +// +// Opens the build-cache DB the exact way the server does (WAL + mmap + busy_timeout), +// writes a row, closes it (WAL checkpoint TRUNCATE + db.close()), then lets the process +// exit. If this crashes with 0xC0000005 on Windows, the origin is node:sqlite teardown +// (mmap unmap / WAL checkpoint on close), independent of parcel and the swap logic. +// +// Run from packages/project: node ../server/test/tmp/probe-sqlite.mjs +import path from "node:path"; +import {fileURLToPath} from "node:url"; + +const here = path.dirname(fileURLToPath(import.meta.url)); +const {default: BuildCacheStorage} = + await import(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js")); + +const dbDir = path.resolve(here, `probe-sqlite-${process.pid}`); +console.log(`[probe-sqlite] opening ${dbDir}`); +const storage = new BuildCacheStorage(dbDir); + +// Exercise a write + read so mmap pages are actually mapped in. +storage.transaction(() => { + storage.putContent("sha512-probe", Buffer.alloc(4096, 7)); +}); +console.log(`[probe-sqlite] hasContent=${storage.hasContent("sha512-probe")}`); +console.log(`[probe-sqlite] size=${storage.getDatabaseSize()}`); + +console.log(`[probe-sqlite] closing`); +storage.close(); +console.log(`[probe-sqlite] closed OK — process exiting`); From 2c52b202f76574cc773f9779df06d18a88f9912e Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 12:59:04 +0200 Subject: [PATCH 05/13] test(server): Fix probe dynamic imports for Windows import() of an absolute path throws ERR_UNSUPPORTED_ESM_URL_SCHEME on Windows, where the default ESM loader requires a file:// URL rather than a bare drive path (e.g. 'c:\...'). Wrap each probe's absolute-path dynamic import in pathToFileURL so the probes run on the Windows machine they target. --- packages/server/test/probes/probe-parcel.mjs | 5 +++-- packages/server/test/probes/probe-serve.mjs | 4 ++-- packages/server/test/probes/probe-sqlite-reopen.mjs | 4 ++-- packages/server/test/probes/probe-sqlite.mjs | 4 ++-- 4 files changed, 9 insertions(+), 8 deletions(-) diff --git a/packages/server/test/probes/probe-parcel.mjs b/packages/server/test/probes/probe-parcel.mjs index 976d9c99fd7..f4181977be8 100644 --- a/packages/server/test/probes/probe-parcel.mjs +++ b/packages/server/test/probes/probe-parcel.mjs @@ -8,10 +8,11 @@ // Run from packages/project: node ../server/test/tmp/probe-parcel.mjs import path from "node:path"; import fs from "node:fs/promises"; -import {fileURLToPath} from "node:url"; +import {fileURLToPath, pathToFileURL} from "node:url"; const here = path.dirname(fileURLToPath(import.meta.url)); -const {subscribe} = await import(path.resolve(here, "../../../project/lib/build/helpers/fileWatcher.js")); +const {subscribe} = await import( + pathToFileURL(path.resolve(here, "../../../project/lib/build/helpers/fileWatcher.js"))); const dir = path.resolve(here, `probe-parcel-${process.pid}`); await fs.mkdir(dir, {recursive: true}); diff --git a/packages/server/test/probes/probe-serve.mjs b/packages/server/test/probes/probe-serve.mjs index deeabd0be6f..4ef95d69052 100644 --- a/packages/server/test/probes/probe-serve.mjs +++ b/packages/server/test/probes/probe-serve.mjs @@ -15,14 +15,14 @@ // // Run from packages/server: node test/probes/probe-serve.mjs import path from "node:path"; -import {fileURLToPath} from "node:url"; +import {fileURLToPath, pathToFileURL} from "node:url"; process.env.NODE_ENV = "test"; const here = path.dirname(fileURLToPath(import.meta.url)); const serverRoot = path.resolve(here, "..", ".."); process.chdir(serverRoot); // so ./test/fixtures/application.a resolves like the test -const {serve} = await import(path.resolve(serverRoot, "lib/server.js")); +const {serve} = await import(pathToFileURL(path.resolve(serverRoot, "lib/server.js"))); const {graphFromPackageDependencies} = await import("@ui5/project/graph"); const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); diff --git a/packages/server/test/probes/probe-sqlite-reopen.mjs b/packages/server/test/probes/probe-sqlite-reopen.mjs index 9e9e933a81c..98f3edd5e8e 100644 --- a/packages/server/test/probes/probe-sqlite-reopen.mjs +++ b/packages/server/test/probes/probe-sqlite-reopen.mjs @@ -8,11 +8,11 @@ // // Run from packages/project: node ../server/test/tmp/probe-sqlite-reopen.mjs import path from "node:path"; -import {fileURLToPath} from "node:url"; +import {fileURLToPath, pathToFileURL} from "node:url"; const here = path.dirname(fileURLToPath(import.meta.url)); const {default: BuildCacheStorage} = - await import(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js")); + await import(pathToFileURL(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js"))); const dbDir = path.resolve(here, `probe-sqlite-reopen-${process.pid}`); console.log(`[probe-reopen] open #1 ${dbDir}`); diff --git a/packages/server/test/probes/probe-sqlite.mjs b/packages/server/test/probes/probe-sqlite.mjs index d3e23643824..96e55c39a75 100644 --- a/packages/server/test/probes/probe-sqlite.mjs +++ b/packages/server/test/probes/probe-sqlite.mjs @@ -7,11 +7,11 @@ // // Run from packages/project: node ../server/test/tmp/probe-sqlite.mjs import path from "node:path"; -import {fileURLToPath} from "node:url"; +import {fileURLToPath, pathToFileURL} from "node:url"; const here = path.dirname(fileURLToPath(import.meta.url)); const {default: BuildCacheStorage} = - await import(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js")); + await import(pathToFileURL(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js"))); const dbDir = path.resolve(here, `probe-sqlite-${process.pid}`); console.log(`[probe-sqlite] opening ${dbDir}`); From 0dcb199ebd8303f25194dd25f661a14b4364a674 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:01:29 +0200 Subject: [PATCH 06/13] test(server): Add AVA-environment probes for reinitialize.js crash MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The four component probes all exit clean on Windows, including the full serve/reinitialize/close lifecycle — so the 0xC0000005 is not a native subsystem in isolation. Add two probes that layer on what the AVA worker adds: supertest request sockets, and three serve/reinitialize/close cycles in one long-lived process (mirroring the three serial subtests). Document the narrowed hypothesis and the -m subtest bisection in README. --- packages/server/test/probes/README.md | 29 ++++++++++++ .../test/probes/probe-serve-supertest.mjs | 47 +++++++++++++++++++ .../server/test/probes/probe-serve-thrice.mjs | 44 +++++++++++++++++ 3 files changed, 120 insertions(+) create mode 100644 packages/server/test/probes/probe-serve-supertest.mjs create mode 100644 packages/server/test/probes/probe-serve-thrice.mjs diff --git a/packages/server/test/probes/README.md b/packages/server/test/probes/README.md index cb9e692ce98..4f99195dd46 100644 --- a/packages/server/test/probes/README.md +++ b/packages/server/test/probes/README.md @@ -56,3 +56,32 @@ npx ava test/lib/server/reinitialize.js -m "reinitialize() without a graphFactor ``` Delete this directory once the origin is confirmed. + +## Findings so far (Windows) + +All four component probes exit **clean** (exit 0), including `probe-serve` (the full +serve → reinitialize → close lifecycle). So the crash is **not** in any native subsystem +in isolation, nor in a single lifecycle. That narrows the trigger to what the AVA worker +adds on top: the `supertest` request sockets, the `--loader=esmock` + `--import +suppressLog` worker flags, and three serial subtests sharing one worker process. + +Next probes isolate those additions (run from `packages/server`): + +``` +node test/probes/probe-serve-supertest.mjs # lifecycle + real HTTP requests (socket churn) +node test/probes/probe-serve-thrice.mjs # three serve/reinitialize/close cycles in one process +``` + +Then bisect the real test under the actual AVA worker (loader + suppressLog + supertest): + +``` +npx ava test/lib/server/reinitialize.js -m "reinitialize() keeps the port bound*" +npx ava test/lib/server/reinitialize.js -m "editing ui5.yaml triggers*" +npx ava test/lib/server/reinitialize.js -m "reinitialize() without a graphFactory*" +``` + +- If a probe crashes → the addition it introduces (sockets / repetition) is the trigger. +- If all probes are clean but a single `-m` subtest crashes → that subtest's specifics + (e.g. the watcher-driven edit, or the tmp-dir copy) are the trigger under AVA. +- If only the full file crashes but each `-m` subtest is clean → cross-subtest state in + one worker (a handle from subtest N surviving into N+1) is the trigger. diff --git a/packages/server/test/probes/probe-serve-supertest.mjs b/packages/server/test/probes/probe-serve-supertest.mjs new file mode 100644 index 00000000000..85d6aff53ee --- /dev/null +++ b/packages/server/test/probes/probe-serve-supertest.mjs @@ -0,0 +1,47 @@ +// Probe E — serve() lifecycle WITH supertest requests, standalone (no AVA). +// +// probe-serve.mjs exits clean, so the isolated lifecycle is fine. The real test differs +// in that it drives HTTP requests through supertest against the bound socket. This probe +// adds exactly that: GET /index.html before and after reinitialize(), then close(). If +// this crashes but probe-serve does not, the trigger involves the request sockets / +// keep-alive handles interacting with teardown. +// +// Run from packages/server: node test/probes/probe-serve-supertest.mjs +import path from "node:path"; +import {fileURLToPath, pathToFileURL} from "node:url"; + +process.env.NODE_ENV = "test"; +const here = path.dirname(fileURLToPath(import.meta.url)); +const serverRoot = path.resolve(here, "..", ".."); +process.chdir(serverRoot); + +const {serve} = await import(pathToFileURL(path.resolve(serverRoot, "lib/server.js"))); +const {graphFromPackageDependencies} = await import("@ui5/project/graph"); +const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); +const {default: supertest} = await import("supertest"); + +const buildGraph = () => graphFromPackageDependencies({cwd: "./test/fixtures/application.a"}); + +const ui5DataDir = path.resolve("test", "tmp", "buildcache", `probe-serve-supertest-${process.pid}`); +const graph = await buildGraph(); +const server = await serve(graph, { + port: 3399, + changePortIfInUse: true, + liveReload: false, + ui5DataDir, +}, undefined, buildGraph, projectWatcher); +console.log(`[probe-supertest] listening on ${server.port}`); + +const request = supertest(`http://127.0.0.1:${server.port}`); +console.log(`[probe-supertest] GET before: ${(await request.get("/index.html")).statusCode}`); + +await server.reinitialize(); +console.log(`[probe-supertest] reinitialized`); + +console.log(`[probe-supertest] GET after: ${(await request.get("/index.html")).statusCode}`); + +await new Promise((resolve) => server.close(resolve)); +console.log(`[probe-supertest] closed`); + +await new Promise((r) => setTimeout(r, 1000)); +console.log(`[probe-supertest] settled — process exiting`); diff --git a/packages/server/test/probes/probe-serve-thrice.mjs b/packages/server/test/probes/probe-serve-thrice.mjs new file mode 100644 index 00000000000..ab4c7f524db --- /dev/null +++ b/packages/server/test/probes/probe-serve-thrice.mjs @@ -0,0 +1,44 @@ +// Probe F — three serve/reinitialize/close cycles in one process (no AVA). +// +// The real test file has three serial subtests, each a full serve/…/close. AVA runs them +// back-to-back in ONE worker process. probe-serve.mjs does a single cycle and exits clean; +// this repeats the cycle three times with supertest requests, so a crash that only shows +// up after repeated open/close of the native handles (parcel re-subscribe, sqlite reopen +// on the same cache dir, socket churn) in one long-lived process is reproduced. +// +// Run from packages/server: node test/probes/probe-serve-thrice.mjs +import path from "node:path"; +import {fileURLToPath, pathToFileURL} from "node:url"; + +process.env.NODE_ENV = "test"; +const here = path.dirname(fileURLToPath(import.meta.url)); +const serverRoot = path.resolve(here, "..", ".."); +process.chdir(serverRoot); + +const {serve} = await import(pathToFileURL(path.resolve(serverRoot, "lib/server.js"))); +const {graphFromPackageDependencies} = await import("@ui5/project/graph"); +const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); +const {default: supertest} = await import("supertest"); + +const buildGraph = () => graphFromPackageDependencies({cwd: "./test/fixtures/application.a"}); + +for (let cycle = 1; cycle <= 3; cycle++) { + const ui5DataDir = path.resolve( + "test", "tmp", "buildcache", `probe-thrice-${cycle}-${process.pid}`); + const graph = await buildGraph(); + const server = await serve(graph, { + port: 3400 + cycle, + changePortIfInUse: true, + liveReload: false, + ui5DataDir, + }, undefined, buildGraph, projectWatcher); + const request = supertest(`http://127.0.0.1:${server.port}`); + await request.get("/index.html"); + await server.reinitialize(); + await request.get("/index.html"); + await new Promise((resolve) => server.close(resolve)); + console.log(`[probe-thrice] cycle ${cycle} done (port ${server.port})`); +} + +await new Promise((r) => setTimeout(r, 1000)); +console.log(`[probe-thrice] all cycles settled — process exiting`); From d2ed813edae7e158aef972f314757ff7d09ae869 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:07:34 +0200 Subject: [PATCH 07/13] test(project): Add env-gated synchronous teardown tracing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The reinitialize.js 0xC0000005 on Windows is flaky and the deterministic probes do not reproduce it, so it is a timing-dependent race in native teardown/exit (@parcel/watcher unsubscribe or node:sqlite close). Add a UI5_TEARDOWN_TRACE=1 tracer that writes each teardown step to fd 2 with writeSync — unbuffered, so the last line survives a hard segfault and names the native call in flight. Wired through Supervisor.destroy, BuildServer.destroy, the definition/source watcher destroys, drainSubscriptions (per unsubscribe), and CacheManager/ BuildCacheStorage close (WAL checkpoint vs db.close). No-op and zero-cost when the env var is unset. See packages/server/test/probes/README.md for the loop- until-crash procedure. --- packages/project/lib/build/BuildServer.js | 11 ++++++ .../lib/build/cache/BuildCacheStorage.js | 5 +++ .../project/lib/build/cache/CacheManager.js | 4 +++ .../project/lib/build/helpers/WatchHandler.js | 4 +++ .../lib/build/helpers/teardownTrace.js | 28 +++++++++++++++ .../project/lib/build/helpers/watchUtil.js | 16 ++++++++- .../lib/graph/ProjectDefinitionWatcher.js | 4 +++ packages/server/lib/serve/Supervisor.js | 15 +++++++- packages/server/lib/serve/teardownTrace.js | 28 +++++++++++++++ packages/server/test/probes/README.md | 34 +++++++++++++++++++ 10 files changed, 147 insertions(+), 2 deletions(-) create mode 100644 packages/project/lib/build/helpers/teardownTrace.js create mode 100644 packages/server/lib/serve/teardownTrace.js diff --git a/packages/project/lib/build/BuildServer.js b/packages/project/lib/build/BuildServer.js index 5b97b336f61..663c2980da1 100644 --- a/packages/project/lib/build/BuildServer.js +++ b/packages/project/lib/build/BuildServer.js @@ -4,6 +4,7 @@ import BuildReader from "./BuildReader.js"; import WatchHandler from "./helpers/WatchHandler.js"; import {isAbortError, isFileNotFoundError} from "./helpers/abort.js"; import {WATCHER_BURST_SETTLE_MS} from "./helpers/watchUtil.js"; +import {trace} from "./helpers/teardownTrace.js"; import RecoveryBudget, {WATCHER_RECOVERY_MAX_ATTEMPTS, WATCHER_RECOVERY_WINDOW_MS} from "./helpers/RecoveryBudget.js"; import {getLogger} from "@ui5/logger"; import ServeLogger from "@ui5/logger/internal/loggers/Serve"; @@ -368,25 +369,35 @@ class BuildServer extends EventEmitter { async destroy() { + trace("BuildServer.destroy: enter"); this.#destroyed = true; clearTimeout(this.#processBuildRequestsTimeout); this.#pendingDeferredRestart = false; clearTimeout(this.#sourcesChangedTimeout); this.#pendingFinalSourcesChanged = false; + trace("BuildServer.destroy: watchHandler.destroy start"); await this.#watchHandler.destroy(); + trace("BuildServer.destroy: watchHandler.destroy done"); try { // Cancel any running background validation pass and wait for it to settle. + trace("BuildServer.destroy: stopActiveValidation start"); await this.#stopActiveValidation("Server destroyed"); + trace("BuildServer.destroy: stopActiveValidation done"); if (this.#activeBuild) { // Await active build to finish + trace("BuildServer.destroy: awaiting activeBuild"); await this.#activeBuild; + trace("BuildServer.destroy: activeBuild settled"); } } finally { // Always release the cache manager, even when the active build rejected // (e.g. Force-mode stale-cache errors). Otherwise the SQLite handle leaks // and subsequent fs.rm of the cache directory fails with EBUSY on Windows. + trace("BuildServer.destroy: closeCacheManager start"); this.#projectBuilder.closeCacheManager(); + trace("BuildServer.destroy: closeCacheManager done"); } + trace("BuildServer.destroy: exit"); } /** diff --git a/packages/project/lib/build/cache/BuildCacheStorage.js b/packages/project/lib/build/cache/BuildCacheStorage.js index 13fb50c491a..353c4da8095 100644 --- a/packages/project/lib/build/cache/BuildCacheStorage.js +++ b/packages/project/lib/build/cache/BuildCacheStorage.js @@ -3,6 +3,7 @@ import {mkdirSync, existsSync} from "node:fs"; import path from "node:path"; import {gzipSync, gunzipSync} from "node:zlib"; import {getLogger} from "@ui5/logger"; +import {trace} from "../helpers/teardownTrace.js"; const log = getLogger("build:cache:BuildCacheStorage"); @@ -603,6 +604,7 @@ export default class BuildCacheStorage { * Closes the database connection */ close() { + trace(`BuildCacheStorage.close: enter (${this.#dbPath})`); if (this.#inTransaction) { try { this.#db.exec("ROLLBACK"); @@ -610,8 +612,11 @@ export default class BuildCacheStorage { this.#inTransaction = false; } } + trace("BuildCacheStorage.close: wal_checkpoint(TRUNCATE) start"); this.#db.exec("PRAGMA wal_checkpoint(TRUNCATE)"); + trace("BuildCacheStorage.close: wal_checkpoint done, db.close() start"); this.#db.close(); + trace("BuildCacheStorage.close: db.close() done"); } /** diff --git a/packages/project/lib/build/cache/CacheManager.js b/packages/project/lib/build/cache/CacheManager.js index d1baec61eb0..0ffde09a83a 100644 --- a/packages/project/lib/build/cache/CacheManager.js +++ b/packages/project/lib/build/cache/CacheManager.js @@ -4,6 +4,7 @@ import Configuration from "../../config/Configuration.js"; import {access} from "node:fs/promises"; import {getLogger} from "@ui5/logger"; import BuildCacheStorage from "./BuildCacheStorage.js"; +import {trace} from "../helpers/teardownTrace.js"; const log = getLogger("build:cache:CacheManager"); @@ -335,9 +336,12 @@ export default class CacheManager { * closed only when the last consumer releases its reference. */ close() { + trace(`CacheManager.close: refCount ${this.#refCount} -> ${this.#refCount - 1} (${this.#cacheDir})`); if (--this.#refCount <= 0) { + trace("CacheManager.close: last ref, closing storage"); this.#storage.close(); cacheManagerInstances.delete(this.#cacheDir); + trace("CacheManager.close: storage closed, instance removed"); } } diff --git a/packages/project/lib/build/helpers/WatchHandler.js b/packages/project/lib/build/helpers/WatchHandler.js index f9180081f93..d721f3a726a 100644 --- a/packages/project/lib/build/helpers/WatchHandler.js +++ b/packages/project/lib/build/helpers/WatchHandler.js @@ -2,6 +2,7 @@ import EventEmitter from "node:events"; import {getLogger} from "@ui5/logger"; import {subscribe as watchSubscribe} from "./fileWatcher.js"; import {drainSubscriptions} from "./watchUtil.js"; +import {trace} from "./teardownTrace.js"; import {exists} from "../../utils/fsHelper.js"; const log = getLogger("build:helpers:WatchHandler"); @@ -63,15 +64,18 @@ class WatchHandler extends EventEmitter { } async destroy() { + trace("WatchHandler.destroy: enter"); // Drain the subscriptions list so a second destroy() is a no-op and a partial // failure cannot leave stale handles behind to be unsubscribed twice. const subscriptions = this.#subscriptions; this.#subscriptions = []; const failures = await drainSubscriptions(subscriptions); + trace("WatchHandler.destroy: drained"); if (failures.length) { const err = new AggregateError(failures, "Failed to unsubscribe one or more file watchers"); this.emit("error", err); } + trace("WatchHandler.destroy: exit"); } #handleWatchEvents(eventType, filePath, project) { diff --git a/packages/project/lib/build/helpers/teardownTrace.js b/packages/project/lib/build/helpers/teardownTrace.js new file mode 100644 index 00000000000..fda43c64337 --- /dev/null +++ b/packages/project/lib/build/helpers/teardownTrace.js @@ -0,0 +1,28 @@ +import {writeSync} from "node:fs"; + +// Synchronous, env-gated teardown tracer. Set UI5_TEARDOWN_TRACE=1 to enable. +// +// Writes straight to fd 2 (stderr) with writeSync, bypassing the async stream buffer, so +// the last line survives a hard native crash (a 0xC0000005 access violation on Windows in +// @parcel/watcher or node:sqlite teardown terminates the process without flushing buffered +// output). Each line is prefixed with the high-resolution time and the pid so interleaved +// teardown across the Supervisor, BuildServer, and watchers can be ordered after the fact. +// +// Off by default and a no-op unless the env var is set, so it costs nothing in normal runs. +const ENABLED = process.env.UI5_TEARDOWN_TRACE === "1"; + +/** + * Emits a teardown trace line to stderr synchronously when UI5_TEARDOWN_TRACE=1. + * + * @param {string} msg Message to trace + */ +export function trace(msg) { + if (!ENABLED) { + return; + } + try { + writeSync(2, `[teardown ${process.hrtime.bigint()} pid=${process.pid}] ${msg}\n`); + } catch { + // Never let tracing throw during teardown. + } +} diff --git a/packages/project/lib/build/helpers/watchUtil.js b/packages/project/lib/build/helpers/watchUtil.js index f1e4ab3ca00..d1f79eb2d45 100644 --- a/packages/project/lib/build/helpers/watchUtil.js +++ b/packages/project/lib/build/helpers/watchUtil.js @@ -1,3 +1,5 @@ +import {trace} from "./teardownTrace.js"; + /** * Settle window (ms) for collapsing a burst of filesystem events into one trailing action. Shared * by every Parcel watcher in the build layer. @@ -13,6 +15,7 @@ */ export const WATCHER_BURST_SETTLE_MS = 550; + /** * Unsubscribes every subscription in parallel and returns the failures. Callers drain their list to * [] before calling, so a second drain is a no-op and a partial failure cannot leave @@ -26,6 +29,17 @@ export const WATCHER_BURST_SETTLE_MS = 550; * when all succeeded */ export async function drainSubscriptions(subscriptions) { - const results = await Promise.allSettled(subscriptions.map((s) => s.unsubscribe())); + trace(`drainSubscriptions: draining ${subscriptions.length} subscription(s)`); + const results = await Promise.allSettled(subscriptions.map(async (s, i) => { + trace(`drainSubscriptions: unsubscribe #${i} start`); + try { + await s.unsubscribe(); + trace(`drainSubscriptions: unsubscribe #${i} done`); + } catch (err) { + trace(`drainSubscriptions: unsubscribe #${i} threw: ${err?.message ?? err}`); + throw err; + } + })); + trace(`drainSubscriptions: all settled`); return results.filter((r) => r.status === "rejected").map((r) => r.reason); } diff --git a/packages/project/lib/graph/ProjectDefinitionWatcher.js b/packages/project/lib/graph/ProjectDefinitionWatcher.js index ad710ecda01..4755aa5f13b 100644 --- a/packages/project/lib/graph/ProjectDefinitionWatcher.js +++ b/packages/project/lib/graph/ProjectDefinitionWatcher.js @@ -3,6 +3,7 @@ import path from "node:path"; import {getLogger} from "@ui5/logger"; import {subscribe as watchSubscribe} from "../build/helpers/fileWatcher.js"; import {drainSubscriptions, WATCHER_BURST_SETTLE_MS} from "../build/helpers/watchUtil.js"; +import {trace} from "../build/helpers/teardownTrace.js"; import RecoveryBudget, { WATCHER_RECOVERY_MAX_ATTEMPTS, WATCHER_RECOVERY_WINDOW_MS, } from "../build/helpers/RecoveryBudget.js"; @@ -258,13 +259,16 @@ class ProjectDefinitionWatcher extends EventEmitter { * @returns {Promise} Resolves once every subscription has been drained */ async destroy() { + trace("ProjectDefinitionWatcher.destroy: enter"); this.#destroyed = true; this.#cancelSettleTimer(); const failures = await this.#drainSubscriptions(); + trace("ProjectDefinitionWatcher.destroy: drained"); if (failures.length) { const err = new AggregateError(failures, "Failed to unsubscribe one or more definition watchers"); this.emit("error", err); } + trace("ProjectDefinitionWatcher.destroy: exit"); } // Cancels a pending settle timer, if any. Safe to call when no timer is armed. diff --git a/packages/server/lib/serve/Supervisor.js b/packages/server/lib/serve/Supervisor.js index 6f0249d65d6..c8bab2253f8 100644 --- a/packages/server/lib/serve/Supervisor.js +++ b/packages/server/lib/serve/Supervisor.js @@ -6,6 +6,7 @@ import {getLogger} from "@ui5/logger"; import buildApp from "./stack.js"; import attachLiveReloadServer from "../liveReload/server.js"; import {listen, addSsl, announceListening} from "./httpListener.js"; +import {trace} from "./teardownTrace.js"; const log = getLogger("server:Supervisor"); @@ -576,19 +577,25 @@ class Supervisor extends EventEmitter { // Synchronous head: runs before any await and before the lock is acquired, so an in-flight // #swap or a late definitionChanged/recovery-timer sees DESTROYED at its next guard, and the // abort unblocks a recovery settle wait immediately rather than after its full window. + trace("Supervisor.destroy: enter"); this.#setState(STATE.DESTROYED); this.#destroyAbortController.abort(); this.#clearRecoveryTimer(); + trace("Supervisor.destroy: liveReloadHandle.close"); this.#liveReloadHandle?.close(); this.#detachRelay(); // Stop accepting new requests now, before waiting out any in-flight swap. Awaited last so the // returned promise resolves only once the socket is fully closed. + trace("Supervisor.destroy: httpServer.close start"); const httpClosed = new Promise((resolve) => { if (!this.#httpServer) { resolve(); return; } - this.#httpServer.close(() => resolve()); + this.#httpServer.close(() => { + trace("Supervisor.destroy: httpServer.close callback"); + resolve(); + }); }); // Teardown of the swappable fields runs under the same exclusive lock as #swap, so it never @@ -600,17 +607,23 @@ class Supervisor extends EventEmitter { const stack = this.#stack; this.#stack = null; try { + trace("Supervisor.destroy: definitionWatcher.destroy start"); await definitionWatcher?.destroy(); + trace("Supervisor.destroy: definitionWatcher.destroy done"); } catch (err) { log.verbose(`Error while destroying definition watcher: ${err?.message ?? err}`); } try { + trace("Supervisor.destroy: buildServer.destroy start"); await stack?.buildServer.destroy(); + trace("Supervisor.destroy: buildServer.destroy done"); } catch (err) { log.verbose(`Error while destroying BuildServer: ${err?.message ?? err}`); } }); + trace("Supervisor.destroy: awaiting httpClosed"); await httpClosed; + trace("Supervisor.destroy: exit"); } } diff --git a/packages/server/lib/serve/teardownTrace.js b/packages/server/lib/serve/teardownTrace.js new file mode 100644 index 00000000000..fda43c64337 --- /dev/null +++ b/packages/server/lib/serve/teardownTrace.js @@ -0,0 +1,28 @@ +import {writeSync} from "node:fs"; + +// Synchronous, env-gated teardown tracer. Set UI5_TEARDOWN_TRACE=1 to enable. +// +// Writes straight to fd 2 (stderr) with writeSync, bypassing the async stream buffer, so +// the last line survives a hard native crash (a 0xC0000005 access violation on Windows in +// @parcel/watcher or node:sqlite teardown terminates the process without flushing buffered +// output). Each line is prefixed with the high-resolution time and the pid so interleaved +// teardown across the Supervisor, BuildServer, and watchers can be ordered after the fact. +// +// Off by default and a no-op unless the env var is set, so it costs nothing in normal runs. +const ENABLED = process.env.UI5_TEARDOWN_TRACE === "1"; + +/** + * Emits a teardown trace line to stderr synchronously when UI5_TEARDOWN_TRACE=1. + * + * @param {string} msg Message to trace + */ +export function trace(msg) { + if (!ENABLED) { + return; + } + try { + writeSync(2, `[teardown ${process.hrtime.bigint()} pid=${process.pid}] ${msg}\n`); + } catch { + // Never let tracing throw during teardown. + } +} diff --git a/packages/server/test/probes/README.md b/packages/server/test/probes/README.md index 4f99195dd46..f9542f24513 100644 --- a/packages/server/test/probes/README.md +++ b/packages/server/test/probes/README.md @@ -57,6 +57,40 @@ npx ava test/lib/server/reinitialize.js -m "reinitialize() without a graphFactor Delete this directory once the origin is confirmed. +## Tracing the real (flaky) test's teardown + +The crash is **flaky** — the test usually passes. So the probes (deterministic) won't +reproduce it; the trigger is a timing-dependent race in native teardown/exit. To catch +*which* native step is being torn down when it does crash, there is an env-gated +synchronous tracer wired into every teardown step: + +- `Supervisor.destroy` (each phase: liveReload close, httpServer close, watcher destroy, + buildServer destroy, httpClosed) +- `BuildServer.destroy` (watchHandler destroy, validation stop, active-build await, cache close) +- `ProjectDefinitionWatcher.destroy` / `WatchHandler.destroy` +- `drainSubscriptions` (each individual `@parcel/watcher` `unsubscribe()`) +- `CacheManager.close` (refcount, last-ref) / `BuildCacheStorage.close` + (WAL checkpoint, then `db.close()`) + +Each line is written with `fs.writeSync(2, …)` so it survives a hard segfault (unbuffered), +and is stamped with `process.hrtime.bigint()` + pid to order interleaved teardown. + +Run the flaky test in a loop with tracing on until it crashes, capturing stderr: + +``` +# PowerShell (repeat until it dies) +$env:UI5_TEARDOWN_TRACE = "1" +for ($i=0; $i -lt 50; $i++) { + npx ava test/lib/server/reinitialize.js --serial 2>&1 | Tee-Object -Append trace.log + if ($LASTEXITCODE -eq -1073741819) { "CRASHED on iteration $i"; break } # -1073741819 = 0xC0000005 +} +``` + +Then look at the **last `[teardown …]` line** in `trace.log`: an operation with a +`start` but no matching `done` is the one that segfaulted (e.g. `db.close() start` with no +`db.close() done`, or `unsubscribe #1 start` with no `unsubscribe #1 done`). That names the +exact native call to harden. + ## Findings so far (Windows) All four component probes exit **clean** (exit 0), including `probe-serve` (the full From a8b9d49f0ef9fc04ca106dd505941f6836fb485e Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:12:14 +0200 Subject: [PATCH 08/13] docs(server): Stop trace loop on any non-zero AVA exit AVA wraps the worker's native 0xC0000005 and reports its own (non-zero) exit code rather than the raw crash code, so the loop must break on any non-zero exit, not on -1073741819. Also tag each iteration in the log so the crashing run is easy to locate. --- packages/server/test/probes/README.md | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/packages/server/test/probes/README.md b/packages/server/test/probes/README.md index f9542f24513..759e6a9cbed 100644 --- a/packages/server/test/probes/README.md +++ b/packages/server/test/probes/README.md @@ -75,18 +75,23 @@ synchronous tracer wired into every teardown step: Each line is written with `fs.writeSync(2, …)` so it survives a hard segfault (unbuffered), and is stamped with `process.hrtime.bigint()` + pid to order interleaved teardown. -Run the flaky test in a loop with tracing on until it crashes, capturing stderr: +Run the flaky test in a loop with tracing on until it crashes, capturing stderr. AVA +wraps the worker's native crash and reports its own exit code (non-zero, not the raw +`0xC0000005`), so stop the loop on **any** non-zero exit: ``` -# PowerShell (repeat until it dies) +# PowerShell (repeat until AVA fails) $env:UI5_TEARDOWN_TRACE = "1" for ($i=0; $i -lt 50; $i++) { + "===== iteration $i =====" | Tee-Object -Append trace.log npx ava test/lib/server/reinitialize.js --serial 2>&1 | Tee-Object -Append trace.log - if ($LASTEXITCODE -eq -1073741819) { "CRASHED on iteration $i"; break } # -1073741819 = 0xC0000005 + if ($LASTEXITCODE -ne 0) { "FAILED on iteration $i (exit $LASTEXITCODE)"; break } } ``` -Then look at the **last `[teardown …]` line** in `trace.log`: an operation with a +The worker's exit code (the actual `3221225477` = `0xC0000005`) is usually printed by AVA +in its failure output as part of the "exited with a non-zero exit code" line, so it lands +in `trace.log` too. Then look at the **last `[teardown …]` line** in `trace.log`: an operation with a `start` but no matching `done` is the one that segfaulted (e.g. `db.close() start` with no `db.close() done`, or `unsubscribe #1 start` with no `unsubscribe #1 done`). That names the exact native call to harden. From ee918d79f0886349987bbb5220d4de0706afdf90 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:21:20 +0200 Subject: [PATCH 09/13] fix(project): Serialize watcher unsubscribe to avoid @parcel/watcher race MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit drainSubscriptions fired every @parcel/watcher unsubscribe() concurrently via Promise.allSettled. @parcel/watcher has a data race on its global shared-backend registry between subscribe and unsubscribe (parcel-bundler/watcher#259); on Windows, where all subscriptions share one backend thread, the overlapping teardown access-violated (0xC0000005), crashing the AVA worker in test/lib/server/reinitialize.js. Synchronous teardown tracing pinpointed the crash to a watcher unsubscribe in flight (the final subscription started with no matching completion) while its siblings were being torn down in parallel — not to node:sqlite, whose db.close() always completed cleanly. Drain the subscriptions one at a time instead. The list is small (one subscription per watched directory) and this only runs at teardown, so the lost concurrency is irrelevant. Every unsubscribe() is still attempted and all failures are still collected. --- packages/project/lib/build/BuildServer.js | 11 -- .../lib/build/cache/BuildCacheStorage.js | 5 - .../project/lib/build/cache/CacheManager.js | 4 - .../project/lib/build/helpers/WatchHandler.js | 4 - .../lib/build/helpers/teardownTrace.js | 28 ---- .../project/lib/build/helpers/watchUtil.js | 32 ++--- .../lib/graph/ProjectDefinitionWatcher.js | 4 - .../test/lib/build/helpers/WatchHandler.js | 24 ++-- .../test/lib/build/helpers/watchUtil.js | 23 +++- packages/server/lib/serve/Supervisor.js | 11 -- packages/server/lib/serve/teardownTrace.js | 28 ---- packages/server/test/probes/README.md | 126 ------------------ packages/server/test/probes/probe-parcel.mjs | 39 ------ .../test/probes/probe-serve-supertest.mjs | 47 ------- .../server/test/probes/probe-serve-thrice.mjs | 44 ------ packages/server/test/probes/probe-serve.mjs | 52 -------- .../test/probes/probe-sqlite-reopen.mjs | 33 ----- packages/server/test/probes/probe-sqlite.mjs | 29 ---- 18 files changed, 54 insertions(+), 490 deletions(-) delete mode 100644 packages/project/lib/build/helpers/teardownTrace.js delete mode 100644 packages/server/lib/serve/teardownTrace.js delete mode 100644 packages/server/test/probes/README.md delete mode 100644 packages/server/test/probes/probe-parcel.mjs delete mode 100644 packages/server/test/probes/probe-serve-supertest.mjs delete mode 100644 packages/server/test/probes/probe-serve-thrice.mjs delete mode 100644 packages/server/test/probes/probe-serve.mjs delete mode 100644 packages/server/test/probes/probe-sqlite-reopen.mjs delete mode 100644 packages/server/test/probes/probe-sqlite.mjs diff --git a/packages/project/lib/build/BuildServer.js b/packages/project/lib/build/BuildServer.js index 663c2980da1..5b97b336f61 100644 --- a/packages/project/lib/build/BuildServer.js +++ b/packages/project/lib/build/BuildServer.js @@ -4,7 +4,6 @@ import BuildReader from "./BuildReader.js"; import WatchHandler from "./helpers/WatchHandler.js"; import {isAbortError, isFileNotFoundError} from "./helpers/abort.js"; import {WATCHER_BURST_SETTLE_MS} from "./helpers/watchUtil.js"; -import {trace} from "./helpers/teardownTrace.js"; import RecoveryBudget, {WATCHER_RECOVERY_MAX_ATTEMPTS, WATCHER_RECOVERY_WINDOW_MS} from "./helpers/RecoveryBudget.js"; import {getLogger} from "@ui5/logger"; import ServeLogger from "@ui5/logger/internal/loggers/Serve"; @@ -369,35 +368,25 @@ class BuildServer extends EventEmitter { async destroy() { - trace("BuildServer.destroy: enter"); this.#destroyed = true; clearTimeout(this.#processBuildRequestsTimeout); this.#pendingDeferredRestart = false; clearTimeout(this.#sourcesChangedTimeout); this.#pendingFinalSourcesChanged = false; - trace("BuildServer.destroy: watchHandler.destroy start"); await this.#watchHandler.destroy(); - trace("BuildServer.destroy: watchHandler.destroy done"); try { // Cancel any running background validation pass and wait for it to settle. - trace("BuildServer.destroy: stopActiveValidation start"); await this.#stopActiveValidation("Server destroyed"); - trace("BuildServer.destroy: stopActiveValidation done"); if (this.#activeBuild) { // Await active build to finish - trace("BuildServer.destroy: awaiting activeBuild"); await this.#activeBuild; - trace("BuildServer.destroy: activeBuild settled"); } } finally { // Always release the cache manager, even when the active build rejected // (e.g. Force-mode stale-cache errors). Otherwise the SQLite handle leaks // and subsequent fs.rm of the cache directory fails with EBUSY on Windows. - trace("BuildServer.destroy: closeCacheManager start"); this.#projectBuilder.closeCacheManager(); - trace("BuildServer.destroy: closeCacheManager done"); } - trace("BuildServer.destroy: exit"); } /** diff --git a/packages/project/lib/build/cache/BuildCacheStorage.js b/packages/project/lib/build/cache/BuildCacheStorage.js index 353c4da8095..13fb50c491a 100644 --- a/packages/project/lib/build/cache/BuildCacheStorage.js +++ b/packages/project/lib/build/cache/BuildCacheStorage.js @@ -3,7 +3,6 @@ import {mkdirSync, existsSync} from "node:fs"; import path from "node:path"; import {gzipSync, gunzipSync} from "node:zlib"; import {getLogger} from "@ui5/logger"; -import {trace} from "../helpers/teardownTrace.js"; const log = getLogger("build:cache:BuildCacheStorage"); @@ -604,7 +603,6 @@ export default class BuildCacheStorage { * Closes the database connection */ close() { - trace(`BuildCacheStorage.close: enter (${this.#dbPath})`); if (this.#inTransaction) { try { this.#db.exec("ROLLBACK"); @@ -612,11 +610,8 @@ export default class BuildCacheStorage { this.#inTransaction = false; } } - trace("BuildCacheStorage.close: wal_checkpoint(TRUNCATE) start"); this.#db.exec("PRAGMA wal_checkpoint(TRUNCATE)"); - trace("BuildCacheStorage.close: wal_checkpoint done, db.close() start"); this.#db.close(); - trace("BuildCacheStorage.close: db.close() done"); } /** diff --git a/packages/project/lib/build/cache/CacheManager.js b/packages/project/lib/build/cache/CacheManager.js index 0ffde09a83a..d1baec61eb0 100644 --- a/packages/project/lib/build/cache/CacheManager.js +++ b/packages/project/lib/build/cache/CacheManager.js @@ -4,7 +4,6 @@ import Configuration from "../../config/Configuration.js"; import {access} from "node:fs/promises"; import {getLogger} from "@ui5/logger"; import BuildCacheStorage from "./BuildCacheStorage.js"; -import {trace} from "../helpers/teardownTrace.js"; const log = getLogger("build:cache:CacheManager"); @@ -336,12 +335,9 @@ export default class CacheManager { * closed only when the last consumer releases its reference. */ close() { - trace(`CacheManager.close: refCount ${this.#refCount} -> ${this.#refCount - 1} (${this.#cacheDir})`); if (--this.#refCount <= 0) { - trace("CacheManager.close: last ref, closing storage"); this.#storage.close(); cacheManagerInstances.delete(this.#cacheDir); - trace("CacheManager.close: storage closed, instance removed"); } } diff --git a/packages/project/lib/build/helpers/WatchHandler.js b/packages/project/lib/build/helpers/WatchHandler.js index d721f3a726a..f9180081f93 100644 --- a/packages/project/lib/build/helpers/WatchHandler.js +++ b/packages/project/lib/build/helpers/WatchHandler.js @@ -2,7 +2,6 @@ import EventEmitter from "node:events"; import {getLogger} from "@ui5/logger"; import {subscribe as watchSubscribe} from "./fileWatcher.js"; import {drainSubscriptions} from "./watchUtil.js"; -import {trace} from "./teardownTrace.js"; import {exists} from "../../utils/fsHelper.js"; const log = getLogger("build:helpers:WatchHandler"); @@ -64,18 +63,15 @@ class WatchHandler extends EventEmitter { } async destroy() { - trace("WatchHandler.destroy: enter"); // Drain the subscriptions list so a second destroy() is a no-op and a partial // failure cannot leave stale handles behind to be unsubscribed twice. const subscriptions = this.#subscriptions; this.#subscriptions = []; const failures = await drainSubscriptions(subscriptions); - trace("WatchHandler.destroy: drained"); if (failures.length) { const err = new AggregateError(failures, "Failed to unsubscribe one or more file watchers"); this.emit("error", err); } - trace("WatchHandler.destroy: exit"); } #handleWatchEvents(eventType, filePath, project) { diff --git a/packages/project/lib/build/helpers/teardownTrace.js b/packages/project/lib/build/helpers/teardownTrace.js deleted file mode 100644 index fda43c64337..00000000000 --- a/packages/project/lib/build/helpers/teardownTrace.js +++ /dev/null @@ -1,28 +0,0 @@ -import {writeSync} from "node:fs"; - -// Synchronous, env-gated teardown tracer. Set UI5_TEARDOWN_TRACE=1 to enable. -// -// Writes straight to fd 2 (stderr) with writeSync, bypassing the async stream buffer, so -// the last line survives a hard native crash (a 0xC0000005 access violation on Windows in -// @parcel/watcher or node:sqlite teardown terminates the process without flushing buffered -// output). Each line is prefixed with the high-resolution time and the pid so interleaved -// teardown across the Supervisor, BuildServer, and watchers can be ordered after the fact. -// -// Off by default and a no-op unless the env var is set, so it costs nothing in normal runs. -const ENABLED = process.env.UI5_TEARDOWN_TRACE === "1"; - -/** - * Emits a teardown trace line to stderr synchronously when UI5_TEARDOWN_TRACE=1. - * - * @param {string} msg Message to trace - */ -export function trace(msg) { - if (!ENABLED) { - return; - } - try { - writeSync(2, `[teardown ${process.hrtime.bigint()} pid=${process.pid}] ${msg}\n`); - } catch { - // Never let tracing throw during teardown. - } -} diff --git a/packages/project/lib/build/helpers/watchUtil.js b/packages/project/lib/build/helpers/watchUtil.js index d1f79eb2d45..fe4ebb05445 100644 --- a/packages/project/lib/build/helpers/watchUtil.js +++ b/packages/project/lib/build/helpers/watchUtil.js @@ -1,5 +1,3 @@ -import {trace} from "./teardownTrace.js"; - /** * Settle window (ms) for collapsing a burst of filesystem events into one trailing action. Shared * by every Parcel watcher in the build layer. @@ -17,10 +15,18 @@ export const WATCHER_BURST_SETTLE_MS = 550; /** - * Unsubscribes every subscription in parallel and returns the failures. Callers drain their list to + * Unsubscribes every subscription and returns the failures. Callers drain their list to * [] before calling, so a second drain is a no-op and a partial failure cannot leave - * stale handles to be unsubscribed twice. Running in parallel and collecting failures keeps one - * misbehaving subscription from taking down the others. + * stale handles to be unsubscribed twice. Each unsubscribe() is attempted even if an + * earlier one rejects, so one misbehaving subscription cannot leave the others subscribed. + * + * Unsubscribes run sequentially, not in parallel: @parcel/watcher has a data + * race on its global shared-backend registry between subscribe and unsubscribe + * (parcel-bundler/watcher#259). Firing every unsubscribe() at once raced that registry + * and access-violated (0xC0000005) mid-teardown on Windows, where all subscriptions + * share one backend thread. Draining one at a time keeps each native teardown from overlapping the + * next. The list is small (one subscription per watched directory) and this only runs at teardown, + * so the lost concurrency does not matter. * * @private * @param {object[]} subscriptions Subscriptions to drain, each exposing an async @@ -29,17 +35,13 @@ export const WATCHER_BURST_SETTLE_MS = 550; * when all succeeded */ export async function drainSubscriptions(subscriptions) { - trace(`drainSubscriptions: draining ${subscriptions.length} subscription(s)`); - const results = await Promise.allSettled(subscriptions.map(async (s, i) => { - trace(`drainSubscriptions: unsubscribe #${i} start`); + const failures = []; + for (const subscription of subscriptions) { try { - await s.unsubscribe(); - trace(`drainSubscriptions: unsubscribe #${i} done`); + await subscription.unsubscribe(); } catch (err) { - trace(`drainSubscriptions: unsubscribe #${i} threw: ${err?.message ?? err}`); - throw err; + failures.push(err); } - })); - trace(`drainSubscriptions: all settled`); - return results.filter((r) => r.status === "rejected").map((r) => r.reason); + } + return failures; } diff --git a/packages/project/lib/graph/ProjectDefinitionWatcher.js b/packages/project/lib/graph/ProjectDefinitionWatcher.js index 4755aa5f13b..ad710ecda01 100644 --- a/packages/project/lib/graph/ProjectDefinitionWatcher.js +++ b/packages/project/lib/graph/ProjectDefinitionWatcher.js @@ -3,7 +3,6 @@ import path from "node:path"; import {getLogger} from "@ui5/logger"; import {subscribe as watchSubscribe} from "../build/helpers/fileWatcher.js"; import {drainSubscriptions, WATCHER_BURST_SETTLE_MS} from "../build/helpers/watchUtil.js"; -import {trace} from "../build/helpers/teardownTrace.js"; import RecoveryBudget, { WATCHER_RECOVERY_MAX_ATTEMPTS, WATCHER_RECOVERY_WINDOW_MS, } from "../build/helpers/RecoveryBudget.js"; @@ -259,16 +258,13 @@ class ProjectDefinitionWatcher extends EventEmitter { * @returns {Promise} Resolves once every subscription has been drained */ async destroy() { - trace("ProjectDefinitionWatcher.destroy: enter"); this.#destroyed = true; this.#cancelSettleTimer(); const failures = await this.#drainSubscriptions(); - trace("ProjectDefinitionWatcher.destroy: drained"); if (failures.length) { const err = new AggregateError(failures, "Failed to unsubscribe one or more definition watchers"); this.emit("error", err); } - trace("ProjectDefinitionWatcher.destroy: exit"); } // Cancels a pending settle timer, if any. Safe to call when no timer is armed. diff --git a/packages/project/test/lib/build/helpers/WatchHandler.js b/packages/project/test/lib/build/helpers/WatchHandler.js index db799d1d002..89a78dfaad9 100644 --- a/packages/project/test/lib/build/helpers/WatchHandler.js +++ b/packages/project/test/lib/build/helpers/WatchHandler.js @@ -283,18 +283,23 @@ test.serial("watch: rejects when subscribe fails on an existing path", async (t) await handler.destroy(); }); -test.serial("destroy: unsubscribes subscriptions in parallel", async (t) => { +test.serial("destroy: unsubscribes subscriptions sequentially, not concurrently", async (t) => { const subA = createMockSubscription(); const subB = createMockSubscription(); - // Make subA's unsubscribe block until subB's has at least started. - // If destroy() runs sequentially, subB.unsubscribe is never called while - // subA is still pending and the test deadlocks (caught by AVA timeout). - let resolveA; - subA.unsubscribe = sinon.stub().returns(new Promise((resolve) => { - resolveA = resolve; - })); + // @parcel/watcher races its shared-backend registry when unsubscribe calls overlap + // (parcel-bundler/watcher#259), which segfaults on Windows. destroy() must not start + // subB.unsubscribe while subA.unsubscribe is still pending. + let subAPending = false; + let overlapped = false; + subA.unsubscribe = sinon.stub().callsFake(async () => { + subAPending = true; + await new Promise((resolve) => setImmediate(resolve)); + subAPending = false; + }); subB.unsubscribe = sinon.stub().callsFake(async () => { - resolveA(); + if (subAPending) { + overlapped = true; + } }); subscribeStub.onFirstCall().resolves(subA); subscribeStub.onSecondCall().resolves(subB); @@ -311,6 +316,7 @@ test.serial("destroy: unsubscribes subscriptions in parallel", async (t) => { t.true(subA.unsubscribe.calledOnce); t.true(subB.unsubscribe.calledOnce); + t.false(overlapped, "subB.unsubscribe did not start while subA.unsubscribe was still pending"); }); test.serial("destroy: continues unsubscribing when one subscription rejects", async (t) => { diff --git a/packages/project/test/lib/build/helpers/watchUtil.js b/packages/project/test/lib/build/helpers/watchUtil.js index 92f70b8d0b5..542493ea635 100644 --- a/packages/project/test/lib/build/helpers/watchUtil.js +++ b/packages/project/test/lib/build/helpers/watchUtil.js @@ -15,7 +15,7 @@ test("drainSubscriptions: unsubscribes every subscription and returns no failure t.true(subs[1].unsubscribe.calledOnce); }); -test("drainSubscriptions: unsubscribes all in parallel even when some reject, collecting the reasons", +test("drainSubscriptions: unsubscribes all even when some reject, collecting the reasons", async (t) => { const errA = new Error("unsub A failed"); const errC = new Error("unsub C failed"); @@ -31,6 +31,27 @@ test("drainSubscriptions: unsubscribes all in parallel even when some reject, co t.true(subs[1].unsubscribe.calledOnce, "a rejecting sibling does not prevent the others"); }); +test("drainSubscriptions: unsubscribes sequentially, not concurrently", async (t) => { + // @parcel/watcher races its shared-backend registry when subscribe/unsubscribe overlap + // (parcel-bundler/watcher#259), which segfaults on Windows. drainSubscriptions must not have a + // second unsubscribe() in flight while an earlier one is still pending. + let inFlight = 0; + let maxInFlight = 0; + const makeSub = () => ({ + unsubscribe: async () => { + inFlight++; + maxInFlight = Math.max(maxInFlight, inFlight); + await new Promise((resolve) => setImmediate(resolve)); + inFlight--; + }, + }); + const subs = [makeSub(), makeSub(), makeSub()]; + + await drainSubscriptions(subs); + + t.is(maxInFlight, 1, "never more than one unsubscribe() in flight at a time"); +}); + test("drainSubscriptions: an empty list resolves to no failures", async (t) => { t.deepEqual(await drainSubscriptions([]), []); }); diff --git a/packages/server/lib/serve/Supervisor.js b/packages/server/lib/serve/Supervisor.js index c8bab2253f8..1dcf583fbab 100644 --- a/packages/server/lib/serve/Supervisor.js +++ b/packages/server/lib/serve/Supervisor.js @@ -6,7 +6,6 @@ import {getLogger} from "@ui5/logger"; import buildApp from "./stack.js"; import attachLiveReloadServer from "../liveReload/server.js"; import {listen, addSsl, announceListening} from "./httpListener.js"; -import {trace} from "./teardownTrace.js"; const log = getLogger("server:Supervisor"); @@ -577,23 +576,19 @@ class Supervisor extends EventEmitter { // Synchronous head: runs before any await and before the lock is acquired, so an in-flight // #swap or a late definitionChanged/recovery-timer sees DESTROYED at its next guard, and the // abort unblocks a recovery settle wait immediately rather than after its full window. - trace("Supervisor.destroy: enter"); this.#setState(STATE.DESTROYED); this.#destroyAbortController.abort(); this.#clearRecoveryTimer(); - trace("Supervisor.destroy: liveReloadHandle.close"); this.#liveReloadHandle?.close(); this.#detachRelay(); // Stop accepting new requests now, before waiting out any in-flight swap. Awaited last so the // returned promise resolves only once the socket is fully closed. - trace("Supervisor.destroy: httpServer.close start"); const httpClosed = new Promise((resolve) => { if (!this.#httpServer) { resolve(); return; } this.#httpServer.close(() => { - trace("Supervisor.destroy: httpServer.close callback"); resolve(); }); }); @@ -607,23 +602,17 @@ class Supervisor extends EventEmitter { const stack = this.#stack; this.#stack = null; try { - trace("Supervisor.destroy: definitionWatcher.destroy start"); await definitionWatcher?.destroy(); - trace("Supervisor.destroy: definitionWatcher.destroy done"); } catch (err) { log.verbose(`Error while destroying definition watcher: ${err?.message ?? err}`); } try { - trace("Supervisor.destroy: buildServer.destroy start"); await stack?.buildServer.destroy(); - trace("Supervisor.destroy: buildServer.destroy done"); } catch (err) { log.verbose(`Error while destroying BuildServer: ${err?.message ?? err}`); } }); - trace("Supervisor.destroy: awaiting httpClosed"); await httpClosed; - trace("Supervisor.destroy: exit"); } } diff --git a/packages/server/lib/serve/teardownTrace.js b/packages/server/lib/serve/teardownTrace.js deleted file mode 100644 index fda43c64337..00000000000 --- a/packages/server/lib/serve/teardownTrace.js +++ /dev/null @@ -1,28 +0,0 @@ -import {writeSync} from "node:fs"; - -// Synchronous, env-gated teardown tracer. Set UI5_TEARDOWN_TRACE=1 to enable. -// -// Writes straight to fd 2 (stderr) with writeSync, bypassing the async stream buffer, so -// the last line survives a hard native crash (a 0xC0000005 access violation on Windows in -// @parcel/watcher or node:sqlite teardown terminates the process without flushing buffered -// output). Each line is prefixed with the high-resolution time and the pid so interleaved -// teardown across the Supervisor, BuildServer, and watchers can be ordered after the fact. -// -// Off by default and a no-op unless the env var is set, so it costs nothing in normal runs. -const ENABLED = process.env.UI5_TEARDOWN_TRACE === "1"; - -/** - * Emits a teardown trace line to stderr synchronously when UI5_TEARDOWN_TRACE=1. - * - * @param {string} msg Message to trace - */ -export function trace(msg) { - if (!ENABLED) { - return; - } - try { - writeSync(2, `[teardown ${process.hrtime.bigint()} pid=${process.pid}] ${msg}\n`); - } catch { - // Never let tracing throw during teardown. - } -} diff --git a/packages/server/test/probes/README.md b/packages/server/test/probes/README.md deleted file mode 100644 index 759e6a9cbed..00000000000 --- a/packages/server/test/probes/README.md +++ /dev/null @@ -1,126 +0,0 @@ -# Windows `0xC0000005` pinpointing kit for `reinitialize.js` - -`test/lib/server/reinitialize.js` exits with `3221225477` (`0xC0000005`, an **access -violation**) on Windows. That is a native crash in the AVA worker **child process** -(AVA runs each test file in a forked process — `workerThreads: false`), not a JS-level -test failure. The two native subsystems this test drives are: - -- **`@parcel/watcher`** — the source watcher (`WatchHandler`) and the definition watcher - (`ProjectDefinitionWatcher`). On Windows it runs a background `ReadDirectoryChangesW` - thread; a watch thread outliving `unsubscribe()` or racing process exit is a classic - `0xC0000005` source. -- **`node:sqlite`** (`BuildCacheStorage`) — opened with `PRAGMA journal_mode=WAL` and - `PRAGMA mmap_size=268435456`. Closing a memory-mapped WAL database, or letting the - process exit while pages are still mapped, can access-violate on Windows. - -The branch already serialized `destroy()` against the in-flight swap and cancelled the -settle timer, yet the crash persists — which points at native teardown / process exit -rather than a JS race. - -Run these probes on the Windows machine (from `packages/server`) and report the exit -code of each. `echo %ERRORLEVEL%` after each in cmd, or `$LASTEXITCODE` in PowerShell. -`3221225477` = the crash; `0` = clean. - -``` -node test/probes/probe-sqlite.mjs # node:sqlite open/write/close, single handle -node test/probes/probe-sqlite-reopen.mjs # two overlapping handles on one WAL+mmap db (the swap pattern) -node test/probes/probe-parcel.mjs # @parcel/watcher subscribe/event/unsubscribe -node test/probes/probe-serve.mjs # full serve() -> reinitialize() -> close(), no AVA -``` - -`probe-serve.mjs` prints staged markers (`serving` / `reinitialized` / `closed` / -`settled`). Note the last line printed before a crash: - -- crash **before** `closed` → teardown while JS still running. -- `closed` + `settled` printed, crash **after** → exit-time native handle not released. -- exit 0 → the isolated lifecycle is clean; the trigger needs the AVA worker environment. - -## Which probe crashed → where it originates - -| Crashes | Clean | Origin | -|---|---|---| -| `probe-sqlite` | — | `node:sqlite` close (WAL checkpoint / mmap unmap) — single handle is enough | -| `probe-sqlite-reopen` | `probe-sqlite` | overlapping handles on one WAL+mmap db (the reinitialize swap) | -| `probe-parcel` | sqlite probes | `@parcel/watcher` native teardown / watch thread vs. exit | -| `probe-serve` | all component probes | interaction only visible in the full lifecycle | -| none | all | needs the AVA worker env (supertest sockets, `--loader`, concurrent files) | - -## Bisecting the AVA subtests - -`reinitialize.js` has three serial subtests. Run each alone to see which crashes: - -``` -npx ava test/lib/server/reinitialize.js -m "reinitialize() keeps the port bound*" -npx ava test/lib/server/reinitialize.js -m "editing ui5.yaml triggers*" -npx ava test/lib/server/reinitialize.js -m "reinitialize() without a graphFactory*" -``` - -Delete this directory once the origin is confirmed. - -## Tracing the real (flaky) test's teardown - -The crash is **flaky** — the test usually passes. So the probes (deterministic) won't -reproduce it; the trigger is a timing-dependent race in native teardown/exit. To catch -*which* native step is being torn down when it does crash, there is an env-gated -synchronous tracer wired into every teardown step: - -- `Supervisor.destroy` (each phase: liveReload close, httpServer close, watcher destroy, - buildServer destroy, httpClosed) -- `BuildServer.destroy` (watchHandler destroy, validation stop, active-build await, cache close) -- `ProjectDefinitionWatcher.destroy` / `WatchHandler.destroy` -- `drainSubscriptions` (each individual `@parcel/watcher` `unsubscribe()`) -- `CacheManager.close` (refcount, last-ref) / `BuildCacheStorage.close` - (WAL checkpoint, then `db.close()`) - -Each line is written with `fs.writeSync(2, …)` so it survives a hard segfault (unbuffered), -and is stamped with `process.hrtime.bigint()` + pid to order interleaved teardown. - -Run the flaky test in a loop with tracing on until it crashes, capturing stderr. AVA -wraps the worker's native crash and reports its own exit code (non-zero, not the raw -`0xC0000005`), so stop the loop on **any** non-zero exit: - -``` -# PowerShell (repeat until AVA fails) -$env:UI5_TEARDOWN_TRACE = "1" -for ($i=0; $i -lt 50; $i++) { - "===== iteration $i =====" | Tee-Object -Append trace.log - npx ava test/lib/server/reinitialize.js --serial 2>&1 | Tee-Object -Append trace.log - if ($LASTEXITCODE -ne 0) { "FAILED on iteration $i (exit $LASTEXITCODE)"; break } -} -``` - -The worker's exit code (the actual `3221225477` = `0xC0000005`) is usually printed by AVA -in its failure output as part of the "exited with a non-zero exit code" line, so it lands -in `trace.log` too. Then look at the **last `[teardown …]` line** in `trace.log`: an operation with a -`start` but no matching `done` is the one that segfaulted (e.g. `db.close() start` with no -`db.close() done`, or `unsubscribe #1 start` with no `unsubscribe #1 done`). That names the -exact native call to harden. - -## Findings so far (Windows) - -All four component probes exit **clean** (exit 0), including `probe-serve` (the full -serve → reinitialize → close lifecycle). So the crash is **not** in any native subsystem -in isolation, nor in a single lifecycle. That narrows the trigger to what the AVA worker -adds on top: the `supertest` request sockets, the `--loader=esmock` + `--import -suppressLog` worker flags, and three serial subtests sharing one worker process. - -Next probes isolate those additions (run from `packages/server`): - -``` -node test/probes/probe-serve-supertest.mjs # lifecycle + real HTTP requests (socket churn) -node test/probes/probe-serve-thrice.mjs # three serve/reinitialize/close cycles in one process -``` - -Then bisect the real test under the actual AVA worker (loader + suppressLog + supertest): - -``` -npx ava test/lib/server/reinitialize.js -m "reinitialize() keeps the port bound*" -npx ava test/lib/server/reinitialize.js -m "editing ui5.yaml triggers*" -npx ava test/lib/server/reinitialize.js -m "reinitialize() without a graphFactory*" -``` - -- If a probe crashes → the addition it introduces (sockets / repetition) is the trigger. -- If all probes are clean but a single `-m` subtest crashes → that subtest's specifics - (e.g. the watcher-driven edit, or the tmp-dir copy) are the trigger under AVA. -- If only the full file crashes but each `-m` subtest is clean → cross-subtest state in - one worker (a handle from subtest N surviving into N+1) is the trigger. diff --git a/packages/server/test/probes/probe-parcel.mjs b/packages/server/test/probes/probe-parcel.mjs deleted file mode 100644 index f4181977be8..00000000000 --- a/packages/server/test/probes/probe-parcel.mjs +++ /dev/null @@ -1,39 +0,0 @@ -// Probe C — @parcel/watcher subscribe/unsubscribe native teardown in isolation. -// -// Subscribes to a directory, triggers an event, unsubscribes, then lets the process exit. -// If this crashes with 0xC0000005 on Windows, the origin is the @parcel/watcher native -// binding (a background ReadDirectoryChangesW thread outliving unsubscribe / racing exit), -// independent of node:sqlite and the swap logic. -// -// Run from packages/project: node ../server/test/tmp/probe-parcel.mjs -import path from "node:path"; -import fs from "node:fs/promises"; -import {fileURLToPath, pathToFileURL} from "node:url"; - -const here = path.dirname(fileURLToPath(import.meta.url)); -const {subscribe} = await import( - pathToFileURL(path.resolve(here, "../../../project/lib/build/helpers/fileWatcher.js"))); - -const dir = path.resolve(here, `probe-parcel-${process.pid}`); -await fs.mkdir(dir, {recursive: true}); -console.log(`[probe-parcel] subscribing to ${dir}`); - -let eventCount = 0; -const sub = await subscribe(dir, (err, events) => { - if (err) { - console.error(`[probe-parcel] watcher error: ${err.message}`); - return; - } - eventCount += events.length; -}); - -// Produce a change so the native watch thread is actively delivering. -await fs.writeFile(path.join(dir, "file.txt"), "hello"); -await new Promise((r) => setTimeout(r, 300)); -await fs.writeFile(path.join(dir, "file.txt"), "world"); -await new Promise((r) => setTimeout(r, 300)); -console.log(`[probe-parcel] observed ${eventCount} event(s)`); - -console.log(`[probe-parcel] unsubscribing`); -await sub.unsubscribe(); -console.log(`[probe-parcel] unsubscribed OK — process exiting`); diff --git a/packages/server/test/probes/probe-serve-supertest.mjs b/packages/server/test/probes/probe-serve-supertest.mjs deleted file mode 100644 index 85d6aff53ee..00000000000 --- a/packages/server/test/probes/probe-serve-supertest.mjs +++ /dev/null @@ -1,47 +0,0 @@ -// Probe E — serve() lifecycle WITH supertest requests, standalone (no AVA). -// -// probe-serve.mjs exits clean, so the isolated lifecycle is fine. The real test differs -// in that it drives HTTP requests through supertest against the bound socket. This probe -// adds exactly that: GET /index.html before and after reinitialize(), then close(). If -// this crashes but probe-serve does not, the trigger involves the request sockets / -// keep-alive handles interacting with teardown. -// -// Run from packages/server: node test/probes/probe-serve-supertest.mjs -import path from "node:path"; -import {fileURLToPath, pathToFileURL} from "node:url"; - -process.env.NODE_ENV = "test"; -const here = path.dirname(fileURLToPath(import.meta.url)); -const serverRoot = path.resolve(here, "..", ".."); -process.chdir(serverRoot); - -const {serve} = await import(pathToFileURL(path.resolve(serverRoot, "lib/server.js"))); -const {graphFromPackageDependencies} = await import("@ui5/project/graph"); -const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); -const {default: supertest} = await import("supertest"); - -const buildGraph = () => graphFromPackageDependencies({cwd: "./test/fixtures/application.a"}); - -const ui5DataDir = path.resolve("test", "tmp", "buildcache", `probe-serve-supertest-${process.pid}`); -const graph = await buildGraph(); -const server = await serve(graph, { - port: 3399, - changePortIfInUse: true, - liveReload: false, - ui5DataDir, -}, undefined, buildGraph, projectWatcher); -console.log(`[probe-supertest] listening on ${server.port}`); - -const request = supertest(`http://127.0.0.1:${server.port}`); -console.log(`[probe-supertest] GET before: ${(await request.get("/index.html")).statusCode}`); - -await server.reinitialize(); -console.log(`[probe-supertest] reinitialized`); - -console.log(`[probe-supertest] GET after: ${(await request.get("/index.html")).statusCode}`); - -await new Promise((resolve) => server.close(resolve)); -console.log(`[probe-supertest] closed`); - -await new Promise((r) => setTimeout(r, 1000)); -console.log(`[probe-supertest] settled — process exiting`); diff --git a/packages/server/test/probes/probe-serve-thrice.mjs b/packages/server/test/probes/probe-serve-thrice.mjs deleted file mode 100644 index ab4c7f524db..00000000000 --- a/packages/server/test/probes/probe-serve-thrice.mjs +++ /dev/null @@ -1,44 +0,0 @@ -// Probe F — three serve/reinitialize/close cycles in one process (no AVA). -// -// The real test file has three serial subtests, each a full serve/…/close. AVA runs them -// back-to-back in ONE worker process. probe-serve.mjs does a single cycle and exits clean; -// this repeats the cycle three times with supertest requests, so a crash that only shows -// up after repeated open/close of the native handles (parcel re-subscribe, sqlite reopen -// on the same cache dir, socket churn) in one long-lived process is reproduced. -// -// Run from packages/server: node test/probes/probe-serve-thrice.mjs -import path from "node:path"; -import {fileURLToPath, pathToFileURL} from "node:url"; - -process.env.NODE_ENV = "test"; -const here = path.dirname(fileURLToPath(import.meta.url)); -const serverRoot = path.resolve(here, "..", ".."); -process.chdir(serverRoot); - -const {serve} = await import(pathToFileURL(path.resolve(serverRoot, "lib/server.js"))); -const {graphFromPackageDependencies} = await import("@ui5/project/graph"); -const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); -const {default: supertest} = await import("supertest"); - -const buildGraph = () => graphFromPackageDependencies({cwd: "./test/fixtures/application.a"}); - -for (let cycle = 1; cycle <= 3; cycle++) { - const ui5DataDir = path.resolve( - "test", "tmp", "buildcache", `probe-thrice-${cycle}-${process.pid}`); - const graph = await buildGraph(); - const server = await serve(graph, { - port: 3400 + cycle, - changePortIfInUse: true, - liveReload: false, - ui5DataDir, - }, undefined, buildGraph, projectWatcher); - const request = supertest(`http://127.0.0.1:${server.port}`); - await request.get("/index.html"); - await server.reinitialize(); - await request.get("/index.html"); - await new Promise((resolve) => server.close(resolve)); - console.log(`[probe-thrice] cycle ${cycle} done (port ${server.port})`); -} - -await new Promise((r) => setTimeout(r, 1000)); -console.log(`[probe-thrice] all cycles settled — process exiting`); diff --git a/packages/server/test/probes/probe-serve.mjs b/packages/server/test/probes/probe-serve.mjs deleted file mode 100644 index 4ef95d69052..00000000000 --- a/packages/server/test/probes/probe-serve.mjs +++ /dev/null @@ -1,52 +0,0 @@ -// Probe D — Full serve() -> reinitialize() -> close() lifecycle, standalone (no AVA). -// -// Mirrors the first subtest of reinitialize.js against the real graph + BuildServer + -// Supervisor, but as a plain Node process so the exit code is attributable to this flow -// alone (AVA is not in the picture). After close() resolves it prints a marker, waits -// briefly, then exits. -// -// - If it crashes 0xC0000005 BEFORE "[probe-serve] closed" -> the crash is during -// destroy()/teardown while JS is still running. -// - If it prints "[probe-serve] closed" and "[probe-serve] settled" and THEN the -// process crashes on exit -> the crash is at process exit with a native handle -// (parcel watch thread / sqlite mmap) not fully released. -// - Exit 0 clean -> the isolated lifecycle does not reproduce it; the trigger needs -// the AVA worker environment (e.g. supertest sockets, the loader, concurrent files). -// -// Run from packages/server: node test/probes/probe-serve.mjs -import path from "node:path"; -import {fileURLToPath, pathToFileURL} from "node:url"; - -process.env.NODE_ENV = "test"; -const here = path.dirname(fileURLToPath(import.meta.url)); -const serverRoot = path.resolve(here, "..", ".."); -process.chdir(serverRoot); // so ./test/fixtures/application.a resolves like the test - -const {serve} = await import(pathToFileURL(path.resolve(serverRoot, "lib/server.js"))); -const {graphFromPackageDependencies} = await import("@ui5/project/graph"); -const projectWatcher = await import("@ui5/project/internal/graph/ProjectDefinitionWatcher"); - -const buildGraph = () => graphFromPackageDependencies({cwd: "./test/fixtures/application.a"}); - -const ui5DataDir = path.resolve("test", "tmp", "buildcache", `probe-serve-${process.pid}`); -console.log(`[probe-serve] serving (ui5DataDir=${ui5DataDir})`); -const graph = await buildGraph(); -const server = await serve(graph, { - port: 3399, // fixed port; changePortIfInUse bumps it if busy - changePortIfInUse: true, - liveReload: false, - ui5DataDir, -}, undefined, buildGraph, projectWatcher); -console.log(`[probe-serve] listening on ${server.port}`); - -console.log(`[probe-serve] reinitialize`); -await server.reinitialize(); -console.log(`[probe-serve] reinitialized`); - -await new Promise((resolve) => server.close(resolve)); -console.log(`[probe-serve] closed`); - -// Hold the process open briefly so an exit-time native crash is clearly separated from -// the in-flight teardown above. -await new Promise((r) => setTimeout(r, 1000)); -console.log(`[probe-serve] settled — process exiting`); diff --git a/packages/server/test/probes/probe-sqlite-reopen.mjs b/packages/server/test/probes/probe-sqlite-reopen.mjs deleted file mode 100644 index 98f3edd5e8e..00000000000 --- a/packages/server/test/probes/probe-sqlite-reopen.mjs +++ /dev/null @@ -1,33 +0,0 @@ -// Probe B — node:sqlite reopen/refcount pattern of a reinitialize() swap. -// -// A reinitialize() opens a SECOND handle on the same cache dir before the first is -// closed (refcount 1 -> 2), then closes the first (2 -> 1), later the second (1 -> 0). -// Two DatabaseSync handles onto the same WAL+mmap file, overlapping, then both closed. -// If this crashes but probe-sqlite does not, the origin is concurrent handles onto the -// same mmapped WAL DB on Windows. -// -// Run from packages/project: node ../server/test/tmp/probe-sqlite-reopen.mjs -import path from "node:path"; -import {fileURLToPath, pathToFileURL} from "node:url"; - -const here = path.dirname(fileURLToPath(import.meta.url)); -const {default: BuildCacheStorage} = - await import(pathToFileURL(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js"))); - -const dbDir = path.resolve(here, `probe-sqlite-reopen-${process.pid}`); -console.log(`[probe-reopen] open #1 ${dbDir}`); -const a = new BuildCacheStorage(dbDir); -a.transaction(() => a.putContent("sha512-a", Buffer.alloc(4096, 1))); - -console.log(`[probe-reopen] open #2 (overlapping) same dir`); -const b = new BuildCacheStorage(dbDir); -console.log(`[probe-reopen] #2 reads #1's row: ${b.hasContent("sha512-a")}`); -b.transaction(() => b.putContent("sha512-b", Buffer.alloc(4096, 2))); - -console.log(`[probe-reopen] close #1 (swap: old stack torn down)`); -a.close(); -console.log(`[probe-reopen] #2 still serving: ${b.hasContent("sha512-a")} / ${b.hasContent("sha512-b")}`); - -console.log(`[probe-reopen] close #2 (server.close)`); -b.close(); -console.log(`[probe-reopen] both closed OK — process exiting`); diff --git a/packages/server/test/probes/probe-sqlite.mjs b/packages/server/test/probes/probe-sqlite.mjs deleted file mode 100644 index 96e55c39a75..00000000000 --- a/packages/server/test/probes/probe-sqlite.mjs +++ /dev/null @@ -1,29 +0,0 @@ -// Probe A — node:sqlite (BuildCacheStorage) native teardown in isolation. -// -// Opens the build-cache DB the exact way the server does (WAL + mmap + busy_timeout), -// writes a row, closes it (WAL checkpoint TRUNCATE + db.close()), then lets the process -// exit. If this crashes with 0xC0000005 on Windows, the origin is node:sqlite teardown -// (mmap unmap / WAL checkpoint on close), independent of parcel and the swap logic. -// -// Run from packages/project: node ../server/test/tmp/probe-sqlite.mjs -import path from "node:path"; -import {fileURLToPath, pathToFileURL} from "node:url"; - -const here = path.dirname(fileURLToPath(import.meta.url)); -const {default: BuildCacheStorage} = - await import(pathToFileURL(path.resolve(here, "../../../project/lib/build/cache/BuildCacheStorage.js"))); - -const dbDir = path.resolve(here, `probe-sqlite-${process.pid}`); -console.log(`[probe-sqlite] opening ${dbDir}`); -const storage = new BuildCacheStorage(dbDir); - -// Exercise a write + read so mmap pages are actually mapped in. -storage.transaction(() => { - storage.putContent("sha512-probe", Buffer.alloc(4096, 7)); -}); -console.log(`[probe-sqlite] hasContent=${storage.hasContent("sha512-probe")}`); -console.log(`[probe-sqlite] size=${storage.getDatabaseSize()}`); - -console.log(`[probe-sqlite] closing`); -storage.close(); -console.log(`[probe-sqlite] closed OK — process exiting`); From ec6e44d6c9f6d4b6da827874aa82c378bfd43c47 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:34:04 +0200 Subject: [PATCH 10/13] test(project): Re-add teardown tracing on top of serialized unsubscribe The serialized-unsubscribe fix was necessary but not sufficient: reinitialize.js still crashed (0xC0000005) on Windows, now after the first subtest fully passes rather than mid-unsubscribe. That points at a second native teardown/exit site. Restore the env-gated synchronous tracer (UI5_TEARDOWN_TRACE=1) over the fix so the next Windows loop shows the new last-surviving operation, and add a trace to the native subscribe path so a fresh subscribe racing a prior teardown is visible too. Silent no-op when the env var is unset. --- packages/project/lib/build/BuildServer.js | 7 +++++ .../lib/build/cache/BuildCacheStorage.js | 5 ++++ .../project/lib/build/cache/CacheManager.js | 4 +++ .../project/lib/build/helpers/WatchHandler.js | 4 +++ .../project/lib/build/helpers/fileWatcher.js | 6 +++- .../lib/build/helpers/teardownTrace.js | 28 +++++++++++++++++++ .../project/lib/build/helpers/watchUtil.js | 9 ++++++ .../lib/graph/ProjectDefinitionWatcher.js | 4 +++ packages/server/lib/serve/Supervisor.js | 10 +++++++ packages/server/lib/serve/teardownTrace.js | 28 +++++++++++++++++++ 10 files changed, 104 insertions(+), 1 deletion(-) create mode 100644 packages/project/lib/build/helpers/teardownTrace.js create mode 100644 packages/server/lib/serve/teardownTrace.js diff --git a/packages/project/lib/build/BuildServer.js b/packages/project/lib/build/BuildServer.js index 5b97b336f61..7112aa616c9 100644 --- a/packages/project/lib/build/BuildServer.js +++ b/packages/project/lib/build/BuildServer.js @@ -4,6 +4,7 @@ import BuildReader from "./BuildReader.js"; import WatchHandler from "./helpers/WatchHandler.js"; import {isAbortError, isFileNotFoundError} from "./helpers/abort.js"; import {WATCHER_BURST_SETTLE_MS} from "./helpers/watchUtil.js"; +import {trace} from "./helpers/teardownTrace.js"; import RecoveryBudget, {WATCHER_RECOVERY_MAX_ATTEMPTS, WATCHER_RECOVERY_WINDOW_MS} from "./helpers/RecoveryBudget.js"; import {getLogger} from "@ui5/logger"; import ServeLogger from "@ui5/logger/internal/loggers/Serve"; @@ -368,12 +369,15 @@ class BuildServer extends EventEmitter { async destroy() { + trace("BuildServer.destroy: enter"); this.#destroyed = true; clearTimeout(this.#processBuildRequestsTimeout); this.#pendingDeferredRestart = false; clearTimeout(this.#sourcesChangedTimeout); this.#pendingFinalSourcesChanged = false; + trace("BuildServer.destroy: watchHandler.destroy start"); await this.#watchHandler.destroy(); + trace("BuildServer.destroy: watchHandler.destroy done"); try { // Cancel any running background validation pass and wait for it to settle. await this.#stopActiveValidation("Server destroyed"); @@ -385,8 +389,11 @@ class BuildServer extends EventEmitter { // Always release the cache manager, even when the active build rejected // (e.g. Force-mode stale-cache errors). Otherwise the SQLite handle leaks // and subsequent fs.rm of the cache directory fails with EBUSY on Windows. + trace("BuildServer.destroy: closeCacheManager start"); this.#projectBuilder.closeCacheManager(); + trace("BuildServer.destroy: closeCacheManager done"); } + trace("BuildServer.destroy: exit"); } /** diff --git a/packages/project/lib/build/cache/BuildCacheStorage.js b/packages/project/lib/build/cache/BuildCacheStorage.js index 13fb50c491a..353c4da8095 100644 --- a/packages/project/lib/build/cache/BuildCacheStorage.js +++ b/packages/project/lib/build/cache/BuildCacheStorage.js @@ -3,6 +3,7 @@ import {mkdirSync, existsSync} from "node:fs"; import path from "node:path"; import {gzipSync, gunzipSync} from "node:zlib"; import {getLogger} from "@ui5/logger"; +import {trace} from "../helpers/teardownTrace.js"; const log = getLogger("build:cache:BuildCacheStorage"); @@ -603,6 +604,7 @@ export default class BuildCacheStorage { * Closes the database connection */ close() { + trace(`BuildCacheStorage.close: enter (${this.#dbPath})`); if (this.#inTransaction) { try { this.#db.exec("ROLLBACK"); @@ -610,8 +612,11 @@ export default class BuildCacheStorage { this.#inTransaction = false; } } + trace("BuildCacheStorage.close: wal_checkpoint(TRUNCATE) start"); this.#db.exec("PRAGMA wal_checkpoint(TRUNCATE)"); + trace("BuildCacheStorage.close: wal_checkpoint done, db.close() start"); this.#db.close(); + trace("BuildCacheStorage.close: db.close() done"); } /** diff --git a/packages/project/lib/build/cache/CacheManager.js b/packages/project/lib/build/cache/CacheManager.js index d1baec61eb0..0ffde09a83a 100644 --- a/packages/project/lib/build/cache/CacheManager.js +++ b/packages/project/lib/build/cache/CacheManager.js @@ -4,6 +4,7 @@ import Configuration from "../../config/Configuration.js"; import {access} from "node:fs/promises"; import {getLogger} from "@ui5/logger"; import BuildCacheStorage from "./BuildCacheStorage.js"; +import {trace} from "../helpers/teardownTrace.js"; const log = getLogger("build:cache:CacheManager"); @@ -335,9 +336,12 @@ export default class CacheManager { * closed only when the last consumer releases its reference. */ close() { + trace(`CacheManager.close: refCount ${this.#refCount} -> ${this.#refCount - 1} (${this.#cacheDir})`); if (--this.#refCount <= 0) { + trace("CacheManager.close: last ref, closing storage"); this.#storage.close(); cacheManagerInstances.delete(this.#cacheDir); + trace("CacheManager.close: storage closed, instance removed"); } } diff --git a/packages/project/lib/build/helpers/WatchHandler.js b/packages/project/lib/build/helpers/WatchHandler.js index f9180081f93..d721f3a726a 100644 --- a/packages/project/lib/build/helpers/WatchHandler.js +++ b/packages/project/lib/build/helpers/WatchHandler.js @@ -2,6 +2,7 @@ import EventEmitter from "node:events"; import {getLogger} from "@ui5/logger"; import {subscribe as watchSubscribe} from "./fileWatcher.js"; import {drainSubscriptions} from "./watchUtil.js"; +import {trace} from "./teardownTrace.js"; import {exists} from "../../utils/fsHelper.js"; const log = getLogger("build:helpers:WatchHandler"); @@ -63,15 +64,18 @@ class WatchHandler extends EventEmitter { } async destroy() { + trace("WatchHandler.destroy: enter"); // Drain the subscriptions list so a second destroy() is a no-op and a partial // failure cannot leave stale handles behind to be unsubscribed twice. const subscriptions = this.#subscriptions; this.#subscriptions = []; const failures = await drainSubscriptions(subscriptions); + trace("WatchHandler.destroy: drained"); if (failures.length) { const err = new AggregateError(failures, "Failed to unsubscribe one or more file watchers"); this.emit("error", err); } + trace("WatchHandler.destroy: exit"); } #handleWatchEvents(eventType, filePath, project) { diff --git a/packages/project/lib/build/helpers/fileWatcher.js b/packages/project/lib/build/helpers/fileWatcher.js index c2694c55d54..70bc9fe9018 100644 --- a/packages/project/lib/build/helpers/fileWatcher.js +++ b/packages/project/lib/build/helpers/fileWatcher.js @@ -1,5 +1,6 @@ import {existsSync, readFileSync} from "node:fs"; import {getLogger} from "@ui5/logger"; +import {trace} from "./teardownTrace.js"; const log = getLogger("build:helpers:fileWatcher"); @@ -114,7 +115,10 @@ export async function subscribe(dir, callback, opts = {}) { if (!shouldUsePolling()) { const native = await loadNativeBackend(); if (native) { - return native.subscribe(dir, callback, opts); + trace(`fileWatcher.subscribe: native subscribe start (${dir})`); + const subscription = await native.subscribe(dir, callback, opts); + trace(`fileWatcher.subscribe: native subscribe done (${dir})`); + return subscription; } // The native binding could not load (see loadNativeBackend). Polling needs no native code, so // fall through to it rather than failing the watch. diff --git a/packages/project/lib/build/helpers/teardownTrace.js b/packages/project/lib/build/helpers/teardownTrace.js new file mode 100644 index 00000000000..fda43c64337 --- /dev/null +++ b/packages/project/lib/build/helpers/teardownTrace.js @@ -0,0 +1,28 @@ +import {writeSync} from "node:fs"; + +// Synchronous, env-gated teardown tracer. Set UI5_TEARDOWN_TRACE=1 to enable. +// +// Writes straight to fd 2 (stderr) with writeSync, bypassing the async stream buffer, so +// the last line survives a hard native crash (a 0xC0000005 access violation on Windows in +// @parcel/watcher or node:sqlite teardown terminates the process without flushing buffered +// output). Each line is prefixed with the high-resolution time and the pid so interleaved +// teardown across the Supervisor, BuildServer, and watchers can be ordered after the fact. +// +// Off by default and a no-op unless the env var is set, so it costs nothing in normal runs. +const ENABLED = process.env.UI5_TEARDOWN_TRACE === "1"; + +/** + * Emits a teardown trace line to stderr synchronously when UI5_TEARDOWN_TRACE=1. + * + * @param {string} msg Message to trace + */ +export function trace(msg) { + if (!ENABLED) { + return; + } + try { + writeSync(2, `[teardown ${process.hrtime.bigint()} pid=${process.pid}] ${msg}\n`); + } catch { + // Never let tracing throw during teardown. + } +} diff --git a/packages/project/lib/build/helpers/watchUtil.js b/packages/project/lib/build/helpers/watchUtil.js index fe4ebb05445..8ddeb7d743d 100644 --- a/packages/project/lib/build/helpers/watchUtil.js +++ b/packages/project/lib/build/helpers/watchUtil.js @@ -1,3 +1,5 @@ +import {trace} from "./teardownTrace.js"; + /** * Settle window (ms) for collapsing a burst of filesystem events into one trailing action. Shared * by every Parcel watcher in the build layer. @@ -35,13 +37,20 @@ export const WATCHER_BURST_SETTLE_MS = 550; * when all succeeded */ export async function drainSubscriptions(subscriptions) { + trace(`drainSubscriptions: draining ${subscriptions.length} subscription(s)`); const failures = []; + let i = 0; for (const subscription of subscriptions) { + trace(`drainSubscriptions: unsubscribe #${i} start`); try { await subscription.unsubscribe(); + trace(`drainSubscriptions: unsubscribe #${i} done`); } catch (err) { + trace(`drainSubscriptions: unsubscribe #${i} threw: ${err?.message ?? err}`); failures.push(err); } + i++; } + trace(`drainSubscriptions: all drained`); return failures; } diff --git a/packages/project/lib/graph/ProjectDefinitionWatcher.js b/packages/project/lib/graph/ProjectDefinitionWatcher.js index ad710ecda01..4755aa5f13b 100644 --- a/packages/project/lib/graph/ProjectDefinitionWatcher.js +++ b/packages/project/lib/graph/ProjectDefinitionWatcher.js @@ -3,6 +3,7 @@ import path from "node:path"; import {getLogger} from "@ui5/logger"; import {subscribe as watchSubscribe} from "../build/helpers/fileWatcher.js"; import {drainSubscriptions, WATCHER_BURST_SETTLE_MS} from "../build/helpers/watchUtil.js"; +import {trace} from "../build/helpers/teardownTrace.js"; import RecoveryBudget, { WATCHER_RECOVERY_MAX_ATTEMPTS, WATCHER_RECOVERY_WINDOW_MS, } from "../build/helpers/RecoveryBudget.js"; @@ -258,13 +259,16 @@ class ProjectDefinitionWatcher extends EventEmitter { * @returns {Promise} Resolves once every subscription has been drained */ async destroy() { + trace("ProjectDefinitionWatcher.destroy: enter"); this.#destroyed = true; this.#cancelSettleTimer(); const failures = await this.#drainSubscriptions(); + trace("ProjectDefinitionWatcher.destroy: drained"); if (failures.length) { const err = new AggregateError(failures, "Failed to unsubscribe one or more definition watchers"); this.emit("error", err); } + trace("ProjectDefinitionWatcher.destroy: exit"); } // Cancels a pending settle timer, if any. Safe to call when no timer is armed. diff --git a/packages/server/lib/serve/Supervisor.js b/packages/server/lib/serve/Supervisor.js index 1dcf583fbab..9013631da4f 100644 --- a/packages/server/lib/serve/Supervisor.js +++ b/packages/server/lib/serve/Supervisor.js @@ -6,6 +6,7 @@ import {getLogger} from "@ui5/logger"; import buildApp from "./stack.js"; import attachLiveReloadServer from "../liveReload/server.js"; import {listen, addSsl, announceListening} from "./httpListener.js"; +import {trace} from "./teardownTrace.js"; const log = getLogger("server:Supervisor"); @@ -576,6 +577,7 @@ class Supervisor extends EventEmitter { // Synchronous head: runs before any await and before the lock is acquired, so an in-flight // #swap or a late definitionChanged/recovery-timer sees DESTROYED at its next guard, and the // abort unblocks a recovery settle wait immediately rather than after its full window. + trace("Supervisor.destroy: enter"); this.#setState(STATE.DESTROYED); this.#destroyAbortController.abort(); this.#clearRecoveryTimer(); @@ -583,12 +585,14 @@ class Supervisor extends EventEmitter { this.#detachRelay(); // Stop accepting new requests now, before waiting out any in-flight swap. Awaited last so the // returned promise resolves only once the socket is fully closed. + trace("Supervisor.destroy: httpServer.close start"); const httpClosed = new Promise((resolve) => { if (!this.#httpServer) { resolve(); return; } this.#httpServer.close(() => { + trace("Supervisor.destroy: httpServer.close callback"); resolve(); }); }); @@ -602,17 +606,23 @@ class Supervisor extends EventEmitter { const stack = this.#stack; this.#stack = null; try { + trace("Supervisor.destroy: definitionWatcher.destroy start"); await definitionWatcher?.destroy(); + trace("Supervisor.destroy: definitionWatcher.destroy done"); } catch (err) { log.verbose(`Error while destroying definition watcher: ${err?.message ?? err}`); } try { + trace("Supervisor.destroy: buildServer.destroy start"); await stack?.buildServer.destroy(); + trace("Supervisor.destroy: buildServer.destroy done"); } catch (err) { log.verbose(`Error while destroying BuildServer: ${err?.message ?? err}`); } }); + trace("Supervisor.destroy: awaiting httpClosed"); await httpClosed; + trace("Supervisor.destroy: exit"); } } diff --git a/packages/server/lib/serve/teardownTrace.js b/packages/server/lib/serve/teardownTrace.js new file mode 100644 index 00000000000..fda43c64337 --- /dev/null +++ b/packages/server/lib/serve/teardownTrace.js @@ -0,0 +1,28 @@ +import {writeSync} from "node:fs"; + +// Synchronous, env-gated teardown tracer. Set UI5_TEARDOWN_TRACE=1 to enable. +// +// Writes straight to fd 2 (stderr) with writeSync, bypassing the async stream buffer, so +// the last line survives a hard native crash (a 0xC0000005 access violation on Windows in +// @parcel/watcher or node:sqlite teardown terminates the process without flushing buffered +// output). Each line is prefixed with the high-resolution time and the pid so interleaved +// teardown across the Supervisor, BuildServer, and watchers can be ordered after the fact. +// +// Off by default and a no-op unless the env var is set, so it costs nothing in normal runs. +const ENABLED = process.env.UI5_TEARDOWN_TRACE === "1"; + +/** + * Emits a teardown trace line to stderr synchronously when UI5_TEARDOWN_TRACE=1. + * + * @param {string} msg Message to trace + */ +export function trace(msg) { + if (!ENABLED) { + return; + } + try { + writeSync(2, `[teardown ${process.hrtime.bigint()} pid=${process.pid}] ${msg}\n`); + } catch { + // Never let tracing throw during teardown. + } +} From 38953184c0dd558e0ec566261f4312652113cfc4 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:49:12 +0200 Subject: [PATCH 11/13] fix(project): Serialize native watcher subscribe/unsubscribe process-wide Serializing drainSubscriptions was necessary but not sufficient: the Windows 0xC0000005 persisted, now during a teardown unsubscribe that raced a fresh subscribe from a reinitialize() swap. The teardown trace confirmed a native unsubscribe in flight (no matching completion) right after subscribe cycles. @parcel/watcher mutates a process-global backend registry from both the JS thread (subscribe: find/emplace/rehash) and a libuv worker thread (unsubscribe of the last subscriber: erase/rehash) with no lock guarding that static map (parcel-bundler/watcher#259). Any overlap of subscribe with an in-flight unsubscribe corrupts the registry and access-violates on Windows. Funnel every native subscribe and unsubscribe through one process-wide promise chain in fileWatcher, so the process never has two registry mutations in flight at once: each waits for the previous to fully settle. The chain is process-wide because the registry it protects is process-global, and it only orders rare watcher-lifecycle calls, so it costs nothing on the hot path. subscribe now returns a thin wrapper whose unsubscribe routes through the same chain. --- .../project/lib/build/helpers/fileWatcher.js | 35 +++++++++++++-- .../test/lib/build/helpers/fileWatcher.js | 43 ++++++++++++++++++- 2 files changed, 74 insertions(+), 4 deletions(-) diff --git a/packages/project/lib/build/helpers/fileWatcher.js b/packages/project/lib/build/helpers/fileWatcher.js index 70bc9fe9018..bbaa4370e41 100644 --- a/packages/project/lib/build/helpers/fileWatcher.js +++ b/packages/project/lib/build/helpers/fileWatcher.js @@ -44,6 +44,28 @@ let usePolling = null; let nativeBackend = null; let nativeBackendLoaded = false; +// Serialization chain for native subscribe/unsubscribe. @parcel/watcher mutates a process-global +// backend registry from both the JS thread (subscribe: find/emplace/rehash) and a libuv worker +// thread (unsubscribe of the last subscriber: erase/rehash), with no lock guarding that static map +// (parcel-bundler/watcher#259). Overlapping a subscribe with an in-flight unsubscribe — the exact +// shape of a reinitialize() swap tearing down the old watcher while subscribing the new one — races +// that registry and access-violates (0xC0000005) on Windows. Funneling every native subscribe and +// unsubscribe through one promise chain means the process never has two registry mutations in +// flight at once: each waits for the previous to fully settle (the unsubscribe promise resolves +// only after the native teardown, including the worker-thread erase, has completed). The chain is +// process-wide because the registry it protects is process-global; it only orders watcher lifecycle +// calls (rare, at startup/teardown), so it costs nothing on the hot path. +let nativeWatcherChain = Promise.resolve(); + +// Runs fn after every previously-chained native watcher operation has settled, and extends the chain +// so the next one waits for fn. Rejections are isolated so one failed operation does not wedge the +// chain, while the returned promise still rejects for its own caller. +function serializeNativeWatcherOp(fn) { + const result = nativeWatcherChain.then(fn, fn); + nativeWatcherChain = result.then(() => undefined, () => undefined); + return result; +} + /** * Decides whether to poll, once per process. UI5_WATCH_MODE=polling|native forces the * choice; otherwise polling is the default inside a container and the native backend is the default @@ -115,10 +137,17 @@ export async function subscribe(dir, callback, opts = {}) { if (!shouldUsePolling()) { const native = await loadNativeBackend(); if (native) { - trace(`fileWatcher.subscribe: native subscribe start (${dir})`); - const subscription = await native.subscribe(dir, callback, opts); + // Serialize against every other native subscribe/unsubscribe: see nativeWatcherChain. + const subscription = await serializeNativeWatcherOp(() => { + trace(`fileWatcher.subscribe: native subscribe start (${dir})`); + return native.subscribe(dir, callback, opts); + }); trace(`fileWatcher.subscribe: native subscribe done (${dir})`); - return subscription; + // Route unsubscribe through the same chain so a teardown never overlaps a subscribe (or + // another unsubscribe) on the shared registry. + return { + unsubscribe: () => serializeNativeWatcherOp(() => subscription.unsubscribe()), + }; } // The native binding could not load (see loadNativeBackend). Polling needs no native code, so // fall through to it rather than failing the watch. diff --git a/packages/project/test/lib/build/helpers/fileWatcher.js b/packages/project/test/lib/build/helpers/fileWatcher.js index f84a78174b9..5bb81ea0389 100644 --- a/packages/project/test/lib/build/helpers/fileWatcher.js +++ b/packages/project/test/lib/build/helpers/fileWatcher.js @@ -72,9 +72,50 @@ test.serial("subscribe: native delegation when UI5_WATCH_MODE=native", async (t) const opts = {ignore: ["**/x/**"]}; const subscription = await watcher.subscribe("/some/dir", cb, opts); - t.is(subscription, nativeSubscription, "returns the native subscription unchanged"); t.true(parcelSubscribe.calledOnceWithExactly("/some/dir", cb, opts), "delegates verbatim to the native backend"); + + // The returned subscription wraps the native one so unsubscribe is funneled through the + // process-wide serialization chain (parcel-bundler/watcher#259); it still delegates to the + // native unsubscribe verbatim. + await subscription.unsubscribe(); + t.true(nativeSubscription.unsubscribe.calledOnce, "unsubscribe delegates to the native subscription"); + } finally { + esmock.purge(watcher); + } +}); + +test.serial("subscribe: native subscribe and unsubscribe never overlap", async (t) => { + // @parcel/watcher races its process-global backend registry when subscribe/unsubscribe overlap + // (parcel-bundler/watcher#259), which segfaults on Windows. fileWatcher must serialize every + // native subscribe and unsubscribe so no two are ever in flight at once. + process.env.UI5_WATCH_MODE = "native"; + let inFlight = 0; + let maxInFlight = 0; + const enter = async () => { + inFlight++; + maxInFlight = Math.max(maxInFlight, inFlight); + await new Promise((resolve) => setImmediate(resolve)); + inFlight--; + }; + const parcelSubscribe = sinon.stub().callsFake(async () => { + await enter(); + return {unsubscribe: async () => enter()}; + }); + const watcher = await importWatcherWithParcel({ + default: {subscribe: parcelSubscribe}, subscribe: parcelSubscribe, + }); + try { + // Fire several subscribes concurrently, then unsubscribe them all concurrently. Without + // serialization the native calls would overlap (maxInFlight > 1). + const subs = await Promise.all([ + watcher.subscribe("/a", () => {}, {}), + watcher.subscribe("/b", () => {}, {}), + watcher.subscribe("/c", () => {}, {}), + ]); + await Promise.all(subs.map((s) => s.unsubscribe())); + + t.is(maxInFlight, 1, "never more than one native subscribe/unsubscribe in flight at a time"); } finally { esmock.purge(watcher); } From 168af5a3c82a09db85ea9f3fb47e88a0fcd39c28 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 13:54:00 +0200 Subject: [PATCH 12/13] fix(project): Pin @parcel/watcher backend with a keep-alive subscription MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Process-wide subscribe/unsubscribe serialization was still not enough: the Windows 0xC0000005 persisted, always in the second reinitialize.js subtest, which fully tears down its server (registry drops to zero subscribers) before the next subtest subscribes. The trace showed a lone, non-overlapping native unsubscribe crashing — proving the corruption is not from our concurrent JS calls but from @parcel/watcher's own libuv worker thread. Per parcel-bundler/watcher#259, the destructive operation is the empty transition: when a backend's last subscriber is removed, removeShared() runs erase() + rehash(0) on a worker thread, and that rehash(0) races a concurrent subscribe from the JS thread. Our unsubscribe promise can resolve before the worker-thread erase completes, so JS-side serialization cannot fence it. Hold one never-unsubscribed keep-alive subscription for the life of the process so the backend registry never empties. rehash(0) only fires at size zero, so keeping one subscriber alive means the destructive transition never happens. The target is os.tmpdir() (always present) with an ignore-everything glob, so it delivers no events and does no work beyond existing; the OS reclaims it at process exit. The serialization chain stays as defense in depth against same-thread overlap. --- .../project/lib/build/helpers/fileWatcher.js | 50 ++++++++++++++++--- .../test/lib/build/helpers/fileWatcher.js | 30 ++++++++++- 2 files changed, 70 insertions(+), 10 deletions(-) diff --git a/packages/project/lib/build/helpers/fileWatcher.js b/packages/project/lib/build/helpers/fileWatcher.js index bbaa4370e41..d0da1d1f290 100644 --- a/packages/project/lib/build/helpers/fileWatcher.js +++ b/packages/project/lib/build/helpers/fileWatcher.js @@ -1,4 +1,5 @@ import {existsSync, readFileSync} from "node:fs"; +import os from "node:os"; import {getLogger} from "@ui5/logger"; import {trace} from "./teardownTrace.js"; @@ -47,14 +48,13 @@ let nativeBackendLoaded = false; // Serialization chain for native subscribe/unsubscribe. @parcel/watcher mutates a process-global // backend registry from both the JS thread (subscribe: find/emplace/rehash) and a libuv worker // thread (unsubscribe of the last subscriber: erase/rehash), with no lock guarding that static map -// (parcel-bundler/watcher#259). Overlapping a subscribe with an in-flight unsubscribe — the exact -// shape of a reinitialize() swap tearing down the old watcher while subscribing the new one — races -// that registry and access-violates (0xC0000005) on Windows. Funneling every native subscribe and -// unsubscribe through one promise chain means the process never has two registry mutations in -// flight at once: each waits for the previous to fully settle (the unsubscribe promise resolves -// only after the native teardown, including the worker-thread erase, has completed). The chain is -// process-wide because the registry it protects is process-global; it only orders watcher lifecycle -// calls (rare, at startup/teardown), so it costs nothing on the hot path. +// (parcel-bundler/watcher#259). Funneling every native subscribe and unsubscribe through one promise +// chain means the process never issues two overlapping registry mutations from the JS thread. This +// pairs with the keep-alive below: the keep-alive prevents the destructive empty-transition rehash, +// and serializing removes the remaining same-thread overlap so subscribe fan-out and teardown drain +// cannot interleave their native calls. The chain is process-wide because the registry it protects +// is process-global; it only orders watcher-lifecycle calls (rare, at startup/teardown), so it costs +// nothing on the hot path. let nativeWatcherChain = Promise.resolve(); // Runs fn after every previously-chained native watcher operation has settled, and extends the chain @@ -66,6 +66,36 @@ function serializeNativeWatcherOp(fn) { return result; } +// Process-lifetime keep-alive subscription that pins @parcel/watcher's shared backend so its global +// registry never empties. The destructive half of parcel-bundler/watcher#259 is the empty +// transition: when the last subscriber for a backend is removed, removeShared() runs erase() + +// rehash(0) on a libuv worker thread, and that rehash(0) races a concurrent subscribe from the JS +// thread — the exact shape of one reinitialize() cycle fully tearing down its watchers before the +// next subscribes. Serializing our own subscribe/unsubscribe calls cannot fence this, because the +// worker-thread erase can run after our unsubscribe promise has already resolved. Holding one +// subscription alive for the whole process keeps the registry size above zero, so rehash(0) never +// fires and the destructive transition never happens. It is intentionally never unsubscribed; the +// OS reclaims it at process exit. The tmpdir target always exists and the "**" ignore drops every +// event, so it delivers nothing and does no work beyond existing. +let keepAlivePromise = null; + +function ensureBackendKeepAlive(native) { + keepAlivePromise ??= serializeNativeWatcherOp(() => { + trace("fileWatcher.subscribe: backend keep-alive subscribe start"); + return native.subscribe(os.tmpdir(), () => {}, {ignore: ["**"]}); + }).then((subscription) => { + trace("fileWatcher.subscribe: backend keep-alive subscribe done"); + return subscription; + }, (err) => { + // A failed keep-alive must not fail real watches: it is an optimization, not a requirement. + // Without it we simply fall back to the pre-fix behavior (the empty-transition race is + // possible again), so log and carry on rather than rejecting the caller's subscribe. + log.verbose(`Watcher backend keep-alive could not start: ${err?.message ?? err}`); + return null; + }); + return keepAlivePromise; +} + /** * Decides whether to poll, once per process. UI5_WATCH_MODE=polling|native forces the * choice; otherwise polling is the default inside a container and the native backend is the default @@ -137,6 +167,10 @@ export async function subscribe(dir, callback, opts = {}) { if (!shouldUsePolling()) { const native = await loadNativeBackend(); if (native) { + // Pin the shared backend before the first real subscribe so its registry never empties + // (see ensureBackendKeepAlive). Awaited so the keep-alive is in place before any real + // subscribe/unsubscribe cycle can drive the registry toward the destructive empty transition. + await ensureBackendKeepAlive(native); // Serialize against every other native subscribe/unsubscribe: see nativeWatcherChain. const subscription = await serializeNativeWatcherOp(() => { trace(`fileWatcher.subscribe: native subscribe start (${dir})`); diff --git a/packages/project/test/lib/build/helpers/fileWatcher.js b/packages/project/test/lib/build/helpers/fileWatcher.js index 5bb81ea0389..b8ed082be0a 100644 --- a/packages/project/test/lib/build/helpers/fileWatcher.js +++ b/packages/project/test/lib/build/helpers/fileWatcher.js @@ -72,7 +72,7 @@ test.serial("subscribe: native delegation when UI5_WATCH_MODE=native", async (t) const opts = {ignore: ["**/x/**"]}; const subscription = await watcher.subscribe("/some/dir", cb, opts); - t.true(parcelSubscribe.calledOnceWithExactly("/some/dir", cb, opts), + t.true(parcelSubscribe.calledWithExactly("/some/dir", cb, opts), "delegates verbatim to the native backend"); // The returned subscription wraps the native one so unsubscribe is funneled through the @@ -85,6 +85,31 @@ test.serial("subscribe: native delegation when UI5_WATCH_MODE=native", async (t) } }); +test.serial("subscribe: pins the shared backend with a keep-alive subscription", async (t) => { + // The destructive half of parcel-bundler/watcher#259 is the empty-transition rehash(0) when the + // backend registry drops to zero subscribers. fileWatcher must hold one never-unsubscribed + // keep-alive subscription so the registry never empties, established before the first real watch. + process.env.UI5_WATCH_MODE = "native"; + const parcelSubscribe = sinon.stub().callsFake(async () => ({unsubscribe: sinon.stub().resolves()})); + const watcher = await importWatcherWithParcel({ + default: {subscribe: parcelSubscribe}, subscribe: parcelSubscribe, + }); + try { + await watcher.subscribe("/some/dir", () => {}, {}); + + // Two native subscribes: the keep-alive (ignore everything) plus the real one. + t.is(parcelSubscribe.callCount, 2, "one keep-alive subscribe plus the real subscribe"); + const keepAliveCall = parcelSubscribe.getCall(0); + t.deepEqual(keepAliveCall.args[2], {ignore: ["**"]}, "the keep-alive ignores every event"); + + // A second subscribe reuses the same keep-alive rather than opening another. + await watcher.subscribe("/other/dir", () => {}, {}); + t.is(parcelSubscribe.callCount, 3, "the keep-alive is established once, not per subscribe"); + } finally { + esmock.purge(watcher); + } +}); + test.serial("subscribe: native subscribe and unsubscribe never overlap", async (t) => { // @parcel/watcher races its process-global backend registry when subscribe/unsubscribe overlap // (parcel-bundler/watcher#259), which segfaults on Windows. fileWatcher must serialize every @@ -107,7 +132,8 @@ test.serial("subscribe: native subscribe and unsubscribe never overlap", async ( }); try { // Fire several subscribes concurrently, then unsubscribe them all concurrently. Without - // serialization the native calls would overlap (maxInFlight > 1). + // serialization the native calls would overlap (maxInFlight > 1). The keep-alive subscribe + // also runs through the chain, so it is covered by the same no-overlap guarantee. const subs = await Promise.all([ watcher.subscribe("/a", () => {}, {}), watcher.subscribe("/b", () => {}, {}), From b8847a63a9252de5dbcd1c154742c00d1c095db5 Mon Sep 17 00:00:00 2001 From: Matthias Osswald Date: Wed, 19 Aug 2026 14:06:21 +0200 Subject: [PATCH 13/13] fix(server): Scope watcher backend keep-alive to the serving session MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The process-lifetime keep-alive killed the 0xC0000005 crash, but because it was never unsubscribed it kept @parcel/watcher's native handle alive, so AVA's test worker could not drain its event loop and reported "Failed to exit". Production exits via process.exit on SIGINT/SIGTERM so it was unaffected, but the leaked handle is still wrong. Make the keep-alive a refcounted, session-scoped pin instead. fileWatcher exposes pinBackend()/unpinBackend(); the Supervisor pins in #init before any watcher subscribes and releases in destroy() after every watcher this session owns is torn down. The keep-alive is established once per active-session set and released only at the last unpin — a quiescent moment where nothing is serving, so no concurrent subscribe can race the final registry-empty. That still covers the risky swap churn (the pin spans all reinitialize() swaps of a session) while letting the process, and the test worker, exit cleanly. --- .../project/lib/build/helpers/fileWatcher.js | 89 ++++++++++++++----- packages/project/package.json | 1 + .../test/lib/build/helpers/fileWatcher.js | 59 ++++++++---- packages/server/lib/serve/Supervisor.js | 19 ++++ .../test/lib/server/serve/Supervisor.js | 12 ++- 5 files changed, 138 insertions(+), 42 deletions(-) diff --git a/packages/project/lib/build/helpers/fileWatcher.js b/packages/project/lib/build/helpers/fileWatcher.js index d0da1d1f290..305b86b69df 100644 --- a/packages/project/lib/build/helpers/fileWatcher.js +++ b/packages/project/lib/build/helpers/fileWatcher.js @@ -66,34 +66,79 @@ function serializeNativeWatcherOp(fn) { return result; } -// Process-lifetime keep-alive subscription that pins @parcel/watcher's shared backend so its global -// registry never empties. The destructive half of parcel-bundler/watcher#259 is the empty -// transition: when the last subscriber for a backend is removed, removeShared() runs erase() + -// rehash(0) on a libuv worker thread, and that rehash(0) races a concurrent subscribe from the JS -// thread — the exact shape of one reinitialize() cycle fully tearing down its watchers before the -// next subscribes. Serializing our own subscribe/unsubscribe calls cannot fence this, because the -// worker-thread erase can run after our unsubscribe promise has already resolved. Holding one -// subscription alive for the whole process keeps the registry size above zero, so rehash(0) never -// fires and the destructive transition never happens. It is intentionally never unsubscribed; the -// OS reclaims it at process exit. The tmpdir target always exists and the "**" ignore drops every -// event, so it delivers nothing and does no work beyond existing. +// Keep-alive subscription that pins @parcel/watcher's shared backend so its global registry never +// empties while a serving session is active. The destructive half of parcel-bundler/watcher#259 is +// the empty transition: when the last subscriber for a backend is removed, removeShared() runs +// erase() + rehash(0) on a libuv worker thread, and that rehash(0) races a concurrent subscribe from +// the JS thread — the exact shape of one reinitialize() swap fully tearing down its watchers before +// the next stack subscribes. Serializing our own subscribe/unsubscribe calls cannot fence this, +// because the worker-thread erase can run after our unsubscribe promise has already resolved. +// +// Holding one keep-alive subscription across the session keeps the registry size above zero, so +// rehash(0) never fires during the churn. It is released only when the last session ends +// (pinCount 0): by then nothing is serving, so no concurrent subscribe can race the final +// registry-empty, and releasing it lets the process (and AVA's test worker) drain the native handle +// and exit cleanly. The tmpdir target always exists and the "**" ignore drops every event, so the +// keep-alive delivers nothing and does no work beyond existing. let keepAlivePromise = null; +let backendPinCount = 0; -function ensureBackendKeepAlive(native) { +/** + * Pins the native watcher backend alive for the duration of a serving session, so its shared + * registry never empties mid-session (see keepAlivePromise). Balanced by {@link unpinBackend}. A + * no-op under the polling backend, which has no such registry. Awaiting the returned promise ensures + * the keep-alive is in place before the first real subscribe of the session. + * + * @returns {Promise} Resolves once the keep-alive is established (or skipped) + */ +export async function pinBackend() { + if (shouldUsePolling()) { + return; + } + const native = await loadNativeBackend(); + if (!native) { + return; + } + backendPinCount++; keepAlivePromise ??= serializeNativeWatcherOp(() => { - trace("fileWatcher.subscribe: backend keep-alive subscribe start"); + trace("fileWatcher: backend keep-alive subscribe start"); return native.subscribe(os.tmpdir(), () => {}, {ignore: ["**"]}); }).then((subscription) => { - trace("fileWatcher.subscribe: backend keep-alive subscribe done"); + trace("fileWatcher: backend keep-alive subscribe done"); return subscription; }, (err) => { - // A failed keep-alive must not fail real watches: it is an optimization, not a requirement. - // Without it we simply fall back to the pre-fix behavior (the empty-transition race is - // possible again), so log and carry on rather than rejecting the caller's subscribe. + // A failed keep-alive must not fail the session: it is an optimization, not a requirement. + // Without it we simply fall back to the empty-transition race being possible again, so log and + // carry on rather than rejecting the caller. log.verbose(`Watcher backend keep-alive could not start: ${err?.message ?? err}`); return null; }); - return keepAlivePromise; + await keepAlivePromise; +} + +/** + * Releases a {@link pinBackend} reference. When the last session ends, the keep-alive subscription is + * torn down so the native handle no longer holds the event loop open. Safe to over-call; a release + * without a matching pin is a no-op. + * + * @returns {Promise} Resolves once the keep-alive has been released (or on the balancing call) + */ +export async function unpinBackend() { + if (backendPinCount === 0) { + return; + } + if (--backendPinCount > 0) { + return; + } + const pending = keepAlivePromise; + keepAlivePromise = null; + const subscription = await pending; + if (subscription) { + await serializeNativeWatcherOp(() => { + trace("fileWatcher: backend keep-alive unsubscribe"); + return subscription.unsubscribe(); + }); + } } /** @@ -167,11 +212,9 @@ export async function subscribe(dir, callback, opts = {}) { if (!shouldUsePolling()) { const native = await loadNativeBackend(); if (native) { - // Pin the shared backend before the first real subscribe so its registry never empties - // (see ensureBackendKeepAlive). Awaited so the keep-alive is in place before any real - // subscribe/unsubscribe cycle can drive the registry toward the destructive empty transition. - await ensureBackendKeepAlive(native); - // Serialize against every other native subscribe/unsubscribe: see nativeWatcherChain. + // Serialize against every other native subscribe/unsubscribe: see nativeWatcherChain. The + // shared backend is pinned for the session via pinBackend(), so the registry does not empty + // between this subscribe and a concurrent teardown. const subscription = await serializeNativeWatcherOp(() => { trace(`fileWatcher.subscribe: native subscribe start (${dir})`); return native.subscribe(dir, callback, opts); diff --git a/packages/project/package.json b/packages/project/package.json index 9ad5f971040..e94ece326a3 100644 --- a/packages/project/package.json +++ b/packages/project/package.json @@ -32,6 +32,7 @@ "./validation/ValidationError": "./lib/validation/ValidationError.js", "./graph/ProjectGraph": "./lib/graph/ProjectGraph.js", "./internal/graph/ProjectDefinitionWatcher": "./lib/graph/ProjectDefinitionWatcher.js", + "./internal/build/helpers/fileWatcher": "./lib/build/helpers/fileWatcher.js", "./graph/projectGraphBuilder": "./lib/graph/projectGraphBuilder.js", "./graph": "./lib/graph/graph.js", "./package.json": "./package.json" diff --git a/packages/project/test/lib/build/helpers/fileWatcher.js b/packages/project/test/lib/build/helpers/fileWatcher.js index b8ed082be0a..0686352889f 100644 --- a/packages/project/test/lib/build/helpers/fileWatcher.js +++ b/packages/project/test/lib/build/helpers/fileWatcher.js @@ -72,7 +72,7 @@ test.serial("subscribe: native delegation when UI5_WATCH_MODE=native", async (t) const opts = {ignore: ["**/x/**"]}; const subscription = await watcher.subscribe("/some/dir", cb, opts); - t.true(parcelSubscribe.calledWithExactly("/some/dir", cb, opts), + t.true(parcelSubscribe.calledOnceWithExactly("/some/dir", cb, opts), "delegates verbatim to the native backend"); // The returned subscription wraps the native one so unsubscribe is funneled through the @@ -85,26 +85,50 @@ test.serial("subscribe: native delegation when UI5_WATCH_MODE=native", async (t) } }); -test.serial("subscribe: pins the shared backend with a keep-alive subscription", async (t) => { - // The destructive half of parcel-bundler/watcher#259 is the empty-transition rehash(0) when the - // backend registry drops to zero subscribers. fileWatcher must hold one never-unsubscribed - // keep-alive subscription so the registry never empties, established before the first real watch. +test.serial("pinBackend/unpinBackend: hold one keep-alive across the session, released at the last unpin", + async (t) => { + // The destructive half of parcel-bundler/watcher#259 is the empty-transition rehash(0) when the + // backend registry drops to zero subscribers. A pinned keep-alive keeps the registry non-empty + // for the whole session; it is established once (refcounted) and released only at the last unpin. + process.env.UI5_WATCH_MODE = "native"; + const keepAlive = {unsubscribe: sinon.stub().resolves()}; + const parcelSubscribe = sinon.stub().resolves(keepAlive); + const watcher = await importWatcherWithParcel({ + default: {subscribe: parcelSubscribe}, subscribe: parcelSubscribe, + }); + try { + await watcher.pinBackend(); + await watcher.pinBackend(); // second session: refcount, not a second keep-alive + + t.is(parcelSubscribe.callCount, 1, "one keep-alive subscribe regardless of pin count"); + t.deepEqual(parcelSubscribe.getCall(0).args[0], os.tmpdir(), "keep-alive watches the temp dir"); + t.deepEqual(parcelSubscribe.getCall(0).args[2], {ignore: ["**"]}, "the keep-alive ignores every event"); + + await watcher.unpinBackend(); // one session ends: keep-alive stays up + t.is(keepAlive.unsubscribe.callCount, 0, "keep-alive held while another session is active"); + + await watcher.unpinBackend(); // last session ends: keep-alive released + t.is(keepAlive.unsubscribe.callCount, 1, "keep-alive released at the last unpin"); + + // A later session re-establishes a fresh keep-alive. + await watcher.pinBackend(); + t.is(parcelSubscribe.callCount, 2, "a new session re-pins the backend"); + } finally { + esmock.purge(watcher); + } + }); + +test.serial("pinBackend: a failed keep-alive does not throw", async (t) => { + // The keep-alive is an optimization, not a requirement: if it cannot start, the session must + // still run (just without protection against the empty-transition race). process.env.UI5_WATCH_MODE = "native"; - const parcelSubscribe = sinon.stub().callsFake(async () => ({unsubscribe: sinon.stub().resolves()})); + const parcelSubscribe = sinon.stub().rejects(new Error("cannot subscribe")); const watcher = await importWatcherWithParcel({ default: {subscribe: parcelSubscribe}, subscribe: parcelSubscribe, }); try { - await watcher.subscribe("/some/dir", () => {}, {}); - - // Two native subscribes: the keep-alive (ignore everything) plus the real one. - t.is(parcelSubscribe.callCount, 2, "one keep-alive subscribe plus the real subscribe"); - const keepAliveCall = parcelSubscribe.getCall(0); - t.deepEqual(keepAliveCall.args[2], {ignore: ["**"]}, "the keep-alive ignores every event"); - - // A second subscribe reuses the same keep-alive rather than opening another. - await watcher.subscribe("/other/dir", () => {}, {}); - t.is(parcelSubscribe.callCount, 3, "the keep-alive is established once, not per subscribe"); + await t.notThrowsAsync(watcher.pinBackend(), "a failed keep-alive is swallowed"); + await t.notThrowsAsync(watcher.unpinBackend(), "unpin after a failed pin is a no-op"); } finally { esmock.purge(watcher); } @@ -132,8 +156,7 @@ test.serial("subscribe: native subscribe and unsubscribe never overlap", async ( }); try { // Fire several subscribes concurrently, then unsubscribe them all concurrently. Without - // serialization the native calls would overlap (maxInFlight > 1). The keep-alive subscribe - // also runs through the chain, so it is covered by the same no-overlap guarantee. + // serialization the native calls would overlap (maxInFlight > 1). const subs = await Promise.all([ watcher.subscribe("/a", () => {}, {}), watcher.subscribe("/b", () => {}, {}), diff --git a/packages/server/lib/serve/Supervisor.js b/packages/server/lib/serve/Supervisor.js index 9013631da4f..eb4a67de458 100644 --- a/packages/server/lib/serve/Supervisor.js +++ b/packages/server/lib/serve/Supervisor.js @@ -6,6 +6,7 @@ import {getLogger} from "@ui5/logger"; import buildApp from "./stack.js"; import attachLiveReloadServer from "../liveReload/server.js"; import {listen, addSsl, announceListening} from "./httpListener.js"; +import {pinBackend, unpinBackend} from "@ui5/project/internal/build/helpers/fileWatcher"; import {trace} from "./teardownTrace.js"; const log = getLogger("server:Supervisor"); @@ -100,6 +101,10 @@ class Supervisor extends EventEmitter { #relayUnsubscribe = null; #liveReloadHandle = null; + // Whether this supervisor holds a native-watcher backend pin (see pinBackend). Guards destroy() + // against releasing a pin that #init never acquired (e.g. a construction failure before pinning). + #backendPinned = false; + // Watches the project-definition files and drives reinitialize() on a change. Owned by the // supervisor (not the BuildServer) so it outlives each swapped-out stack, and re-targeted to // the new graph after every swap. @@ -232,6 +237,12 @@ class Supervisor extends EventEmitter { acceptRemoteConnections = false, liveReload = false, } = this.#config; + // Pin the native watcher backend for the whole serving session before any watcher subscribes, + // so its shared registry never empties across a reinitialize() swap (parcel-bundler/watcher#259). + // Released in destroy(). Never throws: a failed pin degrades to the unprotected behavior. + await pinBackend(); + this.#backendPinned = true; + if (h2) { const nodeVersion = parseInt(process.versions.node.split(".")[0], 10); if (nodeVersion >= 24) { @@ -622,6 +633,14 @@ class Supervisor extends EventEmitter { }); trace("Supervisor.destroy: awaiting httpClosed"); await httpClosed; + // Release the backend pin last: every watcher this session owns is now unsubscribed, so the + // shared registry can empty without a concurrent subscribe to race, and dropping the keep-alive + // lets the native handle stop holding the event loop open. + if (this.#backendPinned) { + this.#backendPinned = false; + trace("Supervisor.destroy: unpinBackend"); + await unpinBackend(); + } trace("Supervisor.destroy: exit"); } } diff --git a/packages/server/test/lib/server/serve/Supervisor.js b/packages/server/test/lib/server/serve/Supervisor.js index 54484e002ba..220fff983d7 100644 --- a/packages/server/test/lib/server/serve/Supervisor.js +++ b/packages/server/test/lib/server/serve/Supervisor.js @@ -74,17 +74,22 @@ function createMocks({stacks, buildAppImpl, definitionWatcherCreate} = {}) { } }; + const pinBackend = sinon.stub().resolves(); + const unpinBackend = sinon.stub().resolves(); + const mocks = { "node:http": httpMock, "../../../../lib/serve/stack.js": {default: buildApp}, "../../../../lib/serve/httpListener.js": {listen, addSsl, announceListening}, "../../../../lib/liveReload/server.js": {default: attachLiveReloadServer}, + "@ui5/project/internal/build/helpers/fileWatcher": {pinBackend, unpinBackend}, }; return { mocks, projectWatcher, httpServer, listen, addSsl, announceListening, attachLiveReloadServer, liveReloadHandle, buildApp, createdHandlers, ProjectDefinitionWatcher, definitionWatchers, waitForProjectGraphSettled, + pinBackend, unpinBackend, }; } @@ -392,16 +397,21 @@ test("create() tears down the bound socket and BuildServer when the definition w test("destroy() closes live-reload, the socket, and the BuildServer; reinitialize() is then a no-op", async (t) => { const stack = createStack(); const graphFactory = sinon.stub().resolves({}); - const {mocks, projectWatcher, httpServer, liveReloadHandle} = createMocks({stacks: [stack]}); + const {mocks, projectWatcher, httpServer, liveReloadHandle, pinBackend, unpinBackend} = + createMocks({stacks: [stack]}); const {default: Supervisor} = await importSupervisor(mocks, projectWatcher); const supervisor = await Supervisor.create({}, baseConfig, undefined, graphFactory); + // The session pins the native watcher backend on create so its registry never empties across a + // swap (parcel-bundler/watcher#259). + t.true(pinBackend.calledOnce, "the backend is pinned for the session"); await supervisor.destroy(); t.true(liveReloadHandle.close.calledOnce); t.true(httpServer.close.calledOnce); t.true(stack.buildServer.destroy.calledOnce); + t.true(unpinBackend.calledOnce, "the backend pin is released on destroy so the process can exit"); await supervisor.reinitialize(); t.true(graphFactory.notCalled, "reinitialize after destroy does nothing");