How to Add Better Logging to Debug when a Previously Working VSTS Build Times out When Executing Unit Tests step

Question

I have a VSTS build with Unit tests that was working previously in VSTS build. This week, it stopped working due to timing out.

The failure occurs due to timing out after 60 minutes. Here's what we know:

• The test library only contains 1 test. We run the test by pointing to the test assembly in the Unit Tests configuration of VSTS.
• The test still works locally (runs in <1 second).
• Even if I remove the actual test and replace it with a single trivial test that just checks Assert.IsTrue(true), the test still time out. So we conclude that it's something about the test configuration, rather than the test itself, causing the issue.
• I tried adding additional Debug logging to the test, but it appears that the test execution never actually starts.
• No trx log file appears to be generated. It doesn't appear to actually attempt to run the test at all.
• We have tried this in a VSTS hosted VM and on our own VM with the same result.
• We tried adding a new test step to the build and pointing that the the test DLL with no other modifications to the defaults, and it still gets stuck.
• We pointed the original test step to a different test DLL, and the tests pass! So there is something related to this particular lib that is different (but again, even if I remove all the tests it still gets stuck).

Does anyone have alternate suggestions for other things to try to narrow down what could be causing this (e.g., trace logging in VSTS)? The log file below shows some of the specifics of our unit test configuration, but please let me know if other details would be helpful.

The failure log looks like this:

> ============================================================================== 2018-07-18T20:14:25.1963123Z Run the tests locally using
> vstest.console.exe 2018-07-18T20:14:25.1964566Z
> ======================================================== 2018-07-18T20:14:25.1965645Z Test selector : Test assemblies
> 2018-07-18T20:14:25.1966925Z Test assemblies : **\<PathToTestLib>.dll
> 2018-07-18T20:14:25.1968187Z Test filter criteria : null
> 2018-07-18T20:14:25.1968810Z Search folder : C:\vsts-agent\_work\4\s
> 2018-07-18T20:14:25.1969311Z Run settings file :
> C:\vsts-agent\_work\4\s 2018-07-18T20:14:25.1970327Z Run in parallel :
> false 2018-07-18T20:14:25.1970792Z Run in isolation : false
> 2018-07-18T20:14:25.1972913Z Path to custom adapters : null
> 2018-07-18T20:14:25.1973153Z Other console options : null
> 2018-07-18T20:14:25.1973381Z Code coverage enabled : false
> 2018-07-18T20:14:25.1974004Z Rerun failed tests: false
> 2018-07-18T20:14:25.1974423Z VisualStudio version selected for test
> execution : latest 2018-07-18T20:14:25.3811086Z
> ======================================================== 2018-07-18T20:14:30.6014691Z [command]"C:\Program Files
> (x86)\Microsoft Visual
> Studio\2017\Enterprise\Common7\IDE\CommonExtensions\Microsoft\TestWindow\vstest.console.exe"
> @C:\vsts-agent\_work\_temp\2aa40f41-8ac7-11e8-b190-a1cdff2b8b30.txt
> 2018-07-18T20:14:30.8198002Z Microsoft (R) Test Execution Command Line
> Tool Version 15.7.2 2018-07-18T20:14:30.8206458Z Copyright (c)
> Microsoft Corporation.  All rights reserved.
> 2018-07-18T20:14:30.8206862Z  2018-07-18T20:14:30.8227447Z
> vstest.console.exe  2018-07-18T20:14:30.8228082Z
> "C:\vsts-agent\_work\4\s\partners\exooutlook\OutlookAnalysisSolution.Test\bin\Debug\OutlookAnalysisSolution.Test.dll"
> 2018-07-18T20:14:30.8228647Z /logger:"trx"
> 2018-07-18T20:14:31.0672644Z Starting test execution, please wait...
> 2018-07-18T21:14:05.8979923Z ##[error]The operation was canceled.
> 2018-07-18T21:14:05.9027909Z ##[section]Finishing: Unit Tests

Answer 1

We found the source of the hang. It was in a test class method marked with the "AssemblyInitialize" attribute.

    [TestClass]
public class TestClassInitializer
{
    [AssemblyInitialize]
    public static void AssemblyInit(TestContext context)
    {
        LocalResourceDeployment.CopyResources();
    }
}

There was a bug in CopyResources() that did not manifest locally but caused a powershell window in VSTS to wait for console input.

We have improved the trace logging in this initialization method so that if it fails again in the future we'll at least have a pointer to where the test got stuck. E.g.:

Trace.WriteLine("Starting test assembly initializtion.");