Print debug log on npm failure

Tasks/Npm/Strings/resources.resjson/en-US/resources.resjson

@@ -39,5 +39,9 @@
   "loc.messages.UsingRegistry": "Using registry: %s",
   "loc.messages.AddingAuthRegistry": "Adding auth for registry: %s",
   "loc.messages.FoundLocalRegistries": "Found %d registries in this account/collection",
-  "loc.messages.ForcePackagingUrl": "Packaging collection url forced to: %s"
+  "loc.messages.ForcePackagingUrl": "Packaging collection url forced to: %s",
+  "loc.messages.DebugLogNotFound": "Couldn't find a debug log in the cache or working directory",
+  "loc.messages.NpmFailed": "Npm failed with return code: %s",
+  "loc.messages.FoundNpmDebugLog": "Found npm debug log, make sure the path matches with the one in npm's output: %s",
+  "loc.messages.TestDebugLog": "Trying debug log location: %s"
 }

Tasks/Npm/Tests/L0.ts

@@ -28,6 +28,37 @@ describe('Npm Task', function () {
         mockery.deregisterAll();
     });
 
+    // npm failure dumps log
+    it('npm failure dumps debug log from npm cache', (done: MochaDone) => {
+        this.timeout(1000);
+        const debugLog = 'NPM_DEBUG_LOG';
+
+        let tp = path.join(__dirname, 'npm-failureDumpsLog-cacheDir.js');
+        let tr = new ttm.MockTestRunner(tp);
+
+        tr.run();
+
+        assert(tr.failed, 'task should have failed');
+        assert(tr.stdOutContained(debugLog));
+
+        done();
+    });
+
+    it('npm failure dumps debug log from working directory', (done: MochaDone) => {
+        this.timeout(1000);
+        const debugLog = 'NPM_DEBUG_LOG';
+
+        let tp = path.join(__dirname, 'npm-failureDumpsLog-workingDir.js');
+        let tr = new ttm.MockTestRunner(tp);
+
+        tr.run();
+
+        assert(tr.failed, 'task should have failed');
+        assert(tr.stdOutContained(debugLog));
+
+        done();
+    });
+
     // custom
     it('custom command should return npm version', (done: MochaDone) => {
         this.timeout(1000);

Tasks/Npm/Tests/NpmMockHelper.ts

@@ -6,6 +6,7 @@ import * as mtr from 'vsts-task-lib/mock-toolrunner';
 
 export class NpmMockHelper extends TaskMockRunner {
     private static NpmCmdPath: string = 'c:\\mock\\location\\npm';
+    private static NpmCachePath: string = 'c:\\mock\\location\\npm_cache';
     private static AgentBuildDirectory: string = 'c:\\mock\\agent\\work\\build';
     private static BuildBuildId: string = '12345';
     private static CollectionUrl: string = 'https://example.visualstudio.com/defaultcollection';
@@ -14,6 +15,7 @@ export class NpmMockHelper extends TaskMockRunner {
         checkPath: {},
         exec: {},
         exist: {},
+        findMatch: {},
         rmRF: {},
         which: {}
     };
@@ -26,18 +28,31 @@ export class NpmMockHelper extends TaskMockRunner {
 
         NpmMockHelper._setVariable('Agent.HomeDirectory', 'c:\\agent\\home\\directory');
         NpmMockHelper._setVariable('Build.SourcesDirectory', 'c:\\agent\\home\\directory\\sources');
-        process.env['ENDPOINT_AUTH_SYSTEMVSSCONNECTION'] = '{"parameters":{"AccessToken":"token"},"scheme":"OAuth"}';
-        process.env['ENDPOINT_URL_SYSTEMVSSCONNECTION'] = NpmMockHelper.CollectionUrl;
         NpmMockHelper._setVariable('System.DefaultWorkingDirectory', 'c:\\agent\\home\\directory');
-        NpmMockHelper._setVariable('System.TeamFoundationCollectionUri', 'https://example.visualstudio.com/defaultcollection');
+        NpmMockHelper._setVariable('System.TeamFoundationCollectionUri', NpmMockHelper.CollectionUrl);
         NpmMockHelper._setVariable('Agent.BuildDirectory', NpmMockHelper.AgentBuildDirectory);
         NpmMockHelper._setVariable('Build.BuildId', NpmMockHelper.BuildBuildId);
         this.setDebugState(false);
 
+        // mock SYSTEMVSSCONNECtION
+        this.mockServiceEndpoint(
+            'SYSTEMVSSCONNECTION',
+            NpmMockHelper.CollectionUrl,
+            {
+                parameters: { AccessToken: 'token'},
+                scheme: 'OAuth'
+            }
+        );
+
+        this.mockNpmCommand('config get cache', { code: 0, stdout: NpmMockHelper.NpmCachePath} as TaskLibAnswerExecResult);
         this._mockNpmConfigList();
         this._setToolPath('npm', NpmMockHelper.NpmCmdPath);
-        this.answers.rmRF[path.join(NpmMockHelper.AgentBuildDirectory, 'npm', `${NpmMockHelper.BuildBuildId}.npmrc`)] = { success: true };
-        this.answers.rmRF[path.join(NpmMockHelper.AgentBuildDirectory, 'npm')] = { success: true };
+        // mock temp npm path
+        const tempNpmPath = path.join(NpmMockHelper.AgentBuildDirectory, 'npm');
+        this.answers.exist[tempNpmPath] = true;
+        this.answers.rmRF[tempNpmPath] = { success: true };
+        const tempNpmrcPath = path.join(tempNpmPath, `${NpmMockHelper.BuildBuildId}.npmrc`);
+        this.answers.rmRF[tempNpmrcPath] = { success: true };
     }
 
     public run(noMockTask?: boolean): void {
@@ -48,14 +63,6 @@ export class NpmMockHelper extends TaskMockRunner {
         NpmMockHelper._setVariable('System.Debug', debug ? 'true' : 'false');
     }
 
-    public setOsType(osTypeVal : string) {
-        if (!this.answers['osType']) {
-            this.answers['osType'] = {};
-        }
-
-        this.answers['osType']['osType'] = osTypeVal;
-    }
-
     private static _setVariable(name: string, value: string): void {
         let key = NpmMockHelper._getVariableKey(name);
         process.env[key] = value;
@@ -65,8 +72,9 @@ export class NpmMockHelper extends TaskMockRunner {
         return name.replace(/\./g, '_').toUpperCase();
     }
 
-    public setExecResponse(command: string, result: TaskLibAnswerExecResult) {
-        this.answers.exec[command] = result;
+    public mockNpmCommand(command: string, result: TaskLibAnswerExecResult) {
+        this.answers.exec[`npm ${command}`] = result;
+        this.answers.exec[`${NpmMockHelper.NpmCmdPath} ${command}`] = result;
     }
 
     public RegisterLocationServiceMocks() {
@@ -106,11 +114,11 @@ export class NpmMockHelper extends TaskMockRunner {
     }
 
     private _mockNpmConfigList() {
-        this.setExecResponse(`${NpmMockHelper.NpmCmdPath} config list`, {
+        this.mockNpmCommand(`config list`, {
             code: 0,
             stdout: '; cli configs'} as TaskLibAnswerExecResult);
 
-        this.setExecResponse(`${NpmMockHelper.NpmCmdPath} config list -l`, {
+        this.mockNpmCommand(`config list -l`, {
             code: 0,
             stdout: '; debug cli configs'} as TaskLibAnswerExecResult);
     }

Tasks/Npm/Tests/config-noDebug.ts

@@ -3,16 +3,17 @@ import * as path from 'path';
 import { TaskLibAnswerExecResult } from 'vsts-task-lib/mock-answer';
 import * as tmrm from 'vsts-task-lib/mock-run';
 
+import { NpmCommand, NpmTaskInput } from '../Constants';
 import { NpmMockHelper } from './NpmMockHelper';
 
 let taskPath = path.join(__dirname, '..', 'npm.js');
 let tmr = new NpmMockHelper(taskPath);
 
 tmr.setDebugState(false);
-tmr.setInput('command', 'custom');
-tmr.setInput('workingDirectory', '');
-tmr.setInput('customCommand', '-v');
-tmr.setExecResponse('npm -v', {
+tmr.setInput(NpmTaskInput.Command, NpmCommand.Custom);
+tmr.setInput(NpmTaskInput.WorkingDir, '');
+tmr.setInput(NpmTaskInput.CustomCommand, '-v');
+tmr.mockNpmCommand('-v', {
     code: 0,
     stdout: '4.6.1'
 } as TaskLibAnswerExecResult);

Tasks/Npm/Tests/custom-version.ts

@@ -3,16 +3,17 @@ import * as path from 'path';
 import { TaskLibAnswerExecResult } from 'vsts-task-lib/mock-answer';
 import * as tmrm from 'vsts-task-lib/mock-run';
 
+import { NpmCommand, NpmTaskInput } from '../constants';
 import { NpmMockHelper } from './NpmMockHelper';
 
 let taskPath = path.join(__dirname, '..', 'npm.js');
 let tmr = new NpmMockHelper(taskPath);
 
 tmr.setDebugState(true);
-tmr.setInput('command', 'custom');
-tmr.setInput('workingDirectory', '');
-tmr.setInput('customCommand', '-v');
-tmr.setExecResponse('npm -v', {
+tmr.setInput(NpmTaskInput.Command, NpmCommand.Custom);
+tmr.setInput(NpmTaskInput.WorkingDir, '');
+tmr.setInput(NpmTaskInput.CustomCommand, '-v');
+tmr.mockNpmCommand('-v', {
     code: 0,
     stdout: '4.6.1'
 } as TaskLibAnswerExecResult);

Tasks/Npm/Tests/install-feed.ts

@@ -13,7 +13,7 @@ tmr.setInput(NpmTaskInput.Command, NpmCommand.Install);
 tmr.setInput(NpmTaskInput.WorkingDir, '');
 tmr.setInput(NpmTaskInput.CustomRegistry, RegistryLocation.Feed);
 tmr.setInput(NpmTaskInput.CustomFeed, 'SomeFeedId');
-tmr.setExecResponse('npm install', {
+tmr.mockNpmCommand('install', {
     code: 0,
     stdout: 'npm install successful'
 } as TaskLibAnswerExecResult);

Tasks/Npm/Tests/install-npmFailure.ts

@@ -3,14 +3,15 @@ import * as path from 'path';
 import { TaskLibAnswerExecResult } from 'vsts-task-lib/mock-answer';
 import * as tmrm from 'vsts-task-lib/mock-run';
 
+import { NpmCommand, NpmTaskInput } from '../Constants';
 import { NpmMockHelper } from './NpmMockHelper';
 
 let taskPath = path.join(__dirname, '..', 'npm.js');
 let tmr = new NpmMockHelper(taskPath);
 
-tmr.setInput('command', 'install');
-tmr.setInput('workingDirectory', '');
-tmr.setExecResponse('npm install', {
+tmr.setInput(NpmTaskInput.Command, NpmCommand.Install);
+tmr.setInput(NpmTaskInput.WorkingDir, '');
+tmr.mockNpmCommand('install', {
     code: -1,
     stdout: 'some npm failure'
 } as TaskLibAnswerExecResult);

Tasks/Npm/Tests/install-npmrc.ts

@@ -12,7 +12,7 @@ let tmr = new NpmMockHelper(taskPath);
 tmr.setInput(NpmTaskInput.Command, NpmCommand.Install);
 tmr.setInput(NpmTaskInput.WorkingDir, '');
 tmr.setInput(NpmTaskInput.CustomRegistry, RegistryLocation.Npmrc);
-tmr.setExecResponse('npm install', {
+tmr.mockNpmCommand('install', {
     code: 0,
     stdout: 'npm install successful'
 } as TaskLibAnswerExecResult);

Tasks/Npm/Tests/npm-failureDumpsLog-cacheDir.ts

@@ -0,0 +1,29 @@
+import * as path from 'path';
+
+import { TaskLibAnswerExecResult } from 'vsts-task-lib/mock-answer';
+import * as tmrm from 'vsts-task-lib/mock-run';
+
+import { NpmCommand, NpmTaskInput } from '../Constants';
+import { NpmMockHelper } from './NpmMockHelper';
+
+let taskPath = path.join(__dirname, '..', 'npm.js');
+let tmr = new NpmMockHelper(taskPath);
+
+tmr.setInput(NpmTaskInput.Command, NpmCommand.Custom);
+tmr.setInput(NpmTaskInput.CustomCommand, 'custom');
+tmr.setInput(NpmTaskInput.WorkingDir, 'C:\\mock\\cache');
+tmr.mockNpmCommand('custom', {
+    code: -1,
+    stdout: 'some npm failure'
+} as TaskLibAnswerExecResult);
+tmr.answers.exist['C:\\mock\\cache\\npm-debug.log'] = false;
+tmr.answers.findMatch['*-debug.log'] = [
+    'C:\\mock\cache\\_logs\\someRandomNpm-debug.log'
+];
+let mockFs = require('fs');
+tmr.registerMock('fs', mockFs);
+mockFs.readFile = (a, b, cb) => {
+    cb(undefined, 'NPM_DEBUG_LOG');
+};
+tmr.run();
+

Tasks/Npm/Tests/npm-failureDumpsLog-workingDir.ts

@@ -0,0 +1,27 @@
+import * as path from 'path';
+
+import { TaskLibAnswerExecResult } from 'vsts-task-lib/mock-answer';
+import * as tmrm from 'vsts-task-lib/mock-run';
+
+import { NpmCommand, NpmTaskInput } from '../Constants';
+import { NpmMockHelper } from './NpmMockHelper';
+
+let taskPath = path.join(__dirname, '..', 'npm.js');
+let tmr = new NpmMockHelper(taskPath);
+
+tmr.setInput(NpmTaskInput.Command, NpmCommand.Custom);
+tmr.setInput(NpmTaskInput.CustomCommand, 'custom');
+tmr.setInput(NpmTaskInput.WorkingDir, 'C:\\mock\\workingDir');
+tmr.mockNpmCommand('custom', {
+    code: -1,
+    stdout: 'some npm failure'
+} as TaskLibAnswerExecResult);
+tmr.answers.exist['C:\\mock\\workingDir\\npm-debug.log'] = true;
+
+let mockFs = require('fs');
+tmr.registerMock('fs', mockFs);
+mockFs.readFile = (a, b, cb) => {
+    cb(undefined, 'NPM_DEBUG_LOG');
+};
+
+tmr.run();

Tasks/Npm/Tests/publish-external.ts

@@ -20,7 +20,7 @@ let auth = {
     }
 };
 tmr.mockServiceEndpoint('SomeEndpointId', 'http://url', auth);
-tmr.setExecResponse('npm publish', {
+tmr.mockNpmCommand('publish', {
     code: 0,
     stdout: 'npm publish successful'
 } as TaskLibAnswerExecResult);

Tasks/Npm/Tests/publish-feed.ts

@@ -13,7 +13,7 @@ tmr.setInput(NpmTaskInput.Command, NpmCommand.Publish);
 tmr.setInput(NpmTaskInput.WorkingDir, 'workingDir');
 tmr.setInput(NpmTaskInput.PublishRegistry, RegistryLocation.Feed);
 tmr.setInput(NpmTaskInput.PublishFeed, 'SomeFeedId');
-tmr.setExecResponse('npm publish', {
+tmr.mockNpmCommand('publish', {
     code: 0,
     stdout: 'npm publish successful'
 } as TaskLibAnswerExecResult);

Tasks/Npm/npmtoolrunner.ts

@@ -1,10 +1,13 @@
 import * as fs from 'fs';
+import * as path from 'path';
 import { format, parse, Url } from 'url';
+import * as Q from 'q';
 
 import * as tl from 'vsts-task-lib/task';
 import * as tr from 'vsts-task-lib/toolrunner';
 
 export class NpmToolRunner extends tr.ToolRunner {
+    private cacheLocation: string;
     private dbg: boolean;
 
     constructor(private workingDirectory: string, private npmrc?: string) {
@@ -18,18 +21,31 @@ export class NpmToolRunner extends tr.ToolRunner {
         if (debugVar.toLowerCase() === 'true') {
             this.dbg = true;
         }
+
+        let cacheOptions = { silent: true } as tr.IExecSyncOptions;
+        this.cacheLocation = tl.execSync('npm', 'config get cache', this._prepareNpmEnvironment(cacheOptions)).stdout.trim();
     }
 
     public exec(options?: tr.IExecOptions): Q.Promise<number> {
         options = this._prepareNpmEnvironment(options) as tr.IExecOptions;
 
-        return super.exec(options);
+        return super.exec(options).catch((reason: any) => {
+            return this._printDebugLog(this._getDebugLogPath(options)).then((value: void): number => {
+                throw reason;
+            });
+        });
     }
 
     public execSync(options?: tr.IExecSyncOptions): tr.IExecSyncResult {
         options = this._prepareNpmEnvironment(options);
 
-        return super.execSync(options);
+        const execResult = super.execSync(options);
+        if (execResult.code !== 0) {
+            this._printDebugLogSync(this._getDebugLogPath(options));
+            throw new Error(tl.loc('NpmFailed', execResult.code));
+        }
+
+        return execResult;
     }
 
     private static _getProxyFromEnvironment(): string {
@@ -74,4 +90,44 @@ export class NpmToolRunner extends tr.ToolRunner {
         let config = tl.execSync('npm', `config list ${this.dbg ? '-l' : ''}`, options);
         return options;
     }
+
+    private _getDebugLogPath(options?: tr.IExecSyncOptions): string {
+        // check cache
+        const logs = tl.findMatch(path.join(this.cacheLocation, '_logs'), '*-debug.log');
+        if (logs && logs.length > 0) {
+            const debugLog = logs[logs.length - 1];
+            console.log(tl.loc('FoundNpmDebugLog', debugLog));
+            return debugLog;
+        }
+
+        // check working dir
+        const cwd = options && options.cwd ? options.cwd : process.cwd;
+        const debugLog = path.join(cwd, 'npm-debug.log');
+        tl.debug(tl.loc('TestDebugLog', debugLog));
+        if (tl.exist(debugLog)) {
+            console.log(tl.loc('FoundNpmDebugLog', debugLog));
+            return debugLog;
+        }
+
+        tl.warning(tl.loc('DebugLogNotFound'));
+        return undefined;
+    }
+
+    private _printDebugLog(log: string): Q.Promise<void> {
+        if (!log) {
+            return Q.fcall(() => {});
+        }
+
+        return Q.nfcall(fs.readFile, log, 'utf-8').then((data: string) => {
+            console.log(data);
+        });
+    }
+
+    private _printDebugLogSync(log: string): void {
+        if (!log) {
+            return;
+        }
+
+        console.log(fs.readFileSync(log, 'utf-8'));
+    }
 }