Skip to content

Commit e76a4d2

Browse files
killaguclaude
andauthored
fix(egg): reopen logger streams on snapshot restore (#6001)
## Motivation After a V8 startup snapshot is restored, writing logs raised `... log stream had been closed` (e.g. `egg-schedule.log` when the schedule plugin's `didReady` starts). Root cause: `EggApplicationCore.snapshotWillSerialize` closed every logger **and** discarded the `EggLoggers` instance (`#loggers = undefined`), relying on the lazy `loggers` getter to rebuild a *fresh* `EggLoggers` on restore. But plugins such as `@eggjs/schedule` capture an individual logger reference in their boot-hook **constructor** during the load phase (before serialize). The fresh `EggLoggers` left those captured references pointing at the original **closed** `FileTransport`, so writing through them after restore threw. ## Scope `packages/egg` snapshot lifecycle resource rebuild only (no bundler changes). Preserve logger **identity** across the snapshot instead of rebuilding: - `snapshotWillSerialize`: still `logger.close()` each logger (releases the fd and clears the `FileBufferTransport` flush interval) but **keeps** the `EggLoggers` instance. - `snapshotDidDeserialize`: new `#reopenLoggers()` reopens the *same* logger objects in place — `transport.reload()` reopens each `FileTransport` stream, and the `FileBufferTransport` flush interval is restarted (which `close()` clears but `reload()` does not restore). This keeps the `willSerialize` / `didDeserialize` resource pairing complete and also fixes the parallel `onelogger` global-registry staleness. Messenger (recreated) and the `unhandledRejection` listener (re-attached) were already paired; the agent keepalive timer is recreated by the lifecycle resume — no changes needed there. ## Test evidence `packages/egg/test/snapshot.test.ts`: - New regression test emulates a plugin capturing a logger before the snapshot, then asserts the file transport goes writable → closed → writable across serialize/deserialize, that logger **identity is preserved**, that the buffer flush timer is restarted, and that a log written through the captured reference after restore actually reaches the `-web.log` file (poll-read to avoid racing the async stream flush). - Updated the previous "clean up loggers" test to assert instance preservation. `pnpm --filter=egg run test test/snapshot.test.ts` → 11/11 pass. `tsgo --noEmit` clean. (Pre-existing unrelated failures in `test/lib/core/logger.test.ts` are present on `next` without this change.) 🤖 Generated with [Claude Code](https://claude.com/claude-code) <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit * **Bug Fixes** * Improved snapshot restore behavior so logger output continues working after a snapshot is serialized and reloaded. * Preserved existing logger instances across restore to avoid missed or interrupted log writes. * Ensured buffered log transports resume flushing correctly after restore, including continued writing to disk. * **Tests** * Updated snapshot lifecycle tests to verify logger preservation and transport reopening/flush behavior after restore. <!-- end of auto-generated comment: release notes by coderabbit.ai --> Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent a311fee commit e76a4d2

2 files changed

Lines changed: 122 additions & 15 deletions

File tree

packages/egg/src/lib/egg.ts

Lines changed: 43 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -524,34 +524,71 @@ export class EggApplicationCore extends EggCore {
524524

525525
/**
526526
* Clean up non-serializable resources before V8 heap serialization.
527-
* Closes messenger (IPC listeners), loggers (file descriptors),
528-
* and removes the process-level unhandledRejection listener.
527+
* Closes messenger (IPC listeners), logger streams and flush timers
528+
* (file descriptors), and removes the process-level unhandledRejection
529+
* listener.
530+
*
531+
* The `EggLoggers` instance is intentionally kept (not discarded): plugins
532+
* such as `@eggjs/schedule` capture individual logger references during the
533+
* load phase, before serialization. Replacing them with a fresh `EggLoggers`
534+
* on restore would leave those captured references pointing at closed
535+
* streams (`... log stream had been closed`). Instead, `snapshotDidDeserialize`
536+
* reopens these same logger objects in place.
529537
*/
530538
protected snapshotWillSerialize(): void {
531539
this.messenger.close();
532540
if (this.#loggers) {
533541
for (const logger of this.#loggers.values()) {
542+
// close() releases the file descriptor and, for buffered transports,
543+
// clears the flush interval. The objects themselves stay reachable.
534544
logger.close();
535545
}
536-
this.#loggers = undefined;
537546
}
538547
process.removeListener('unhandledRejection', this._unhandledRejectionHandler);
539548
}
540549

541550
/**
542551
* Restore non-serializable resources after V8 heap deserialization.
543-
* Recreates messenger, re-registers the egg-ready listener,
544-
* and re-attaches the process-level unhandledRejection listener.
545-
* Loggers are lazily re-created via the `loggers` getter.
552+
* Recreates messenger, re-registers the egg-ready listener, reopens the
553+
* logger streams closed during serialize, and re-attaches the process-level
554+
* unhandledRejection listener.
546555
*/
547556
protected snapshotDidDeserialize(): void {
548557
(this as { messenger: IMessenger }).messenger = createMessenger(this);
549558
this.messenger.once('egg-ready', () => {
550559
this.lifecycle.triggerServerDidReady();
551560
});
561+
this.#reopenLoggers();
552562
process.on('unhandledRejection', this._unhandledRejectionHandler);
553563
}
554564

565+
/**
566+
* Reopen logger resources that `snapshotWillSerialize` released.
567+
*
568+
* `transport.reload()` reopens each `FileTransport` stream on the existing
569+
* logger objects (so references captured before the snapshot keep working).
570+
* `FileBufferTransport`, however, clears its flush interval in `close()` and
571+
* does not restart it in `reload()`, so buffered logs would never flush after
572+
* restore. Restart that interval explicitly to keep the willSerialize /
573+
* didDeserialize resource pairing complete.
574+
*/
575+
#reopenLoggers(): void {
576+
if (!this.#loggers) return;
577+
for (const logger of this.#loggers.values()) {
578+
for (const transport of logger.values()) {
579+
// No-op for ConsoleTransport; reopens the stream for file transports.
580+
transport.reload();
581+
const bufferTransport = transport as unknown as {
582+
_timer?: NodeJS.Timeout | null;
583+
_createInterval?: () => NodeJS.Timeout;
584+
};
585+
if (typeof bufferTransport._createInterval === 'function' && !bufferTransport._timer) {
586+
bufferTransport._timer = bufferTransport._createInterval();
587+
}
588+
}
589+
}
590+
}
591+
555592
/**
556593
* dump out the config and meta object
557594
* @private

packages/egg/test/snapshot.test.ts

Lines changed: 79 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,5 @@
11
import { strict as assert } from 'node:assert';
2+
import { readFileSync } from 'node:fs';
23
import path from 'node:path';
34

45
import { describe, it, afterEach } from 'vitest';
@@ -119,7 +120,7 @@ describe('test/snapshot.test.ts', () => {
119120
assert.ok(app.messenger.listenerCount('egg-ready') >= 1, 'new messenger should have egg-ready listener');
120121
});
121122

122-
it('should clean up loggers on snapshotWillSerialize', async () => {
123+
it('should keep the same EggLoggers instance across serialize/deserialize', async () => {
123124
app = new Application({
124125
baseDir: demoApp,
125126
mode: 'single',
@@ -128,20 +129,89 @@ describe('test/snapshot.test.ts', () => {
128129
await app.ready();
129130

130131
// Access loggers to force lazy creation
131-
const _loggers = app.loggers;
132-
assert.ok(_loggers, 'loggers should exist');
132+
const loggersBefore = app.loggers;
133+
assert.ok(loggersBefore, 'loggers should exist');
133134

134135
await app.triggerSnapshotWillSerialize();
135136

136-
// After serialize, loggers are cleared (set to undefined internally).
137-
// Accessing loggers again would re-create them lazily.
138-
// We can't directly check the private #loggers field, but we can verify
139-
// that new loggers are created after deserialize.
137+
// The EggLoggers instance is intentionally NOT discarded on serialize:
138+
// plugins capture individual logger references during load, so replacing
139+
// them with a fresh instance would orphan those captured references.
140140
await app.triggerSnapshotDidDeserialize();
141141
await new Promise<void>((resolve) => process.nextTick(resolve));
142142

143-
// After deserialize, loggers should be lazily re-created on access
144-
assert.ok(app.loggers, 'loggers should be lazily re-created');
143+
// Same instance is reused (reopened in place), not lazily re-created.
144+
assert.strictEqual(app.loggers, loggersBefore, 'loggers instance should be preserved');
145+
});
146+
147+
it('should reopen logger streams so captured references keep writing after deserialize', async () => {
148+
app = new Application({
149+
baseDir: demoApp,
150+
mode: 'single',
151+
snapshot: true,
152+
});
153+
await app.ready();
154+
await app.loadFinished;
155+
156+
// Plugins such as @eggjs/schedule grab a logger reference during the load
157+
// phase (in their boot hook constructor) and keep using it afterwards.
158+
// Emulate that: capture the logger up-front, then drive serialize/restore.
159+
const capturedLogger = app.getLogger('logger');
160+
assert.ok(capturedLogger, 'logger should exist');
161+
162+
// Collect the file-backed transports of the captured logger.
163+
const fileTransports: any[] = [...capturedLogger.values()].filter(
164+
(t: any) => t.options && typeof t.options.file === 'string',
165+
);
166+
assert.ok(fileTransports.length > 0, 'logger should have a file transport');
167+
for (const t of fileTransports) {
168+
assert.equal(t.writable, true, 'file transport should be writable before serialize');
169+
}
170+
171+
// Serialize: streams are closed and buffer flush timers cleared.
172+
await app.triggerSnapshotWillSerialize();
173+
for (const t of fileTransports) {
174+
assert.ok(!t.writable, 'file transport should be closed after serialize');
175+
}
176+
177+
// Deserialize: the SAME transports must be reopened (not replaced).
178+
await app.triggerSnapshotDidDeserialize();
179+
await new Promise<void>((resolve) => process.nextTick(resolve));
180+
181+
// Identity is preserved — the captured reference is still the live logger.
182+
assert.strictEqual(app.getLogger('logger'), capturedLogger, 'captured logger reference should stay live');
183+
for (const t of fileTransports) {
184+
assert.equal(t.writable, true, 'file transport should be reopened after deserialize');
185+
// Buffered transports clear their flush interval on close(); it must be
186+
// restarted so buffered logs flush again.
187+
if (typeof t._createInterval === 'function') {
188+
assert.ok(t._timer, 'buffer flush timer should be restarted after deserialize');
189+
}
190+
}
191+
192+
// End-to-end: writing through the captured reference lands on disk
193+
// instead of hitting the "log stream had been closed" path.
194+
// Unique per execution so the assertion can't match a stale line left in
195+
// the demo app's (append-only) log file by an earlier test run.
196+
const marker = `snapshot-restore-marker-${process.pid}-${Date.now()}-${Math.random().toString(36).slice(2)}`;
197+
capturedLogger.info(marker);
198+
for (const t of fileTransports) {
199+
// flush buffered transports immediately so we don't wait for the interval
200+
if (typeof t.flush === 'function') t.flush();
201+
}
202+
const appLog = fileTransports.find((t) => t.options.file.endsWith('-web.log'));
203+
assert.ok(appLog, 'app web log transport should exist');
204+
// flush() issues an async WriteStream.write(); poll until it reaches disk
205+
// so the assertion does not race the libuv threadpool write on slow CI.
206+
let landed = false;
207+
for (let i = 0; i < 100 && !landed; i++) {
208+
if (readFileSync(appLog.options.file, 'utf8').includes(marker)) {
209+
landed = true;
210+
break;
211+
}
212+
await new Promise<void>((resolve) => setTimeout(resolve, 20));
213+
}
214+
assert.ok(landed, 'log written after restore should reach the file');
145215
});
146216

147217
it('should remove unhandledRejection handler on serialize and restore on deserialize', async () => {

0 commit comments

Comments
 (0)