Azure-pipelines-tasks: Npm V1 task does not write proper output to logs

[marcin-chwedczuk-meow]

In my build pipeline I use Npm v1 task to run npm test and npm install commands. In the log output from the task I can see only a single line like:

 [command]C:\Windows\system32\cmd.exe /D /S /C "C:\BuildAgents\A\_work\_tool\node\8.11.1\x64\npm.cmd install --no-optional"

This is not sufficient for my needs I would like to see detiled logs - just exactly the logs that I can see when I start npm via cmd.exe on my local machine. I use VSTS with the "new" visual theme.

[jotaylo]

Which version of the task are you running, and what sort of build agent? I've just checked our suite of validation builds for the Npm V1 task, and they all contain the full npm logs as expected.

[marcin-chwedczuk-meow]

We use a self-hosted agent:

Agent.OS | Windows_NT
Agent.OSVersion | 10.0.14393
Agent.Version | 2.120.2

Task version 1.* (dropdown in VSTS), command Custom, exact command line:

run test -- --env=$(env) $(customOptions)

Before this command we use Use Node 8.x block (Node Tool Installer) - version speck 8.x.

Where can I check VSTS version itself? I will try to provide all necessary information so please ask if something is missing.

[marcin-chwedczuk-meow]

OK I double checked (in meanwhile we have an update to VSTS) and now we indeed get log output on completed builds. But still output is missing on ongoing builds. Now I must wait 10 minutes until command is finished and only then I can see log output - no immediate results.

Please see attached screenshot - I entered the build log after command run for 4 minutes still without any output.

[marcin-chwedczuk-meow]

I consulted with my teammates and indeed on completed builds logs were always present, here we are concerned only about logs that we can see during ongoing builds. Sorry for this misunderstanding.

[bryanmacfarlane]

is only the npm test not showing live console output? or are all tasks not showing live console?

are your tests buffering output?

[rehael]

In the build @marcin-chwedczuk-meow describes we use mainly node steps. All of them behave like buffered on the agent. Get Sources is too quick to say if it's buffered or not.
Node commands, when run manually in cmd.exe, generate output just fine, line by line.
We use mainly: npm install --no-optional, npm test, and some custom scripts too. All output it presented only after the command finishes fully. For short tasks it's ok. But npm test (which uses TestCafe and custom reporter, not buffered) takes a lot of time, and especially for that one we'd like to see the output live. Previously (in the old VSTS UI) it worked just fine.

[bryanmacfarlane]

some things to narrow:
trying cmdline task (and run npm test) to see if that's buffering - trying to see if task or whether you're having a general signal R issue

Do F12 / devtools in the browser and see if you're getting an errors

If you "queue with diagnostics" the logs will have trace output from the agent and that will help us see if the task or the agent is buffering.

[rehael]

Task _Utility: Command line_ v2 – does indeed _not_ buffer npm output. Chrome console does not show any errors (some warning for getCodeCoverageSummary promise returning null only, not important here I think).

Diagnostic log contains some data we'd like not to share publicly. Is there something specific we should extract from the diagnostic log, anonymize our sensitive data and share with you?

What I see by comparing the two tasks (npm and command line) is that npm task first show that npm test failed, and then shows the command output.

[keithrob]

The NPM task synchronously runs your command, buffers the output, and prints it at the end of the task. We will be switching to async (i.e. streaming STDOUT/STDERR) but there should be no change in total duration of your step. The only difference will be that you observe STDOUT/STDERR sooner.

[rehael]

Okay, thanks for clarification. Any ETA on the async?

[bryanmacfarlane]

@keithrob - thanks for confirming. I think it should be as simple as switching a line to await tl.exec (instead of tf.execSync)? Let me know if that's correct. In the early days it was harder but await makes it awesome :) Regarding the task model async is a big deal as buffering gives the impression of a hang or non responsive.

[mikeharder]

@keithrob, @bryanmacfarlane: The current behavior of the npm task buffering output is also a problem for us. We need to enable realtime output from long-running tests. For now, we will workaround this by using a script task instead of npm.

[elbatk]

Hello! I'm a PM over on the Azure Artifacts team. I wanted to drop in here and address some of these issues with the news that we're currently reevaluating the types of tasks we offer in Azure Pipelines, and looking to focus more on lighter-weight tasks that cover authentication and setup. In lieu of the task redesign, we're going to forego making changes to the current tasks (with a few exceptions). We hope the new tasks we spin up in the next quarter or so are easier and more helpful, be on the lookout!

An addition to my copied/pasted blurb above: The issue seen here is one of the reasons we're switching - to remove some of our unwanted/unexpected behavior in favor of simply using the scripts/command line tools from the actual protocols.

[alexb5dh]

@elbatk, is there any estimate or issue that can be tracked for this redesign?

[kepikoi]

@elangelo can we have an update on this issue?

[kepikoi]

@elangelo Any update on this? I'm struggling with timeouts on long-running npm test task and cannot see the culprit due to missing logs

[JonathanLydall]

@kepikoi

elangelo Any update on this? I'm struggling with timeouts on long-running npm test task and cannot see the culprit due to missing logs

Try use a different task type instead, we do something like the following and it then shows output:

- task: CmdLine@2
  condition: succeeded()
  inputs:
    script: npm test
    workingDirectory: $(workingDirectory)