From e4b09e3e5e8db0bf482c78af32b56c579e7ca12a Mon Sep 17 00:00:00 2001 From: errusso Date: Tue, 13 Oct 2026 22:43:45 +0200 Subject: [PATCH 01/11] feat: add structured logging with logger module Replace console.log() calls with structured logger methods (info, warn, error) that provide consistent formatting with log level prefixes. Add support for debug mode to output additional structured data. - create src/logger.ts with Logger class supporting info/warn/error/debug levels - update cli.ts to use logger for all user-facing output - update build.ts to use logger for build status messages --- src/build.ts | 7 ++++--- src/cli.ts | 15 +++++++++------ src/logger.ts | 50 ++++++++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 63 insertions(+), 9 deletions(-) create mode 100644 src/logger.ts diff --git a/src/build.ts b/src/build.ts index 3235349..c3549e1 100644 --- a/src/build.ts +++ b/src/build.ts @@ -4,6 +4,7 @@ import { dirname, extname, join, resolve } from 'node:path'; import { loadProject, type ProjectConfig } from './project.js'; import { createBuildDirectory, ensureZig, runZig } from './toolchain.js'; import { hostImportsSource, readDefSymbols } from './windows-host.js'; +import { logger } from './logger.js'; const require = createRequire(import.meta.url); type NodeApiHeaders = { include_dir: string; def_paths: { node_api_def: string } }; @@ -33,7 +34,7 @@ async function compile(config: ProjectConfig, options: BuildOptions, cleanOnly: const output = join(outputDir, `${config.name}.node`); if (cleanOnly) { await rm(output, { force: true }); - console.log(`Removed ${output}`); + logger.info(`Removed ${output}`); return; } @@ -82,7 +83,7 @@ async function compile(config: ProjectConfig, options: BuildOptions, cleanOnly: await mkdir(dirname(output), { recursive: true }); await runZig(zig, args, options.directory); - console.log(`Addon built: ${output}`); + logger.info(`Addon built: ${output}`); } finally { await rm(temporaryDir, { recursive: true, force: true }); } @@ -91,7 +92,7 @@ async function compile(config: ProjectConfig, options: BuildOptions, cleanOnly: export async function configure(options: BuildOptions): Promise { const config = await loadProject(options.directory, { target: options.target }); await ensureZig(config.zigVersion); - console.log(`Configuration ready: ${config.name} (${config.sources.length} sources)`); + logger.info(`Configuration ready: ${config.name} (${config.sources.length} sources)`); return config; } diff --git a/src/cli.ts b/src/cli.ts index b6e229c..45e7a14 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -3,6 +3,7 @@ import { resolve } from 'node:path'; import { build, clean, configure, type BuildOptions } from './build.js'; import { CliArgumentError, CliCommandError, normalizeError } from './errors.js'; import { ensureZig, listZigVersions, removeZigVersion } from './toolchain.js'; +import { logger } from './logger.js'; const usage = `Marmotta - build tool for Node.js addons with Zig @@ -60,12 +61,14 @@ function parseArgs(argv: string[]): ParsedArgs { async function main(): Promise { const parsed = parseArgs(process.argv.slice(2)); + logger.setDebugMode(parsed.options.debug); + if (parsed.help) { - console.log(usage); + logger.info(usage); return; } if (parsed.command === '--version' || parsed.command === '-v') { - console.log('marmotta 0.6.0'); + logger.info('marmotta 0.6.0'); return; } @@ -85,11 +88,11 @@ async function main(): Promise { break; case 'install': await ensureZig(); - console.log('Zig toolchain is ready.'); + logger.info('Zig toolchain is ready.'); break; case 'list': { const versions = await listZigVersions(); - console.log(versions.length > 0 ? versions.join('\n') : 'No Zig versions installed by Marmotta.'); + logger.info(versions.length > 0 ? versions.join('\n') : 'No Zig versions installed by Marmotta.'); break; } case 'remove': { @@ -98,7 +101,7 @@ async function main(): Promise { throw new CliArgumentError('Specify the Zig version to remove.'); } await removeZigVersion(version); - console.log(`Removed Zig version ${version}.`); + logger.info(`Removed Zig version ${version}.`); break; } default: @@ -108,6 +111,6 @@ async function main(): Promise { main().catch((error: unknown) => { const normalized = normalizeError(error); - console.error(`marmotta [${normalized.code}]: ${normalized.message}`); + logger.error(`marmotta [${normalized.code}]: ${normalized.message}`); process.exitCode = normalized.exitCode; }); diff --git a/src/logger.ts b/src/logger.ts new file mode 100644 index 0000000..064465e --- /dev/null +++ b/src/logger.ts @@ -0,0 +1,50 @@ +export class Logger { + private debugMode: boolean; + + constructor(debugMode: boolean = false) { + this.debugMode = debugMode; + } + + setDebugMode(debugMode: boolean): void { + this.debugMode = debugMode; + } + + info(message: string, data?: unknown): void { + if (message) { + console.log(`[INFO] ${message}`); + if (this.debugMode && data !== undefined) { + console.log(` ${JSON.stringify(data, null, 2)}`); + } + } + } + + warn(message: string, data?: unknown): void { + if (message) { + console.warn(`[WARN] ${message}`); + if (this.debugMode && data !== undefined) { + console.warn(` ${JSON.stringify(data, null, 2)}`); + } + } + } + + error(message: string, data?: unknown): void { + if (message) { + console.error(`[ERROR] ${message}`); + if (this.debugMode && data !== undefined) { + console.error(` ${JSON.stringify(data, null, 2)}`); + } + } + } + + debug(message: string, data?: unknown): void { + if (this.debugMode && message) { + console.log(`[DEBUG] ${message}`); + if (data !== undefined) { + console.log(` ${JSON.stringify(data, null, 2)}`); + } + } + } +} + +// Default logger instance for use throughout the application +export const logger = new Logger(); \ No newline at end of file From 63241657d23b358d7e49edc2d6682d509bdbec62 Mon Sep 17 00:00:00 2001 From: errusso Date: Tue, 13 Oct 2026 22:55:16 +0200 Subject: [PATCH 02/11] feat: add structured logging with logger module Replace console.log() calls with structured logger methods (info, warn, error) that provide consistent formatting with log level prefixes. Add support for debug mode to output additional structured data. - create src/logger.ts with Logger class supporting info/warn/error/debug levels - update cli.ts to use logger for all user-facing output (7 replacements) - update build.ts to use logger for build status messages (4 replacements) --- src/logger.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/logger.ts b/src/logger.ts index 064465e..2a95023 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -47,4 +47,4 @@ export class Logger { } // Default logger instance for use throughout the application -export const logger = new Logger(); \ No newline at end of file +export const logger = new Logger(); From 8ff9350771ed1d689cde129fcf64b0860e3492b7 Mon Sep 17 00:00:00 2001 From: errusso Date: Wed, 14 Oct 2026 01:48:49 +0200 Subject: [PATCH 03/11] fix: ensure debug mode defaults to false when not specified --- src/cli.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/cli.ts b/src/cli.ts index 45e7a14..1b65ea3 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -61,7 +61,7 @@ function parseArgs(argv: string[]): ParsedArgs { async function main(): Promise { const parsed = parseArgs(process.argv.slice(2)); - logger.setDebugMode(parsed.options.debug); + logger.setDebugMode(parsed.options.debug ?? false); if (parsed.help) { logger.info(usage); From cfde4eab096c2af979e3dbbcfd89af4ecfe8e824 Mon Sep 17 00:00:00 2001 From: errusso Date: Wed, 14 Oct 2026 02:09:29 +0200 Subject: [PATCH 04/11] feat: improve structured CLI logging for CI --- README.md | 3 ++ src/build.ts | 3 +- src/cli.ts | 5 ++- src/logger.ts | 96 +++++++++++++++++++++++++++++++++------------ test/cli.test.js | 24 +++++++++++- test/logger.test.js | 72 ++++++++++++++++++++++++++++++++++ 6 files changed, 174 insertions(+), 29 deletions(-) create mode 100644 test/logger.test.js diff --git a/README.md b/README.md index c04e4f4..ed1c331 100644 --- a/README.md +++ b/README.md @@ -174,6 +174,7 @@ Run `marmotta --help` or `npx marmotta --help` for the built-in usage summary. | `-o, --output-dir ` | `build`, `rebuild`, `clean` | Override `outputDir`. Relative paths are resolved from the project directory. | | `--target ` | `build`, `rebuild` | Zig target triple used for cross-compilation. | | `--debug` | `build`, `rebuild` | Compile without optimization and include debug information (`-O0 -g` instead of `-O2`). | +| `--json` | Any command | Emit one valid JSON object per line to stdout (information/debug) or stderr (warning/error), suitable for CI logs. | | `-h, --help` | Any command | Show help. | | `-v, --version` | Top-level command | Show the Marmotta version. | @@ -183,6 +184,8 @@ For example, request a build for ARM64 macOS: npx marmotta build --target aarch64-macos ``` +Use `--json` in CI when another process needs to consume Marmotta's output. Each log entry is a complete JSON Lines record; informational and debug records go to stdout, while warnings and errors go to stderr. + Use a target triple supported by Zig for the intended target. Cross-compilation does not run the resulting addon on the host; load it on a compatible target system. ## Zig toolchain diff --git a/src/build.ts b/src/build.ts index c3549e1..595b49a 100644 --- a/src/build.ts +++ b/src/build.ts @@ -4,7 +4,7 @@ import { dirname, extname, join, resolve } from 'node:path'; import { loadProject, type ProjectConfig } from './project.js'; import { createBuildDirectory, ensureZig, runZig } from './toolchain.js'; import { hostImportsSource, readDefSymbols } from './windows-host.js'; -import { logger } from './logger.js'; +import { logger, type LogFormat } from './logger.js'; const require = createRequire(import.meta.url); type NodeApiHeaders = { include_dir: string; def_paths: { node_api_def: string } }; @@ -15,6 +15,7 @@ export type BuildOptions = { outputDir?: string; target?: string; debug?: boolean; + logFormat?: LogFormat; }; function isCpp(source: string): boolean { diff --git a/src/cli.ts b/src/cli.ts index 1b65ea3..4785141 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -3,7 +3,7 @@ import { resolve } from 'node:path'; import { build, clean, configure, type BuildOptions } from './build.js'; import { CliArgumentError, CliCommandError, normalizeError } from './errors.js'; import { ensureZig, listZigVersions, removeZigVersion } from './toolchain.js'; -import { logger } from './logger.js'; +import { logger, type LogFormat } from './logger.js'; const usage = `Marmotta - build tool for Node.js addons with Zig @@ -23,6 +23,7 @@ Options: -o, --output-dir directory where .node is generated --target Zig target, e.g. aarch64-macos or x86_64-windows --debug compile without optimizations + --json output machine-readable JSON lines -h, --help show this help -v, --version show the version @@ -42,6 +43,7 @@ function parseArgs(argv: string[]): ParsedArgs { const token = tokens[index]; if (token === '-h' || token === '--help') help = true; else if (token === '--debug') options.debug = true; + else if (token === '--json') options.logFormat = 'json'; else if (token === '-C' || token === '--directory' || token === '-o' || token === '--output-dir' || token === '--target') { const value = tokens[index + 1]; if (!value || value.startsWith('-')) { @@ -62,6 +64,7 @@ function parseArgs(argv: string[]): ParsedArgs { async function main(): Promise { const parsed = parseArgs(process.argv.slice(2)); logger.setDebugMode(parsed.options.debug ?? false); + logger.setFormat(parsed.options.logFormat ?? 'text'); if (parsed.help) { logger.info(usage); diff --git a/src/logger.ts b/src/logger.ts index 2a95023..5ea04e9 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -1,48 +1,92 @@ +export type LogFormat = 'text' | 'json'; + +type LogLevel = 'info' | 'warn' | 'error' | 'debug'; + +type LogSink = (line: string) => void; + +export interface LoggerOptions { + debug?: boolean; + format?: LogFormat; + stdout?: LogSink; + stderr?: LogSink; +} + +function formatTextData(data: unknown): string { + try { + const serialized = JSON.stringify(data, null, 2); + return serialized === undefined ? `\n${String(data)}` : `\n${serialized}`; + } catch { + return `\n${String(data)}`; + } +} + +function formatJsonEntry(level: LogLevel, message: string, data?: unknown): string { + const entry: Record = { level, message }; + if (data !== undefined) entry.data = data; + try { + return JSON.stringify(entry); + } catch { + // Keep the record valid even when context contains a circular value. + entry.data = String(data); + return JSON.stringify(entry); + } +} + export class Logger { private debugMode: boolean; + private format: LogFormat; + private stdout: LogSink; + private stderr: LogSink; - constructor(debugMode: boolean = false) { - this.debugMode = debugMode; + constructor(options: LoggerOptions = {}) { + this.debugMode = options.debug ?? false; + this.format = options.format ?? 'text'; + this.stdout = options.stdout ?? ((line) => process.stdout.write(line)); + this.stderr = options.stderr ?? ((line) => process.stderr.write(line)); } setDebugMode(debugMode: boolean): void { this.debugMode = debugMode; } - info(message: string, data?: unknown): void { - if (message) { - console.log(`[INFO] ${message}`); - if (this.debugMode && data !== undefined) { - console.log(` ${JSON.stringify(data, null, 2)}`); - } + setFormat(format: LogFormat): void { + if (format !== 'text' && format !== 'json') { + throw new TypeError(`Unsupported log format: ${String(format)}`); } + this.format = format; + } + + info(message: string, data?: unknown): void { + this.log('info', message, data); } warn(message: string, data?: unknown): void { - if (message) { - console.warn(`[WARN] ${message}`); - if (this.debugMode && data !== undefined) { - console.warn(` ${JSON.stringify(data, null, 2)}`); - } - } + this.log('warn', message, data); } error(message: string, data?: unknown): void { - if (message) { - console.error(`[ERROR] ${message}`); - if (this.debugMode && data !== undefined) { - console.error(` ${JSON.stringify(data, null, 2)}`); - } - } + this.log('error', message, data); } debug(message: string, data?: unknown): void { - if (this.debugMode && message) { - console.log(`[DEBUG] ${message}`); - if (data !== undefined) { - console.log(` ${JSON.stringify(data, null, 2)}`); - } - } + if (!this.debugMode) return; + this.log('debug', message, data); + } + + private log(level: LogLevel, message: string, data?: unknown): void { + if (!message) return; + + const line = this.format === 'json' + ? formatJsonEntry(level, message, data) + : this.formatTextMessage(level, message, data); + const sink = level === 'warn' || level === 'error' ? this.stderr : this.stdout; + sink(line); + } + + private formatTextMessage(level: LogLevel, message: string, data?: unknown): string { + const normalizedMessage = message.replace(/\r?\n/g, ' '); + const line = `[${level.toUpperCase()}] ${normalizedMessage}`; + return this.debugMode && data !== undefined ? `${line}${formatTextData(data)}` : line; } } diff --git a/test/cli.test.js b/test/cli.test.js index 5413117..98b873f 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -260,6 +260,28 @@ NAPI_MODULE_INIT() { } }); +test('supports JSON Lines output for CI consumers', () => { + const help = spawnSync(process.execPath, [cli, '--help', '--json'], { encoding: 'utf8' }); + assert.equal(help.status, 0, help.stderr || help.stdout); + assert.equal(help.stderr.length, 0); + + const entry = JSON.parse(help.stdout); + assert.equal(entry.level, 'info'); + assert.equal(typeof entry.message, 'string'); +}); + +test('reports CLI errors as structured JSON Lines', () => { + const result = spawnSync(process.execPath, [cli, 'unknown-command', '--json'], { + encoding: 'utf8', + }); + assert.equal(result.status, 2); + assert.equal(result.stdout.length, 0); + + const entry = JSON.parse(result.stderr); + assert.equal(entry.level, 'error'); + assert.match(entry.message, /Unknown command/); +}); + test('reports an invalid MARMOTTA_HOME without breaking help', () => { const env = { ...process.env, MARMOTTA_HOME: 'relative/marmotta-home' }; const help = spawnSync(process.execPath, [cli, '--help'], { encoding: 'utf8', env }); @@ -268,5 +290,5 @@ test('reports an invalid MARMOTTA_HOME without breaking help', () => { const list = spawnSync(process.execPath, [cli, 'list'], { encoding: 'utf8', env }); assert.equal(list.status, 2); - assert.match(list.stderr, /^marmotta \[MARMOTTA_HOME_INVALID\]: MARMOTTA_HOME must be an absolute path/); + assert.match(list.stderr, /^\[ERROR\] marmotta \[MARMOTTA_HOME_INVALID\]: MARMOTTA_HOME must be an absolute path/); }); diff --git a/test/logger.test.js b/test/logger.test.js new file mode 100644 index 0000000..5f9110a --- /dev/null +++ b/test/logger.test.js @@ -0,0 +1,72 @@ +import assert from 'node:assert/strict'; +import { test } from 'node:test'; +import { Logger } from '../dist/logger.js'; + +function capture(format = 'json') { + const stdout = []; + const stderr = []; + return { + logger: new Logger({ + debug: true, + format, + stdout: (line) => stdout.push(line), + stderr: (line) => stderr.push(line), + }), + stdout, + stderr, + }; +} + +test('writes structured JSON lines without prefixing the payload', () => { + const { logger, stdout, stderr } = capture(); + + logger.info('build complete', { addon: 'hello.node', target: 'x64-linux' }); + logger.warn('cache miss'); + logger.error('compile failed', { code: 'TOOLCHAIN_COMMAND_FAILED' }); + + assert.deepEqual(JSON.parse(stdout[0]), { + level: 'info', + message: 'build complete', + data: { addon: 'hello.node', target: 'x64-linux' }, + }); + assert.equal(stderr[0], JSON.stringify({ level: 'warn', message: 'cache miss' })); + assert.deepEqual(JSON.parse(stderr[1]), { + level: 'error', + message: 'compile failed', + data: { code: 'TOOLCHAIN_COMMAND_FAILED' }, + }); +}); + +test('keeps text output readable and keeps debug data attached to debug logs', () => { + const { logger, stdout, stderr } = capture('text'); + + logger.info('ready'); + logger.debug('compiler path', '/opt/zig/zig'); + + assert.equal(stdout[0], '[INFO] ready'); + assert.match(stdout[1], /^\[DEBUG\] compiler path\n/); + assert.match(stdout[1], /"\/opt\/zig\/zig"/); + assert.equal(stderr.length, 0); +}); + +test('keeps JSON records valid when context is circular', () => { + const stdout = []; + const logger = new Logger({ format: 'json', stdout: (line) => stdout.push(line) }); + const context = {}; + context.self = context; + + logger.info('context', context); + assert.equal(JSON.parse(stdout[0]).data, '[object Object]'); +}); + +test('debug mode defaults to disabled', () => { + const stdout = []; + const logger = new Logger({ format: 'json', stdout: (line) => stdout.push(line) }); + + logger.debug('hidden'); + assert.equal(stdout.length, 0); + + logger.setDebugMode(true); + logger.debug('visible'); + assert.equal(JSON.parse(stdout[0]).message, 'visible'); +}); From 66305daf7d81fb844ab75e00745b0278b9a16d2f Mon Sep 17 00:00:00 2001 From: errusso Date: Fri, 16 Oct 2026 17:08:49 +0200 Subject: [PATCH 05/11] refactor: back the logger with pino and keep plain text output Replace the hand-rolled serialization with pino, which gives newline- terminated JSON Lines, circular-safe records, and standard level handling while keeping the plain-text output byte-compatible with the console calls it replaced: - text mode writes messages unchanged (no [INFO]/[ERROR] prefixes, multi- line help and list output preserved) and passes data through util.inspect - --json emits {"level":"info","time":...,"message":...} records through pino, with warn/error on stderr, and ignores errors from closed pipes - MARMOTTA_LOG sets the minimum level, decoupling verbosity from --debug - --json is resolved from the raw arguments before parsing and is accepted before or after the command, so argument errors honor the requested format - errors carry code and exitCode as structured data; list emits one record per version in JSON mode - drop the unused logFormat BuildOptions field --- package-lock.json | 131 ++++++++++++++++++++++++++++++++++++++++++++- package.json | 3 +- src/build.ts | 3 +- src/cli.ts | 59 ++++++++++++++------- src/logger.ts | 132 ++++++++++++++++++++++++++++++++-------------- 5 files changed, 266 insertions(+), 62 deletions(-) diff --git a/package-lock.json b/package-lock.json index 601a2bd..4fbfd77 100644 --- a/package-lock.json +++ b/package-lock.json @@ -9,7 +9,8 @@ "version": "0.6.0", "license": "Apache-2.0", "dependencies": { - "node-api-headers": "^1.3.0" + "node-api-headers": "^1.3.0", + "pino": "^10.4.0" }, "bin": { "marmotta": "dist/cli.js" @@ -22,6 +23,12 @@ "node": ">=20" } }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@types/node": { "version": "22.20.4", "resolved": "https://registry.npmjs.org/@types/node/-/node-22.20.4.tgz", @@ -32,12 +39,134 @@ "undici-types": "~6.21.0" } }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/node-api-headers": { "version": "1.9.0", "resolved": "https://registry.npmjs.org/node-api-headers/-/node-api-headers-1.9.0.tgz", "integrity": "sha512-2oNILP4jXwRB4ywnYKjVk1YyJ96n2D4EOVJO6S3oYZ5PtbJrw3Yt9TpAuX3nBLMuzn74rnfGQrv13pS9vC+YiA==", "license": "MIT" }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, + "node_modules/pino": { + "version": "10.4.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.4.0.tgz", + "integrity": "sha512-bk1ZMTwG/Vymx+zPoa28MhNzucFvXJWp3csrSuxuHPSMeUettaCoQ5Jvg07mtC4JGNpcfTwz41oVCnNgBK9+vA==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^1.0.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, + "node_modules/process-warning": { + "version": "5.1.1", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.1.1.tgz", + "integrity": "sha512-oCkNVj4OKnKEcocVBcDfiIugN1/cE6rgfT3nCtzeqZPA8+rIxMaQ0xXzIkGP8Gj2qUaP1UR7uhJ1VD8lUCpzCg==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, + "node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "engines": { + "node": ">= 10.x" + } + }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, "node_modules/typescript": { "version": "5.9.3", "resolved": "https://registry.npmjs.org/typescript/-/typescript-5.9.3.tgz", diff --git a/package.json b/package.json index 249f750..b2b7f19 100644 --- a/package.json +++ b/package.json @@ -50,7 +50,8 @@ "node": ">=20" }, "dependencies": { - "node-api-headers": "^1.3.0" + "node-api-headers": "^1.3.0", + "pino": "^10.4.0" }, "devDependencies": { "@types/node": "^22.15.0", diff --git a/src/build.ts b/src/build.ts index 595b49a..c3549e1 100644 --- a/src/build.ts +++ b/src/build.ts @@ -4,7 +4,7 @@ import { dirname, extname, join, resolve } from 'node:path'; import { loadProject, type ProjectConfig } from './project.js'; import { createBuildDirectory, ensureZig, runZig } from './toolchain.js'; import { hostImportsSource, readDefSymbols } from './windows-host.js'; -import { logger, type LogFormat } from './logger.js'; +import { logger } from './logger.js'; const require = createRequire(import.meta.url); type NodeApiHeaders = { include_dir: string; def_paths: { node_api_def: string } }; @@ -15,7 +15,6 @@ export type BuildOptions = { outputDir?: string; target?: string; debug?: boolean; - logFormat?: LogFormat; }; function isCpp(source: string): boolean { diff --git a/src/cli.ts b/src/cli.ts index 4785141..a01178e 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -3,7 +3,7 @@ import { resolve } from 'node:path'; import { build, clean, configure, type BuildOptions } from './build.js'; import { CliArgumentError, CliCommandError, normalizeError } from './errors.js'; import { ensureZig, listZigVersions, removeZigVersion } from './toolchain.js'; -import { logger, type LogFormat } from './logger.js'; +import { logger } from './logger.js'; const usage = `Marmotta - build tool for Node.js addons with Zig @@ -29,23 +29,27 @@ Options: Environment: MARMOTTA_HOME absolute path that replaces ~/.marmotta as Marmotta's root directory - MARMOTTA_ZIG_DIR absolute path of an existing Zig installation to use instead of downloading Zig`; + MARMOTTA_ZIG_DIR absolute path of an existing Zig installation to use instead of downloading Zig + MARMOTTA_LOG minimum log level: trace, debug, info (default), warn, error, fatal, silent`; -type ParsedArgs = { command: string; positional: string[]; options: BuildOptions; help: boolean }; +type ParsedArgs = { command: string; positional: string[]; options: BuildOptions; help: boolean; version: boolean }; +// Flags are recognized before or after the command, so `marmotta --json build` and +// `marmotta build --json` behave the same. The first positional token names the command. function parseArgs(argv: string[]): ParsedArgs { - const [command = 'help', ...tokens] = argv; const options: BuildOptions = { directory: process.cwd() }; - const positional: string[] = []; - let help = command === 'help' || command === '--help' || command === '-h'; + const positionals: string[] = []; + let help = false; + let version = false; - for (let index = 0; index < tokens.length; index += 1) { - const token = tokens[index]; + for (let index = 0; index < argv.length; index += 1) { + const token = argv[index]; if (token === '-h' || token === '--help') help = true; + else if (token === '-v' || token === '--version') version = true; else if (token === '--debug') options.debug = true; - else if (token === '--json') options.logFormat = 'json'; + else if (token === '--json') { /* the output format is applied before parsing; see main() */ } else if (token === '-C' || token === '--directory' || token === '-o' || token === '--output-dir' || token === '--target') { - const value = tokens[index + 1]; + const value = argv[index + 1]; if (!value || value.startsWith('-')) { throw new CliArgumentError(`Missing value for ${token}`); } @@ -55,22 +59,32 @@ function parseArgs(argv: string[]): ParsedArgs { else options.target = value; } else if (token.startsWith('-')) { throw new CliArgumentError(`Unknown option: ${token}`); - } else positional.push(token); + } else positionals.push(token); } - return { command, positional, options, help }; + const [command, ...rest] = positionals; + return { + command: command ?? 'help', + positional: rest, + options, + // No positional token means help, unless the user asked for --version instead. + help: help || command === 'help' || (command === undefined && !version), + version, + }; } async function main(): Promise { - const parsed = parseArgs(process.argv.slice(2)); - logger.setDebugMode(parsed.options.debug ?? false); - logger.setFormat(parsed.options.logFormat ?? 'text'); + const argv = process.argv.slice(2); + // The output format is resolved from the raw arguments before parsing, so argument-parsing + // failures are reported in the requested format too. + logger.setFormat(argv.includes('--json') ? 'json' : 'text'); + const parsed = parseArgs(argv); if (parsed.help) { logger.info(usage); return; } - if (parsed.command === '--version' || parsed.command === '-v') { + if (parsed.version) { logger.info('marmotta 0.6.0'); return; } @@ -95,7 +109,10 @@ async function main(): Promise { break; case 'list': { const versions = await listZigVersions(); - logger.info(versions.length > 0 ? versions.join('\n') : 'No Zig versions installed by Marmotta.'); + if (versions.length === 0) logger.info('No Zig versions installed by Marmotta.'); + // JSON consumers get one record per version; text mode prints the list unchanged. + else if (logger.format === 'json') for (const version of versions) logger.info(version); + else logger.info(versions.join('\n')); break; } case 'remove': { @@ -114,6 +131,12 @@ async function main(): Promise { main().catch((error: unknown) => { const normalized = normalizeError(error); - logger.error(`marmotta [${normalized.code}]: ${normalized.message}`); + // Text mode keeps the historical "marmotta [CODE]: message" line; JSON records carry the code + // and exit code as structured fields instead of embedding them in the message. + if (logger.format === 'json') { + logger.error(normalized.message, { code: normalized.code, exitCode: normalized.exitCode }); + } else { + logger.error(`marmotta [${normalized.code}]: ${normalized.message}`); + } process.exitCode = normalized.exitCode; }); diff --git a/src/logger.ts b/src/logger.ts index 5ea04e9..761dfe5 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -1,59 +1,65 @@ -export type LogFormat = 'text' | 'json'; +import { inspect } from 'node:util'; +import pino, { type DestinationStream, type Logger as PinoLogger } from 'pino'; -type LogLevel = 'info' | 'warn' | 'error' | 'debug'; +export type LogFormat = 'text' | 'json'; +export type LogLevel = 'info' | 'warn' | 'error' | 'debug'; type LogSink = (line: string) => void; export interface LoggerOptions { - debug?: boolean; format?: LogFormat; + /** Lowest level that produces output. Defaults to MARMOTTA_LOG, or "info" when unset or invalid. */ + level?: string; stdout?: LogSink; stderr?: LogSink; } -function formatTextData(data: unknown): string { - try { - const serialized = JSON.stringify(data, null, 2); - return serialized === undefined ? `\n${String(data)}` : `\n${serialized}`; - } catch { - return `\n${String(data)}`; - } -} +// pino uses the same scale, so one table drives both the JSON writers and the plain-text gate. +const levelValues: Record = pino.levels.values; -function formatJsonEntry(level: LogLevel, message: string, data?: unknown): string { - const entry: Record = { level, message }; - if (data !== undefined) entry.data = data; +// inspect handles circular references, prototypes and throwing accessors without failing, which +// keeps the plain-text payload best-effort even for context that JSON cannot represent. +function formatTextData(data: unknown): string { try { - return JSON.stringify(entry); + return inspect(data, { depth: null, colors: false, breakLength: 100 }); } catch { - // Keep the record valid even when context contains a circular value. - entry.data = String(data); - return JSON.stringify(entry); + return '[unserializable data]'; } } export class Logger { - private debugMode: boolean; - private format: LogFormat; - private stdout: LogSink; - private stderr: LogSink; + private readonly requestedLevel: string; + private readonly stdoutSink: LogSink; + private readonly stderrSink: LogSink; + private readonly customSinks: boolean; + private logFormat: LogFormat; + private levelName?: string; + private minLevel?: number; + private jsonStdout?: PinoLogger; + private jsonStderr?: PinoLogger; constructor(options: LoggerOptions = {}) { - this.debugMode = options.debug ?? false; - this.format = options.format ?? 'text'; - this.stdout = options.stdout ?? ((line) => process.stdout.write(line)); - this.stderr = options.stderr ?? ((line) => process.stderr.write(line)); + this.logFormat = options.format ?? 'text'; + this.customSinks = options.stdout !== undefined || options.stderr !== undefined; + // console.* appends the newline, keeps multi-line messages intact and passes them through + // unchanged, and silently absorbs errors from closed pipes, so text output stays + // byte-compatible with the plain console usage this logger replaces. + this.stdoutSink = options.stdout ?? ((line) => console.log(line)); + this.stderrSink = options.stderr ?? ((line) => console.error(line)); + // Resolved on first use, so the format is already settled and an invalid value is reported + // through the same channel as every other record. + this.requestedLevel = (options.level ?? process.env.MARMOTTA_LOG ?? 'info').toLowerCase(); } - setDebugMode(debugMode: boolean): void { - this.debugMode = debugMode; + get format(): LogFormat { + return this.logFormat; } setFormat(format: LogFormat): void { if (format !== 'text' && format !== 'json') { throw new TypeError(`Unsupported log format: ${String(format)}`); } - this.format = format; + this.logFormat = format; } info(message: string, data?: unknown): void { @@ -69,25 +75,71 @@ export class Logger { } debug(message: string, data?: unknown): void { - if (!this.debugMode) return; this.log('debug', message, data); } + private resolveLevel(): void { + if (this.minLevel !== undefined) return; + const value = levelValues[this.requestedLevel]; + if (value !== undefined) { + this.levelName = this.requestedLevel; + this.minLevel = value; + return; + } + this.levelName = 'info'; + this.minLevel = levelValues.info; + this.warn(`marmotta: ignoring invalid MARMOTTA_LOG value ${JSON.stringify(this.requestedLevel)}; using "info"`); + } + private log(level: LogLevel, message: string, data?: unknown): void { - if (!message) return; + this.resolveLevel(); + if (levelValues[level] < this.minLevel!) return; + if (this.logFormat === 'json') this.logJson(level, message, data); + else this.logText(level, message, data); + } + + // pino newline-terminates every record, so stdout stays valid JSON Lines across many records, + // and it serializes circular context as "[Circular]" instead of dropping the whole payload. + private logJson(level: LogLevel, message: string, data?: unknown): void { + const target = this.jsonLogger(level === 'warn' || level === 'error' ? 'stderr' : 'stdout'); + if (data === undefined) target[level](message); + else target[level]({ data }, message); + } - const line = this.format === 'json' - ? formatJsonEntry(level, message, data) - : this.formatTextMessage(level, message, data); - const sink = level === 'warn' || level === 'error' ? this.stderr : this.stdout; - sink(line); + private logText(level: LogLevel, message: string, data?: unknown): void { + const line = data === undefined ? message : `${message}\n${formatTextData(data)}`; + (level === 'warn' || level === 'error' ? this.stderrSink : this.stdoutSink)(line); } - private formatTextMessage(level: LogLevel, message: string, data?: unknown): string { - const normalizedMessage = message.replace(/\r?\n/g, ' '); - const line = `[${level.toUpperCase()}] ${normalizedMessage}`; - return this.debugMode && data !== undefined ? `${line}${formatTextData(data)}` : line; + private jsonLogger(stream: 'stdout' | 'stderr'): PinoLogger { + const existing = stream === 'stdout' ? this.jsonStdout : this.jsonStderr; + if (existing) return existing; + const options = { + level: this.levelName, + messageKey: 'message', + formatters: { + level: (label: string) => ({ level: label }), + bindings: () => ({}), + }, + }; + const sink = stream === 'stdout' ? this.stdoutSink : this.stderrSink; + const logger = pino(options, this.customSinks ? sinkDestination(sink) : this.standardDestination(stream)); + if (stream === 'stdout') this.jsonStdout = logger; + else this.jsonStderr = logger; + return logger; } + + private standardDestination(stream: 'stdout' | 'stderr'): DestinationStream { + const destination = pino.destination({ dest: stream === 'stdout' ? 1 : 2, sync: true }); + // A downstream reader such as `head` can close the pipe early; console.* would silently absorb + // the write error, and the logger must not crash the process where console would not. + destination.on('error', () => {}); + return destination; + } +} + +function sinkDestination(sink: LogSink): DestinationStream { + return { write: (line: string) => void sink(line) }; } // Default logger instance for use throughout the application From 8b20946096f722cf345cb50513af8d50caa55164 Mon Sep 17 00:00:00 2001 From: errusso Date: Fri, 16 Oct 2026 17:08:49 +0200 Subject: [PATCH 06/11] fix: capture toolchain output as JSON records in --json mode zig and tar previously inherited the terminal, so their raw diagnostics were mixed into --json output and broke the JSON Lines promise. In JSON mode their stdout and stderr are now piped, split into lines, and re-emitted as info and warn records carrying the command name; text mode keeps inheriting stdio. --- src/toolchain.ts | 43 ++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 42 insertions(+), 1 deletion(-) diff --git a/src/toolchain.ts b/src/toolchain.ts index f8141ed..c5a0fd3 100644 --- a/src/toolchain.ts +++ b/src/toolchain.ts @@ -4,6 +4,7 @@ import { constants } from 'node:fs'; import { access, chmod, mkdtemp, mkdir, readdir, rename, rm, writeFile } from 'node:fs/promises'; import { homedir } from 'node:os'; import { basename, isAbsolute, join, resolve, win32 } from 'node:path'; +import { logger } from './logger.js'; import { MarmottaDirectoryFailedError, MarmottaHomeInvalidError, @@ -119,9 +120,49 @@ function prepareZigCache(command: ZigCommand): Promise { return prepared; } +// Re-emits a captured child stream one line at a time, buffering the trailing partial line until the +// stream ends, so each forwarded line becomes its own log record. +function forwardLines(stream: NodeJS.ReadableStream | null, emit: (line: string) => void): void { + if (!stream) return; + let pending = ''; + stream.setEncoding('utf8'); + stream.on('data', (chunk: string) => { + pending += chunk; + let newline = pending.indexOf('\n'); + while (newline !== -1) { + const line = pending.slice(0, newline).replace(/\r$/, ''); + pending = pending.slice(newline + 1); + if (line.length > 0) emit(line); + newline = pending.indexOf('\n'); + } + }); + const flush = () => { + const line = pending.replace(/\r$/, ''); + pending = ''; + if (line.length > 0) emit(line); + }; + stream.on('end', flush); + // A stream error is reported by the child's own close event; swallowing it here only prevents an + // unhandled 'error' event from crashing the process while the output was being reformatted. + stream.on('error', () => {}); +} + function run(executable: string, args: string[], options: { cwd?: string; env?: NodeJS.ProcessEnv } = {}): Promise { return new Promise((resolve, reject) => { - const child = spawn(executable, args, { cwd: options.cwd, env: options.env, stdio: 'inherit' }); + // JSON output promises one JSON object per line, so raw zig/tar output cannot inherit the + // terminal in that mode: it is captured and re-emitted as records instead. Text mode keeps the + // live, streaming output users expect from a build. + const capture = logger.format === 'json'; + const child = spawn(executable, args, { + cwd: options.cwd, + env: options.env, + stdio: capture ? ['inherit', 'pipe', 'pipe'] : 'inherit', + }); + if (capture) { + const command = basename(executable); + forwardLines(child.stdout, (line) => logger.info(line, { command })); + forwardLines(child.stderr, (line) => logger.warn(line, { command })); + } child.once('error', (cause: Error) => { reject(new ToolchainSpawnFailedError(basename(executable), { cause })); }); From 23a58f4178e3b3d82306a8fc32178ca9a6164989 Mon Sep 17 00:00:00 2001 From: errusso Date: Fri, 16 Oct 2026 17:08:49 +0200 Subject: [PATCH 07/11] test: cover logging formats and document MARMOTTA_LOG Add tests for newline-terminated multi-record output, argument errors under --json, leading --json, multi-line help, circular/null-prototype context, empty messages, level gating and invalid MARMOTTA_LOG values, and restore the plain-text MARMOTTA_HOME and --version expectations. Document the JSON record shape, child-output capture, and MARMOTTA_LOG in the README. --- README.md | 28 +++++++++- test/cli.test.js | 81 +++++++++++++++++++++++++-- test/logger.test.js | 132 +++++++++++++++++++++++++++++++++----------- 3 files changed, 201 insertions(+), 40 deletions(-) diff --git a/README.md b/README.md index ed1c331..54a11aa 100644 --- a/README.md +++ b/README.md @@ -174,7 +174,7 @@ Run `marmotta --help` or `npx marmotta --help` for the built-in usage summary. | `-o, --output-dir ` | `build`, `rebuild`, `clean` | Override `outputDir`. Relative paths are resolved from the project directory. | | `--target ` | `build`, `rebuild` | Zig target triple used for cross-compilation. | | `--debug` | `build`, `rebuild` | Compile without optimization and include debug information (`-O0 -g` instead of `-O2`). | -| `--json` | Any command | Emit one valid JSON object per line to stdout (information/debug) or stderr (warning/error), suitable for CI logs. | +| `--json` | Any command | Emit machine-readable JSON Lines instead of plain text. Recognized before or after the command. | | `-h, --help` | Any command | Show help. | | `-v, --version` | Top-level command | Show the Marmotta version. | @@ -184,10 +184,34 @@ For example, request a build for ARM64 macOS: npx marmotta build --target aarch64-macos ``` -Use `--json` in CI when another process needs to consume Marmotta's output. Each log entry is a complete JSON Lines record; informational and debug records go to stdout, while warnings and errors go to stderr. +Use `--json` in CI when another process needs to consume Marmotta's output; see [Logging](#logging) for the record format and the `MARMOTTA_LOG` variable. Use a target triple supported by Zig for the intended target. Cross-compilation does not run the resulting addon on the host; load it on a compatible target system. +### Logging + +By default Marmotta writes plain text: status messages on stdout and errors on stderr, with no level prefixes, so scripts that read `marmotta --version` or `marmotta list` keep working unchanged. + +Pass `--json` when another process needs to consume the output, as in CI. The flag is recognized before or after the command, and each record is one JSON object on its own line (JSON Lines): + +```sh +npx marmotta build --json +npx marmotta --json list +``` + +```json +{"level":"info","time":1730000000000,"message":"Addon built: /project/build/hello.node"} +{"level":"error","time":1730000000001,"data":{"code":"CLI_ARGUMENT_ERROR","exitCode":2},"message":"Unknown option: --bogus"} +``` + +- `level` is a string such as `info`, `warn`, or `error`. Informational records go to stdout; warnings and errors go to stderr. +- `message` is the human-readable text, and `data` carries the record's structured context when there is any, such as the error `code` and `exitCode`. +- Output from the Zig and `tar` child processes is captured and re-emitted as records, so every line printed in `--json` mode is valid JSON. +- Set `MARMOTTA_LOG` to the minimum level to report: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, or `silent`. The default is `info`, which hides `debug` records. An unrecognized value is ignored with a warning. + +`MARMOTTA_LOG` applies to both formats; it only changes which records are emitted, not the shape of the output. + + ## Zig toolchain Without a `zigVersion` pin, Marmotta uses `zig` from `PATH` when available, then a locally managed version, and otherwise downloads the latest stable Zig release for the supported host platform into the Marmotta home directory (see [Marmotta home directory](#marmotta-home-directory)). If `zigVersion` is set, Marmotta ignores `PATH` and selects that exact managed version, downloading it if necessary. If the pinned version is not available for the host platform, the command fails instead of falling back to another version. If the download index includes a checksum, Marmotta verifies the downloaded archive. If `MARMOTTA_ZIG_DIR` is set, Marmotta uses only that Zig and never downloads one (see [Existing Zig installation](#existing-zig-installation)). diff --git a/test/cli.test.js b/test/cli.test.js index 98b873f..cf9cad5 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -56,9 +56,7 @@ test('classifies invalid options as argument errors', () => { assert.match(result.stderr, /CLI_ARGUMENT_ERROR/); }); -test('builds and loads a C Node-API addon with Zig', { skip: !zigAvailable }, async () => { - const directory = await mkdtemp(join(tmpdir(), 'marmotta-addon-')); - const source = `#include +const addonSource = `#include #include static napi_value Method(napi_env env, napi_callback_info info) { @@ -80,6 +78,10 @@ static napi_value Initialize(napi_env env, napi_value exports) { NAPI_MODULE(NODE_GYP_MODULE_NAME, Initialize) `; +test('builds and loads a C Node-API addon with Zig', { skip: !zigAvailable }, async () => { + const directory = await mkdtemp(join(tmpdir(), 'marmotta-addon-')); + const source = addonSource; + try { await mkdir(join(directory, 'build')); await writeFile(join(directory, 'hello.c'), source); @@ -264,12 +266,25 @@ test('supports JSON Lines output for CI consumers', () => { const help = spawnSync(process.execPath, [cli, '--help', '--json'], { encoding: 'utf8' }); assert.equal(help.status, 0, help.stderr || help.stdout); assert.equal(help.stderr.length, 0); + assert.ok(help.stdout.endsWith('\n'), 'JSON records must be newline-terminated'); - const entry = JSON.parse(help.stdout); + const lines = help.stdout.split('\n').filter((line) => line.length > 0); + assert.equal(lines.length, 1); + const entry = JSON.parse(lines[0]); assert.equal(entry.level, 'info'); assert.equal(typeof entry.message, 'string'); }); +test('recognizes --json before the command', () => { + const result = spawnSync(process.execPath, [cli, '--json', 'unknown-command'], { encoding: 'utf8' }); + assert.equal(result.status, 2); + assert.equal(result.stdout.length, 0); + + const entry = JSON.parse(result.stderr); + assert.equal(entry.level, 'error'); + assert.match(entry.message, /Unknown command/); +}); + test('reports CLI errors as structured JSON Lines', () => { const result = spawnSync(process.execPath, [cli, 'unknown-command', '--json'], { encoding: 'utf8', @@ -280,6 +295,62 @@ test('reports CLI errors as structured JSON Lines', () => { const entry = JSON.parse(result.stderr); assert.equal(entry.level, 'error'); assert.match(entry.message, /Unknown command/); + assert.equal(entry.data.code, 'CLI_COMMAND_ERROR'); + assert.equal(entry.data.exitCode, 2); +}); + +test('reports argument errors as structured JSON Lines', () => { + for (const args of [['build', '--bogus', '--json'], ['build', '--json', '--target']]) { + const result = spawnSync(process.execPath, [cli, ...args], { encoding: 'utf8' }); + assert.equal(result.status, 2, args.join(' ')); + assert.equal(result.stdout.length, 0, args.join(' ')); + + const entry = JSON.parse(result.stderr); + assert.equal(entry.level, 'error', args.join(' ')); + assert.equal(entry.data.code, 'CLI_ARGUMENT_ERROR', args.join(' ')); + } +}); + +test('keeps the plain text output for --version and --help', () => { + const version = spawnSync(process.execPath, [cli, '--version'], { encoding: 'utf8' }); + assert.equal(version.status, 0, version.stderr); + assert.equal(version.stdout, 'marmotta 0.6.0\n'); + assert.equal(version.stderr.length, 0); + + const help = spawnSync(process.execPath, [cli, '--help'], { encoding: 'utf8' }); + assert.equal(help.status, 0, help.stderr); + const lines = help.stdout.split('\n'); + assert.ok(lines.length > 10, 'help must not be collapsed onto a single line'); + assert.equal(lines[0], 'Marmotta - build tool for Node.js addons with Zig'); +}); + +test('emits one JSON record per line for a multi-step build', { skip: !zigAvailable }, async () => { + const directory = await mkdtemp(join(tmpdir(), 'marmotta-json-lines-')); + try { + await writeFile(join(directory, 'hello.c'), addonSource); + await writeFile(join(directory, 'marmotta.config.json'), JSON.stringify({ name: 'hello' })); + + const result = spawnSync(process.execPath, [cli, 'rebuild', '-C', directory, '--json'], { + encoding: 'utf8', + maxBuffer: 16 * 1024 * 1024, + }); + assert.equal(result.status, 0, result.stderr || result.stdout); + assert.ok(result.stdout.endsWith('\n'), 'stdout must end with a newline'); + + const lines = result.stdout.split('\n'); + assert.equal(lines.at(-1), ''); + const entries = lines.slice(0, -1).map((line) => JSON.parse(line)); + assert.ok(entries.length >= 2, `expected several records, got ${entries.length}`); + assert.ok(entries.every((entry) => typeof entry.level === 'string' && typeof entry.message === 'string')); + assert.ok(entries.some((entry) => /Removed/.test(entry.message))); + assert.ok(entries.some((entry) => /Addon built/.test(entry.message))); + + for (const line of result.stderr.split('\n').filter((line) => line.length > 0)) { + assert.doesNotThrow(() => JSON.parse(line), `stderr line is not JSON: ${line}`); + } + } finally { + await rm(directory, { recursive: true, force: true }); + } }); test('reports an invalid MARMOTTA_HOME without breaking help', () => { @@ -290,5 +361,5 @@ test('reports an invalid MARMOTTA_HOME without breaking help', () => { const list = spawnSync(process.execPath, [cli, 'list'], { encoding: 'utf8', env }); assert.equal(list.status, 2); - assert.match(list.stderr, /^\[ERROR\] marmotta \[MARMOTTA_HOME_INVALID\]: MARMOTTA_HOME must be an absolute path/); + assert.match(list.stderr, /^marmotta \[MARMOTTA_HOME_INVALID\]: MARMOTTA_HOME must be an absolute path/); }); diff --git a/test/logger.test.js b/test/logger.test.js index 5f9110a..25052bb 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -1,14 +1,16 @@ import assert from 'node:assert/strict'; +import { spawnSync } from 'node:child_process'; import { test } from 'node:test'; +import { fileURLToPath } from 'node:url'; import { Logger } from '../dist/logger.js'; -function capture(format = 'json') { +function capture(format = 'json', level = 'info') { const stdout = []; const stderr = []; return { logger: new Logger({ - debug: true, format, + level, stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line), }), @@ -17,56 +19,120 @@ function capture(format = 'json') { }; } -test('writes structured JSON lines without prefixing the payload', () => { +// Splits captured chunks on newlines and parses each record, which fails if a record is not +// newline-terminated or if two records share a line. +function records(chunks) { + return chunks.join('').split('\n').filter((line) => line.length > 0).map((line) => JSON.parse(line)); +} + +test('writes one newline-terminated JSON record per call and routes levels to the right stream', () => { const { logger, stdout, stderr } = capture(); - logger.info('build complete', { addon: 'hello.node', target: 'x64-linux' }); + logger.info('first record'); + logger.info('second record', { addon: 'hello.node' }); logger.warn('cache miss'); logger.error('compile failed', { code: 'TOOLCHAIN_COMMAND_FAILED' }); - assert.deepEqual(JSON.parse(stdout[0]), { - level: 'info', - message: 'build complete', - data: { addon: 'hello.node', target: 'x64-linux' }, - }); - assert.equal(stderr[0], JSON.stringify({ level: 'warn', message: 'cache miss' })); - assert.deepEqual(JSON.parse(stderr[1]), { - level: 'error', - message: 'compile failed', - data: { code: 'TOOLCHAIN_COMMAND_FAILED' }, - }); + for (const chunk of [...stdout, ...stderr]) assert.ok(chunk.endsWith('\n'), JSON.stringify(chunk)); + + const [first, second] = records(stdout); + assert.equal(first.level, 'info'); + assert.equal(first.message, 'first record'); + assert.equal(typeof first.time, 'number'); + assert.deepEqual(second.data, { addon: 'hello.node' }); + + const [warned, failed] = records(stderr); + assert.equal(warned.level, 'warn'); + assert.equal(warned.message, 'cache miss'); + assert.equal(failed.level, 'error'); + assert.deepEqual(failed.data, { code: 'TOOLCHAIN_COMMAND_FAILED' }); }); -test('keeps text output readable and keeps debug data attached to debug logs', () => { +test('keeps text output plain, multi-line, and includes the data payload', () => { const { logger, stdout, stderr } = capture('text'); - logger.info('ready'); - logger.debug('compiler path', '/opt/zig/zig'); + logger.info('marmotta 0.6.0'); + logger.info('Commands:\n build\n clean'); + logger.warn('careful', { code: 'SOMETHING' }); - assert.equal(stdout[0], '[INFO] ready'); - assert.match(stdout[1], /^\[DEBUG\] compiler path\n/); - assert.match(stdout[1], /"\/opt\/zig\/zig"/); - assert.equal(stderr.length, 0); + assert.deepEqual(stdout, ['marmotta 0.6.0', 'Commands:\n build\n clean']); + assert.match(stderr[0], /^careful\n/); + assert.match(stderr[0], /code: 'SOMETHING'/); +}); + +test('emits records for empty messages instead of dropping them', () => { + const json = capture(); + json.logger.info(''); + json.logger.error('', { code: 'SOMETHING' }); + assert.equal(records(json.stdout)[0].message, ''); + assert.deepEqual(records(json.stderr)[0].data, { code: 'SOMETHING' }); + + const text = capture('text'); + text.logger.info(''); + assert.deepEqual(text.stdout, ['']); }); test('keeps JSON records valid when context is circular', () => { - const stdout = []; - const logger = new Logger({ format: 'json', stdout: (line) => stdout.push(line) }); - const context = {}; + const { logger, stdout } = capture(); + const context = { addon: 'hello.node' }; context.self = context; logger.info('context', context); - assert.equal(JSON.parse(stdout[0]).data, '[object Object]'); + + const [record] = records(stdout); + assert.equal(record.data.self, '[Circular]'); + assert.equal(record.data.addon, 'hello.node'); }); -test('debug mode defaults to disabled', () => { - const stdout = []; - const logger = new Logger({ format: 'json', stdout: (line) => stdout.push(line) }); +test('does not throw on null-prototype objects in either format', () => { + const context = Object.create(null); + context.self = context; + const json = capture(); + assert.doesNotThrow(() => json.logger.info('null-prototype', context)); + assert.equal(records(json.stdout)[0].data.self, '[Circular]'); + + const text = capture('text'); + assert.doesNotThrow(() => text.logger.info('null-prototype', context)); + assert.match(text.stdout[0], /self/); +}); + +test('debug records are hidden until the level allows them', () => { + const quiet = capture(); + quiet.logger.debug('hidden'); + assert.deepEqual(quiet.stdout, []); + assert.deepEqual(quiet.stderr, []); + + const loud = capture('json', 'debug'); + loud.logger.debug('visible'); + assert.equal(records(loud.stdout)[0].message, 'visible'); + + const text = capture('text', 'warn'); + text.logger.info('hidden'); + text.logger.warn('shown'); + assert.deepEqual(text.stdout, []); + assert.deepEqual(text.stderr, ['shown']); +}); + +test('falls back to info for an invalid MARMOTTA_LOG value', () => { + const stdout = []; + const stderr = []; + const logger = new Logger({ format: 'json', level: 'bogus', stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line) }); + logger.info('visible'); logger.debug('hidden'); - assert.equal(stdout.length, 0); - logger.setDebugMode(true); - logger.debug('visible'); - assert.equal(JSON.parse(stdout[0]).message, 'visible'); + assert.match(stderr[0], /ignoring invalid MARMOTTA_LOG value/); + assert.equal(records(stdout).length, 1); +}); + +test('MARMOTTA_LOG configures the default logger level', () => { + const module = fileURLToPath(new URL('../dist/logger.js', import.meta.url)); + const script = `import(${JSON.stringify(module)}).then(({ logger }) => { logger.info('hidden'); logger.error('shown'); });`; + const result = spawnSync(process.execPath, ['-e', script], { + encoding: 'utf8', + env: { ...process.env, MARMOTTA_LOG: 'error' }, + }); + + assert.equal(result.stdout, ''); + assert.equal(result.stderr, 'shown\n'); }); From 3b7edadb70a633de67c4ccf9575712d06dd4ba5e Mon Sep 17 00:00:00 2001 From: errusso Date: Fri, 16 Oct 2026 17:21:39 +0200 Subject: [PATCH 08/11] test: import the logger module through a file URL on Windows Dynamic import of a raw Windows path ("D:\...") is rejected as a URL scheme, so the MARMOTTA_LOG test now imports a file:// URL and compares stderr without assuming a newline style. --- test/logger.test.js | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/test/logger.test.js b/test/logger.test.js index 25052bb..f95ec19 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -1,7 +1,6 @@ import assert from 'node:assert/strict'; import { spawnSync } from 'node:child_process'; import { test } from 'node:test'; -import { fileURLToPath } from 'node:url'; import { Logger } from '../dist/logger.js'; function capture(format = 'json', level = 'info') { @@ -126,13 +125,14 @@ test('falls back to info for an invalid MARMOTTA_LOG value', () => { }); test('MARMOTTA_LOG configures the default logger level', () => { - const module = fileURLToPath(new URL('../dist/logger.js', import.meta.url)); - const script = `import(${JSON.stringify(module)}).then(({ logger }) => { logger.info('hidden'); logger.error('shown'); });`; + // A file:// URL imports correctly on Windows, where "D:\..." is read as a URL scheme. + const moduleUrl = new URL('../dist/logger.js', import.meta.url).href; + const script = `import(${JSON.stringify(moduleUrl)}).then(({ logger }) => { logger.info('hidden'); logger.error('shown'); });`; const result = spawnSync(process.execPath, ['-e', script], { encoding: 'utf8', env: { ...process.env, MARMOTTA_LOG: 'error' }, }); assert.equal(result.stdout, ''); - assert.equal(result.stderr, 'shown\n'); + assert.equal(result.stderr.trim(), 'shown'); }); From a8306f07a075988d0d38de40cb3c8ba5c5b03207 Mon Sep 17 00:00:00 2001 From: errusso Date: Fri, 16 Oct 2026 17:35:08 +0200 Subject: [PATCH 09/11] ci: retrigger checks after a flaky Windows temp-directory cleanup From 5b8b7c008c91ec5a02c647e86a4b483cf8b8af7d Mon Sep 17 00:00:00 2001 From: errusso Date: Tue, 20 Oct 2026 00:51:21 +0200 Subject: [PATCH 10/11] fix: separate command output from level-filtered diagnostics Address the second review round on the structured logging change: - command results (help, version, list, confirmations, build results) and the final error now go through an unfiltered output()/failure() path, so MARMOTTA_LOG can no longer hide them; MARMOTTA_LOG filters diagnostics only - zig/tar output is re-emitted through output() instead of warn(), so compiler errors survive MARMOTTA_LOG=error, and records carry command and stream - --version combined with a command is rejected with CLI_ARGUMENT_ERROR instead of printing the version and skipping the requested work - custom sinks receive one unterminated line per call in both formats - level validation uses Object.hasOwn, rejecting inherited names such as "constructor" that would otherwise disable the gate - empty or whitespace-only MARMOTTA_LOG counts as unset - list --json emits a single structured record with data.versions - unknown-command JSON messages no longer embed the usage block - child output lines are split with node:readline instead of a manual buffer --- README.md | 15 ++++---- src/build.ts | 6 ++-- src/cli.ts | 35 +++++++++--------- src/logger.ts | 69 ++++++++++++++++++++++++++++------- src/toolchain.ts | 35 +++++++----------- test/cli.test.js | 88 +++++++++++++++++++++++++++++++++++++++++++-- test/logger.test.js | 63 +++++++++++++++++++++++++++++--- 7 files changed, 243 insertions(+), 68 deletions(-) diff --git a/README.md b/README.md index 54a11aa..263990a 100644 --- a/README.md +++ b/README.md @@ -190,7 +190,7 @@ Use a target triple supported by Zig for the intended target. Cross-compilation ### Logging -By default Marmotta writes plain text: status messages on stdout and errors on stderr, with no level prefixes, so scripts that read `marmotta --version` or `marmotta list` keep working unchanged. +By default Marmotta writes plain text: command results on stdout and errors on stderr, with no level prefixes, so scripts that read `marmotta --version` or `marmotta list` keep working unchanged. Pass `--json` when another process needs to consume the output, as in CI. The flag is recognized before or after the command, and each record is one JSON object on its own line (JSON Lines): @@ -201,15 +201,18 @@ npx marmotta --json list ```json {"level":"info","time":1730000000000,"message":"Addon built: /project/build/hello.node"} -{"level":"error","time":1730000000001,"data":{"code":"CLI_ARGUMENT_ERROR","exitCode":2},"message":"Unknown option: --bogus"} +{"level":"info","time":1730000000001,"data":{"versions":["0.13.0","0.14.0"]},"message":"Installed Zig versions"} +{"level":"error","time":1730000000002,"data":{"code":"CLI_ARGUMENT_ERROR","exitCode":2},"message":"Unknown option: --bogus"} ``` - `level` is a string such as `info`, `warn`, or `error`. Informational records go to stdout; warnings and errors go to stderr. -- `message` is the human-readable text, and `data` carries the record's structured context when there is any, such as the error `code` and `exitCode`. -- Output from the Zig and `tar` child processes is captured and re-emitted as records, so every line printed in `--json` mode is valid JSON. -- Set `MARMOTTA_LOG` to the minimum level to report: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, or `silent`. The default is `info`, which hides `debug` records. An unrecognized value is ignored with a warning. +- `message` is the human-readable text, and `data` carries the record's structured context when there is any, such as the error `code` and `exitCode`, the installed `versions`, or a child process's `command` and `stream`. +- Command results, such as help, the version, `list`, confirmations and error messages, are always printed. Output from the Zig and `tar` child processes is captured and re-emitted as records tagged with `command` and `stream`, so every line printed in `--json` mode is valid JSON and compiler errors are never hidden. +- Set `MARMOTTA_LOG` to the minimum level for diagnostic records: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, or `silent`. The default is `info`, which hides `debug` records. An unrecognized value is ignored with a warning. -`MARMOTTA_LOG` applies to both formats; it only changes which records are emitted, not the shape of the output. +`MARMOTTA_LOG` filters diagnostics only; it never hides a command's result or its final error. It applies to both formats and does not change the shape of the output. + +`--version` is a top-level request and cannot be combined with a command, so `marmotta build --version` fails with an argument error instead of printing the version and skipping the build. ## Zig toolchain diff --git a/src/build.ts b/src/build.ts index c3549e1..36ba6f2 100644 --- a/src/build.ts +++ b/src/build.ts @@ -34,7 +34,7 @@ async function compile(config: ProjectConfig, options: BuildOptions, cleanOnly: const output = join(outputDir, `${config.name}.node`); if (cleanOnly) { await rm(output, { force: true }); - logger.info(`Removed ${output}`); + logger.output(`Removed ${output}`); return; } @@ -83,7 +83,7 @@ async function compile(config: ProjectConfig, options: BuildOptions, cleanOnly: await mkdir(dirname(output), { recursive: true }); await runZig(zig, args, options.directory); - logger.info(`Addon built: ${output}`); + logger.output(`Addon built: ${output}`); } finally { await rm(temporaryDir, { recursive: true, force: true }); } @@ -92,7 +92,7 @@ async function compile(config: ProjectConfig, options: BuildOptions, cleanOnly: export async function configure(options: BuildOptions): Promise { const config = await loadProject(options.directory, { target: options.target }); await ensureZig(config.zigVersion); - logger.info(`Configuration ready: ${config.name} (${config.sources.length} sources)`); + logger.output(`Configuration ready: ${config.name} (${config.sources.length} sources)`); return config; } diff --git a/src/cli.ts b/src/cli.ts index a01178e..88c1e67 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -63,6 +63,11 @@ function parseArgs(argv: string[]): ParsedArgs { } const [command, ...rest] = positionals; + // --version is a top-level request. Combining it with a command would print the version and + // silently skip the requested work, so reject the combination instead. + if (version && command !== undefined && command !== 'help') { + throw new CliArgumentError('--version cannot be combined with a command'); + } return { command: command ?? 'help', positional: rest, @@ -81,11 +86,11 @@ async function main(): Promise { const parsed = parseArgs(argv); if (parsed.help) { - logger.info(usage); + logger.output(usage); return; } if (parsed.version) { - logger.info('marmotta 0.6.0'); + logger.output('marmotta 0.6.0'); return; } @@ -105,14 +110,14 @@ async function main(): Promise { break; case 'install': await ensureZig(); - logger.info('Zig toolchain is ready.'); + logger.output('Zig toolchain is ready.'); break; case 'list': { const versions = await listZigVersions(); - if (versions.length === 0) logger.info('No Zig versions installed by Marmotta.'); - // JSON consumers get one record per version; text mode prints the list unchanged. - else if (logger.format === 'json') for (const version of versions) logger.info(version); - else logger.info(versions.join('\n')); + logger.output(versions.length > 0 ? 'Installed Zig versions' : 'No Zig versions installed by Marmotta.', { + data: { versions }, + text: versions.length > 0 ? versions.join('\n') : undefined, + }); break; } case 'remove': { @@ -121,22 +126,20 @@ async function main(): Promise { throw new CliArgumentError('Specify the Zig version to remove.'); } await removeZigVersion(version); - logger.info(`Removed Zig version ${version}.`); + logger.output(`Removed Zig version ${version}.`); break; } default: - throw new CliCommandError(`Unknown command: ${parsed.command}\n\n${usage}`); + throw new CliCommandError(`Unknown command: ${parsed.command}`); } } main().catch((error: unknown) => { const normalized = normalizeError(error); - // Text mode keeps the historical "marmotta [CODE]: message" line; JSON records carry the code - // and exit code as structured fields instead of embedding them in the message. - if (logger.format === 'json') { - logger.error(normalized.message, { code: normalized.code, exitCode: normalized.exitCode }); - } else { - logger.error(`marmotta [${normalized.code}]: ${normalized.message}`); - } + // Text mode keeps the historical "marmotta [CODE]: message" line and appends the usage block for + // unknown commands; the JSON record omits it so its message stays a single line. + const base = `marmotta [${normalized.code}]: ${normalized.message}`; + const text = normalized.code === 'CLI_COMMAND_ERROR' ? `${base}\n\n${usage}` : base; + logger.failure(normalized.message, { code: normalized.code, exitCode: normalized.exitCode }, text); process.exitCode = normalized.exitCode; }); diff --git a/src/logger.ts b/src/logger.ts index 761dfe5..bb1f6d8 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -4,6 +4,10 @@ import pino, { type DestinationStream, type Logger as PinoLogger } from 'pino'; export type LogFormat = 'text' | 'json'; export type LogLevel = 'info' | 'warn' | 'error' | 'debug'; +/** + * Receives one record per call, without a trailing newline, in both text and JSON mode, so the + * same sink works for either format. + */ type LogSink = (line: string) => void; export interface LoggerOptions { @@ -14,6 +18,17 @@ export interface LoggerOptions { stderr?: LogSink; } +export interface OutputOptions { + /** Structured context merged into the JSON record. Ignored in text mode. */ + data?: unknown; + /** Text written instead of the message in text mode, for results that render differently. */ + text?: string; + /** Destination stream. Defaults to stdout. */ + stream?: 'stdout' | 'stderr'; + /** Level of the JSON record. Defaults to "info". */ + level?: LogLevel; +} + // pino uses the same scale, so one table drives both the JSON writers and the plain-text gate. const levelValues: Record = pino.levels.values; @@ -33,7 +48,6 @@ export class Logger { private readonly stderrSink: LogSink; private readonly customSinks: boolean; private logFormat: LogFormat; - private levelName?: string; private minLevel?: number; private jsonStdout?: PinoLogger; private jsonStderr?: PinoLogger; @@ -46,15 +60,20 @@ export class Logger { // byte-compatible with the plain console usage this logger replaces. this.stdoutSink = options.stdout ?? ((line) => console.log(line)); this.stderrSink = options.stderr ?? ((line) => console.error(line)); - // Resolved on first use, so the format is already settled and an invalid value is reported - // through the same channel as every other record. - this.requestedLevel = (options.level ?? process.env.MARMOTTA_LOG ?? 'info').toLowerCase(); + // Empty or whitespace-only counts as unset, matching MARMOTTA_HOME and MARMOTTA_ZIG_DIR. + const requested = (options.level ?? process.env.MARMOTTA_LOG ?? '').trim(); + this.requestedLevel = requested === '' ? 'info' : requested.toLowerCase(); } get format(): LogFormat { return this.logFormat; } + /** Child process output must be captured and re-emitted as records in JSON mode. */ + get capturesChildOutput(): boolean { + return this.logFormat === 'json'; + } + setFormat(format: LogFormat): void { if (format !== 'text' && format !== 'json') { throw new TypeError(`Unsupported log format: ${String(format)}`); @@ -78,15 +97,32 @@ export class Logger { this.log('debug', message, data); } + /** + * Writes a command result. Level filtering never applies: MARMOTTA_LOG controls diagnostics, not + * the command's own output, so `--version`, `list`, confirmations and compiler output stay + * visible even when MARMOTTA_LOG is set to "error" or "silent". + */ + output(message: string, options: OutputOptions = {}): void { + this.resolveLevel(); + const { data, text, stream = 'stdout', level = 'info' } = options; + if (this.logFormat === 'json') this.writeJson(stream, level, message, data); + else (stream === 'stderr' ? this.stderrSink : this.stdoutSink)(text ?? message); + } + + /** Writes the final CLI error; it is always printed, on stderr. */ + failure(message: string, data?: unknown, text?: string): void { + this.output(message, { data, text, stream: 'stderr', level: 'error' }); + } + private resolveLevel(): void { if (this.minLevel !== undefined) return; - const value = levelValues[this.requestedLevel]; - if (value !== undefined) { - this.levelName = this.requestedLevel; + // Object.hasOwn rejects inherited names such as "constructor" or "__proto__", which would + // otherwise resolve to prototype members and silently disable the gate. + const value = Object.hasOwn(levelValues, this.requestedLevel) ? levelValues[this.requestedLevel] : undefined; + if (typeof value === 'number') { this.minLevel = value; return; } - this.levelName = 'info'; this.minLevel = levelValues.info; this.warn(`marmotta: ignoring invalid MARMOTTA_LOG value ${JSON.stringify(this.requestedLevel)}; using "info"`); } @@ -98,10 +134,15 @@ export class Logger { else this.logText(level, message, data); } - // pino newline-terminates every record, so stdout stays valid JSON Lines across many records, - // and it serializes circular context as "[Circular]" instead of dropping the whole payload. + // pino is configured at "trace" so log() performs the only level filtering. output() records + // therefore always pass, while pino still newline-terminates each record and serializes circular + // context as "[Circular]" instead of dropping the payload. private logJson(level: LogLevel, message: string, data?: unknown): void { - const target = this.jsonLogger(level === 'warn' || level === 'error' ? 'stderr' : 'stdout'); + this.writeJson(level === 'warn' || level === 'error' ? 'stderr' : 'stdout', level, message, data); + } + + private writeJson(stream: 'stdout' | 'stderr', level: LogLevel, message: string, data?: unknown): void { + const target = this.jsonLogger(stream); if (data === undefined) target[level](message); else target[level]({ data }, message); } @@ -115,7 +156,7 @@ export class Logger { const existing = stream === 'stdout' ? this.jsonStdout : this.jsonStderr; if (existing) return existing; const options = { - level: this.levelName, + level: 'trace', messageKey: 'message', formatters: { level: (label: string) => ({ level: label }), @@ -139,7 +180,9 @@ export class Logger { } function sinkDestination(sink: LogSink): DestinationStream { - return { write: (line: string) => void sink(line) }; + // pino terminates JSON records with a newline; the sink contract is one unterminated line per + // call, so strip it before handing the line over. + return { write: (line: string) => void sink(line.replace(/\n$/, '')) }; } // Default logger instance for use throughout the application diff --git a/src/toolchain.ts b/src/toolchain.ts index c5a0fd3..bd701da 100644 --- a/src/toolchain.ts +++ b/src/toolchain.ts @@ -4,6 +4,7 @@ import { constants } from 'node:fs'; import { access, chmod, mkdtemp, mkdir, readdir, rename, rm, writeFile } from 'node:fs/promises'; import { homedir } from 'node:os'; import { basename, isAbsolute, join, resolve, win32 } from 'node:path'; +import { createInterface } from 'node:readline'; import { logger } from './logger.js'; import { MarmottaDirectoryFailedError, @@ -120,28 +121,14 @@ function prepareZigCache(command: ZigCommand): Promise { return prepared; } -// Re-emits a captured child stream one line at a time, buffering the trailing partial line until the -// stream ends, so each forwarded line becomes its own log record. +// Re-emits a captured child stream one line at a time. readline handles CRLF and the trailing +// partial line at end of stream; empty lines are dropped so they do not become blank records. function forwardLines(stream: NodeJS.ReadableStream | null, emit: (line: string) => void): void { if (!stream) return; - let pending = ''; - stream.setEncoding('utf8'); - stream.on('data', (chunk: string) => { - pending += chunk; - let newline = pending.indexOf('\n'); - while (newline !== -1) { - const line = pending.slice(0, newline).replace(/\r$/, ''); - pending = pending.slice(newline + 1); - if (line.length > 0) emit(line); - newline = pending.indexOf('\n'); - } - }); - const flush = () => { - const line = pending.replace(/\r$/, ''); - pending = ''; + const lines = createInterface({ input: stream, crlfDelay: Infinity, terminal: false }); + lines.on('line', (line) => { if (line.length > 0) emit(line); - }; - stream.on('end', flush); + }); // A stream error is reported by the child's own close event; swallowing it here only prevents an // unhandled 'error' event from crashing the process while the output was being reformatted. stream.on('error', () => {}); @@ -152,7 +139,7 @@ function run(executable: string, args: string[], options: { cwd?: string; env?: // JSON output promises one JSON object per line, so raw zig/tar output cannot inherit the // terminal in that mode: it is captured and re-emitted as records instead. Text mode keeps the // live, streaming output users expect from a build. - const capture = logger.format === 'json'; + const capture = logger.capturesChildOutput; const child = spawn(executable, args, { cwd: options.cwd, env: options.env, @@ -160,8 +147,12 @@ function run(executable: string, args: string[], options: { cwd?: string; env?: }); if (capture) { const command = basename(executable); - forwardLines(child.stdout, (line) => logger.info(line, { command })); - forwardLines(child.stderr, (line) => logger.warn(line, { command })); + // Child output is a command result, not a diagnostic: it bypasses MARMOTTA_LOG so compiler + // errors cannot be filtered out, and `stream` identifies which pipe it came from. + forwardLines(child.stdout, (line) => + logger.output(line, { data: { command, stream: 'stdout' }, stream: 'stdout' })); + forwardLines(child.stderr, (line) => + logger.output(line, { data: { command, stream: 'stderr' }, stream: 'stderr' })); } child.once('error', (cause: Error) => { reject(new ToolchainSpawnFailedError(basename(executable), { cause })); diff --git a/test/cli.test.js b/test/cli.test.js index cf9cad5..194039e 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -12,7 +12,7 @@ const cli = fileURLToPath(new URL('../dist/cli.js', import.meta.url)); // Every CLI process inherits this environment: run it with Marmotta's defaults, not the developer's own settings. // node --test runs each file in its own process, and Windows variable names are case-insensitive. for (const name of Object.keys(process.env)) { - if (['MARMOTTA_HOME', 'MARMOTTA_ZIG_DIR', 'ZIG_GLOBAL_CACHE_DIR'].includes(name.toUpperCase())) delete process.env[name]; + if (['MARMOTTA_HOME', 'MARMOTTA_ZIG_DIR', 'ZIG_GLOBAL_CACHE_DIR', 'MARMOTTA_LOG'].includes(name.toUpperCase())) delete process.env[name]; } const zigAvailable = spawnSync('zig', ['version'], { stdio: 'ignore' }).status === 0; @@ -282,7 +282,8 @@ test('recognizes --json before the command', () => { const entry = JSON.parse(result.stderr); assert.equal(entry.level, 'error'); - assert.match(entry.message, /Unknown command/); + assert.equal(entry.message, 'Unknown command: unknown-command'); + assert.doesNotMatch(entry.message, /Usage:/, 'the usage block must not flood the JSON message'); }); test('reports CLI errors as structured JSON Lines', () => { @@ -294,7 +295,7 @@ test('reports CLI errors as structured JSON Lines', () => { const entry = JSON.parse(result.stderr); assert.equal(entry.level, 'error'); - assert.match(entry.message, /Unknown command/); + assert.equal(entry.message, 'Unknown command: unknown-command'); assert.equal(entry.data.code, 'CLI_COMMAND_ERROR'); assert.equal(entry.data.exitCode, 2); }); @@ -311,6 +312,87 @@ test('reports argument errors as structured JSON Lines', () => { } }); +test('does not let MARMOTTA_LOG hide command output', () => { + for (const level of ['warn', 'silent']) { + const env = { ...process.env, MARMOTTA_LOG: level }; + const version = spawnSync(process.execPath, [cli, '--version'], { encoding: 'utf8', env }); + assert.equal(version.status, 0, level); + assert.equal(version.stdout, 'marmotta 0.6.0\n', level); + + const help = spawnSync(process.execPath, [cli, '--help'], { encoding: 'utf8', env }); + assert.equal(help.status, 0, level); + assert.match(help.stdout, /^Marmotta - build tool/, level); + } +}); + +test('still reports the final error when MARMOTTA_LOG hides diagnostics', () => { + const env = { ...process.env, MARMOTTA_HOME: 'relative/marmotta-home', MARMOTTA_LOG: 'silent' }; + + const text = spawnSync(process.execPath, [cli, 'list'], { encoding: 'utf8', env }); + assert.equal(text.status, 2); + assert.match(text.stderr, /^marmotta \[MARMOTTA_HOME_INVALID\]:/); + + const json = spawnSync(process.execPath, [cli, 'list', '--json'], { encoding: 'utf8', env }); + assert.equal(json.status, 2); + const entry = JSON.parse(json.stderr); + assert.equal(entry.level, 'error'); + assert.equal(entry.data.code, 'MARMOTTA_HOME_INVALID'); +}); + +test('rejects --version combined with a command', () => { + for (const args of [['build', '--version'], ['remove', '0.13.0', '-v'], ['--json', 'build', '--version']]) { + const result = spawnSync(process.execPath, [cli, ...args], { encoding: 'utf8' }); + assert.equal(result.status, 2, args.join(' ')); + assert.match(result.stderr, /CLI_ARGUMENT_ERROR/, args.join(' ')); + assert.match(result.stderr, /--version cannot be combined with a command/, args.join(' ')); + } +}); + +test('lists installed Zig versions as structured data in JSON mode', async () => { + const home = await mkdtemp(join(tmpdir(), 'marmotta-list-')); + try { + await mkdir(join(home, 'toolchains', 'zig', '0.13.0'), { recursive: true }); + await mkdir(join(home, 'toolchains', 'zig', '0.14.0'), { recursive: true }); + const env = { ...process.env, MARMOTTA_HOME: home }; + + const json = spawnSync(process.execPath, [cli, 'list', '--json'], { encoding: 'utf8', env }); + assert.equal(json.status, 0, json.stderr); + const entry = JSON.parse(json.stdout); + assert.equal(entry.message, 'Installed Zig versions'); + assert.deepEqual(entry.data.versions, ['0.13.0', '0.14.0']); + + const text = spawnSync(process.execPath, [cli, 'list'], { encoding: 'utf8', env }); + assert.equal(text.status, 0, text.stderr); + assert.equal(text.stdout, '0.13.0\n0.14.0\n'); + } finally { + await rm(home, { recursive: true, force: true }); + } +}); + +test('keeps Zig compiler errors in --json output when MARMOTTA_LOG=error', { skip: !zigAvailable }, async () => { + const directory = await mkdtemp(join(tmpdir(), 'marmotta-json-errors-')); + try { + await writeFile(join(directory, 'hello.c'), '#include \n\nint broken(void) { return missing_symbol; }\n'); + await writeFile(join(directory, 'marmotta.config.json'), JSON.stringify({ name: 'hello' })); + + const result = spawnSync(process.execPath, [cli, 'build', '-C', directory, '--json'], { + encoding: 'utf8', + maxBuffer: 16 * 1024 * 1024, + env: { ...process.env, MARMOTTA_LOG: 'error' }, + }); + assert.equal(result.status, 1, result.stdout || result.stderr); + + const entries = result.stderr.split('\n').filter((line) => line.length > 0).map((line) => JSON.parse(line)); + assert.ok( + entries.some((entry) => entry.data?.command === 'zig' && entry.data?.stream === 'stderr'), + 'Zig compiler output must survive MARMOTTA_LOG=error', + ); + assert.ok(entries.some((entry) => entry.data?.code === 'TOOLCHAIN_COMMAND_FAILED')); + } finally { + await rm(directory, { recursive: true, force: true }); + } +}); + test('keeps the plain text output for --version and --help', () => { const version = spawnSync(process.execPath, [cli, '--version'], { encoding: 'utf8' }); assert.equal(version.status, 0, version.stderr); diff --git a/test/logger.test.js b/test/logger.test.js index f95ec19..6f9e662 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -18,13 +18,12 @@ function capture(format = 'json', level = 'info') { }; } -// Splits captured chunks on newlines and parses each record, which fails if a record is not -// newline-terminated or if two records share a line. +// Each sink call is one complete record: JSON records parse directly, without splitting on newlines. function records(chunks) { - return chunks.join('').split('\n').filter((line) => line.length > 0).map((line) => JSON.parse(line)); + return chunks.map((chunk) => JSON.parse(chunk)); } -test('writes one newline-terminated JSON record per call and routes levels to the right stream', () => { +test('writes one JSON record per call to the matching stream', () => { const { logger, stdout, stderr } = capture(); logger.info('first record'); @@ -32,7 +31,9 @@ test('writes one newline-terminated JSON record per call and routes levels to th logger.warn('cache miss'); logger.error('compile failed', { code: 'TOOLCHAIN_COMMAND_FAILED' }); - for (const chunk of [...stdout, ...stderr]) assert.ok(chunk.endsWith('\n'), JSON.stringify(chunk)); + assert.equal(stdout.length, 2); + assert.equal(stderr.length, 2); + for (const chunk of [...stdout, ...stderr]) assert.ok(!chunk.endsWith('\n'), JSON.stringify(chunk)); const [first, second] = records(stdout); assert.equal(first.level, 'info'); @@ -59,6 +60,34 @@ test('keeps text output plain, multi-line, and includes the data payload', () => assert.match(stderr[0], /code: 'SOMETHING'/); }); +test('uses the same sink contract in both formats', () => { + const lines = []; + const sink = (line) => lines.push(line); + + new Logger({ format: 'json', stdout: sink }).info('json record'); + new Logger({ format: 'text', stdout: sink }).info('text record'); + + assert.equal(lines.length, 2); + assert.equal(JSON.parse(lines[0]).message, 'json record'); + assert.equal(lines[1], 'text record'); + for (const line of lines) assert.ok(!line.endsWith('\n'), JSON.stringify(line)); +}); + +test('never filters command output with the level', () => { + const json = capture('json', 'error'); + json.logger.output('marmotta 0.6.0'); + json.logger.output('compiler error', { data: { command: 'zig', stream: 'stderr' }, stream: 'stderr' }); + json.logger.info('hidden'); + json.logger.debug('hidden'); + assert.deepEqual(records(json.stdout).map((record) => record.message), ['marmotta 0.6.0']); + assert.deepEqual(records(json.stderr).map((record) => record.message), ['compiler error']); + + const text = capture('text', 'error'); + text.logger.output('marmotta 0.6.0'); + text.logger.info('hidden'); + assert.deepEqual(text.stdout, ['marmotta 0.6.0']); +}); + test('emits records for empty messages instead of dropping them', () => { const json = capture(); json.logger.info(''); @@ -124,6 +153,30 @@ test('falls back to info for an invalid MARMOTTA_LOG value', () => { assert.equal(records(stdout).length, 1); }); +test('rejects inherited property names as levels', () => { + for (const level of ['constructor', '__proto__', 'toString']) { + const stdout = []; + const stderr = []; + const logger = new Logger({ format: 'json', level, stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line) }); + logger.info('visible'); + logger.debug('hidden'); + + assert.match(stderr[0], /ignoring invalid MARMOTTA_LOG value/, level); + assert.equal(records(stdout).length, 1, level); + } +}); + +test('treats an empty level as unset', () => { + const stdout = []; + const stderr = []; + const logger = new Logger({ format: 'json', level: '', stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line) }); + logger.info('visible'); + logger.debug('hidden'); + + assert.deepEqual(stderr, []); + assert.equal(records(stdout).length, 1); +}); + test('MARMOTTA_LOG configures the default logger level', () => { // A file:// URL imports correctly on Windows, where "D:\..." is read as a URL scheme. const moduleUrl = new URL('../dist/logger.js', import.meta.url).href; From bc69bf6b61b775137d5fd202df1e6cc1da0509db Mon Sep 17 00:00:00 2001 From: Nicola Del Gobbo Date: Thu, 22 Oct 2026 00:05:18 +0200 Subject: [PATCH 11/11] feat: enhance logging and command handling with improved diagnostics and error reporting --- README.md | 4 +- src/cli.ts | 67 +++++++++++++++++----- src/logger.ts | 133 ++++++++++++++++++++++++-------------------- src/toolchain.ts | 21 +++++-- test/cli.test.js | 60 ++++++++++++++++++-- test/logger.test.js | 48 ++++++++++++---- 6 files changed, 235 insertions(+), 98 deletions(-) diff --git a/README.md b/README.md index 263990a..53aad27 100644 --- a/README.md +++ b/README.md @@ -207,8 +207,8 @@ npx marmotta --json list - `level` is a string such as `info`, `warn`, or `error`. Informational records go to stdout; warnings and errors go to stderr. - `message` is the human-readable text, and `data` carries the record's structured context when there is any, such as the error `code` and `exitCode`, the installed `versions`, or a child process's `command` and `stream`. -- Command results, such as help, the version, `list`, confirmations and error messages, are always printed. Output from the Zig and `tar` child processes is captured and re-emitted as records tagged with `command` and `stream`, so every line printed in `--json` mode is valid JSON and compiler errors are never hidden. -- Set `MARMOTTA_LOG` to the minimum level for diagnostic records: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, or `silent`. The default is `info`, which hides `debug` records. An unrecognized value is ignored with a warning. +- Command results, such as help, the version, `list`, confirmations and error messages, are always printed. Output from the Zig and `tar` child processes is captured and re-emitted as records tagged with `command` and `stream`, so every line printed in `--json` mode is valid JSON and compiler errors are never hidden. Lines from the child's stderr are `warn` records on stderr; lines from its stdout are `info` records on stdout. Lines keep their order within each stream, but the order between a child's stdout and stderr lines is not preserved. +- Set `MARMOTTA_LOG` to the minimum level for diagnostic records: `trace`, `debug`, `info`, `warn`, `error`, `fatal`, or `silent`. The default is `info`, which hides `debug` records: which Zig is used, where Zig is downloaded from, and each Zig or `tar` command line. An unrecognized value is ignored with a warning. `MARMOTTA_LOG` filters diagnostics only; it never hides a command's result or its final error. It applies to both formats and does not change the shape of the output. diff --git a/src/cli.ts b/src/cli.ts index 88c1e67..783aaed 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -32,33 +32,62 @@ Environment: MARMOTTA_ZIG_DIR absolute path of an existing Zig installation to use instead of downloading Zig MARMOTTA_LOG minimum log level: trace, debug, info (default), warn, error, fatal, silent`; -type ParsedArgs = { command: string; positional: string[]; options: BuildOptions; help: boolean; version: boolean }; +type ParsedArgs = { + command: string; + positional: string[]; + options: BuildOptions; + help: boolean; + version: boolean; + json: boolean; + /** The first argument error. main() throws it once the output format is applied. */ + error?: Error; +}; + +// Errors that are followed by the usage block in text mode, marked where they are thrown. +const usageErrors = new WeakSet(); + +function withUsage(error: E): E { + usageErrors.add(error); + return error; +} // Flags are recognized before or after the command, so `marmotta --json build` and // `marmotta build --json` behave the same. The first positional token names the command. +// Parsing continues past the first error, so a later --json still selects the format that error +// is reported in. function parseArgs(argv: string[]): ParsedArgs { const options: BuildOptions = { directory: process.cwd() }; const positionals: string[] = []; let help = false; let version = false; + let json = false; + let commandOption = false; + let error: Error | undefined; + const fail = (failure: Error) => { + error ??= failure; + }; for (let index = 0; index < argv.length; index += 1) { const token = argv[index]; if (token === '-h' || token === '--help') help = true; else if (token === '-v' || token === '--version') version = true; - else if (token === '--debug') options.debug = true; - else if (token === '--json') { /* the output format is applied before parsing; see main() */ } - else if (token === '-C' || token === '--directory' || token === '-o' || token === '--output-dir' || token === '--target') { + else if (token === '--json') json = true; + else if (token === '--debug') { + options.debug = true; + commandOption = true; + } else if (token === '-C' || token === '--directory' || token === '-o' || token === '--output-dir' || token === '--target') { + commandOption = true; const value = argv[index + 1]; if (!value || value.startsWith('-')) { - throw new CliArgumentError(`Missing value for ${token}`); + fail(new CliArgumentError(`Missing value for ${token}`)); + continue; } index += 1; if (token === '-C' || token === '--directory') options.directory = resolve(value); else if (token === '-o' || token === '--output-dir') options.outputDir = value; else options.target = value; } else if (token.startsWith('-')) { - throw new CliArgumentError(`Unknown option: ${token}`); + fail(new CliArgumentError(`Unknown option: ${token}`)); } else positionals.push(token); } @@ -66,7 +95,12 @@ function parseArgs(argv: string[]): ParsedArgs { // --version is a top-level request. Combining it with a command would print the version and // silently skip the requested work, so reject the combination instead. if (version && command !== undefined && command !== 'help') { - throw new CliArgumentError('--version cannot be combined with a command'); + fail(new CliArgumentError('--version cannot be combined with a command')); + } + // Command options without a command would otherwise fall through to help and exit 0, so a + // script that forgot the command would pass without doing anything. + if (command === undefined && commandOption && !help && !version) { + fail(withUsage(new CliCommandError('Missing command'))); } return { command: command ?? 'help', @@ -75,15 +109,18 @@ function parseArgs(argv: string[]): ParsedArgs { // No positional token means help, unless the user asked for --version instead. help: help || command === 'help' || (command === undefined && !version), version, + json, + error, }; } async function main(): Promise { - const argv = process.argv.slice(2); - // The output format is resolved from the raw arguments before parsing, so argument-parsing - // failures are reported in the requested format too. - logger.setFormat(argv.includes('--json') ? 'json' : 'text'); - const parsed = parseArgs(argv); + const parsed = parseArgs(process.argv.slice(2)); + // The format is applied before any argument error is thrown, so that error and an invalid + // MARMOTTA_LOG warning are both reported in the requested format. + logger.setFormat(parsed.json ? 'json' : 'text'); + logger.checkLevel(); + if (parsed.error) throw parsed.error; if (parsed.help) { logger.output(usage); @@ -130,16 +167,16 @@ async function main(): Promise { break; } default: - throw new CliCommandError(`Unknown command: ${parsed.command}`); + throw withUsage(new CliCommandError(`Unknown command: ${parsed.command}`)); } } main().catch((error: unknown) => { const normalized = normalizeError(error); // Text mode keeps the historical "marmotta [CODE]: message" line and appends the usage block for - // unknown commands; the JSON record omits it so its message stays a single line. + // errors marked with withUsage(); the JSON record omits it so its message stays a single line. const base = `marmotta [${normalized.code}]: ${normalized.message}`; - const text = normalized.code === 'CLI_COMMAND_ERROR' ? `${base}\n\n${usage}` : base; + const text = usageErrors.has(normalized) ? `${base}\n\n${usage}` : base; logger.failure(normalized.message, { code: normalized.code, exitCode: normalized.exitCode }, text); process.exitCode = normalized.exitCode; }); diff --git a/src/logger.ts b/src/logger.ts index bb1f6d8..ea68453 100644 --- a/src/logger.ts +++ b/src/logger.ts @@ -23,14 +23,22 @@ export interface OutputOptions { data?: unknown; /** Text written instead of the message in text mode, for results that render differently. */ text?: string; - /** Destination stream. Defaults to stdout. */ - stream?: 'stdout' | 'stderr'; - /** Level of the JSON record. Defaults to "info". */ + /** Level of the record, which also picks the stream: warn and error go to stderr. Defaults to "info". */ level?: LogLevel; } -// pino uses the same scale, so one table drives both the JSON writers and the plain-text gate. -const levelValues: Record = pino.levels.values; +// pino's level scale also drives the plain-text gate. "silent" is accepted by pino but is not part +// of its value table. +function levelValue(level: string): number | undefined { + if (level === 'silent') return Infinity; + // Object.hasOwn rejects inherited names such as "constructor" or "__proto__", which would + // otherwise resolve to prototype members and silently disable the gate. + return Object.hasOwn(pino.levels.values, level) ? pino.levels.values[level] : undefined; +} + +function isStderrLevel(level: LogLevel): boolean { + return level === 'warn' || level === 'error'; +} // inspect handles circular references, prototypes and throwing accessors without failing, which // keeps the plain-text payload best-effort even for context that JSON cannot represent. @@ -42,15 +50,23 @@ function formatTextData(data: unknown): string { } } +type JsonLoggers = { + /** Gated by the requested level, like the plain-text diagnostics. */ + diagnostics: PinoLogger; + /** Shares the destination but is never gated, for command output. */ + output: PinoLogger; +}; + export class Logger { private readonly requestedLevel: string; + private readonly level: string; + private readonly minLevel: number; private readonly stdoutSink: LogSink; private readonly stderrSink: LogSink; private readonly customSinks: boolean; private logFormat: LogFormat; - private minLevel?: number; - private jsonStdout?: PinoLogger; - private jsonStderr?: PinoLogger; + private levelChecked = false; + private json?: JsonLoggers; constructor(options: LoggerOptions = {}) { this.logFormat = options.format ?? 'text'; @@ -63,6 +79,9 @@ export class Logger { // Empty or whitespace-only counts as unset, matching MARMOTTA_HOME and MARMOTTA_ZIG_DIR. const requested = (options.level ?? process.env.MARMOTTA_LOG ?? '').trim(); this.requestedLevel = requested === '' ? 'info' : requested.toLowerCase(); + const value = levelValue(this.requestedLevel); + this.level = value === undefined ? 'info' : this.requestedLevel; + this.minLevel = value ?? levelValue('info')!; } get format(): LogFormat { @@ -81,6 +100,17 @@ export class Logger { this.logFormat = format; } + /** + * Warns, once, when the requested level was not recognized and "info" is used instead. Call it + * after the output format is final, so the warning is written in that format. + */ + checkLevel(): void { + if (this.levelChecked) return; + this.levelChecked = true; + if (this.level === this.requestedLevel) return; + this.warn(`marmotta: ignoring invalid MARMOTTA_LOG value ${JSON.stringify(this.requestedLevel)}; using "info"`); + } + info(message: string, data?: unknown): void { this.log('info', message, data); } @@ -103,80 +133,61 @@ export class Logger { * visible even when MARMOTTA_LOG is set to "error" or "silent". */ output(message: string, options: OutputOptions = {}): void { - this.resolveLevel(); - const { data, text, stream = 'stdout', level = 'info' } = options; - if (this.logFormat === 'json') this.writeJson(stream, level, message, data); - else (stream === 'stderr' ? this.stderrSink : this.stdoutSink)(text ?? message); + const { data, text, level = 'info' } = options; + if (this.logFormat === 'json') this.writeJson(this.jsonLoggers().output, level, message, data); + else (isStderrLevel(level) ? this.stderrSink : this.stdoutSink)(text ?? message); } /** Writes the final CLI error; it is always printed, on stderr. */ failure(message: string, data?: unknown, text?: string): void { - this.output(message, { data, text, stream: 'stderr', level: 'error' }); + this.output(message, { data, text, level: 'error' }); } - private resolveLevel(): void { - if (this.minLevel !== undefined) return; - // Object.hasOwn rejects inherited names such as "constructor" or "__proto__", which would - // otherwise resolve to prototype members and silently disable the gate. - const value = Object.hasOwn(levelValues, this.requestedLevel) ? levelValues[this.requestedLevel] : undefined; - if (typeof value === 'number') { - this.minLevel = value; + private log(level: LogLevel, message: string, data?: unknown): void { + if (this.logFormat === 'json') { + this.writeJson(this.jsonLoggers().diagnostics, level, message, data); return; } - this.minLevel = levelValues.info; - this.warn(`marmotta: ignoring invalid MARMOTTA_LOG value ${JSON.stringify(this.requestedLevel)}; using "info"`); - } - - private log(level: LogLevel, message: string, data?: unknown): void { - this.resolveLevel(); - if (levelValues[level] < this.minLevel!) return; - if (this.logFormat === 'json') this.logJson(level, message, data); - else this.logText(level, message, data); - } - - // pino is configured at "trace" so log() performs the only level filtering. output() records - // therefore always pass, while pino still newline-terminates each record and serializes circular - // context as "[Circular]" instead of dropping the payload. - private logJson(level: LogLevel, message: string, data?: unknown): void { - this.writeJson(level === 'warn' || level === 'error' ? 'stderr' : 'stdout', level, message, data); + if (levelValue(level)! < this.minLevel) return; + const line = data === undefined ? message : `${message}\n${formatTextData(data)}`; + (isStderrLevel(level) ? this.stderrSink : this.stdoutSink)(line); } - private writeJson(stream: 'stdout' | 'stderr', level: LogLevel, message: string, data?: unknown): void { - const target = this.jsonLogger(stream); + // pino serializes circular context as "[Circular]" instead of dropping the payload. + private writeJson(target: PinoLogger, level: LogLevel, message: string, data?: unknown): void { if (data === undefined) target[level](message); else target[level]({ data }, message); } - private logText(level: LogLevel, message: string, data?: unknown): void { - const line = data === undefined ? message : `${message}\n${formatTextData(data)}`; - (level === 'warn' || level === 'error' ? this.stderrSink : this.stdoutSink)(line); - } - - private jsonLogger(stream: 'stdout' | 'stderr'): PinoLogger { - const existing = stream === 'stdout' ? this.jsonStdout : this.jsonStderr; - if (existing) return existing; - const options = { - level: 'trace', + // Both loggers write through one multistream that sends warn and above to stderr and everything + // else to stdout; dedupe keeps a warn or error record off stdout. + private jsonLoggers(): JsonLoggers { + if (this.json) return this.json; + const stdout = this.customSinks ? sinkDestination(this.stdoutSink) : standardDestination(1); + const stderr = this.customSinks ? sinkDestination(this.stderrSink) : standardDestination(2); + const destination = pino.multistream([ + { level: 'trace', stream: stdout }, + { level: 'warn', stream: stderr }, + ], { dedupe: true }); + const diagnostics = pino({ + level: this.level, messageKey: 'message', formatters: { level: (label: string) => ({ level: label }), bindings: () => ({}), }, - }; - const sink = stream === 'stdout' ? this.stdoutSink : this.stderrSink; - const logger = pino(options, this.customSinks ? sinkDestination(sink) : this.standardDestination(stream)); - if (stream === 'stdout') this.jsonStdout = logger; - else this.jsonStderr = logger; - return logger; + }, destination); + this.json = { diagnostics, output: diagnostics.child({}, { level: 'trace' }) }; + return this.json; } +} - private standardDestination(stream: 'stdout' | 'stderr'): DestinationStream { - const destination = pino.destination({ dest: stream === 'stdout' ? 1 : 2, sync: true }); - // A downstream reader such as `head` can close the pipe early; console.* would silently absorb - // the write error, and the logger must not crash the process where console would not. - destination.on('error', () => {}); - return destination; - } +function standardDestination(fd: 1 | 2): DestinationStream { + const destination = pino.destination({ dest: fd, sync: true }); + // A downstream reader such as `head` can close the pipe early; console.* would silently absorb + // the write error, and the logger must not crash the process where console would not. + destination.on('error', () => {}); + return destination; } function sinkDestination(sink: LogSink): DestinationStream { diff --git a/src/toolchain.ts b/src/toolchain.ts index bd701da..9f1714c 100644 --- a/src/toolchain.ts +++ b/src/toolchain.ts @@ -140,6 +140,7 @@ function run(executable: string, args: string[], options: { cwd?: string; env?: // terminal in that mode: it is captured and re-emitted as records instead. Text mode keeps the // live, streaming output users expect from a build. const capture = logger.capturesChildOutput; + logger.debug(`Running ${basename(executable)}`, { executable, args, cwd: options.cwd ?? process.cwd() }); const child = spawn(executable, args, { cwd: options.cwd, env: options.env, @@ -148,11 +149,15 @@ function run(executable: string, args: string[], options: { cwd?: string; env?: if (capture) { const command = basename(executable); // Child output is a command result, not a diagnostic: it bypasses MARMOTTA_LOG so compiler - // errors cannot be filtered out, and `stream` identifies which pipe it came from. + // errors cannot be filtered out, and `stream` identifies which pipe it came from. stderr + // carries Zig's and tar's warnings and errors, so its records are "warn" records on stderr; + // the final failure record is the one with level "error". Each pipe keeps its own line + // order, but two pipes cannot keep the order between them: Zig and tar write their + // diagnostics to stderr only, so a note and the error it refers to stay together. forwardLines(child.stdout, (line) => - logger.output(line, { data: { command, stream: 'stdout' }, stream: 'stdout' })); + logger.output(line, { data: { command, stream: 'stdout' } })); forwardLines(child.stderr, (line) => - logger.output(line, { data: { command, stream: 'stderr' }, stream: 'stderr' })); + logger.output(line, { data: { command, stream: 'stderr' }, level: 'warn' })); } child.once('error', (cause: Error) => { reject(new ToolchainSpawnFailedError(basename(executable), { cause })); @@ -256,6 +261,7 @@ async function downloadZig(requestedVersion?: string): Promise<{ version: string throw new ZigInstallFailedError(`No Zig ${version} package available for ${platformKey()}.`); } + logger.debug(`Downloading Zig ${version}`, { url: artifact.tarball }); let archiveResponse: Response; try { archiveResponse = await fetch(artifact.tarball); @@ -345,12 +351,19 @@ export async function ensureZig(version?: string): Promise { const home = marmottaHome(); const zigDirectory = configuredZigDirectory(); const zig = zigDirectory === undefined ? await findZig(home, version) : await configuredZig(zigDirectory); - return withZigEnvironment(home, zig); + const command = withZigEnvironment(home, zig); + logger.debug(`Using Zig: ${command.executable}`, { + executable: command.executable, + home: home.path, + cacheDirectory: command.cacheDirectory, + }); + return command; } export async function listZigVersions(): Promise { const root = zigRoot(marmottaHome()); + logger.debug(`Reading Zig versions in ${root}`); try { return (await readdir(root, { withFileTypes: true })) .filter((entry) => entry.isDirectory() && !entry.name.startsWith('.')) diff --git a/test/cli.test.js b/test/cli.test.js index 194039e..d4655f9 100644 --- a/test/cli.test.js +++ b/test/cli.test.js @@ -48,6 +48,24 @@ test('reports an unknown command with an error code', () => { assert.equal(result.status, 2); assert.match(result.stderr, /CLI_COMMAND_ERROR/); assert.match(result.stderr, /Unknown command/); + assert.match(result.stderr, /Usage: marmotta /); +}); + +test('rejects command options given without a command', () => { + for (const args of [['--debug'], ['-C', '.'], ['--target', 'x86_64-linux'], ['--json', '-o', 'build']]) { + const result = spawnSync(process.execPath, [cli, ...args], { encoding: 'utf8' }); + assert.equal(result.status, 2, args.join(' ')); + assert.equal(result.stdout.length, 0, args.join(' ')); + assert.match(result.stderr, /CLI_COMMAND_ERROR/, args.join(' ')); + assert.match(result.stderr, /Missing command/, args.join(' ')); + } + + const text = spawnSync(process.execPath, [cli, '--debug'], { encoding: 'utf8' }); + assert.match(text.stderr, /Usage: marmotta /); + // --json alone only selects the format, so it still shows help. + const json = spawnSync(process.execPath, [cli, '--json'], { encoding: 'utf8' }); + assert.equal(json.status, 0, json.stderr); + assert.match(JSON.parse(json.stdout).message, /^Marmotta - build tool/); }); test('classifies invalid options as argument errors', () => { @@ -339,6 +357,41 @@ test('still reports the final error when MARMOTTA_LOG hides diagnostics', () => assert.equal(entry.data.code, 'MARMOTTA_HOME_INVALID'); }); +test('MARMOTTA_LOG=debug shows diagnostics that the default level hides', async () => { + const home = await mkdtemp(join(tmpdir(), 'marmotta-debug-')); + try { + const run = (level) => spawnSync(process.execPath, [cli, 'list', '--json'], { + encoding: 'utf8', + env: level === undefined ? { ...process.env, MARMOTTA_HOME: home } : { ...process.env, MARMOTTA_HOME: home, MARMOTTA_LOG: level }, + }); + const levels = (result) => result.stdout.split('\n').filter((line) => line.length > 0).map((line) => JSON.parse(line).level); + + const quiet = run(undefined); + assert.equal(quiet.status, 0, quiet.stderr); + assert.deepEqual(levels(quiet), ['info']); + + const loud = run('debug'); + assert.equal(loud.status, 0, loud.stderr); + assert.deepEqual(levels(loud), ['debug', 'info']); + } finally { + await rm(home, { recursive: true, force: true }); + } +}); + +test('warns about an invalid MARMOTTA_LOG value in the requested format', () => { + const env = { ...process.env, MARMOTTA_LOG: 'bogus' }; + const json = spawnSync(process.execPath, [cli, '--version', '--json'], { encoding: 'utf8', env }); + assert.equal(json.status, 0, json.stderr); + assert.equal(JSON.parse(json.stdout).message, 'marmotta 0.6.0'); + const warning = JSON.parse(json.stderr); + assert.equal(warning.level, 'warn'); + assert.match(warning.message, /ignoring invalid MARMOTTA_LOG value "bogus"/); + + const text = spawnSync(process.execPath, [cli, '--version'], { encoding: 'utf8', env }); + assert.equal(text.stdout, 'marmotta 0.6.0\n'); + assert.match(text.stderr, /^marmotta: ignoring invalid MARMOTTA_LOG value "bogus"/); +}); + test('rejects --version combined with a command', () => { for (const args of [['build', '--version'], ['remove', '0.13.0', '-v'], ['--json', 'build', '--version']]) { const result = spawnSync(process.execPath, [cli, ...args], { encoding: 'utf8' }); @@ -383,10 +436,9 @@ test('keeps Zig compiler errors in --json output when MARMOTTA_LOG=error', { ski assert.equal(result.status, 1, result.stdout || result.stderr); const entries = result.stderr.split('\n').filter((line) => line.length > 0).map((line) => JSON.parse(line)); - assert.ok( - entries.some((entry) => entry.data?.command === 'zig' && entry.data?.stream === 'stderr'), - 'Zig compiler output must survive MARMOTTA_LOG=error', - ); + const compilerEntries = entries.filter((entry) => entry.data?.command === 'zig' && entry.data?.stream === 'stderr'); + assert.ok(compilerEntries.length > 0, 'Zig compiler output must survive MARMOTTA_LOG=error'); + assert.ok(compilerEntries.every((entry) => entry.level === 'warn'), 'stderr records must not claim level info'); assert.ok(entries.some((entry) => entry.data?.code === 'TOOLCHAIN_COMMAND_FAILED')); } finally { await rm(directory, { recursive: true, force: true }); diff --git a/test/logger.test.js b/test/logger.test.js index 6f9e662..b0662d0 100644 --- a/test/logger.test.js +++ b/test/logger.test.js @@ -76,11 +76,11 @@ test('uses the same sink contract in both formats', () => { test('never filters command output with the level', () => { const json = capture('json', 'error'); json.logger.output('marmotta 0.6.0'); - json.logger.output('compiler error', { data: { command: 'zig', stream: 'stderr' }, stream: 'stderr' }); + json.logger.output('compiler error', { data: { command: 'zig', stream: 'stderr' }, level: 'warn' }); json.logger.info('hidden'); json.logger.debug('hidden'); assert.deepEqual(records(json.stdout).map((record) => record.message), ['marmotta 0.6.0']); - assert.deepEqual(records(json.stderr).map((record) => record.message), ['compiler error']); + assert.deepEqual(records(json.stderr).map((record) => [record.level, record.message]), [['warn', 'compiler error']]); const text = capture('text', 'error'); text.logger.output('marmotta 0.6.0'); @@ -142,22 +142,35 @@ test('debug records are hidden until the level allows them', () => { assert.deepEqual(text.stderr, ['shown']); }); +test('routes warn and error records to stderr only', () => { + const { logger, stdout, stderr } = capture('json', 'trace'); + logger.debug('debug record'); + logger.output('result'); + logger.warn('warning'); + logger.failure('failed', { code: 'SOMETHING' }); + + assert.deepEqual(records(stdout).map((record) => record.level), ['debug', 'info']); + assert.deepEqual(records(stderr).map((record) => record.level), ['warn', 'error']); +}); + test('falls back to info for an invalid MARMOTTA_LOG value', () => { - const stdout = []; - const stderr = []; - const logger = new Logger({ format: 'json', level: 'bogus', stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line) }); + const { logger, stdout, stderr } = capture('json', 'bogus'); logger.info('visible'); logger.debug('hidden'); + assert.deepEqual(stderr, [], 'the warning is written only by checkLevel()'); - assert.match(stderr[0], /ignoring invalid MARMOTTA_LOG value/); + logger.checkLevel(); + logger.checkLevel(); + assert.equal(stderr.length, 1, 'the warning is written once'); + assert.equal(records(stderr)[0].level, 'warn'); + assert.match(records(stderr)[0].message, /ignoring invalid MARMOTTA_LOG value "bogus"/); assert.equal(records(stdout).length, 1); }); test('rejects inherited property names as levels', () => { for (const level of ['constructor', '__proto__', 'toString']) { - const stdout = []; - const stderr = []; - const logger = new Logger({ format: 'json', level, stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line) }); + const { logger, stdout, stderr } = capture('json', level); + logger.checkLevel(); logger.info('visible'); logger.debug('hidden'); @@ -167,9 +180,8 @@ test('rejects inherited property names as levels', () => { }); test('treats an empty level as unset', () => { - const stdout = []; - const stderr = []; - const logger = new Logger({ format: 'json', level: '', stdout: (line) => stdout.push(line), stderr: (line) => stderr.push(line) }); + const { logger, stdout, stderr } = capture('json', ''); + logger.checkLevel(); logger.info('visible'); logger.debug('hidden'); @@ -177,6 +189,18 @@ test('treats an empty level as unset', () => { assert.equal(records(stdout).length, 1); }); +test('accepts silent as a level that hides every diagnostic but not command output', () => { + for (const format of ['json', 'text']) { + const { logger, stdout, stderr } = capture(format, 'silent'); + logger.checkLevel(); + logger.error('hidden'); + logger.output('result'); + + assert.deepEqual(stderr, [], format); + assert.equal(stdout.length, 1, format); + } +}); + test('MARMOTTA_LOG configures the default logger level', () => { // A file:// URL imports correctly on Windows, where "D:\..." is read as a URL scheme. const moduleUrl = new URL('../dist/logger.js', import.meta.url).href;