fix: stream whisper output through logger

.github/workflows/ci.yml

@@ -28,6 +28,9 @@ jobs:
 
     - name: Run type check
       run: npm run typecheck
+
+    - name: Run unit tests
+      run: npm test
 
     - name: Format code
       run: npm run format

.github/workflows/integration.yml

@@ -27,7 +27,10 @@ jobs:
     - name: Install dependencies
       run: npm ci
 
-    - name: Run tests
+    - name: Run unit tests
+      run: npm test
+
+    - name: Run integration test
       env:
         NODEJS_WHISPER_CMAKE_ARGS: ${{ runner.os == 'macOS' && '-DGGML_NATIVE=OFF' || '' }}
-      run: npm test
+      run: npm run test:integration

README.md

@@ -57,7 +57,7 @@ npx nodejs-whisper download
 
 ## Usage/Examples
 
-See `example/index.ts` (can be run with `$ npm run test`)
+See `example/index.ts` (can be run with `$ npm run test:example`)
 
 ```javascript
 import path from 'path'
@@ -106,6 +106,10 @@ const MODELS_LIST = [
 ]
 ```
 
+The configured logger receives transcript output through `logger.log`, whisper.cpp initialization and progress
+details through `logger.debug`, and command failures through `logger.error`. Child-process output is not written
+directly to the parent process.
+
 Custom CMake flags can be passed with `NODEJS_WHISPER_CMAKE_ARGS`.
 
 ```bash
@@ -194,9 +198,24 @@ Start the server
 Build project
 
 ```bash
-  npm run build
+npm run build
+```
+
+Run the fast unit suite
+
+```bash
+npm test
 ```
 
+Run the end-to-end transcription test
+
+```bash
+npm run test:integration
+```
+
+The integration test downloads and builds `tiny.en` when needed, transcribes the bundled audio sample, verifies the
+returned transcript and VTT file, and checks that whisper.cpp output is routed through the configured logger.
+
 ## Made with
 
 -   [Whisper OpenAI (using C++ port by: ggerganov)](https://github.com/ggerganov/whisper.cpp)

package.json

@@ -1,6 +1,6 @@
 {
 	"name": "nodejs-whisper",
-	"version": "0.2.9",
+	"version": "0.3.1",
 	"description": "Node bindings for OpenAI's Whisper. Optimized for CPU.",
 	"main": "dist/index.js",
 	"types": "dist/index.d.ts",
@@ -17,10 +17,12 @@
 	"scripts": {
 		"start": "ts-node src/index.ts",
 		"dev": "nodemon --watch 'src/**/*.ts' --exec ts-node src/index.ts",
-		"test": "ts-node example/index.ts",
+		"test": "node --require ts-node/register --test test/*.test.js",
+		"test:integration": "node --require ts-node/register --test test/core.integration.js",
+		"test:example": "ts-node example/index.ts",
 		"typecheck": "tsc --noEmit",
 		"build": "tsc && chmod +x dist/downloadModel.js",
-		"format": "prettier --write src/**/*.ts"
+		"format": "prettier --write src/**/*.ts test/**/*.js"
 	},
 	"keywords": [
 		"OpenAI",

src/whisper.ts

@@ -12,7 +12,8 @@ export interface IShellOptions {
 }
 
 const defaultShellOptions: IShellOptions = {
-	silent: false,
+	// Route child output through the configured logger.
+	silent: true,
 	async: true,
 }
 
@@ -77,10 +78,8 @@ export async function whisperShell(
 			windowsHide: true, // Prevent command window popup on Windows
 		}
 
-		shell.exec(command, shellOptions, (code, stdout, stderr) => {
+		const child = shell.exec(command, shellOptions, (code, stdout, stderr) => {
 			logger.debug('Exit code:', code)
-			logger.debug('Stdout:', stdout)
-			logger.debug('Stderr:', stderr)
 
 			if (code === 0) {
 				if (stdout.includes('error:')) {
@@ -94,6 +93,11 @@ export async function whisperShell(
 				reject(new Error(stderr || `Command failed with exit code ${code}`))
 			}
 		})
+
+		child.stdout?.on('data', data => logger.log(data.toString()))
+		// whisper.cpp writes normal initialization and progress details to stderr,
+		// so keep those at debug level. Actual command failures are logged as errors.
+		child.stderr?.on('data', data => logger.debug(data.toString()))
 	}).catch((error: Error) => {
 		handleError(error, logger, projectDir)
 		return Promise.reject(error)

test/core.integration.js

@@ -0,0 +1,81 @@
+const assert = require('node:assert/strict')
+const fs = require('node:fs')
+const path = require('node:path')
+const test = require('node:test')
+
+const { nodewhisper } = require('../src/index')
+const { MODEL_OBJECT, WHISPER_CPP_PATH } = require('../src/constants')
+
+test(
+	'transcribes audio with tiny.en and routes whisper.cpp output through the logger',
+	{ timeout: 10 * 60 * 1000 },
+	async t => {
+		const audioFile = path.resolve(__dirname, '../example/mother_teresa.wav')
+		const outputFile = `${audioFile}.vtt`
+		const modelFile = path.join(WHISPER_CPP_PATH, 'models', MODEL_OBJECT['tiny.en'])
+		const loggerEvents = []
+		const leakedWhisperOutput = []
+		const logger = {
+			debug: (...args) => loggerEvents.push(['debug', ...args]),
+			error: (...args) => loggerEvents.push(['error', ...args]),
+			log: (...args) => loggerEvents.push(['log', ...args]),
+		}
+
+		fs.rmSync(outputFile, { force: true })
+		t.after(() => fs.rmSync(outputFile, { force: true }))
+
+		const originalStdoutWrite = process.stdout.write
+		const originalStderrWrite = process.stderr.write
+		const captureWhisperLeak = (stream, originalWrite) =>
+			function (chunk, ...args) {
+				const text = chunk.toString()
+				if (text.includes('whisper_init_with_params_no_state:') || text.includes('[00:00:')) {
+					leakedWhisperOutput.push([stream, text])
+					return true
+				}
+				return originalWrite.call(this, chunk, ...args)
+			}
+
+		process.stdout.write = captureWhisperLeak('stdout', originalStdoutWrite)
+		process.stderr.write = captureWhisperLeak('stderr', originalStderrWrite)
+
+		let transcript
+		try {
+			transcript = await nodewhisper(audioFile, {
+				modelName: 'tiny.en',
+				autoDownloadModelName: 'tiny.en',
+				logger,
+				whisperOptions: {
+					noGpu: true,
+					outputInVtt: true,
+					timestamps_length: 14,
+				},
+			})
+		} finally {
+			process.stdout.write = originalStdoutWrite
+			process.stderr.write = originalStderrWrite
+		}
+
+		const normalizedTranscript = transcript.replace(/\s+/g, ' ').toLowerCase()
+		const debugOutput = loggerEvents
+			.filter(([level]) => level === 'debug')
+			.flatMap(([, ...args]) => args)
+			.join(' ')
+		const loggedTranscript = loggerEvents
+			.filter(([level]) => level === 'log')
+			.flatMap(([, ...args]) => args)
+			.join(' ')
+
+		assert.equal(fs.existsSync(modelFile), true, 'tiny.en model should be available')
+		assert.match(normalizedTranscript, /i do not want.*your money/)
+		assert.match(normalizedTranscript, /i want your.*forgiveness/)
+		assert.match(loggedTranscript.toLowerCase(), /i do not want/)
+		assert.match(debugOutput, /whisper_init_with_params_no_state:/)
+		assert.deepEqual(leakedWhisperOutput, [])
+
+		assert.equal(fs.existsSync(outputFile), true, 'VTT output should be created')
+		const vtt = fs.readFileSync(outputFile, 'utf8').toLowerCase()
+		assert.match(vtt, /^webvtt/)
+		assert.match(vtt, /i do not want/)
+	}
+)

test/whisper.test.js

@@ -0,0 +1,92 @@
+const assert = require('node:assert/strict')
+const test = require('node:test')
+
+const { whisperShell } = require('../src/whisper')
+
+const quoteArgument = value => `"${value.replace(/"/g, '\\"')}"`
+
+test('whisperShell streams child output through the logger without leaking to the parent process', async () => {
+	const stdoutChunks = ['logger-routing-stdout-1', 'logger-routing-stdout-2']
+	const stderrChunk = 'logger-routing-stderr'
+	const childScript = [
+		`process.stdout.write('${stdoutChunks[0]}')`,
+		`setTimeout(() => {`,
+		`process.stderr.write('${stderrChunk}')`,
+		`process.stdout.write('${stdoutChunks[1]}')`,
+		`}, 50)`,
+	].join(';')
+	const encodedScript = Buffer.from(childScript).toString('base64')
+	const command = `${quoteArgument(process.execPath)} -e "eval(Buffer.from('${encodedScript}','base64').toString())"`
+
+	const loggerEvents = []
+	const leakedOutput = []
+	let commandCompleted = false
+	const logger = {
+		debug: (...args) => loggerEvents.push({ level: 'debug', args, commandCompleted }),
+		error: (...args) => loggerEvents.push({ level: 'error', args, commandCompleted }),
+		log: (...args) => loggerEvents.push({ level: 'log', args, commandCompleted }),
+	}
+
+	const originalStdoutWrite = process.stdout.write
+	const originalStderrWrite = process.stderr.write
+	process.stdout.write = function (chunk, ...args) {
+		const text = chunk.toString()
+		if (stdoutChunks.some(marker => text.includes(marker))) {
+			leakedOutput.push({ stream: 'stdout', text })
+			return true
+		}
+		return originalStdoutWrite.call(this, chunk, ...args)
+	}
+	process.stderr.write = function (chunk, ...args) {
+		const text = chunk.toString()
+		if (text.includes(stderrChunk)) {
+			leakedOutput.push({ stream: 'stderr', text })
+			return true
+		}
+		return originalStderrWrite.call(this, chunk, ...args)
+	}
+
+	let transcript
+	try {
+		transcript = await whisperShell(command, undefined, logger)
+		commandCompleted = true
+	} finally {
+		process.stdout.write = originalStdoutWrite
+		process.stderr.write = originalStderrWrite
+	}
+
+	assert.equal(transcript, stdoutChunks.join(''))
+	assert.deepEqual(leakedOutput, [])
+
+	const childOutputEvents = loggerEvents.filter(event => [...stdoutChunks, stderrChunk].includes(event.args[0]))
+	assert.deepEqual(
+		childOutputEvents.filter(event => event.level === 'log').map(event => event.args[0]),
+		stdoutChunks
+	)
+	assert.deepEqual(
+		childOutputEvents.filter(event => event.level === 'debug').map(event => event.args[0]),
+		[stderrChunk]
+	)
+	assert.ok(childOutputEvents.every(event => event.commandCompleted === false))
+})
+
+test('whisperShell rejects failed commands while preserving diagnostic output', async () => {
+	const stderrMessage = 'intentional-whisper-failure'
+	const encodedScript = Buffer.from(`process.stderr.write('${stderrMessage}'); process.exit(7)`).toString('base64')
+	const command = `${quoteArgument(process.execPath)} -e "eval(Buffer.from('${encodedScript}','base64').toString())"`
+	const events = []
+	const logger = {
+		debug: (...args) => events.push(['debug', ...args]),
+		error: (...args) => events.push(['error', ...args]),
+		log: (...args) => events.push(['log', ...args]),
+	}
+
+	await assert.rejects(() => whisperShell(command, undefined, logger), new RegExp(stderrMessage))
+	assert.ok(events.some(([level, message]) => level === 'debug' && message === stderrMessage))
+	assert.ok(
+		events.some(
+			([level, message, detail]) =>
+				level === 'error' && message === '[Nodejs-whisper] Error:' && detail.includes(stderrMessage)
+		)
+	)
+})