From 489873691e47e07cc6b4d65734c86043cb07d63b Mon Sep 17 00:00:00 2001 From: Elaheh Rashedi Date: Mon, 1 Aug 2022 15:47:22 -0700 Subject: [PATCH] fix the race between timeout and close in proc.execute (#2662) Co-authored-by: Colen Garoutte-Carson --- src/kit.ts | 4 +- src/proc.ts | 144 +++++++++++++++++++++++++--------------------------- 2 files changed, 71 insertions(+), 77 deletions(-) diff --git a/src/kit.ts b/src/kit.ts index 127ae225b..a98b2c2dd 100644 --- a/src/kit.ts +++ b/src/kit.ts @@ -157,8 +157,8 @@ export async function getCompilerVersion(vendor: CompilerVendorEnum, binPath: st if (pr) { pr.report({ message: localize('getting.compiler.version', 'Getting {0} version for {1}', vendor, binPath) }); } - const exec = await proc.execute(binPath, ['-v'], undefined, { overrideLocale: true, timeout: 30000 }).result; - if (exec.retc !== 0) { + const exec = await proc.execute(binPath, ['-v'], undefined, { overrideLocale: true, timeout: 60000 }).result; + if (exec.retc !== 0 && !exec.stderr) { log.debug(localize('bad.compiler.binary', 'Bad {0} binary ("-v" returns {1}): {2}', vendor, exec.retc, binPath)); return null; } diff --git a/src/proc.ts b/src/proc.ts index 019967680..b7b9b7fd9 100644 --- a/src/proc.ts +++ b/src/proc.ts @@ -131,9 +131,13 @@ export function execute(command: string, args?: string[], outputConsumer?: Outpu env: final_env, shell: !!options.shell }; - if (options && options.cwd) { + if (options?.cwd !== undefined) { spawn_opts.cwd = options.cwd; } + if (options?.timeout) { + spawn_opts.timeout = options.timeout; + } + let child: proc.ChildProcess | undefined; let result: Promise; const useTask = (options && options.useTask) ? options.useTask : false; @@ -154,7 +158,7 @@ export function execute(command: string, args?: string[], outputConsumer?: Outpu } catch { child = undefined; } - if (child === undefined) { + if (!child) { return { child: undefined, result: Promise.resolve({ @@ -164,6 +168,7 @@ export function execute(command: string, args?: string[], outputConsumer?: Outpu }) }; } + if (options.encoding) { child.stdout?.setEncoding(options.encoding); } @@ -171,87 +176,76 @@ export function execute(command: string, args?: string[], outputConsumer?: Outpu const encoding = options.outputEncoding && iconv.encodingExists(options.outputEncoding) ? options.outputEncoding : 'utf8'; result = new Promise(resolve => { - if (child) { - let stdout_acc = ''; - let line_acc = ''; - let stderr_acc = ''; - let stderr_line_acc = ''; - let timeoutId: NodeJS.Timeout; - child.on('error', err => { - if (timeoutId) { - clearTimeout(timeoutId); + let stdout_acc = ''; + let line_acc = ''; + let stderr_acc = ''; + let stderr_line_acc = ''; + child?.on('error', err => { + log.warning(localize('process.error', 'The command: {0} failed with error: {1}', `${cmdstr}`, `${err}`)); + }); + child?.on('exit', (code, signal) => { + if (code !== 0) { + log.warning(localize('process.exit', 'The command: {0} exited with code: {1} and signal: {2}', `${cmdstr}`, `${code}`, `${signal}`)); + } + }); + child?.stdout?.on('data', (data: Uint8Array) => { + rollbar.invoke(localize('processing.data.event.stdout', 'Processing "data" event from proc stdout'), { data, command, args }, () => { + const str = iconv.decode(Buffer.from(data), encoding); + const lines = str.split('\n').map(l => l.endsWith('\r') ? l.substr(0, l.length - 1) : l); + while (lines.length > 1) { + line_acc += lines[0]; + if (outputConsumer) { + outputConsumer.output(line_acc); + } else if (util.isTestMode()) { + log.info(line_acc); + } + line_acc = ''; + // Erase the first line from the list + lines.splice(0, 1); } - resolve({ retc: -1, stdout: "", stderr: err.message ?? '' }); + console.assert(lines.length, 'Invalid lines', JSON.stringify(lines)); + line_acc += lines[0]; + stdout_acc += str; }); - child.stdout?.on('data', (data: Uint8Array) => { - rollbar.invoke(localize('processing.data.event.stdout', 'Processing "data" event from proc stdout'), { data, command, args }, () => { - const str = iconv.decode(Buffer.from(data), encoding); - const lines = str.split('\n').map(l => l.endsWith('\r') ? l.substr(0, l.length - 1) : l); - while (lines.length > 1) { - line_acc += lines[0]; - if (outputConsumer) { - outputConsumer.output(line_acc); - } else if (util.isTestMode()) { - log.info(line_acc); - } - line_acc = ''; - // Erase the first line from the list - lines.splice(0, 1); + }); + child?.stderr?.on('data', (data: Uint8Array) => { + rollbar.invoke(localize('processing.data.event.stderr', 'Processing "data" event from proc stderr'), { data, command, args }, () => { + const str = iconv.decode(Buffer.from(data), encoding); + const lines = str.split('\n').map(l => l.endsWith('\r') ? l.substr(0, l.length - 1) : l); + while (lines.length > 1) { + stderr_line_acc += lines[0]; + if (outputConsumer) { + outputConsumer.error(stderr_line_acc); + } else if (util.isTestMode() && stderr_line_acc) { + log.info(stderr_line_acc); } - console.assert(lines.length, 'Invalid lines', JSON.stringify(lines)); - line_acc += lines[0]; - stdout_acc += str; - }); + stderr_line_acc = ''; + // Erase the first line from the list + lines.splice(0, 1); + } + console.assert(lines.length, 'Invalid lines', JSON.stringify(lines)); + stderr_line_acc += lines[0]; + stderr_acc += str; }); - child.stderr?.on('data', (data: Uint8Array) => { - rollbar.invoke(localize('processing.data.event.stderr', 'Processing "data" event from proc stderr'), { data, command, args }, () => { - const str = iconv.decode(Buffer.from(data), encoding); - const lines = str.split('\n').map(l => l.endsWith('\r') ? l.substr(0, l.length - 1) : l); - while (lines.length > 1) { - stderr_line_acc += lines[0]; - if (outputConsumer) { - outputConsumer.error(stderr_line_acc); - } else if (util.isTestMode() && stderr_line_acc) { - log.info(stderr_line_acc); - } - stderr_line_acc = ''; - // Erase the first line from the list - lines.splice(0, 1); + }); + // The 'close' event is emitted after a process has ended and the stdio streams of a child process have been closed. + // This is distinct from the 'exit' event, since multiple processes might share the same stdio streams. + // The 'close' event will always emit after 'exit' was already emitted, or 'error' if the child failed to spawn. + child?.on('close', retc => { + try { + rollbar.invoke(localize('resolving.close.event', 'Resolving process on "close" event'), { line_acc, stderr_line_acc, command, retc }, () => { + if (line_acc && outputConsumer) { + outputConsumer.output(line_acc); } - console.assert(lines.length, 'Invalid lines', JSON.stringify(lines)); - stderr_line_acc += lines[0]; - stderr_acc += str; - }); - }); - // Don't stop until the child stream is closed, otherwise we might not read - // the whole output of the command. - child.on('close', retc => { - try { - if (timeoutId) { - clearTimeout(timeoutId); + if (stderr_line_acc && outputConsumer) { + outputConsumer.error(stderr_line_acc); } - rollbar.invoke(localize('resolving.close.event', 'Resolving process on "close" event'), { line_acc, stderr_line_acc, command, retc }, () => { - if (line_acc && outputConsumer) { - outputConsumer.output(line_acc); - } - if (stderr_line_acc && outputConsumer) { - outputConsumer.error(stderr_line_acc); - } - resolve({ retc, stdout: stdout_acc, stderr: stderr_acc }); - }); - } catch (_) { - // No error handling since Rollbar has taken the error. resolve({ retc, stdout: stdout_acc, stderr: stderr_acc }); - } - }); - if (options?.timeout) { - timeoutId = setTimeout(() => { - log.warning(localize('process.timeout', 'The command timed out: {0}', `${cmdstr}`)); - child?.kill(); - resolve({retc: -1, stdout: stdout_acc, stderr: stderr_acc }); - }, options.timeout); + }); + } catch (e: any) { + resolve({ retc, stdout: stdout_acc, stderr: stderr_acc }); } - } + }); }); } return { child, result };