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..305b86b69df 100644 --- a/packages/project/lib/build/helpers/fileWatcher.js +++ b/packages/project/lib/build/helpers/fileWatcher.js @@ -1,5 +1,7 @@ import {existsSync, readFileSync} from "node:fs"; +import os from "node:os"; import {getLogger} from "@ui5/logger"; +import {trace} from "./teardownTrace.js"; const log = getLogger("build:helpers:fileWatcher"); @@ -43,6 +45,102 @@ 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). 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 +// 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; +} + +// 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; + +/** + * 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: backend keep-alive subscribe start"); + return native.subscribe(os.tmpdir(), () => {}, {ignore: ["**"]}); + }).then((subscription) => { + trace("fileWatcher: backend keep-alive subscribe done"); + return subscription; + }, (err) => { + // 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; + }); + 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(); + }); + } +} + /** * 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 @@ -114,7 +212,19 @@ export async function subscribe(dir, callback, opts = {}) { if (!shouldUsePolling()) { const native = await loadNativeBackend(); if (native) { - return native.subscribe(dir, callback, opts); + // 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); + }); + trace(`fileWatcher.subscribe: native subscribe done (${dir})`); + // 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/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..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. @@ -13,11 +15,20 @@ */ 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 @@ -26,6 +37,20 @@ 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())); - return results.filter((r) => r.status === "rejected").map((r) => r.reason); + 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 d9a13549128..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"; @@ -230,13 +231,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; } @@ -258,20 +259,33 @@ 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. + #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/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/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/fileWatcher.js b/packages/project/test/lib/build/helpers/fileWatcher.js index f84a78174b9..0686352889f 100644 --- a/packages/project/test/lib/build/helpers/fileWatcher.js +++ b/packages/project/test/lib/build/helpers/fileWatcher.js @@ -72,9 +72,99 @@ 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("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().rejects(new Error("cannot subscribe")); + const watcher = await importWatcherWithParcel({ + default: {subscribe: parcelSubscribe}, subscribe: parcelSubscribe, + }); + try { + 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); + } +}); + +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); } 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/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 () => { 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/lib/serve/Supervisor.js b/packages/server/lib/serve/Supervisor.js index af4834aa33a..eb4a67de458 100644 --- a/packages/server/lib/serve/Supervisor.js +++ b/packages/server/lib/serve/Supervisor.js @@ -6,6 +6,8 @@ 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"); @@ -99,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. @@ -125,6 +131,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 +184,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; @@ -212,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) { @@ -289,6 +320,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 +387,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 +539,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 +553,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,35 +585,63 @@ 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. + trace("Supervisor.destroy: enter"); 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. + 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 + // 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 { + 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}`); + } }); - 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}`); - } + 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/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/lib/server/serve/Supervisor.js b/packages/server/test/lib/server/serve/Supervisor.js index 55b9dbe70d9..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"); @@ -419,6 +429,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]}); 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, () => {}); +}