From 79ba3eb676d764d95c2e42f6eeb9a3bf74b66a53 Mon Sep 17 00:00:00 2001 From: kkdev92 <112151103+kkdev92@users.noreply.github.com> Date: Sat, 29 Aug 2026 21:08:12 +0900 Subject: [PATCH] feat(diagnostics): say what a shutdown that ran out of budget was still holding `application.shutdownTimeout` reported the phase it stopped in and nothing else, which left the only question that matters unanswered: which hosted service, which operation, which scope. Its details now carry the phase, the budget, how long it waited, the hosted service inside its own `stop`, the ones still up, the operations that never settled and the resource scope tree. The Host supplies the scopes and the deadline; naming a hosted service or an operation is the Application's job, so it passes a `describeRemaining` callback in. That callback is treated like any other observer -- if it throws, the stop pipeline carries on without the explanation. Both are built on `RegistrationScope.inspect()` and `ResourceScope.inspect()`, which report a scope's name, its entry count and its attached children. For tests, `createTestHost().inspect()` exposes the same view. `leaks()` is deliberately unchanged: adding the fields there was the obvious move and it broke the first extension it was tried on, because the guide tells you to assert on the whole object and `toEqual` sees a new field. A separate method costs one call and breaks nobody. Ids, names and counts only. Command arguments, webview payloads and secret values stay out of a diagnostic, because a diagnostic ends up in whatever log gets pasted into an issue. Also documents `onDiagnostic`, which has been part of `defineExtension` since 3.0.0 and appeared in no guide. Co-Authored-By: Claude Opus 5 (1M context) --- CHANGELOG.md | 33 ++++++ README.md | 2 +- docs/guide.md | 66 +++++++++++ docs/samples/diagnostics.ts | 34 ++++++ src/foundation/application/application.ts | 111 +++++++++++++++++- src/foundation/hosting/application-host.ts | 76 +++++++++++- .../resources/registration-scope.ts | 38 ++++++ src/foundation/resources/resource-scope.ts | 22 +++- src/index.ts | 6 +- src/testing/index.ts | 1 + src/testing/test-host.ts | 15 ++- .../application/lifecycle-hardening.test.ts | 92 ++++++++++++++- .../hosting/application-host.test.ts | 93 +++++++++++++++ .../resources/registration-scope.test.ts | 31 +++++ .../resources/resource-scope.test.ts | 30 +++++ tests/testing/test-host.test.ts | 12 ++ 16 files changed, 649 insertions(+), 13 deletions(-) create mode 100644 docs/samples/diagnostics.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index ab29641..15de951 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,39 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). From 1.0.0 onward this project follows [Semantic Versioning](https://semver.org/spec/v2.0.0.html). Pre-1.0 releases followed it in spirit; their breaking changes are marked **Breaking**. +## [Unreleased] + +### Added + +- **A shutdown that runs out of budget now says what was holding it.** The + `application.shutdownTimeout` diagnostic carried a phase name and nothing + else, which left the only question that matters unanswered: which hosted + service, which operation, which scope. Its `details` now carry the phase, the + budget, how long it waited, the hosted service inside its own `stop`, the + services still up, the operations that never settled and the resource scope + tree — ids, names and counts, never an argument or a payload. + +- **`createTestHost().inspect()` says what a failed leak assertion could not.** + `leaks()` reports three counts; when one is not zero the next question is + which module or operation still holds something, and there was no way to ask. + `inspect()` answers it: the scope trees, the hosted services still up, the + operations that never settled. + + `leaks()` itself is deliberately unchanged. Adding the fields there was the + obvious move and it broke the first extension it was tried on: the guide + tells you to assert on the whole object, `toEqual` sees a new field, and the + test fails for a reason that has nothing to do with the extension. A separate + method costs one call and breaks nobody. + +- **`RegistrationScope` and `ResourceScope` gained `inspect()`**, returning a + `ScopeInspection` — name, entry count, attached children. This is what both + of the above are built on, and it is safe to call at any point, including + during disposal. + +- **`onDiagnostic` is documented.** It has been part of `defineExtension` since + 3.0.0 and appeared in no guide; the guide now has a Diagnostics section + listing the events and what they are useful for. + ## [4.0.1] - 2026-08-29 **A patch to the tree-view adapter, plus four corrections to what the project diff --git a/README.md b/README.md index 6dd45bf..b78bf0f 100644 --- a/README.md +++ b/README.md @@ -278,7 +278,7 @@ Stated plainly, because a framework that is vague about its boundaries gets trusted for things it cannot do. - **Nothing unwinds on a crash**: If the extension host is killed, `deactivate` never runs — persist what matters when the operation that produced it completes, not during shutdown -- **The shutdown budget is shared and hard**: VS Code races _every_ extension's deactivation against 5 seconds and then exits; the framework's own budget (3 s by default) sits inside that, and past it pending work is abandoned rather than awaited +- **The shutdown budget is shared and hard**: VS Code races _every_ extension's deactivation against 5 seconds and then exits; the framework's own budget (3 s by default) sits inside that, and past it pending work is abandoned rather than awaited — the `application.shutdownTimeout` diagnostic names what was still holding on - **Rollback covers what the framework owns**: registrations, the services it created, resources placed in one of its scopes, started hosted services — it cannot un-write a file or un-send a request - **Leak detection has the same boundary**: it sees what the framework tracks, and nothing else - **Cancellation is cooperative**: aborting a signal asks a handler to stop; one that ignores its signal keeps running, and the framework cannot terminate it diff --git a/docs/guide.md b/docs/guide.md index c2dec27..339ed05 100644 --- a/docs/guide.md +++ b/docs/guide.md @@ -36,6 +36,7 @@ same code runs in a test and in the editor. - [UI](#ui) - [Views: trees and webviews](#views-trees-and-webviews) - [Testing](#testing) +- [Diagnostics](#diagnostics) - [Keeping package.json honest](#keeping-packagejson-honest) - [The escape hatch](#the-escape-hatch) - [Publishing an API](#publishing-an-api) @@ -644,6 +645,71 @@ The Test Host does not reproduce VS Code. Anything that depends on what VS Code does _with_ what you hand it — rather than on what it hands back — needs a real Extension Host test. +`host.leaks()` reports what the framework still owns after `stop()` — three +counts, and the assertion worth writing at the end of every host test. When one +of them is not zero, `host.inspect()` says what: the scope trees, naming the +module or operation that still holds an entry, plus the hosted services that +never stopped and the operations that never settled. + +## Diagnostics + +The framework narrates its own lifecycle. Pass `onDiagnostic` and you get every +transition as it happens: `application.starting` / `running` / `stopping` / +`stopped` / `failed`, `application.preflight.error` and `.warning`, +`module.binding` / `bound` / `failed` / `rollbackFailed`, `hostedService.*`, +`operation.started` / `completed` / `cancelled` / `failed`, and the +suppressions the notification and settings layers report. + + + +```ts +import { defineExtension } from '@kkdev92/vscode-ext-kit'; +import type { HostDiagnostic } from '@kkdev92/vscode-ext-kit'; + +import { projectsModule } from './commands-and-services.js'; + +/** The last few lifecycle events, for a "report an issue" command to attach. */ +const recent: HostDiagnostic[] = []; + +export const app = defineExtension({ + name: 'Sample', + modules: [projectsModule], + // Called synchronously as the host starts, binds modules, runs operations and + // stops. Keep it cheap: it is not awaited, and an exception here is swallowed + // rather than allowed to affect the lifecycle it is watching. + onDiagnostic: (diagnostic) => { + recent.push(diagnostic); + if (recent.length > 100) { + recent.shift(); + } + }, +}); + +/** + * `application.shutdownTimeout` is the one worth reading first. + * + * It means the stop budget ran out and the remaining work was abandoned rather + * than awaited. `details` says which phase ran out, how long it waited, which + * hosted service was inside its `stop`, which operations never settled, and + * which resource scopes still held entries — ids and counts, never arguments + * or payloads. + */ +export function unfinishedAtShutdown(): readonly HostDiagnostic[] { + return recent.filter((diagnostic) => diagnostic.event === 'application.shutdownTimeout'); +} +``` + +The event name is a string and `details` is plain data, so this is a stream to +log, count or attach to a bug report — not an event bus. Delivery is +best-effort by design: a listener that throws is ignored, and nothing waits for +one. + +`application.shutdownTimeout` deserves the special attention above because it is +the one event that reports something the framework could not do. VS Code races +every extension's deactivation against a few seconds and then exits; the +framework's own budget sits inside that, and past it pending work is abandoned. +Knowing _which_ work is the difference between a mystery and a fix. + ## Keeping package.json honest VS Code reads the manifest before any extension code runs, so `src` and diff --git a/docs/samples/diagnostics.ts b/docs/samples/diagnostics.ts new file mode 100644 index 0000000..897d3eb --- /dev/null +++ b/docs/samples/diagnostics.ts @@ -0,0 +1,34 @@ +import { defineExtension } from '@kkdev92/vscode-ext-kit'; +import type { HostDiagnostic } from '@kkdev92/vscode-ext-kit'; + +import { projectsModule } from './commands-and-services.js'; + +/** The last few lifecycle events, for a "report an issue" command to attach. */ +const recent: HostDiagnostic[] = []; + +export const app = defineExtension({ + name: 'Sample', + modules: [projectsModule], + // Called synchronously as the host starts, binds modules, runs operations and + // stops. Keep it cheap: it is not awaited, and an exception here is swallowed + // rather than allowed to affect the lifecycle it is watching. + onDiagnostic: (diagnostic) => { + recent.push(diagnostic); + if (recent.length > 100) { + recent.shift(); + } + }, +}); + +/** + * `application.shutdownTimeout` is the one worth reading first. + * + * It means the stop budget ran out and the remaining work was abandoned rather + * than awaited. `details` says which phase ran out, how long it waited, which + * hosted service was inside its `stop`, which operations never settled, and + * which resource scopes still held entries — ids and counts, never arguments + * or payloads. + */ +export function unfinishedAtShutdown(): readonly HostDiagnostic[] { + return recent.filter((diagnostic) => diagnostic.event === 'application.shutdownTimeout'); +} diff --git a/src/foundation/application/application.ts b/src/foundation/application/application.ts index 51db018..4234660 100644 --- a/src/foundation/application/application.ts +++ b/src/foundation/application/application.ts @@ -29,7 +29,11 @@ import type { import { AsyncCallbackError, PreflightError, ScopeCleanupError } from '../internal/errors.js'; import { claimRejection, isThenable } from '../internal/thenable.js'; import { createApplicationHost } from '../hosting/application-host.js'; -import type { ApplicationHost, HostDiagnostic } from '../hosting/application-host.js'; +import type { + ApplicationHost, + HostDiagnostic, + HostInspection, +} from '../hosting/application-host.js'; import { StopReason } from '../hosting/host-state.js'; import { CancellationReason, @@ -177,6 +181,22 @@ export interface CreateApplicationOptions { | undefined; } +/** + * What an Application still owns, as plain data. + * + * Extends the Host's view — scopes and state — with the work only the + * Application knows about: which hosted services are up, and which operations + * have not settled. Names and counts only. + */ +export interface ApplicationInspection extends HostInspection { + /** Hosted services that started and have not stopped, in start order. */ + readonly hostedServices: readonly string[]; + /** Ids of operations that started and have not settled. */ + readonly operations: readonly string[]; + /** Background hosted-service loops still being tracked. */ + readonly backgroundTasks: number; +} + /** * A compiled plan wired to platform capabilities, ready for Extension Host * activation. @@ -205,6 +225,11 @@ export interface Application { * rejects; cleanup failures are emitted as diagnostics. */ deactivate(): Promise; + /** + * What the framework still owns. Read by the Test Host's leak report, and by + * the Host itself when a shutdown runs out of budget. + */ + inspect(): ApplicationInspection; } /** @@ -234,11 +259,26 @@ export function createApplication(options: CreateApplicationOptions): Applicatio ? createNoopLogger() : createLogger(options.logSink, { application: plan.name }); + /** Hosted services that have started and not yet stopped, in start order. */ const startedServices: { readonly definition: HostedServiceDefinition; readonly injected: Readonly>; }[] = []; const backgroundTasks: Promise[] = []; + /** + * Operations that started and have not settled, keyed by id. + * + * Bookkeeping on a stream that already exists rather than a second one: the + * executor stamps every `operation.*` diagnostic with its id, so the events + * flowing through this file are enough to answer "what is still running?" + * when a shutdown runs out of budget. + */ + const inFlightOperations = new Map< + string, + { readonly name: string; readonly kind: string; readonly startedAt: number } + >(); + /** The hosted service currently inside its `stop`, if any. */ + let stoppingService: string | undefined; // Observability must never interfere: a throwing observer cannot be allowed // to fail activation, an operation, or cleanup. @@ -250,13 +290,56 @@ export function createApplication(options: CreateApplicationOptions): Applicatio } }; + /** Reads a diagnostic field that is `unknown` by contract. */ + const text = (value: unknown): string => (typeof value === 'string' ? value : ''); + const emitOperationDiagnostic = ( event: string, details: Readonly> ): void => { + const id: unknown = details['operationId']; + if (typeof id === 'string') { + if (event === 'operation.started') { + inFlightOperations.set(id, { + name: text(details['name']), + kind: text(details['kind']), + startedAt: Date.now(), + }); + } else if ( + event === 'operation.completed' || + event === 'operation.cancelled' || + event === 'operation.failed' + ) { + // The executor settles an operation with exactly one of these, before + // its `finally` reports any cleanup failure. + inFlightOperations.delete(id); + } + } emitDiagnostic({ event, details }); }; + /** + * Who is still holding the shutdown budget when it runs out. + * + * Ids, names and counts. Command arguments, webview payloads and secret + * values are deliberately absent: naming the owner is enough to act on, and + * a diagnostic that carried the work's own data would put it wherever the + * log goes. + */ + const describeRemaining = (): Readonly> => ({ + hostedServices: { + started: startedServices.map((started) => started.definition.id), + ...(stoppingService === undefined ? {} : { stopping: stoppingService }), + }, + operations: [...inFlightOperations].map(([id, operation]) => ({ + id, + name: operation.name, + kind: operation.kind, + elapsedMs: Date.now() - operation.startedAt, + })), + backgroundTasks: backgroundTasks.length, + }); + /** * Waits for tracked background loops to settle, never past the remaining * budget. The tasks already carry their own catch handlers, so abandoning an @@ -277,7 +360,12 @@ export function createApplication(options: CreateApplicationOptions): Applicatio }); try { if ((await Promise.race([Promise.all(pending), timeout])) === 'timeout') { - emitDiagnostic({ event: 'application.shutdownTimeout', details: { phase: 'background' } }); + emitDiagnostic({ + event: 'application.shutdownTimeout', + // `pending` rather than the tracked list: this drain took ownership + // of those promises, so `describeRemaining` no longer counts them. + details: { phase: 'background', pending: pending.length, ...describeRemaining() }, + }); } } finally { if (timer !== undefined) { @@ -340,6 +428,11 @@ export function createApplication(options: CreateApplicationOptions): Applicatio ): Promise => { for (let index = startedServices.length - 1; index >= 0; index -= 1) { const started = startedServices[index]; + // Truncated as the loop goes, so `startedServices` always names what is + // still up rather than everything that ever started -- which is what a + // shutdown-timeout diagnostic has to report. Safe while iterating + // backwards: only entries at or after the current index are removed. + startedServices.length = index; const stop = started?.definition.stop; if (started === undefined || stop === undefined) { continue; @@ -348,6 +441,7 @@ export function createApplication(options: CreateApplicationOptions): Applicatio const logger = rootLogger.withFields({ hostedServiceId: definition.id }); const context: HostedServiceStopContext = { signal, logger, remainingMs }; emitDiagnostic({ event: 'hostedService.stopping', details: { id: definition.id } }); + stoppingService = definition.id; try { await stop(context, injected); emitDiagnostic({ event: 'hostedService.stopped', details: { id: definition.id } }); @@ -357,14 +451,16 @@ export function createApplication(options: CreateApplicationOptions): Applicatio event: 'hostedService.failed', details: { id: definition.id, error }, }); + } finally { + stoppingService = undefined; } } - startedServices.length = 0; }; const host = createApplicationHost({ name: plan.name, shutdownTimeoutMs: plan.shutdown.timeoutMs, + describeRemaining, ...(options.onDiagnostic === undefined ? {} : { onDiagnostic: options.onDiagnostic }), async start({ registrations, resources, signal }) { @@ -1038,6 +1134,15 @@ export function createApplication(options: CreateApplicationOptions): Applicatio deactivate(): Promise { return host.stop(StopReason.Deactivate); }, + + inspect(): ApplicationInspection { + return { + ...host.inspect(), + hostedServices: startedServices.map((started) => started.definition.id), + operations: [...inFlightOperations.keys()], + backgroundTasks: backgroundTasks.length, + }; + }, }; } diff --git a/src/foundation/hosting/application-host.ts b/src/foundation/hosting/application-host.ts index 21f5065..2c3d5a8 100644 --- a/src/foundation/hosting/application-host.ts +++ b/src/foundation/hosting/application-host.ts @@ -3,6 +3,7 @@ import { CancellationReason, OperationCancelledError } from '../operations/cance import { createRegistrationScope, type RegistrationScope, + type ScopeInspection, } from '../resources/registration-scope.js'; import { createResourceScope, type ResourceScope } from '../resources/resource-scope.js'; import { HostState, StopReason, acceptsWork, isTerminalState } from './host-state.js'; @@ -48,6 +49,21 @@ export interface HostDiagnostic { readonly details?: Readonly>; } +/** + * What the Host still owns, as plain data. + * + * The counts on {@link ApplicationHost} answer "did anything leak?"; this + * answers "what, and whose is it?" without handing out the scopes themselves. + */ +export interface HostInspection { + /** Current lifecycle state. */ + readonly state: HostState; + /** Synchronous registrations, or undefined before `start()` runs. */ + readonly registrations: ScopeInspection | undefined; + /** Asynchronous resources, or undefined before `start()` runs. */ + readonly resources: ScopeInspection | undefined; +} + /** Options for {@link createApplicationHost}. */ export interface ApplicationHostOptions { /** Application name, used in scope names and diagnostics. */ @@ -70,6 +86,16 @@ export interface ApplicationHostOptions { readonly shutdownTimeoutMs?: number | undefined; /** Receives lifecycle diagnostics. Exceptions from the observer are ignored. */ readonly onDiagnostic?: ((diagnostic: HostDiagnostic) => void) | undefined; + /** + * Names what the application still has in flight, merged into the details of + * a shutdown-timeout diagnostic. + * + * The Host owns scopes and a deadline; it does not know what a hosted + * service or an operation is called. Called only when the budget is + * exhausted, and never trusted to succeed — an exception here is swallowed + * like any other observability failure. + */ + readonly describeRemaining?: (() => Readonly>) | undefined; } /** @@ -136,6 +162,9 @@ export interface ApplicationHost { * settle while non-cooperative asynchronous work is still pending. */ stop(reason: StopReason): Promise; + + /** What the Host still owns, for leak reports and shutdown diagnostics. */ + inspect(): HostInspection; } /** @@ -160,6 +189,21 @@ export function createApplicationHost(options: ApplicationHostOptions): Applicat let registrations: RegistrationScope | undefined; let resources: ResourceScope | undefined; + /** + * Asks the application what it still has running, tolerating a failure. + * + * Same rule as `emit` below: this exists to explain a timeout, and an + * explanation that could itself fail the stop pipeline would be worse than + * no explanation at all. + */ + const remainingWork = (): Readonly> => { + try { + return options.describeRemaining?.() ?? {}; + } catch { + return {}; + } + }; + const emit = (event: string, details?: Readonly>): void => { const listener = options.onDiagnostic; if (listener === undefined) { @@ -267,15 +311,33 @@ export function createApplicationHost(options: ApplicationHostOptions): Applicat // start's unwinding, the stop hook and resource disposal all share it. A // start hook that ignores its signal must not be able to hold stop() past // the budget. - const deadlineAt = Date.now() + shutdownTimeoutMs; + const startedAt = Date.now(); + const deadlineAt = startedAt + shutdownTimeoutMs; const remainingMs = (): number => Math.max(0, deadlineAt - Date.now()); + /** + * What an exhausted budget reports beyond the phase it stopped in. + * + * "It timed out" leaves the same question open every time: which hosted + * service, which operation, which scope is still holding on. Ids, names + * and counts answer it; arguments, payloads and object references stay + * out, because a diagnostic ends up in whatever log gets pasted into an + * issue. + */ + const timeoutDetails = (phase: string): Readonly> => ({ + phase, + budgetMs: shutdownTimeoutMs, + elapsedMs: Date.now() - startedAt, + ...remainingWork(), + ...(resources === undefined ? {} : { resources: resources.inspect() }), + }); + beginStop(reason); const withBudget = async (phase: string, work: () => Promise): Promise => { const remaining = remainingMs(); if (remaining <= 0) { - emit('application.shutdownTimeout', { phase }); + emit('application.shutdownTimeout', timeoutDetails(phase)); return; } @@ -297,7 +359,7 @@ export function createApplicationHost(options: ApplicationHostOptions): Applicat try { // Past the budget we stop waiting; the pending work is abandoned, not awaited. if ((await Promise.race([settled, timeout])) === 'timeout') { - emit('application.shutdownTimeout', { phase }); + emit('application.shutdownTimeout', timeoutDetails(phase)); } } finally { if (timer !== undefined) { @@ -391,6 +453,14 @@ export function createApplicationHost(options: ApplicationHostOptions): Applicat } }, + inspect(): HostInspection { + return { + state, + registrations: registrations?.inspect(), + resources: resources?.inspect(), + }; + }, + stop(reason: StopReason): Promise { if (stopPromise !== undefined) { return stopPromise; diff --git a/src/foundation/resources/registration-scope.ts b/src/foundation/resources/registration-scope.ts index 56d5e0a..737316e 100644 --- a/src/foundation/resources/registration-scope.ts +++ b/src/foundation/resources/registration-scope.ts @@ -10,6 +10,23 @@ export interface Registration { dispose(): unknown; } +/** + * What a scope is still holding, as plain data. + * + * Exists because a count on its own is not actionable. "Four registrations + * survived shutdown" starts an investigation; "`sample/projects` still holds + * four" ends one. Only names and counts cross this boundary — the entries + * themselves are opaque callbacks, and a diagnostic gets logged and shared. + */ +export interface ScopeInspection { + /** The scope's diagnostic name, including its parent path. */ + readonly name: string; + /** Cleanup entries still held, including anonymous `defer` callbacks. */ + readonly size: number; + /** Attached children, which is where module and operation names appear. */ + readonly children: readonly ScopeInspection[]; +} + /** * Owns registrations that must be released **synchronously**, so that stopping * the host closes ingress immediately: no new command invocation or event @@ -75,6 +92,14 @@ export interface RegistrationScope { * calls after the first are no-ops. */ dispose(): void; + + /** + * Reports what this scope and its attached children still hold. + * + * Read-only and safe at any point in the lifecycle, including after + * disposal, when it reports zero. + */ + inspect(): ScopeInspection; } interface ScopeInternals { @@ -117,6 +142,9 @@ function rejectAsyncDisposal(result: unknown, scopeName: string): void { export function createRegistrationScope(name: string): RegistrationScope { const cleanups: Array<() => void> = []; + // Tracked apart from `cleanups`, which holds opaque callbacks: a child is + // the one entry that can name itself, and naming is the point of `inspect`. + const children: RegistrationScope[] = []; let disposed = false; const scope: RegistrationScope = { @@ -172,11 +200,20 @@ export function createRegistrationScope(name: string): RegistrationScope { return; } childInternals.attached = true; + children.push(child); cleanups.push(() => { child.dispose(); }); }, + inspect(): ScopeInspection { + return { + name, + size: cleanups.length, + children: children.map((child) => child.inspect()), + }; + }, + dispose(): void { if (disposed) { return; @@ -197,6 +234,7 @@ export function createRegistrationScope(name: string): RegistrationScope { } } cleanups.length = 0; + children.length = 0; if (errors.length > 0) { throw new ScopeCleanupError(name, errors); diff --git a/src/foundation/resources/resource-scope.ts b/src/foundation/resources/resource-scope.ts index 8b4db5d..f4d6a6b 100644 --- a/src/foundation/resources/resource-scope.ts +++ b/src/foundation/resources/resource-scope.ts @@ -1,6 +1,6 @@ import { ScopeCleanupError } from '../internal/errors.js'; import { claimRejection, isThenable } from '../internal/thenable.js'; -import type { Registration } from './registration-scope.js'; +import type { Registration, ScopeInspection } from './registration-scope.js'; /** Options for {@link createResourceScope}. */ export interface ResourceScopeOptions { @@ -94,6 +94,13 @@ export interface ResourceScope { * same promise. */ dispose(): Promise; + + /** + * Reports what this scope and its attached children still hold. Safe to call + * while disposal is in progress, which is exactly when a shutdown that ran + * out of budget wants to know. + */ + inspect(): ScopeInspection; } interface ScopeInternals { @@ -113,6 +120,9 @@ const internals = new WeakMap(); */ export function createResourceScope(name: string, options: ResourceScopeOptions): ResourceScope { const cleanups: Array<() => void | Promise> = []; + // Tracked apart from `cleanups`, which holds opaque callbacks: a child is + // the one entry that can name itself, and naming is the point of `inspect`. + const children: ResourceScope[] = []; let disposed = false; let disposePromise: Promise | undefined; @@ -131,6 +141,7 @@ export function createResourceScope(name: string, options: ResourceScopeOptions) } } cleanups.length = 0; + children.length = 0; if (errors.length > 0) { throw new ScopeCleanupError(name, errors); @@ -230,9 +241,18 @@ export function createResourceScope(name: string, options: ResourceScopeOptions) ); } childInternals.attached = true; + children.push(child); cleanups.push(() => child.dispose()); }, + inspect(): ScopeInspection { + return { + name, + size: cleanups.length, + children: children.map((child) => child.inspect()), + }; + }, + dispose(): Promise { if (disposePromise !== undefined) { return disposePromise; diff --git a/src/index.ts b/src/index.ts index 5afd378..6771635 100644 --- a/src/index.ts +++ b/src/index.ts @@ -107,7 +107,11 @@ export type { LogEntry, LogFields, Logger, LogSink } from './foundation/logging/ // For a service, which has no operation to take `context.logger` from. export { Log } from './foundation/logging/token.js'; export type { ResourceScope } from './foundation/resources/resource-scope.js'; -export type { Registration, RegistrationScope } from './foundation/resources/registration-scope.js'; +export type { + Registration, + RegistrationScope, + ScopeInspection, +} from './foundation/resources/registration-scope.js'; // --- Background lifetime and the managed raw-API escape hatch -------------- export type { diff --git a/src/testing/index.ts b/src/testing/index.ts index ab410c5..a173a9e 100644 --- a/src/testing/index.ts +++ b/src/testing/index.ts @@ -44,6 +44,7 @@ export type { export { createTestHost } from './test-host.js'; export type { CreateTestHostOptions, LeakReport, ServiceOverrides, TestHost } from './test-host.js'; +export type { ApplicationInspection } from '../foundation/application/application.js'; // Manifest and source remain separate because VS Code consumes contributions // before activation. This assertion makes source declarations authoritative diff --git a/src/testing/test-host.ts b/src/testing/test-host.ts index dae9e78..fafe092 100644 --- a/src/testing/test-host.ts +++ b/src/testing/test-host.ts @@ -16,7 +16,7 @@ * require the low-level mock or, for authoritative behavior, an Extension Host. */ import { createApplication } from '../foundation/application/application.js'; -import type { Application } from '../foundation/application/application.js'; +import type { Application, ApplicationInspection } from '../foundation/application/application.js'; import type { ApplicationPlan } from '../foundation/application/plan.js'; import type { HostDiagnostic } from '../foundation/hosting/application-host.js'; import { ServiceLifetime } from '../foundation/services/descriptors.js'; @@ -145,6 +145,15 @@ export interface TestHost { stop(): Promise; /** What the framework still owns. Assert this is empty after `stop()`. */ leaks(): LeakReport; + /** + * The same ownership, named rather than counted: the scope trees, the hosted + * services that are up, the operations that have not settled. + * + * `leaks()` answers "did anything survive `stop()`"; this answers "what, and + * whose is it". Reach for it when a leak assertion fails, or to assert that + * a specific module's scope is the one still holding something. + */ + inspect(): ApplicationInspection; } /** Options for {@link createTestHost}. */ @@ -301,5 +310,9 @@ export function createTestHost(options: CreateTestHostOptions): TestHost { commands: commands.registeredIds, }; }, + + inspect(): ApplicationInspection { + return application.inspect(); + }, }; } diff --git a/tests/foundation/application/lifecycle-hardening.test.ts b/tests/foundation/application/lifecycle-hardening.test.ts index 27075df..ebfa11a 100644 --- a/tests/foundation/application/lifecycle-hardening.test.ts +++ b/tests/foundation/application/lifecycle-hardening.test.ts @@ -16,7 +16,9 @@ declare const process: { import { createApplication } from '../../../src/foundation/application/application.js'; import { compileApplication } from '../../../src/foundation/application/plan.js'; +import { defineCommandContract } from '../../../src/foundation/commands/contract.js'; import { createApplicationHost } from '../../../src/foundation/hosting/application-host.js'; +import type { HostDiagnostic } from '../../../src/foundation/hosting/application-host.js'; import { defineModule } from '../../../src/foundation/modules/definition.js'; import { serviceToken } from '../../../src/foundation/services/token.js'; import { createFakeCommands } from '../../../src/testing/fakes/fake-commands.js'; @@ -120,7 +122,7 @@ describe('activation failure with hosted services', () => { return undefined; }); - const events: string[] = []; + const diagnostics: HostDiagnostic[] = []; const app = createApplication({ plan: compileApplication({ name: 'sample', @@ -128,7 +130,7 @@ describe('activation failure with hosted services', () => { shutdown: { timeoutMs: 200 }, }), capabilities: { commands: createFakeCommands(), environment: createFakeEnvironment({}) }, - onDiagnostic: (diagnostic) => events.push(diagnostic.event), + onDiagnostic: (diagnostic) => diagnostics.push(diagnostic), }); const pending = app.activate({ subscriptions: [] }); @@ -136,7 +138,12 @@ describe('activation failure with hosted services', () => { await vi.advanceTimersByTimeAsync(250); await settled; - expect(events).toContain('application.shutdownTimeout'); + const timeout = diagnostics.find( + (diagnostic) => diagnostic.event === 'application.shutdownTimeout' + ); + // Which loop was abandoned matters as much as the fact that one was: a + // count alone leaves the reader to guess which service ignored its signal. + expect(timeout?.details).toMatchObject({ phase: 'background', pending: 1 }); } finally { vi.useRealTimers(); } @@ -398,3 +405,82 @@ describe('sync-only guards claim the discarded rejection', () => { expect(unhandled).toEqual([]); }); }); + +describe('shutdown timeout diagnostics', () => { + const Slow = defineCommandContract({ id: 'sample.slow', title: 'Slow' }); + + it('names the hosted service and the operation still holding the budget', async () => { + vi.useFakeTimers(); + try { + const module = defineModule('sample', (builder): undefined => { + // Ignores its signal, so the stop hook holds the budget to the end. + builder.commands.handle(Slow, () => new Promise(() => undefined)); + // Two services, so the report distinguishes the one being stopped from + // the one that has not been asked yet. Stop order is reverse, so the + // stuck one goes first and the first one never gets its turn. + builder.hostedServices.add({ id: 'sample.first', stop: () => undefined }); + builder.hostedServices.add({ + id: 'sample.stuck', + stop: () => new Promise(() => undefined), + }); + return undefined; + }); + + const diagnostics: HostDiagnostic[] = []; + const commands = createFakeCommands(); + const app = createApplication({ + plan: compileApplication({ + name: 'sample', + modules: [module], + shutdown: { timeoutMs: 200 }, + }), + capabilities: { commands, environment: createFakeEnvironment({}) }, + onDiagnostic: (diagnostic) => diagnostics.push(diagnostic), + }); + await app.activate({ subscriptions: [] }); + + // Started and never settles: the handler ignores its signal, the way one + // that forgot to check it would. + void commands.execute('sample.slow').catch(() => undefined); + const stopping = app.deactivate(); + await vi.advanceTimersByTimeAsync(250); + await stopping; + + const timeout = diagnostics.find( + (diagnostic) => diagnostic.event === 'application.shutdownTimeout' + ); + expect(timeout?.details).toMatchObject({ + phase: 'stop-hook', + budgetMs: 200, + // `started` is what is still up and untouched; the one inside its own + // `stop` is named separately, because "still running" and "refusing to + // stop" call for different things from whoever reads this. + hostedServices: { started: ['sample.first'], stopping: 'sample.stuck' }, + operations: [{ name: 'sample.slow', kind: 'command' }], + }); + } finally { + vi.useRealTimers(); + } + }); + + it('forgets an operation once it settles', async () => { + const Quick = defineCommandContract({ id: 'sample.quick', title: 'Quick' }); + const module = defineModule('sample', (builder): undefined => { + builder.commands.handle(Quick, () => undefined); + return undefined; + }); + const commands = createFakeCommands(); + const app = createApplication({ + plan: compileApplication({ name: 'sample', modules: [module] }), + capabilities: { commands, environment: createFakeEnvironment({}) }, + }); + await app.activate({ subscriptions: [] }); + + await commands.execute('sample.quick'); + + // Otherwise the tracking map grows for the life of the extension, and a + // shutdown diagnostic would name every command ever run. + expect(app.inspect().operations).toEqual([]); + await app.deactivate(); + }); +}); diff --git a/tests/foundation/hosting/application-host.test.ts b/tests/foundation/hosting/application-host.test.ts index 75586ee..e89e08d 100644 --- a/tests/foundation/hosting/application-host.test.ts +++ b/tests/foundation/hosting/application-host.test.ts @@ -18,6 +18,12 @@ const recorder = (): { events: string[]; onDiagnostic: (d: HostDiagnostic) => vo return { events, onDiagnostic: (diagnostic) => events.push(diagnostic.event) }; }; +/** Keeps whole diagnostics, for the assertions that are about the details. */ +const detailed = (): { entries: HostDiagnostic[]; onDiagnostic: (d: HostDiagnostic) => void } => { + const entries: HostDiagnostic[] = []; + return { entries, onDiagnostic: (diagnostic) => entries.push(diagnostic) }; +}; + afterEach(() => { vi.useRealTimers(); }); @@ -405,6 +411,93 @@ describe('createApplicationHost', () => { expect(events).toContain('application.shutdownTimeout'); expect(host.state).toBe('stopped'); }); + + it('says which phase, how long it waited, and what was still held', async () => { + vi.useFakeTimers(); + const { entries, onDiagnostic } = detailed(); + const host = createApplicationHost({ + name: 'app', + shutdownTimeoutMs: 1_000, + onDiagnostic, + // The Host owns scopes and a deadline; only the application can name a + // hosted service, so that half of the answer is supplied. + describeRemaining: () => ({ hostedServices: { stopping: 'projects.index' } }), + start: ({ resources }) => { + resources.attach(resources.detachedChild('projects')); + }, + stop: () => new Promise(() => undefined), + }); + await host.start(); + + const stopping = host.stop('deactivate'); + await vi.advanceTimersByTimeAsync(1_000); + await stopping; + + const timeout = entries.find((entry) => entry.event === 'application.shutdownTimeout'); + expect(timeout?.details).toMatchObject({ + phase: 'stop-hook', + budgetMs: 1_000, + hostedServices: { stopping: 'projects.index' }, + resources: { name: 'app#resources', children: [{ name: 'app#resources/projects' }] }, + }); + expect(timeout?.details?.['elapsedMs']).toBeGreaterThanOrEqual(1_000); + }); + + it('still stops when describeRemaining throws', async () => { + vi.useFakeTimers(); + const { events, onDiagnostic } = recorder(); + const host = createApplicationHost({ + name: 'app', + shutdownTimeoutMs: 1_000, + onDiagnostic, + describeRemaining: () => { + throw new Error('describe failed'); + }, + stop: () => new Promise(() => undefined), + }); + await host.start(); + + const stopping = host.stop('deactivate'); + await vi.advanceTimersByTimeAsync(1_000); + await stopping; + + // The explanation failed; the stop pipeline it was explaining did not. + expect(events).toContain('application.shutdownTimeout'); + expect(host.state).toBe('stopped'); + }); + }); + + describe('inspect', () => { + it('reports the scope tree, and nothing before start', async () => { + const host = createApplicationHost({ + name: 'app', + start: ({ registrations }) => { + registrations.own({ dispose: () => undefined }); + registrations.attach(registrations.detachedChild('projects')); + }, + }); + + expect(host.inspect()).toEqual({ + state: 'new', + registrations: undefined, + resources: undefined, + }); + + await host.start(); + + expect(host.inspect()).toMatchObject({ + state: 'running', + registrations: { + name: 'app#registrations', + size: 2, + children: [{ name: 'app#registrations/projects', size: 0, children: [] }], + }, + }); + + await host.stop('manual'); + + expect(host.inspect()).toMatchObject({ state: 'stopped', registrations: { size: 0 } }); + }); }); it('survives a diagnostic listener that throws', async () => { diff --git a/tests/foundation/resources/registration-scope.test.ts b/tests/foundation/resources/registration-scope.test.ts index 784c599..2053afc 100644 --- a/tests/foundation/resources/registration-scope.test.ts +++ b/tests/foundation/resources/registration-scope.test.ts @@ -251,3 +251,34 @@ describe('createRegistrationScope', () => { }); }); }); + +describe('inspect', () => { + it('names the scope, counts its entries and walks its attached children', () => { + const root = createRegistrationScope('extension'); + root.own({ dispose: () => undefined }); + const child = root.detachedChild('projects'); + child.own({ dispose: () => undefined }); + child.own({ dispose: () => undefined }); + + // Detached: the child is not part of the parent's picture until it commits. + expect(root.inspect()).toEqual({ name: 'extension', size: 1, children: [] }); + + root.attach(child); + + expect(root.inspect()).toEqual({ + name: 'extension', + // The attach itself is an entry, alongside the registration above. + size: 2, + children: [{ name: 'extension/projects', size: 2, children: [] }], + }); + }); + + it('reports nothing once disposed', () => { + const root = createRegistrationScope('extension'); + root.attach(root.detachedChild('projects')); + + root.dispose(); + + expect(root.inspect()).toEqual({ name: 'extension', size: 0, children: [] }); + }); +}); diff --git a/tests/foundation/resources/resource-scope.test.ts b/tests/foundation/resources/resource-scope.test.ts index 0719830..aa4efdf 100644 --- a/tests/foundation/resources/resource-scope.test.ts +++ b/tests/foundation/resources/resource-scope.test.ts @@ -293,3 +293,33 @@ describe('createResourceScope', () => { }); }); }); + +describe('inspect', () => { + const scopeOptions = { signal: new AbortController().signal }; + + it('names the scope, counts its entries and walks its attached children', () => { + const root = createResourceScope('extension', scopeOptions); + root.deferAsync(() => Promise.resolve()); + const child = root.detachedChild('projects'); + child.defer(() => undefined); + + expect(root.inspect()).toEqual({ name: 'extension', size: 1, children: [] }); + + root.attach(child); + + expect(root.inspect()).toEqual({ + name: 'extension', + size: 2, + children: [{ name: 'extension/projects', size: 1, children: [] }], + }); + }); + + it('reports nothing once disposed', async () => { + const root = createResourceScope('extension', scopeOptions); + root.attach(root.detachedChild('projects')); + + await root.dispose(); + + expect(root.inspect()).toEqual({ name: 'extension', size: 0, children: [] }); + }); +}); diff --git a/tests/testing/test-host.test.ts b/tests/testing/test-host.test.ts index e8948d1..6169547 100644 --- a/tests/testing/test-host.test.ts +++ b/tests/testing/test-host.test.ts @@ -67,7 +67,19 @@ describe('createTestHost', () => { await host.stop(); + // Exactly these three fields: consumers assert on the whole object, and + // the guide tells them to, so the shape is part of the contract. expect(host.leaks()).toEqual({ registrations: 0, resources: 0, commands: [] }); + // The same ownership, named. A zero count beside a non-empty scope would + // mean one of the two is reading something other than what it claims. + expect(host.inspect()).toMatchObject({ + state: 'stopped', + registrations: { size: 0, children: [] }, + resources: { size: 0, children: [] }, + hostedServices: [], + operations: [], + backgroundTasks: 0, + }); }); it('replaces a singleton without touching the plan', async () => {