Add more tracing to HttpClient on Unix

Some recent investigations based on tracing data revealed some gaps in usefulness.  This adds some more tracing to try to fill those gaps.

src/System.Net.Http/src/System/Net/Http/NetEventSource.Http.cs

@@ -61,19 +61,19 @@ namespace System.Net
             WriteEvent(HeadersInvalidValueId, name, rawValue);
 
         [Event(HandlerMessageId, Keywords = Keywords.Debug, Level = EventLevel.Verbose)]
-        public void HandlerMessage(int workerId, int requestId, string memberName, string message) =>
-            WriteEvent(HandlerMessageId, workerId, requestId, memberName, message);
+        public void HandlerMessage(int handlerId, int workerId, int requestId, string memberName, string message) =>
+            WriteEvent(HandlerMessageId, handlerId, workerId, requestId, memberName, message);
 
         [NonEvent]
-        private unsafe void WriteEvent(int eventId, int arg1, int arg2, string arg3, string arg4)
+        private unsafe void WriteEvent(int eventId, int arg1, int arg2, int arg3, string arg4, string arg5)
         {
             if (IsEnabled())
             {
-                if (arg3 == null) arg3 = "";
                 if (arg4 == null) arg4 = "";
+                if (arg5 == null) arg5 = "";
 
-                fixed (char* string3Bytes = arg3)
                 fixed (char* string4Bytes = arg4)
+                fixed (char* string5Bytes = arg5)
                 {
                     const int NumEventDatas = 4;
                     var descrs = stackalloc EventData[NumEventDatas];
@@ -84,12 +84,15 @@ namespace System.Net
                     descrs[1].DataPointer = (IntPtr)(&arg2);
                     descrs[1].Size = sizeof(int);
 
-                    descrs[2].DataPointer = (IntPtr)string3Bytes;
-                    descrs[2].Size = ((arg3.Length + 1) * 2);
+                    descrs[2].DataPointer = (IntPtr)(&arg3);
+                    descrs[2].Size = sizeof(int);
 
                     descrs[3].DataPointer = (IntPtr)string4Bytes;
                     descrs[3].Size = ((arg4.Length + 1) * 2);
 
+                    descrs[4].DataPointer = (IntPtr)string5Bytes;
+                    descrs[4].Size = ((arg5.Length + 1) * 2);
+
                     WriteEventCore(eventId, NumEventDatas, descrs);
                 }
             }

src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.ClientCertificateProvider.cs

@@ -28,6 +28,7 @@ namespace System.Net.Http
 
             private int TlsClientCertCallback(IntPtr ssl, out IntPtr certHandle, out IntPtr privateKeyHandle)
             {
+                EventSourceTrace("SSL: {0}", ssl);
                 const int CertificateSet = 1, NoCertificateSet = 0, SuspendHandshake = -1;
 
                 certHandle = IntPtr.Zero;
@@ -52,17 +53,24 @@ namespace System.Net.Http
                     if (_clientCertificates != null) // manual mode
                     {
                         // If there's one certificate, just use it. Otherwise, try to find the best one.
-                        if (_clientCertificates.Count == 1)
+                        int certCount = _clientCertificates.Count;
+                        if (certCount == 1)
                         {
+                            EventSourceTrace("Single certificate.  Building chain.");
                             certificate = _clientCertificates[0];
                             chain = TLSCertificateExtensions.BuildNewChain(certificate, includeClientApplicationPolicy: false);
                         }
-                        else if (!_clientCertificates.TryFindClientCertificate(issuerNames, out certificate, out chain))
+                        else
                         {
-                            EventSourceTrace("No manual certificate or chain.");
+                            EventSourceTrace("Finding the best of {0} certificates", certCount);
+                            if (!_clientCertificates.TryFindClientCertificate(issuerNames, out certificate, out chain))
+                            {
+                                EventSourceTrace("No certificate set.");
                                 return NoCertificateSet;
                             }
                         }
+                        EventSourceTrace("Chain built.");
+                    }
                     else if (!GetAutomaticClientCertificate(issuerNames, out certificate, out chain)) // automatic mode
                     {
                         EventSourceTrace("No automatic certificate or chain.");

src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.EasyRequest.cs

@@ -87,6 +87,8 @@ namespace System.Net.Http
                 }
                 _easyHandle = easyHandle;
 
+                EventSourceTrace("Configuring request.");
+
                 // Before setting any other options, turn on curl's debug tracing
                 // if desired.  CURLOPT_VERBOSE may also be set subsequently if
                 // EventSource tracing is enabled.
@@ -109,6 +111,8 @@ namespace System.Net.Http
                 SetCookieOption(_requestMessage.RequestUri);
                 SetRequestHeaders();
                 SetSslOptions();
+
+                EventSourceTrace("Done configuring request.");
             }
 
             public void EnsureResponseMessagePublished()

src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.MultiAgent.cs

@@ -431,6 +431,7 @@ namespace System.Net.Http
             private void HandleIncomingRequests()
             {
                 Debug.Assert(!Monitor.IsEntered(_incomingRequests), "Incoming requests lock should only be held while accessing the queue");
+                EventSourceTrace(null);
 
                 while (true)
                 {
@@ -499,7 +500,9 @@ namespace System.Net.Http
             private void PerformCurlWork()
             {
                 CURLMcode performResult;
+                EventSourceTrace("Ask libcurl to perform any available work...");
                 while ((performResult = Interop.Http.MultiPerform(_multiHandle)) == CURLMcode.CURLM_CALL_MULTI_PERFORM) ;
+                EventSourceTrace("...done performing work: {0}", performResult);
                 ThrowIfCURLMError(performResult);
             }
 
@@ -542,9 +545,12 @@ namespace System.Net.Http
             /// <summary>Handle a libcurl message received as part of processing work.  This should signal a completed operation.</summary>
             private void HandleCurlMessage(Interop.Http.CURLMSG message, IntPtr easyHandle, CURLcode result)
             {
-                Debug.Assert(message == Interop.Http.CURLMSG.CURLMSG_DONE, $"CURLMSG_DONE is supposed to be the only message type, but got {message}");
                 if (message != Interop.Http.CURLMSG.CURLMSG_DONE)
+                {
+                    Debug.Fail($"CURLMSG_DONE is supposed to be the only message type, but got {message}");
+                    EventSourceTrace("Unexpected CURLMSG: {0}", message);
                     return;
+                }
 
                 // Get the GCHandle pointer from the easy handle's state
                 IntPtr gcHandlePtr;

src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.SslProvider.cs

@@ -27,6 +27,7 @@ namespace System.Net.Http
 
             internal static void SetSslOptions(EasyRequest easy, ClientCertificateOption clientCertOption)
             {
+                EventSourceTrace("ClientCertificateOption: {0}", clientCertOption, easy:easy);
                 Debug.Assert(clientCertOption == ClientCertificateOption.Automatic || clientCertOption == ClientCertificateOption.Manual);
 
                 // Create a client certificate provider if client certs may be used.
@@ -38,6 +39,8 @@ namespace System.Net.Http
                 IntPtr userPointer = IntPtr.Zero;
                 if (certProvider != null)
                 {
+                    EventSourceTrace("Created certificate provider", easy:easy);
+
                     // The client cert provider needs to be passed through to the callback, and thus
                     // we create a GCHandle to keep it rooted.  This handle needs to be cleaned up
                     // when the request has completed, and a simple and pay-for-play way to do that
@@ -67,6 +70,7 @@ namespace System.Net.Http
             private static void SetSslOptionsForSupportedBackend(EasyRequest easy, ClientCertificateProvider certProvider, IntPtr userPointer)
             {
                 CURLcode answer = easy.SetSslCtxCallback(s_sslCtxCallback, userPointer);
+                EventSourceTrace("Callback registration result: {0}", answer, easy: easy);
                 switch (answer)
                 {
                     case CURLcode.CURLE_OK:
@@ -86,7 +90,6 @@ namespace System.Net.Http
 
                     case CURLcode.CURLE_UNKNOWN_OPTION: // Curl 7.38 and prior
                     case CURLcode.CURLE_NOT_BUILT_IN:   // Curl 7.39 and later
-                        EventSourceTrace("CURLOPT_SSL_CTX_FUNCTION not supported: {0}", answer, easy: easy);
                         SetSslOptionsForUnsupportedBackend(easy, certProvider);
                         break;
 
@@ -181,6 +184,7 @@ namespace System.Net.Http
                 {
                     return CURLcode.CURLE_ABORTED_BY_CALLBACK;
                 }
+                EventSourceTrace(null, easy: easy);
 
                 // Configure the SSL protocols allowed.
                 SslProtocols protocols = easy._handler.SslProtocols;

src/System.Net.Http/src/System/Net/Http/Unix/CurlHandler.cs

@@ -720,6 +720,7 @@ namespace System.Net.Http
             }
 
             NetEventSource.Log.HandlerMessage(
+                agent?.GetHashCode() ?? 0,
                 (agent?.RunningWorkerId).GetValueOrDefault(),
                 easy?.Task.Id ?? 0,
                 memberName,