diff --git a/.vscode/tasks.json b/.vscode/tasks.json index 1a78cbd21b..b5ff23e775 100644 --- a/.vscode/tasks.json +++ b/.vscode/tasks.json @@ -21,7 +21,24 @@ "build", "${workspaceRoot}/KestrelHttpServer.sln" ], - "problemMatcher": "$msCompile" + "problemMatcher": "$msCompile", + // these have to defined here because of https://github.com/Microsoft/vscode/issues/20740 + "osx": { + "options": { + "env": { + // The location of .NET Framework reference assembiles. + // These may not be installed yet if you have not run build.sh. + "ReferenceAssemblyRoot": "${env.HOME}/.nuget/packages/netframeworkreferenceassemblies/4.6.1/content" + } + } + }, + "linux": { + "options": { + "env": { + "ReferenceAssemblyRoot": "${env.HOME}/.nuget/packages/netframeworkreferenceassemblies/4.6.1/content" + } + } + } }, { "taskName": "Compile: CodeGenerator", diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionHandler.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionHandler.cs index 9a346f1805..933e04b8ab 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionHandler.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/ConnectionHandler.cs @@ -1,25 +1,16 @@ // 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.IO.Pipelines; -using System.Threading; using Microsoft.AspNetCore.Hosting.Server; using Microsoft.AspNetCore.Server.Kestrel.Internal.Http; +using Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure; using Microsoft.AspNetCore.Server.Kestrel.Transport; namespace Microsoft.AspNetCore.Server.Kestrel.Internal { public class ConnectionHandler : IConnectionHandler { - // Base32 encoding - in ascii sort order for easy text based sorting - private static readonly string _encode32Chars = "0123456789ABCDEFGHIJKLMNOPQRSTUV"; - - // Seed the _lastConnectionId for this application instance with - // the number of 100-nanosecond intervals that have elapsed since 12:00:00 midnight, January 1, 0001 - // for a roughly increasing _requestId over restarts - private static long _lastConnectionId = DateTime.UtcNow.Ticks; - private readonly ServiceContext _serviceContext; private readonly IHttpApplication _application; @@ -34,7 +25,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal var inputPipe = connectionInfo.PipeFactory.Create(GetInputPipeOptions(connectionInfo.InputWriterScheduler)); var outputPipe = connectionInfo.PipeFactory.Create(GetOutputPipeOptions(connectionInfo.OutputWriterScheduler)); - var connectionId = GenerateConnectionId(Interlocked.Increment(ref _lastConnectionId)); + var connectionId = CorrelationIdGenerator.GetNextId(); var frameContext = new FrameContext { @@ -60,6 +51,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal OutputProducer = outputProducer }); + _serviceContext.Log.ConnectionStart(connectionId); + KestrelEventSource.Log.ConnectionStart(connection, connectionInfo); + // Since data cannot be added to the inputPipe by the transport until OnConnection returns, // Frame.RequestProcessingAsync is guaranteed to unblock the transport thread before calling // application code. @@ -97,32 +91,5 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal // null means that we have no back pressure return bufferSize ?? 0; } - - private static unsafe string GenerateConnectionId(long id) - { - // The following routine is ~310% faster than calling long.ToString() on x64 - // and ~600% faster than calling long.ToString() on x86 in tight loops of 1 million+ iterations - // See: https://github.com/aspnet/Hosting/pull/385 - - // stackalloc to allocate array on stack rather than heap - char* charBuffer = stackalloc char[13]; - - charBuffer[0] = _encode32Chars[(int)(id >> 60) & 31]; - charBuffer[1] = _encode32Chars[(int)(id >> 55) & 31]; - charBuffer[2] = _encode32Chars[(int)(id >> 50) & 31]; - charBuffer[3] = _encode32Chars[(int)(id >> 45) & 31]; - charBuffer[4] = _encode32Chars[(int)(id >> 40) & 31]; - charBuffer[5] = _encode32Chars[(int)(id >> 35) & 31]; - charBuffer[6] = _encode32Chars[(int)(id >> 30) & 31]; - charBuffer[7] = _encode32Chars[(int)(id >> 25) & 31]; - charBuffer[8] = _encode32Chars[(int)(id >> 20) & 31]; - charBuffer[9] = _encode32Chars[(int)(id >> 15) & 31]; - charBuffer[10] = _encode32Chars[(int)(id >> 10) & 31]; - charBuffer[11] = _encode32Chars[(int)(id >> 5) & 31]; - charBuffer[12] = _encode32Chars[(int)id & 31]; - - // string ctor overload that takes char* - return new string(charBuffer, 0, 13); - } } } diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs index e601f5f0a7..af5454f581 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/FrameConnection.cs @@ -73,6 +73,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal } } + public void OnConnectionClosed() + { + Log.ConnectionStop(ConnectionId); + KestrelEventSource.Log.ConnectionStop(this); + } + public async Task StopAsync() { await _frameStartedTcs.Task; diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.FeatureCollection.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.FeatureCollection.cs index bffde30a58..c1dada9715 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.FeatureCollection.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.FeatureCollection.cs @@ -19,7 +19,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http IHttpResponseFeature, IHttpUpgradeFeature, IHttpConnectionFeature, - IHttpRequestLifetimeFeature + IHttpRequestLifetimeFeature, + IHttpRequestIdentifierFeature { // NOTE: When feature interfaces are added to or removed from this Frame class implementation, // then the list of `implementedFeatures` in the generated code project MUST also be updated. @@ -75,188 +76,89 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http string IHttpRequestFeature.Protocol { - get - { - return HttpVersion; - } - - set - { - HttpVersion = value; - } + get => HttpVersion; + set => HttpVersion = value; } string IHttpRequestFeature.Scheme { - get - { - return Scheme ?? "http"; - } - - set - { - Scheme = value; - } + get => Scheme ?? "http"; + set => Scheme = value; } string IHttpRequestFeature.Method { - get - { - return Method; - } - - set - { - Method = value; - } + get => Method; + set => Method = value; } string IHttpRequestFeature.PathBase { - get - { - return PathBase ?? ""; - } - - set - { - PathBase = value; - } + get => PathBase ?? ""; + set => PathBase = value; } string IHttpRequestFeature.Path { - get - { - return Path; - } - - set - { - Path = value; - } + get => Path; + set => Path = value; } string IHttpRequestFeature.QueryString { - get - { - return QueryString; - } - - set - { - QueryString = value; - } + get => QueryString; + set => QueryString = value; } string IHttpRequestFeature.RawTarget { - get - { - return RawTarget; - } - set - { - RawTarget = value; - } + get => RawTarget; + set => RawTarget = value; } IHeaderDictionary IHttpRequestFeature.Headers { - get - { - return RequestHeaders; - } - - set - { - RequestHeaders = value; - } + get => RequestHeaders; + set => RequestHeaders = value; } Stream IHttpRequestFeature.Body { - get - { - return RequestBody; - } - - set - { - RequestBody = value; - } + get => RequestBody; + set => RequestBody = value; } int IHttpResponseFeature.StatusCode { - get - { - return StatusCode; - } - - set - { - StatusCode = value; - } + get => StatusCode; + set => StatusCode = value; } string IHttpResponseFeature.ReasonPhrase { - get - { - return ReasonPhrase; - } - - set - { - ReasonPhrase = value; - } + get => ReasonPhrase; + set => ReasonPhrase = value; } IHeaderDictionary IHttpResponseFeature.Headers { - get - { - return ResponseHeaders; - } - - set - { - ResponseHeaders = value; - } + get => ResponseHeaders; + set => ResponseHeaders = value; } Stream IHttpResponseFeature.Body { - get - { - return ResponseBody; - } - - set - { - ResponseBody = value; - } + get => ResponseBody; + set => ResponseBody = value; } CancellationToken IHttpRequestLifetimeFeature.RequestAborted { - get - { - return RequestAborted; - } - set - { - RequestAborted = value; - } + get => RequestAborted; + set => RequestAborted = value; } - bool IHttpResponseFeature.HasStarted - { - get { return HasResponseStarted; } - } + bool IHttpResponseFeature.HasStarted => HasResponseStarted; bool IHttpUpgradeFeature.IsUpgradableRequest => _upgrade; @@ -266,38 +168,44 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http IPAddress IHttpConnectionFeature.RemoteIpAddress { - get { return RemoteIpAddress; } - set { RemoteIpAddress = value; } + get => RemoteIpAddress; + set => RemoteIpAddress = value; } IPAddress IHttpConnectionFeature.LocalIpAddress { - get { return LocalIpAddress; } - set { LocalIpAddress = value; } + get => LocalIpAddress; + set => LocalIpAddress = value; } int IHttpConnectionFeature.RemotePort { - get { return RemotePort; } - set { RemotePort = value; } + get => RemotePort; + set => RemotePort = value; } int IHttpConnectionFeature.LocalPort { - get { return LocalPort; } - set { LocalPort = value; } + get => LocalPort; + set => LocalPort = value; } string IHttpConnectionFeature.ConnectionId { - get { return ConnectionIdFeature; } - set { ConnectionIdFeature = value; } + get => ConnectionIdFeature; + set => ConnectionIdFeature = value; + } + + string IHttpRequestIdentifierFeature.TraceIdentifier + { + get => TraceIdentifier; + set => TraceIdentifier = value; } object IFeatureCollection.this[Type key] { - get { return FastFeatureGet(key); } - set { FastFeatureSet(key, value); } + get => FastFeatureGet(key); + set => FastFeatureSet(key, value); } TFeature IFeatureCollection.Get() diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.Generated.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.Generated.cs index 160d110c54..a1caf15e33 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.Generated.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.Generated.cs @@ -47,10 +47,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http _currentIHttpRequestFeature = this; _currentIHttpResponseFeature = this; _currentIHttpUpgradeFeature = this; + _currentIHttpRequestIdentifierFeature = this; _currentIHttpRequestLifetimeFeature = this; _currentIHttpConnectionFeature = this; - _currentIHttpRequestIdentifierFeature = null; _currentIServiceProvidersFeature = null; _currentIHttpAuthenticationFeature = null; _currentIQueryFeature = null; diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.cs index e91ca62917..e5b10948e2 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/Frame.cs @@ -69,6 +69,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http protected HttpVersion _httpVersion; + private string _requestId; private int _remainingRequestHeadersBytesAllowed; private int _requestHeadersParsed; @@ -112,6 +113,24 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http protected string ConnectionId => _frameContext.ConnectionId; public string ConnectionIdFeature { get; set; } + + /// + /// The request id. + /// + public string TraceIdentifier + { + set => _requestId = value; + get + { + // don't generate an ID until it is requested + if (_requestId == null) + { + _requestId = CorrelationIdGenerator.GetNextId(); + } + return _requestId; + } + } + public IPAddress RemoteIpAddress { get; set; } public int RemotePort { get; set; } public IPAddress LocalIpAddress { get; set; } @@ -341,6 +360,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http ResetFeatureCollection(); + TraceIdentifier = null; Scheme = null; Method = null; PathBase = null; @@ -417,7 +437,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http } catch (Exception ex) { - Log.ApplicationError(ConnectionId, ex); + Log.ApplicationError(ConnectionId, TraceIdentifier, ex); } } @@ -1196,7 +1216,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http _applicationException = new AggregateException(_applicationException, ex); } - Log.ApplicationError(ConnectionId, ex); + Log.ApplicationError(ConnectionId, TraceIdentifier, ex); } public void OnStartLine(HttpMethod method, HttpVersion version, Span target, Span path, Span query, Span customMethod, bool pathEncoded) diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/FrameOfT.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/FrameOfT.cs index 9fdb0497ac..dbf6a629e2 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/FrameOfT.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Http/FrameOfT.cs @@ -6,6 +6,7 @@ using System.IO; using System.Threading; using System.Threading.Tasks; using Microsoft.AspNetCore.Hosting.Server; +using Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure; using Microsoft.AspNetCore.Server.Kestrel.Transport.Exceptions; using Microsoft.Extensions.Logging; @@ -95,6 +96,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http { try { + KestrelEventSource.Log.RequestStart(this); + await _application.ProcessRequestAsync(context).ConfigureAwait(false); if (Volatile.Read(ref _requestAborted) == 0) @@ -113,6 +116,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http } finally { + KestrelEventSource.Log.RequestStop(this); + // Trigger OnStarting if it hasn't been called yet and the app hasn't // already failed. If an OnStarting callback throws we can go through // our normal error handling in ProduceEnd. diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/CorrelationIdGenerator.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/CorrelationIdGenerator.cs new file mode 100644 index 0000000000..81233b3a3f --- /dev/null +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/CorrelationIdGenerator.cs @@ -0,0 +1,48 @@ +// 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.Threading; + +namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure +{ + internal static class CorrelationIdGenerator + { + // Base32 encoding - in ascii sort order for easy text based sorting + private static readonly string _encode32Chars = "0123456789ABCDEFGHIJKLMNOPQRSTUV"; + + // Seed the _lastConnectionId for this application instance with + // the number of 100-nanosecond intervals that have elapsed since 12:00:00 midnight, January 1, 0001 + // for a roughly increasing _lastId over restarts + private static long _lastId = DateTime.UtcNow.Ticks; + + public static string GetNextId() => GenerateId(Interlocked.Increment(ref _lastId)); + + private static unsafe string GenerateId(long id) + { + // The following routine is ~310% faster than calling long.ToString() on x64 + // and ~600% faster than calling long.ToString() on x86 in tight loops of 1 million+ iterations + // See: https://github.com/aspnet/Hosting/pull/385 + + // stackalloc to allocate array on stack rather than heap + char* charBuffer = stackalloc char[13]; + + charBuffer[0] = _encode32Chars[(int)(id >> 60) & 31]; + charBuffer[1] = _encode32Chars[(int)(id >> 55) & 31]; + charBuffer[2] = _encode32Chars[(int)(id >> 50) & 31]; + charBuffer[3] = _encode32Chars[(int)(id >> 45) & 31]; + charBuffer[4] = _encode32Chars[(int)(id >> 40) & 31]; + charBuffer[5] = _encode32Chars[(int)(id >> 35) & 31]; + charBuffer[6] = _encode32Chars[(int)(id >> 30) & 31]; + charBuffer[7] = _encode32Chars[(int)(id >> 25) & 31]; + charBuffer[8] = _encode32Chars[(int)(id >> 20) & 31]; + charBuffer[9] = _encode32Chars[(int)(id >> 15) & 31]; + charBuffer[10] = _encode32Chars[(int)(id >> 10) & 31]; + charBuffer[11] = _encode32Chars[(int)(id >> 5) & 31]; + charBuffer[12] = _encode32Chars[(int)id & 31]; + + // string ctor overload that takes char* + return new string(charBuffer, 0, 13); + } + } +} diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs index ff622fa69b..5e744b678e 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/IKestrelTrace.cs @@ -45,6 +45,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure void NotAllConnectionsAborted(); - void ApplicationError(string connectionId, Exception ex); + void ApplicationError(string connectionId, string traceIdentifier, Exception ex); } } \ No newline at end of file diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Infrastructure/KestrelEventSource.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelEventSource.cs similarity index 59% rename from src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Infrastructure/KestrelEventSource.cs rename to src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelEventSource.cs index 552b65ff33..84d7702503 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Infrastructure/KestrelEventSource.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelEventSource.cs @@ -4,6 +4,7 @@ using System.Diagnostics.Tracing; using System.Runtime.CompilerServices; using Microsoft.AspNetCore.Server.Kestrel.Internal.Http; +using Microsoft.AspNetCore.Server.Kestrel.Transport; namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure { @@ -25,16 +26,16 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure // - Avoid renaming methods or parameters marked with EventAttribute. EventSource uses these to form the event object. [NonEvent] - public void ConnectionStart(Connection connection) + public void ConnectionStart(IConnectionContext context, IConnectionInformation information) { // avoid allocating strings unless this event source is enabled if (IsEnabled()) { ConnectionStart( - connection.ConnectionId, - connection.ListenerContext.ListenOptions.Scheme, - connection.LocalEndPoint.ToString(), - connection.RemoteEndPoint.ToString()); + context.ConnectionId, + information.ListenOptions.Scheme, + information.LocalEndPoint.ToString(), + information.RemoteEndPoint.ToString()); } } @@ -55,7 +56,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure } [NonEvent] - public void ConnectionStop(Connection connection) + public void ConnectionStop(IConnectionContext connection) { if (IsEnabled()) { @@ -69,5 +70,39 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure { WriteEvent(2, connectionId); } + + [NonEvent] + public void RequestStart(Frame frame) + { + // avoid allocating the trace identifier unless logging is enabled + if (IsEnabled()) + { + RequestStart(frame.ConnectionIdFeature, frame.TraceIdentifier); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(3, Level = EventLevel.Verbose)] + private void RequestStart(string connectionId, string requestId) + { + WriteEvent(3, connectionId, requestId); + } + + [NonEvent] + public void RequestStop(Frame frame) + { + // avoid allocating the trace identifier unless logging is enabled + if (IsEnabled()) + { + RequestStop(frame.ConnectionIdFeature, frame.TraceIdentifier); + } + } + + [MethodImpl(MethodImplOptions.NoInlining)] + [Event(4, Level = EventLevel.Verbose)] + private void RequestStop(string connectionId, string requestId) + { + WriteEvent(4, connectionId, requestId); + } } } diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs index 94f85518b6..50cd3c3f0a 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs @@ -45,8 +45,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal // ConnectionWriteCallback: Reserved: 12 - private static readonly Action _applicationError = - LoggerMessage.Define(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"": An unhandled exception was thrown by the application."); + private static readonly Action _applicationError = + LoggerMessage.Define(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": An unhandled exception was thrown by the application."); private static readonly Action _connectionError = LoggerMessage.Define(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error."); @@ -142,9 +142,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal // Reserved: Event ID 12 } - public virtual void ApplicationError(string connectionId, Exception ex) + public virtual void ApplicationError(string connectionId, string traceIdentifier, Exception ex) { - _applicationError(_logger, connectionId, ex); + _applicationError(_logger, connectionId, traceIdentifier, ex); } public virtual void ConnectionError(string connectionId, Exception ex) diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Transport/IConnectionContext.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Transport/IConnectionContext.cs index 3e1b19119a..1ef633d445 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Core/Transport/IConnectionContext.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Core/Transport/IConnectionContext.cs @@ -14,6 +14,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport IPipeReader Output { get; } // TODO: Remove these (Use Pipes instead?) + void OnConnectionClosed(); Task StopAsync(); void Abort(Exception ex); void Timeout(); diff --git a/src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Http/Connection.cs b/src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Http/Connection.cs index 8cf743bbdd..bff2e1021a 100644 --- a/src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Http/Connection.cs +++ b/src/Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv/Internal/Http/Connection.cs @@ -71,9 +71,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http _connectionContext = ConnectionHandler.OnConnection(this); ConnectionId = _connectionContext.ConnectionId; - Log.ConnectionStart(ConnectionId); - KestrelEventSource.Log.ConnectionStart(this); - Input = _connectionContext.Input; Output = new SocketOutputConsumer(_connectionContext.Output, Thread, _socket, this, ConnectionId, Log); @@ -82,7 +79,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http _lastTimestamp = Thread.Loop.Now(); // This *must* happen after socket.ReadStart - // The socket output consumer is the only thing that can close the connection. If the + // The socket output consumer is the only thing that can close the connection. If the // output pipe is already closed by the time we start then it's fine since, it'll close gracefully afterwards. var ignore = Output.StartWrites(); } @@ -109,9 +106,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http { _socket.Dispose(); - Log.ConnectionStop(ConnectionId); - - KestrelEventSource.Log.ConnectionStop(this); + _connectionContext.OnConnectionClosed(); Input.Complete(new TaskCanceledException("The request was aborted")); _socketClosedTcs.TrySetResult(null); diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/EventSourceTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/EventSourceTests.cs index 40610fe4c3..74180ccbab 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/EventSourceTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/EventSourceTests.cs @@ -27,10 +27,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests public async Task EmitsConnectionStartAndStop() { string connectionId = null; + string requestId = null; int port; using (var server = new TestServer(context => { connectionId = context.Features.Get().ConnectionId; + requestId = context.TraceIdentifier; return Task.CompletedTask; })) { @@ -47,16 +49,33 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests // capture list here as other tests executing in parallel may log events Assert.NotNull(connectionId); + Assert.NotNull(requestId); + var events = _listener.EventData.Where(e => e != null && GetProperty(e, "connectionId") == connectionId).ToList(); - var start = Assert.Single(events, e => e.EventName == "ConnectionStart"); - Assert.All(new[] { "connectionId", "scheme", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, start.PayloadNames)); - Assert.Equal("http", GetProperty(start, "scheme")); - Assert.Equal($"127.0.0.1:{port}", GetProperty(start, "localEndPoint")); - - 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); + { + var start = Assert.Single(events, e => e.EventName == "ConnectionStart"); + Assert.All(new[] { "connectionId", "scheme", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, start.PayloadNames)); + Assert.Equal("http", GetProperty(start, "scheme")); + Assert.Equal($"127.0.0.1:{port}", GetProperty(start, "localEndPoint")); + } + { + 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); + } + { + 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); + } + { + 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); + } } private string GetProperty(EventWrittenEventArgs data, string propName) diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs index 6b9007c6d3..9dc073f100 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/RequestTests.cs @@ -2,6 +2,7 @@ // 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.Globalization; using System.IO; using System.Net; @@ -566,6 +567,72 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } + [Fact] + public async Task AppCanSetTraceIdentifier() + { + const string knownId = "xyz123"; + using (var server = new TestServer(async context => + { + context.TraceIdentifier = knownId; + await context.Response.WriteAsync(context.TraceIdentifier); + })) + { + var requestId = await HttpClientSlim.GetStringAsync($"http://{server.EndPoint}") + .TimeoutAfter(TimeSpan.FromSeconds(10)); + Assert.Equal(knownId, requestId); + } + } + + [Fact] + public async Task TraceIdentifierIsUnique() + { + const int IdentifierLength = 13; + const int iterations = 10; + + using (var server = new TestServer(async context => + { + Assert.Equal(IdentifierLength, Encoding.ASCII.GetByteCount(context.TraceIdentifier)); + context.Response.ContentLength = IdentifierLength; + await context.Response.WriteAsync(context.TraceIdentifier); + })) + { + var usedIds = new ConcurrentBag(); + var uri = $"http://{server.EndPoint}"; + + // requests on separate connections in parallel + Parallel.For(0, iterations, async i => + { + var id = await HttpClientSlim.GetStringAsync(uri); + Assert.DoesNotContain(id, usedIds.ToArray()); + usedIds.Add(id); + }); + + // requests on same connection + using (var connection = server.CreateConnection()) + { + var buffer = new char[IdentifierLength]; + for (var i = 0; i < iterations; i++) + { + await connection.Send("GET / HTTP/1.1", + "", + ""); + + await connection.Receive($"HTTP/1.1 200 OK", + $"Date: {server.Context.DateHeaderValue}", + $"Content-Length: {IdentifierLength}", + "", + "").TimeoutAfter(TimeSpan.FromSeconds(10)); + + var read = await connection.Reader.ReadAsync(buffer, 0, IdentifierLength); + Assert.Equal(IdentifierLength, read); + var id = new string(buffer, 0, read); + Assert.DoesNotContain(id, usedIds.ToArray()); + usedIds.Add(id); + } + } + } + } + private async Task TestRemoteIPAddress(string registerAddress, string requestAddress, string expectAddress) { var builder = new WebHostBuilder() @@ -603,4 +670,4 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } } -} \ No newline at end of file +} diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs index 1e8fd21746..2b2854df79 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.FunctionalTests/ResponseTests.cs @@ -635,8 +635,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests var logTcs = new TaskCompletionSource(); var mockTrace = new Mock(); mockTrace - .Setup(trace => trace.ApplicationError(It.IsAny(), It.IsAny())) - .Callback((connectionId, ex) => + .Setup(trace => trace.ApplicationError(It.IsAny(), It.IsAny(), It.IsAny())) + .Callback((connectionId, requestId, ex) => { logTcs.SetResult(null); }); @@ -675,6 +675,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests mockTrace.Verify(trace => trace.ApplicationError( + It.IsAny(), It.IsAny(), It.Is(ex => ex.Message.Equals($"Response Content-Length mismatch: too few bytes written (12 of 13).", StringComparison.Ordinal)))); @@ -724,7 +725,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } // With the server disposed we know all connections were drained and all messages were logged. - mockTrace.Verify(trace => trace.ApplicationError(It.IsAny(), It.IsAny()), Times.Never); + mockTrace.Verify(trace => trace.ApplicationError(It.IsAny(), It.IsAny(), It.IsAny()), Times.Never); } [Fact] diff --git a/test/Microsoft.AspNetCore.Server.Kestrel.Performance/Mocks/MockTrace.cs b/test/Microsoft.AspNetCore.Server.Kestrel.Performance/Mocks/MockTrace.cs index f7737a63f9..915c4805d1 100644 --- a/test/Microsoft.AspNetCore.Server.Kestrel.Performance/Mocks/MockTrace.cs +++ b/test/Microsoft.AspNetCore.Server.Kestrel.Performance/Mocks/MockTrace.cs @@ -9,7 +9,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance { public class MockTrace : IKestrelTrace { - public void ApplicationError(string connectionId, Exception ex) { } + public void ApplicationError(string connectionId, string requestId, Exception ex) { } public IDisposable BeginScope(TState state) => null; public void ConnectionBadRequest(string connectionId, BadHttpRequestException ex) { } public void ConnectionDisconnect(string connectionId) { } diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/FrameTests.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/FrameTests.cs index 9e0a068f16..70f63f8a72 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/FrameTests.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/FrameTests.cs @@ -123,6 +123,33 @@ namespace Microsoft.AspNetCore.Server.KestrelTests Assert.Equal("http", ((IFeatureCollection)_frame).Get().Scheme); } + [Fact] + public void ResetResetsTraceIdentifier() + { + _frame.TraceIdentifier = "xyz"; + + _frame.Reset(); + + var nextId = ((IFeatureCollection)_frame).Get().TraceIdentifier; + Assert.NotEqual("xyz", nextId); + + _frame.Reset(); + var secondId = ((IFeatureCollection)_frame).Get().TraceIdentifier; + Assert.NotEqual(nextId, secondId); + } + + [Fact] + public void TraceIdentifierGeneratesWhenNull() + { + _frame.TraceIdentifier = null; + var id = _frame.TraceIdentifier; + Assert.NotNull(id); + Assert.Equal(id, _frame.TraceIdentifier); + + _frame.TraceIdentifier = null; + Assert.NotEqual(id, _frame.TraceIdentifier); + } + [Fact] public async Task ResetResetsHeaderLimits() { diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelEventSourceTests.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelEventSourceTests.cs index 1d5c1fdd81..97a38802b6 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelEventSourceTests.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/KestrelEventSourceTests.cs @@ -4,7 +4,7 @@ using System; using System.Diagnostics.Tracing; using System.Reflection; -using Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv; +using Microsoft.AspNetCore.Server.Kestrel; using Xunit; namespace Microsoft.AspNetCore.Server.KestrelTests @@ -14,7 +14,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests [Fact] public void ExistsWithCorrectId() { - var esType = typeof(LibuvTransportFactory).GetTypeInfo().Assembly.GetType( + var esType = typeof(KestrelServer).GetTypeInfo().Assembly.GetType( "Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure.KestrelEventSource", throwOnError: true, ignoreCase: false @@ -27,4 +27,4 @@ namespace Microsoft.AspNetCore.Server.KestrelTests Assert.NotEmpty(EventSource.GenerateManifest(esType, "assemblyPathToIncludeInManifest")); } } -} \ No newline at end of file +} diff --git a/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/MockConnectionHandler.cs b/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/MockConnectionHandler.cs index 6df2d283de..f50f3572c6 100644 --- a/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/MockConnectionHandler.cs +++ b/test/Microsoft.AspNetCore.Server.KestrelTests/TestHelpers/MockConnectionHandler.cs @@ -47,6 +47,11 @@ namespace Microsoft.AspNetCore.Server.KestrelTests.TestHelpers public IPipeWriter Input { get; set; } public IPipeReader Output { get; set; } + public void OnConnectionClosed() + { + throw new NotImplementedException(); + } + public Task StopAsync() { throw new NotImplementedException(); diff --git a/test/shared/TestConnection.cs b/test/shared/TestConnection.cs index aef4561448..33016bd473 100644 --- a/test/shared/TestConnection.cs +++ b/test/shared/TestConnection.cs @@ -32,6 +32,8 @@ namespace Microsoft.AspNetCore.Testing Create(port, addressFamily); } + public StreamReader Reader => _reader; + public void Create(int port, AddressFamily addressFamily) { _socket = CreateConnectedLoopbackSocket(port, addressFamily); diff --git a/test/shared/TestServer.cs b/test/shared/TestServer.cs index bf72cd0486..3763c61c53 100644 --- a/test/shared/TestServer.cs +++ b/test/shared/TestServer.cs @@ -59,6 +59,7 @@ namespace Microsoft.AspNetCore.Testing } } + public IPEndPoint EndPoint => _listenOptions.IPEndPoint; public int Port => _listenOptions.IPEndPoint.Port; public AddressFamily AddressFamily => _listenOptions.IPEndPoint.AddressFamily; diff --git a/tools/CodeGenerator/FrameFeatureCollection.cs b/tools/CodeGenerator/FrameFeatureCollection.cs index 22e6a9316b..6c85665fe9 100644 --- a/tools/CodeGenerator/FrameFeatureCollection.cs +++ b/tools/CodeGenerator/FrameFeatureCollection.cs @@ -61,8 +61,9 @@ namespace CodeGenerator typeof(IHttpRequestFeature), typeof(IHttpResponseFeature), typeof(IHttpUpgradeFeature), + typeof(IHttpRequestIdentifierFeature), typeof(IHttpRequestLifetimeFeature), - typeof(IHttpConnectionFeature) + typeof(IHttpConnectionFeature), }; return $@"// Copyright (c) .NET Foundation. All rights reserved.