Increase timeouts for datacollector to connect to Testhost (#1406)

* Increase timeouts for datacollector to connect to Testhost

* Removing asserts on elaspsed time.

* PR comments

* Explain why we are waiting infinitely in testhost.exe to connect to vstest.console

src/Microsoft.TestPlatform.CommunicationUtilities/DataCollectionRequestHandler.cs

@@ -29,7 +29,9 @@ namespace Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.DataCollect
     /// </summary>
     internal class DataCollectionRequestHandler : IDataCollectionRequestHandler, IDisposable
     {
-        private const int DATACOLLECTIONCONNTIMEOUT = 15 * 1000;
+        // On Slower Machines(hosted agents) with Profiling enabled 15secs is not enough for testhost to get started(weird right!!),
+        // hence increasing this timeout
+        private const int DataCollectionCommTimeOut = 60 * 1000;
 
         private static readonly object SyncObject = new object();
 
@@ -198,7 +200,7 @@ public void ProcessRequests()
                                         {
                                             if (
                                                 this.dataCollectionTestCaseEventHandler.WaitForRequestHandlerConnection(
-                                                    DATACOLLECTIONCONNTIMEOUT))
+                                                    DataCollectionCommTimeOut))
                                             {
                                                 this.dataCollectionTestCaseEventHandler.ProcessRequests();
                                             }

src/Microsoft.TestPlatform.CrossPlatEngine/EventHandlers/TestRequestHandler.cs

@@ -265,7 +265,7 @@ public void OnMessageReceived(object sender, MessageReceivedEventArgs messageRec
 
                 case MessageType.ExecutionInitialize:
                     {
-                        EqtTrace.Info("Discovery Session Initialize.");
+                        EqtTrace.Info("Execution Session Initialize.");
                         this.testHostManagerFactoryReady.Wait();
                         var pathToAdditionalExtensions = message.Payload.ToObject<IEnumerable<string>>();
                         jobQueue.QueueJob(

src/testhost.x86/DefaultEngineInvoker.cs

@@ -32,6 +32,8 @@ internal class DefaultEngineInvoker :
         /// </summary>
         private const int ClientListenTimeOut = Timeout.Infinite;
 
+        private const int DataConnectionClientListenTimeOut = 60 * 1000;
+
         private const string EndpointArgument = "--endpoint";
 
         private const string RoleArgument = "--role";
@@ -107,7 +109,16 @@ public void Invoke(IDictionary<string, string> argsDictionary)
                 {
                     var dataCollectionTestCaseEventSender = DataCollectionTestCaseEventSender.Create();
                     dataCollectionTestCaseEventSender.InitializeCommunication(dcPort);
-                    dataCollectionTestCaseEventSender.WaitForRequestSenderConnection(ClientListenTimeOut);
+
+                    // It's possible that connection to vstest.console happens, but to datacollector fails, why?
+                    // DataCollector keeps the server alive for testhost only for 15secs(increased to 60 now), 
+                    // if somehow(on slower machines, with Profiler Enabled) testhost can take considerable time to launch,
+                    // in such scenario dc.exe would have killed the server, but testhost will wait infinitely to connect to it,
+                    // hence do not wait to connect to datacollector process infinitely, as it will cause process hang.
+                    if(!dataCollectionTestCaseEventSender.WaitForRequestSenderConnection(DataConnectionClientListenTimeOut))
+                    {
+                        EqtTrace.Info("DefaultEngineInvoker: Connection to DataCollector failed: '{0}', DataCollection will not happen in this session", dcPort);
+                    }
                 }
 
                 // Checks for Telemetry Opted in or not from Command line Arguments.
@@ -152,6 +163,13 @@ private Task StartProcessingAsync(ITestRequestHandler requestHandler, ITestHostM
                 () =>
                     {
                         // Wait for the connection to the sender and start processing requests from sender
+                        // Note that we are waiting here infinitely to connect to vstest.console, but at the same time vstest.console doesn't wait infinitely.
+                        // It has a default timeout of 60secs(which is configurable), & then it kills testhost.exe
+                        // The reason to wait infinitely, was remote debugging scenarios of UWP app,
+                        // in such cases after the app gets launched, VS debugger takes control of it, & causes a lot of delay, which frequently causes timeout with vstest.console.
+                        // One fix would be just double this timeout, but there is no telling how much time it can actually take.
+                        // Hence we are waiting here indefinelty, to avoid such guessed timeouts, & letting user kill the debugging if they feel it is taking too much time.
+                        // In other cases if vstest.console's timeout exceeds it will definitelty such down the app.
                 if (requestHandler.WaitForRequestSenderConnection(ClientListenTimeOut))
                 {
                     requestHandler.ProcessRequests(managerFactory);

test/vstest.console.PlatformTests/AssemblyMetadataProviderTests.cs

@@ -75,9 +75,11 @@ public void GetArchitectureForNativeDll(string platform)
             var arch = this.assemblyMetadataProvider.GetArchitecture(assemblyPath);
             stopWatch.Stop();
 
-            Assert.AreEqual(Enum.Parse(typeof(Architecture), platform, ignoreCase: true), arch);
             Console.WriteLine("Platform:{0}, {1}", platform, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
-            Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
+            Assert.AreEqual(Enum.Parse(typeof(Architecture), platform, ignoreCase: true), arch);
+
+            // We should not assert on time elapsed, it will vary depending on machine, & their state, commenting below assert
+            // Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
         }
 
         [TestMethod]
@@ -109,7 +111,9 @@ public void GetFrameWorkForDotNetAssembly(string framework)
             }
 
             Console.WriteLine("Framework:{0}, {1}", framework, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
-            Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
+
+            // We should not assert on time elapsed, it will vary depending on machine, & their state.
+            // Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
         }
 
         [TestMethod]
@@ -121,10 +125,12 @@ public void GetFrameWorkForNativeDll()
             var stopWatch = Stopwatch.StartNew();
             var fx = this.assemblyMetadataProvider.GetFrameWork(assemblyPath);
             stopWatch.Stop();
-            Assert.AreEqual(Framework.DefaultFramework.Name, fx.FullName);
 
             Console.WriteLine(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds);
-            Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
+            Assert.AreEqual(Framework.DefaultFramework.Name, fx.FullName);
+
+            // We should not assert on time elapsed, it will vary depending on machine, & their state.
+            // Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
         }
 
         private void TestDotnetAssemblyArch(string projectName, string framework, Architecture expectedArch, long expectedElapsedTime)
@@ -134,11 +140,12 @@ private void TestDotnetAssemblyArch(string projectName, string framework, Archit
             var stopWatch = Stopwatch.StartNew();
             var arch = this.assemblyMetadataProvider.GetArchitecture(assemblyPath);
             stopWatch.Stop();
-            Assert.AreEqual(expectedArch, arch, $"Expected: {expectedArch} Actual: {arch}");
+
             Console.WriteLine("Framework:{0}, {1}", framework, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
-            Assert.IsTrue(
-                stopWatch.ElapsedMilliseconds < expectedElapsedTime,
-                string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
+            Assert.AreEqual(expectedArch, arch, $"Expected: {expectedArch} Actual: {arch}");
+
+            // We should not assert on time elapsed, it will vary depending on machine, & their state.
+            // Assert.IsTrue(stopWatch.ElapsedMilliseconds < expectedElapsedTime, string.Format(PerfAssertMessageFormat, expectedElapsedTime, stopWatch.ElapsedMilliseconds));
         }
 
         private void LoadAssemblyIntoMemory(string assemblyPath)