azure-pipelines-tasks: Test runs intermittently fail with "did not complete yet".

Required Information

Entering this information will route you directly to the right team and expedite traction.

Question, Bug, or Feature?
Bug

Enter Task Name:
VsTest

Environment

DevOps Server 2019.1 / Dev17.M153.3 Agent: Private, v2.153.1 on Windows 10 v1809

Issue Description

Test runs where vstest executes mstest unit tests intermittently fail with error message “Test run NNNN did not complete yet.”

(Edit: removed “on multiple agents” because this error reproduces for a run executing a single test)

Before this, the logs say IsValidServiceResponse: Received None command..Service Workflow is not active. Successful runs log “Received the command : Start”, while failing runs do not.

Error logs

Relevant section of a failing run

2020-01-15T14:44:12.8228735Z Test run with Id 32871 associated
2020-01-15T14:44:12.9581464Z ##[debug]TestHostStart.Run : Waiting to get a start command or stop/cancel command
2020-01-15T14:44:22.6980998Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:44:42.7125011Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:45:22.7503409Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:46:22.7426443Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:47:22.7365086Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:48:22.8552866Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:49:22.8468945Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:50:22.8552019Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:51:22.8904590Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:52:22.8791732Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:53:22.8891899Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:54:22.8998115Z IsValidServiceResponse: Received None command..Service Workflow is not active
2020-01-15T14:54:22.9050145Z TestExecutionHost.ProcessCommand. Stop Command handled
2020-01-15T14:54:22.9051666Z ##[debug]TestHostStart.Run : TestHost stop/cancel invoked
2020-01-15T14:54:22.9051985Z ##[debug]ExecutionStateResolver.SetNextPhase : Current Phase: TestHostStart
2020-01-15T14:54:22.9052242Z ##[debug]ExecutionStateResolver.SetNextPhase : Next Phase: TestHostEnd
2020-01-15T14:54:22.9052434Z ##[debug]TestExecutionHost.Execute: Current Phase TestHostEnd
2020-01-15T14:54:22.9053775Z ##[debug]VstestAdapter.ExecuteAsync : Starting Execution
2020-01-15T14:54:22.9910946Z ##[debug]ProceedAfterAbortedTestCase : False
2020-01-15T14:54:23.2377448Z ##[debug]SliceDetailsStore.NormalizeSettings : No Slice details or run information
2020-01-15T14:54:23.2377777Z ##[debug]VstestAdapter.ExecuteAsync : Returning
2020-01-15T14:54:23.2406652Z ##[debug]TestHostEnd.Run : CancellatationRequested: True : RunCreated : True : RunCompleted : False
2020-01-15T14:54:23.2505280Z ##[debug]TestHostEnd.Run: Run not completed. Waiting for the stop event
2020-01-15T14:54:23.2505582Z ##[debug]TestHostStop.Run : Logging the test run details
2020-01-15T14:54:23.2623773Z Test run '32871' is in 'InProgress' state.
2020-01-15T14:54:23.2705405Z ##[error]Test run 32871 did not complete yet.
2020-01-15T14:54:23.4977768Z ##[debug]Processed: ##vso[task.logissue type=error;]Test run 32871 did not complete yet.
2020-01-15T14:54:23.5004022Z ##[debug]Processed: ##vso[task.complete result=Failed;]Test run 32871 did not complete yet.
2020-01-15T14:54:23.5895491Z ##[debug]Deleted test settings with id : 9422

For comparison, a successful build has “Received the command : Start” and continues to execute tests.

2020-01-15T12:54:09.3060326Z Test run with Id 32829 associated
2020-01-15T12:54:09.4245735Z ##[debug]TestHostStart.Run : Waiting to get a start command or stop/cancel command
2020-01-15T12:54:20.2245116Z Received the command : Start
2020-01-15T12:54:20.2281652Z TestExecutionHost.ProcessCommand. Start Command handled
2020-01-15T12:54:20.2282673Z ##[debug]Notified the command 1 : {"Command":1}
2020-01-15T12:54:20.2283839Z ##[debug]TestHostStart.Run : TestHost start invoked
2020-01-15T12:54:20.2284475Z ##[debug]ExecutionStateResolver.SetNextPhase : Current Phase: TestHostStart

Task logs

Can provide privately if necessary, they are quite large