Ensure Http Telemetry correctness (#40338)
authorMiha Zupan <mihazupan.zupan1@gmail.com>
Tue, 11 Aug 2020 02:41:35 +0000 (04:41 +0200)
committerGitHub <noreply@github.com>
Tue, 11 Aug 2020 02:41:35 +0000 (04:41 +0200)
* Ensure Http Telemetry correctness

* Remove unnecessary GC.SuppressFinalize call

* Add another Telemetry.IsEnabled() check

* Rename MessageShouldEmitTelemetry to MessageAlreadySent_StopNotYetCalled

* Improve Telemetry tests

* Log Aborted instead of Stopped on Connection Dispose

* Ensure request is canceled after a connection is established

14 files changed:
src/libraries/System.Net.Http/src/System/Net/Http/HttpRequestMessage.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ChunkedEncodingReadStream.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ConnectionCloseReadStream.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/ContentLengthReadStream.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Stream.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnection.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPool.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpConnectionPoolManager.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/HttpContentStream.cs
src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/RawConnectionStream.cs
src/libraries/System.Net.Http/tests/FunctionalTests/System.Net.Http.Functional.Tests.csproj
src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs [new file with mode: 0644]
src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs [new file with mode: 0644]
src/libraries/System.Net.Http/tests/UnitTests/System.Net.Http.Unit.Tests.csproj

index 5e1d9bb..f74fd02 100644 (file)
@@ -6,6 +6,7 @@ using System.Net.Http.Headers;
 using System.Text;
 using System.Threading;
 using System.Collections.Generic;
+using System.Diagnostics;
 
 namespace System.Net.Http
 {
@@ -13,9 +14,10 @@ namespace System.Net.Http
     {
         private const int MessageNotYetSent = 0;
         private const int MessageAlreadySent = 1;
+        private const int MessageAlreadySent_StopNotYetCalled = 2;
 
         // Track whether the message has been sent.
-        // The message shouldn't be sent again if this field is equal to MessageAlreadySent.
+        // The message should only be sent if this field is equal to MessageNotYetSent.
         private int _sendStatus = MessageNotYetSent;
 
         private HttpMethod _method;
@@ -183,7 +185,31 @@ namespace System.Net.Http
 
         internal bool MarkAsSent()
         {
-            return Interlocked.Exchange(ref _sendStatus, MessageAlreadySent) == MessageNotYetSent;
+            return Interlocked.CompareExchange(ref _sendStatus, MessageAlreadySent, MessageNotYetSent) == MessageNotYetSent;
+        }
+
+        internal void MarkAsTrackedByTelemetry()
+        {
+            Debug.Assert(_sendStatus != MessageAlreadySent_StopNotYetCalled);
+            _sendStatus = MessageAlreadySent_StopNotYetCalled;
+        }
+
+        internal void OnAborted() => OnStopped(aborted: true);
+
+        internal void OnStopped(bool aborted = false)
+        {
+            if (HttpTelemetry.Log.IsEnabled())
+            {
+                if (Interlocked.Exchange(ref _sendStatus, MessageAlreadySent) == MessageAlreadySent_StopNotYetCalled)
+                {
+                    if (aborted)
+                    {
+                        HttpTelemetry.Log.RequestAborted();
+                    }
+
+                    HttpTelemetry.Log.RequestStop();
+                }
+            }
         }
 
         #region IDisposable Members
@@ -200,6 +226,8 @@ namespace System.Net.Http
                     _content.Dispose();
                 }
             }
+
+            OnStopped();
         }
 
         public void Dispose()
index d747bd8..b9ccbce 100644 (file)
@@ -56,7 +56,6 @@ namespace System.Net.Http
                     if (_connection == null)
                     {
                         // Fully consumed the response in ReadChunksFromConnectionBuffer.
-                        if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                         return 0;
                     }
 
@@ -362,7 +361,6 @@ namespace System.Net.Http
                                     cancellationRegistration.Dispose();
                                     CancellationHelper.ThrowIfCancellationRequested(cancellationRegistration.Token);
 
-                                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                                     _state = ParsingState.Done;
                                     _connection.CompleteResponse();
                                     _connection = null;
index 1d7a0b2..28ef24f 100644 (file)
@@ -28,7 +28,6 @@ namespace System.Net.Http
                 if (bytesRead == 0)
                 {
                     // We cannot reuse this connection, so close it.
-                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                     _connection = null;
                     connection.Dispose();
                 }
@@ -81,7 +80,6 @@ namespace System.Net.Http
                     CancellationHelper.ThrowIfCancellationRequested(cancellationToken);
 
                     // We cannot reuse this connection, so close it.
-                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                     _connection = null;
                     connection.Dispose();
                 }
@@ -143,7 +141,6 @@ namespace System.Net.Http
             private void Finish(HttpConnection connection)
             {
                 // We cannot reuse this connection, so close it.
-                if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                 _connection = null;
                 connection.Dispose();
             }
index f6f7b44..a946a7a 100644 (file)
@@ -47,7 +47,6 @@ namespace System.Net.Http
                 if (_contentBytesRemaining == 0)
                 {
                     // End of response body
-                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                     _connection.CompleteResponse();
                     _connection = null;
                 }
@@ -110,7 +109,6 @@ namespace System.Net.Http
                 if (_contentBytesRemaining == 0)
                 {
                     // End of response body
-                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                     _connection.CompleteResponse();
                     _connection = null;
                 }
@@ -165,7 +163,6 @@ namespace System.Net.Http
 
             private void Finish()
             {
-                if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                 _contentBytesRemaining = 0;
                 _connection!.CompleteResponse();
                 _connection = null;
index 0635de4..8671947 100644 (file)
@@ -351,7 +351,7 @@ namespace System.Net.Http
                     _creditWaiter = null;
                 }
 
-                if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestStop();
+                if (HttpTelemetry.Log.IsEnabled()) _request.OnStopped();
             }
 
             private void Cancel()
@@ -387,7 +387,7 @@ namespace System.Net.Http
                     _waitSource.SetResult(true);
                 }
 
-                if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestAborted();
+                if (HttpTelemetry.Log.IsEnabled()) _request.OnAborted();
             }
 
             // Returns whether the waiter should be signalled or not.
@@ -1147,6 +1147,10 @@ namespace System.Net.Http
                 {
                     Cancel();
                 }
+                else
+                {
+                    _request.OnStopped();
+                }
 
                 _responseBuffer.Dispose();
             }
index 131af80..ac88a2e 100644 (file)
@@ -90,6 +90,8 @@ namespace System.Net.Http
             if (NetEventSource.Log.IsEnabled()) TraceConnection(_stream);
         }
 
+        ~HttpConnection() => Dispose(disposing: false);
+
         public void Dispose() => Dispose(disposing: true);
 
         protected void Dispose(bool disposing)
@@ -100,6 +102,9 @@ namespace System.Net.Http
             {
                 if (NetEventSource.Log.IsEnabled()) Trace("Connection closing.");
                 _pool.DecrementConnectionCount();
+
+                if (HttpTelemetry.Log.IsEnabled()) _currentRequest?.OnAborted();
+
                 if (disposing)
                 {
                     GC.SuppressFinalize(this);
@@ -630,7 +635,6 @@ namespace System.Net.Http
                 Stream responseStream;
                 if (ReferenceEquals(normalizedMethod, HttpMethod.Head) || response.StatusCode == HttpStatusCode.NoContent || response.StatusCode == HttpStatusCode.NotModified)
                 {
-                    if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestStop();
                     responseStream = EmptyReadStream.Instance;
                     CompleteResponse();
                 }
@@ -653,7 +657,6 @@ namespace System.Net.Http
                     long contentLength = response.Content.Headers.ContentLength.GetValueOrDefault();
                     if (contentLength <= 0)
                     {
-                        if (HttpTelemetry.Log.IsEnabled()) HttpTelemetry.Log.RequestStop();
                         responseStream = EmptyReadStream.Instance;
                         CompleteResponse();
                     }
@@ -1850,6 +1853,8 @@ namespace System.Net.Http
             Debug.Assert(_currentRequest != null, "Expected the connection to be associated with a request.");
             Debug.Assert(_writeOffset == 0, "Everything in write buffer should have been flushed.");
 
+            if (HttpTelemetry.Log.IsEnabled()) _currentRequest.OnStopped();
+
             // Disassociate the connection from a request.
             _currentRequest = null;
 
@@ -1963,13 +1968,4 @@ namespace System.Net.Http
                 memberName,                          // method name
                 message);                            // message
     }
-
-    internal sealed class HttpConnectionWithFinalizer : HttpConnection
-    {
-        public HttpConnectionWithFinalizer(HttpConnectionPool pool, Connection connection, TransportContext? transportContext) : base(pool, connection, transportContext) { }
-
-        // This class is separated from HttpConnection so we only pay the price of having a finalizer
-        // when it's actually needed, e.g. when MaxConnectionsPerServer is enabled.
-        ~HttpConnectionWithFinalizer() => Dispose(disposing: false);
-    }
 }
index e2c2e36..e6644c1 100644 (file)
@@ -1238,9 +1238,7 @@ namespace System.Net.Http
 
         private HttpConnection ConstructHttp11Connection(Connection connection, TransportContext? transportContext)
         {
-            return _maxConnections == int.MaxValue ?
-                new HttpConnection(this, connection, transportContext) :
-                new HttpConnectionWithFinalizer(this, connection, transportContext); // finalizer needed to signal the pool when a connection is dropped
+            return new HttpConnection(this, connection, transportContext);
         }
 
         // Returns the established stream or an HttpResponseMessage from the proxy indicating failure.
index 6790613..06575e4 100644 (file)
@@ -354,20 +354,22 @@ namespace System.Net.Http
                 request.RequestUri.PathAndQuery,
                 request.Version.Major,
                 request.Version.Minor);
+
+            request.MarkAsTrackedByTelemetry();
+
             try
             {
                 return await SendAsyncHelper(request, async, doRequestAuth, cancellationToken).ConfigureAwait(false);
             }
-            catch (Exception e) when (LogException(e))
+            catch when (LogException(request))
             {
                 // This code should never run.
                 throw;
             }
 
-            static bool LogException(Exception e)
+            static bool LogException(HttpRequestMessage request)
             {
-                HttpTelemetry.Log.RequestAborted();
-                HttpTelemetry.Log.RequestStop();
+                request.OnAborted();
 
                 // Returning false means the catch handler isn't run.
                 // So the exception isn't considered to be caught so it will now propagate up the stack.
index 7530988..c5da3ef 100644 (file)
@@ -1,17 +1,12 @@
 // Licensed to the .NET Foundation under one or more agreements.
 // The .NET Foundation licenses this file to you under the MIT license.
 
-using System.Threading;
-
 namespace System.Net.Http
 {
     internal abstract class HttpContentStream : HttpBaseStream
     {
         protected HttpConnection? _connection;
 
-        // Makes sure we don't call HttpTelemetry events more than once.
-        private int _requestStopCalled; // 0==no, 1==yes
-
         public HttpContentStream(HttpConnection connection)
         {
             _connection = connection;
@@ -45,14 +40,6 @@ namespace System.Net.Http
                 ThrowObjectDisposedException();
         }
 
-        protected void LogRequestStop()
-        {
-            if (Interlocked.Exchange(ref _requestStopCalled, 1) == 0)
-            {
-                HttpTelemetry.Log.RequestStop();
-            }
-        }
-
         private HttpConnection ThrowObjectDisposedException() => throw new ObjectDisposedException(GetType().Name);
     }
 }
index 33b1935..b1f8bd9 100644 (file)
@@ -33,7 +33,6 @@ namespace System.Net.Http
                 if (bytesRead == 0)
                 {
                     // We cannot reuse this connection, so close it.
-                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                     _connection = null;
                     connection.Dispose();
                 }
@@ -81,7 +80,6 @@ namespace System.Net.Http
                     CancellationHelper.ThrowIfCancellationRequested(cancellationToken);
 
                     // We cannot reuse this connection, so close it.
-                    if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                     _connection = null;
                     connection.Dispose();
                 }
@@ -143,7 +141,6 @@ namespace System.Net.Http
             private void Finish(HttpConnection connection)
             {
                 // We cannot reuse this connection, so close it.
-                if (HttpTelemetry.Log.IsEnabled()) LogRequestStop();
                 connection.Dispose();
                 _connection = null;
             }
index 9a5928a..baea536 100644 (file)
     <Compile Include="$(CommonTestPath)System\Net\Http\SchSendAuxRecordHttpTest.cs"
              Link="Common\System\Net\Http\SchSendAuxRecordHttpTest.cs" />
     <Compile Include="SyncHttpHandlerTest.cs" />
+    <Compile Include="TelemetryTest.cs" />
     <Compile Include="StreamContentTest.cs" />
     <Compile Include="StringContentTest.cs" />
     <Compile Include="$(CommonTestPath)System\Net\Http\SyncBlockingContent.cs"
diff --git a/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs b/src/libraries/System.Net.Http/tests/FunctionalTests/TelemetryTest.cs
new file mode 100644 (file)
index 0000000..89dc6ac
--- /dev/null
@@ -0,0 +1,178 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+using System.Collections.Concurrent;
+using System.Collections.Generic;
+using System.Diagnostics.Tracing;
+using System.Linq;
+using System.Threading;
+using System.Threading.Tasks;
+using Microsoft.DotNet.RemoteExecutor;
+using Xunit;
+using Xunit.Abstractions;
+
+namespace System.Net.Http.Functional.Tests
+{
+    public sealed class TelemetryTest_Http11 : TelemetryTest
+    {
+        public TelemetryTest_Http11(ITestOutputHelper output) : base(output) { }
+    }
+
+    public sealed class TelemetryTest_Http20 : TelemetryTest
+    {
+        public TelemetryTest_Http20(ITestOutputHelper output) : base(output) { }
+    }
+
+    public abstract class TelemetryTest : HttpClientHandlerTestBase
+    {
+        public TelemetryTest(ITestOutputHelper output) : base(output) { }
+
+        [Fact]
+        public static void EventSource_ExistsWithCorrectId()
+        {
+            Type esType = typeof(HttpClient).Assembly.GetType("System.Net.Http.HttpTelemetry", throwOnError: true, ignoreCase: false);
+            Assert.NotNull(esType);
+
+            Assert.Equal("System.Net.Http", EventSource.GetName(esType));
+            Assert.Equal(Guid.Parse("d30b5633-7ef1-5485-b4e0-94979b102068"), EventSource.GetGuid(esType));
+
+            Assert.NotEmpty(EventSource.GenerateManifest(esType, esType.Assembly.Location));
+        }
+
+        [OuterLoop]
+        [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))]
+        public void EventSource_SuccessfulRequest_LogsStartStop()
+        {
+            RemoteExecutor.Invoke(async useVersionString =>
+            {
+                using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
+
+                var events = new ConcurrentQueue<EventWrittenEventArgs>();
+                await listener.RunWithCallbackAsync(events.Enqueue, async () =>
+                {
+                    await GetFactoryForVersion(Version.Parse(useVersionString)).CreateClientAndServerAsync(
+                        async uri =>
+                        {
+                            using HttpClient client = CreateHttpClient(useVersionString);
+                            await client.GetStringAsync(uri);
+                        },
+                        async server =>
+                        {
+                            await server.AcceptConnectionAsync(async connection =>
+                            {
+                                await Task.Delay(300);
+                                await connection.ReadRequestDataAsync();
+                                await connection.SendResponseAsync();
+                            });
+                        });
+
+                    await Task.Delay(300);
+                });
+                Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself
+
+                EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "RequestStart");
+                ValidateStartEventPayload(start);
+
+                EventWrittenEventArgs stop = Assert.Single(events, e => e.EventName == "RequestStop");
+                Assert.Equal(0, stop.Payload.Count);
+
+                Assert.DoesNotContain(events, e => e.EventName == "RequestAborted");
+
+                VerifyEventCounters(events, shouldHaveFailures: false);
+            }, UseVersion.ToString()).Dispose();
+        }
+
+        [OuterLoop]
+        [ConditionalFact(typeof(RemoteExecutor), nameof(RemoteExecutor.IsSupported))]
+        public void EventSource_UnsuccessfulRequest_LogsStartAbortedStop()
+        {
+            RemoteExecutor.Invoke(async useVersionString =>
+            {
+                using var listener = new TestEventListener("System.Net.Http", EventLevel.Verbose, eventCounterInterval: 0.1d);
+
+                var events = new ConcurrentQueue<EventWrittenEventArgs>();
+                await listener.RunWithCallbackAsync(events.Enqueue, async () =>
+                {
+                    var semaphore = new SemaphoreSlim(0, 1);
+                    var cts = new CancellationTokenSource();
+
+                    await GetFactoryForVersion(Version.Parse(useVersionString)).CreateClientAndServerAsync(
+                        async uri =>
+                        {
+                            using HttpClient client = CreateHttpClient(useVersionString);
+                            await Assert.ThrowsAsync<TaskCanceledException>(async () => await client.GetStringAsync(uri, cts.Token));
+                            semaphore.Release();
+                        },
+                        async server =>
+                        {
+                            await server.AcceptConnectionAsync(async connection =>
+                            {
+                                cts.CancelAfter(TimeSpan.FromMilliseconds(300));
+                                Assert.True(await semaphore.WaitAsync(TimeSpan.FromSeconds(5)));
+                                connection.Dispose();
+                            });
+                        });
+
+                    await Task.Delay(300);
+                });
+                Assert.DoesNotContain(events, ev => ev.EventId == 0); // errors from the EventSource itself
+
+                EventWrittenEventArgs start = Assert.Single(events, e => e.EventName == "RequestStart");
+                ValidateStartEventPayload(start);
+
+                EventWrittenEventArgs abort = Assert.Single(events, e => e.EventName == "RequestAborted");
+                Assert.Equal(0, abort.Payload.Count);
+
+                EventWrittenEventArgs stop = Assert.Single(events, e => e.EventName == "RequestStop");
+                Assert.Equal(0, stop.Payload.Count);
+
+                VerifyEventCounters(events, shouldHaveFailures: true);
+            }, UseVersion.ToString()).Dispose();
+        }
+
+        private static void ValidateStartEventPayload(EventWrittenEventArgs startEvent)
+        {
+            Assert.Equal("RequestStart", startEvent.EventName);
+            Assert.Equal(6, startEvent.Payload.Count);
+
+            Assert.Equal("http", (string)startEvent.Payload[0]);
+            Assert.NotEmpty((string)startEvent.Payload[1]); // host
+            Assert.True(startEvent.Payload[2] is int port && port >= 0 && port <= 65535);
+            Assert.NotEmpty((string)startEvent.Payload[3]); // pathAndQuery
+            Assert.True(startEvent.Payload[4] is int versionMajor && (versionMajor == 1 || versionMajor == 2));
+            Assert.True(startEvent.Payload[5] is int versionMinor && (versionMinor == 1 || versionMinor == 0));
+        }
+
+        private static void VerifyEventCounters(ConcurrentQueue<EventWrittenEventArgs> events, bool shouldHaveFailures)
+        {
+            Dictionary<string, double[]> eventCounters = events
+                .Where(e => e.EventName == "EventCounters")
+                .Select(e => (IDictionary<string, object>)e.Payload.Single())
+                .GroupBy(d => (string)d["Name"], d => (double)(d.ContainsKey("Mean") ? d["Mean"] : d["Increment"]))
+                .ToDictionary(p => p.Key, p => p.ToArray());
+
+            Assert.True(eventCounters.TryGetValue("requests-started", out double[] requestsStarted));
+            Assert.Equal(1, requestsStarted[^1]);
+
+            Assert.True(eventCounters.TryGetValue("requests-started-rate", out double[] requestRate));
+            Assert.Contains(requestRate, r => r > 0);
+
+            Assert.True(eventCounters.TryGetValue("requests-aborted", out double[] requestsAborted));
+            Assert.True(eventCounters.TryGetValue("requests-aborted-rate", out double[] requestsAbortedRate));
+            if (shouldHaveFailures)
+            {
+                Assert.Equal(1, requestsAborted[^1]);
+                Assert.Contains(requestsAbortedRate, r => r > 0);
+            }
+            else
+            {
+                Assert.All(requestsAborted, a => Assert.Equal(0, a));
+                Assert.All(requestsAbortedRate, r => Assert.Equal(0, r));
+            }
+
+            Assert.True(eventCounters.TryGetValue("current-requests", out double[] currentRequests));
+            Assert.Contains(currentRequests, c => c > 0);
+            Assert.Equal(0, currentRequests[^1]);
+        }
+    }
+}
diff --git a/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs b/src/libraries/System.Net.Http/tests/UnitTests/Fakes/HttpTelemetry.cs
new file mode 100644 (file)
index 0000000..e6ca982
--- /dev/null
@@ -0,0 +1,16 @@
+// Licensed to the .NET Foundation under one or more agreements.
+// The .NET Foundation licenses this file to you under the MIT license.
+
+namespace System.Net.Http
+{
+    public class HttpTelemetry
+    {
+        public static readonly HttpTelemetry Log = new HttpTelemetry();
+
+        public bool IsEnabled() => false;
+
+        public void RequestStop() { }
+
+        public void RequestAborted() { }
+    }
+}
index 19de137..6bf7e93 100644 (file)
              Link="ProductionCode\System\Net\Http\HttpHandlerDefaults.cs" />
     <Compile Include="DigestAuthenticationTests.cs" />
     <Compile Include="Fakes\HttpClientHandler.cs" />
+    <Compile Include="Fakes\HttpTelemetry.cs" />
     <Compile Include="Fakes\MacProxy.cs" Condition=" ('$(TargetsOSX)' == 'true' or '$(TargetsiOS)' == 'true' or '$(TargetstvOS)' == 'true') and '$(TargetFramework)' == '$(NetCoreAppCurrent)'" />
     <Compile Include="Headers\AltSvcHeaderParserTest.cs" />
     <Compile Include="Headers\AuthenticationHeaderValueTest.cs" />