Increase datacollector initial communication timeout

src/Microsoft.TestPlatform.Build/Tasks/VSTestForwardingApp.cs

@@ -58,7 +58,7 @@ public void Cancel()
             }
             catch(ArgumentException ex)
             {
-                Tracing.Trace(string.Format("VSTest: Killing process throws ArgumentException with the following message {0}. It may be that process is not running", ex.Message));
+                Tracing.Trace(string.Format("VSTest: Killing process throws ArgumentException with the following message {0}. It may be that process is not running", ex));
             }
         }
     }

src/Microsoft.TestPlatform.Client/DesignMode/DesignModeClient.cs

@@ -136,7 +136,11 @@ private void ProcessRequests(ITestRequestManager testRequestManager)
                 {
                     var message = this.communicationManager.ReceiveMessage();
 
-                    EqtTrace.Info("DesignModeClient: Processing Message of message type: {0}", message.MessageType);
+                    if (EqtTrace.IsInfoEnabled)
+                    {
+                        EqtTrace.Info("DesignModeClient.ProcessRequests: Processing Message: {0}", message);
+                    }
+
                     switch (message.MessageType)
                     {
                         case MessageType.VersionCheck:

src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionAttachmentManager.cs

@@ -131,7 +131,7 @@ public List<AttachmentSet> GetAttachments(DataCollectionContext dataCollectionCo
             }
             catch (Exception ex)
             {
-                EqtTrace.Error(ex.Message);
+                EqtTrace.Error("DataCollectionAttachmentManager.GetAttachments: Fail to get attachments: {0} ", ex);
             }
 
             List<AttachmentSet> attachments = new List<AttachmentSet>();
@@ -295,7 +295,7 @@ private void AddNewFileTransfer(FileTransferInformation fileTransferInfo, AsyncC
                     catch (Exception ex)
                     {
                         this.LogError(
-                           ex.Message,
+                           ex.ToString(),
                            uri,
                            friendlyName,
                            Guid.Parse(testCaseId));

src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionManager.cs

@@ -450,7 +450,7 @@ private void LoadAndInitialize(DataCollectorSettings dataCollectorSettings, stri
                 }
 
                 // Log error.
-                dataCollectorInfo.Logger.LogError(this.dataCollectionEnvironmentContext.SessionDataCollectionContext, string.Format(CultureInfo.CurrentCulture, Resources.Resources.DataCollectorInitializationError, dataCollectorConfig.FriendlyName, ex.Message));
+                dataCollectorInfo.Logger.LogError(this.dataCollectionEnvironmentContext.SessionDataCollectionContext, string.Format(CultureInfo.CurrentCulture, Resources.Resources.DataCollectorInitializationError, dataCollectorConfig.FriendlyName, ex));
 
                 // Dispose datacollector.
                 dataCollectorInfo.DisposeDataCollector();

src/Microsoft.TestPlatform.Common/ExtensionFramework/VSExtensionManager.cs

@@ -62,7 +62,7 @@ public IEnumerable<string> GetUnitTestExtensions()
             }
             catch (Exception ex)
             {
-                string message = string.Format(CultureInfo.CurrentCulture, Resources.FailedToFindInstalledUnitTestExtensions, ex.Message);
+                string message = string.Format(CultureInfo.CurrentCulture, Resources.FailedToFindInstalledUnitTestExtensions, ex);
                 throw new TestPlatformException(message, ex);
             }
         }

src/Microsoft.TestPlatform.CommunicationUtilities/DataCollectionRequestHandler.cs

@@ -164,6 +164,12 @@ public void ProcessRequests()
             do
             {
                 var message = this.communicationManager.ReceiveMessage();
+
+                if (EqtTrace.IsVerboseEnabled)
+                {
+                    EqtTrace.Verbose("DataCollectionRequestHandler.ProcessRequests : Datacollector received message: {0}", message);
+                }
+
                 switch (message.MessageType)
                 {
                     case MessageType.BeforeTestRunStart:
@@ -214,7 +220,7 @@ public void ProcessRequests()
                                             {
                                                 EqtTrace.Error(
                                                     "DataCollectionRequestHandler.ProcessRequests : Error occured during initialization of TestHost : {0}",
-                                                    e.Message);
+                                                    e);
                                             }
                                         }
                                     },
@@ -253,7 +259,7 @@ public void ProcessRequests()
                         {
                             if (EqtTrace.IsErrorEnabled)
                             {
-                                EqtTrace.Error("DataCollectionRequestHandler.ProcessRequests : {0}", ex.Message);
+                                EqtTrace.Error("DataCollectionRequestHandler.ProcessRequests : {0}", ex.ToString());
                             }
                         }
 

src/Microsoft.TestPlatform.CommunicationUtilities/DataCollectionRequestSender.cs

@@ -55,6 +55,11 @@ internal DataCollectionRequestSender(ICommunicationManager communicationManager,
         /// <returns>Port number</returns>
         public int InitializeCommunication()
         {
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("DataCollectionRequestSender.InitializeCommunication : Initialize communication. ");
+            }
+
             var endpoint = this.communicationManager.HostServer(new IPEndPoint(IPAddress.Loopback, 0));
             this.communicationManager.AcceptClientAsync();
             return endpoint.Port;
@@ -67,6 +72,11 @@ public int InitializeCommunication()
         /// <returns>True, if Handler is connected</returns>
         public bool WaitForRequestHandlerConnection(int clientConnectionTimeout)
         {
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("DataCollectionRequestSender.WaitForRequestHandlerConnection : Waiting for connection with timeout: {0}", clientConnectionTimeout);
+            }
+
             return this.communicationManager.WaitForClientConnection(clientConnectionTimeout);
         }
 
@@ -97,12 +107,22 @@ public BeforeTestRunStartResult SendBeforeTestRunStartAndGetResult(string settin
             var isDataCollectionStarted = false;
             BeforeTestRunStartResult result = null;
 
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("DataCollectionRequestSender.SendBeforeTestRunStartAndGetResult : Send BeforeTestRunStart message with settingsXml: {0}", settingsXml);
+            }
+
             this.communicationManager.SendMessage(MessageType.BeforeTestRunStart, settingsXml);
 
             while (!isDataCollectionStarted)
             {
                 var message = this.communicationManager.ReceiveMessage();
 
+                if (EqtTrace.IsVerboseEnabled)
+                {
+                    EqtTrace.Verbose("DataCollectionRequestSender.SendBeforeTestRunStartAndGetResult : Received message: {0}", message);
+                }
+
                 if (message.MessageType == MessageType.DataCollectionMessage)
                 {
                     var dataCollectionMessageEventArgs = this.dataSerializer.DeserializePayload<DataCollectionMessageEventArgs>(message);
@@ -124,6 +144,11 @@ public Collection<AttachmentSet> SendAfterTestRunStartAndGetResult(ITestMessageE
             var isDataCollectionComplete = false;
             Collection<AttachmentSet> attachmentSets = null;
 
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("DataCollectionRequestSender.SendAfterTestRunStartAndGetResult : Send AfterTestRunEnd message with isCancelled: {0}", isCancelled);
+            }
+
             this.communicationManager.SendMessage(MessageType.AfterTestRunEnd, isCancelled);
 
             // Cycle through the messages that the datacollector sends.
@@ -132,6 +157,11 @@ public Collection<AttachmentSet> SendAfterTestRunStartAndGetResult(ITestMessageE
             {
                 var message = this.communicationManager.ReceiveMessage();
 
+                if (EqtTrace.IsVerboseEnabled)
+                {
+                    EqtTrace.Verbose("DataCollectionRequestSender.SendAfterTestRunStartAndGetResult : Received message: {0}", message);
+                }
+
                 if (message.MessageType == MessageType.DataCollectionMessage)
                 {
                     var dataCollectionMessageEventArgs = this.dataSerializer.DeserializePayload<DataCollectionMessageEventArgs>(message);

src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs

@@ -196,7 +196,7 @@ public async Task SetupClientAsync(IPEndPoint endpoint)
                 }
                 catch (Exception ex)
                 {
-                    EqtTrace.Verbose("Connection Failed with error {0}, retrying", ex.Message);
+                    EqtTrace.Verbose("Connection Failed with error {0}, retrying", ex.ToString());
                 }
             }
             while ((this.tcpClient != null) && !this.tcpClient.Connected && watch.ElapsedMilliseconds < CONNECTIONRETRYTIMEOUT);

src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs

@@ -6,7 +6,6 @@ namespace Microsoft.VisualStudio.TestPlatform.CommunicationUtilities
     using System;
     using System.Collections.Generic;
     using System.Globalization;
-    using System.Net;
     using System.Threading;
 
     using Microsoft.VisualStudio.TestPlatform.CommunicationUtilities.Interfaces;
@@ -110,6 +109,11 @@ internal TestRequestSender(
         /// <inheritdoc />
         public int InitializeCommunication()
         {
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.InitializeCommunication: initialize communication. ");
+            }
+
             // this.clientExitCancellationSource = new CancellationTokenSource();
             this.clientExitErrorMessage = string.Empty;
 
@@ -133,6 +137,11 @@ public int InitializeCommunication()
         /// <inheritdoc />
         public bool WaitForRequestHandlerConnection(int connectionTimeout)
         {
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.WaitForRequestHandlerConnection: waiting for connection with timeout: {0}", connectionTimeout);
+            }
+
             return this.connected.Wait(connectionTimeout);
         }
 
@@ -148,22 +157,21 @@ public void CheckVersionWithTestHost()
             {
                 var message = this.dataSerializer.DeserializeMessage(args.Data);
 
+                if (EqtTrace.IsVerboseEnabled)
+                {
+                    EqtTrace.Verbose("TestRequestSender.CheckVersionWithTestHost: onMessageReceived received message: {0}", message);
+                }
+
                 if (message.MessageType == MessageType.VersionCheck)
                 {
                     this.protocolVersion = this.dataSerializer.DeserializePayload<int>(message);
-
-                    EqtTrace.Info(@"TestRequestSender: VersionCheck Succeeded, NegotiatedVersion = {0}", this.protocolVersion);
                 }
 
                 // TRH can also send TestMessage if tracing is enabled, so log it at runner end
                 else if (message.MessageType == MessageType.TestMessage)
                 {
-                    // Only Deserialize if Tracing is enabled
-                    if (EqtTrace.IsInfoEnabled)
-                    {
-                        var testMessagePayload = this.dataSerializer.DeserializePayload<TestMessagePayload>(message);
-                        EqtTrace.Info("TestRequestSender.CheckVersionWithTestHost: " + testMessagePayload.Message);
-                    }
+                    // Ignore test messages. Currently we don't have handler(which sends messages to client/console.) here.
+                    // Above we are logging it to EqtTrace.
                 }
                 else if (message.MessageType == MessageType.ProtocolError)
                 {
@@ -242,6 +250,11 @@ public void InitializeExecution(IEnumerable<string> pathToAdditionalExtensions)
                 MessageType.ExecutionInitialize,
                 pathToAdditionalExtensions,
                 this.protocolVersion);
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.InitializeExecution: Sending initializing execution with message: {0}", message);
+            }
+
             this.channel.Send(message);
         }
 
@@ -260,6 +273,12 @@ public void StartTestRun(TestRunCriteriaWithSources runCriteria, ITestRunEventsH
                 MessageType.StartTestExecutionWithSources,
                 runCriteria,
                 this.protocolVersion);
+
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.StartTestRun: Sending test run with message: {0}", message);
+            }
+
             this.channel.Send(message);
         }
 
@@ -278,18 +297,33 @@ public void StartTestRun(TestRunCriteriaWithTests runCriteria, ITestRunEventsHan
                 MessageType.StartTestExecutionWithTests,
                 runCriteria,
                 this.protocolVersion);
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.StartTestRun: Sending test run with message: {0}", message);
+            }
+
             this.channel.Send(message);
         }
 
         /// <inheritdoc />
         public void SendTestRunCancel()
         {
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.SendTestRunCancel: Sending test run cancel.");
+            }
+
             this.channel?.Send(this.dataSerializer.SerializeMessage(MessageType.CancelTestRun));
         }
 
         /// <inheritdoc />
         public void SendTestRunAbort()
         {
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.SendTestRunAbort: Sending test run abort.");
+            }
+
             this.channel?.Send(this.dataSerializer.SerializeMessage(MessageType.AbortTestRun));
         }
 
@@ -300,6 +334,11 @@ public void EndSession()
         {
             if (!this.IsOperationComplete())
             {
+                if (EqtTrace.IsVerboseEnabled)
+                {
+                    EqtTrace.Verbose("TestRequestSender.EndSession: Sending end session.");
+                }
+
                 this.channel.Send(this.dataSerializer.SerializeMessage(MessageType.SessionEnd));
             }
         }
@@ -309,7 +348,12 @@ public void OnClientProcessExit(string stdError)
         {
             // This method is called on test host exit. If test host has any errors, stdError
             // provides the crash call stack.
-            EqtTrace.Info("TestRequestSender.OnClientProcessExit: Test host process exited. Standard error: " + stdError);
+            if (EqtTrace.IsInfoEnabled)
+            {
+                EqtTrace.Info("TestRequestSender.OnClientProcessExit: Test host process exited. Standard error: " +
+                              stdError);
+            }
+
             this.clientExitErrorMessage = stdError;
             this.clientExited.Set();
 
@@ -340,6 +384,10 @@ private void OnExecutionMessageReceived(object sender, MessageReceivedEventArgs
             try
             {
                 var rawMessage = messageReceived.Data;
+                if (EqtTrace.IsVerboseEnabled)
+                {
+                    EqtTrace.Verbose("TestRequestSender.OnExecutionMessageReceived: Received message: {0}", rawMessage);
+                }
 
                 // Send raw message first to unblock handlers waiting to send message to IDEs
                 testRunEventsHandler.HandleRawMessage(rawMessage);
@@ -375,6 +423,10 @@ private void OnExecutionMessageReceived(object sender, MessageReceivedEventArgs
                                 MessageType.LaunchAdapterProcessWithDebuggerAttachedCallback,
                                 processId,
                                 this.protocolVersion);
+                        if (EqtTrace.IsVerboseEnabled)
+                        {
+                            EqtTrace.Verbose("TestRequestSender.OnExecutionMessageReceived: Sending LaunchAdapterProcessWithDebuggerAttachedCallback message: {0}", data);
+                        }
 
                         this.channel.Send(data);
                         break;
@@ -393,9 +445,9 @@ private void OnDiscoveryMessageReceived(ITestDiscoveryEventsHandler2 discoveryEv
                 var rawMessage = args.Data;
 
                 // Currently each of the operations are not separate tasks since they should not each take much time. This is just a notification.
-                if (EqtTrace.IsInfoEnabled)
+                if (EqtTrace.IsVerboseEnabled)
                 {
-                    EqtTrace.Info("TestRequestSender: Received message: {0}", rawMessage);
+                    EqtTrace.Verbose("TestRequestSender.OnDiscoveryMessageReceived: Received message: {0}", rawMessage);
                 }
 
                 // Send raw message first to unblock handlers waiting to send message to IDEs
@@ -539,6 +591,11 @@ private bool IsOperationComplete()
         private void SetOperationComplete()
         {
             // Complete the currently ongoing operation (Discovery/Execution)
+            if (EqtTrace.IsVerboseEnabled)
+            {
+                EqtTrace.Verbose("TestRequestSender.SetOperationComplete: Setting operation complete.");
+            }
+
             Interlocked.CompareExchange(ref this.operationCompleted, 1, 0);
         }
 
@@ -563,4 +620,4 @@ private void SetCommunicationEndPoint()
             }
         }
     }
-}
+}

src/Microsoft.TestPlatform.CrossPlatEngine/Client/ProxyDiscoveryManager.cs

@@ -111,7 +111,7 @@ public void DiscoverTests(DiscoveryCriteria discoveryCriteria, ITestDiscoveryEve
                 EqtTrace.Error("ProxyDiscoveryManager.DiscoverTests: Failed to discover tests: {0}", exception);
 
                 // Log to vs ide test output
-                var testMessagePayload = new TestMessagePayload { MessageLevel = TestMessageLevel.Error, Message = exception.Message };
+                var testMessagePayload = new TestMessagePayload { MessageLevel = TestMessageLevel.Error, Message = exception.ToString() };
                 var rawMessage = this.dataSerializer.SerializePayload(MessageType.TestMessage, testMessagePayload);
                 this.HandleRawMessage(rawMessage);
 
@@ -120,7 +120,7 @@ public void DiscoverTests(DiscoveryCriteria discoveryCriteria, ITestDiscoveryEve
                 // Aborted is `true`: in case of parallel discovery (or non shared host), an aborted message ensures another discovery manager
                 // created to replace the current one. This will help if the current discovery manager is aborted due to irreparable error
                 // and the test host is lost as well.
-                this.HandleLogMessage(TestMessageLevel.Error, exception.Message);
+                this.HandleLogMessage(TestMessageLevel.Error, exception.ToString());
 
                 var discoveryCompleteEventsArgs = new DiscoveryCompleteEventArgs(-1, true);
 

src/Microsoft.TestPlatform.CrossPlatEngine/Client/ProxyExecutionManager.cs

@@ -152,7 +152,7 @@ public virtual int StartTestRun(TestRunCriteria testRunCriteria, ITestRunEventsH
             catch (Exception exception)
             {
                 EqtTrace.Error("ProxyExecutionManager.StartTestRun: Failed to start test run: {0}", exception);
-                this.LogMessage(TestMessageLevel.Error, exception.Message);
+                this.LogMessage(TestMessageLevel.Error, exception.ToString());
 
                 // Send a run complete to caller. Similar logic is also used in ParallelProxyExecutionManager.StartTestRunOnConcurrentManager
                 // Aborted is `true`: in case of parallel run (or non shared host), an aborted message ensures another execution manager