From 053052d4053843247b8ace6b8d27e676822e5e00 Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Thu, 8 Oct 2020 11:47:48 -0700 Subject: [PATCH] Remove KestrelEventSource events with broken ActivityId tracking (#26684) * Remove KestrelEventSource events with broken ActivityId tracking * Skip test requiring ALPN on macOS --- .../Infrastructure/KestrelEventSource.cs | 88 ---- .../FunctionalTests/Http2/HandshakeTests.cs | 6 +- .../FunctionalTests/Http2/ShutdownTests.cs | 2 +- .../EventSourceTests.cs | 492 ++++++++++++++++-- .../Http2/TlsTests.cs | 2 +- .../HttpsConnectionMiddlewareTests.cs | 2 +- .../Interop.FunctionalTests/ChromeTests.cs | 2 +- .../test/Interop.FunctionalTests/Utilities.cs | 2 +- 8 files changed, 459 insertions(+), 137 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs index 898376d5df97..d392346da161 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelEventSource.cs @@ -144,54 +144,12 @@ public void ConnectionRejected(string connectionId) public void ConnectionQueuedStart(BaseConnectionContext connection) { Interlocked.Increment(ref _connectionQueueLength); - if (IsEnabled()) - { - ConnectionQueuedStart( - connection.ConnectionId, - connection.LocalEndPoint?.ToString(), - connection.RemoteEndPoint?.ToString()); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(6, Level = EventLevel.Informational)] - private void ConnectionQueuedStart(string connectionId, - string localEndPoint, - string remoteEndPoint) - { - WriteEvent( - 6, - connectionId, - localEndPoint, - remoteEndPoint - ); } [NonEvent] public void ConnectionQueuedStop(BaseConnectionContext connection) { Interlocked.Decrement(ref _connectionQueueLength); - if (IsEnabled()) - { - ConnectionQueuedStop( - connection.ConnectionId, - connection.LocalEndPoint?.ToString(), - connection.RemoteEndPoint?.ToString()); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(7, Level = EventLevel.Informational)] - private void ConnectionQueuedStop(string connectionId, - string localEndPoint, - string remoteEndPoint) - { - WriteEvent( - 7, - connectionId, - localEndPoint, - remoteEndPoint - ); } [NonEvent] @@ -245,70 +203,24 @@ public void TlsHandshakeFailed(string connectionId) public void RequestQueuedStart(HttpProtocol httpProtocol, string httpVersion) { Interlocked.Increment(ref _httpRequestQueueLength); - // avoid allocating the trace identifier unless logging is enabled - if (IsEnabled()) - { - RequestQueuedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(11, Level = EventLevel.Informational)] - private void RequestQueuedStart(string connectionId, string requestId, string httpVersion) - { - WriteEvent(11, connectionId, requestId, httpVersion); } [NonEvent] public void RequestQueuedStop(HttpProtocol httpProtocol, string httpVersion) { Interlocked.Decrement(ref _httpRequestQueueLength); - // avoid allocating the trace identifier unless logging is enabled - if (IsEnabled()) - { - RequestQueuedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpVersion); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(12, Level = EventLevel.Informational)] - private void RequestQueuedStop(string connectionId, string requestId, string httpVersion) - { - WriteEvent(12, connectionId, requestId, httpVersion); } [NonEvent] public void RequestUpgradedStart(HttpProtocol httpProtocol) { Interlocked.Increment(ref _currentUpgradedHttpRequests); - if (IsEnabled()) - { - RequestUpgradedStart(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(13, Level = EventLevel.Informational)] - private void RequestUpgradedStart(string connectionId, string requestId, string httpVersion, string path, string method) - { - WriteEvent(13, connectionId, requestId, httpVersion, path, method); } [NonEvent] public void RequestUpgradedStop(HttpProtocol httpProtocol) { Interlocked.Decrement(ref _currentUpgradedHttpRequests); - if (IsEnabled()) - { - RequestUpgradedStop(httpProtocol.ConnectionIdFeature, httpProtocol.TraceIdentifier, httpProtocol.HttpVersion, httpProtocol.Path, httpProtocol.MethodText); - } - } - - [MethodImpl(MethodImplOptions.NoInlining)] - [Event(14, Level = EventLevel.Informational)] - private void RequestUpgradedStop(string connectionId, string requestId, string httpVersion, string path, string method) - { - WriteEvent(14, connectionId, requestId, httpVersion, path, method); } protected override void OnEventCommand(EventCommandEventArgs command) diff --git a/src/Servers/Kestrel/test/FunctionalTests/Http2/HandshakeTests.cs b/src/Servers/Kestrel/test/FunctionalTests/Http2/HandshakeTests.cs index c2e1917bea0c..2c28ba950a76 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/Http2/HandshakeTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/Http2/HandshakeTests.cs @@ -36,7 +36,7 @@ public HandshakeTests() [ConditionalFact] [OSSkipCondition(OperatingSystems.Linux | OperatingSystems.Windows)] - // Mac SslStream is missing ALPN support: https://github.com/dotnet/corefx/issues/30492 + // Mac SslStream is missing ALPN support: https://github.com/dotnet/runtime/issues/27727 public void TlsAndHttp2NotSupportedOnMac() { var ex = Assert.Throws(() => new TestServer(context => @@ -79,7 +79,7 @@ public void TlsAndHttp2NotSupportedOnWin7() } [ConditionalFact] - [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492")] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10)] public async Task TlsAlpnHandshakeSelectsHttp2From1and2() { @@ -107,7 +107,7 @@ public async Task TlsAlpnHandshakeSelectsHttp2From1and2() } [ConditionalFact] - [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492")] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10)] public async Task TlsAlpnHandshakeSelectsHttp2() { diff --git a/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs b/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs index 99606310d500..25b8fdf13a5a 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs @@ -21,7 +21,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests.Http2 { - [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492")] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10)] public class ShutdownTests : TestApplicationErrorLoggerLoggedTest { diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/EventSourceTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/EventSourceTests.cs index 2fb46cc0f127..372362d720cd 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/EventSourceTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/EventSourceTests.cs @@ -1,108 +1,518 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. +using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics.Tracing; +using System.IO; using System.Linq; +using System.Net.Http; +using System.Net.Security; +using System.Security.Authentication; +using System.Security.Cryptography.X509Certificates; +using System.Text.Json; +using System.Threading; using System.Threading.Tasks; +using Microsoft.AspNetCore.Connections; +using Microsoft.AspNetCore.Hosting; using Microsoft.AspNetCore.Http.Features; +using Microsoft.AspNetCore.Server.Kestrel.Core; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.TestTransport; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging; using Xunit; namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests { public class EventSourceTests : LoggedTest { - private readonly TestEventListener _listener = new TestEventListener(); + private static readonly X509Certificate2 _x509Certificate2 = TestResources.GetTestCertificate(); - public EventSourceTests() - { - _listener.EnableEvents(KestrelEventSource.Log, EventLevel.Verbose); - } + // To log all KestrelEventSource events, add `_listener = new TestEventListener(Logger);` to the start of the test method. + // We could always construct TestEventListener with the test logger, but other concurrent tests could make this noisy. + private TestEventListener _listener = new TestEventListener(); [Fact] - public async Task EmitsConnectionStartAndStop() + public async Task Http1_EmitsStartAndStopEventsWithActivityIds() { + int port; string connectionId = null; - string requestId = null; + + const int requestsToSend = 2; + var requestIds = new string[requestsToSend]; + var requestsReceived = 0; + + await using (var server = new TestServer(async context => + { + connectionId = context.Features.Get().ConnectionId; + requestIds[requestsReceived++] = context.TraceIdentifier; + + var upgradeFeature = context.Features.Get(); + + if (upgradeFeature.IsUpgradableRequest) + { + await upgradeFeature.UpgradeAsync(); + } + }, + new TestServiceContext(LoggerFactory))) + { + port = server.Port; + + using var connection = server.CreateConnection(); + + await connection.SendEmptyGet(); + await connection.Receive( + "HTTP/1.1 200 OK", + $"Date: {server.Context.DateHeaderValue}", + "Content-Length: 0", + "", + ""); + + await connection.SendEmptyGetWithUpgrade(); + await connection.ReceiveEnd("HTTP/1.1 101 Switching Protocols", + "Connection: Upgrade", + $"Date: {server.Context.DateHeaderValue}", + "", + ""); + } + + Assert.NotNull(connectionId); + Assert.Equal(2, requestsReceived); + + // Other tests executing in parallel may log events. + var events = _listener.EventData.Where(e => e != null && GetProperty(e, "connectionId") == connectionId).ToList(); + var eventIndex = 0; + + var connectionStart = events[eventIndex++]; + Assert.Equal("ConnectionStart", connectionStart.EventName); + Assert.Equal(1, connectionStart.EventId); + Assert.All(new[] { "connectionId", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, connectionStart.PayloadNames)); + Assert.Equal($"127.0.0.1:{port}", GetProperty(connectionStart, "localEndPoint")); + Assert.Same(KestrelEventSource.Log, connectionStart.EventSource); + Assert.NotEqual(Guid.Empty, connectionStart.ActivityId); + + var firstRequestStart = events[eventIndex++]; + Assert.Equal("RequestStart", firstRequestStart.EventName); + Assert.Equal(3, firstRequestStart.EventId); + Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, firstRequestStart.PayloadNames)); + Assert.Equal(requestIds[0], GetProperty(firstRequestStart, "requestId")); + Assert.Same(KestrelEventSource.Log, firstRequestStart.EventSource); + Assert.NotEqual(Guid.Empty, firstRequestStart.ActivityId); + Assert.Equal(connectionStart.ActivityId, firstRequestStart.RelatedActivityId); + + var firstRequestStop = events[eventIndex++]; + Assert.Equal("RequestStop", firstRequestStop.EventName); + Assert.Equal(4, firstRequestStop.EventId); + Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, firstRequestStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, firstRequestStop.EventSource); + Assert.Equal(requestIds[0], GetProperty(firstRequestStop, "requestId")); + Assert.Equal(firstRequestStart.ActivityId, firstRequestStop.ActivityId); + Assert.Equal(Guid.Empty, firstRequestStop.RelatedActivityId); + + var secondRequestStart = events[eventIndex++]; + Assert.Equal("RequestStart", secondRequestStart.EventName); + Assert.Equal(3, secondRequestStart.EventId); + Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, secondRequestStart.PayloadNames)); + Assert.Equal(requestIds[1], GetProperty(secondRequestStart, "requestId")); + Assert.Same(KestrelEventSource.Log, secondRequestStart.EventSource); + Assert.NotEqual(Guid.Empty, secondRequestStart.ActivityId); + Assert.Equal(connectionStart.ActivityId, secondRequestStart.RelatedActivityId); + + var secondRequestStop = events[eventIndex++]; + Assert.Equal("RequestStop", secondRequestStop.EventName); + Assert.Equal(4, secondRequestStop.EventId); + Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, secondRequestStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, secondRequestStop.EventSource); + Assert.Equal(requestIds[1], GetProperty(secondRequestStop, "requestId")); + Assert.Equal(secondRequestStart.ActivityId, secondRequestStop.ActivityId); + Assert.Equal(Guid.Empty, secondRequestStop.RelatedActivityId); + + var connectionStop = events[eventIndex++]; + Assert.Equal("ConnectionStop", connectionStop.EventName); + Assert.Equal(2, connectionStop.EventId); + Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, connectionStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, connectionStop.EventSource); + Assert.Equal(connectionStart.ActivityId, connectionStop.ActivityId); + Assert.Equal(Guid.Empty, connectionStop.RelatedActivityId); + + Assert.Equal(eventIndex, events.Count); + } + + [ConditionalFact] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] + [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10)] + public async Task Http2_EmitsStartAndStopEventsWithActivityIds() + { int port; + string connectionId = null; + + const int requestsToSend = 2; + var requestIds = new string[requestsToSend]; + var requestsReceived = 0; + await using (var server = new TestServer(context => { connectionId = context.Features.Get().ConnectionId; - requestId = context.TraceIdentifier; + requestIds[requestsReceived++] = context.TraceIdentifier; return Task.CompletedTask; - }, new TestServiceContext(LoggerFactory))) + }, + new TestServiceContext(LoggerFactory), + listenOptions => + { + listenOptions.UseHttps(_x509Certificate2); + listenOptions.Protocols = HttpProtocols.Http2; + })) { port = server.Port; - using (var connection = server.CreateConnection()) + + using var connection = server.CreateConnection(); + + using var socketsHandler = new SocketsHttpHandler() { - await connection.SendAll("GET / HTTP/1.1", - "Host:", - "", - "") - .DefaultTimeout(); - await connection.Receive("HTTP/1.1 200"); + ConnectCallback = (_, _) => + { + // This test should only require a single connection. + if (connectionId != null) + { + throw new InvalidOperationException(); + } + + return new ValueTask(connection.Stream); + }, + SslOptions = new SslClientAuthenticationOptions + { + RemoteCertificateValidationCallback = (_, _, _, _) => true + } + }; + + using var httpClient = new HttpClient(socketsHandler); + + for (int i = 0; i < requestsToSend; i++) + { + using var httpRequestMessage = new HttpRequestMessage() + { + RequestUri = new Uri("https://localhost/"), + Version = new Version(2, 0), + VersionPolicy = HttpVersionPolicy.RequestVersionExact, + }; + + using var responseMessage = await httpClient.SendAsync(httpRequestMessage); + responseMessage.EnsureSuccessStatusCode(); } } - // capture list here as other tests executing in parallel may log events Assert.NotNull(connectionId); - Assert.NotNull(requestId); + Assert.Equal(2, requestsReceived); + // Other tests executing in parallel may log events. var events = _listener.EventData.Where(e => e != null && GetProperty(e, "connectionId") == connectionId).ToList(); + var eventIndex = 0; + var connectionStart = events[eventIndex++]; + Assert.Equal("ConnectionStart", connectionStart.EventName); + Assert.Equal(1, connectionStart.EventId); + Assert.All(new[] { "connectionId", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, connectionStart.PayloadNames)); + Assert.Same(KestrelEventSource.Log, connectionStart.EventSource); + Assert.Equal($"127.0.0.1:{port}", GetProperty(connectionStart, "localEndPoint")); + Assert.NotEqual(Guid.Empty, connectionStart.ActivityId); + + var tlsHandshakeStart = events[eventIndex++]; + Assert.Equal("TlsHandshakeStart", tlsHandshakeStart.EventName); + Assert.Equal(8, tlsHandshakeStart.EventId); + Assert.All(new[] { "connectionId", "sslProtocols" }, p => Assert.Contains(p, tlsHandshakeStart.PayloadNames)); + Assert.Same(KestrelEventSource.Log, tlsHandshakeStart.EventSource); + Assert.NotEqual(Guid.Empty, tlsHandshakeStart.ActivityId); + Assert.Equal(connectionStart.ActivityId, tlsHandshakeStart.RelatedActivityId); + + var tlsHandshakeStop = events[eventIndex++]; + Assert.Equal("TlsHandshakeStop", tlsHandshakeStop.EventName); + Assert.Equal(9, tlsHandshakeStop.EventId); + Assert.All(new[] { "connectionId", "sslProtocols", "applicationProtocol", "hostName" }, p => Assert.Contains(p, tlsHandshakeStop.PayloadNames)); + Assert.Equal("h2", GetProperty(tlsHandshakeStop, "applicationProtocol")); + Assert.Same(KestrelEventSource.Log, tlsHandshakeStop.EventSource); + Assert.Equal(tlsHandshakeStart.ActivityId, tlsHandshakeStop.ActivityId); + Assert.Equal(Guid.Empty, tlsHandshakeStop.RelatedActivityId); + + for (int i = 0; i < requestsToSend; i++) { - var start = Assert.Single(events, e => e.EventName == "ConnectionStart"); - Assert.All(new[] { "connectionId", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, start.PayloadNames)); - Assert.Equal($"127.0.0.1:{port}", GetProperty(start, "localEndPoint")); + var requestStart = events[eventIndex++]; + Assert.Equal("RequestStart", requestStart.EventName); + Assert.Equal(3, requestStart.EventId); + Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, requestStart.PayloadNames)); + Assert.Equal(requestIds[i], GetProperty(requestStart, "requestId")); + Assert.Same(KestrelEventSource.Log, requestStart.EventSource); + Assert.NotEqual(Guid.Empty, requestStart.ActivityId); + Assert.Equal(connectionStart.ActivityId, requestStart.RelatedActivityId); + + var requestStop = events[eventIndex++]; + Assert.Equal("RequestStop", requestStop.EventName); + Assert.Equal(4, requestStop.EventId); + Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, requestStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, requestStop.EventSource); + Assert.Equal(requestIds[i], GetProperty(requestStop, "requestId")); + Assert.Equal(requestStart.ActivityId, requestStop.ActivityId); + Assert.Equal(Guid.Empty, requestStop.RelatedActivityId); } + + var connectionStop = events[eventIndex++]; + Assert.Equal("ConnectionStop", connectionStop.EventName); + Assert.Equal(2, connectionStop.EventId); + Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, connectionStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, connectionStop.EventSource); + Assert.Equal(connectionStart.ActivityId, connectionStop.ActivityId); + Assert.Equal(Guid.Empty, connectionStop.RelatedActivityId); + + Assert.Equal(eventIndex, events.Count); + } + + [Fact] + public async Task TlsHandshakeFailure_EmitsStartAndStopEventsWithActivityIds() + { + int port; + string connectionId = null; + + await using (var server = new TestServer(context => Task.CompletedTask, new TestServiceContext(LoggerFactory), + listenOptions => { - var stop = Assert.Single(events, e => e.EventName == "ConnectionStop"); - Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, stop.PayloadNames)); - Assert.Same(KestrelEventSource.Log, stop.EventSource); - } + listenOptions.Use(next => + { + return connectionContext => + { + connectionId = connectionContext.ConnectionId; + return next(connectionContext); + }; + }); + + listenOptions.UseHttps(_x509Certificate2); + })) { - var requestStart = Assert.Single(events, e => e.EventName == "RequestStart"); - Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, requestStart.PayloadNames)); - Assert.Equal(requestId, GetProperty(requestStart, "requestId")); - Assert.Same(KestrelEventSource.Log, requestStart.EventSource); + port = server.Port; + + using var connection = server.CreateConnection(); + await using var sslStream = new SslStream(connection.Stream); + + var clientAuthOptions = new SslClientAuthenticationOptions + { + TargetHost = "localhost", + + // Only enabling SslProtocols.Ssl2 should cause a handshake failure on all platforms. +#pragma warning disable CS0618 // Type or member is obsolete + EnabledSslProtocols = SslProtocols.Ssl2, +#pragma warning restore CS0618 // Type or member is obsolete + }; + + using var handshakeCts = new CancellationTokenSource(TestConstants.DefaultTimeout); + await Assert.ThrowsAnyAsync(() => sslStream.AuthenticateAsClientAsync(clientAuthOptions, handshakeCts.Token)); } + + Assert.NotNull(connectionId); + + // Other tests executing in parallel may log events. + var events = _listener.EventData.Where(e => e != null && GetProperty(e, "connectionId") == connectionId).ToList(); + var eventIndex = 0; + + var connectionStart = events[eventIndex++]; + Assert.Equal("ConnectionStart", connectionStart.EventName); + Assert.Equal(1, connectionStart.EventId); + Assert.All(new[] { "connectionId", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, connectionStart.PayloadNames)); + Assert.Equal($"127.0.0.1:{port}", GetProperty(connectionStart, "localEndPoint")); + Assert.Same(KestrelEventSource.Log, connectionStart.EventSource); + Assert.NotEqual(Guid.Empty, connectionStart.ActivityId); + + var tlsHandshakeStart = events[eventIndex++]; + Assert.Equal("TlsHandshakeStart", tlsHandshakeStart.EventName); + Assert.Equal(8, tlsHandshakeStart.EventId); + Assert.All(new[] { "connectionId", "sslProtocols" }, p => Assert.Contains(p, tlsHandshakeStart.PayloadNames)); + Assert.Same(KestrelEventSource.Log, tlsHandshakeStart.EventSource); + Assert.NotEqual(Guid.Empty, tlsHandshakeStart.ActivityId); + Assert.Equal(connectionStart.ActivityId, tlsHandshakeStart.RelatedActivityId); + + var tlsHandshakeFailed = events[eventIndex++]; + Assert.Equal("TlsHandshakeFailed", tlsHandshakeFailed.EventName); + Assert.Equal(10, tlsHandshakeFailed.EventId); + Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, tlsHandshakeFailed.PayloadNames)); + Assert.Same(KestrelEventSource.Log, tlsHandshakeFailed.EventSource); + Assert.Equal(tlsHandshakeStart.ActivityId, tlsHandshakeFailed.ActivityId); + Assert.Equal(Guid.Empty, tlsHandshakeFailed.RelatedActivityId); + + var tlsHandshakeStop = events[eventIndex++]; + Assert.Equal("TlsHandshakeStop", tlsHandshakeStop.EventName); + Assert.Equal(9, tlsHandshakeStop.EventId); + Assert.All(new[] { "connectionId", "sslProtocols", "applicationProtocol", "hostName" }, p => Assert.Contains(p, tlsHandshakeStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, tlsHandshakeStop.EventSource); + Assert.Equal(tlsHandshakeStart.ActivityId, tlsHandshakeStop.ActivityId); + Assert.Equal(Guid.Empty, tlsHandshakeStop.RelatedActivityId); + + var connectionStop = events[eventIndex++]; + Assert.Equal("ConnectionStop", connectionStop.EventName); + Assert.Equal(2, connectionStop.EventId); + Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, connectionStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, connectionStop.EventSource); + Assert.Equal(connectionStart.ActivityId, connectionStop.ActivityId); + Assert.Equal(Guid.Empty, connectionStop.RelatedActivityId); + + Assert.Equal(eventIndex, events.Count); + } + + [Fact] + public async Task ConnectionLimitExceeded_EmitsStartAndStopEventsWithActivityIds() + { + int port; + string connectionId = null; + + var serviceContext = new TestServiceContext(LoggerFactory); + + await using (var server = new TestServer(context => Task.CompletedTask, serviceContext, + listenOptions => { - var requestStop = Assert.Single(events, e => e.EventName == "RequestStop"); - Assert.All(new[] { "connectionId", "requestId" }, p => Assert.Contains(p, requestStop.PayloadNames)); - Assert.Equal(requestId, GetProperty(requestStop, "requestId")); - Assert.Same(KestrelEventSource.Log, requestStop.EventSource); + listenOptions.Use(next => + { + return connectionContext => + { + connectionId = connectionContext.ConnectionId; + return next(connectionContext); + }; + }); + + listenOptions.Use(next => + { + return new ConnectionLimitMiddleware(c => next(c), connectionLimit: 0, serviceContext.Log).OnConnectionAsync; + }); + })) + { + port = server.Port; + + using var connection = server.CreateConnection(); + await connection.ReceiveEnd(); } + + Assert.NotNull(connectionId); + + // Other tests executing in parallel may log events. + var events = _listener.EventData.Where(e => e != null && GetProperty(e, "connectionId") == connectionId).ToList(); + var eventIndex = 0; + + var connectionStart = events[eventIndex++]; + Assert.Equal("ConnectionStart", connectionStart.EventName); + Assert.Equal(1, connectionStart.EventId); + Assert.All(new[] { "connectionId", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, connectionStart.PayloadNames)); + Assert.Equal($"127.0.0.1:{port}", GetProperty(connectionStart, "localEndPoint")); + Assert.Same(KestrelEventSource.Log, connectionStart.EventSource); + Assert.NotEqual(Guid.Empty, connectionStart.ActivityId); + + var connectionRejected = events[eventIndex++]; + Assert.Equal("ConnectionRejected", connectionRejected.EventName); + Assert.Equal(5, connectionRejected.EventId); + Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, connectionRejected.PayloadNames)); + Assert.Same(KestrelEventSource.Log, connectionRejected.EventSource); + Assert.Equal(connectionStart.ActivityId, connectionRejected.ActivityId); + Assert.Equal(Guid.Empty, connectionRejected.RelatedActivityId); + + var connectionStop = events[eventIndex++]; + Assert.Equal("ConnectionStop", connectionStop.EventName); + Assert.Equal(2, connectionStop.EventId); + Assert.All(new[] { "connectionId" }, p => Assert.Contains(p, connectionStop.PayloadNames)); + Assert.Same(KestrelEventSource.Log, connectionStop.EventSource); + Assert.Equal(connectionStart.ActivityId, connectionStop.ActivityId); + Assert.Equal(Guid.Empty, connectionStop.RelatedActivityId); + + Assert.Equal(eventIndex, events.Count); } - private string GetProperty(EventWrittenEventArgs data, string propName) - => data.Payload[data.PayloadNames.IndexOf(propName)] as string; + private string GetProperty(EventSnapshot data, string propName) => data.Payload[propName]; private class TestEventListener : EventListener { - private volatile bool _disposed; - private ConcurrentQueue _events = new ConcurrentQueue(); + private readonly ConcurrentQueue _events = new ConcurrentQueue(); + private readonly ILogger _logger; + + private readonly object _disposeLock = new object(); + private bool _disposed; + + public TestEventListener() + { + EnableEvents(KestrelEventSource.Log, EventLevel.Verbose); + } + + public TestEventListener(ILogger logger) + : this() + { + _logger = logger; + } - public IEnumerable EventData => _events; + public IEnumerable EventData => _events; + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == "System.Threading.Tasks.TplEventSource") + { + // Enable TasksFlowActivityIds + EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)0x80); + } + } protected override void OnEventWritten(EventWrittenEventArgs eventData) { - if (!_disposed) + lock (_disposeLock) { - _events.Enqueue(eventData); + if (_disposed) + { + return; + } + + _logger?.LogInformation("{event}", JsonSerializer.Serialize(eventData, new JsonSerializerOptions + { + WriteIndented = true + })); + + // EventWrittenEventArgs.ActivityId sometimes falls back to EventSource.CurrentThreadActivityId, + // so we need to take a snapshot to verify the ActivityId later on a different thread. + // https://github.com/dotnet/runtime/blob/85162fbf9ccdeb4fa1df357f27308ae96579c066/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs#L4551 + _events.Enqueue(new EventSnapshot(eventData)); } } public override void Dispose() { - _disposed = true; + lock (_disposeLock) + { + _disposed = true; + } + base.Dispose(); } } + private class EventSnapshot + { + public EventSnapshot(EventWrittenEventArgs eventWrittenEventArgs) + { + EventName = eventWrittenEventArgs.EventName; + EventId = eventWrittenEventArgs.EventId; + EventSource = eventWrittenEventArgs.EventSource; + ActivityId = eventWrittenEventArgs.ActivityId; + RelatedActivityId = eventWrittenEventArgs.RelatedActivityId; + Payload = new Dictionary(eventWrittenEventArgs.PayloadNames.Count); + + for (int i = 0; i < eventWrittenEventArgs.PayloadNames.Count; i++) + { + Payload[eventWrittenEventArgs.PayloadNames[i]] = eventWrittenEventArgs.Payload[i] as string; + } + } + + public string EventName { get; } + public int EventId { get; } + public EventSource EventSource { get; } + public Guid ActivityId { get; } + public Guid RelatedActivityId { get; } + public Dictionary Payload { get; } + + public IEnumerable PayloadNames => Payload.Keys; + } + public override void Dispose() { _listener.Dispose(); diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/TlsTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/TlsTests.cs index 120958c0dfea..891a274bb621 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/TlsTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/TlsTests.cs @@ -21,7 +21,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests.Http2 { - [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492")] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10, SkipReason = "Missing Windows ALPN support: https://en.wikipedia.org/wiki/Application-Layer_Protocol_Negotiation#Support or incompatible ciphers on Windows 8.1")] public class TlsTests : LoggedTest diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpsConnectionMiddlewareTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpsConnectionMiddlewareTests.cs index 6ad3338e2aff..61fdb0586b0f 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpsConnectionMiddlewareTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpsConnectionMiddlewareTests.cs @@ -733,7 +733,7 @@ public void ThrowsForCertificatesMissingServerEku(string testCertName) [InlineData(HttpProtocols.Http1)] [InlineData(HttpProtocols.Http2)] [InlineData(HttpProtocols.Http1AndHttp2)] - [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492")] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win10)] public async Task ListenOptionsProtolsCanBeSetAfterUseHttps(HttpProtocols httpProtocols) { diff --git a/src/Servers/Kestrel/test/Interop.FunctionalTests/ChromeTests.cs b/src/Servers/Kestrel/test/Interop.FunctionalTests/ChromeTests.cs index 4e940a66bc09..0018f3b45370 100644 --- a/src/Servers/Kestrel/test/Interop.FunctionalTests/ChromeTests.cs +++ b/src/Servers/Kestrel/test/Interop.FunctionalTests/ChromeTests.cs @@ -64,7 +64,7 @@ private void InitializeArgs() } [ConditionalTheory(Skip = "Disabling while debugging. https://github.com/dotnet/aspnetcore-internal/issues/1363")] - [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492")] + [OSSkipCondition(OperatingSystems.MacOSX, SkipReason = "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727")] [MinimumOSVersion(OperatingSystems.Windows, WindowsVersions.Win81, SkipReason = "Missing Windows ALPN support: https://en.wikipedia.org/wiki/Application-Layer_Protocol_Negotiation#Support")] [InlineData("", "Interop HTTP/2 GET")] [InlineData("?TestMethod=POST", "Interop HTTP/2 POST")] diff --git a/src/Servers/Kestrel/test/Interop.FunctionalTests/Utilities.cs b/src/Servers/Kestrel/test/Interop.FunctionalTests/Utilities.cs index 21b18f8aee01..b995ee25d08d 100644 --- a/src/Servers/Kestrel/test/Interop.FunctionalTests/Utilities.cs +++ b/src/Servers/Kestrel/test/Interop.FunctionalTests/Utilities.cs @@ -11,7 +11,7 @@ internal static bool CurrentPlatformSupportsHTTP2OverTls() { return // "Missing Windows ALPN support: https://en.wikipedia.org/wiki/Application-Layer_Protocol_Negotiation#Support" or missing compatible ciphers (Win8.1) new MinimumOSVersionAttribute(OperatingSystems.Windows, WindowsVersions.Win10).IsMet - // "Missing SslStream ALPN support: https://github.com/dotnet/corefx/issues/30492" + // "Missing SslStream ALPN support: https://github.com/dotnet/runtime/issues/27727" && new OSSkipConditionAttribute(OperatingSystems.MacOSX).IsMet; } }