From 04d076668bb6024918f64eba8805031ef5b82646 Mon Sep 17 00:00:00 2001 From: Jack Zhuang <277994282+os-zhuang@users.noreply.github.com> Date: Fri, 17 Jul 2026 19:41:49 +0800 Subject: [PATCH] fix(core): ObjectLogger file destination silently no-ops in ESM builds (#3110) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `openFileStream` loaded `fs` with a lazy `require()` to keep the browser-safe logger entry out of the `fs` bundle graph. esbuild rewrites that to its `__require` shim in the ESM output, which throws `Dynamic require of "fs" is not supported`, and the surrounding bare `catch {}` swallowed it. The workspace is `type: module`, so every Node ESM consumer — `os serve`, `os dev` — silently got no file logging at all, while the CJS build kept working. Load the builtin through `process.getBuiltinModule` instead: a plain method call, opaque to bundlers, working in both module systems, still behind the existing `typeof process` guard. `require` stays as a fallback for Node < 20.16, which predates it. A `file` destination that cannot be opened now reports on stderr rather than vanishing — the silence is what kept this hidden. Opening the destination for the first time also exposed three faults that were unreachable while it never opened: - `child()` passed `file` to the constructor, which opens eagerly, so every child opened a second stream to the same path and immediately orphaned it — despite the "no double-open" comment. - Destroying a child ended the stream its parent and siblings were still writing to. - `createWriteStream` reports open failures asynchronously; an 'error' event with no listener is an uncaught exception, so an unwritable log path would have taken the host process down. The regression test bundles the entry with esbuild and spawns a real `node`, because under vitest the source runs through vite-node where `require` IS defined — an in-process test of this code passes against the broken version. Co-Authored-By: Claude Opus 4.8 --- .changeset/logger-esm-file-destination.md | 7 ++ packages/core/package.json | 1 + packages/core/src/logger-esm-file.test.ts | 119 ++++++++++++++++++++++ packages/core/src/logger.ts | 105 ++++++++++++++++--- pnpm-lock.yaml | 3 + 5 files changed, 222 insertions(+), 13 deletions(-) create mode 100644 .changeset/logger-esm-file-destination.md create mode 100644 packages/core/src/logger-esm-file.test.ts diff --git a/.changeset/logger-esm-file-destination.md b/.changeset/logger-esm-file-destination.md new file mode 100644 index 0000000000..0ae3935b2c --- /dev/null +++ b/.changeset/logger-esm-file-destination.md @@ -0,0 +1,7 @@ +--- +"@objectstack/core": patch +--- + +**`createLogger({ file })` now actually writes the file under ESM.** `openFileStream` loaded `fs` with a lazy `require()` to keep the browser-safe logger entry out of the `fs` bundle graph; esbuild rewrites that to its `__require` shim in the ESM output, which throws `Dynamic require of "fs" is not supported`, and a bare `catch {}` swallowed it. Since the workspace is `type: module`, every Node ESM consumer — `os serve`, `os dev` — silently got no file logging at all, while the CJS build kept working. The builtin now loads via `process.getBuiltinModule` (opaque to bundlers, works in both module systems, with a `require` fallback for Node < 20.16), and a `file` destination that cannot be opened reports itself on stderr instead of disappearing. + +Turning the destination back on also fixed three faults that were unreachable while it never opened: `child()` opened a second stream per child and orphaned it, destroying a child logger closed the stream its parent and siblings were still writing to, and an async open failure (e.g. an unwritable path) hit an `'error'` event with no listener and took the process down. diff --git a/packages/core/package.json b/packages/core/package.json index 89d89bad70..090c37b0aa 100644 --- a/packages/core/package.json +++ b/packages/core/package.json @@ -25,6 +25,7 @@ }, "devDependencies": { "@types/node": "^26.1.1", + "esbuild": "^0.28.1", "typescript": "^6.0.3", "vitest": "^4.1.10" }, diff --git a/packages/core/src/logger-esm-file.test.ts b/packages/core/src/logger-esm-file.test.ts new file mode 100644 index 0000000000..3a49370f38 --- /dev/null +++ b/packages/core/src/logger-esm-file.test.ts @@ -0,0 +1,119 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. +// +// Regression: `createLogger({ file })` must actually write the file when the +// logger is consumed as ESM (#3110). `openFileStream` used to `require('fs')` +// to keep `fs` out of the browser bundle graph; esbuild rewrites that to its +// `__require` shim in the ESM output, which throws `Dynamic require of "fs" is +// not supported`, and the surrounding `catch {}` swallowed it. Every Node ESM +// consumer — `os serve`, `os dev`, the whole workspace is `type: module` — +// silently got no file logging, while the CJS build kept working. +// +// These have to bundle and spawn a real `node`: under vitest the source runs +// through vite-node, where `require` IS defined, so an in-process test of this +// code passes against the broken version. Exercising the shipped shape is the +// only thing that fails on the bug. + +import { describe, it, expect, beforeAll, afterAll } from 'vitest'; +import { build } from 'esbuild'; +import { spawnSync } from 'node:child_process'; +import { mkdtempSync, rmSync, existsSync, readFileSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { fileURLToPath, pathToFileURL } from 'node:url'; + +const here = fileURLToPath(new URL('.', import.meta.url)); + +let workdir: string; +let bundleHref: string; +let bundlePath: string; + +// Mirrors the ESM half of tsup.config.ts — the logger entry, bundled, es2020. +// Keep in sync if that config's format/target change. +beforeAll(async () => { + workdir = mkdtempSync(join(tmpdir(), 'os-logger-esm-')); + bundlePath = join(workdir, 'logger.mjs'); + await build({ + entryPoints: [join(here, 'logger.ts')], + outfile: bundlePath, + bundle: true, + format: 'esm', + platform: 'node', + target: 'es2020', + }); + bundleHref = pathToFileURL(bundlePath).href; +}, 30_000); + +afterAll(() => { + rmSync(workdir, { recursive: true, force: true }); +}); + +/** Run `body` as real Node ESM with `createLogger` imported from the bundle. */ +function runEsm(body: string) { + const source = `import { createLogger } from ${JSON.stringify(bundleHref)};\n${body}`; + const result = spawnSync(process.execPath, ['--input-type=module', '-e', source], { + cwd: workdir, + encoding: 'utf8', + }); + return { status: result.status, stdout: result.stdout ?? '', stderr: result.stderr ?? '' }; +} + +describe('ObjectLogger file destination under ESM (#3110)', () => { + it('writes the configured file when imported as ESM', () => { + const logfile = join(workdir, 'app.log'); + const run = runEsm(` +const l = createLogger({ format: 'text', file: ${JSON.stringify(logfile)} }); +l.info('hello from esm'); +await l.destroy(); +`); + + expect(run.stderr).toBe(''); + expect(run.status).toBe(0); + expect(existsSync(logfile)).toBe(true); + expect(readFileSync(logfile, 'utf8')).toContain('hello from esm'); + }); + + it('does not reach esbuild\'s dynamic-require shim to load fs', () => { + // The precise failure mode, asserted on the artifact so the diagnosis + // stays attached to the test if a lazy `require` is ever reintroduced. + const code = readFileSync(bundlePath, 'utf8'); + expect(code.slice(code.indexOf('openFileStream'))).not.toMatch(/__require\(["'](?:node:)?fs["']\)/); + }); + + it('reports an unusable file path on stderr instead of dropping it silently', () => { + // A directory is never a valid log file. `createWriteStream` reports + // EISDIR asynchronously, so this also covers the 'error' event: with no + // listener it would be an uncaught exception and a non-zero exit. + const run = runEsm(` +const l = createLogger({ format: 'text', file: ${JSON.stringify(workdir)} }); +l.info('console logging must continue'); +await l.destroy(); +await new Promise((r) => setTimeout(r, 50)); +console.log('SURVIVED'); +`); + + expect(run.status).toBe(0); + expect(run.stdout).toContain('console logging must continue'); + expect(run.stdout).toContain('SURVIVED'); + expect(run.stderr).toContain('file logging disabled'); + }); + + it('keeps the shared stream alive when a child logger is destroyed', () => { + // `child()` shares the opener's stream, so a child's teardown must not + // end it: the parent's next write would hit 'write after end' — fatal, + // and unreachable until file logging actually opened under ESM. + const logfile = join(workdir, 'child.log'); + const run = runEsm(` +const parent = createLogger({ format: 'text', file: ${JSON.stringify(logfile)} }); +const child = parent.child({ requestId: 'r1' }); +child.info('from child'); +await child.destroy(); +parent.info('from parent after child teardown'); +await parent.destroy(); +`); + + expect(run.status).toBe(0); + const contents = readFileSync(logfile, 'utf8'); + expect(contents).toContain('from child'); + expect(contents).toContain('from parent after child teardown'); + }); +}); diff --git a/packages/core/src/logger.ts b/packages/core/src/logger.ts index cd1646ffd2..adc843bfe4 100644 --- a/packages/core/src/logger.ts +++ b/packages/core/src/logger.ts @@ -44,6 +44,39 @@ function colorEnabled(stream: { isTTY?: boolean } | undefined): boolean { return Boolean(stream?.isTTY); } +/** + * Resolve a Node builtin without putting it in this module's import graph. + * + * This entry is deliberately browser-safe — `@objectstack/client` bundles it — + * so `fs`/`path` must never be imported statically. A lazy `require()` used to + * meet that bar, but esbuild rewrites it to the `__require` shim in the ESM + * output, which throws `Dynamic require of "fs" is not supported`. Every Node + * ESM consumer (`os serve`, `os dev`) therefore lost file logging (#3110). + * `process.getBuiltinModule` is a plain method call — opaque to bundlers — and + * works in both module systems. + */ +function loadNodeBuiltin(id: string): T | undefined { + if (typeof process === 'undefined') return undefined; + + const getBuiltinModule = (process as { getBuiltinModule?: (id: string) => unknown }).getBuiltinModule; + if (typeof getBuiltinModule === 'function') { + try { + return getBuiltinModule.call(process, `node:${id}`) as T; + } catch { + return undefined; + } + } + + // Node < 20.16 / < 22.3 predates `getBuiltinModule`. Real `require` still + // resolves in the CJS build; in the ESM build this is the shim that throws, + // which the caller now reports rather than swallows. + try { + return require(id) as T; + } catch { + return undefined; + } +} + export class ObjectLogger implements Logger { private config: Required> & { file?: string; @@ -52,6 +85,9 @@ export class ObjectLogger implements Logger { }; private bindings: Record; private fileStream?: any; + /** Only the logger that opened the stream may close it — children share it. */ + private ownsFileStream = false; + private fileLoggingDisabled = false; constructor(config: Partial = {}, bindings: Record = {}) { this.config = { @@ -71,14 +107,48 @@ export class ObjectLogger implements Logger { } private openFileStream(path: string) { + const fs = loadNodeBuiltin('fs'); + const nodePath = loadNodeBuiltin('path'); + if (!fs || !nodePath) { + this.disableFileLogging(path, 'no filesystem access in this runtime'); + return; + } + try { - // Lazy require to avoid bundling issues - const fs = require('fs'); - const dir = require('path').dirname(path); - fs.mkdirSync(dir, { recursive: true }); - this.fileStream = fs.createWriteStream(path, { flags: 'a' }); - } catch { - // ignore — file logging is optional + fs.mkdirSync(nodePath.dirname(path), { recursive: true }); + const stream = fs.createWriteStream(path, { flags: 'a' }); + // `createWriteStream` reports open failures (EACCES, EISDIR, …) + // asynchronously. An 'error' event with no listener is fatal to the + // process, so file logging must degrade here rather than take the + // host down. + stream.on('error', (err: Error) => this.disableFileLogging(path, err.message)); + this.fileStream = stream; + this.ownsFileStream = true; + } catch (err) { + this.disableFileLogging(path, (err as Error).message); + } + } + + /** + * Report — once — that an explicitly configured `file` destination is not + * being written, and stop trying. + * + * Deliberately not routed through `write()`: this says the logger cannot + * honour its own config, so `level` must not filter it. The bare `catch {}` + * this replaces is exactly how #3110 stayed hidden. + */ + private disableFileLogging(path: string, reason: string) { + this.fileStream = undefined; + this.ownsFileStream = false; + if (this.fileLoggingDisabled) return; + this.fileLoggingDisabled = true; + + const label = this.config.name ? `[${this.config.name}] ` : ''; + const notice = `${label}logger: file logging disabled — cannot write to ${path}: ${reason}`; + if (typeof process !== 'undefined' && (process as any).stderr) { + (process as any).stderr.write(notice + '\n'); + } else if (typeof console !== 'undefined') { + console.warn(notice); } } @@ -197,8 +267,12 @@ export class ObjectLogger implements Logger { } child(context: Record): ObjectLogger { - const child = new ObjectLogger(this.config, { ...this.bindings, ...context }); - // Share the file stream — no double-open + // Construct without `file`, then share the parent's stream: the + // constructor opens eagerly, so passing `file` through would open a + // second stream per child and immediately orphan it. That leak was + // unreachable while #3110 kept the ESM open path dead. + const child = new ObjectLogger({ ...this.config, file: undefined }, { ...this.bindings, ...context }); + child.config.file = this.config.file; child.fileStream = this.fileStream; return child; } @@ -208,10 +282,15 @@ export class ObjectLogger implements Logger { } async destroy(): Promise { - if (this.fileStream) { - await new Promise((resolve) => this.fileStream.end(resolve)); - this.fileStream = undefined; - } + const stream = this.fileStream; + this.fileStream = undefined; + // Children share the opener's stream; if they closed it too, one child's + // teardown would end file logging for the parent and every sibling, + // whose writes then land on a closed stream and only trip the 'error' + // handler above. + if (!stream || !this.ownsFileStream) return; + this.ownsFileStream = false; + await new Promise((resolve) => stream.end(resolve)); } } diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index 0f41c51876..b7a88a0ae6 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -735,6 +735,9 @@ importers: '@types/node': specifier: ^26.1.1 version: 26.1.1 + esbuild: + specifier: '>=0.28.1' + version: 0.28.1 typescript: specifier: ^6.0.3 version: 6.0.3