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.

Author: stephentoub

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

@@ -61,19 +61,19 @@ public void HeadersInvalidValue(string name, string rawValue) =>
             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 @@ private unsafe void WriteEvent(int eventId, int arg1, int arg2, string arg3, str
                     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 @@ internal ClientCertificateProvider(X509Certificate2Collection clientCertificates
 
             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,16 +53,23 @@ private int TlsClientCertCallback(IntPtr ssl, out IntPtr certHandle, out IntPtr
                     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.");
-                            return NoCertificateSet;
+                            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
                     {

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

@@ -87,6 +87,8 @@ internal void InitializeCurl()
                 }
                 _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 @@ internal void InitializeCurl()
                 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 @@ private void WorkerBodyLoop()
             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 @@ private void HandleIncomingRequests()
             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 @@ private void WaitForWork()
             /// <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 @@ private static class SslProvider
 
             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 @@ internal static void SetSslOptions(EasyRequest easy, ClientCertificateOption cli
                 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 @@ internal static void SetSslOptions(EasyRequest easy, ClientCertificateOption cli
             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 @@ private static void SetSslOptionsForSupportedBackend(EasyRequest easy, ClientCer
 
                     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 @@ private static CURLcode SslCtxCallback(IntPtr curl, IntPtr sslCtx, IntPtr userPo
                 {
                     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 @@ private static void EventSourceTraceCore(string message, MultiAgent agent, EasyR
             }
 
             NetEventSource.Log.HandlerMessage(
+                agent?.GetHashCode() ?? 0,
                 (agent?.RunningWorkerId).GetValueOrDefault(),
                 easy?.Task.Id ?? 0,
                 memberName,