diff --git a/src/Microsoft.TestPlatform.Client/Discovery/DiscoveryRequest.cs b/src/Microsoft.TestPlatform.Client/Discovery/DiscoveryRequest.cs index 182584ee9a..acf7197631 100644 --- a/src/Microsoft.TestPlatform.Client/Discovery/DiscoveryRequest.cs +++ b/src/Microsoft.TestPlatform.Client/Discovery/DiscoveryRequest.cs @@ -398,7 +398,7 @@ public void HandleRawMessage(string rawMessage) HandleLoggerManagerDiscoveryComplete(discoveryCompletePayload); } - OnRawMessageReceived?.Invoke(this, rawMessage); + OnRawMessageReceived?.SafeInvoke(this, rawMessage, "DiscoveryRequest.RawMessageReceived"); } /// diff --git a/src/Microsoft.TestPlatform.Client/Execution/TestRunRequest.cs b/src/Microsoft.TestPlatform.Client/Execution/TestRunRequest.cs index 36697c47ea..91f9d51993 100644 --- a/src/Microsoft.TestPlatform.Client/Execution/TestRunRequest.cs +++ b/src/Microsoft.TestPlatform.Client/Execution/TestRunRequest.cs @@ -545,7 +545,7 @@ public void HandleRawMessage(string rawMessage) HandleLoggerManagerTestRunComplete(testRunCompletePayload); } - OnRawMessageReceived?.Invoke(this, rawMessage); + OnRawMessageReceived?.SafeInvoke(this, rawMessage, "TestRunRequest.RawMessageReceived"); } /// diff --git a/src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionAttachmentManager.cs b/src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionAttachmentManager.cs index 5599c615b8..d369d49c00 100644 --- a/src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionAttachmentManager.cs +++ b/src/Microsoft.TestPlatform.Common/DataCollection/DataCollectionAttachmentManager.cs @@ -347,7 +347,7 @@ private void AddNewFileTransfer(FileTransferInformation fileTransferInfo, AsyncC } } - sendFileCompletedCallback?.Invoke(this, new AsyncCompletedEventArgs(t.Exception, false, fileTransferInfo.UserToken)); + sendFileCompletedCallback?.SafeInvoke(this, new AsyncCompletedEventArgs(t.Exception, false, fileTransferInfo.UserToken), "DataCollectionManager.AddNewFileTransfer"); } catch (Exception e) { diff --git a/src/Microsoft.TestPlatform.CommunicationUtilities/LengthPrefixCommunicationChannel.cs b/src/Microsoft.TestPlatform.CommunicationUtilities/LengthPrefixCommunicationChannel.cs index 8357b99994..5f84d8259e 100644 --- a/src/Microsoft.TestPlatform.CommunicationUtilities/LengthPrefixCommunicationChannel.cs +++ b/src/Microsoft.TestPlatform.CommunicationUtilities/LengthPrefixCommunicationChannel.cs @@ -67,6 +67,13 @@ public Task Send(string data) /// public Task NotifyDataAvailable() { + // TODO: Review the comment below, because it says something different than what is + // actually happening, and doing what it suggests would potentially lose messages. + // For example in the case where we start testhost process, send it version, and + // it responds, we then replace the handler with a new one, and there is quite a long time + // (tens of milliseconds) when there is no handler present, which would pump the message + // and dump it. + // // Try read data even if no one is listening to the data stream. Some server // implementations (like Sockets) depend on the read operation to determine if a // connection is closed. @@ -75,6 +82,10 @@ public Task NotifyDataAvailable() var data = _reader.ReadString(); MessageReceived.SafeInvoke(this, new MessageReceivedEventArgs { Data = data }, "LengthPrefixCommunicationChannel: MessageReceived"); } + else + { + EqtTrace.Verbose("LengthPrefixCommunicationChannel.NotifyDataAvailable: New data are waiting to be received, but there is no subscriber to be notified. Not reading them from the stream."); + } return Task.FromResult(0); } diff --git a/src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs b/src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs index 325f0c58d5..68225ef2c7 100644 --- a/src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs +++ b/src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs @@ -139,7 +139,11 @@ public async Task AcceptClientAsync() /// True if Client is connected, false otherwise public bool WaitForClientConnection(int clientConnectionTimeout) { - return _clientConnectedEvent.WaitOne(clientConnectionTimeout); + var stopWatch = Stopwatch.StartNew(); + var result = _clientConnectedEvent.WaitOne(clientConnectionTimeout); + EqtTrace.Verbose("SocketCommunicationManager.WaitForClientConnection took: {0} ms, with {1} ms timeout, and finished with {2}.", stopWatch.ElapsedMilliseconds, clientConnectionTimeout, result); + + return result; } /// @@ -215,7 +219,11 @@ public async Task SetupClientAsync(IPEndPoint endpoint) /// True, if Server got a connection from client public bool WaitForServerConnection(int connectionTimeout) { - return _clientConnectionAcceptedEvent.WaitOne(connectionTimeout); + var stopWatch = Stopwatch.StartNew(); + var result = _clientConnectionAcceptedEvent.WaitOne(connectionTimeout); + EqtTrace.Verbose("SocketCommunicationManager.WaitForServerConnection took: {0} ms, with {1} ms timeout, and finished with {2}.", stopWatch.ElapsedMilliseconds, connectionTimeout, result); + + return result; } /// diff --git a/src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs b/src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs index 42dbbe9290..5c8b810f11 100644 --- a/src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs +++ b/src/Microsoft.TestPlatform.CommunicationUtilities/TestRequestSender.cs @@ -5,6 +5,7 @@ namespace Microsoft.VisualStudio.TestPlatform.CommunicationUtilities; using System; using System.Collections.Generic; +using System.Diagnostics; using System.Globalization; using System.Threading; @@ -164,9 +165,10 @@ public int InitializeCommunication() /// public bool WaitForRequestHandlerConnection(int connectionTimeout, CancellationToken cancellationToken) { + var sw = Stopwatch.StartNew(); if (EqtTrace.IsVerboseEnabled) { - EqtTrace.Verbose("TestRequestSender.WaitForRequestHandlerConnection: waiting for connection with timeout: {0}", connectionTimeout); + EqtTrace.Verbose("TestRequestSender.WaitForRequestHandlerConnection: waiting for connection with timeout: {0}.", connectionTimeout); } // Wait until either connection is successful, handled by connected.WaitHandle @@ -174,6 +176,11 @@ public bool WaitForRequestHandlerConnection(int connectionTimeout, CancellationT // or testhost exits unexpectedly, handled by clientExited.WaitHandle var waitIndex = WaitHandle.WaitAny(new WaitHandle[] { _connected.WaitHandle, cancellationToken.WaitHandle, _clientExited.WaitHandle }, connectionTimeout); + if (EqtTrace.IsVerboseEnabled) + { + EqtTrace.Verbose("TestRequestSender.WaitForRequestHandlerConnection: waiting took {0} ms, with timeout {1} ms, and result {2}, which is {3}.", sw.ElapsedMilliseconds, connectionTimeout, waitIndex, waitIndex == 0 ? "success" : "failure"); + } + // Return true if connection was successful. return waitIndex == 0; } diff --git a/src/Microsoft.TestPlatform.CoreUtilities/PublicAPI/PublicAPI.Unshipped.txt b/src/Microsoft.TestPlatform.CoreUtilities/PublicAPI/PublicAPI.Unshipped.txt index 5f282702bb..64339d8507 100644 --- a/src/Microsoft.TestPlatform.CoreUtilities/PublicAPI/PublicAPI.Unshipped.txt +++ b/src/Microsoft.TestPlatform.CoreUtilities/PublicAPI/PublicAPI.Unshipped.txt @@ -1 +1 @@ - \ No newline at end of file +static Microsoft.VisualStudio.TestPlatform.Utilities.MulticastDelegateUtilities.SafeInvoke(this System.Delegate delegates, object sender, object args, string traceDisplayName) -> void \ No newline at end of file diff --git a/src/Microsoft.TestPlatform.CoreUtilities/Utilities/MulticastDelegateUtilities.cs b/src/Microsoft.TestPlatform.CoreUtilities/Utilities/MulticastDelegateUtilities.cs index 155e7f29b3..dd7e68a95b 100644 --- a/src/Microsoft.TestPlatform.CoreUtilities/Utilities/MulticastDelegateUtilities.cs +++ b/src/Microsoft.TestPlatform.CoreUtilities/Utilities/MulticastDelegateUtilities.cs @@ -4,11 +4,10 @@ namespace Microsoft.VisualStudio.TestPlatform.Utilities; using System; +using System.Diagnostics; using System.Reflection; -using CoreUtilities.Resources; - -using ObjectModel; +using Microsoft.VisualStudio.TestPlatform.ObjectModel; /// /// Utility methods for MulticastDelegates. @@ -23,7 +22,22 @@ public static class MulticastDelegateUtilities /// Sender to use when raising the event. /// Arguments to provide. /// Name to use when tracing out errors. + // Using [CallerMemberName] for the traceDisplayName is a possibility, but in few places we call through other + // methods until we reach here. And it would change the public API. public static void SafeInvoke(this Delegate delegates, object sender, EventArgs args, string traceDisplayName) + { + SafeInvoke(delegates, sender, (object)args, traceDisplayName); + } + + /// + /// Invokes each of the subscribers of the event and handles exceptions which are thrown + /// ensuring that each handler is invoked even if one throws. + /// + /// Event handler to invoke. + /// Sender to use when raising the event. + /// Arguments to provide. + /// Name to use when tracing out errors. + public static void SafeInvoke(this Delegate delegates, object sender, object args, string traceDisplayName) { if (args == null) { @@ -32,30 +46,65 @@ public static void SafeInvoke(this Delegate delegates, object sender, EventArgs if (string.IsNullOrWhiteSpace(traceDisplayName)) { - throw new ArgumentException(Resources.CannotBeNullOrEmpty, nameof(traceDisplayName)); + throw new ArgumentNullException(nameof(traceDisplayName)); } if (delegates != null) { - foreach (Delegate handler in delegates.GetInvocationList()) + var invocationList = delegates.GetInvocationList(); + var i = 0; + foreach (Delegate handler in invocationList) { + var stopwatch = Stopwatch.StartNew(); + try { handler.DynamicInvoke(sender, args); + if (EqtTrace.IsVerboseEnabled) + { + EqtTrace.Verbose("MulticastDelegateUtilities.SafeInvoke: {0}: Invoking callback {1}/{2} for {3}.{4}, took {5} ms.", + traceDisplayName, + ++i, + invocationList.Length, + handler.GetTargetName(), + handler.GetMethodName(), + stopwatch.ElapsedMilliseconds); + } } - catch (TargetInvocationException e) + catch (TargetInvocationException exception) { if (EqtTrace.IsErrorEnabled) { EqtTrace.Error( - "{0}: Exception occurred while calling handler of type {1} for {2}: {3}", + "MulticastDelegateUtilities.SafeInvoke: {0}: Invoking callback {1}/{2} for {3}.{4}, failed after {5} ms with: {6}.", + ++i, + invocationList.Length, + handler.GetTargetName(), + handler.GetMethodName(), traceDisplayName, - handler.Target.GetType().FullName, - args.GetType().Name, - e); + stopwatch.ElapsedMilliseconds, + exception); } } } } + else + { + EqtTrace.Verbose("MulticastDelegateUtilities.SafeInvoke: {0}: Invoking callbacks was skipped because there are no subscribers.", traceDisplayName); + } + } + + internal static string GetMethodName(this Delegate @delegate) + { +#if NETSTANDARD2_0 + return @delegate.Method.Name; +#else + return null; +#endif + } + + internal static string GetTargetName(this Delegate @delegate) + { + return @delegate.Target?.ToString() ?? "static"; } -} \ No newline at end of file +} diff --git a/src/Microsoft.TestPlatform.CrossPlatEngine/AttachmentsProcessing/TestRunAttachmentsProcessingManager.cs b/src/Microsoft.TestPlatform.CrossPlatEngine/AttachmentsProcessing/TestRunAttachmentsProcessingManager.cs index 60d672ea86..6f68bca4fe 100644 --- a/src/Microsoft.TestPlatform.CrossPlatEngine/AttachmentsProcessing/TestRunAttachmentsProcessingManager.cs +++ b/src/Microsoft.TestPlatform.CrossPlatEngine/AttachmentsProcessing/TestRunAttachmentsProcessingManager.cs @@ -54,7 +54,7 @@ public Task> ProcessTestRunAttachmentsAsync(string run private async Task> InternalProcessTestRunAttachmentsAsync(string runSettingsXml, IRequestData requestData, Collection attachments, IEnumerable invokedDataCollector, ITestRunAttachmentsProcessingEventsHandler eventHandler, CancellationToken cancellationToken) { - Stopwatch stopwatch = Stopwatch.StartNew(); + var stopwatch = Stopwatch.StartNew(); try { diff --git a/test/Microsoft.TestPlatform.Client.UnitTests/Execution/TestRunRequestTests.cs b/test/Microsoft.TestPlatform.Client.UnitTests/Execution/TestRunRequestTests.cs index e4ca1e7f9e..8f3f3e8596 100644 --- a/test/Microsoft.TestPlatform.Client.UnitTests/Execution/TestRunRequestTests.cs +++ b/test/Microsoft.TestPlatform.Client.UnitTests/Execution/TestRunRequestTests.cs @@ -170,6 +170,10 @@ public void OnTestSessionTimeoutShouldLogMessage() bool handleLogMessageCalled = false; bool handleRawMessageCalled = false; + _mockDataSerializer + .Setup(s => s.SerializePayload(It.IsAny(), It.IsAny())) + .Returns("non-empty rawMessage"); + _testRunRequest.TestRunMessage += (object sender, TestRunMessageEventArgs e) => handleLogMessageCalled = true; _testRunRequest.OnRawMessageReceived += (object sender, string message) => handleRawMessageCalled = true;