Log callbacks to delegates better

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");
     }
 
     /// <summary>

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");
     }
 
     /// <summary>

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)
                 {

src/Microsoft.TestPlatform.CommunicationUtilities/LengthPrefixCommunicationChannel.cs

@@ -67,6 +67,13 @@ public Task Send(string data)
     /// <inheritdoc />
     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);
     }

src/Microsoft.TestPlatform.CommunicationUtilities/SocketCommunicationManager.cs

@@ -139,7 +139,11 @@ public async Task AcceptClientAsync()
     /// <returns>True if Client is connected, false otherwise</returns>
     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;
     }
 
     /// <summary>
@@ -215,7 +219,11 @@ public async Task SetupClientAsync(IPEndPoint endpoint)
     /// <returns>True, if Server got a connection from client</returns>
     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;
     }
 
     /// <summary>

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,16 +165,22 @@ public int InitializeCommunication()
     /// <inheritdoc />
     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
         // or operation is canceled, handled by cancellationToken.WaitHandle
         // 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;
     }

src/Microsoft.TestPlatform.CoreUtilities/PublicAPI/PublicAPI.Unshipped.txt

@@ -1 +1 @@
-
+static Microsoft.VisualStudio.TestPlatform.Utilities.MulticastDelegateUtilities.SafeInvoke(this System.Delegate delegates, object sender, object args, string traceDisplayName) -> void

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;
 
 /// <summary>
 /// Utility methods for MulticastDelegates.
@@ -23,7 +22,22 @@ public static class MulticastDelegateUtilities
     /// <param name="sender">Sender to use when raising the event.</param>
     /// <param name="args">Arguments to provide.</param>
     /// <param name="traceDisplayName">Name to use when tracing out errors.</param>
+    // 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);
+    }
+
+    /// <summary>
+    /// Invokes each of the subscribers of the event and handles exceptions which are thrown
+    /// ensuring that each handler is invoked even if one throws.
+    /// </summary>
+    /// <param name="delegates">Event handler to invoke.</param>
+    /// <param name="sender">Sender to use when raising the event.</param>
+    /// <param name="args">Arguments to provide.</param>
+    /// <param name="traceDisplayName">Name to use when tracing out errors.</param>
+    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";
     }
-}
+}

src/Microsoft.TestPlatform.CrossPlatEngine/AttachmentsProcessing/TestRunAttachmentsProcessingManager.cs

@@ -54,7 +54,7 @@ public Task<Collection<AttachmentSet>> ProcessTestRunAttachmentsAsync(string run
 
     private async Task<Collection<AttachmentSet>> InternalProcessTestRunAttachmentsAsync(string runSettingsXml, IRequestData requestData, Collection<AttachmentSet> attachments, IEnumerable<InvokedDataCollector> invokedDataCollector, ITestRunAttachmentsProcessingEventsHandler eventHandler, CancellationToken cancellationToken)
     {
-        Stopwatch stopwatch = Stopwatch.StartNew();
+        var stopwatch = Stopwatch.StartNew();
 
         try
         {

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<string>(), It.IsAny<Object>()))
+            .Returns("non-empty rawMessage");
+
         _testRunRequest.TestRunMessage += (object sender, TestRunMessageEventArgs e) => handleLogMessageCalled = true;
 
         _testRunRequest.OnRawMessageReceived += (object sender, string message) => handleRawMessageCalled = true;