Skip to content

Commit

Permalink
Increase datacollector initial communication timeout (#1355)
Browse files Browse the repository at this point in the history 
* Add logging to print stack trace

* Increase datacollector communication connection timeout

* Update unit tests

* Remove unneccesary using statement

* Throw exception on failed to connect datacollector

* Fix acceptance test

* Fix unit tests

* Address PR comments
  • Loading branch information
@smadala
smadala authored Jan 8, 2018
1 parent d65ba16 commit cc8957a
Show file tree
Hide file tree
Showing 39 changed files with 305 additions and 71 deletions.
2 changes: 1 addition & 1 deletion src/Microsoft.TestPlatform.Build/Tasks/VSTestForwardingApp.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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));
}
}
}
Expand Down
6 changes: 5 additions & 1 deletion src/Microsoft.TestPlatform.Client/DesignMode/DesignModeClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down
4 changes: 2 additions & 2 deletions src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionAttachmentManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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>();
Expand Down Expand Up @@ -295,7 +295,7 @@ private void AddNewFileTransfer(FileTransferInformation fileTransferInfo, AsyncC
catch (Exception ex)
{
this.LogError(
ex.Message,
ex.ToString(),
uri,
friendlyName,
Guid.Parse(testCaseId));
Expand Down
2 changes: 1 addition & 1 deletion src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down
2 changes: 1 addition & 1 deletion src/Microsoft.TestPlatform.Common/ExtensionFramework/VSExtensionManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Expand Down
10 changes: 8 additions & 2 deletions src/Microsoft.TestPlatform.CommunicationUtilities/DataCollectionRequestHandler.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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:
Expand Down Expand Up @@ -214,7 +220,7 @@ public void ProcessRequests()
{
EqtTrace.Error(
"DataCollectionRequestHandler.ProcessRequests : Error occured during initialization of TestHost : {0}",
e.Message);
e);
}
}
},
Expand Down Expand Up @@ -253,7 +259,7 @@ public void ProcessRequests()
{
if (EqtTrace.IsErrorEnabled)
{
EqtTrace.Error("DataCollectionRequestHandler.ProcessRequests : {0}", ex.Message);
EqtTrace.Error("DataCollectionRequestHandler.ProcessRequests : {0}", ex.ToString());
}
}

Expand Down
30 changes: 30 additions & 0 deletions src/Microsoft.TestPlatform.CommunicationUtilities/DataCollectionRequestSender.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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);
}

Expand Down Expand Up @@ -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);
Expand All @@ -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.
Expand All @@ -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);
Expand Down
2 changes: 1 addition & 1 deletion src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down
83 changes: 70 additions & 13 deletions src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;

Expand All @@ -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);
}

Expand All @@ -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)
{
Expand Down Expand Up @@ -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);
}

Expand All @@ -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);
}

Expand All @@ -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));
}

Expand All @@ -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));
}
}
Expand All @@ -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();

Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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;
Expand All @@ -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
Expand Down Expand Up @@ -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);
}

Expand All @@ -563,4 +620,4 @@ private void SetCommunicationEndPoint()
}
}
}
}
}
4 changes: 2 additions & 2 deletions src/Microsoft.TestPlatform.CrossPlatEngine/Client/ProxyDiscoveryManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);

Expand All @@ -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);

Expand Down
2 changes: 1 addition & 1 deletion src/Microsoft.TestPlatform.CrossPlatEngine/Client/ProxyExecutionManager.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Loading

0 comments on commit cc8957a

Please sign in to comment.