diff --git a/.github/workflows/plugin-ci.yml b/.github/workflows/plugin-ci.yml index ff3b74031..1d9be2001 100644 --- a/.github/workflows/plugin-ci.yml +++ b/.github/workflows/plugin-ci.yml @@ -536,6 +536,73 @@ jobs: cat << 'LIFECYCLE' > /tmp/check-lifecycle.js const path = require('path'); const pkg = require(process.cwd() + '/package.json'); + + // ── Async crash trap ───────────────────────────────────── + // A plugin can start cleanly and still take the server down a + // moment later: an 'error' event emitted on a socket/emitter with + // no listener, or a floating promise that rejects after start() + // has already resolved. Neither travels the promise path, so the + // try/catch around `await plugin.start({})` below cannot see them. + // + // In production the server has no such trap either — Node's + // default action for an unhandled 'error' event is to throw, and + // under systemd Restart=always the result is an endless + // crash-restart loop rather than one bad plugin. + // + // Recording them here (rather than dying immediately) lets the + // lifecycle run finish and report every problem it found, which + // is more useful than surfacing whichever one happened to fire + // first. Anything caught is fatal — see the report below. + const ASYNC_CRASH_DRAIN_MS = 1500; + const asyncCrashes = []; + process.on('uncaughtException', (e) => { + asyncCrashes.push('uncaught exception: ' + ((e && e.message) || String(e))); + }); + process.on('unhandledRejection', (e) => { + asyncCrashes.push('unhandled rejection: ' + ((e && e.message) || String(e))); + }); + + // Every exit from the lifecycle check goes through here, including + // the early returns taken when start() or stop() throws. A plugin + // can schedule a failing timer and *then* throw synchronously from + // start(): the server catches that throw and keeps running (see + // doPluginStart in src/interfaces/plugins.ts), so the timer still + // fires and still kills the server. Exiting on the throw alone + // would report success for exactly that plugin. + const finish = async (code) => { + // Let queued failures surface before deciding the verdict. A + // microtask turn would cover an 'error' already on the queue, but + // the failures worth catching are slower: a socket connect, a + // D-Bus handshake or a DNS lookup started during start() + // typically fails a second or so in, which is exactly the + // "started fine, died shortly after" shape this check exists for. + // + // 1.5s covers those while staying far inside the step's 2-minute + // budget. It is a fixed cost on every run, so it is not raised + // further: this drains what start() already kicked off, and is + // not meant to wait out a slow remote endpoint. + await new Promise((resolve) => setTimeout(resolve, ASYNC_CRASH_DRAIN_MS)); + + if (asyncCrashes.length > 0) { + console.log(''); + // start() may run twice (initial + restart), so one faulty code + // path reports the same message twice. Collapse duplicates — + // two identical lines read as two separate problems. + [...new Set(asyncCrashes)].forEach(c => console.log('::error::Lifecycle: ' + c)); + console.log(''); + console.log('The plugin crashed the process after start() had already'); + console.log('returned. The server does not sandbox plugins: an unhandled'); + console.log("'error' event or a rejected floating promise terminates the"); + console.log('whole server, and under systemd it then restart-loops.'); + console.log(''); + console.log('Common cause: an emitter or socket used without an error'); + console.log("listener. Attach one ('error' handlers are required, not"); + console.log('optional), or await the operation so the failure reaches the'); + console.log('try/catch in start().'); + process.exit(1); + } + process.exit(code); + }; // See validate-entry.js for the rationale — object/conditional // exports must be resolved, not flattened to 'index.js'. function resolveEntry(p, fallback) { @@ -713,6 +780,8 @@ jobs: plugin = ctor(mockApp); } catch (e) { console.log('Plugin constructor requires server context — skipping lifecycle check'); + // Pre-IIFE skip path: start() never ran, so there is nothing for + // finish() to drain (and top-level await is not available here). process.exit(0); } @@ -754,7 +823,7 @@ jobs: } else { console.log('::warning::Plugins should handle empty/default configuration gracefully.'); } - process.exit(0); + await finish(0); } try { @@ -769,7 +838,10 @@ jobs: } else { console.log('::error::plugin.stop() threw: ' + msg); console.log('::error::This causes the server to leak resources when the plugin is disabled or restarted.'); - process.exit(1); + // finish() rather than a bare exit: the job already fails here, + // but stop() may also have scheduled a delayed failure, and + // reporting it tells the author about both problems at once. + return await finish(1); } } @@ -782,11 +854,11 @@ jobs: if (isMockGap(msg)) { console.log('::warning::plugin.start({}) threw on restart: ' + msg); console.log('::warning::This looks like a missing CI mock method, not a plugin bug. Please report at https://github.com/SignalK/signalk-server/issues'); - process.exit(0); + await finish(0); } console.log('::error::plugin.start({}) threw on second call: ' + msg); console.log('::error::Plugins must support restart (stop then start). This fails when users toggle the plugin in the server UI.'); - process.exit(1); + return await finish(1); } try { await Promise.resolve(plugin.stop()); } catch (e) { /* ignore */ } @@ -802,11 +874,11 @@ jobs: console.log(''); console.log('Malformed deltas are silently discarded by the server —'); console.log('the plugin appears to work but data never reaches consumers.'); - process.exit(1); + await finish(1); } console.log('Plugin lifecycle (start/stop/restart) is clean'); - process.exit(0); + await finish(0); })().catch(e => { console.log('::error::Unexpected error during lifecycle check: ' + (e && e.message || String(e))); process.exit(1); @@ -1895,7 +1967,7 @@ jobs: echo "- **package.json** — \`signalk-node-server-plugin\` keyword, \`main\`/\`exports\` field, \`engines.node\`" echo "- **Entry point** — Plugin exports a constructor function" echo "- **plugin.schema()** — Returns valid JSON Schema without crashing" - echo "- **Lifecycle** — start()/stop()/restart cycle works without errors" + echo "- **Lifecycle** — start()/stop()/restart cycle works without errors, and the plugin does not crash the process asynchronously afterwards" echo "- **API usage** — No deprecated (\`setProviderStatus\`), internal (\`app.server\`), file storage, or security anti-patterns" echo "- **Node built-in modules** — \`node:sqlite\` requires \`engines.node >= 22.5.0\` declared in package.json" echo "- **npm pack** — All files referenced by \`main\`/\`exports\` are included in the package" diff --git a/docs/develop/plugins/ci.md b/docs/develop/plugins/ci.md index 873787e24..ad73181f3 100644 --- a/docs/develop/plugins/ci.md +++ b/docs/develop/plugins/ci.md @@ -58,6 +58,8 @@ The desktop jobs (Linux, Linux arm64, macOS, Windows) run these checks, even if **Lifecycle** — Runs `start()` → `stop()` → `start()` (restart) with an empty configuration. Validates delta messages emitted during startup and checks that `registerDeltaInputHandler` handlers forward deltas correctly. +**Async crashes** — Watches for roughly 1.5 seconds after the lifecycle calls return and fails the job if the plugin fails asynchronously in that window — an unhandled `'error'` event (which ends the server process) or a floating promise that rejects late. A failure that takes longer to surface will not be caught, so a clean run is not proof there is none. See [Crashing the server after start()](#crashing-the-server-after-start) below. + **API usage** — Scans source files for: - Deprecated APIs (`setProviderStatus` → `setPluginStatus`, `setProviderError` → `setPluginError`) @@ -175,6 +177,61 @@ test-cerbo-hardware: - run: npm test ``` +## Crashing the server after start() + +The server does not sandbox plugins. Everything runs in one Node process, so +an error your plugin fails to handle does not disable just that plugin — it +terminates the whole server. Under a process supervisor (`Restart=always`, +Docker's `restart: unless-stopped`) the server then restart-loops: it comes up, +runs for a few seconds, dies again, and keeps going indefinitely. + +The dangerous case is the one that escapes `try/catch`. Wrapping the body of +`start()` is not enough, because two common failures arrive _after_ `start()` +has already returned successfully: + +**Unhandled `'error'` events.** In Node, `'error'` is special: an `EventEmitter` +that emits it with no listener attached throws, and there is nothing up the +stack to catch it. Sockets, streams, D-Bus connections, serial ports and MQTT +clients all report failures this way. + +Attach an `'error'` listener to every emitter your plugin holds, at the point +you create it, and report the failure through `app.setPluginError()`. A +listener that only handles the success event (`'data'`, `'message'`, +`'connect'`) leaves the failure path unguarded. + +A library opening the connection for you does not remove the obligation — if it +hands back an emitter and attaches no listener itself, the responsibility is +still yours. + +**Floating promises.** An async call started but never awaited (and with no +`.catch()`) becomes an unhandled rejection. Node terminates the process for +these by default, but the server installs an `unhandledRejection` handler: it +logs the rejection and, when the originating plugin can be identified from the +stack, records a plugin error. So a floating rejection usually degrades your +plugin rather than killing the server — the failure is silent from the user's +point of view, and the work you meant to do never happened. + +Either await the call inside `start()`, so its own error handling applies, or — +when the work must continue in the background — attach a rejection handler when +you kick it off. What fails the check is a call whose rejection nothing +observes. + +The general rule: a plugin should report failures through +`app.setPluginError()` and keep the process alive. Hardware that is absent, a +socket that is missing, a remote service that is down — these are normal +conditions on a boat, not reasons to take navigation data offline. + +CI installs `uncaughtException` and `unhandledRejection` handlers around the +lifecycle check and **fails the job** if either fires, including when +`start()`, `stop()` and restart all report success. + +The check is an error rather than a warning because of the first case. The +server's own `uncaughtException` handler logs the error and flags the plugin, +but it cannot stop an unhandled `'error'` event: Node throws on those +synchronously, and the throw ends the process regardless of what the handler +logged. One faulty emitter therefore takes the whole server down, and the +resulting crash-loop is difficult for users to trace back to its cause. + ## See also - [Releases and Changelogs](./release.md) — once CI passes, automate the release cut and publish step. diff --git a/src/api/ble/index.ts b/src/api/ble/index.ts index 91bc6b474..ace8adfcb 100644 --- a/src/api/ble/index.ts +++ b/src/api/ble/index.ts @@ -15,6 +15,7 @@ import { SignalKMessageHub, WithConfig } from '../../app' import WebSocket from 'ws' import { writeSettingsFile } from '../../config/config' import { LocalBLEProvider } from './localProvider' +import { createBluetoothSafe } from './safeBluetooth' import { RemoteGatewayProvider } from './remoteProvider' import { bleVendorName } from './bleCompanyIds' @@ -150,12 +151,16 @@ export class BLEApi implements IBLEApi { } try { - // eslint-disable-next-line @typescript-eslint/no-require-imports - const { createBluetooth } = require('@naugehyde/node-ble') - const { bluetooth, destroy } = createBluetooth() - const adapters = await bluetooth.activeAdapters() - destroy() - return adapters.map((a: any) => a.adapter as string) + const { bluetooth, destroy } = createBluetoothSafe() + // destroy() in finally: activeAdapters() rejects on a host with no + // usable bus, and skipping the teardown would leak the D-Bus + // connection every time this probe runs. + try { + const adapters = await bluetooth.activeAdapters() + return adapters.map((a: any) => a.adapter as string) + } finally { + destroy() + } } catch { return [] } diff --git a/src/api/ble/localProvider.ts b/src/api/ble/localProvider.ts index db645f542..e253ff11d 100644 --- a/src/api/ble/localProvider.ts +++ b/src/api/ble/localProvider.ts @@ -17,6 +17,8 @@ import { GATTSubscriptionHandle } from '@signalk/server-api' +import { createBluetoothSafe } from './safeBluetooth' + // How often to poll BlueZ for newly discovered devices const DEVICE_WATCH_INTERVAL_MS = 5000 // waitDevice timeout when attaching a listener to an already-known device @@ -113,9 +115,7 @@ export class LocalBLEProvider { async init(): Promise { try { - // eslint-disable-next-line @typescript-eslint/no-require-imports - const { createBluetooth } = require('@naugehyde/node-ble') - const bt = createBluetooth() + const bt = createBluetoothSafe() this.bluetooth = bt.bluetooth this.destroy = bt.destroy this.adapter = await this.bluetooth.getAdapter(this.adapterName) diff --git a/src/api/ble/safeBluetooth.ts b/src/api/ble/safeBluetooth.ts new file mode 100644 index 000000000..bfaa6280d --- /dev/null +++ b/src/api/ble/safeBluetooth.ts @@ -0,0 +1,144 @@ +/** + * Safe wrapper around `@naugehyde/node-ble`'s `createBluetooth()`. + * + * `createBluetooth()` opens a D-Bus system-bus connection eagerly and returns + * synchronously, without attaching an `error` listener to it. The underlying + * `@jellybrick/dbus-next` connection reports transport failures by emitting + * `error` on that connection rather than by rejecting the pending call, so a + * missing or unreachable `/var/run/dbus/system_bus_socket` surfaces as an + * `error` event with no listener — which Node escalates into an uncaught + * exception. Because it arrives on the event emitter and not through the + * promise chain, an `await createBluetooth()...` inside `try/catch` never sees + * it: the process dies with `connect ENOENT /var/run/dbus/system_bus_socket` + * a few seconds after the server has otherwise started cleanly. + * + * This happens on any host without a reachable system bus — most commonly a + * container that does not bind-mount the socket, but also a stripped-down + * Linux install with no D-Bus daemon running. + * + * Attaching a listener before handing the session back keeps the failure on + * the promise path, where the existing `try/catch` blocks already handle it. + */ + +import { createDebug } from '../../debug' +const debug = createDebug('signalk-server:api:ble:safe') + +/** + * The parts of node-ble's Bluetooth object this codebase actually uses. + * node-ble's shipped declarations are incomplete relative to its runtime — + * they expose neither `activeAdapters()` (already used here) nor `dbus` — so + * the surface is described locally instead. + */ +export interface SafeBluetooth { + activeAdapters(): Promise> + getAdapter(adapter: string): Promise +} + +export interface BluetoothSession { + bluetooth: SafeBluetooth + destroy: () => void +} + +/** The only part of the dbus-next connection this module touches. */ +interface ErrorEmitter { + on(event: 'error', listener: (err: unknown) => void): void + off(event: 'error', listener: (err: unknown) => void): void +} + +/** + * Creates a node-ble session whose D-Bus connection can never raise an + * unhandled `error` event, and whose pending operations never hang. + * + * Two failure modes have to be handled together: + * + * 1. `createBluetooth()` opens the system-bus connection eagerly and attaches + * no `error` listener. dbus-next reports transport failures by emitting + * `error` rather than by rejecting the pending call, so a missing or + * unreachable `/var/run/dbus/system_bus_socket` surfaces as an `error` + * event with no listener — which Node escalates into an uncaught + * exception. Because it arrives on the event emitter and not the promise + * chain, `await`ing inside `try/catch` never sees it. + * + * 2. Merely swallowing that event is not enough. dbus-next does not settle + * in-flight calls when the connection dies, so an operation issued before + * the failure stays pending forever and `await bluetooth.activeAdapters()` + * never returns — trading a crash for a hang, which is harder to diagnose. + * + * So the listener is attached synchronously (before the caller can await + * anything, leaving no window for an early error to escape) and the recorded + * failure is replayed as a rejection from every method this codebase calls. + * Callers already treat "no usable adapter" as a normal outcome, so the + * rejection lands in error handling that exists. + */ +export function createBluetoothSafe(): BluetoothSession { + // eslint-disable-next-line @typescript-eslint/no-require-imports + const { createBluetooth } = require('@naugehyde/node-ble') + const session = createBluetooth() as { + bluetooth: SafeBluetooth + destroy: () => void + } + + // Set once the bus reports a transport failure. Every later call fails + // fast with this rather than waiting on a connection that is gone. + let busError: Error | undefined + + // node-ble keeps the dbus-next connection on the Bluetooth instance; guard + // the lookup so an upstream rename degrades to today's behaviour rather + // than throwing from inside the safety wrapper itself. + const maybeBus = (session.bluetooth as unknown as { dbus?: ErrorEmitter }) + ?.dbus + const canListen = + !!maybeBus && + typeof maybeBus.on === 'function' && + typeof maybeBus.off === 'function' + const bus = maybeBus as ErrorEmitter + if (canListen) { + bus.on('error', (err: unknown) => { + busError = + err instanceof Error ? err : new Error(String(err ?? 'unknown error')) + debug.enabled && debug(`D-Bus system bus error: ${busError.message}`) + }) + } else { + debug('Could not attach D-Bus error listener — node-ble internals changed') + } + + // Races each call against the bus failing under it. Without this an + // operation already in flight when the socket dies never settles. + const guard = (op: () => Promise): Promise => { + if (busError) return Promise.reject(busError) + if (!canListen) return op() + return new Promise((resolve, reject) => { + // Detached on every settle path, including the bus-error one: when the + // bus fails the underlying operation stays pending forever, so the + // op().then() handlers below never run and would leave the listener + // attached. A long-lived session would then trip Node's max-listeners + // warning after ten failed operations. + const done = () => bus.off('error', onBusError) + function onBusError(err: unknown) { + done() + reject( + err instanceof Error ? err : new Error(String(err ?? 'bus error')) + ) + } + bus.on('error', onBusError) + op().then( + (v) => { + done() + resolve(v) + }, + (e) => { + done() + reject(e) + } + ) + }) + } + + const bluetooth: SafeBluetooth = { + activeAdapters: () => guard(() => session.bluetooth.activeAdapters()), + getAdapter: (adapter: string) => + guard(() => session.bluetooth.getAdapter(adapter)) + } + + return { bluetooth, destroy: session.destroy } +} diff --git a/test/ble-dbus-error.ts b/test/ble-dbus-error.ts new file mode 100644 index 000000000..bbe7f4d26 --- /dev/null +++ b/test/ble-dbus-error.ts @@ -0,0 +1,185 @@ +import { expect } from 'chai' +import { EventEmitter } from 'node:events' +import Module from 'node:module' + +/** + * Regression test for the BLE local provider taking the whole server down. + * + * `@naugehyde/node-ble`'s `createBluetooth()` opens a D-Bus system-bus + * connection eagerly and hands it back without an `error` listener. dbus-next + * reports transport failures by emitting `error` on that connection, so on a + * host with no reachable `/var/run/dbus/system_bus_socket` (any container that + * does not mount it) the failure arrives as an unhandled `error` event and + * Node escalates it to an uncaught exception — several seconds after the + * server has otherwise started cleanly. The `try/catch` around the awaited + * calls cannot catch it because it never travels the promise path. + * + * `createBluetoothSafe()` attaches the listener synchronously, before the + * caller can await anything, closing that window. + */ + +// Stand-in for the dbus-next connection: an emitter whose only interesting +// behaviour is that an unlistened 'error' throws, exactly as Node's does. +class FakeBus extends EventEmitter {} + +// The wrapper returns its own bluetooth facade, so the stub records the bus +// it handed out for the test to drive. +let lastBus: FakeBus | undefined + +// Module.prototype.require is not in @types/node's public surface, so the +// patch point is described structurally rather than reached through `any`. +type Requirer = (this: unknown, id: string, ...rest: unknown[]) => unknown +interface PatchableModule { + prototype: { require: Requirer } +} + +const patchable = Module as unknown as PatchableModule +const requireStub: Requirer = patchable.prototype.require + +// Returns whatever the callback returns, and hands back the bus the stub +// created so tests never read a stale one from an earlier case. +const withStubbedNodeBle = (fn: () => T): { result: T; bus: FakeBus } => { + lastBus = undefined + patchable.prototype.require = function ( + this: unknown, + id: string, + ...rest: unknown[] + ) { + if (id === '@naugehyde/node-ble') { + return { + createBluetooth: () => { + const dbus = new FakeBus() + lastBus = dbus + return { + bluetooth: { + dbus, + // Never settles on its own — mirrors dbus-next leaving calls + // in flight when the connection dies. + activeAdapters: () => new Promise(() => undefined), + getAdapter: () => Promise.resolve({}) + }, + destroy: () => undefined + } + } + } + } + return requireStub.call(this, id, ...rest) + } + let result: T + try { + result = fn() + } finally { + patchable.prototype.require = requireStub + } + if (!lastBus) { + throw new Error('stub was never invoked — createBluetooth() not called') + } + return { result, bus: lastBus } +} + +describe('BLE D-Bus transport errors', () => { + it('does not let a system-bus error escape as an uncaught exception', () => { + const { bus } = withStubbedNodeBle(() => { + // Imported inside the stub so the wrapper picks up the fake module. + const { createBluetoothSafe } = + // eslint-disable-next-line @typescript-eslint/no-require-imports + require('../src/api/ble/safeBluetooth') as typeof import('../src/api/ble/safeBluetooth') + + return createBluetoothSafe() + }) + + expect(bus.listenerCount('error')).to.equal( + 1, + 'expected an error listener to be attached synchronously' + ) + + // The real failure: ENOENT on the system bus socket. Without a + // listener attached, this emit throws and takes the process down. + const emit = () => + bus.emit( + 'error', + Object.assign( + new Error('connect ENOENT /var/run/dbus/system_bus_socket'), + { + code: 'ENOENT' + } + ) + ) + + expect(emit).to.not.throw() + }) + + it('rejects a pending adapter call when the bus fails under it', async () => { + // Swallowing the 'error' event is not enough on its own: dbus-next does + // not settle in-flight calls when the connection dies, so an operation + // issued before the failure would otherwise stay pending forever and + // turn the crash into a hang. + const { result: session, bus } = withStubbedNodeBle(() => { + const { createBluetoothSafe: make } = + // eslint-disable-next-line @typescript-eslint/no-require-imports + require('../src/api/ble/safeBluetooth') as typeof import('../src/api/ble/safeBluetooth') + return make() + }) + + const baseline = bus.listenerCount('error') + + // A call that never settles on its own, as the real one does not. + const pending = session.bluetooth.activeAdapters() + + bus.emit( + 'error', + new Error('connect ENOENT /var/run/dbus/system_bus_socket') + ) + + let rejected = false + await pending.catch(() => { + rejected = true + }) + expect(rejected).to.equal( + true, + 'expected the pending call to reject once the bus failed' + ) + + // The underlying op stays pending forever after a bus failure, so the + // listener has to come off on the rejection path too — nothing else + // will remove it. + expect(bus.listenerCount('error')).to.equal( + baseline, + 'expected the per-call listener to be removed on the bus-error path' + ) + }) + + it('does not accumulate bus listeners across calls', async () => { + // guard() attaches an 'error' listener per call so a bus failure can + // reject the operation under way. Without removing it on settle, a + // long-lived session trips Node's max-listeners warning after ten + // operations and slowly leaks. + const { result: session, bus } = withStubbedNodeBle(() => { + const { createBluetoothSafe: make } = + // eslint-disable-next-line @typescript-eslint/no-require-imports + require('../src/api/ble/safeBluetooth') as typeof import('../src/api/ble/safeBluetooth') + return make() + }) + + const before = bus.listenerCount('error') + for (let i = 0; i < 12; i++) { + await session.bluetooth.getAdapter('hci0') + } + expect(bus.listenerCount('error')).to.equal( + before, + 'expected per-call listeners to be removed once the call settled' + ) + }) + + it('still returns a usable session when the bus is healthy', () => { + withStubbedNodeBle(() => { + const { createBluetoothSafe } = + // eslint-disable-next-line @typescript-eslint/no-require-imports + require('../src/api/ble/safeBluetooth') as typeof import('../src/api/ble/safeBluetooth') + + const session = createBluetoothSafe() + expect(session.bluetooth).to.be.an('object') + expect(session.destroy).to.be.a('function') + }) + }) +})