From 57a79e1065516060927405526040f9fd1a763c99 Mon Sep 17 00:00:00 2001 From: Liudmila Molkova Date: Mon, 13 Feb 2017 17:16:35 -0800 Subject: [PATCH] Call DiagnosticListener.IsEnabled() to check if someone listens to DiagnosticListener, send exception as separate event --- .../src/System/Net/Http/DiagnosticsHandler.cs | 73 ++++++++++++------- .../Http/DiagnosticsHandlerLoggingStrings.cs | 1 + .../tests/FunctionalTests/DiagnosticsTests.cs | 21 +++++- 3 files changed, 64 insertions(+), 31 deletions(-) diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs index 37c3db679421..322484d5ede3 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandler.cs +++ b/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 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 responseTask = base.SendAsync(request, cancellationToken); LogHttpResponse(responseTask, loggingRequestId); @@ -53,17 +52,20 @@ protected internal override Task 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 responseTask, Guid loggingRequestId) @@ -73,17 +75,32 @@ private static void LogHttpResponse(Task 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); } diff --git a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs b/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs index 4dfe9641ccc4..0b0dc0bda48d 100644 --- a/src/System.Net.Http/src/System/Net/Http/DiagnosticsHandlerLoggingStrings.cs +++ b/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"; } } diff --git a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs b/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs index e40e8f262c21..1c59c9c3e82e 100644 --- a/src/System.Net.Http/tests/FunctionalTests/DiagnosticsTests.cs +++ b/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(kvp.Value, "Exception"); var requestStatus = GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "RequestTaskStatus"); Assert.Equal(TaskStatus.Faulted, requestStatus); + responseLogged = true; + } + else if (kvp.Key.Equals("System.Net.Http.Exception")) + { + Assert.NotNull(kvp.Value); + GetPropertyValueFromAnonymousTypeInstance(kvp.Value, "Exception"); + exceptionLogged = true; } }); @@ -203,8 +217,9 @@ public void SendAsync_ExpectedDiagnosticExceptionLogging() Assert.ThrowsAsync(() => 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(); }