Implement IHttpRequestIdentifierFeature on Frame

This feature generates a unique ID per request. This unique ID can be
used in event source and logging.

Also, this change improves KestrelEventSource by moving it back into the
Kestrel.Core assembly and de-coupling from the Libuv transport. This
adds two new events, RequestStart and RequestStop, which can be used to
identify the correlation between connection ID and request trace
identifier.
This commit is contained in:
Nate McMaster 2017-03-31 09:09:01 -07:00
parent 6b9d54265f
commit 83958886cc
No known key found for this signature in database
GPG Key ID: BD729980AA6A21BD
23 changed files with 343 additions and 218 deletions

19
.vscode/tasks.json vendored
View File

@ -21,7 +21,24 @@
"build", "build",
"${workspaceRoot}/KestrelHttpServer.sln" "${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", "taskName": "Compile: CodeGenerator",

View File

@ -1,25 +1,16 @@
// Copyright (c) .NET Foundation. All rights reserved. // 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. // 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.IO.Pipelines;
using System.Threading;
using Microsoft.AspNetCore.Hosting.Server; using Microsoft.AspNetCore.Hosting.Server;
using Microsoft.AspNetCore.Server.Kestrel.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Internal.Http;
using Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure;
using Microsoft.AspNetCore.Server.Kestrel.Transport; using Microsoft.AspNetCore.Server.Kestrel.Transport;
namespace Microsoft.AspNetCore.Server.Kestrel.Internal namespace Microsoft.AspNetCore.Server.Kestrel.Internal
{ {
public class ConnectionHandler<TContext> : IConnectionHandler public class ConnectionHandler<TContext> : 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 ServiceContext _serviceContext;
private readonly IHttpApplication<TContext> _application; private readonly IHttpApplication<TContext> _application;
@ -34,7 +25,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
var inputPipe = connectionInfo.PipeFactory.Create(GetInputPipeOptions(connectionInfo.InputWriterScheduler)); var inputPipe = connectionInfo.PipeFactory.Create(GetInputPipeOptions(connectionInfo.InputWriterScheduler));
var outputPipe = connectionInfo.PipeFactory.Create(GetOutputPipeOptions(connectionInfo.OutputWriterScheduler)); var outputPipe = connectionInfo.PipeFactory.Create(GetOutputPipeOptions(connectionInfo.OutputWriterScheduler));
var connectionId = GenerateConnectionId(Interlocked.Increment(ref _lastConnectionId)); var connectionId = CorrelationIdGenerator.GetNextId();
var frameContext = new FrameContext var frameContext = new FrameContext
{ {
@ -60,6 +51,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
OutputProducer = outputProducer 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, // 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 // Frame.RequestProcessingAsync is guaranteed to unblock the transport thread before calling
// application code. // application code.
@ -97,32 +91,5 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
// null means that we have no back pressure // null means that we have no back pressure
return bufferSize ?? 0; 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);
}
} }
} }

View File

@ -73,6 +73,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
} }
} }
public void OnConnectionClosed()
{
Log.ConnectionStop(ConnectionId);
KestrelEventSource.Log.ConnectionStop(this);
}
public async Task StopAsync() public async Task StopAsync()
{ {
await _frameStartedTcs.Task; await _frameStartedTcs.Task;

View File

@ -19,7 +19,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
IHttpResponseFeature, IHttpResponseFeature,
IHttpUpgradeFeature, IHttpUpgradeFeature,
IHttpConnectionFeature, IHttpConnectionFeature,
IHttpRequestLifetimeFeature IHttpRequestLifetimeFeature,
IHttpRequestIdentifierFeature
{ {
// NOTE: When feature interfaces are added to or removed from this Frame class implementation, // 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. // 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 string IHttpRequestFeature.Protocol
{ {
get get => HttpVersion;
{ set => HttpVersion = value;
return HttpVersion;
}
set
{
HttpVersion = value;
}
} }
string IHttpRequestFeature.Scheme string IHttpRequestFeature.Scheme
{ {
get get => Scheme ?? "http";
{ set => Scheme = value;
return Scheme ?? "http";
}
set
{
Scheme = value;
}
} }
string IHttpRequestFeature.Method string IHttpRequestFeature.Method
{ {
get get => Method;
{ set => Method = value;
return Method;
}
set
{
Method = value;
}
} }
string IHttpRequestFeature.PathBase string IHttpRequestFeature.PathBase
{ {
get get => PathBase ?? "";
{ set => PathBase = value;
return PathBase ?? "";
}
set
{
PathBase = value;
}
} }
string IHttpRequestFeature.Path string IHttpRequestFeature.Path
{ {
get get => Path;
{ set => Path = value;
return Path;
}
set
{
Path = value;
}
} }
string IHttpRequestFeature.QueryString string IHttpRequestFeature.QueryString
{ {
get get => QueryString;
{ set => QueryString = value;
return QueryString;
}
set
{
QueryString = value;
}
} }
string IHttpRequestFeature.RawTarget string IHttpRequestFeature.RawTarget
{ {
get get => RawTarget;
{ set => RawTarget = value;
return RawTarget;
}
set
{
RawTarget = value;
}
} }
IHeaderDictionary IHttpRequestFeature.Headers IHeaderDictionary IHttpRequestFeature.Headers
{ {
get get => RequestHeaders;
{ set => RequestHeaders = value;
return RequestHeaders;
}
set
{
RequestHeaders = value;
}
} }
Stream IHttpRequestFeature.Body Stream IHttpRequestFeature.Body
{ {
get get => RequestBody;
{ set => RequestBody = value;
return RequestBody;
}
set
{
RequestBody = value;
}
} }
int IHttpResponseFeature.StatusCode int IHttpResponseFeature.StatusCode
{ {
get get => StatusCode;
{ set => StatusCode = value;
return StatusCode;
}
set
{
StatusCode = value;
}
} }
string IHttpResponseFeature.ReasonPhrase string IHttpResponseFeature.ReasonPhrase
{ {
get get => ReasonPhrase;
{ set => ReasonPhrase = value;
return ReasonPhrase;
}
set
{
ReasonPhrase = value;
}
} }
IHeaderDictionary IHttpResponseFeature.Headers IHeaderDictionary IHttpResponseFeature.Headers
{ {
get get => ResponseHeaders;
{ set => ResponseHeaders = value;
return ResponseHeaders;
}
set
{
ResponseHeaders = value;
}
} }
Stream IHttpResponseFeature.Body Stream IHttpResponseFeature.Body
{ {
get get => ResponseBody;
{ set => ResponseBody = value;
return ResponseBody;
}
set
{
ResponseBody = value;
}
} }
CancellationToken IHttpRequestLifetimeFeature.RequestAborted CancellationToken IHttpRequestLifetimeFeature.RequestAborted
{ {
get get => RequestAborted;
{ set => RequestAborted = value;
return RequestAborted;
}
set
{
RequestAborted = value;
}
} }
bool IHttpResponseFeature.HasStarted bool IHttpResponseFeature.HasStarted => HasResponseStarted;
{
get { return HasResponseStarted; }
}
bool IHttpUpgradeFeature.IsUpgradableRequest => _upgrade; bool IHttpUpgradeFeature.IsUpgradableRequest => _upgrade;
@ -266,38 +168,44 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
IPAddress IHttpConnectionFeature.RemoteIpAddress IPAddress IHttpConnectionFeature.RemoteIpAddress
{ {
get { return RemoteIpAddress; } get => RemoteIpAddress;
set { RemoteIpAddress = value; } set => RemoteIpAddress = value;
} }
IPAddress IHttpConnectionFeature.LocalIpAddress IPAddress IHttpConnectionFeature.LocalIpAddress
{ {
get { return LocalIpAddress; } get => LocalIpAddress;
set { LocalIpAddress = value; } set => LocalIpAddress = value;
} }
int IHttpConnectionFeature.RemotePort int IHttpConnectionFeature.RemotePort
{ {
get { return RemotePort; } get => RemotePort;
set { RemotePort = value; } set => RemotePort = value;
} }
int IHttpConnectionFeature.LocalPort int IHttpConnectionFeature.LocalPort
{ {
get { return LocalPort; } get => LocalPort;
set { LocalPort = value; } set => LocalPort = value;
} }
string IHttpConnectionFeature.ConnectionId string IHttpConnectionFeature.ConnectionId
{ {
get { return ConnectionIdFeature; } get => ConnectionIdFeature;
set { ConnectionIdFeature = value; } set => ConnectionIdFeature = value;
}
string IHttpRequestIdentifierFeature.TraceIdentifier
{
get => TraceIdentifier;
set => TraceIdentifier = value;
} }
object IFeatureCollection.this[Type key] object IFeatureCollection.this[Type key]
{ {
get { return FastFeatureGet(key); } get => FastFeatureGet(key);
set { FastFeatureSet(key, value); } set => FastFeatureSet(key, value);
} }
TFeature IFeatureCollection.Get<TFeature>() TFeature IFeatureCollection.Get<TFeature>()

View File

@ -47,10 +47,10 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
_currentIHttpRequestFeature = this; _currentIHttpRequestFeature = this;
_currentIHttpResponseFeature = this; _currentIHttpResponseFeature = this;
_currentIHttpUpgradeFeature = this; _currentIHttpUpgradeFeature = this;
_currentIHttpRequestIdentifierFeature = this;
_currentIHttpRequestLifetimeFeature = this; _currentIHttpRequestLifetimeFeature = this;
_currentIHttpConnectionFeature = this; _currentIHttpConnectionFeature = this;
_currentIHttpRequestIdentifierFeature = null;
_currentIServiceProvidersFeature = null; _currentIServiceProvidersFeature = null;
_currentIHttpAuthenticationFeature = null; _currentIHttpAuthenticationFeature = null;
_currentIQueryFeature = null; _currentIQueryFeature = null;

View File

@ -69,6 +69,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
protected HttpVersion _httpVersion; protected HttpVersion _httpVersion;
private string _requestId;
private int _remainingRequestHeadersBytesAllowed; private int _remainingRequestHeadersBytesAllowed;
private int _requestHeadersParsed; private int _requestHeadersParsed;
@ -112,6 +113,24 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
protected string ConnectionId => _frameContext.ConnectionId; protected string ConnectionId => _frameContext.ConnectionId;
public string ConnectionIdFeature { get; set; } public string ConnectionIdFeature { get; set; }
/// <summary>
/// The request id. <seealso cref="HttpContext.TraceIdentifier"/>
/// </summary>
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 IPAddress RemoteIpAddress { get; set; }
public int RemotePort { get; set; } public int RemotePort { get; set; }
public IPAddress LocalIpAddress { get; set; } public IPAddress LocalIpAddress { get; set; }
@ -341,6 +360,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
ResetFeatureCollection(); ResetFeatureCollection();
TraceIdentifier = null;
Scheme = null; Scheme = null;
Method = null; Method = null;
PathBase = null; PathBase = null;
@ -417,7 +437,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
} }
catch (Exception ex) 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); _applicationException = new AggregateException(_applicationException, ex);
} }
Log.ApplicationError(ConnectionId, ex); Log.ApplicationError(ConnectionId, TraceIdentifier, ex);
} }
public void OnStartLine(HttpMethod method, HttpVersion version, Span<byte> target, Span<byte> path, Span<byte> query, Span<byte> customMethod, bool pathEncoded) public void OnStartLine(HttpMethod method, HttpVersion version, Span<byte> target, Span<byte> path, Span<byte> query, Span<byte> customMethod, bool pathEncoded)

View File

@ -6,6 +6,7 @@ using System.IO;
using System.Threading; using System.Threading;
using System.Threading.Tasks; using System.Threading.Tasks;
using Microsoft.AspNetCore.Hosting.Server; using Microsoft.AspNetCore.Hosting.Server;
using Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure;
using Microsoft.AspNetCore.Server.Kestrel.Transport.Exceptions; using Microsoft.AspNetCore.Server.Kestrel.Transport.Exceptions;
using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging;
@ -95,6 +96,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
{ {
try try
{ {
KestrelEventSource.Log.RequestStart(this);
await _application.ProcessRequestAsync(context).ConfigureAwait(false); await _application.ProcessRequestAsync(context).ConfigureAwait(false);
if (Volatile.Read(ref _requestAborted) == 0) if (Volatile.Read(ref _requestAborted) == 0)
@ -113,6 +116,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
} }
finally finally
{ {
KestrelEventSource.Log.RequestStop(this);
// Trigger OnStarting if it hasn't been called yet and the app hasn't // 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 // already failed. If an OnStarting callback throws we can go through
// our normal error handling in ProduceEnd. // our normal error handling in ProduceEnd.

View File

@ -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);
}
}
}

View File

@ -45,6 +45,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
void NotAllConnectionsAborted(); void NotAllConnectionsAborted();
void ApplicationError(string connectionId, Exception ex); void ApplicationError(string connectionId, string traceIdentifier, Exception ex);
} }
} }

View File

@ -4,6 +4,7 @@
using System.Diagnostics.Tracing; using System.Diagnostics.Tracing;
using System.Runtime.CompilerServices; using System.Runtime.CompilerServices;
using Microsoft.AspNetCore.Server.Kestrel.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Internal.Http;
using Microsoft.AspNetCore.Server.Kestrel.Transport;
namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure 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. // - Avoid renaming methods or parameters marked with EventAttribute. EventSource uses these to form the event object.
[NonEvent] [NonEvent]
public void ConnectionStart(Connection connection) public void ConnectionStart(IConnectionContext context, IConnectionInformation information)
{ {
// avoid allocating strings unless this event source is enabled // avoid allocating strings unless this event source is enabled
if (IsEnabled()) if (IsEnabled())
{ {
ConnectionStart( ConnectionStart(
connection.ConnectionId, context.ConnectionId,
connection.ListenerContext.ListenOptions.Scheme, information.ListenOptions.Scheme,
connection.LocalEndPoint.ToString(), information.LocalEndPoint.ToString(),
connection.RemoteEndPoint.ToString()); information.RemoteEndPoint.ToString());
} }
} }
@ -55,7 +56,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
} }
[NonEvent] [NonEvent]
public void ConnectionStop(Connection connection) public void ConnectionStop(IConnectionContext connection)
{ {
if (IsEnabled()) if (IsEnabled())
{ {
@ -69,5 +70,39 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure
{ {
WriteEvent(2, connectionId); 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);
}
} }
} }

View File

@ -45,8 +45,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
// ConnectionWriteCallback: Reserved: 12 // ConnectionWriteCallback: Reserved: 12
private static readonly Action<ILogger, string, Exception> _applicationError = private static readonly Action<ILogger, string, string, Exception> _applicationError =
LoggerMessage.Define<string>(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"": An unhandled exception was thrown by the application."); LoggerMessage.Define<string, string>(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": An unhandled exception was thrown by the application.");
private static readonly Action<ILogger, string, Exception> _connectionError = private static readonly Action<ILogger, string, Exception> _connectionError =
LoggerMessage.Define<string>(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error."); LoggerMessage.Define<string>(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error.");
@ -142,9 +142,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal
// Reserved: Event ID 12 // 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) public virtual void ConnectionError(string connectionId, Exception ex)

View File

@ -14,6 +14,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport
IPipeReader Output { get; } IPipeReader Output { get; }
// TODO: Remove these (Use Pipes instead?) // TODO: Remove these (Use Pipes instead?)
void OnConnectionClosed();
Task StopAsync(); Task StopAsync();
void Abort(Exception ex); void Abort(Exception ex);
void Timeout(); void Timeout();

View File

@ -71,9 +71,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
_connectionContext = ConnectionHandler.OnConnection(this); _connectionContext = ConnectionHandler.OnConnection(this);
ConnectionId = _connectionContext.ConnectionId; ConnectionId = _connectionContext.ConnectionId;
Log.ConnectionStart(ConnectionId);
KestrelEventSource.Log.ConnectionStart(this);
Input = _connectionContext.Input; Input = _connectionContext.Input;
Output = new SocketOutputConsumer(_connectionContext.Output, Thread, _socket, this, ConnectionId, Log); Output = new SocketOutputConsumer(_connectionContext.Output, Thread, _socket, this, ConnectionId, Log);
@ -109,9 +106,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Internal.Http
{ {
_socket.Dispose(); _socket.Dispose();
Log.ConnectionStop(ConnectionId); _connectionContext.OnConnectionClosed();
KestrelEventSource.Log.ConnectionStop(this);
Input.Complete(new TaskCanceledException("The request was aborted")); Input.Complete(new TaskCanceledException("The request was aborted"));
_socketClosedTcs.TrySetResult(null); _socketClosedTcs.TrySetResult(null);

View File

@ -27,10 +27,12 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
public async Task EmitsConnectionStartAndStop() public async Task EmitsConnectionStartAndStop()
{ {
string connectionId = null; string connectionId = null;
string requestId = null;
int port; int port;
using (var server = new TestServer(context => using (var server = new TestServer(context =>
{ {
connectionId = context.Features.Get<IHttpConnectionFeature>().ConnectionId; connectionId = context.Features.Get<IHttpConnectionFeature>().ConnectionId;
requestId = context.TraceIdentifier;
return Task.CompletedTask; 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 // capture list here as other tests executing in parallel may log events
Assert.NotNull(connectionId); Assert.NotNull(connectionId);
Assert.NotNull(requestId);
var events = _listener.EventData.Where(e => e != null && GetProperty(e, "connectionId") == connectionId).ToList(); 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)); var start = Assert.Single(events, e => e.EventName == "ConnectionStart");
Assert.Equal("http", GetProperty(start, "scheme")); Assert.All(new[] { "connectionId", "scheme", "remoteEndPoint", "localEndPoint" }, p => Assert.Contains(p, start.PayloadNames));
Assert.Equal($"127.0.0.1:{port}", GetProperty(start, "localEndPoint")); 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 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) private string GetProperty(EventWrittenEventArgs data, string propName)

View File

@ -2,6 +2,7 @@
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System; using System;
using System.Collections.Concurrent;
using System.Globalization; using System.Globalization;
using System.IO; using System.IO;
using System.Net; 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<string>();
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) private async Task TestRemoteIPAddress(string registerAddress, string requestAddress, string expectAddress)
{ {
var builder = new WebHostBuilder() var builder = new WebHostBuilder()

View File

@ -635,8 +635,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
var logTcs = new TaskCompletionSource<object>(); var logTcs = new TaskCompletionSource<object>();
var mockTrace = new Mock<IKestrelTrace>(); var mockTrace = new Mock<IKestrelTrace>();
mockTrace mockTrace
.Setup(trace => trace.ApplicationError(It.IsAny<string>(), It.IsAny<InvalidOperationException>())) .Setup(trace => trace.ApplicationError(It.IsAny<string>(), It.IsAny<string>(), It.IsAny<InvalidOperationException>()))
.Callback<string, Exception>((connectionId, ex) => .Callback<string, string, Exception>((connectionId, requestId, ex) =>
{ {
logTcs.SetResult(null); logTcs.SetResult(null);
}); });
@ -675,6 +675,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests
mockTrace.Verify(trace => mockTrace.Verify(trace =>
trace.ApplicationError( trace.ApplicationError(
It.IsAny<string>(),
It.IsAny<string>(), It.IsAny<string>(),
It.Is<InvalidOperationException>(ex => It.Is<InvalidOperationException>(ex =>
ex.Message.Equals($"Response Content-Length mismatch: too few bytes written (12 of 13).", StringComparison.Ordinal)))); 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. // With the server disposed we know all connections were drained and all messages were logged.
mockTrace.Verify(trace => trace.ApplicationError(It.IsAny<string>(), It.IsAny<InvalidOperationException>()), Times.Never); mockTrace.Verify(trace => trace.ApplicationError(It.IsAny<string>(), It.IsAny<string>(), It.IsAny<InvalidOperationException>()), Times.Never);
} }
[Fact] [Fact]

View File

@ -9,7 +9,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance
{ {
public class MockTrace : IKestrelTrace public class MockTrace : IKestrelTrace
{ {
public void ApplicationError(string connectionId, Exception ex) { } public void ApplicationError(string connectionId, string requestId, Exception ex) { }
public IDisposable BeginScope<TState>(TState state) => null; public IDisposable BeginScope<TState>(TState state) => null;
public void ConnectionBadRequest(string connectionId, BadHttpRequestException ex) { } public void ConnectionBadRequest(string connectionId, BadHttpRequestException ex) { }
public void ConnectionDisconnect(string connectionId) { } public void ConnectionDisconnect(string connectionId) { }

View File

@ -123,6 +123,33 @@ namespace Microsoft.AspNetCore.Server.KestrelTests
Assert.Equal("http", ((IFeatureCollection)_frame).Get<IHttpRequestFeature>().Scheme); Assert.Equal("http", ((IFeatureCollection)_frame).Get<IHttpRequestFeature>().Scheme);
} }
[Fact]
public void ResetResetsTraceIdentifier()
{
_frame.TraceIdentifier = "xyz";
_frame.Reset();
var nextId = ((IFeatureCollection)_frame).Get<IHttpRequestIdentifierFeature>().TraceIdentifier;
Assert.NotEqual("xyz", nextId);
_frame.Reset();
var secondId = ((IFeatureCollection)_frame).Get<IHttpRequestIdentifierFeature>().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] [Fact]
public async Task ResetResetsHeaderLimits() public async Task ResetResetsHeaderLimits()
{ {

View File

@ -4,7 +4,7 @@
using System; using System;
using System.Diagnostics.Tracing; using System.Diagnostics.Tracing;
using System.Reflection; using System.Reflection;
using Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv; using Microsoft.AspNetCore.Server.Kestrel;
using Xunit; using Xunit;
namespace Microsoft.AspNetCore.Server.KestrelTests namespace Microsoft.AspNetCore.Server.KestrelTests
@ -14,7 +14,7 @@ namespace Microsoft.AspNetCore.Server.KestrelTests
[Fact] [Fact]
public void ExistsWithCorrectId() public void ExistsWithCorrectId()
{ {
var esType = typeof(LibuvTransportFactory).GetTypeInfo().Assembly.GetType( var esType = typeof(KestrelServer).GetTypeInfo().Assembly.GetType(
"Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure.KestrelEventSource", "Microsoft.AspNetCore.Server.Kestrel.Internal.Infrastructure.KestrelEventSource",
throwOnError: true, throwOnError: true,
ignoreCase: false ignoreCase: false

View File

@ -47,6 +47,11 @@ namespace Microsoft.AspNetCore.Server.KestrelTests.TestHelpers
public IPipeWriter Input { get; set; } public IPipeWriter Input { get; set; }
public IPipeReader Output { get; set; } public IPipeReader Output { get; set; }
public void OnConnectionClosed()
{
throw new NotImplementedException();
}
public Task StopAsync() public Task StopAsync()
{ {
throw new NotImplementedException(); throw new NotImplementedException();

View File

@ -32,6 +32,8 @@ namespace Microsoft.AspNetCore.Testing
Create(port, addressFamily); Create(port, addressFamily);
} }
public StreamReader Reader => _reader;
public void Create(int port, AddressFamily addressFamily) public void Create(int port, AddressFamily addressFamily)
{ {
_socket = CreateConnectedLoopbackSocket(port, addressFamily); _socket = CreateConnectedLoopbackSocket(port, addressFamily);

View File

@ -59,6 +59,7 @@ namespace Microsoft.AspNetCore.Testing
} }
} }
public IPEndPoint EndPoint => _listenOptions.IPEndPoint;
public int Port => _listenOptions.IPEndPoint.Port; public int Port => _listenOptions.IPEndPoint.Port;
public AddressFamily AddressFamily => _listenOptions.IPEndPoint.AddressFamily; public AddressFamily AddressFamily => _listenOptions.IPEndPoint.AddressFamily;

View File

@ -61,8 +61,9 @@ namespace CodeGenerator
typeof(IHttpRequestFeature), typeof(IHttpRequestFeature),
typeof(IHttpResponseFeature), typeof(IHttpResponseFeature),
typeof(IHttpUpgradeFeature), typeof(IHttpUpgradeFeature),
typeof(IHttpRequestIdentifierFeature),
typeof(IHttpRequestLifetimeFeature), typeof(IHttpRequestLifetimeFeature),
typeof(IHttpConnectionFeature) typeof(IHttpConnectionFeature),
}; };
return $@"// Copyright (c) .NET Foundation. All rights reserved. return $@"// Copyright (c) .NET Foundation. All rights reserved.