Skip to content

Commit f30f045

Browse files
committed
Merge remote-tracking branch 'origin/main' into claude/issue-4834-plugin-runtime-family-retire
2 parents 8f3eb49 + a2ebea2 commit f30f045

8 files changed

Lines changed: 838 additions & 49 deletions
Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,33 @@
1+
---
2+
'@objectstack/core': patch
3+
---
4+
5+
fix(core): 插件 init/start 的超时守卫定时器在 race 结束时被清除,进程不再空转 `startupTimeout` (#4813)
6+
7+
`ObjectKernel.initPluginWithTimeout()` / `startPluginWithTimeout()` 各自 `setTimeout` armed
8+
一根超时守卫,然后**把它扔了**:插件赢下 race 之后,那根定时器既没 `clearTimeout` 也没
9+
`unref()`,带着 ref 一直挂到 `startupTimeout` 走完。于是每个进程在活干完之后还要空转整整
10+
一个 `startupTimeout` —— `ObjectQLPlugin` 是 120 秒。
11+
12+
实测(`examples/app-crm`,同一条 `migrate recorded-by --json`,同一个构建链,唯一差别是本
13+
改动):
14+
15+
| | 墙钟 |
16+
|:--|:--|
17+
| 修复前 | 122.4s |
18+
| 修复后 | 3.1s |
19+
20+
JSON 与 `✅ Graceful shutdown complete` 两次都在 ~3 秒出现 —— 后面那 119 秒纯粹是 8 根
21+
孤儿定时器(4 个 init + 4 个 start)钉着事件循环。`os serve` 里同样漏,只是那里进程本来
22+
就长命,看不出来。
23+
24+
**为什么是 `clearTimeout` 而不是 `unref()`** 隔壁 `shutdown()` 的守卫用的是 `unref()`,
25+
但那个写法在这里是错的,而且不是风格问题:`unref()` 让定时器不再钉住事件循环,**同时也
26+
让它不再是一个守卫** —— 若 hook 永不 settle 且没有别的东西撑着事件循环,Node 会在定时器
27+
触发之前直接退出,超时被**静默吞掉**,谁也不会收到那个 error。守卫必须在 race 未决期间
28+
保持 ref'd,在 race 落定的那一刻被回收,这正是 `finally { clearTimeout(guard) }` 表达的
29+
语义。两个守卫合并为一个私有 helper `raceStartupTimeout()`,措辞与理由写在它的 doc
30+
comment 里。
31+
32+
`startupTimeout` 的取值一个都没动 —— 慢启动的插件需要那个上限,问题从来不在时长,而在
33+
没人回收。
Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
---
2+
'@objectstack/spec': patch
3+
---
4+
5+
Re-measure the #4001 unknown-key strictness ledger, and fix the instrument that was measuring it.
6+
7+
No schema changed posture in this change — it is the measurement step the
8+
2026-08-03 ruling asked for before the remaining batches are cut.
9+
10+
**The site counter now reads the AST instead of matching source text**, because
11+
the textual method was wrong in both directions at once. It counted
12+
`z.object({ … })` written inside JSDoc prose (`ui/action.zod.ts` declared 9 sites
13+
and has 8), and it missed both the prettier-wrapped `z\n .object({` form
14+
(`ui/chart.zod.ts`, 6 → 7) and `z.looseObject(` (`data/field-value.zod.ts`,
15+
1 → 2). On `ui/` the two errors cancelled exactly, so a correct section total sat
16+
over two wrong rows.
17+
18+
The worst case was `automation/time-relative-trigger.zod.ts`: its only site is
19+
written wrapped, so it counted **zero** — and a zero-site file is deliberately
20+
skipped by the coverage walk, so an authorable schema stayed outside the ledger
21+
while the gate printed "no undeclared schema files". It is now classified.
22+
23+
**`check:strictness-ledger` gained a remaining-strip-site map** — per file, how
24+
many object sites still silently discard unknown keys, which is the number batch
25+
plans are actually scheduled against and which nothing measured before. It is
26+
gated in both directions: a file with strip sites must have a row, and a row
27+
whose file reaches zero strip sites fails, so a closed file drops out of the
28+
worklist rather than outliving it.

docs/audits/2026-07-unknown-key-strictness-ledger.md

Lines changed: 191 additions & 9 deletions
Large diffs are not rendered by default.

packages/core/src/kernel.test.ts

Lines changed: 128 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
import { describe, it, expect, beforeEach } from 'vitest';
1+
import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest';
22
import { ObjectKernel } from './kernel';
33
import { ServiceLifecycle, PluginMetadata } from './plugin-loader';
44
import type { Plugin } from './types';
@@ -231,6 +231,133 @@ describe('ObjectKernel', () => {
231231
});
232232
});
233233

234+
// #4813 — the guard timer must not outlive the race it guards.
235+
//
236+
// These tests are about the *process*, not about the source: asserting
237+
// "kernel.ts calls clearTimeout" would be a tautology that any refactor
238+
// could satisfy while still pinning the event loop. What is asserted here
239+
// is the observable consequence — after the work is done, nothing the
240+
// guards armed is still holding the loop open.
241+
describe('Startup timeout guards do not outlive the race (#4813)', () => {
242+
/**
243+
* Ref'd `Timeout` handles — `getActiveResourcesInfo()` reports only
244+
* resources that are *currently keeping the event loop alive*, which
245+
* is precisely the property that made `os migrate` hang ~120s after
246+
* printing `✅ Graceful shutdown complete`.
247+
*/
248+
const refdTimers = () =>
249+
process.getActiveResourcesInfo().filter((r) => r === 'Timeout').length;
250+
251+
it('leaves no ref\'d timer behind after the plugin wins the race', async () => {
252+
const plugin: PluginMetadata = {
253+
name: 'fast-plugin-long-guard',
254+
version: '1.0.0',
255+
init: async () => {},
256+
start: async () => {},
257+
// The real value that hung one-shot CLI processes: ObjectQLPlugin.
258+
startupTimeout: 120_000,
259+
};
260+
261+
await kernel.use(plugin);
262+
263+
const before = refdTimers();
264+
await kernel.bootstrap();
265+
const after = refdTimers();
266+
267+
// Two guards were armed (init + start) and both lost their race.
268+
// While either is still ref'd the process cannot exit for up to
269+
// `startupTimeout` — 120s of idling after a 3s job.
270+
expect(after).toBe(before);
271+
272+
await kernel.shutdown();
273+
});
274+
275+
it('reclaims one guard per lifecycle hook, for every plugin', async () => {
276+
const makePlugin = (n: number): PluginMetadata => ({
277+
name: `guarded-plugin-${n}`,
278+
version: '1.0.0',
279+
init: async () => {},
280+
start: async () => {},
281+
startupTimeout: 120_000,
282+
});
283+
284+
for (let n = 0; n < 4; n++) {
285+
await kernel.use(makePlugin(n));
286+
}
287+
288+
const before = refdTimers();
289+
await kernel.bootstrap();
290+
291+
// The issue's probe caught exactly this shape: 8 ref'd Timeouts
292+
// for 4 plugins (4 init + 4 start). The count must not scale with
293+
// the plugin list — it must not grow at all.
294+
expect(refdTimers()).toBe(before);
295+
296+
await kernel.shutdown();
297+
});
298+
299+
it('still fires the guard when the plugin loses the race', async () => {
300+
// The companion assertion to the two above: reclaiming the guard
301+
// must not disarm it. `unref()` would satisfy "no ref'd timer" by
302+
// detaching the guard from the loop — and a process with nothing
303+
// else to run then exits *silently* instead of reporting the
304+
// timeout. Clearing on settle keeps the guard armed exactly while
305+
// the race is undecided.
306+
const plugin: PluginMetadata = {
307+
name: 'hanging-plugin',
308+
version: '1.0.0',
309+
init: async () => {
310+
await new Promise((resolve) => setTimeout(resolve, 5000));
311+
},
312+
startupTimeout: 50,
313+
};
314+
315+
await kernel.use(plugin);
316+
317+
await expect(kernel.bootstrap()).rejects.toThrow(
318+
'Plugin hanging-plugin init timeout after 50ms'
319+
);
320+
}, 1000);
321+
});
322+
323+
describe('Startup timeout guards under fake timers (#4813)', () => {
324+
beforeEach(() => {
325+
vi.useFakeTimers();
326+
});
327+
328+
afterEach(() => {
329+
vi.useRealTimers();
330+
});
331+
332+
it('schedules no pending timer once bootstrap has settled', async () => {
333+
const kernelWithFakeTimers = new ObjectKernel({
334+
logger: { level: 'error' },
335+
gracefulShutdown: false,
336+
skipSystemValidation: true,
337+
});
338+
339+
const plugin: PluginMetadata = {
340+
name: 'fake-timer-plugin',
341+
version: '1.0.0',
342+
init: async () => {},
343+
start: async () => {},
344+
startupTimeout: 120_000,
345+
};
346+
347+
await kernelWithFakeTimers.use(plugin);
348+
349+
const before = vi.getTimerCount();
350+
await kernelWithFakeTimers.bootstrap();
351+
352+
// Unlike `getActiveResourcesInfo()`, the fake-timer count includes
353+
// unref'd timers — so this one distinguishes "the guard was
354+
// reclaimed" from "the guard was merely detached from the loop".
355+
expect(vi.getTimerCount()).toBe(before);
356+
357+
await kernelWithFakeTimers.shutdown();
358+
});
359+
});
360+
234361
describe('Startup Failure Rollback', () => {
235362
it('should rollback started plugins on failure', async () => {
236363
let plugin1Destroyed = false;

packages/core/src/kernel.ts

Lines changed: 53 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -541,19 +541,59 @@ export class ObjectKernel {
541541

542542
this.currentlyInitializing = plugin.name;
543543
try {
544-
const initPromise = plugin.init(this.context);
545-
const timeoutPromise = new Promise<void>((_, reject) => {
546-
setTimeout(() => {
547-
reject(new Error(`Plugin ${plugin.name} init timeout after ${timeout}ms`));
548-
}, timeout);
549-
});
550-
551-
await Promise.race([initPromise, timeoutPromise]);
544+
await this.raceStartupTimeout(
545+
plugin.init(this.context),
546+
timeout,
547+
`Plugin ${plugin.name} init timeout after ${timeout}ms`
548+
);
552549
} finally {
553550
this.currentlyInitializing = undefined;
554551
}
555552
}
556553

554+
/**
555+
* Race a plugin lifecycle hook against its startup-timeout guard, and
556+
* reclaim the guard the moment the race settles (#4813).
557+
*
558+
* The guard used to be armed and then abandoned: when the plugin won the
559+
* race, its `setTimeout` stayed ref'd in the event loop for the full
560+
* `startupTimeout`, so every process idled that long after its work was
561+
* done. One `os migrate` finished in 3s and then sat for 120s
562+
* (`ObjectQLPlugin.startupTimeout`), held open by 8 orphaned guards — one
563+
* per init plus one per start.
564+
*
565+
* Clearing on settle rather than `unref()`-ing at arm time is deliberate.
566+
* An unref'd guard also stops pinning the loop, but it stops being a guard
567+
* as well: if the hook never settles and nothing else keeps the loop alive,
568+
* Node exits before the timer can fire and the timeout is never reported.
569+
* The guard has to stay ref'd exactly as long as the race is undecided,
570+
* which is what `clearTimeout` in a `finally` expresses.
571+
*
572+
* `operation` is widened to `T | PromiseLike<T>` because the Plugin
573+
* contract permits a synchronous hook (`init`/`start` return
574+
* `void | Promise<void>`); such a hook wins the race immediately and the
575+
* guard is reclaimed on the same turn.
576+
*/
577+
private async raceStartupTimeout<T>(
578+
operation: T | PromiseLike<T>,
579+
timeout: number,
580+
message: string
581+
): Promise<T> {
582+
let guard: ReturnType<typeof setTimeout> | undefined;
583+
584+
const timeoutPromise = new Promise<never>((_, reject) => {
585+
guard = setTimeout(() => {
586+
reject(new Error(message));
587+
}, timeout);
588+
});
589+
590+
try {
591+
return await Promise.race([operation, timeoutPromise]);
592+
} finally {
593+
clearTimeout(guard);
594+
}
595+
}
596+
557597
/**
558598
* Whether a service is resolvable on this kernel right now — direct
559599
* registration or a loader-registered factory. Backs the init-service
@@ -584,15 +624,12 @@ export class ObjectKernel {
584624
this.logger.debug(`Start: ${plugin.name}`, { plugin: plugin.name });
585625

586626
try {
587-
const startPromise = plugin.start(this.context);
588-
const timeoutPromise = new Promise<void>((_, reject) => {
589-
setTimeout(() => {
590-
reject(new Error(`Plugin ${plugin.name} start timeout after ${timeout}ms`));
591-
}, timeout);
592-
});
627+
await this.raceStartupTimeout(
628+
plugin.start(this.context),
629+
timeout,
630+
`Plugin ${plugin.name} start timeout after ${timeout}ms`
631+
);
593632

594-
await Promise.race([startPromise, timeoutPromise]);
595-
596633
const duration = Date.now() - startTime;
597634
this.startedPlugins.add(plugin.name);
598635
this.pluginStartTimes.set(plugin.name, duration);

0 commit comments

Comments
 (0)