Command-line task reports false success if STDIO left open

[glucaci]

Originally posted by @glucaci in https://github.com/microsoft/azure-pipelines-tasks/issues/11334#issuecomment-583333300

I've created new issue because nobody answers on closed one. Below is the content of the original post:

Original:

Lately we have the same problem with a .NET Core Task. I reported this also in https://github.com/microsoft/azure-pipelines-image-generation/issues/1386 because I'm not sure where this fits.

Starting: dotnet tool restore
==============================================================================
Task         : .NET Core
Description  : Build, test, package, or publish a dotnet application, or run a custom dotnet command
Version      : 2.164.0
Author       : Microsoft Corporation
Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/build/dotnet-core-cli
==============================================================================
/opt/hostedtoolcache/dotnet/dotnet tool restore --ignore-failed-sources --no-cache --verbosity normal

... restoring packages

Restore was successful.
The STDIO streams did not close within 10 seconds of the exit event from process '/opt/hostedtoolcache/dotnet/dotnet'. This may indicate a child process inherited the STDIO streams and has not yet exited.

and the task will remain blocked until build timeout expires.

Update:

Also with Task Version 2.169.1

Workaround:

Enable Continue on error and set Timeout on 1 min

[tejasd1990]

Hi @glucaci, can you share the full debug logs where you have faced this issue? Also, how can I repro this for investigation?

[glucaci]

There is nothing more to add from the logs, it's running dotnet tool restore successfully and then it blocks and you can see the message The STDIO streams did not close....

I don't know how you can reproduce it, because also on our pipelines it happens sporadic and i assume it's a race condition somehow.

[Kolky]

I'm having the same issue. Before this task I also do a NuGetAuthenticate, because we are using a DevOps Artifact Repo. Before I noticed it was running for 45mins. It happens about once every 20 builds.

This is part of the pipeline, the log for the last step is below;

  # Authenticate to Azure NuGet Source
  - task: NuGetAuthenticate@0
    displayName: 'NuGet Authenticate'

  # Build & Test DotNet apps
  - task: DotNetCoreCLI@2
    displayName: 'Restore DotNet Packages'
    inputs:
      command: 'restore'
      feedsToUse: 'config'
      nugetConfigPath: 'nuget.config'
      verbosityRestore: 'normal'

  - task: DotNetCoreCLI@2
    displayName: 'Restore DotNet Tools'
    inputs:
      command: 'custom'
      custom: 'tool'
      arguments: 'restore --verbosity normal'

As suggested by others we also have the following variables in our yml; reference https://developercommunity.visualstudio.com/content/problem/899022/dotnetcorecli-5.html If I omit this our "dotnet tool restore" fails even more often.

  - name: 'NUGET_PLUGIN_REQUEST_TIMEOUT_IN_SECONDS'
    value: 30
  - name: 'NUGET_PLUGIN_HANDSHAKE_TIMEOUT_IN_SECONDS'
    value: 30

2021-01-19T13:56:50.5484644Z ##[section]Starting: Restore DotNet Tools
2021-01-19T13:56:50.5742532Z ==============================================================================
2021-01-19T13:56:50.5742850Z Task         : .NET Core
2021-01-19T13:56:50.5743126Z Description  : Build, test, package, or publish a dotnet application, or run a custom dotnet command
2021-01-19T13:56:50.5743408Z Version      : 2.179.2
2021-01-19T13:56:50.5743595Z Author       : Microsoft Corporation
2021-01-19T13:56:50.5743876Z Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/build/dotnet-core-cli
2021-01-19T13:56:50.5744215Z ==============================================================================
2021-01-19T13:56:51.5741331Z [command]C:\windows\system32\chcp.com 65001
2021-01-19T13:56:51.5915522Z Active code page: 65001
2021-01-19T13:56:51.6178914Z Info: .NET Core SDK/runtime 2.2 and 3.0 are now End of Life(EOL) and have been removed from all hosted agents. If you're using these SDK/runtimes on hosted agents, kindly upgrade to newer versions which are not EOL, or else use UseDotNet task to install the required version.
2021-01-19T13:56:51.6211035Z [command]"C:\Program Files\dotnet\dotnet.exe" tool restore --verbosity normal
2021-01-19T13:56:53.3117884Z Build started 1/19/2021 1:56:53 PM.
2021-01-19T13:56:53.3301669Z Build started 1/19/2021 1:56:53 PM.
2021-01-19T13:56:53.9619862Z      1>Project "C:\Users\VssAdministrator\AppData\Local\Temp\yb2xbuyx.doe\restore.csproj" on node 1 (Restore target(s)).
2021-01-19T13:56:53.9620852Z      1>_GetAllRestoreProjectPathItems:
2021-01-19T13:56:53.9621572Z          Determining projects to restore...
2021-01-19T13:56:53.9853258Z      1>Project "C:\Users\VssAdministrator\AppData\Local\Temp\h5bsbxpr.gzp\restore.csproj" on node 1 (Restore target(s)).
2021-01-19T13:56:53.9855129Z      1>_GetAllRestoreProjectPathItems:
2021-01-19T13:56:53.9856100Z          Determining projects to restore...
2021-01-19T13:56:54.3239663Z        Restore:
2021-01-19T13:56:54.3240773Z          Restoring packages .....

<snipped>

2021-01-19T13:57:01.6979291Z Build succeeded.
2021-01-19T13:57:01.7001260Z     0 Warning(s)
2021-01-19T13:57:01.7006055Z     0 Error(s)
2021-01-19T13:57:01.7006635Z 
2021-01-19T13:57:01.7007167Z Time Elapsed 00:00:08.37
2021-01-19T13:57:01.8580229Z Tool 'gitversion.tool' (version '5.5.1') was restored. Available commands: dotnet-gitversion
2021-01-19T13:57:01.8581114Z Tool 'dotnet-reportgenerator-globaltool' (version '4.8.4') was restored. Available commands: reportgenerator
2021-01-19T13:57:01.8582664Z 
2021-01-19T13:57:01.8582882Z Restore was successful.
2021-01-19T13:57:11.8858947Z The STDIO streams did not close within 10 seconds of the exit event from process 'C:\Program Files\dotnet\dotnet.exe'. This may indicate a child process inherited the STDIO streams and has not yet exited.
2021-01-19T13:57:11.8885895Z Info: Azure Pipelines hosted agents have been updated and now contain .Net 5.x SDK/Runtime along with the older .Net Core version which are currently lts. Unless you have locked down a SDK version for your project(s), 5.x SDK might be picked up which might have breaking behavior as compared to previous versions. You can learn more about the breaking changes here: https://docs.microsoft.com/en-us/dotnet/core/tools/ and https://docs.microsoft.com/en-us/dotnet/core/compatibility/ . To learn about more such changes and troubleshoot, refer here: https://docs.microsoft.com/en-us/azure/devops/pipelines/tasks/build/dotnet-core-cli?view=azure-devops#troubleshooting

[prabhakarreddy1234]

We are getting this error too on dotnet test command. But it's occurring intermittently.

[alanwales]

We have also seen this happen in the past couple of weeks with dotnet test. It seems to happen when the runner is uploading the test results and then hangs, and also intermittently

[albigi]

we are having the same, even after isolating the publishing result into a different step we sometimes see this error message when the test runs are over.

the problem started all of a sudden a couple of weeks ago. It's not clear to us whether this depends on anything in our code at all (e.g. ApplicationInsights telemetry), the tests host itself or else. we went through our codebase several times to make sure all the dotnet hosts are properly disposed and we are currently stalled with the investigation.

while this is not really a blocking issue the impact on our business is huge as it's essentially breaking our automated deployment process several times a day with lots of delays

any help in troubleshooting this is greatly appreciated

[BartNetJS]

Same issue here with bash

The STDIO streams did not close within 10 seconds of the exit event from process 'C:\Program Files\Git\bin\bash.exe'. This may indicate a child process inherited the STDIO streams and has not yet exited.

[Kolky]

This happens daily to us! There is - afaik - no workaround except cancel and retry your build. Can this get more attention? Will there be improvements for dotnet tool restore using Azure DevOps?

[bishal-pdMSFT]

@vineetmimrot please take a look

[Kolky]

Small update; we've changed nothing and it hasn't occured in several days. Maybe something was changed at the agent level?

[tejasd1990]

Hi all, the dotnet task uses the task-lib to run dotnet commands, and the error is coming from there. From the task-lib code, it seems that the wait for streams to close(default 10000, which is 10 seconds) can be increased through the TASKLIB_TEST_TOOLRUNNER_EXITDELAY environment variable. Can you try to set it to 60000 or even more and see if this issue still persists? And if yes, please share the complete pipeline and full debug logs.

[mattduguid]

we have recently had this start happening in a "AzurePowerShell@4" task where we run terraform from on a microsoft hosted agent running "ubuntu-20.04",

The STDIO streams did not close within 10 seconds of the exit event from process '/usr/bin/pwsh'. This may indicate a child process inherited the STDIO streams and has not yet exited.

...have tried the env var of TASKLIB_TEST_TOOLRUNNER_EXITDELAY=60000 but doesnt have any effect on the issue.

UPDATE 12/04/2021: Located a contributor to our issue by capturing a list of the processes running at start and end of our "AzurePowerShell@4" task then comparing them to find the new ones. There was one of immediate interest so we ran a kill command on it at the end of the task and the problem was then worked around for us. We had recently introduced a new terraform lastpass provider and while it performed its task correctly somewhere during its work something was leaving the lastpass-cli (./lpass) process open. We'll need to open a ticket for this with both the developers of the terraform lastpass provider and lastpass-cli to locate the true root cause but the short term workaround has unblocked us.

[chenzhen0592]

Same issue with you. Do you fix the issue, or have some workarounds? @alanwales

[alanwales]

We worked around it by outputting the logs to a file and failing the pipeline if issues were found. We added this to a PowerShell file which runs the build:

dotnet build "$buildFile" --configuration "Release" -warnaserror | tee build.log

foreach($line in [System.IO.File]::ReadLines("build.log")){ if($line -contains "Build FAILED.") { Write-Error "Build forced as fail in powershell because errors were found in the build output. Fix the errors and retry" } }

---

I just re-read the issue and for the STDIO left open we found there were processes being spawned which weren't closed during the test run, so we added a test dispose method which ensured the hosts we were creating are disposed and that solved it e.g.

[TestClass] public class PlatformAssemblyInitializer { [AssemblyCleanup] public static async Task DisposeAsync() { await SimulatedEnvironmentRunner.DisposeAsync(); } }

[Kolky]

Seems to still occur to us. Still happening when executing a dotnet tool restore after a NuGet Authenticate step (0.181.0). Setup is still similar to the one suggested by me above.

I have been looking at agent versions and dates; and it has not occurred for the whole of last week and this week until today. Today it occurred twice, both for agent image version '20210531.1' and '20210608.0' (both using agent version '2.186.1'). Although most runs from last week use the first image.

Last time it occurred for us was 31st of May and before that 20th of May. And always just once or twice a day. There is no pattern or anything.

[tejasd1990]

ack, will look into this and update today

[tejasd1990]

hi all, since we have not been able to repro this issue, will need the pipeline(including any src) and debug logs for one of your failure instance(as i had said earlier) for investigating. It will be helpful in figuring out what kind of projects see this error. If you need to share in private, you can mail me at tejasd1990@github.com Also, can anyone tell how frequently you see this error(what percent of deployments)?

[stesee]

The issue was 100% reproducable with https://github.com/Codeuctivity/OpenXmlToHtml as long, as I missed closing every spawned chromium processes before the unit tests end.

After fixing the missing disposing of chromium processes, the pipeline stopped failing.

romanko also found out, that orphaned browsers could lead to the same issue https://stackoverflow.com/questions/55953465/azure-devops-pipeline-test-showing-partially-succeeded/56955030#comment120054880_56955030

You got a mail with links to the build history.

[Kolky]

@tejasd1990 I've send an email with our pipeline and log-files.

[AlessandroDalMas]

In my case, we see this log:

  Determining projects to restore...
  Restored D:\Build\a2\212\s\Tests\Domain.Tests.Unit\Domain.Tests.Unit.csproj (in 421 ms).
  3 of 4 projects are up-to-date for restore.
CSC : warning SA0001: XML comment analysis is disabled due to project configuration [D:\Build\a2\212\s\Tests\Domain.Tests.Unit\Domain.Tests.Unit.csproj]
Test run for D:\Build\a2\212\s\Tests\Domain.Tests.Unit\bin\release\net461\ServiziCgn.Inventario.Domain.Tests.Unit.dll(.NETFramework,Version=v4.6.1)
Microsoft (R) Test Execution Command Line Tool Version 16.7.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...

A total of 1 test files matched the specified pattern.

Test Run Successful.
Total tests: 118
     Passed: 118
 Total time: 1,7004 Seconds
##[debug]Exit code 0 received from tool 'C:\Program Files\dotnet\dotnet.exe'
The STDIO streams did not close within 10 seconds of the exit event from process 'C:\Program Files\dotnet\dotnet.exe'. This may indicate a child process inherited the STDIO streams and has not yet exited.
##[debug]The STDIO streams did not close within 10 seconds of the exit event from process 'C:\Program Files\dotnet\dotnet.exe'. This may indicate a child process inherited the STDIO streams and has not yet exited.
##[debug]which 'C:\Program Files\dotnet\dotnet.exe'
##[debug]found: 'C:\Program Files\dotnet\dotnet.exe'

In this case it refers to a project with only classes and business logic inside. no dependency or anything more. But sometimes it changes the project that cause this. One of the way we have to repro the problem is starting two or more pipelines for the same repo.

[donwlewis]

I am experiencing this issue as well when running a bash script. If I use a script block in the azure-pipelines.yml file and write out the bash code there, it works fine, but if I leverage it as a script, it will get the STDIO error.

[fadilafidina]

Happy new year!

We've also been seeing this issue since at least November 2021. It's erroring for us when we run this task as part of our build and test stage.

- task: DotNetCoreCLI@2
      displayName: .NET Test
      inputs:
        command: 'test'

We also use the UseDotNet@2 task and set the version to 5.0.x before the build and test tasks. We also don't have any dependencies such as drivers, and the tests we have are just NUnit tests.

We see this timeout happening around 80% of our pipeline runs.

[onpaj]

Hi, we've also started to hit this issue durin dotnet tool restore task:

/opt/hostedtoolcache/dotnet/dotnet tool restore
Tool 'swashbuckle.aspnetcore.cli' (version '6.2.3') was restored. Available commands: swagger

Restore was successful.
The STDIO streams did not close within 10 seconds of the exit event from process '/opt/hostedtoolcache/dotnet/dotnet'. This may indicate a child process inherited the STDIO streams and has not yet exited.

The build will timeout eventually. Retrying the build helps most of the time.

[abatishchev]

Getting this error from dotnet test for a test project having multiple target frameworks.

[DenisRumyantsev]

Hi @abatishchev, could you please provide a link to your test project if it is public? If not, could you provide steps to create such a test project to reproduce this issue?

[DenisRumyantsev]

Hi @stesee, could you please provide a hash of the commit on which this issue is reproduced in this project?

The issue was 100% reproducable with https://github.com/Codeuctivity/OpenXmlToHtml as long, as I missed closing every spawned chromium processes before the unit tests end.

[stesee]

As far as I can remember it was the change in the dependency https://github.com/Codeuctivity/OpenXmlToHtml/commit/9569b6fdc4d5b0dc25562673509ca1d70416023c#diff-5d0f6f7eb881422177fbe495c1b81ac39b4a349ab25c4299dcbe7ec13aa4cfb0L13 that fixed the issue.

There was some disposing missing in the code of PuppeteerSharp.Renderer 1.1.14 which got fixed here https://github.com/Codeuctivity/PuppeteerSharp.Renderer/compare/1.1.23...1.1.32#diff-8fdf9d8aa24b945d9607963cdaa80d28ec187e794de3bbdbd1043d8b1518786bR83

The azure build pipeline history seems to be ommited after some time, but github history still shows a log from https://github.com/Codeuctivity/OpenXmlToHtml/commit/c9319101ffe6b29520c33a004e19f7bcbd158cc7 with a timeout at azure build pipeline after 60 minutes... try that one to reproduce.

[mateusz-dobrowolny]

I have the same issue. Using Appium driver for Android app. Appium server is using chromedriver (because App is hybrid). I am looking into way to close chromedriver which I suppose is responsible for this "STDIO streams".

And I am using DotNetCoreCLI@2 task with test command, nothing fancy here. If the test passes - no error. If the test fails - job continues ...

[ChristoWolf]

Because several commenters mentioned a similar issue with dotnet test, I wanted to report this too, see #17548.

[sicil1ano]

@vineetmimrot please take a look

Did you eventually take a look at this issue?

This error is affecting our builds when we want to install a tool to generate code-coverage reports using dotnet CLI task, after a build task, that is nothing under our control. We already added a 1-minute timeout to the failing task as workaround, but it's really annoying to see in 5 builds, 4 builds failing and then 1 passing because of this.

[ChristoWolf]

I cannot verify this currently, but this might be fixed by this agent bug fix.

[eriktack]

We see this frequently with the DotNetCoreCLI@2 yaml task. It writes "The STDIO streams did not close within 10 seconds of the exit event from process 'C:\Program Files\dotnet\dotnet.exe'. This may indicate a child process inherited the STDIO streams and has not yet exited." to the log and then does nothing until the job times out (after 60 minutes).

After cancelling/timeout of the job it can be run again without changing any parameters and then will succeed.

Note: The dotnet command we run is "pack".

[apzeiss]

Hi, Any updates on this one, we are also having this problem. Thanks.

[WebdeveloperIsaac]

Hi Team, Even I am Facing Similar Issue, The STDIO streams did not close within 10 seconds of the exit event from process '/usr/bin/bash'. This may indicate a child process inherited the STDIO streams and has not yet exited. In my Use Case I am Running a python Script from my azure pipeline which Internally Calls A python Script to Return Some Value which takes some 5 mins but during this Call, I am Facing this I Have Already Tried adding this timeoutInMinutes: 30 as well So Do we Have Any Resolution on this or any Workaround also is fine. Please Drop A suggestion Thank you.

[lr90]

Hitting the same issue with an AzureCLI@2 bash task. Running a background process that I can terminate but even with long waits before and after killing the process still getting the The STDIO streams did not close within 10 seconds of the exit event from process '/usr/bin/bash'. This may indicate a child process inherited the STDIO streams and has not yet exited. and a hung (at 100%) ADO task :(

Possible fix here https://github.com/microsoft/azure-pipelines-agent/pull/4074 but the env var is not settable on Azure hosted agents