Skip to content

Commit 98dccbd

Browse files
localconstlocalconst
authored
Fix debug logs inside user commands (#1064)
* Move process exit and close logs to exec end * bump version * Add explanation comments * Add changelog
1 parent 6224ae1 commit 98dccbd

File tree

4 files changed

+74
-55
lines changed

4 files changed

+74
-55
lines changed

‎node/CHANGELOG.md

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,6 +2,10 @@
22

33
## 4.x
44

5+
## 4.17.1
6+
7+
- Fix debug logs inside user commands - [#1064](https://github.com/microsoft/azure-pipelines-task-lib/pull/1064)
8+
59
## 4.17.0
610

711
- Added signal handler for process execution to kill process with proper signal - [#1008](https://github.com/microsoft/azure-pipelines-task-lib/pull/1008)

‎node/package-lock.json

Lines changed: 1 addition & 1 deletion
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

‎node/package.json

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
{
22
"name": "azure-pipelines-task-lib",
3-
"version": "4.17.0",
3+
"version": "4.17.1",
44
"description": "Azure Pipelines Task SDK",
55
"main": "./task.js",
66
"typings": "./task.d.ts",

‎node/toolrunner.ts

Lines changed: 68 additions & 53 deletions
Original file line numberDiff line numberDiff line change
@@ -98,7 +98,7 @@ export class ToolRunner extends events.EventEmitter {
9898
if (c !== '"') {
9999
arg += '\\';
100100
} else {
101-
arg.slice(0, -1);
101+
arg.slice(0, -1);
102102
}
103103
}
104104
arg += c;
@@ -174,7 +174,7 @@ export class ToolRunner extends events.EventEmitter {
174174
// Windows (regular)
175175
else {
176176
commandParts.push(this._windowsQuoteCmdArg(toolPath));
177-
commandParts = commandParts.concat(args.map(arg =>this._windowsQuoteCmdArg(arg)));
177+
commandParts = commandParts.concat(args.map(arg => this._windowsQuoteCmdArg(arg)));
178178
}
179179
}
180180
else {
@@ -333,7 +333,7 @@ export class ToolRunner extends events.EventEmitter {
333333
return args;
334334
}
335335
} else if (options.shell) {
336-
return this.args.map(arg => {
336+
return this.args.map(arg => {
337337
if (this._isWrapped(arg, "'")) {
338338
return arg;
339339
}
@@ -636,7 +636,7 @@ export class ToolRunner extends events.EventEmitter {
636636
this._getSpawnArgs(optionsNonNull),
637637
this._getSpawnOptions(optionsNonNull));
638638

639-
waitingEvents ++;
639+
waitingEvents++;
640640
cp = child.spawn(
641641
pipeOutputToTool._getSpawnFileName(optionsNonNull),
642642
pipeOutputToTool._getSpawnArgs(optionsNonNull),
@@ -650,7 +650,7 @@ export class ToolRunner extends events.EventEmitter {
650650
fileStream.on('finish', () => {
651651
waitingEvents--; //file write is complete
652652
fileStream = null;
653-
if(waitingEvents == 0) {
653+
if (waitingEvents == 0) {
654654
if (error) {
655655
reject(error);
656656
} else {
@@ -662,7 +662,7 @@ export class ToolRunner extends events.EventEmitter {
662662
waitingEvents--; //there were errors writing to the file, write is done
663663
this._debug(`Failed to pipe output of ${toolPathFirst} to file ${this.pipeOutputToFile}. Error = ${err}`);
664664
fileStream = null;
665-
if(waitingEvents == 0) {
665+
if (waitingEvents == 0) {
666666
if (error) {
667667
reject(error);
668668
} else {
@@ -671,7 +671,7 @@ export class ToolRunner extends events.EventEmitter {
671671
}
672672
});
673673
}
674-
674+
675675
//pipe stdout of first tool to stdin of second tool
676676
cpFirst.stdout?.on('data', (data: Buffer) => {
677677
try {
@@ -703,7 +703,7 @@ export class ToolRunner extends events.EventEmitter {
703703
}
704704
cp.stdin?.end();
705705
error = new Error(toolPathFirst + ' failed. ' + err.message);
706-
if(waitingEvents == 0) {
706+
if (waitingEvents == 0) {
707707
reject(error);
708708
}
709709
});
@@ -719,77 +719,77 @@ export class ToolRunner extends events.EventEmitter {
719719
fileStream.end();
720720
}
721721
cp.stdin?.end();
722-
if(waitingEvents == 0) {
722+
if (waitingEvents == 0) {
723723
if (error) {
724724
reject(error);
725725
} else {
726726
resolve(returnCode);
727727
}
728728
}
729729
});
730-
730+
731731
var stdbuffer: string = '';
732732
cp.stdout?.on('data', (data: Buffer) => {
733733
this.emit('stdout', data);
734-
734+
735735
if (!optionsNonNull.silent) {
736736
optionsNonNull.outStream!.write(data);
737737
}
738-
738+
739739
this._processLineBuffer(data, stdbuffer, (line: string) => {
740740
this.emit('stdline', line);
741741
});
742742
});
743-
743+
744744
var errbuffer: string = '';
745745
cp.stderr?.on('data', (data: Buffer) => {
746746
this.emit('stderr', data);
747-
747+
748748
success = !optionsNonNull.failOnStdErr;
749749
if (!optionsNonNull.silent) {
750750
var s = optionsNonNull.failOnStdErr ? optionsNonNull.errStream! : optionsNonNull.outStream!;
751751
s.write(data);
752752
}
753-
753+
754754
this._processLineBuffer(data, errbuffer, (line: string) => {
755755
this.emit('errline', line);
756756
});
757757
});
758-
758+
759759
cp.on('error', (err: Error) => {
760760
waitingEvents--; //process is done with errors
761761
error = new Error(toolPath + ' failed. ' + err.message);
762-
if(waitingEvents == 0) {
762+
if (waitingEvents == 0) {
763763
reject(error);
764764
}
765765
});
766-
766+
767767
cp.on('close', (code: number, signal: any) => {
768768
waitingEvents--; //process is complete
769769
this._debug('rc:' + code);
770770
returnCode = code;
771-
771+
772772
if (stdbuffer.length > 0) {
773773
this.emit('stdline', stdbuffer);
774774
}
775-
775+
776776
if (errbuffer.length > 0) {
777777
this.emit('errline', errbuffer);
778778
}
779-
779+
780780
if (code != 0 && !optionsNonNull.ignoreReturnCode) {
781781
success = false;
782782
}
783-
783+
784784
this._debug('success:' + success);
785-
785+
786786
if (!successFirst) { //in the case output is piped to another tool, check exit code of both tools
787787
error = new Error(toolPathFirst + ' failed with return code: ' + returnCodeFirst);
788788
} else if (!success) {
789789
error = new Error(toolPath + ' failed with return code: ' + code);
790790
}
791-
792-
if(waitingEvents == 0) {
791+
792+
if (waitingEvents == 0) {
793793
if (error) {
794794
reject(error);
795795
} else {
@@ -838,7 +838,7 @@ export class ToolRunner extends events.EventEmitter {
838838
this._getSpawnArgs(optionsNonNull),
839839
this._getSpawnOptions(optionsNonNull));
840840

841-
waitingEvents ++;
841+
waitingEvents++;
842842
cp = child.spawn(
843843
pipeOutputToTool._getSpawnFileName(optionsNonNull),
844844
pipeOutputToTool._getSpawnArgs(optionsNonNull),
@@ -850,7 +850,7 @@ export class ToolRunner extends events.EventEmitter {
850850
fileStream.on('finish', () => {
851851
waitingEvents--; //file write is complete
852852
fileStream = null;
853-
if(waitingEvents == 0) {
853+
if (waitingEvents == 0) {
854854
if (error) {
855855
defer.reject(error);
856856
} else {
@@ -862,7 +862,7 @@ export class ToolRunner extends events.EventEmitter {
862862
waitingEvents--; //there were errors writing to the file, write is done
863863
this._debug(`Failed to pipe output of ${toolPathFirst} to file ${this.pipeOutputToFile}. Error = ${err}`);
864864
fileStream = null;
865-
if(waitingEvents == 0) {
865+
if (waitingEvents == 0) {
866866
if (error) {
867867
defer.reject(error);
868868
} else {
@@ -901,7 +901,7 @@ export class ToolRunner extends events.EventEmitter {
901901
}
902902
cp.stdin?.end();
903903
error = new Error(toolPathFirst + ' failed. ' + err.message);
904-
if(waitingEvents == 0) {
904+
if (waitingEvents == 0) {
905905
defer.reject(error);
906906
}
907907
});
@@ -917,7 +917,7 @@ export class ToolRunner extends events.EventEmitter {
917917
fileStream.end();
918918
}
919919
cp.stdin?.end();
920-
if(waitingEvents == 0) {
920+
if (waitingEvents == 0) {
921921
if (error) {
922922
defer.reject(error);
923923
} else {
@@ -957,7 +957,7 @@ export class ToolRunner extends events.EventEmitter {
957957
cp.on('error', (err: Error) => {
958958
waitingEvents--; //process is done with errors
959959
error = new Error(toolPath + ' failed. ' + err.message);
960-
if(waitingEvents == 0) {
960+
if (waitingEvents == 0) {
961961
defer.reject(error);
962962
}
963963
});
@@ -987,7 +987,7 @@ export class ToolRunner extends events.EventEmitter {
987987
error = new Error(toolPath + ' failed with return code: ' + code);
988988
}
989989

990-
if(waitingEvents == 0) {
990+
if (waitingEvents == 0) {
991991
if (error) {
992992
defer.reject(error);
993993
} else {
@@ -1107,15 +1107,15 @@ export class ToolRunner extends events.EventEmitter {
11071107
if (stdbuffer.length > 0) {
11081108
this.emit('stdline', stdbuffer);
11091109
}
1110-
1110+
11111111
if (errbuffer.length > 0) {
11121112
this.emit('errline', errbuffer);
11131113
}
1114-
1114+
11151115
if (cp) {
11161116
cp.removeAllListeners();
11171117
}
1118-
1118+
11191119
if (error) {
11201120
reject(error);
11211121
}
@@ -1182,18 +1182,19 @@ export class ToolRunner extends events.EventEmitter {
11821182
state.CheckComplete();
11831183
});
11841184

1185-
cp.on('exit', (code: number, signal: number | NodeJS.Signals) => {
1185+
// Do not write debug logs here. Sometimes stdio not closed yet and you can damage user output commands.
1186+
cp.on('exit', (code: number | null, signal: NodeJS.Signals | null) => {
11861187
state.processExitCode = code;
1188+
state.processExitSignal = signal;
11871189
state.processExited = true;
1188-
this._debug(`STDIO streams have closed and received exit code ${code} and signal ${signal} for tool '${this.toolPath}'`);
11891190
state.CheckComplete()
11901191
});
11911192

1192-
cp.on('close', (code: number, signal: number | NodeJS.Signals) => {
1193-
state.processExitCode = code;
1194-
state.processExited = true;
1193+
cp.on('close', (code: number | null, signal: NodeJS.Signals | null) => {
1194+
state.processCloseCode = code;
1195+
state.processCloseSignal = signal;
11951196
state.processClosed = true;
1196-
this._debug(`STDIO streams have closed and received exit code ${code} and signal ${signal} for tool '${this.toolPath}'`);
1197+
state.processExited = true;
11971198
state.CheckComplete();
11981199
});
11991200

@@ -1314,18 +1315,19 @@ export class ToolRunner extends events.EventEmitter {
13141315
state.CheckComplete();
13151316
});
13161317

1317-
cp.on('exit', (code: number, signal: number | NodeJS.Signals) => {
1318+
// Do not write debug logs here. Sometimes stdio not closed yet and you can damage user output commands.
1319+
cp.on('exit', (code: number | null, signal: NodeJS.Signals | null) => {
13181320
state.processExitCode = code;
1321+
state.processExitSignal = signal;
13191322
state.processExited = true;
1320-
this._debug(`STDIO streams have closed and received exit code ${code} and signal ${signal} for tool '${this.toolPath}'`);
13211323
state.CheckComplete()
13221324
});
13231325

1324-
cp.on('close', (code: number, signal: number | NodeJS.Signals) => {
1325-
state.processExitCode = code;
1326-
state.processExited = true;
1326+
cp.on('close', (code: number | null, signal: NodeJS.Signals | null) => {
1327+
state.processCloseCode = code;
1328+
state.processCloseSignal = signal;
13271329
state.processClosed = true;
1328-
this._debug(`STDIO streams have closed and received exit code ${code} and signal ${signal} for tool '${this.toolPath}'`);
1330+
state.processExited = true;
13291331
state.CheckComplete();
13301332
});
13311333

@@ -1404,15 +1406,22 @@ class ExecState extends events.EventEmitter {
14041406
}
14051407

14061408
processClosed: boolean; // tracks whether the process has exited and stdio is closed
1407-
processError: string;
1408-
processExitCode: number;
1409+
processCloseCode: number | null;
1410+
processCloseSignal: NodeJS.Signals | null;
1411+
14091412
processExited: boolean; // tracks whether the process has exited
1413+
processExitCode: number | null;
1414+
processExitSignal: NodeJS.Signals | null;
1415+
1416+
processError: string;
14101417
processStderr: boolean; // tracks whether stderr was written to
1411-
private delay = 10000; // 10 seconds
1412-
private done: boolean;
1413-
private options: IExecOptions;
1418+
1419+
private readonly delay: number = 10000; // 10 seconds
1420+
private readonly options: IExecOptions;
1421+
private readonly toolPath: string;
1422+
14141423
private timeout: NodeJS.Timer | null = null;
1415-
private toolPath: string;
1424+
private done: boolean;
14161425

14171426
public CheckComplete(): void {
14181427
if (this.done) {
@@ -1435,6 +1444,8 @@ class ExecState extends events.EventEmitter {
14351444
// determine whether there is an error
14361445
let error: Error | undefined;
14371446
if (this.processExited) {
1447+
this._debug(`Process exited with code ${this.processExitCode} and signal ${this.processExitSignal} for tool '${this.toolPath}'`);
1448+
14381449
if (this.processError) {
14391450
error = new Error(im._loc('LIB_ProcessError', this.toolPath, this.processError));
14401451
}
@@ -1446,6 +1457,10 @@ class ExecState extends events.EventEmitter {
14461457
}
14471458
}
14481459

1460+
if (this.processClosed) {
1461+
this._debug(`STDIO streams have closed and received exit code ${this.processCloseCode} and signal ${this.processCloseSignal} for tool '${this.toolPath}'`);
1462+
}
1463+
14491464
// clear the timeout
14501465
if (this.timeout) {
14511466
clearTimeout(this.timeout);

0 commit comments

Comments
 (0)