diff --git a/__tests__/fixtures/stdio-lifecycle-child.js b/__tests__/fixtures/stdio-lifecycle-child.js new file mode 100644 index 0000000..ac8ae4d --- /dev/null +++ b/__tests__/fixtures/stdio-lifecycle-child.js @@ -0,0 +1,39 @@ +const { createStdIoState, handleStdIoStreamError } = require('../../server-lifecycle'); + +const mode = process.argv[2]; +const stdioState = createStdIoState(); + +function shutdown(reason, code) { + process.stderr.write(`shutdown:${reason}:${code}\n`); + process.exit(code); +} + +process.stdout.on('error', (error) => { + handleStdIoStreamError('stdout', error, { + stdioState, + addBreadcrumb: () => {}, + captureException: () => {}, + shutdown + }); +}); + +process.stderr.on('error', (error) => { + handleStdIoStreamError('stderr', error, { + stdioState, + addBreadcrumb: () => {}, + captureException: () => {}, + shutdown + }); +}); + +if (mode === 'stdout-broken') { + console.log('first'); + const interval = setInterval(() => { + console.log(`tick-${Date.now()}`); + }, 10); + + setTimeout(() => { + clearInterval(interval); + process.exit(99); + }, 500); +} diff --git a/__tests__/server-lifecycle.test.js b/__tests__/server-lifecycle.test.js new file mode 100644 index 0000000..cf0dc63 --- /dev/null +++ b/__tests__/server-lifecycle.test.js @@ -0,0 +1,191 @@ +import { describe, test, expect } from 'bun:test'; +import { spawn } from 'child_process'; +import path from 'path'; +import { + createStdIoState, + handleProcessFailure, + handleStdIoStreamError, + isBrokenPipeError +} from '../server-lifecycle.js'; + +function createBrokenPipeError() { + const error = new Error('write EPIPE'); + error.code = 'EPIPE'; + error.errno = 'EPIPE'; + return error; +} + +function runBrokenPipeFixture(fixturePath, timeoutMs = 2000) { + return new Promise((resolve, reject) => { + const child = spawn('node', [fixturePath, 'stdout-broken'], { + cwd: process.cwd(), + stdio: ['ignore', 'pipe', 'pipe'] + }); + let stdout = ''; + let stderr = ''; + let closedStdout = false; + let settled = false; + + const timeout = setTimeout(() => { + child.kill('SIGKILL'); + reject(new Error(`child timed out after ${timeoutMs}ms`)); + }, timeoutMs); + + function closeStdoutAfterFirstLine() { + if (closedStdout || !stdout.includes('\n')) { + return; + } + + closedStdout = true; + child.stdout.pause(); + child.stdout.destroy(); + } + + child.stdout.on('data', (chunk) => { + stdout += chunk.toString(); + closeStdoutAfterFirstLine(); + }); + child.stderr.on('data', (chunk) => { + stderr += chunk.toString(); + }); + + child.on('error', (error) => { + if (settled) { + return; + } + settled = true; + clearTimeout(timeout); + reject(error); + }); + + child.on('close', (code, signal) => { + if (settled) { + return; + } + settled = true; + clearTimeout(timeout); + resolve({ code, signal, stdout, stderr, closedStdout }); + }); + }); +} + +describe('isBrokenPipeError', () => { + test('detects common broken-pipe shapes', () => { + expect(isBrokenPipeError(createBrokenPipeError())).toBe(true); + expect(isBrokenPipeError({ errno: 'EPIPE' })).toBe(true); + expect(isBrokenPipeError(new Error('stream failed with EPIPE'))).toBe(true); + }); + + test('ignores unrelated errors', () => { + expect(isBrokenPipeError(new Error('permission denied'))).toBe(false); + expect(isBrokenPipeError({ code: 'ENOENT' })).toBe(false); + }); +}); + +describe('createStdIoState', () => { + test('suppresses repeated writes after an stdout broken pipe and emits telemetry once', () => { + const telemetry = []; + const stdioState = createStdIoState({ + onBrokenPipeTelemetry: (details) => telemetry.push(details) + }); + const fakeConsole = { + log() { + throw createBrokenPipeError(); + } + }; + + expect(stdioState.writeLog('log', 'stdout', 'first', [], fakeConsole)).toBe(false); + expect(stdioState.writeLog('log', 'stdout', 'second', [], fakeConsole)).toBe(false); + expect(telemetry).toHaveLength(1); + expect(stdioState.state).toMatchObject({ + stdoutBrokenPipe: true, + stderrBrokenPipe: false, + brokenPipeTelemetrySent: true + }); + }); +}); + +describe('handleStdIoStreamError', () => { + test('gracefully shuts down on stdout EPIPE', () => { + const telemetry = []; + const shutdownCalls = []; + const stdioState = createStdIoState({ + onBrokenPipeTelemetry: (details) => telemetry.push(details) + }); + + handleStdIoStreamError('stdout', createBrokenPipeError(), { + stdioState, + addBreadcrumb: () => {}, + captureException: () => {}, + shutdown: (reason, code) => shutdownCalls.push({ reason, code }) + }); + + expect(shutdownCalls).toEqual([{ reason: 'stdout-epipe', code: 0 }]); + expect(telemetry).toHaveLength(1); + }); + + test('keeps non-broken-pipe stdio errors fatal', () => { + const breadcrumbs = []; + const exceptions = []; + const shutdownCalls = []; + const error = new Error('stream failure'); + + handleStdIoStreamError('stderr', error, { + stdioState: createStdIoState(), + addBreadcrumb: (...args) => breadcrumbs.push(args), + captureException: (...args) => exceptions.push(args), + shutdown: (reason, code) => shutdownCalls.push({ reason, code }) + }); + + expect(breadcrumbs).toHaveLength(1); + expect(exceptions).toHaveLength(1); + expect(shutdownCalls).toEqual([{ reason: 'stderr-error', code: 1 }]); + }); +}); + +describe('handleProcessFailure', () => { + test('keeps uncaught EPIPE fatal outside stdio handlers', () => { + const shutdownCalls = []; + const exceptions = []; + const logCalls = []; + + handleProcessFailure('uncaughtException', createBrokenPipeError(), { + addBreadcrumb: () => {}, + captureException: (...args) => exceptions.push(args), + logError: (...args) => logCalls.push(args), + shutdown: (reason, code) => shutdownCalls.push({ reason, code }) + }); + + expect(exceptions).toHaveLength(1); + expect(logCalls).toHaveLength(1); + expect(shutdownCalls).toEqual([{ reason: 'uncaughtException', code: 1 }]); + }); + + test('keeps unhandledRejection EPIPE fatal outside stdio handlers', () => { + const shutdownCalls = []; + const exceptions = []; + const logCalls = []; + + handleProcessFailure('unhandledRejection', createBrokenPipeError(), { + addBreadcrumb: () => {}, + captureException: (...args) => exceptions.push(args), + logError: (...args) => logCalls.push(args), + shutdown: (reason, code) => shutdownCalls.push({ reason, code }) + }); + + expect(exceptions).toHaveLength(1); + expect(logCalls).toHaveLength(1); + expect(shutdownCalls).toEqual([{ reason: 'unhandledRejection', code: 1 }]); + }); +}); + +describe('broken pipe integration', () => { + test('exits cleanly after stdout closes', async () => { + const fixturePath = path.join(process.cwd(), '__tests__', 'fixtures', 'stdio-lifecycle-child.js'); + const result = await runBrokenPipeFixture(fixturePath); + expect(result.closedStdout).toBe(true); + expect(result.stdout.startsWith('first\n')).toBe(true); + expect(result.code).toBe(0); + expect(result.stderr).toContain('shutdown:stdout-epipe:0'); + }); +}); diff --git a/package.json b/package.json index f01c259..1830f7b 100644 --- a/package.json +++ b/package.json @@ -7,7 +7,7 @@ "server": "cross-env FONT_DATA_DIR=assets/onlyoffice-fontdata node server.js", "test": "bun run test:unit && bun run test:e2e", "test:all": "bun run test:unit && bun run test:e2e", - "test:unit": "bun test __tests__/server-utils.test.js __tests__/desktop-stub-utils.test.js __tests__/generate-office-fonts-path.test.js __tests__/offline-loader-config.test.js && node test-url-scheme.js", + "test:unit": "bun test __tests__/server-utils.test.js __tests__/server-lifecycle.test.js __tests__/desktop-stub-utils.test.js __tests__/generate-office-fonts-path.test.js __tests__/offline-loader-config.test.js && node test-url-scheme.js", "test:e2e": "bun run test:console-batch && bun run test:logo && bun run test:save", "test:console-batch": "node test-console-batch.js", "test:logo": "node __tests__/logo-header.test.js", diff --git a/server-lifecycle.js b/server-lifecycle.js new file mode 100644 index 0000000..39d5cfb --- /dev/null +++ b/server-lifecycle.js @@ -0,0 +1,170 @@ +function isBrokenPipeError(error) { + const message = error && typeof error.message === 'string' ? error.message : ''; + const mentionsBrokenPipe = /\bEPIPE\b/.test(message); + return Boolean(error && ( + error.code === 'EPIPE' + || error.errno === 'EPIPE' + || mentionsBrokenPipe + )); +} + +function getErrorOwnProperties(error) { + if (!error || typeof error !== 'object') { + return {}; + } + + const details = {}; + for (const key of Object.getOwnPropertyNames(error)) { + details[key] = error[key]; + } + + return details; +} + +function createStdIoState(options = {}) { + const { onBrokenPipeTelemetry } = options; + const state = { + stdoutBrokenPipe: false, + stderrBrokenPipe: false, + brokenPipeTelemetrySent: false + }; + + function markBrokenPipeStream(streamName, error) { + if (streamName === 'stdout') { + state.stdoutBrokenPipe = true; + } else { + state.stderrBrokenPipe = true; + } + + if (state.brokenPipeTelemetrySent) { + return; + } + + state.brokenPipeTelemetrySent = true; + if (typeof onBrokenPipeTelemetry === 'function') { + onBrokenPipeTelemetry({ + event: 'stdio broken pipe', + stream: streamName, + timestamp: new Date().toISOString(), + pid: process.pid, + ppid: process.ppid, + runtime: typeof Bun !== 'undefined' && typeof Bun.version === 'string' + ? `bun-${Bun.version}` + : `node-${process.versions.node}`, + brokenPipeState: { ...state }, + errorType: error && error.constructor ? error.constructor.name : typeof error, + error: { + name: error && error.name ? error.name : 'Error', + message: error && error.message ? error.message : 'write EPIPE', + code: error && error.code ? error.code : 'EPIPE', + errno: error && error.errno ? error.errno : 'EPIPE', + syscall: error && error.syscall ? error.syscall : null, + stack: error && error.stack ? error.stack : null, + ownProperties: getErrorOwnProperties(error) + } + }); + } + } + + function isStreamBroken(streamName) { + return streamName === 'stdout' ? state.stdoutBrokenPipe : state.stderrBrokenPipe; + } + + function writeLog(method, streamName, formattedMessage, args = [], consoleLike = console) { + if (isStreamBroken(streamName)) { + return false; + } + + try { + consoleLike[method](formattedMessage, ...args); + return true; + } catch (error) { + if (isBrokenPipeError(error)) { + markBrokenPipeStream(streamName, error); + return false; + } + + throw error; + } + } + + return { + state, + markBrokenPipeStream, + writeLog + }; +} + +function handleStdIoStreamError(streamName, error, handlers) { + const { + stdioState, + addBreadcrumb, + captureException, + shutdown + } = handlers; + + if (isBrokenPipeError(error)) { + stdioState.markBrokenPipeStream(streamName, error); + shutdown(`${streamName}-epipe`, 0); + return; + } + + addBreadcrumb('stdio stream error', { + stream: streamName, + message: error && error.message ? error.message : String(error) + }, { + category: 'oo-editors.process', + level: 'error' + }); + captureException(error, { + level: 'error', + tags: { + phase: 'stdio', + stream: streamName + } + }); + shutdown(`${streamName}-error`, 1); +} + +function handleProcessFailure(kind, error, handlers) { + const { + addBreadcrumb, + captureException, + logError, + shutdown + } = handlers; + + if (kind === 'unhandledRejection') { + addBreadcrumb('unhandled rejection', { + reason: error instanceof Error ? error.message : String(error) + }, { + category: 'oo-editors.process', + level: 'error' + }); + } else { + addBreadcrumb('uncaught exception', { + message: error && error.message ? error.message : String(error), + name: error && error.name ? error.name : 'Error' + }, { + category: 'oo-editors.process', + level: 'error' + }); + } + + captureException(error, { + level: 'fatal', + tags: { + phase: kind + } + }); + logError('PROCESS', kind === 'unhandledRejection' ? 'unhandled rejection:' : 'uncaught exception:', error); + shutdown(kind, 1); +} + +module.exports = { + createStdIoState, + getErrorOwnProperties, + handleProcessFailure, + handleStdIoStreamError, + isBrokenPipeError +}; diff --git a/server.js b/server.js index 8f67dc5..f9de705 100644 --- a/server.js +++ b/server.js @@ -12,6 +12,11 @@ const { captureLifecycleException, flushSentry } = require('./sentry'); +const { + createStdIoState, + handleProcessFailure, + handleStdIoStreamError +} = require('./server-lifecycle'); const { getX2TFormatCode, getOutputFormatInfo, @@ -29,6 +34,14 @@ const { const LOG_NAMESPACE = 'oo-editors'; const SHUTDOWN_FORCE_EXIT_TIMEOUT_MS = 5000; +const stdioState = createStdIoState({ + onBrokenPipeTelemetry: (details) => { + addLifecycleBreadcrumb('stdio broken pipe', details, { + category: 'oo-editors.process', + level: 'warning' + }); + } +}); function normalizeLogScope(scope) { return Array.isArray(scope) ? scope : [scope]; @@ -38,16 +51,20 @@ function formatLogScope(scope) { return `[${LOG_NAMESPACE}:${normalizeLogScope(scope).join(':')}]`; } +function writeLog(method, streamName, scope, message, args) { + stdioState.writeLog(method, streamName, `${formatLogScope(scope)} ${message}`, args, console); +} + function logInfo(scope, message, ...args) { - console.log(`${formatLogScope(scope)} ${message}`, ...args); + writeLog('log', 'stdout', scope, message, args); } function logWarn(scope, message, ...args) { - console.log(`${formatLogScope(scope)} ${message}`, ...args); + writeLog('log', 'stdout', scope, message, args); } function logError(scope, message, ...args) { - console.error(`${formatLogScope(scope)} ${message}`, ...args); + writeLog('error', 'stderr', scope, message, args); } initOoEditorsSentry(); @@ -329,6 +346,22 @@ function shutdownServer(reason, exitCode) { }); } +process.stdout.on('error', (error) => { + handleStdIoStreamError('stdout', error, { + stdioState, + addBreadcrumb: addLifecycleBreadcrumb, + captureException: captureLifecycleException, + shutdown: shutdownServer + }); +}); +process.stderr.on('error', (error) => { + handleStdIoStreamError('stderr', error, { + stdioState, + addBreadcrumb: addLifecycleBreadcrumb, + captureException: captureLifecycleException, + shutdown: shutdownServer + }); +}); process.on('SIGTERM', () => shutdownServer('SIGTERM', 0)); process.on('SIGINT', () => shutdownServer('SIGINT', 0)); process.on('disconnect', () => shutdownServer('disconnect', 0)); @@ -339,37 +372,20 @@ process.on('exit', (code) => { logInfo('PROCESS', `exit with code ${code}`); }); process.on('uncaughtException', (err) => { - addLifecycleBreadcrumb('uncaught exception', { - message: err.message, - name: err.name - }, { - category: 'oo-editors.process', - level: 'error' - }); - captureLifecycleException(err, { - level: 'fatal', - tags: { - phase: 'uncaughtException' - } + handleProcessFailure('uncaughtException', err, { + addBreadcrumb: addLifecycleBreadcrumb, + captureException: captureLifecycleException, + logError, + shutdown: shutdownServer }); - logError('PROCESS', 'uncaught exception:', err); - shutdownServer('uncaughtException', 1); }); process.on('unhandledRejection', (reason) => { - addLifecycleBreadcrumb('unhandled rejection', { - reason: reason instanceof Error ? reason.message : String(reason) - }, { - category: 'oo-editors.process', - level: 'error' - }); - captureLifecycleException(reason, { - level: 'fatal', - tags: { - phase: 'unhandledRejection' - } + handleProcessFailure('unhandledRejection', reason, { + addBreadcrumb: addLifecycleBreadcrumb, + captureException: captureLifecycleException, + logError, + shutdown: shutdownServer }); - logError('PROCESS', 'unhandled rejection:', reason); - shutdownServer('unhandledRejection', 1); }); // API Endpoint: Health check