Refactor HTTP DiagnosticSource logging (part1 continued)

src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs

@@ -24,22 +24,21 @@ public DiagnosticsHandler(HttpMessageHandler innerHandler) : base(innerHandler)
 
         internal static bool IsEnabled()
         {
-            return s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteName);
+            //check if someone listens to HttpHandlerDiagnosticListener
+            return s_diagnosticListener.IsEnabled();
         }
 
         protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessage request,
             CancellationToken cancellationToken)
         {
-            //HttpClientHandler is responsible to call DelegatingHandler.IsEnabled() before forwarding request here.
-            //This code will not be reached if ResponseWriteName is not enabled, unless consumer unsubscribes
+            //HttpClientHandler is responsible to call DiagnosticsHandler.IsEnabled() before forwarding request here.
+            //This code will not be reached if no one listens to 'HttpHandlerDiagnosticListener', unless consumer unsubscribes
             //from DiagnosticListener right after the check. So some requests happening right after subscription starts
             //might not be instrumented. Similarly, when consumer unsubscribes, extra requests might be instumented
 
             Guid loggingRequestId = Guid.NewGuid();
-            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteName))
-            {
-                LogHttpRequest(request,  loggingRequestId);
-            }
+            LogHttpRequest(request,  loggingRequestId);
+
             Task<HttpResponseMessage> responseTask = base.SendAsync(request, cancellationToken);
 
             LogHttpResponse(responseTask, loggingRequestId);
@@ -53,17 +52,20 @@ protected internal override Task<HttpResponseMessage> SendAsync(HttpRequestMessa
 
         private static void LogHttpRequest(HttpRequestMessage request, Guid loggingRequestId)
         {
-            long timestamp = Stopwatch.GetTimestamp();
+            if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.RequestWriteName))
+            {
+                long timestamp = Stopwatch.GetTimestamp();
 
-            s_diagnosticListener.Write(
-                DiagnosticsHandlerLoggingStrings.RequestWriteName,
-                new
-                {
-                    Request = request,
-                    LoggingRequestId = loggingRequestId,
-                    Timestamp = timestamp
-                }
-            );
+                s_diagnosticListener.Write(
+                    DiagnosticsHandlerLoggingStrings.RequestWriteName,
+                    new
+                    {
+                        Request = request,
+                        LoggingRequestId = loggingRequestId,
+                        Timestamp = timestamp
+                    }
+                );
+            }
         }
 
         private static void LogHttpResponse(Task<HttpResponseMessage> responseTask, Guid loggingRequestId)
@@ -73,17 +75,32 @@ private static void LogHttpResponse(Task<HttpResponseMessage> responseTask, Guid
                 {
                     long timestamp = Stopwatch.GetTimestamp();
 
-                    s_diagnosticListener.Write(
-                        DiagnosticsHandlerLoggingStrings.ResponseWriteName,
-                        new
-                        {
-                            Response = t.Status == TaskStatus.RanToCompletion ? t.Result : null,
-                            LoggingRequestId = (Guid)s,
-                            TimeStamp = timestamp,
-                            Exception = t.Exception,
-                            RequestTaskStatus = t.Status
-                        }
-                    );
+                    if (t.IsFaulted && s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ExceptionWriteName))
+                    {
+                        s_diagnosticListener.Write(
+                            DiagnosticsHandlerLoggingStrings.ExceptionWriteName,
+                            new
+                            {
+                                LoggingRequestId = (Guid) s,
+                                Timestamp = timestamp,
+                                Exception = t.Exception,
+                            }
+                        );
+                    }
+
+                    if (s_diagnosticListener.IsEnabled(DiagnosticsHandlerLoggingStrings.ResponseWriteName))
+                    {
+                        s_diagnosticListener.Write(
+                            DiagnosticsHandlerLoggingStrings.ResponseWriteName,
+                            new
+                            {
+                                Response = t.Status == TaskStatus.RanToCompletion ? t.Result : null,
+                                LoggingRequestId = (Guid) s,
+                                TimeStamp = timestamp,
+                                RequestTaskStatus = t.Status
+                            }
+                        );
+                    }
                 }, loggingRequestId, CancellationToken.None, TaskContinuationOptions.None, TaskScheduler.Default);
         }
 

src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs

@@ -12,5 +12,6 @@ internal static class DiagnosticsHandlerLoggingStrings
         public const string DiagnosticListenerName = "HttpHandlerDiagnosticListener";
         public const string RequestWriteName = "System.Net.Http.Request";
         public const string ResponseWriteName = "System.Net.Http.Response";
+        public const string ExceptionWriteName = "System.Net.Http.Exception";
     }
 }

src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs

@@ -51,6 +51,8 @@ public void SendAsync_ExpectedDiagnosticSourceLogging()
                 Guid requestGuid = Guid.Empty;
                 bool responseLogged = false;
                 Guid responseGuid = Guid.Empty;
+
+                bool exceptionLogged = false;
                 var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp =>
                 {
                     if (kvp.Key.Equals("System.Net.Http.Request"))
@@ -71,6 +73,10 @@ public void SendAsync_ExpectedDiagnosticSourceLogging()
 
                         responseLogged = true;
                     }
+                    else if (kvp.Key.Equals("System.Net.Http.Exception"))
+                    {
+                        exceptionLogged = true;
+                    }
                 });
 
                 using (DiagnosticListener.AllListeners.Subscribe(diagnosticListenerObserver))
@@ -85,6 +91,7 @@ public void SendAsync_ExpectedDiagnosticSourceLogging()
                     // Poll with a timeout since logging response is not synchronized with returning a response.
                     WaitForTrue(() => responseLogged, TimeSpan.FromSeconds(1), "Response was not logged within 1 second timeout.");
                     Assert.Equal(requestGuid, responseGuid);
+                    Assert.False(exceptionLogged, "Exception was logged for successful request");
                     diagnosticListenerObserver.Disable();
                 }
 
@@ -182,15 +189,22 @@ public void SendAsync_ExpectedDiagnosticExceptionLogging()
             RemoteInvoke(() =>
             {
                 bool exceptionLogged = false;
+                bool responseLogged = false;
                 var diagnosticListenerObserver = new FakeDiagnosticListenerObserver(kvp =>
                 {
                     if (kvp.Key.Equals("System.Net.Http.Response"))
                     {
                         Assert.NotNull(kvp.Value);
-                        GetPropertyValueFromAnonymousTypeInstance<Exception>(kvp.Value, "Exception");
                         var requestStatus = GetPropertyValueFromAnonymousTypeInstance<TaskStatus>(kvp.Value, "RequestTaskStatus");
                         Assert.Equal(TaskStatus.Faulted, requestStatus);
 
+                        responseLogged = true;
+                    }
+                    else if (kvp.Key.Equals("System.Net.Http.Exception"))
+                    {
+                        Assert.NotNull(kvp.Value);
+                        GetPropertyValueFromAnonymousTypeInstance<Exception>(kvp.Value, "Exception");
+
                         exceptionLogged = true;
                     }
                 });
@@ -203,8 +217,9 @@ public void SendAsync_ExpectedDiagnosticExceptionLogging()
                         Assert.ThrowsAsync<HttpRequestException>(() => client.GetAsync($"http://{Guid.NewGuid()}.com")).Wait();
                     }
                     // Poll with a timeout since logging response is not synchronized with returning a response.
-                    WaitForTrue(() => exceptionLogged, TimeSpan.FromSeconds(1),
-                        "Exception was not logged within 1 second timeout.");
+                    WaitForTrue(() => responseLogged, TimeSpan.FromSeconds(1),
+                        "Response with exception was not logged within 1 second timeout.");
+                    Assert.True(exceptionLogged, "Exception was not logged");
                     diagnosticListenerObserver.Disable();
                 }