Azure-pipelines-tasks: NPM Task sometimes hangs

[mqlkmd]

We are building an Angular2 application and use the VSTS "npm Task" for building and testing using Angular CLI.
We have recently experienced that the "ng test" step just hangs until the build timeouts. There are no error or debug information at all even though system.debug is turned on. This of course only happens on the build server - we can't reproduce it locally.

To investigate the issue we put the build on a private agent to get some more insight. Here, the build also hangs on the "ng test" step and when it happens no CPU is consumed so its not an endless loop or such.
Running the exact same step directly on the private agent in the cmd shell works fine, so it seems to be related to the agent/vsts-task.

The debug info from the build that causes the issue indicates that we are using the correct Node version:
2017-05-30T09:28:11.2174577Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-05-30T09:28:11.2174577Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-05-30T09:28:11.2174577Z npm verb cli 'run',
2017-05-30T09:28:11.2174577Z npm verb cli 'ci' ]
2017-05-30T09:28:11.2174577Z npm info using [email protected]
2017-05-30T09:28:11.2174577Z npm info using [email protected]

But when looking at the log in the agent's "_diag" folder for that same build, it indicates that another node binary is used:
[2017-05-30 09:28:04Z INFO ProcessInvoker] Starting process:
[2017-05-30 09:28:04Z INFO ProcessInvoker] File name: 'C:\AzureAgent02\externals\nodebin\node.exe'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Arguments: '"C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\npmtask.js"'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Working directory: 'C:\AzureAgent02_work\2\s'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Require exit code zero: 'True'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Encoding web name: utf-8 ; code page: '65001'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Force kill process on cancellation: 'False'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Process started with process id 2256, waiting for process exit.

If the "ng test" step is run with the agent's node binary in a cmd shell, it throws an exception because of a feature (js syntax) not yet available in that version of node (v 5.10.1.0).

So our workaround was to drop the "npm Task" and just use the "Command Line Task" directly which will use the globally installed node on the build server and not the one provided by the agent.

It seems like a bug, that the "npm Task" dont report back the exception that is actually thrown but just hangs infinitely.

If using the "npm Task", how can we force it to use the globally installed node or how can we update the agent's included node binary?

[bryanmacfarlane]

The npm task shouldn't be using the agent's internal node version to run npm. It should be using the one in the path. The internal node version is used to execute the tasks script (as an internal script engine). The tasks script itself should run the users tools (the one in the path).

On the agent you used, was node 7 in the path?

And the hang indicates a callback is missed in an error condition.

Finally, you don't update the agent's internal node - it shouldn't be used to run user scenarios - it's used to exec the task.

Your log snippet is showing the agent running the task (npmtask.js) which is what it's supposed to do. Can you include the log lines which indicates when it runs ng test it's using that node? Per the code, it should be using the one in the path and not internal node.

https://github.com/Microsoft/vsts-tasks/blob/master/Tasks/Npm/npmtask.ts#L27

I think your hang is do to a missed error callback in the task and not that it was using internal node. Can you include the full log when it hangs?

[mqlkmd]

Hi Bryan

Thanks for looking at this.
On the agent I only have C:\Program Files\nodejs\ in my PATH and thats v7.10.0. If I run "node --version" at a cmd shell, it reports v7.10.0.

I could reproduce the error each time using "npm task", but it runs successfully when using "Command Line Task".

I've included more loglines below. I explicitly cancelled the task after 3 minutes of waiting.

[2017-05-30 09:28:04Z INFO StepsRunner] Processing step: DisplayName='npm run ci', ContinueOnError=False, Enabled=True
[2017-05-30 09:28:04Z INFO ExpressionManager] Evaluating: succeeded()
[2017-05-30 09:28:04Z INFO ExpressionManager] Expanded: True
[2017-05-30 09:28:04Z INFO ExpressionManager] Result: True
[2017-05-30 09:28:04Z INFO StepsRunner] Starting the step.
[2017-05-30 09:28:04Z INFO TaskManager] Loading task definition 'C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\task.json'.
[2017-05-30 09:28:04Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IJobExtension'
[2017-05-30 09:28:04Z INFO BuildJobExtension] Build JobExtension resolving path use source provide: src\Gandalf.Web
[2017-05-30 09:28:04Z INFO BuildJobExtension] The Default Path Root of Build JobExtension is build.sourcesDirectory: C:\AzureAgent02_work\2\s
[2017-05-30 09:28:04Z INFO BuildJobExtension] After prefix Default Path Root provide by JobExtension: C:\AzureAgent02_work\2\s\src\Gandalf.Web
[2017-05-30 09:28:04Z INFO BuildJobExtension] Return absolute path after prefix DefaultPathRoot: C:\AzureAgent02_work\2\s\src\Gandalf.Web
[2017-05-30 09:28:04Z INFO TaskRunner] Build JobExtension resolved a rooted path:: C:\AzureAgent02_work\2\s\src\Gandalf.Web
[2017-05-30 09:28:04Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IJobExtension'
[2017-05-30 09:28:04Z INFO BuildJobExtension] Build JobExtension resolving path use source provide:
[2017-05-30 09:28:04Z INFO BuildJobExtension] The Default Path Root of Build JobExtension is build.sourcesDirectory: C:\AzureAgent02_work\2\s
[2017-05-30 09:28:04Z INFO BuildJobExtension] After prefix Default Path Root provide by JobExtension: C:\AzureAgent02_work\2\s
[2017-05-30 09:28:04Z INFO BuildJobExtension] Return absolute path after prefix DefaultPathRoot: C:\AzureAgent02_work\2\s
[2017-05-30 09:28:04Z INFO TaskRunner] Build JobExtension resolved a rooted path:: C:\AzureAgent02_work\2\s
[2017-05-30 09:28:04Z INFO ExtensionManager] Getting extensions for interface: 'Microsoft.VisualStudio.Services.Agent.Worker.IWorkerCommandExtension'
[2017-05-30 09:28:04Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TaskCommandExtension, Agent.Worker
[2017-05-30 09:28:04Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.ArtifactCommandExtension, Agent.Worker
[2017-05-30 09:28:04Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.Build.BuildCommandExtension, Agent.Worker
[2017-05-30 09:28:04Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.CodeCoverage.CodeCoverageCommandExtension, Agent.Worker
[2017-05-30 09:28:04Z INFO ExtensionManager] Creating instance: Microsoft.VisualStudio.Services.Agent.Worker.TestResults.ResultsCommandExtension, Agent.Worker
[2017-05-30 09:28:04Z INFO WorkerCommandManager] Register command extension for area task
[2017-05-30 09:28:04Z INFO WorkerCommandManager] Register command extension for area artifact
[2017-05-30 09:28:04Z INFO WorkerCommandManager] Register command extension for area build
[2017-05-30 09:28:04Z INFO WorkerCommandManager] Register command extension for area codecoverage
[2017-05-30 09:28:04Z INFO WorkerCommandManager] Register command extension for area results
[2017-05-30 09:28:04Z INFO ProcessInvoker] Starting process:
[2017-05-30 09:28:04Z INFO ProcessInvoker] File name: 'C:\AzureAgent02\externals\node\bin\node.exe'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Arguments: '"C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\npmtask.js"'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Working directory: 'C:\AzureAgent02_work\2\s'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Require exit code zero: 'True'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Encoding web name: utf-8 ; code page: '65001'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Force kill process on cancellation: 'False'
[2017-05-30 09:28:04Z INFO ProcessInvoker] Process started with process id 2256, waiting for process exit.
[2017-05-30 09:28:04Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:05Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:05Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:09Z INFO JobServerQueue] Try to upload 1 log files or attachments, success rate: 1/1.
[2017-05-30 09:28:09Z INFO ProcessInvoker] Scean all processes to find relationship between all processes.
[2017-05-30 09:28:09Z INFO ProcessInvoker] Find all child processes of process '1928'.
[2017-05-30 09:28:09Z INFO ProcessInvoker] Kill process '1928'.
[2017-05-30 09:28:09Z ERR ProcessInvoker] Ignore ArgumentException during Process.GetProcessById().
[2017-05-30 09:28:09Z ERR ProcessInvoker] System.ArgumentException: Process with an Id of 1928 is not running.
at System.Diagnostics.Process.GetProcessById(Int32 processId, String machineName)
at Microsoft.VisualStudio.Services.Agent.ProcessInvoker.WindowsKillProcessTree()
[2017-05-30 09:28:09Z INFO ProcessInvoker] Scean all processes to find relationship between all processes.
[2017-05-30 09:28:10Z INFO ProcessInvoker] Find all child processes of process '3736'.
[2017-05-30 09:28:10Z INFO ProcessInvoker] Kill process '3736'.
[2017-05-30 09:28:10Z ERR ProcessInvoker] Ignore ArgumentException during Process.GetProcessById().
[2017-05-30 09:28:10Z ERR ProcessInvoker] System.ArgumentException: Process with an Id of 3736 is not running.
at System.Diagnostics.Process.GetProcessById(Int32 processId, String machineName)
at Microsoft.VisualStudio.Services.Agent.ProcessInvoker.WindowsKillProcessTree()
[2017-05-30 09:28:10Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:11Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:11Z INFO JobServerQueue] Try to append 2 batches web console lines, success rate: 2/2.
[2017-05-30 09:28:13Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:23Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:23Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:28:24Z INFO JobServerQueue] Try to append 1 batches web console lines, success rate: 1/1.
[2017-05-30 09:31:54Z INFO Worker] Cancellation message received.
[2017-05-30 09:31:54Z INFO ExpressionManager] Evaluating: succeeded()
[2017-05-30 09:31:54Z INFO ExpressionManager] Expanded: False
[2017-05-30 09:31:54Z INFO ExpressionManager] Result: False
[2017-05-30 09:31:54Z INFO StepsRunner] Cancel current running step.

The complete log from the npm task in vsts can be found below. (I've ** some of the info)

2017-05-30T09:28:04.7031670Z ##[debug]Evaluating condition for step: 'npm run ci'
2017-05-30T09:28:04.7031670Z ##[debug]Evaluating: succeeded()
2017-05-30T09:28:04.7031670Z ##[debug]Evaluating succeeded:
2017-05-30T09:28:04.7031670Z ##[debug]=> (Boolean) True
2017-05-30T09:28:04.7031670Z ##[debug]Expanded: True
2017-05-30T09:28:04.7031670Z ##[debug]Result: True
2017-05-30T09:28:04.7031670Z ##[section]Starting: npm run ci
2017-05-30T09:28:04.7187881Z ==============================================================================
2017-05-30T09:28:04.7187881Z Task : npm
2017-05-30T09:28:04.7187881Z Description : Run an npm command
2017-05-30T09:28:04.7187881Z Version : 0.2.22
2017-05-30T09:28:04.7187881Z Author : Microsoft Corporation
2017-05-30T09:28:04.7187881Z Help : More Information
2017-05-30T09:28:04.7187881Z ==============================================================================
2017-05-30T09:28:04.9687469Z ##[debug]agent.workFolder=C:\AzureAgent02_work
2017-05-30T09:28:04.9687469Z ##[debug]loading inputs and endpoints
2017-05-30T09:28:04.9687469Z ##[debug]loading ENDPOINT_AUTH_*
2017-05-30T09:28:04.9687469Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_
2017-05-30T09:28:04.9687469Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_
2017-05-30T09:28:04.9687469Z ##[debug]loading ENDPOINT_AUTH_SCHEME_
2017-05-30T09:28:04.9687469Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2017-05-30T09:28:04.9687469Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2017-05-30T09:28:04.9687469Z ##[debug]loading INPUT_ARGUMENTS
2017-05-30T09:28:04.9687469Z ##[debug]loading INPUT_COMMAND
2017-05-30T09:28:04.9687469Z ##[debug]loading INPUT_CWD
2017-05-30T09:28:04.9687469Z ##[debug]loaded 9
2017-05-30T09:28:04.9687469Z ##[debug]check path : C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\task.json
2017-05-30T09:28:04.9687469Z ##[debug]set resource file to: C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\task.json
2017-05-30T09:28:04.9687469Z ##[debug]system.culture=en-US
2017-05-30T09:28:04.9687469Z ##[debug]cwd=C:\AzureAgent02_work\2\s\src\Gandalf.Web
2017-05-30T09:28:04.9687469Z ##[debug]testing directory 'C:\AzureAgent02_work\2\s\src\Gandalf.Web'
2017-05-30T09:28:04.9687469Z ##[debug]command=run
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\AzureAgent02\externals\git\cmd/npm = C:\AzureAgent02\externals\git\cmd\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows\system32/npm = C:\Windows\system32\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows/npm = C:\Windows\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\Wbem/npm = C:\Windows\System32\Wbem\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\WindowsPowerShell\v1.0\/npm = C:\Windows\System32\WindowsPowerShell\v1.0\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\120\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\120\Tools\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\130\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\130\Tools\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft Emulator Manager\1.0\/npm = C:\Program Files (x86)\Microsoft Emulator Manager\1.0\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: /npm = C:\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Git\cmd/npm = C:\Program Files\Git\cmd\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\/npm = C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft\Web Platform Installer\/npm = C:\Program Files\Microsoft\Web Platform Installer\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\dotnet\/npm = C:\Program Files\dotnet\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\ProgramData\chocolatey\bin/npm = C:\ProgramData\chocolatey\bin\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\nodejs\/npm = C:\Program Files\nodejs\npm
2017-05-30T09:28:04.9687469Z ##[debug]check path : C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]npm=C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: run
2017-05-30T09:28:04.9687469Z ##[debug]arguments=ci
2017-05-30T09:28:04.9687469Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: ci
2017-05-30T09:28:04.9687469Z ##[debug]USE_DEPRECATED_TASK_VERSION=undefined
2017-05-30T09:28:04.9687469Z ##[debug]Agent.BuildDirectory=C:\AzureAgent02_work\2
2017-05-30T09:28:04.9687469Z ##[debug]testing directory 'C:\AzureAgent02_work\2\npm'
2017-05-30T09:28:04.9687469Z ##[debug]build.buildId=24933
2017-05-30T09:28:04.9687469Z ##[debug]system.debug=true
2017-05-30T09:28:04.9687469Z ##[debug]system.debug=true
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\AzureAgent02\externals\git\cmd/npm = C:\AzureAgent02\externals\git\cmd\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows\system32/npm = C:\Windows\system32\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows/npm = C:\Windows\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\Wbem/npm = C:\Windows\System32\Wbem\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\WindowsPowerShell\v1.0\/npm = C:\Windows\System32\WindowsPowerShell\v1.0\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\120\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\120\Tools\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\130\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\130\Tools\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft Emulator Manager\1.0\/npm = C:\Program Files (x86)\Microsoft Emulator Manager\1.0\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: /npm = C:\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Git\cmd/npm = C:\Program Files\Git\cmd\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\/npm = C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft\Web Platform Installer\/npm = C:\Program Files\Microsoft\Web Platform Installer\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\dotnet\/npm = C:\Program Files\dotnet\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\ProgramData\chocolatey\bin/npm = C:\ProgramData\chocolatey\bin\npm
2017-05-30T09:28:04.9687469Z ##[debug]Absolute path for pathSegments: C:\Program Files\nodejs\/npm = C:\Program Files\nodejs\npm
2017-05-30T09:28:04.9687469Z ##[debug]check path : C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]npm=C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: config list
2017-05-30T09:28:04.9687469Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: -l
2017-05-30T09:28:04.9687469Z ##[debug]exec tool: C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]Arguments:
2017-05-30T09:28:04.9687469Z ##[debug] config
2017-05-30T09:28:04.9687469Z ##[debug] list
2017-05-30T09:28:04.9687469Z ##[debug] -l
2017-05-30T09:28:04.9687469Z [command]C:\Program Files\nodejs\npm.cmd config list -l
2017-05-30T09:28:05.7654493Z npm info it worked if it ends with ok
2017-05-30T09:28:05.7654493Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-05-30T09:28:05.7654493Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-05-30T09:28:05.7654493Z npm verb cli 'prefix',
2017-05-30T09:28:05.7654493Z npm verb cli '-g' ]
2017-05-30T09:28:05.7654493Z npm info using [email protected]
2017-05-30T09:28:05.7654493Z npm info using [email protected]
2017-05-30T09:28:05.7654493Z npm verb exit [ 0, true ]
2017-05-30T09:28:05.7654493Z npm info ok
2017-05-30T09:28:09.9364702Z npm info it worked if it ends with ok
2017-05-30T09:28:10.0458226Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-05-30T09:28:10.3426436Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-05-30T09:28:10.9362742Z npm verb cli 'config',
2017-05-30T09:28:11.2018355Z npm verb cli 'list',
2017-05-30T09:28:11.2018355Z npm verb cli '-l' ]
2017-05-30T09:28:11.2018355Z npm info using [email protected]
2017-05-30T09:28:11.2018355Z npm info using [email protected]
2017-05-30T09:28:11.2018355Z ; cli configs
2017-05-30T09:28:11.2018355Z long = true
2017-05-30T09:28:11.2018355Z scope = ""
2017-05-30T09:28:11.2018355Z user-agent = "npm/4.2.0 node/v7.10.0 win32 x64"
2017-05-30T09:28:11.2018355Z
2017-05-30T09:28:11.2018355Z ; environment configs
2017-05-30T09:28:11.2018355Z loglevel = "verbose"
2017-05-30T09:28:11.2018355Z
2017-05-30T09:28:11.2018355Z ; builtin config undefined
2017-05-30T09:28:11.2018355Z prefix = "C:\Users\\AppData\Roaming\npm"
2017-05-30T09:28:11.2018355Z
2017-05-30T09:28:11.2018355Z ; default values
2017-05-30T09:28:11.2018355Z access = null
2017-05-30T09:28:11.2018355Z also = null
2017-05-30T09:28:11.2018355Z always-auth = false
2017-05-30T09:28:11.2018355Z bin-links = true
2017-05-30T09:28:11.2018355Z browser = null
2017-05-30T09:28:11.2018355Z ca = null
2017-05-30T09:28:11.2018355Z cache = "C:\Users\\AppData\Roaming\npm-cache"
2017-05-30T09:28:11.2018355Z cache-lock-retries = 10
2017-05-30T09:28:11.2018355Z cache-lock-stale = 60000
2017-05-30T09:28:11.2018355Z cache-lock-wait = 10000
2017-05-30T09:28:11.2018355Z cache-max = null
2017-05-30T09:28:11.2018355Z cache-min = 10
2017-05-30T09:28:11.2018355Z cafile = undefined
2017-05-30T09:28:11.2018355Z cert = null
2017-05-30T09:28:11.2018355Z color = true
2017-05-30T09:28:11.2018355Z depth = null
2017-05-30T09:28:11.2018355Z description = true
2017-05-30T09:28:11.2018355Z dev = false
2017-05-30T09:28:11.2018355Z dry-run = false
2017-05-30T09:28:11.2018355Z editor = "notepad.exe"
2017-05-30T09:28:11.2018355Z engine-strict = false
2017-05-30T09:28:11.2018355Z fetch-retries = 2
2017-05-30T09:28:11.2018355Z fetch-retry-factor = 10
2017-05-30T09:28:11.2018355Z fetch-retry-maxtimeout = 60000
2017-05-30T09:28:11.2018355Z fetch-retry-mintimeout = 10000
2017-05-30T09:28:11.2018355Z force = false
2017-05-30T09:28:11.2018355Z git = "git"
2017-05-30T09:28:11.2018355Z git-tag-version = true
2017-05-30T09:28:11.2018355Z global = false
2017-05-30T09:28:11.2018355Z global-style = false
2017-05-30T09:28:11.2018355Z globalconfig = "C:\Users\\AppData\Roaming\npm\etc\npmrc"
2017-05-30T09:28:11.2018355Z globalignorefile = "C:\Users\\AppData\Roaming\npm\etc\npmignore"
2017-05-30T09:28:11.2018355Z group = 0
2017-05-30T09:28:11.2018355Z heading = "npm"
2017-05-30T09:28:11.2018355Z https-proxy = null
2017-05-30T09:28:11.2018355Z if-present = false
2017-05-30T09:28:11.2018355Z ignore-scripts = false
2017-05-30T09:28:11.2018355Z init-author-email = ""
2017-05-30T09:28:11.2018355Z init-author-name = ""
2017-05-30T09:28:11.2018355Z init-author-url = ""
2017-05-30T09:28:11.2018355Z init-license = "ISC"
2017-05-30T09:28:11.2018355Z init-module = "C:\Users\\.npm-init.js"
2017-05-30T09:28:11.2018355Z init-version = "1.0.0"
2017-05-30T09:28:11.2018355Z json = false
2017-05-30T09:28:11.2018355Z key = null
2017-05-30T09:28:11.2018355Z legacy-bundling = false
2017-05-30T09:28:11.2018355Z link = false
2017-05-30T09:28:11.2018355Z local-address = undefined
2017-05-30T09:28:11.2018355Z ; loglevel = "warn" (overridden)
2017-05-30T09:28:11.2018355Z logs-max = 10
2017-05-30T09:28:11.2018355Z ; long = false (overridden)
2017-05-30T09:28:11.2018355Z maxsockets = 50
2017-05-30T09:28:11.2018355Z message = "%s"
2017-05-30T09:28:11.2018355Z metrics-registry = "https://registry.npmjs.org/"
2017-05-30T09:28:11.2018355Z node-version = "7.10.0"
2017-05-30T09:28:11.2018355Z onload-script = null
2017-05-30T09:28:11.2018355Z only = null
2017-05-30T09:28:11.2018355Z optional = true
2017-05-30T09:28:11.2018355Z parseable = false
2017-05-30T09:28:11.2018355Z ; prefix = "C:\Program Files\nodejs" (overridden)
2017-05-30T09:28:11.2018355Z production = false
2017-05-30T09:28:11.2018355Z progress = true
2017-05-30T09:28:11.2018355Z proprietary-attribs = true
2017-05-30T09:28:11.2018355Z proxy = null
2017-05-30T09:28:11.2018355Z rebuild-bundle = true
2017-05-30T09:28:11.2018355Z registry = "https://registry.npmjs.org/"
2017-05-30T09:28:11.2018355Z rollback = true
2017-05-30T09:28:11.2018355Z save = false
2017-05-30T09:28:11.2018355Z save-bundle = false
2017-05-30T09:28:11.2018355Z save-dev = false
2017-05-30T09:28:11.2018355Z save-exact = false
2017-05-30T09:28:11.2018355Z save-optional = false
2017-05-30T09:28:11.2018355Z save-prefix = "^"
2017-05-30T09:28:11.2018355Z scope = ""
2017-05-30T09:28:11.2018355Z scripts-prepend-node-path = "warn-only"
2017-05-30T09:28:11.2018355Z searchexclude = null
2017-05-30T09:28:11.2018355Z searchlimit = 20
2017-05-30T09:28:11.2018355Z searchopts = ""
2017-05-30T09:28:11.2018355Z searchstaleness = 900
2017-05-30T09:28:11.2174577Z send-metrics = false
2017-05-30T09:28:11.2174577Z shell = "C:\Windows\system32\cmd.exe"
2017-05-30T09:28:11.2174577Z shrinkwrap = true
2017-05-30T09:28:11.2174577Z sign-git-tag = false
2017-05-30T09:28:11.2174577Z strict-ssl = true
2017-05-30T09:28:11.2174577Z tag = "latest"
2017-05-30T09:28:11.2174577Z tag-version-prefix = "v"
2017-05-30T09:28:11.2174577Z tmp = "C:\AzureAgent02\_work\_temp"
2017-05-30T09:28:11.2174577Z umask = 0
2017-05-30T09:28:11.2174577Z unicode = false
2017-05-30T09:28:11.2174577Z unsafe-perm = true
2017-05-30T09:28:11.2174577Z usage = false
2017-05-30T09:28:11.2174577Z user = 0
2017-05-30T09:28:11.2174577Z ; user-agent = "npm/{npm-version} node/{node-version} {platform} {arch}" (overridden)
2017-05-30T09:28:11.2174577Z userconfig = "C:\Users\*\.npmrc"
2017-05-30T09:28:11.2174577Z version = false
2017-05-30T09:28:11.2174577Z versions = false
2017-05-30T09:28:11.2174577Z viewer = "browser"
2017-05-30T09:28:11.2174577Z
2017-05-30T09:28:11.2174577Z
2017-05-30T09:28:11.2174577Z npm verb exit [ 0, true ]
2017-05-30T09:28:11.2174577Z npm info ok
2017-05-30T09:28:11.2174577Z ##[debug]rc:0
2017-05-30T09:28:11.2174577Z ##[debug]success:true
2017-05-30T09:28:11.2174577Z ##[debug]exec tool: C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:11.2174577Z ##[debug]Arguments:
2017-05-30T09:28:11.2174577Z ##[debug] run
2017-05-30T09:28:11.2174577Z ##[debug] ci
2017-05-30T09:28:11.2174577Z [command]C:\Program Files\nodejs\npm.cmd run ci
2017-05-30T09:28:11.2174577Z npm info it worked if it ends with ok
2017-05-30T09:28:11.2174577Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-05-30T09:28:11.2174577Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-05-30T09:28:11.2174577Z npm verb cli 'prefix',
2017-05-30T09:28:11.2174577Z npm verb cli '-g' ]
2017-05-30T09:28:11.2174577Z npm info using [email protected]
2017-05-30T09:28:11.2174577Z npm info using [email protected]
2017-05-30T09:28:11.2174577Z npm verb exit [ 0, true ]
2017-05-30T09:28:11.2174577Z npm info ok
2017-05-30T09:28:11.2174577Z npm info it worked if it ends with ok
2017-05-30T09:28:11.2174577Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-05-30T09:28:11.2174577Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-05-30T09:28:11.2174577Z npm verb cli 'run',
2017-05-30T09:28:11.2174577Z npm verb cli 'ci' ]
2017-05-30T09:28:11.2174577Z npm info using [email protected]
2017-05-30T09:28:11.2174577Z npm info using [email protected]
2017-05-30T09:28:11.2174577Z npm verb run-script [ 'preci', 'ci', 'postci' ]
2017-05-30T09:28:11.2174577Z npm info lifecycle [email protected]~preci: [email protected]
2017-05-30T09:28:11.2174577Z npm info lifecycle [email protected]~ci: [email protected]
2017-05-30T09:28:11.2174577Z
2017-05-30T09:28:11.2174577Z > [email protected] ci C:\AzureAgent02_work\2\s\src\Gandalf.Web
2017-05-30T09:28:11.2174577Z > yarn install && yarn run test
2017-05-30T09:28:11.2174577Z
2017-05-30T09:28:11.2174577Z yarn install v0.24.6
2017-05-30T09:28:11.2174577Z [1/4] Resolving packages...
2017-05-30T09:28:11.2174577Z [2/4] Fetching packages...
2017-05-30T09:28:12.8508646Z warning [email protected]: The platform "win32" is incompatible with this module.
2017-05-30T09:28:12.8508646Z info "[email protected]" is an optional dependency and failed compatibility check. Excluding it from installation.
2017-05-30T09:28:12.8508646Z [3/4] Linking dependencies...
2017-05-30T09:28:23.1424952Z [4/4] Building fresh packages...
2017-05-30T09:28:23.3455783Z success Saved lockfile.
2017-05-30T09:28:23.3455783Z Done in 15.61s.
2017-05-30T09:28:23.5955274Z yarn run v0.24.6
2017-05-30T09:28:23.7048799Z $ node --max-old-space-size=4096 node_modules/@angular/cli/bin/ng test
2017-05-30T09:31:54.2376116Z ##[debug]Re-evaluate condition on job cancellation for step: 'npm run ci'.
2017-05-30T09:31:54.2660433Z ##[error]The operation was canceled.
2017-05-30T09:31:54.2660433Z ##[debug]System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at Microsoft.VisualStudio.Services.Agent.ProcessInvoker.d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.NodeHandler.d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.d__24.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.StepsRunner.d__1.MoveNext()
2017-05-30T09:31:54.2660433Z ##[section]Finishing: npm run ci

[bryanmacfarlane]

The task was executed using internal node (expected - use to execute the task script)

The npm task ran your node installed on the box (not our internal one) to run npm

2017-05-30T09:28:04.9687469Z ##[debug]check path : C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]npm=C:\Program Files\nodejs\npm.cmd
2017-05-30T09:28:04.9687469Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: run
2017-05-30T09:28:04.9687469Z ##[debug]arguments=ci

It's not using internal node to run npm. It's hanging for another reason.

Does your tests use UI components? Have you tried it by running an agent interactively (not as a service)?

[mqlkmd]

The agent is running interactively. The tests are using phantomjs. I've tried changing that to Chrome with no different result.
On the build server, if I run the step "npm run ci" manually in a cmd shell using the same useraccount as the agent, it runs ok.

[keithrob]

@mqlkmd ,
A couple of questions:
1) I noticed in the logs you have "yarn install && yarn run test". Is your "npm run ci" script calling yarn? Can you explain why you're doing this?

2) You mentioned that you're running phantomjs. Is PHANTOMJS_BIN set in your environment? It has been a source of problems in the past?

3) Finally, let's add some logging to figure out where we're coming off the rails. Please add..

• "--verbose" to your "npm run ci" command
• If you are calling yarn, from the 'ci' script please add --verbose to that also.
• Please set the log level to DEBUG in your karma config file.

[bryanmacfarlane]

additional side note - even though I don't think this is it - you can try the 117.1 agent (it's in pre -release in a download). It has the LTS version of node 6 for it's task script engine (node 5.10 was on that LTS release channel).

[mqlkmd]

@keithrob

1. Actually its for historic reasons when we were on a hosted agent that had issues in calling yarn commands directly so we triggered it through npm. This construct is actually not needed now, we would however like to use yarn for installing packages and not npm.
   Since you mentioned it, I just tried running the step with the VSTS "yarn Task" instead of npm. And that also hangs. As mentioned earlier, if I run the step through the VSTS "Command Line Task" it's fine.

2. Actually I already tried switching out phantomjs for Chrome browser in my karma.config, but to no avail. I have just added PHANTOMJS_BIN to env., reran the npm task and still the same issue.

3. Here are the complete log from the build with verbose switch: (Username replaced with *)

2017-06-01T05:54:41.9562196Z ##[debug]Evaluating condition for step: 'npm run ci'
2017-06-01T05:54:41.9562196Z ##[debug]Evaluating: succeeded()
2017-06-01T05:54:41.9562196Z ##[debug]Evaluating succeeded:
2017-06-01T05:54:41.9562196Z ##[debug]=> (Boolean) True
2017-06-01T05:54:41.9562196Z ##[debug]Expanded: True
2017-06-01T05:54:41.9562196Z ##[debug]Result: True
2017-06-01T05:54:41.9562196Z ##[section]Starting: npm run ci
2017-06-01T05:54:41.9562196Z ==============================================================================
2017-06-01T05:54:41.9562196Z Task : npm
2017-06-01T05:54:41.9562196Z Description : Run an npm command
2017-06-01T05:54:41.9562196Z Version : 0.2.22
2017-06-01T05:54:41.9562196Z Author : Microsoft Corporation
2017-06-01T05:54:41.9562196Z Help : More Information
2017-06-01T05:54:41.9562196Z ==============================================================================
2017-06-01T05:54:43.1446373Z ##[debug]agent.workFolder=C:\AzureAgent02_work
2017-06-01T05:54:43.1446373Z ##[debug]loading inputs and endpoints
2017-06-01T05:54:43.1446373Z ##[debug]loading ENDPOINT_AUTH_*
2017-06-01T05:54:43.1446373Z ##[debug]loading ENDPOINT_AUTH_PARAMETER__ACCESSTOKEN
2017-06-01T05:54:43.1446373Z ##[debug]loading ENDPOINT_AUTH_PARAMETER_SYSTEMVSSCONNECTION_ACCESSTOKEN
2017-06-01T05:54:43.1446373Z ##[debug]loading ENDPOINT_AUTH_SCHEME_
2017-06-01T05:54:43.1446373Z ##[debug]loading ENDPOINT_AUTH_SCHEME_SYSTEMVSSCONNECTION
2017-06-01T05:54:43.1446373Z ##[debug]loading ENDPOINT_AUTH_SYSTEMVSSCONNECTION
2017-06-01T05:54:43.1446373Z ##[debug]loading INPUT_ARGUMENTS
2017-06-01T05:54:43.1446373Z ##[debug]loading INPUT_COMMAND
2017-06-01T05:54:43.1446373Z ##[debug]loading INPUT_CWD
2017-06-01T05:54:43.1446373Z ##[debug]loaded 9
2017-06-01T05:54:43.1446373Z ##[debug]check path : C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\task.json
2017-06-01T05:54:43.1446373Z ##[debug]set resource file to: C:\AzureAgent02_work_tasks\Npm_fe47e961-9fa8-4106-8639-368c022d43ad\0.2.22\task.json
2017-06-01T05:54:43.1446373Z ##[debug]system.culture=en-US
2017-06-01T05:54:43.2244450Z ##[debug]cwd=C:\AzureAgent02_work\2\s\src\Gandalf.Web
2017-06-01T05:54:43.2244450Z ##[debug]testing directory 'C:\AzureAgent02_work\2\s\src\Gandalf.Web'
2017-06-01T05:54:43.2244450Z ##[debug]command=run
2017-06-01T05:54:43.2400794Z ##[debug]Absolute path for pathSegments: C:\AzureAgent02\externalsgit\cmd/npm = C:\AzureAgent02\externalsgit\cmd\npm
2017-06-01T05:54:43.2400794Z ##[debug]Absolute path for pathSegments: \AzureAgent02\NETLOGON/npm = \AzureAgent02\NETLOGON\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows\system32/npm = C:\Windows\system32\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows/npm = C:\Windows\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\Wbem/npm = C:\Windows\System32\Wbem\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\WindowsPowerShell\v1.0\/npm = C:\Windows\System32\WindowsPowerShell\v1.0\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\120\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\120\Tools\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\130\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\130\Tools\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft Emulator Manager\1.0\/npm = C:\Program Files (x86)\Microsoft Emulator Manager\1.0\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: /npm = C:\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Git\cmd/npm = C:\Program Files\Git\cmd\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\/npm = C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft\Web Platform Installer\/npm = C:\Program Files\Microsoft\Web Platform Installer\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\dotnet\/npm = C:\Program Files\dotnet\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\ProgramData\chocolateybin/npm = C:\ProgramData\chocolateybin\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\nodejs\/npm = C:\Program Files\nodejs\npm
2017-06-01T05:54:43.2557056Z ##[debug]check path : C:\Program Files\nodejs\npm.cmd
2017-06-01T05:54:43.2557056Z ##[debug]npm=C:\Program Files\nodejs\npm.cmd
2017-06-01T05:54:43.2557056Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: run
2017-06-01T05:54:43.2557056Z ##[debug]arguments=ci --verbose
2017-06-01T05:54:43.2557056Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: ci --verbose
2017-06-01T05:54:43.2557056Z ##[debug]USE_DEPRECATED_TASK_VERSION=undefined
2017-06-01T05:54:43.2557056Z ##[debug]Agent.BuildDirectory=C:\AzureAgent02_work\2
2017-06-01T05:54:43.2557056Z ##[debug]testing directory 'C:\AzureAgent02_work\2\npm'
2017-06-01T05:54:43.2557056Z ##[debug]build.buildId=25267
2017-06-01T05:54:43.2557056Z ##[debug]system.debug=true
2017-06-01T05:54:43.2557056Z ##[debug]system.debug=true
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\AzureAgent02\externalsgit\cmd/npm = C:\AzureAgent02\externalsgit\cmd\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: \AzureAgent02\NETLOGON/npm = \AzureAgent02\NETLOGON\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows\system32/npm = C:\Windows\system32\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows/npm = C:\Windows\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\Wbem/npm = C:\Windows\System32\Wbem\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Windows\System32\WindowsPowerShell\v1.0\/npm = C:\Windows\System32\WindowsPowerShell\v1.0\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\120\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\120\Tools\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft SQL Server\130\Tools\Binn\/npm = C:\Program Files\Microsoft SQL Server\130\Tools\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft Emulator Manager\1.0\/npm = C:\Program Files (x86)\Microsoft Emulator Manager\1.0\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: /npm = C:\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Git\cmd/npm = C:\Program Files\Git\cmd\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\/npm = C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\Microsoft\Web Platform Installer\/npm = C:\Program Files\Microsoft\Web Platform Installer\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\dotnet\/npm = C:\Program Files\dotnet\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\110\DTS\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\120\DTS\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\/npm = C:\Program Files (x86)\Microsoft SQL Server\130\DTS\Binn\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\ProgramData\chocolateybin/npm = C:\ProgramData\chocolateybin\npm
2017-06-01T05:54:43.2557056Z ##[debug]Absolute path for pathSegments: C:\Program Files\nodejs\/npm = C:\Program Files\nodejs\npm
2017-06-01T05:54:43.2557056Z ##[debug]check path : C:\Program Files\nodejs\npm.cmd
2017-06-01T05:54:43.2557056Z ##[debug]npm=C:\Program Files\nodejs\npm.cmd
2017-06-01T05:54:43.2557056Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: config list
2017-06-01T05:54:43.2557056Z ##[debug]C:\Program Files\nodejs\npm.cmd arg: -l
2017-06-01T05:54:43.2557056Z ##[debug]exec tool: C:\Program Files\nodejs\npm.cmd
2017-06-01T05:54:43.2557056Z ##[debug]Arguments:
2017-06-01T05:54:43.2557056Z ##[debug] config
2017-06-01T05:54:43.2557056Z ##[debug] list
2017-06-01T05:54:43.2557056Z ##[debug] -l
2017-06-01T05:54:43.2557056Z [command]C:\Program Files\nodejs\npm.cmd config list -l
2017-06-01T05:54:57.4368576Z npm info it worked if it ends with ok
2017-06-01T05:54:57.4368576Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-06-01T05:54:57.4368576Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-06-01T05:54:57.4368576Z npm verb cli 'prefix',
2017-06-01T05:54:57.4368576Z npm verb cli '-g' ]
2017-06-01T05:54:57.4368576Z npm info using [email protected]
2017-06-01T05:54:57.4368576Z npm info using [email protected]
2017-06-01T05:55:07.8042249Z npm verb exit [ 0, true ]
2017-06-01T05:55:07.8980046Z npm info ok
2017-06-01T05:55:08.4464320Z npm info it worked if it ends with ok
2017-06-01T05:55:08.4464320Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-06-01T05:55:08.4464320Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-06-01T05:55:08.4464320Z npm verb cli 'config',
2017-06-01T05:55:08.4464320Z npm verb cli 'list',
2017-06-01T05:55:08.4464320Z npm verb cli '-l' ]
2017-06-01T05:55:08.4464320Z npm info using [email protected]
2017-06-01T05:55:08.4464320Z npm info using [email protected]
2017-06-01T05:55:08.6026898Z ; cli configs
2017-06-01T05:55:08.6026898Z long = true
2017-06-01T05:55:08.6026898Z scope = ""
2017-06-01T05:55:08.6026898Z user-agent = "npm/4.2.0 node/v7.10.0 win32 x64"
2017-06-01T05:55:08.6026898Z
2017-06-01T05:55:08.6183159Z ; environment configs
2017-06-01T05:55:08.6183159Z loglevel = "verbose"
2017-06-01T05:55:08.6183159Z
2017-06-01T05:55:08.6183159Z ; builtin config undefined
2017-06-01T05:55:08.6183159Z prefix = "C:\Users\\AppData\Roaming\npm"
2017-06-01T05:55:08.6339414Z
2017-06-01T05:55:08.6339414Z ; default values
2017-06-01T05:55:08.7745746Z access = null
2017-06-01T05:55:08.7745746Z also = null
2017-06-01T05:55:08.7902000Z always-auth = false
2017-06-01T05:55:08.7902000Z bin-links = true
2017-06-01T05:55:08.7902000Z browser = null
2017-06-01T05:55:08.7902000Z ca = null
2017-06-01T05:55:08.7902000Z cache = "C:\Users\\AppData\Roaming\npm-cache"
2017-06-01T05:55:08.7902000Z cache-lock-retries = 10
2017-06-01T05:55:08.7902000Z cache-lock-stale = 60000
2017-06-01T05:55:08.7902000Z cache-lock-wait = 10000
2017-06-01T05:55:08.7902000Z cache-max = null
2017-06-01T05:55:08.7902000Z cache-min = 10
2017-06-01T05:55:08.7902000Z cafile = undefined
2017-06-01T05:55:08.7902000Z cert = null
2017-06-01T05:55:08.7902000Z color = true
2017-06-01T05:55:08.8370782Z depth = null
2017-06-01T05:55:08.9152065Z description = true
2017-06-01T05:55:09.0406040Z dev = false
2017-06-01T05:55:09.2120973Z dry-run = false
2017-06-01T05:55:09.2120973Z editor = "notepad.exe"
2017-06-01T05:55:09.2120973Z engine-strict = false
2017-06-01T05:55:09.2277381Z fetch-retries = 2
2017-06-01T05:55:09.2277381Z fetch-retry-factor = 10
2017-06-01T05:55:09.2277381Z fetch-retry-maxtimeout = 60000
2017-06-01T05:55:09.2277381Z fetch-retry-mintimeout = 10000
2017-06-01T05:55:09.2277381Z force = false
2017-06-01T05:55:09.5558627Z git = "git"
2017-06-01T05:55:09.5714894Z git-tag-version = true
2017-06-01T05:55:09.5714894Z global = false
2017-06-01T05:55:09.5714894Z global-style = false
2017-06-01T05:55:09.5714894Z globalconfig = "C:\Users\\AppData\Roaming\npm\etc\npmrc"
2017-06-01T05:55:09.5714894Z globalignorefile = "C:\Users\\AppData\Roaming\npm\etc\npmignore"
2017-06-01T05:55:09.5714894Z group = 0
2017-06-01T05:55:09.5714894Z heading = "npm"
2017-06-01T05:55:09.5714894Z https-proxy = null
2017-06-01T05:55:09.5714894Z if-present = false
2017-06-01T05:55:09.5714894Z ignore-scripts = false
2017-06-01T05:55:09.5714894Z init-author-email = ""
2017-06-01T05:55:09.5714894Z init-author-name = ""
2017-06-01T05:55:09.5714894Z init-author-url = ""
2017-06-01T05:55:09.5714894Z init-license = "ISC"
2017-06-01T05:55:09.6183677Z init-module = "C:\Users\\.npm-init.js"
2017-06-01T05:55:09.6183677Z init-version = "1.0.0"
2017-06-01T05:55:09.7121222Z json = false
2017-06-01T05:55:09.8215026Z key = null
2017-06-01T05:55:09.9777606Z legacy-bundling = false
2017-06-01T05:55:09.9777606Z link = false
2017-06-01T05:55:09.9777606Z local-address = undefined
2017-06-01T05:55:09.9777606Z ; loglevel = "warn" (overridden)
2017-06-01T05:55:09.9777606Z logs-max = 10
2017-06-01T05:55:09.9777606Z ; long = false (overridden)
2017-06-01T05:55:09.9777606Z maxsockets = 50
2017-06-01T05:55:09.9777606Z message = "%s"
2017-06-01T05:55:09.9777606Z metrics-registry = "https://registry.npmjs.org/"
2017-06-01T05:55:09.9777606Z node-version = "7.10.0"
2017-06-01T05:55:09.9777606Z onload-script = null
2017-06-01T05:55:09.9777606Z only = null
2017-06-01T05:55:09.9777606Z optional = true
2017-06-01T05:55:09.9777606Z parseable = false
2017-06-01T05:55:09.9777606Z ; prefix = "C:\Program Files\nodejs" (overridden)
2017-06-01T05:55:09.9777606Z production = false
2017-06-01T05:55:09.9777606Z progress = true
2017-06-01T05:55:09.9777606Z proprietary-attribs = true
2017-06-01T05:55:09.9777606Z proxy = null
2017-06-01T05:55:09.9777606Z rebuild-bundle = true
2017-06-01T05:55:09.9777606Z registry = "https://registry.npmjs.org/"
2017-06-01T05:55:09.9777606Z rollback = true
2017-06-01T05:55:09.9777606Z save = false
2017-06-01T05:55:09.9777606Z save-bundle = false
2017-06-01T05:55:09.9777606Z save-dev = false
2017-06-01T05:55:09.9777606Z save-exact = false
2017-06-01T05:55:09.9777606Z save-optional = false
2017-06-01T05:55:09.9777606Z save-prefix = "^"
2017-06-01T05:55:09.9777606Z scope = ""
2017-06-01T05:55:09.9933861Z scripts-prepend-node-path = "warn-only"
2017-06-01T05:55:09.9933861Z searchexclude = null
2017-06-01T05:55:09.9933861Z searchlimit = 20
2017-06-01T05:55:09.9933861Z searchopts = ""
2017-06-01T05:55:09.9933861Z searchstaleness = 900
2017-06-01T05:55:09.9933861Z send-metrics = false
2017-06-01T05:55:09.9933861Z shell = "C:\Windows\system32\cmd.exe"
2017-06-01T05:55:09.9933861Z shrinkwrap = true
2017-06-01T05:55:09.9933861Z sign-git-tag = false
2017-06-01T05:55:09.9933861Z strict-ssl = true
2017-06-01T05:55:09.9933861Z tag = "latest"
2017-06-01T05:55:09.9933861Z tag-version-prefix = "v"
2017-06-01T05:55:09.9933861Z tmp = "C:\AzureAgent02\_work\_temp"
2017-06-01T05:55:09.9933861Z umask = 0
2017-06-01T05:55:09.9933861Z unicode = false
2017-06-01T05:55:09.9933861Z unsafe-perm = true
2017-06-01T05:55:09.9933861Z usage = false
2017-06-01T05:55:09.9933861Z user = 0
2017-06-01T05:55:09.9933861Z ; user-agent = "npm/{npm-version} node/{node-version} {platform} {arch}" (overridden)
2017-06-01T05:55:09.9933861Z userconfig = "C:\Users\\.npmrc"
2017-06-01T05:55:09.9933861Z version = false
2017-06-01T05:55:09.9933861Z versions = false
2017-06-01T05:55:09.9933861Z viewer = "browser"
2017-06-01T05:55:09.9933861Z
2017-06-01T05:55:09.9933861Z
2017-06-01T05:55:09.9933861Z npm verb exit [ 0, true ]
2017-06-01T05:55:09.9933861Z npm info ok
2017-06-01T05:55:09.9933861Z ##[debug]rc:0
2017-06-01T05:55:09.9933861Z ##[debug]success:true
2017-06-01T05:55:09.9933861Z ##[debug]exec tool: C:\Program Files\nodejs\npm.cmd
2017-06-01T05:55:09.9933861Z ##[debug]Arguments:
2017-06-01T05:55:09.9933861Z ##[debug] run
2017-06-01T05:55:09.9933861Z ##[debug] ci
2017-06-01T05:55:09.9933861Z ##[debug] --verbose
2017-06-01T05:55:09.9933861Z [command]C:\Program Files\nodejs\npm.cmd run ci --verbose
2017-06-01T05:55:09.9933861Z npm info it worked if it ends with ok
2017-06-01T05:55:09.9933861Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-06-01T05:55:09.9933861Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-06-01T05:55:09.9933861Z npm verb cli 'prefix',
2017-06-01T05:55:09.9933861Z npm verb cli '-g' ]
2017-06-01T05:55:09.9933861Z npm info using [email protected]
2017-06-01T05:55:09.9933861Z npm info using [email protected]
2017-06-01T05:55:09.9933861Z npm verb exit [ 0, true ]
2017-06-01T05:55:09.9933861Z npm info ok
2017-06-01T05:55:09.9933861Z npm info it worked if it ends with ok
2017-06-01T05:55:09.9933861Z npm verb cli [ 'C:\Program Files\nodejs\node.exe',
2017-06-01T05:55:09.9933861Z npm verb cli 'C:\Program Files\nodejs\node_modules\npm\bin\npm-cli.js',
2017-06-01T05:55:09.9933861Z npm verb cli 'run',
2017-06-01T05:55:09.9933861Z npm verb cli 'ci',
2017-06-01T05:55:09.9933861Z npm verb cli '--verbose' ]
2017-06-01T05:55:09.9933861Z npm info using [email protected]
2017-06-01T05:55:09.9933861Z npm info using [email protected]
2017-06-01T05:55:10.5770112Z npm verb run-script [ 'preci', 'ci', 'postci' ]
2017-06-01T05:55:10.5770112Z npm info lifecycle [email protected]~preci: [email protected]
2017-06-01T05:55:10.5926375Z npm info lifecycle [email protected]~ci: [email protected]
2017-06-01T05:55:10.5926375Z
2017-06-01T05:55:10.5926375Z > [email protected] ci C:\AzureAgent02_work\2\s\src\Gandalf.Web
2017-06-01T05:55:10.5926375Z > yarn install && yarn run test --verbose
2017-06-01T05:55:10.5926375Z
2017-06-01T05:55:11.2530781Z yarn install v0.24.6
2017-06-01T05:55:11.8414855Z [1/4] Resolving packages...
2017-06-01T05:55:12.9196449Z success Already up-to-date.
2017-06-01T05:55:12.9196449Z Done in 1.67s.
2017-06-01T05:55:13.1696558Z yarn run v0.24.6
2017-06-01T05:55:13.2946739Z verbose 0.247 Checking for configuration file "C:\AzureAgent02\_work\2\s\src\Gandalf.Web\.npmrc".
2017-06-01T05:55:13.2946739Z verbose 0.249 Checking for configuration file "C:\Users\\.npmrc".
2017-06-01T05:55:13.2946739Z verbose 0.249 Checking for configuration file "C:\Program Files\nodejs\.npmrc".
2017-06-01T05:55:13.3149503Z verbose 0.25 Checking for configuration file "C:\AzureAgent02\_work\2\s\src\Gandalf.Web\.npmrc".
2017-06-01T05:55:13.3259135Z verbose 0.25 Checking for configuration file "C:\AzureAgent02\_work\2\s\src\.npmrc".
2017-06-01T05:55:13.3259135Z verbose 0.25 Checking for configuration file "C:\AzureAgent02\_work\2\s\.npmrc".
2017-06-01T05:55:13.3259135Z verbose 0.25 Checking for configuration file "C:\AzureAgent02\_work\2\.npmrc".
2017-06-01T05:55:13.3259135Z verbose 0.251 Checking for configuration file "C:\AzureAgent02\_work\.npmrc".
2017-06-01T05:55:13.3259135Z verbose 0.251 Checking for configuration file "C:\AzureAgent02\.npmrc".
2017-06-01T05:55:13.3259135Z verbose 0.255 Checking for configuration file "C:\AzureAgent02\_work\2\s\src\Gandalf.Web\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.255 Checking for configuration file "C:\Users\\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.255 Found configuration file "C:\Users\*\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.256 Checking for configuration file "C:\Program Files\nodejs\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.257 Checking for configuration file "C:\AzureAgent02\_work\2\s\src\Gandalf.Web\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.257 Checking for configuration file "C:\AzureAgent02\_work\2\s\src\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.257 Checking for configuration file "C:\AzureAgent02\_work\2\s\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.257 Checking for configuration file "C:\AzureAgent02\_work\2\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.257 Checking for configuration file "C:\AzureAgent02\_work\.yarnrc".
2017-06-01T05:55:13.3259135Z verbose 0.258 Checking for configuration file "C:\AzureAgent02\.yarnrc".
2017-06-01T05:55:13.4352950Z verbose 0.259 current time: 2017-06-01T05:55:13.200Z
2017-06-01T05:55:13.4352950Z $ node --max-old-space-size=4096 node_modules/@angular/cli/bin/ng test
2017-06-01T06:03:48.3157752Z ##[debug]Re-evaluate condition on job cancellation for step: 'npm run ci'.
2017-06-01T06:03:49.1905493Z ##[error]The operation was canceled.
2017-06-01T06:03:49.1905493Z ##[debug]System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at Microsoft.VisualStudio.Services.Agent.ProcessInvoker.d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.NodeHandler.d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.d__24.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.StepsRunner.d__1.MoveNext()
2017-06-01T06:03:49.1905493Z ##[section]Finishing: npm run ci

[mqlkmd]

@bryanmacfarlane

I can't find the pre-release 117.1 in the releases tab here on github. Can you point me to where I can download it to try it out?
Thanks.

[bryanmacfarlane]

Sorry - in agent repo: https://github.com/microsoft/vsts-agent

[keithrob]

@mqlkmd,
I am interested to know if @bryanmacfarlane's suggestion resolved the issue. If it hasn't then, I need you to try a few more things.

Looking at the log it looks like you're calling "ng test" at "2017-06-01T05:55:13.4352950Z" and then the process is hanging and we get no additional information. Lets try adding logging via the ng cli to karma. Please add "--log-level debug" to "ng test". Angular CLI will pass this information to Karma and hopefully we'll get some additional information.

[mqlkmd]

Yes, I tried the new agent, but the same result. We do require node v7 AFAIK, so don't know if that makes a difference.

Is there a way I can run the npmtask manually on the build server to perhaps get some more info? Which variables should be set before executing the npmtask.js ?

I just ran the build again with debug loglevel set, but still no more info.
2017-06-02T06:19:57.5281310Z verbose 0.305 current time: 2017-06-02T06:19:57.433Z
2017-06-02T06:19:57.5281310Z $ node --max-old-space-size=4096 node_modules/@angular/cli/bin/ng test --log-level debug
2017-06-02T06:35:52.2433368Z ##[debug]Re-evaluate condition on job cancellation for step: 'npm run ci'.
2017-06-02T06:35:52.5841527Z ##[error]The operation was canceled.
2017-06-02T06:35:52.5841527Z ##[debug]System.OperationCanceledException: The operation was canceled.
at System.Threading.CancellationToken.ThrowOperationCanceledException()
at Microsoft.VisualStudio.Services.Agent.ProcessInvoker.d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.Handlers.NodeHandler.d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.TaskRunner.d__24.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Microsoft.VisualStudio.Services.Agent.Worker.StepsRunner.d__1.MoveNext()
2017-06-02T06:35:52.5841527Z ##[section]Finishing: npm run ci

[b-barthel]

I find it interesting that the command line task passes but both the NPM task and the yarn task hang - I'm assuming you used the yarn task from here. It feels like (both) tool tasks are executing npm/yarn in a slightly different manner than you expect, causing some kind of issue inside "ng test". Are you doing anything special in the command task like setting the working directory? I see that the npm task thinks your working directory is:

2017-06-01T05:54:43.2244450Z ##[debug]cwd=C:\AzureAgent02_work\2\s\src\Gandalf.Web

Is that the correct directory for running these tests?

[bryanmacfarlane]

@b-barthel - Yes! Exactly what I've been pondering. Both the cmd line task and npm task exec a process with the exact same code. Analyzing the chain of processes involved after that might be the clue.

Good point on cwd as well.

[mqlkmd]

Yes, that is the correct working directory. Please see below snippet from cmdline: (here I tried to switch out phantomjs for Chrome) and it still fails on the npm task but not through cmdline.

C:\AzureAgent02_work\2\s\src\Gandalf.Web>node --max-old-space-size=4096 node_modules/@angular/cli/bin/ng test --log-level debug
06 06 2017 09:57:41.129:DEBUG [config]: Loading config C:\AzureAgent02_work\2\s\src\Gandalf.Webkarma.conf.js
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining framework:jasmine).
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining launcher:Chrome, launcher:ChromeCanary, launcher:Chromium, launcher:Dartium, test).
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining launcher:PhantomJS).
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining reporter:kjhtml).
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining reporter:coverage-istanbul).
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining framework:@angular/cli, preprocessor:@angular/cli, middleware:angularCliBlocker).
06 06 2017 09:57:42.410:DEBUG [plugin]: Loading inlined plugin (defining launcher:Chrome_with_debugging).
10% building modules 1/1 modules 0 active06 06 2017 09:57:45.473:DEBUG [web-server]: Instantiating middleware
06 06 2017 09:57:45.473:DEBUG [reporter]: Trying to load reporter: kjhtml
06 06 2017 09:57:45.488:DEBUG [reporter]: Trying to load color-version of reporter: kjhtml (kjhtml_color)
06 06 2017 09:57:45.488:DEBUG [reporter]: Couldn't load color-version.
06 06 2017 09:57:52.942:INFO [karma]: Karma v1.4.0 server started at http://0.0.0.0:9876/
06 06 2017 09:57:52.942:INFO [launcher]: Launching browser Chrome with unlimited concurrency
06 06 2017 09:57:52.957:INFO [launcher]: Starting browser Chrome
.......
06 06 2017 09:58:18.333:DEBUG [middleware:source-files]: Requesting /_karma_webpack_/scripts.bundle.js /
06 06 2017 09:58:18.334:DEBUG [middleware:source-files]: Fetching /_karma_webpack_/scripts.bundle.js
06 06 2017 09:58:18.341:DEBUG [middleware:source-files]: Requesting /_karma_webpack_/vendor.bundle.js /
06 06 2017 09:58:18.342:DEBUG [middleware:source-files]: Fetching /_karma_webpack_/vendor.bundle.js
06 06 2017 09:58:18.410:DEBUG [middleware:source-files]: Requesting /_karma_webpack_/main.bundle.js /
06 06 2017 09:58:18.411:DEBUG [middleware:source-files]: Fetching /_karma_webpack_/main.bundle.js
Chrome 58.0.3029 (Windows 8.1 0.0.0): Executed 70 of 70 SUCCESS (9.134 secs / 8.857 secs)
06 06 2017 09:58:29.356:DEBUG [karma]: Run complete, exiting.
06 06 2017 09:58:29.356:DEBUG [launcher]: Disconnecting all browsers
06 06 2017 09:58:29.679:DEBUG [launcher]: Process Chrome exited with code 0
06 06 2017 09:58:29.679:DEBUG [temp-dir]: Cleaning temp dir C:\Users\DEVTES~1\AppData\Local\Tempkarma-30358082
06 06 2017 09:58:29.804:DEBUG [launcher]: Finished all browsers

[keithrob]

@mqlkmd,
There is nothing interesting/useful between "2017-06-01T05:55:13.4352950Z" and "2017-06-01T06:03:49.1905493Z" and we need more information to successfully debug this. Let's try a few more things:

I can see that "ng test" includes "--log-level=DEBUG"; however, I'm not seeing any debug output from Karma. You should see something like this...

• 07 06 2017 09:32:45.810:DEBUG [reporter]: Trying to load reporter

What happens when you run "node ./node_modules/karma/bin/karma start --log-level=DEBUG" as the build identity (not a normal user)? Do you get prompted for firewall exceptions? What is the port in karma.conf.js and is there anything else running on that port?

[mqlkmd]

Interestingly, the "karma start" works fine both from cmd shell and vsts npm task, so it seems like "ng test" never triggers karma start:
2017-06-08T07:36:04.8554994Z $ node ./node_modules/karma/bin/karma start --log-level=DEBUG
2017-06-08T07:36:05.1211076Z 08 06 2017 07:35:59.184:DEBUG [config]: Loading config C:\AzureAgent02_work\2\s\src\Gandalf.Webkarma.conf.js
2017-06-08T07:36:05.3242174Z 08 06 2017 07:36:00.621:DEBUG [plugin]: Loading inlined plugin (defining framework:jasmine).
2017-06-08T07:36:05.5273298Z 08 06 2017 07:36:00.621:DEBUG [plugin]: Loading inlined plugin (defining launcher:Chrome, launcher:ChromeCanary, launcher:Chromium, launcher:Dartium, test).
2017-06-08T07:36:05.7460656Z 08 06 2017 07:36:00.621:DEBUG [plugin]: Loading inlined plugin (defining launcher:PhantomJS).
2017-06-08T07:36:06.0897945Z 08 06 2017 07:36:00.621:DEBUG [plugin]: Loading inlined plugin (defining reporter:kjhtml).
2017-06-08T07:36:06.3397775Z 08 06 2017 07:36:00.621:DEBUG [plugin]: Loading inlined plugin (defining reporter:coverage-istanbul).

angular-cli.json has following configuration for "test":
"test": {
"karma": {
"config": "./karma.conf.js"
}
},

[keithrob]

@mqlkmd,
Still having this problem?
Keith

[mqlkmd]

@keithrob ,
We had to abandon the NPM tasks and just use plain cmd tasks.
I just tried another run using npm tasks and the problem unfortunately remains.
We are not blocked by this now since we are not using the npm tasks, but we might be sometime in the future if we need some of the features of npm task, like auth using buildagent's accesstoken.

[keithrob]

@mqlkmd,
Glad to hear you worked around the issue.

Also, we are going to be releasing a new build task soon which will inject credentials into a .npmrc and leave them around for the lifespan of the build. This should allow you to authenticate to a Feed using your custom scripts without some of the clunky/insecure work-a-rounds (e.g. userlevel .npmrc on build system or checked in credentials).

Keith

[abannsunny]

you can try
ng test --watch=false

This worked for us!

watch mode will look for file changes and re run the tests.

"Tests will execute after a build is executed via Karma, and it will automatically watch your files for changes. You can run tests a single time via --watch=false."

[bsoulier]

For those who are still blocked on that, I have been able to solve this by replacing my "npm" task by a "Command line" task that run npm and set max_old_space_size as an environment variable.