VsTest hangs (v.15.6.0) or fails immediately (v.16.1.0) in Azure DevOps Release Pipeline

[scale-tone]

Description

"Visual Studio Test" task does not work in Azure DevOps Release Pipelines. This makes it impossible to run VsTest-based integration tests after deployments. The behavior differs from version to version. Latest VsTest fails immediately (and does not respect the VSTEST_CONNECTION_TIMEOUT environment variable). Previous versions hang forever.

Steps to reproduce

• In Azure DevOps get yourself a build artifact containing some DLL with VsTest tests. I have just one test method, and it does nothing.
• Configure a Release Pipeline for that artifact.
• Add the "Visual Studio Test" task to that Release Pipeline.
• Run the Release Pipeline.

Expected behavior

The Release Pipeline succeeds, along with it's VsTest task.

Actual behavior

Latest VsTest (v.16.1.0) fails immediately with the following error:

2019-05-22T18:41:13.0640989Z Starting test execution, please wait...
2019-05-22T18:41:19.8690080Z vstest.console process failed to connect to testhost process after 600 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout.

Note the timing. Also note that VSTEST_CONNECTION_TIMEOUT environment variable was set to "600", and surprisingly enough the task prints the value of it, but does not respect it.

VsTest v.15.6.0 hangs:

2019-05-22T16:50:09.3370582Z Starting test execution, please wait...
2019-05-22T17:48:32.1829446Z ##[error]The operation was canceled.

Diagnostic logs

v.16.1.0:

2019-05-22T18:41:03.5716101Z ##[section]Starting: VsTest - testAssemblies
2019-05-22T18:41:03.5821061Z ==============================================================================
2019-05-22T18:41:03.5821173Z Task         : Visual Studio Test
2019-05-22T18:41:03.5821298Z Description  : Run unit and functional tests (Selenium, Appium, Coded UI test, etc.) using the Visual Studio Test (VsTest) runner. Test frameworks that have a Visual Studio test adapter such as MsTest, xUnit, NUnit, Chutzpah (for JavaScript tests using QUnit, Mocha and Jasmine), etc. can be run. Tests can be distributed on multiple agents using this task (version 2).
2019-05-22T18:41:03.5821461Z Version      : 2.151.6
2019-05-22T18:41:03.5821527Z Author       : Microsoft Corporation
2019-05-22T18:41:03.5821598Z Help         : [More information](https://go.microsoft.com/fwlink/?LinkId=835764)
2019-05-22T18:41:03.5821693Z ==============================================================================
2019-05-22T18:41:04.7387149Z SystemVssConnection exists true
2019-05-22T18:41:04.8100700Z SystemVssConnection exists true
2019-05-22T18:41:04.8686896Z SystemVssConnection exists true
2019-05-22T18:41:04.9210426Z Running tests using vstest.console.exe runner.
2019-05-22T18:41:04.9210942Z ======================================================
2019-05-22T18:41:04.9276357Z Test selector : Test assemblies
2019-05-22T18:41:04.9278202Z Test filter criteria : null
2019-05-22T18:41:04.9279211Z Search folder : d:\a\r1\a
2019-05-22T18:41:05.0523388Z Run in parallel : false
2019-05-22T18:41:05.0523770Z Run in isolation : false
2019-05-22T18:41:05.0524101Z Path to custom adapters : null
2019-05-22T18:41:05.0524996Z Other console options : null
2019-05-22T18:41:05.0525725Z Code coverage enabled : false
2019-05-22T18:41:05.0526223Z Diagnostics enabled : true
2019-05-22T18:41:05.0526929Z SystemVssConnection exists true
2019-05-22T18:41:05.0529202Z Run the tests locally using vstest.console.exe
2019-05-22T18:41:05.0529393Z ========================================================
2019-05-22T18:41:05.0529750Z Test selector : Test assemblies
2019-05-22T18:41:05.0530088Z Test assemblies : **\*IntegrationTest.dll,!**\*TestAdapter.dll,!**\obj\**
2019-05-22T18:41:05.0530407Z Test filter criteria : null
2019-05-22T18:41:05.0530803Z Search folder : d:\a\r1\a
2019-05-22T18:41:05.0531099Z Run settings file : d:\a\r1\a
2019-05-22T18:41:05.0531567Z Run in parallel : false
2019-05-22T18:41:05.0531855Z Run in isolation : false
2019-05-22T18:41:05.0558259Z Path to custom adapters : null
2019-05-22T18:41:05.0558637Z Other console options : null
2019-05-22T18:41:05.0598278Z Code coverage enabled : false
2019-05-22T18:41:05.0598401Z Diagnostics enabled : false
2019-05-22T18:41:05.0598692Z Rerun failed tests: false
2019-05-22T18:41:05.6180819Z VisualStudio version selected for test execution : toolsInstaller
2019-05-22T18:41:06.8931379Z ========================================================
2019-05-22T18:41:06.9227547Z ======================================================
2019-05-22T18:41:07.0095170Z [command]C:\hostedtoolcache\windows\VsTest\16.1.0\x64\tools\net451\Common7\IDE\Extensions\TestPlatform\vstest.console.exe @d:\a\_temp\28ed6651-7cc1-11e9-a6cb-dfccd7ec5ba8.txt
2019-05-22T18:41:07.4670156Z Microsoft (R) Test Execution Command Line Tool Version 16.1.0
2019-05-22T18:41:07.4670889Z Copyright (c) Microsoft Corporation.  All rights reserved.
2019-05-22T18:41:07.4671261Z 
2019-05-22T18:41:07.7357518Z vstest.console.exe 
2019-05-22T18:41:07.7358115Z "d:\a\r1\a\WhatIfDemo-Functions\drop\unzipped\bin\WhatIfDemo-Functions.IntegrationTest.dll"
2019-05-22T18:41:07.7358346Z /logger:"trx"
2019-05-22T18:41:07.7358535Z /TestAdapterPath:"d:\a\r1\a"
2019-05-22T18:41:13.0640989Z Starting test execution, please wait...
2019-05-22T18:41:19.8690080Z vstest.console process failed to connect to testhost process after 600 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout.
2019-05-22T18:41:22.3432980Z Results File: d:\a\r1\a\TestResults\VssAdministrator_fv-az644_2019-05-22_18_41_21.trx
2019-05-22T18:41:22.3454889Z 
2019-05-22T18:41:22.3459478Z Test Run Aborted.
2019-05-22T18:41:22.5316259Z ##[warning]Vstest failed with error. Check logs for failures. There might be failed tests.
2019-05-22T18:41:22.5418434Z ##[error]Error: The process 'C:\hostedtoolcache\windows\VsTest\16.1.0\x64\tools\net451\Common7\IDE\Extensions\TestPlatform\vstest.console.exe' failed with exit code 1
2019-05-22T18:41:23.0611262Z ##[warning]Invalid results file. Make sure the result format of the file 'd:\a\r1\a\TestResults\VssAdministrator_fv-az644_2019-05-22_18_41_21.trx' matches 'VSTest' test results format.
2019-05-22T18:41:23.0689893Z ##[error]VsTest task failed.
2019-05-22T18:41:23.0859417Z ##[section]Async Command Start: Publish test results
2019-05-22T18:41:23.0859548Z ##[section]Async Command End: Publish test results
2019-05-22T18:41:23.0860144Z ##[section]Finishing: VsTest - testAssemblies

v.15.6.0

2019-05-22T16:49:53.3586970Z ##[section]Starting: VsTest - testAssemblies
2019-05-22T16:49:53.3692075Z ==============================================================================
2019-05-22T16:49:53.3692194Z Task         : Visual Studio Test
2019-05-22T16:49:53.3692354Z Description  : Run unit and functional tests (Selenium, Appium, Coded UI test, etc.) using the Visual Studio Test (VsTest) runner. Test frameworks that have a Visual Studio test adapter such as MsTest, xUnit, NUnit, Chutzpah (for JavaScript tests using QUnit, Mocha and Jasmine), etc. can be run. Tests can be distributed on multiple agents using this task (version 2).
2019-05-22T16:49:53.3692515Z Version      : 2.151.6
2019-05-22T16:49:53.3692575Z Author       : Microsoft Corporation
2019-05-22T16:49:53.3692694Z Help         : [More information](https://go.microsoft.com/fwlink/?LinkId=835764)
2019-05-22T16:49:53.3692787Z ==============================================================================
2019-05-22T16:49:54.4110518Z SystemVssConnection exists true
2019-05-22T16:49:54.4841209Z SystemVssConnection exists true
2019-05-22T16:49:54.5419637Z SystemVssConnection exists true
2019-05-22T16:49:54.5965780Z Running tests using vstest.console.exe runner.
2019-05-22T16:49:54.5965903Z ======================================================
2019-05-22T16:49:54.5966088Z Test selector : Test assemblies
2019-05-22T16:49:54.5966211Z Test filter criteria : null
2019-05-22T16:49:54.5966324Z Search folder : d:\a\r1\a
2019-05-22T16:49:54.7202883Z Run in parallel : false
2019-05-22T16:49:54.7203058Z Run in isolation : false
2019-05-22T16:49:54.7203168Z Path to custom adapters : null
2019-05-22T16:49:54.7203431Z Other console options : null
2019-05-22T16:49:54.7203533Z Code coverage enabled : false
2019-05-22T16:49:54.7205103Z Diagnostics enabled : true
2019-05-22T16:49:54.7205334Z SystemVssConnection exists true
2019-05-22T16:49:54.7206060Z Run the tests locally using vstest.console.exe
2019-05-22T16:49:54.7206139Z ========================================================
2019-05-22T16:49:54.7206281Z Test selector : Test assemblies
2019-05-22T16:49:54.7206418Z Test assemblies : **\*IntegrationTest.dll,!**\*TestAdapter.dll,!**\obj\**
2019-05-22T16:49:54.7206538Z Test filter criteria : null
2019-05-22T16:49:54.7206647Z Search folder : d:\a\r1\a
2019-05-22T16:49:54.7206742Z Run settings file : d:\a\r1\a
2019-05-22T16:49:54.7206883Z Run in parallel : false
2019-05-22T16:49:54.7206989Z Run in isolation : false
2019-05-22T16:49:54.7207793Z Path to custom adapters : null
2019-05-22T16:49:54.7207905Z Other console options : null
2019-05-22T16:49:54.7242672Z Code coverage enabled : false
2019-05-22T16:49:54.7242779Z Diagnostics enabled : false
2019-05-22T16:49:54.7243027Z Rerun failed tests: false
2019-05-22T16:49:54.9921523Z VisualStudio version selected for test execution : toolsInstaller
2019-05-22T16:50:01.8758005Z ========================================================
2019-05-22T16:50:01.9083682Z ======================================================
2019-05-22T16:50:01.9920866Z [command]C:\hostedtoolcache\windows\VsTest\15.6.0\x64\tools\net451\Common7\IDE\Extensions\TestPlatform\vstest.console.exe @d:\a\_temp\a4459531-7cb1-11e9-b272-2199ba4c9b49.txt
2019-05-22T16:50:02.4601426Z Microsoft (R) Test Execution Command Line Tool Version 15.6.0
2019-05-22T16:50:02.4601788Z Copyright (c) Microsoft Corporation.  All rights reserved.
2019-05-22T16:50:02.4601842Z 
2019-05-22T16:50:02.9257930Z vstest.console.exe 
2019-05-22T16:50:02.9259166Z "d:\a\r1\a\WhatIfDemo-Functions\drop\unzipped\bin\WhatIfDemo-Functions.IntegrationTest.dll"
2019-05-22T16:50:02.9259513Z /logger:"trx"
2019-05-22T16:50:02.9259807Z /TestAdapterPath:"d:\a\r1\a"
2019-05-22T16:50:09.3370582Z Starting test execution, please wait...
2019-05-22T17:48:32.1829446Z ##[error]The operation was canceled.
2019-05-22T17:48:32.1834516Z ##[section]Finishing: VsTest - testAssemblies

Environment

<TargetFramework>netcoreapp2.1</TargetFramework>

<PackageReference Include="Microsoft.NET.Test.Sdk" Version="16.1.0" />
<PackageReference Include="MSTest.TestAdapter" Version="1.4.0" />
<PackageReference Include="MSTest.TestFramework" Version="1.4.0" />

[scale-tone]

Any news?

[ShreyasRmsft]

Hi @scale-tone, let me look into this.

[ShreyasRmsft]

Quick thing for you to try, can you set it to 600000 and then give it a shot. I'm suspecting a "unit of time" issue

[scale-tone]

Nice try, but no luck:

2019-06-03T13:34:45.7200327Z Starting test execution, please wait...
2019-06-03T13:34:48.7649332Z vstest.console process failed to connect to testhost process after 600000 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout.
2019-06-03T13:34:50.2346886Z Results File: D:\a\r1\a\TestResults\VssAdministrator_fv-az297_2019-06-03_13_34_50.trx
2019-06-03T13:34:50.2436564Z 
2019-06-03T13:34:50.2442769Z Test Run Aborted.

Besides, it wouldn't explain the difference in behavior between versions.

[ShreyasRmsft]

@scale-tone we tried it out on the hosted agent, setting it to 600, then 10. It worked fine (version 16.1.0).
https://clttestsu0.visualstudio.com/validationTest/_build/results?buildId=19566&view=logs

Leading me to believe it's something specific to the agent machine you are running it on. Set system.debug = true in your release definition and please provide the full zip logs that you get.

Also what agent are you using? private or hosted?

Additionally please set up a public project with sample/dummy code as i have done above where you have the repro. This will make it easier for me to investigate

[scale-tone]

@ShreyasRmsft , what you pointed to is a build pipeline.

I explicitly underscored in the bug that the problem occurs inside a Release pipeline (please, pay attention). Build pipelines work fine.

The build agent is the very default one provided by Azure DevOps, no changes. I just created an empty release pipeline and added a VsTest task to it, no any other specifics.

Logs under system.debug=true are here:
https://microsoft-my.sharepoint-df.com/:u:/p/kolepes/ERe8RDIrp0VAi3Ak_v6LgUMBL_Zrf2yYTDRD3iBtCk7ycQ?e=DkTvZn
(not sure they're free from secrets, so sharing them via internal OneDrive).

[ShreyasRmsft]

@scale-tone if you are running dotnet core tests you will need to make sure you run dotnet publish before running the tests in the releases pipeline (or a different machine from where the dlls were built basically. This is because additional dlls are copied to the output directory and these are required to run the tests. On the same machine they are picked up from the packages folder directly.)

Sample release where I did not do dotnet publish. I got this error
https://clttestsu0.visualstudio.com/validationTest/_releaseProgress?releaseId=1&environmentId=1&_a=release-environment-logs

After doing the publish in the build definition here is the run in release
https://clttestsu0.visualstudio.com/validationTest/_releaseProgress?releaseId=2&environmentId=2&_a=release-environment-logs

There is no difference between the build pipeline and the release pipeline as far as the VsTest task is concerned!

[ShreyasRmsft]

@scale-tone after examining the logs that you sent I see a different error than the one you reported

2019-06-05T19:39:12.5895992Z vstest.console.exe 
2019-06-05T19:39:12.5896214Z "d:\a\r1\a\WhatIfDemo-Functions\drop\unzipped\bin\WhatIfDemo-Functions.IntegrationTest.dll"
2019-06-05T19:39:12.5896299Z /logger:"trx"
2019-06-05T19:39:12.5896375Z /TestAdapterPath:"d:\a\r1\a"
2019-06-05T19:39:12.5896481Z /diag:"d:\a\_temp\95c913b0-87c9-11e9-a9d3-6d751601273c.txt"
2019-06-05T19:39:24.6543893Z Starting test execution, please wait...
2019-06-05T19:39:24.7550586Z Logging Vstest Diagnostics in file: d:\a\_temp\95c913b0-87c9-11e9-a9d3-6d751601273c.txt
2019-06-05T19:39:38.5359784Z Testhost process exited with error: A fatal error was encountered. The library 'hostpolicy.dll' required to execute the application was not found in 'd:\a\r1\a\WhatIfDemo-Functions\drop\unzipped\bin\'.
2019-06-05T19:39:38.5360300Z Failed to run as a self-contained app. If this should be a framework-dependent app, add the d:\a\r1\a\WhatIfDemo-Functions\drop\unzipped\bin\testhost.runtimeconfig.json file specifying the appropriate framework.
2019-06-05T19:39:38.5360554Z 
2019-06-05T19:39:41.0150491Z Results File: d:\a\r1\a\TestResults\VssAdministrator_fv-az644_2019-06-05_19_39_40.trx

And here's a run with the same version of vstest.console.exe 16.1.1 where everything went smoothly

https://clttestsu0.visualstudio.com/validationTest/_releaseProgress?_a=release-environment-logs&releaseId=4&environmentId=4

[ShreyasRmsft]

@scale-tone I think the issue is specific to the test project that you have. Is it possible to provide a scaled down repro with a dummy test and dummy code and upload it somewhere on github?

[ShreyasRmsft]

I think the issue is with the target framework of the test project. It would speed up the investigation if you can author a simple test project with a single dummy test (keeping all the target framework etc. similar to your actual test project) and see if it repros there and then provide that to me. I should be able to narrow down the cause. Also make sure you use the latest version 16.1.1

[scale-tone]

I see a different error than the one you reported

Indeed, occasionally it fails with a different error, without me doing or changing anything.
Here are the logs from another occurrence, with system.debug=true and "vstest.console process failed to connect to testhost process after 600000 seconds" error message:
https://microsoft-my.sharepoint-df.com/:u:/p/kolepes/EbbRibWtkEhPgCo4Pbbl4skBk3_XzRQGg9kUH9YzaNj0gA?e=gOIK4T

Sources are here: https://github.com/scale-tone/WhatIfDemo/tree/master/WhatIfDemo-Functions.IntegrationTest. Have no idea what might be the "issue with the target framework of the test project".

The release pipeline is this one: https://dev.azure.com/kolepes/WhatIfDemo/_release?definitionId=1
I explicitly added you (your ms account) to the devops team, so you should be able to access it.

[ShreyasRmsft]

@scale-tone thanks. Let me take it from here. Will get to the RCA and update here.

[ShreyasRmsft]

@scale-tone i am currently setting this up locally to get a repro i can debug through. Was a little busy the last few days. Will get back to you soon. Sorry for the delay.

[ShreyasRmsft]

@scale-tone this has proved to be an interesting issue indeed!

We had a small bug in our code where if the testhost process exited/crashed we were incorrectly showing this

vstest.console process failed to connect to testhost process after 600 seconds. This may occur due to machine slowness, please set environment variable VSTEST_CONNECTION_TIMEOUT to increase timeout.

I am currently in the process of fixing this logging issue.

Further the root cause for this is that the testhost process is crashing and it is crashing because of this

Testhost process exited with error: A fatal error was encountered. The library 'hostpolicy.dll' required to execute the application was not found in 'd:\a\r1\a\WhatIfDemo-Functions\drop\unzipped\bin'.

On further digging the issue is in the dotnet sdk

https://stackoverflow.com/questions/38085430/the-library-hostpolicy-dll-was-not-found

I think publishing your test project using the dotnet publish command will probably solve the issue as a simple workaround instead of using msbuild to make the publish.

[scale-tone]

dotnet publish over the test project during build time was not enough.
An extra step of copying the [testProject].runtimeconfig.json file into the artifacts folder was also needed (that file is produced by dotnet publish).
A combination of these two changes indeed helped.

[ShreyasRmsft]

[testProject].runtimeconfig.json gets generated in the publish folder itself right?

Also I think you can remove the additional arguments from msbuid (/p:WebPublishMethod=FileSystem etc related to publishing your webapp) and use dotnet publish to publish your webapp also. You can find documentation for this on the dotnet cli page.

Also many thanks for reporting this issue and patiently providing all the logs and samples needed for us to get to the bottom of this :)