Skip to content

Commit

Permalink
fix the race between timeout and close in proc.execute (#2662)
Browse files Browse the repository at this point in the history 
Co-authored-by: Colen Garoutte-Carson <[email protected]>
  • Loading branch information
@elahehrashedi @Colengms
elahehrashedi and Colengms authored Aug 1, 2022
1 parent 71bed0c commit 4898736
Show file tree
Hide file tree
Showing 2 changed files with 71 additions and 77 deletions.
4 changes: 2 additions & 2 deletions src/kit.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down
144 changes: 69 additions & 75 deletions src/proc.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<ExecutionResult>;
const useTask = (options && options.useTask) ? options.useTask : false;
Expand All @@ -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({
Expand All @@ -164,94 +168,84 @@ export function execute(command: string, args?: string[], outputConsumer?: Outpu
})
};
}

if (options.encoding) {
child.stdout?.setEncoding(options.encoding);
}

const encoding = options.outputEncoding && iconv.encodingExists(options.outputEncoding) ? options.outputEncoding : 'utf8';

result = new Promise<ExecutionResult>(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 };
Expand Down

0 comments on commit 4898736

Please sign in to comment.