Merge pull request #20095 from stephentoub/http_tracing

Add more tracing to HttpClient on Unix

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,16 +53,23 @@ 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.");
-                            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 @@ 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,