Azure-pipelines-tasks: VsTest 2.3.17 - Test Impact Analysis Failing

[psyvision]

Environment

TFS On-Premise 2018 RTM (16.122.27102.1)

Private Agent (v2.122.1) on Windows Server 2012 R2

VsTest 2.3.17

Issue Description

We have a vNext build that builds a C# project and then runs unit tests using the VsTest task. We are wanting to use Test Impact Analysis (TIA) but are having a couple of problems.

Firstly - The build that normally takes 15 minutes takes 115 minutes. I can expect it to take longer, but is this realistic for ~800 unit tests?

Secondly and more importantly, after running the tests and gathering the testimpact.xml files it seems to crash when using TestSelector.exe.

Error logs

6_Test Assemblies.txt
6_TestSelector.log
6_eaeda910-f606-11e7-af9a-63fe0f449198.txt

I've attached a snippet of the log below:

2018-01-10T14:49:28.0261411Z ##[debug]C:\TfsAgents\AgentA\_work\_tasks\VSTest_ef087383-ee5e-42c7-9a53-ab56c98420f9\2.3.17\TestSelector\TestSelector.exe arg: UpdateTestResults
2018-01-10T14:49:28.0261411Z ##[debug]Build.BuildId=38430
2018-01-10T14:49:28.0261411Z ##[debug]System.TeamFoundationCollectionUri=http://tfs/DefaultCollection/
2018-01-10T14:49:28.0261411Z ##[debug]System.TeamProject=STANMIS
2018-01-10T14:49:28.0261411Z ##[debug]SystemVssConnection auth param AccessToken = ********
2018-01-10T14:49:28.0261411Z ##[debug]AGENT.VERSION=2.122.1
2018-01-10T14:49:28.0261411Z ##[debug]VSTS_HTTP_RETRY=undefined
2018-01-10T14:49:28.0261411Z ##[debug]VSTS_HTTP_TIMEOUT=undefined
2018-01-10T14:49:28.0261411Z ##[debug]System.Debug=true
2018-01-10T14:49:28.0261411Z ##[debug]exec tool: C:\TfsAgents\AgentA\_work\_tasks\VSTest_ef087383-ee5e-42c7-9a53-ab56c98420f9\2.3.17\TestSelector\TestSelector.exe
2018-01-10T14:49:28.0261411Z ##[debug]arguments:
2018-01-10T14:49:28.0261411Z ##[debug]   UpdateTestResults
2018-01-10T14:49:28.0261411Z [command]C:\TfsAgents\AgentA\_work\_tasks\VSTest_ef087383-ee5e-42c7-9a53-ab56c98420f9\2.3.17\TestSelector\TestSelector.exe UpdateTestResults
2018-01-10T14:49:29.7448898Z 
2018-01-10T14:49:29.7448898Z 
2018-01-10T14:49:29.7448898Z Exception : TestManagement.TestResults.UsePublishTestResultsLibraryInVSTestTask
2018-01-10T14:49:29.7448898Z ***************************** Section 'Update test results' Starting *****************************
2018-01-10T14:49:30.8542669Z ##[debug]Processed: ##vso[telemetry.publish area=TestExecution;feature=TestSelector]{"Command":"UpdateTestResults","definitionrunid":38430,"context":"CI","GetTestCaseResults:PerfCounter":551.19490000000008,"ExceptionType":"System.AggregateException, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089","ExceptionMessage":"One or more errors occurred.","ExceptionStack":"   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)\r\n   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)\r\n   at System.Threading.Tasks.Task`1.get_Result()\r\n   at Microsoft.TestFoundation.TestImpact.TestSelector.CommandUpdateTestResults.GetFeatureFlagValue() in E:\\v2.0\\A8\\_work\\21\\s\\Ta\\Tasks\\TestImpact\\TestSelector\\Commands\\Command\\CommandUpdateTestResults.cs:line 206\r\n   at Microsoft.TestFoundation.TestImpact.TestSelector.CommandUpdateTestResults.Run() in E:\\v2.0\\A8\\_work\\21\\s\\Ta\\Tasks\\TestImpact\\TestSelector\\Commands\\Command\\CommandUpdateTestResults.cs:line 139\r\n   at Microsoft.TestFoundation.TestImpact.TestSelector.Program.RunCommand(String commandName, String[] args) in E:\\v2.0\\A8\\_work\\21\\s\\Ta\\Tasks\\TestImpact\\TestSelector\\Program.cs:line 44","InnerExceptionType":"Microsoft.VisualStudio.Services.Common.VssServiceException, Microsoft.VisualStudio.Services.Common, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a","InnerExceptionMessage":"TestManagement.TestResults.UsePublishTestResultsLibraryInVSTestTask","InnerExceptionStack":"   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<HandleResponseAsync>d__51.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 893\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__49.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 836\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__46`1.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 727\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__27`1.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 0","VsTest_TaskInstanceIdentifier":"eae1c233-f606-11e7-af9a-63fe0f449198"}
2018-01-10T14:49:30.8542669Z ***************************** Section 'Update test results' Ended ********************************
2018-01-10T14:49:30.8542669Z 
2018-01-10T14:49:30.8542669Z ##[debug]Processed: ##vso[task.logissue type=warning;SubTaskName=UploadTestResults;SubTaskDuration=3359.1329070003703]
2018-01-10T14:49:30.8542669Z ##[debug]Total time taken to upload test results: 3359.1329070003703 milliseconds.
2018-01-10T14:49:30.8542669Z ##[error]
Exception : TestManagement.TestResults.UsePublishTestResultsLibraryInVSTestTask

2018-01-10T14:49:30.8542669Z ##[debug]Processed: ##vso[task.issue type=error;]%0AException : TestManagement.TestResults.UsePublishTestResultsLibraryInVSTestTask%0D%0A

Exception specific information:

ExceptionType: 
System.AggregateException, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089

ExceptionMessage:
One or more errors occurred.

ExceptionStack:
at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)\r\n  
 at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)\r\n  
 at System.Threading.Tasks.Task`1.get_Result()\r\n   
at Microsoft.TestFoundation.TestImpact.TestSelector.CommandUpdateTestResults.GetFeatureFlagValue() in E:\\v2.0\\A8\\_work\\21\\s\\Ta\\Tasks\\TestImpact\\TestSelector\\Commands\\Command\\CommandUpdateTestResults.cs:line 206\r\n   
at Microsoft.TestFoundation.TestImpact.TestSelector.CommandUpdateTestResults.Run() in E:\\v2.0\\A8\\_work\\21\\s\\Ta\\Tasks\\TestImpact\\TestSelector\\Commands\\Command\\CommandUpdateTestResults.cs:line 139\r\n   
at Microsoft.TestFoundation.TestImpact.TestSelector.Program.RunCommand(String commandName, String[] args) in E:\\v2.0\\A8\\_work\\21\\s\\Ta\\Tasks\\TestImpact\\TestSelector\\Program.cs:line 44",

"InnerExceptionType":"Microsoft.VisualStudio.Services.Common.VssServiceException, Microsoft.VisualStudio.Services.Common, Version=15.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a",

"InnerExceptionMessage":"TestManagement.TestResults.UsePublishTestResultsLibraryInVSTestTask",

"InnerExceptionStack":"   
at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<HandleResponseAsync>d__51.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 893\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n   
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   
at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__49.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 836\r\n--- End of stack trace from previous location where exception was thrown ---\r\n   
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n   
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   
at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__46`1.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 727\r\n
--- End of stack trace from previous location where exception was thrown ---\r\n   
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)\r\n   
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)\r\n   at Microsoft.VisualStudio.Services.WebApi.VssHttpClientBase.<SendAsync>d__27`1.MoveNext() in E:\\v2.0\\A8\\_work\\21\\s\\Vssf\\Client\\WebApi\\VssHttpClientBase.cs:line 0

[acesiddhu]

@psyvision Sorry for late reply here. can you get fiddler trace from build machine when this happens

[acesiddhu]

I just noticed that your tfs version is TFS 2018 RTM and your task version is 2.3.17. Did you upload the task manually? If yes this is not supported as the task has some dependencies on server side which it is not able to find. Can you confirm

[psyvision]

Hi @acesiddhu - Thank you for getting back to me. The task was an old version - I then upgraded TFS from RC to RTM and the task didn't update, therefore I did so manually.

Is it possible to un-install and TFS will replace it with the default? Or do I need to upgrade to newer?

Unfortunately due to this being a restricted development network (due to nature of work) I can't use Fiddler on the build machine as we can't change proxy settings.

Edit: In addition, if it's not supported, is this a VSTS only thing?

[acesiddhu]

@psyvision the update of in box tasks happens based on tfs upgrades and ideally there shouldn't be updated manually. what you see in master is what is going to be deployed on vsts or may be in upcoming TFS release trains. all releases/* branches is what goes into vsts production or tfs update.

@bryanmacfarlane can suggest a way to revert to inbox version of task.

The latest task which you uploaded has few feature that talk to latest vsts service feature. you should be able to use TIA in tfs 2018 out of the box.

[psyvision]

@acesiddhu thank you. I'll wait to hear what @bryanmacfarlane says, I hadn't noticed the releases/* branches, not sure if that is clear enough in the documentation or if I missed it.

It looks as though I should pull from https://github.com/Microsoft/vsts-tasks/tree/releases/tfs2018rtw that contains task version 2.1.9

[bryanmacfarlane]

If you upload a task manually, the system returns the in the box versions unioned with the custom one you uploaded. If you use tfx to then delete that task, we delete the overlay. You cannot delete the in the box versions we upload on upgrade so that works fine.

Regarding support, it's not that it's not supported. It's more of you're kind of on your own to build correctly and upload. We don't release an official "update pack" even though we've considered it.

Also, always make sure it's a release branch since master is unshipped code.

hth

[psyvision]

Thanks Bryan! I'll delete the task and run a build and then report back.

[psyvision]

Morning update - we ran two jobs through last night.

The first took longer than the 2 hour allowed time when running which caused it to be terminated, it was the unit test running that took the time.

The second job took just under 2 hours and succeeded:

2018-02-06T18:48:16.9628937Z Results File: C:\TfsAgents\AgentF\_work\141\s\TestResults\isuser_VM-BUILD01 2018-02-06 16_57_29.trx
2018-02-06T18:48:16.9628937Z 
2018-02-06T18:48:16.9628937Z Total tests: 820. Passed: 820. Failed: 0. Skipped: 0.
2018-02-06T18:48:16.9628937Z Test Run Successful.
2018-02-06T18:48:16.9628937Z Test execution time: 1.8482 Hours
2018-02-06T18:48:18.8691517Z [command]C:\TfsAgents\AgentF\_work\_tasks\VSTest_ef087383-ee5e-42c7-9a53-ab56c98420f9\2.1.9\TestSelector\TestSelector.exe UpdateTestResults
2018-02-06T18:48:19.0722928Z 
2018-02-06T18:48:19.0722928Z ***************************** Section 'Update test results' Starting *****************************
2018-02-06T18:48:19.5566659Z Attachment location: C:\TfsAgents\AgentF\_work\141\s\TestResults\isuser_VM-BUILD01 2018-02-06 16_57_29\In
2018-02-06T18:48:19.6035374Z Setting run start and finish times.
2018-02-06T18:48:19.6347850Z Total test results: 820
2018-02-06T18:48:19.6660338Z Test results remaining to be updated: 820
2018-02-06T18:48:20.3541139Z Test impact meta data remaining: 820
2018-02-06T18:48:22.5728846Z Test impact meta data remaining: 320
2018-02-06T18:48:23.6359674Z Total not impacted test: 0
2018-02-06T18:48:23.9953425Z ***************************** Section 'Update test results' Ended ********************************

I'll run a build this morning and see if it runs quicker, I presume it should now only run a subset of tests.

[acesiddhu]

Thanks for the update @psyvision . also in the mean time can you tell what kind of test these are. are they ui test/integration/functional test. does it test a web server etc?

[psyvision]

A small change to the code with a CI build has now only taken 2 minutes.

2018-02-07T08:23:24.5770978Z Total tests: 1. Passed: 1. Failed: 0. Skipped: 0.
2018-02-07T08:23:24.5770978Z Test Run Successful.
2018-02-07T08:23:24.5770978Z Test execution time: 8.8634 Seconds
2018-02-07T08:23:24.6708446Z [command]C:\TfsAgents\AgentA\_work\_tasks\VSTest_ef087383-ee5e-42c7-9a53-ab56c98420f9\2.1.9\TestSelector\TestSelector.exe UpdateTestResults
2018-02-07T08:23:24.8583503Z 
2018-02-07T08:23:24.8583503Z ***************************** Section 'Update test results' Starting *****************************
2018-02-07T08:23:25.2333494Z Attachment location: C:\TfsAgents\AgentA\_work\166\s\TestResults\isuser_VM-BUILD01 2018-02-07 08_23_24\In
2018-02-07T08:23:25.2489762Z Setting run start and finish times.
2018-02-07T08:23:25.2646010Z Total test results: 1
2018-02-07T08:23:25.2958533Z Test results remaining to be updated: 1
2018-02-07T08:23:25.6396104Z Test impact meta data remaining: 1
2018-02-07T08:23:25.6708556Z Total not impacted test: 819
2018-02-07T08:23:26.1864825Z ***************************** Section 'Update test results' Ended ********************************

Cool!

Thanks for the help - I'll close this now :)

[psyvision]

@acesiddhu missed your comment - these are purely middle-tier functional tests. No UI. In some of these, the slower ones, we are mocking EF and ADO (with NSubstitute). No additional web/database servers are used, it's all pretty self contained.

[psyvision]

After running some more builds, it seems that it's okay as long as you don't touch code that impacts certain tests. I.e., with TIA turned on, some test runs are taking much longer, the initial build taking ~2 hours doesn't appear to be because it was the first run.

I've put TIA on a separate project and the builds have all taken the same time as without TIA or much shorter times to run.

[acesiddhu]

can you share logs

[psyvision]

A subset of the logs is just this:

2018-02-06T17:09:36.5510165Z Passed   GetTableName_on_class_with_attribute_returns_correct_name
2018-02-06T17:10:55.3485918Z Passed   GetTableName_on_class_without_attribute_returns_correct_name
2018-02-06T17:12:15.8180533Z Passed   GetMappingFromDatabase_returns_valid_data
2018-02-06T17:13:36.3187719Z Passed   CreateDataTable_converts_POCO_to_datatable
2018-02-06T17:14:58.5694951Z Passed   ImportTable_does_nothing_with_null_data
2018-02-06T17:16:18.6014564Z Passed   ImportTable_does_nothing_with_empty_data
2018-02-06T17:17:39.3365499Z Passed   ImportTable_with_NoAction_calls_ExecuteNonQuery_correctly
2018-02-06T17:18:59.2747679Z Passed   ImportTable_with_PreserveData_calls_ExecuteNonQuery_correctly
2018-02-06T17:20:19.7285944Z Passed   ImportTable_with_DataPreservedKeep_calls_ExecuteNonQuery_correctly
2018-02-06T17:21:39.9324307Z Passed   ImportTable_with_DataPreservedWipe_calls_ExecuteNonQuery_correctly
2018-02-06T17:23:01.3394009Z Passed   Extranet_Export_Lookups_should_export_to_the_container
2018-02-06T17:24:22.1838711Z Passed   Extranet_Export_User_accounts_should_export_to_the_container
2018-02-06T17:24:24.0120106Z Passed   Should_Set_Date_Version_And_User_Then_Commit_for_extranet
2018-02-06T17:24:24.0276386Z Passed   Should_Set_Date_Version_And_User_Then_Commit_for_rli

Do you want me to set the system.debug build variable to give further details?

[acesiddhu]

can we hop on a quick call if this is a good time. will make things faster. mail me on Siddhartha.pandeyATmicrosoft DOT COM

[acesiddhu]

We chatted on the issue and looks like the profiler we have is adding overhead for one of the build definition. I have suggested a way to @psyvision which he is going to try out. The time came down to 2.1 minutes!. below is the chnage i asked

You need to do follow changes

1. Enable Trigger build as scheduled build for your definition and keep it on week end or your non office hours
2. Change vstest task input “Number of builds after which all tests should be run to $(FullIterationInterval)

Add FullIterationInterval as one of the build variables and make the value as 50 or value which you want to have. Add one more variable call it tia.disabletiadatacollector and set it to true

1. Add a powershell task just above visual studio test task and have this content in that
   Write-Host "##vso[task.setvariable variable= FullIterationInterval;]1"
   Write-Host "##vso[task.setvariable variable= tia.disabletiadatacollector;]false"
2. In above powershell task choose custom condition

So what will happen is by default TIA profiler wont be on. It will be on only because of the powershell script. And the powershell script is supposed to be run only for scheduled build.

[acesiddhu]

@psyvision I am closing the issue. If you still face any issues please create a new issue on GitHub and we can take it from there. Thanks