diff --git a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs index c4f9dffdb435..c13a1c4e252d 100644 --- a/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs +++ b/src/Servers/Kestrel/Core/src/Internal/ConnectionDispatcher.cs @@ -24,7 +24,7 @@ public ConnectionDispatcher(ServiceContext serviceContext, Func connect _transportConnectionManager = transportConnectionManager; } - private IKestrelTrace Log => _serviceContext.Log; + private KestrelTrace Log => _serviceContext.Log; public Task StartAcceptingConnections(IConnectionListener listener) { diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/Http1OutputProducer.cs b/src/Servers/Kestrel/Core/src/Internal/Http/Http1OutputProducer.cs index 41abf1f6c53e..2bd7a870db23 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/Http1OutputProducer.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/Http1OutputProducer.cs @@ -34,7 +34,7 @@ internal class Http1OutputProducer : IHttpOutputProducer, IDisposable private readonly string _connectionId; private readonly BaseConnectionContext _connectionContext; private readonly MemoryPool _memoryPool; - private readonly IKestrelTrace _log; + private readonly KestrelTrace _log; private readonly IHttpMinResponseDataRateFeature _minResponseDataRateFeature; private readonly IHttpOutputAborter _outputAborter; private readonly TimingPipeFlusher _flusher; @@ -78,7 +78,7 @@ public Http1OutputProducer( string connectionId, BaseConnectionContext connectionContext, MemoryPool memoryPool, - IKestrelTrace log, + KestrelTrace log, ITimeoutControl timeoutControl, IHttpMinResponseDataRateFeature minResponseDataRateFeature, IHttpOutputAborter outputAborter) diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs index c868b3223d74..1c36862676e6 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/HttpProtocol.cs @@ -101,7 +101,7 @@ public void Initialize(HttpConnectionContext context) public IFeatureCollection ConnectionFeatures => _context.ConnectionFeatures; public IHttpOutputProducer Output { get; protected set; } = default!; - protected IKestrelTrace Log => ServiceContext.Log; + protected KestrelTrace Log => ServiceContext.Log; private DateHeaderValueManager DateHeaderValueManager => ServiceContext.DateHeaderValueManager; // Hold direct reference to ServerOptions since this is used very often in the request processing path protected KestrelServerOptions ServerOptions { get; set; } = default!; diff --git a/src/Servers/Kestrel/Core/src/Internal/Http/MessageBody.cs b/src/Servers/Kestrel/Core/src/Internal/Http/MessageBody.cs index 96924d1469c5..f6fd6792281c 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http/MessageBody.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http/MessageBody.cs @@ -42,7 +42,7 @@ protected MessageBody(HttpProtocol context) public virtual bool IsEmpty => false; - protected IKestrelTrace Log => _context.ServiceContext.Log; + protected KestrelTrace Log => _context.ServiceContext.Log; public abstract ValueTask ReadAsync(CancellationToken cancellationToken = default); diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs index a9e10b912dc1..d1985b63ec93 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2Connection.cs @@ -139,7 +139,7 @@ public Http2Connection(HttpConnectionContext context) public PipeReader Input => _input.Reader; - public IKestrelTrace Log => _context.ServiceContext.Log; + public KestrelTrace Log => _context.ServiceContext.Log; public IFeatureCollection ConnectionFeatures => _context.ConnectionFeatures; public ISystemClock SystemClock => _context.ServiceContext.SystemClock; public ITimeoutControl TimeoutControl => _context.TimeoutControl; diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2FrameWriter.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2FrameWriter.cs index 5822182a288f..96259c982ad5 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2FrameWriter.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2FrameWriter.cs @@ -34,7 +34,7 @@ internal class Http2FrameWriter private readonly Http2Connection _http2Connection; private readonly OutputFlowControl _connectionOutputFlowControl; private readonly string _connectionId; - private readonly IKestrelTrace _log; + private readonly KestrelTrace _log; private readonly ITimeoutControl _timeoutControl; private readonly MinDataRate? _minResponseDataRate; private readonly TimingPipeFlusher _flusher; diff --git a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2OutputProducer.cs b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2OutputProducer.cs index 7be6cc652090..7ba43be3aeaf 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http2/Http2OutputProducer.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http2/Http2OutputProducer.cs @@ -23,7 +23,7 @@ internal class Http2OutputProducer : IHttpOutputProducer, IHttpOutputAborter, IV private int StreamId => _stream.StreamId; private readonly Http2FrameWriter _frameWriter; private readonly TimingPipeFlusher _flusher; - private readonly IKestrelTrace _log; + private readonly KestrelTrace _log; // This should only be accessed via the FrameWriter. The connection-level output flow control is protected by the // FrameWriter's connection-level write lock. diff --git a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs index 92dd733318e8..6e4e9a852c40 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3Connection.cs @@ -83,7 +83,7 @@ private void UpdateHighestOpenedRequestStreamId(long streamId) // https://quicwg.org/base-drafts/draft-ietf-quic-http.html#section-5.2-2 private long GetCurrentGoAwayStreamId() => Interlocked.Read(ref _highestOpenedRequestStreamId) + 4; - private IKestrelTrace Log => _context.ServiceContext.Log; + private KestrelTrace Log => _context.ServiceContext.Log; public KestrelServerLimits Limits => _context.ServiceContext.ServerOptions.Limits; public Http3ControlStream? OutboundControlStream { get; set; } public Http3ControlStream? ControlStream { get; set; } diff --git a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3ControlStream.cs b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3ControlStream.cs index 418a52a9d989..308b629f79d2 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3ControlStream.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3ControlStream.cs @@ -65,7 +65,7 @@ private void OnStreamClosed() } public PipeReader Input => _context.Transport.Input; - public IKestrelTrace Log => _context.ServiceContext.Log; + public KestrelTrace Log => _context.ServiceContext.Log; public long StreamTimeoutTicks { get; set; } public bool IsReceivingHeader => _headerType == -1; diff --git a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3FrameWriter.cs b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3FrameWriter.cs index f0278038d337..0c9794182834 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3FrameWriter.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3FrameWriter.cs @@ -41,7 +41,7 @@ internal class Http3FrameWriter private readonly ITimeoutControl _timeoutControl; private readonly MinDataRate? _minResponseDataRate; private readonly MemoryPool _memoryPool; - private readonly IKestrelTrace _log; + private readonly KestrelTrace _log; private readonly IStreamIdFeature _streamIdFeature; private readonly IHttp3Stream _http3Stream; private readonly Http3RawFrame _outgoingFrame; @@ -61,7 +61,7 @@ internal class Http3FrameWriter private bool _completed; private bool _aborted; - public Http3FrameWriter(ConnectionContext connectionContext, ITimeoutControl timeoutControl, MinDataRate? minResponseDataRate, MemoryPool memoryPool, IKestrelTrace log, IStreamIdFeature streamIdFeature, Http3PeerSettings clientPeerSettings, IHttp3Stream http3Stream) + public Http3FrameWriter(ConnectionContext connectionContext, ITimeoutControl timeoutControl, MinDataRate? minResponseDataRate, MemoryPool memoryPool, KestrelTrace log, IStreamIdFeature streamIdFeature, Http3PeerSettings clientPeerSettings, IHttp3Stream http3Stream) { _connectionContext = connectionContext; _timeoutControl = timeoutControl; diff --git a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3OutputProducer.cs b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3OutputProducer.cs index 27c92f8eae32..a4fa43cd31b4 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Http3/Http3OutputProducer.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Http3/Http3OutputProducer.cs @@ -21,7 +21,7 @@ internal class Http3OutputProducer : IHttpOutputProducer, IHttpOutputAborter { private readonly Http3FrameWriter _frameWriter; private readonly TimingPipeFlusher _flusher; - private readonly IKestrelTrace _log; + private readonly KestrelTrace _log; private readonly MemoryPool _memoryPool; private readonly Http3Stream _stream; private readonly Pipe _pipe; @@ -40,7 +40,7 @@ public Http3OutputProducer( Http3FrameWriter frameWriter, MemoryPool pool, Http3Stream stream, - IKestrelTrace log) + KestrelTrace log) { _frameWriter = frameWriter; _memoryPool = pool; diff --git a/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs b/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs index 09aeb663dbca..dac3b891c59e 100644 --- a/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/HttpConnection.cs @@ -45,7 +45,7 @@ public HttpConnection(BaseHttpConnectionContext context) _context.TimeoutControl ??= _timeoutControl; } - private IKestrelTrace Log => _context.ServiceContext.Log; + private KestrelTrace Log => _context.ServiceContext.Log; public async Task ProcessRequestsAsync(IHttpApplication httpApplication) where TContext : notnull { diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/ConnectionManager.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/ConnectionManager.cs index f3e0eabee430..1c8dfb416bfd 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/ConnectionManager.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/ConnectionManager.cs @@ -12,14 +12,14 @@ internal class ConnectionManager private long _lastConnectionId = long.MinValue; private readonly ConcurrentDictionary _connectionReferences = new ConcurrentDictionary(); - private readonly IKestrelTrace _trace; + private readonly KestrelTrace _trace; - public ConnectionManager(IKestrelTrace trace, long? upgradedConnectionLimit) + public ConnectionManager(KestrelTrace trace, long? upgradedConnectionLimit) : this(trace, GetCounter(upgradedConnectionLimit)) { } - public ConnectionManager(IKestrelTrace trace, ResourceCounter upgradedConnections) + public ConnectionManager(KestrelTrace trace, ResourceCounter upgradedConnections) { UpgradedConnectionCount = upgradedConnections; _trace = trace; diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs index 5a9fab8ae0ac..d3eb0ccf338b 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs @@ -14,12 +14,12 @@ internal class Heartbeat : IDisposable private readonly IHeartbeatHandler[] _callbacks; private readonly ISystemClock _systemClock; private readonly IDebugger _debugger; - private readonly IKestrelTrace _trace; + private readonly KestrelTrace _trace; private readonly TimeSpan _interval; private readonly Thread _timerThread; private volatile bool _stopped; - public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace) + public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, KestrelTrace trace) { _callbacks = callbacks; _systemClock = systemClock; diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs deleted file mode 100644 index 6a75f4657b14..000000000000 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs +++ /dev/null @@ -1,105 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Net.Http; -using System.Net.Http.HPack; -using System.Net.Http.QPack; -using Microsoft.AspNetCore.Connections; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3; -using Microsoft.Extensions.Logging; - -namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure -{ - internal interface IKestrelTrace : ILogger - { - void ConnectionAccepted(string connectionId); - - void ConnectionStart(string connectionId); - - void ConnectionStop(string connectionId); - - void ConnectionPause(string connectionId); - - void ConnectionResume(string connectionId); - - void ConnectionRejected(string connectionId); - - void ConnectionKeepAlive(string connectionId); - - void ConnectionDisconnect(string connectionId); - - void RequestProcessingError(string connectionId, Exception ex); - - void ConnectionHeadResponseBodyWrite(string connectionId, long count); - - void NotAllConnectionsClosedGracefully(); - - void ConnectionBadRequest(string connectionId, Microsoft.AspNetCore.Http.BadHttpRequestException ex); - - void ApplicationError(string connectionId, string traceIdentifier, Exception ex); - - void NotAllConnectionsAborted(); - - void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now); - - void ApplicationNeverCompleted(string connectionId); - - void RequestBodyStart(string connectionId, string traceIdentifier); - - void RequestBodyDone(string connectionId, string traceIdentifier); - - void RequestBodyNotEntirelyRead(string connectionId, string traceIdentifier); - - void RequestBodyDrainTimedOut(string connectionId, string traceIdentifier); - - void RequestBodyMinimumDataRateNotSatisfied(string connectionId, string? traceIdentifier, double rate); - - void ResponseMinimumDataRateNotSatisfied(string connectionId, string? traceIdentifier); - - void ApplicationAbortedConnection(string connectionId, string traceIdentifier); - - void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex); - - void Http2ConnectionClosing(string connectionId); - - void Http2ConnectionClosed(string connectionId, int highestOpenedStreamId); - - void Http2StreamError(string connectionId, Http2StreamErrorException ex); - - void Http2StreamResetAbort(string traceIdentifier, Http2ErrorCode error, ConnectionAbortedException abortReason); - - void HPackDecodingError(string connectionId, int streamId, Exception ex); - - void HPackEncodingError(string connectionId, int streamId, Exception ex); - - void Http2FrameReceived(string connectionId, Http2Frame frame); - - void Http2FrameSending(string connectionId, Http2Frame frame); - - void Http2MaxConcurrentStreamsReached(string connectionId); - - void InvalidResponseHeaderRemoved(); - - void Http3ConnectionError(string connectionId, Http3ConnectionErrorException ex); - - void Http3ConnectionClosing(string connectionId); - - void Http3ConnectionClosed(string connectionId, long? highestOpenedStreamId); - - void Http3StreamAbort(string traceIdentifier, Http3ErrorCode error, ConnectionAbortedException abortReason); - - void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame); - - void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame); - - void QPackDecodingError(string connectionId, long streamId, Exception ex); - - void QPackEncodingError(string connectionId, long streamId, Exception ex); - - void Http3OutboundControlStreamError(string connectionId, Exception ex); - - void Http3GoAwayStreamId(string connectionId, long goAwayStreamId); - } -} diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs index f9734bd0810c..d6f2737efca6 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnection.cs @@ -28,7 +28,7 @@ internal abstract class KestrelConnection : IConnectionHeartbeatFeature, IConnec public KestrelConnection(long id, ServiceContext serviceContext, TransportConnectionManager transportConnectionManager, - IKestrelTrace logger) + KestrelTrace logger) { _id = id; _serviceContext = serviceContext; @@ -38,7 +38,7 @@ public KestrelConnection(long id, ConnectionClosedRequested = _connectionClosingCts.Token; } - protected IKestrelTrace Logger { get; } + protected KestrelTrace Logger { get; } public CancellationToken ConnectionClosedRequested { get; set; } public Task ExecutionTask => _completionTcs.Task; diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs index 964432736e7d..b2fc93d687b5 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelConnectionOfT.cs @@ -20,7 +20,7 @@ public KestrelConnection(long id, TransportConnectionManager transportConnectionManager, Func connectionDelegate, T connectionContext, - IKestrelTrace logger) + KestrelTrace logger) : base(id, serviceContext, transportConnectionManager, logger) { _connectionDelegate = connectionDelegate; diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index 3c3b7bc4af07..6fbeffff422b 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs @@ -10,13 +10,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure { - internal partial class KestrelTrace : IKestrelTrace + internal sealed partial class KestrelTrace : ILogger { - protected readonly ILogger _generalLogger; - protected readonly ILogger _badRequestsLogger; - protected readonly ILogger _connectionsLogger; - protected readonly ILogger _http2Logger; - protected readonly ILogger _http3Logger; + private readonly ILogger _generalLogger; + private readonly ILogger _badRequestsLogger; + private readonly ILogger _connectionsLogger; + private readonly ILogger _http2Logger; + private readonly ILogger _http3Logger; public KestrelTrace(ILoggerFactory loggerFactory) { @@ -30,7 +30,7 @@ public KestrelTrace(ILoggerFactory loggerFactory) [LoggerMessage(39, LogLevel.Debug, @"Connection id ""{ConnectionId}"" accepted.", EventName = "ConnectionAccepted")] private static partial void ConnectionAccepted(ILogger logger, string connectionId); - public virtual void ConnectionAccepted(string connectionId) + public void ConnectionAccepted(string connectionId) { ConnectionAccepted(_connectionsLogger, connectionId); } @@ -38,7 +38,7 @@ public virtual void ConnectionAccepted(string connectionId) [LoggerMessage(1, LogLevel.Debug, @"Connection id ""{ConnectionId}"" started.", EventName = "ConnectionStart")] private static partial void ConnectionStart(ILogger logger, string connectionId); - public virtual void ConnectionStart(string connectionId) + public void ConnectionStart(string connectionId) { ConnectionStart(_connectionsLogger, connectionId); } @@ -46,7 +46,7 @@ public virtual void ConnectionStart(string connectionId) [LoggerMessage(2, LogLevel.Debug, @"Connection id ""{ConnectionId}"" stopped.", EventName = "ConnectionStop")] private static partial void ConnectionStop(ILogger logger, string connectionId); - public virtual void ConnectionStop(string connectionId) + public void ConnectionStop(string connectionId) { ConnectionStop(_connectionsLogger, connectionId); } @@ -54,7 +54,7 @@ public virtual void ConnectionStop(string connectionId) [LoggerMessage(4, LogLevel.Debug, @"Connection id ""{ConnectionId}"" paused.", EventName = "ConnectionPause")] private static partial void ConnectionPause(ILogger logger, string connectionId); - public virtual void ConnectionPause(string connectionId) + public void ConnectionPause(string connectionId) { ConnectionPause(_connectionsLogger, connectionId); } @@ -62,7 +62,7 @@ public virtual void ConnectionPause(string connectionId) [LoggerMessage(5, LogLevel.Debug, @"Connection id ""{ConnectionId}"" resumed.", EventName = "ConnectionResume")] private static partial void ConnectionResume(ILogger logger, string connectionId); - public virtual void ConnectionResume(string connectionId) + public void ConnectionResume(string connectionId) { ConnectionResume(_connectionsLogger, connectionId); } @@ -70,7 +70,7 @@ public virtual void ConnectionResume(string connectionId) [LoggerMessage(9, LogLevel.Debug, @"Connection id ""{ConnectionId}"" completed keep alive response.", EventName = "ConnectionKeepAlive")] private static partial void ConnectionKeepAlive(ILogger logger, string connectionId); - public virtual void ConnectionKeepAlive(string connectionId) + public void ConnectionKeepAlive(string connectionId) { ConnectionKeepAlive(_connectionsLogger, connectionId); } @@ -78,7 +78,7 @@ public virtual void ConnectionKeepAlive(string connectionId) [LoggerMessage(24, LogLevel.Warning, @"Connection id ""{ConnectionId}"" rejected because the maximum number of concurrent connections has been reached.", EventName = "ConnectionRejected")] private static partial void ConnectionRejected(ILogger logger, string connectionId); - public virtual void ConnectionRejected(string connectionId) + public void ConnectionRejected(string connectionId) { ConnectionRejected(_connectionsLogger, connectionId); } @@ -86,7 +86,7 @@ public virtual void ConnectionRejected(string connectionId) [LoggerMessage(10, LogLevel.Debug, @"Connection id ""{ConnectionId}"" disconnecting.", EventName = "ConnectionDisconnect")] private static partial void ConnectionDisconnect(ILogger logger, string connectionId); - public virtual void ConnectionDisconnect(string connectionId) + public void ConnectionDisconnect(string connectionId) { ConnectionDisconnect(_connectionsLogger, connectionId); } @@ -94,7 +94,7 @@ public virtual void ConnectionDisconnect(string connectionId) [LoggerMessage(13, LogLevel.Error, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": An unhandled exception was thrown by the application.", EventName = "ApplicationError")] private static partial void ApplicationError(ILogger logger, string connectionId, string traceIdentifier, Exception ex); - public virtual void ApplicationError(string connectionId, string traceIdentifier, Exception ex) + public void ApplicationError(string connectionId, string traceIdentifier, Exception ex) { ApplicationError(_generalLogger, connectionId, traceIdentifier, ex); } @@ -102,7 +102,7 @@ public virtual void ApplicationError(string connectionId, string traceIdentifier [LoggerMessage(18, LogLevel.Debug, @"Connection id ""{ConnectionId}"" write of ""{count}"" body bytes to non-body HEAD response.", EventName = "ConnectionHeadResponseBodyWrite")] private static partial void ConnectionHeadResponseBodyWrite(ILogger logger, string connectionId, long count); - public virtual void ConnectionHeadResponseBodyWrite(string connectionId, long count) + public void ConnectionHeadResponseBodyWrite(string connectionId, long count) { ConnectionHeadResponseBodyWrite(_generalLogger, connectionId, count); } @@ -110,7 +110,7 @@ public virtual void ConnectionHeadResponseBodyWrite(string connectionId, long co [LoggerMessage(16, LogLevel.Debug, "Some connections failed to close gracefully during server shutdown.", EventName = "NotAllConnectionsClosedGracefully")] private static partial void NotAllConnectionsClosedGracefully(ILogger logger); - public virtual void NotAllConnectionsClosedGracefully() + public void NotAllConnectionsClosedGracefully() { NotAllConnectionsClosedGracefully(_connectionsLogger); } @@ -118,7 +118,7 @@ public virtual void NotAllConnectionsClosedGracefully() [LoggerMessage(17, LogLevel.Debug, @"Connection id ""{ConnectionId}"" bad request data: ""{message}""", EventName = "ConnectionBadRequest")] private static partial void ConnectionBadRequest(ILogger logger, string connectionId, string message, Microsoft.AspNetCore.Http.BadHttpRequestException ex); - public virtual void ConnectionBadRequest(string connectionId, Microsoft.AspNetCore.Http.BadHttpRequestException ex) + public void ConnectionBadRequest(string connectionId, Microsoft.AspNetCore.Http.BadHttpRequestException ex) { ConnectionBadRequest(_badRequestsLogger, connectionId, ex.Message, ex); } @@ -126,7 +126,7 @@ public virtual void ConnectionBadRequest(string connectionId, Microsoft.AspNetCo [LoggerMessage(20, LogLevel.Debug, @"Connection id ""{ConnectionId}"" request processing ended abnormally.", EventName = "RequestProcessingError")] private static partial void RequestProcessingError(ILogger logger, string connectionId, Exception ex); - public virtual void RequestProcessingError(string connectionId, Exception ex) + public void RequestProcessingError(string connectionId, Exception ex) { RequestProcessingError(_badRequestsLogger, connectionId, ex); } @@ -134,7 +134,7 @@ public virtual void RequestProcessingError(string connectionId, Exception ex) [LoggerMessage(21, LogLevel.Debug, "Some connections failed to abort during server shutdown.", EventName = "NotAllConnectionsAborted")] private static partial void NotAllConnectionsAborted(ILogger logger); - public virtual void NotAllConnectionsAborted() + public void NotAllConnectionsAborted() { NotAllConnectionsAborted(_connectionsLogger); } @@ -142,7 +142,7 @@ public virtual void NotAllConnectionsAborted() [LoggerMessage(22, LogLevel.Warning, @"As of ""{now}"", the heartbeat has been running for ""{heartbeatDuration}"" which is longer than ""{interval}"". This could be caused by thread pool starvation.", EventName = "HeartbeatSlow")] private static partial void HeartbeatSlow(ILogger logger, DateTimeOffset now, TimeSpan heartbeatDuration, TimeSpan interval); - public virtual void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now) + public void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now) { // while the heartbeat does loop over connections, this log is usually an indicator of threadpool starvation HeartbeatSlow(_generalLogger, now, heartbeatDuration, interval); @@ -151,7 +151,7 @@ public virtual void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, [LoggerMessage(23, LogLevel.Critical, @"Connection id ""{ConnectionId}"" application never completed.", EventName = "ApplicationNeverCompleted")] private static partial void ApplicationNeverCompleted(ILogger logger, string connectionId); - public virtual void ApplicationNeverCompleted(string connectionId) + public void ApplicationNeverCompleted(string connectionId) { ApplicationNeverCompleted(_generalLogger, connectionId); } @@ -159,7 +159,7 @@ public virtual void ApplicationNeverCompleted(string connectionId) [LoggerMessage(25, LogLevel.Debug, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": started reading request body.", EventName = "RequestBodyStart", SkipEnabledCheck = true)] private static partial void RequestBodyStart(ILogger logger, string connectionId, string traceIdentifier); - public virtual void RequestBodyStart(string connectionId, string traceIdentifier) + public void RequestBodyStart(string connectionId, string traceIdentifier) { RequestBodyStart(_generalLogger, connectionId, traceIdentifier); } @@ -167,7 +167,7 @@ public virtual void RequestBodyStart(string connectionId, string traceIdentifier [LoggerMessage(26, LogLevel.Debug, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": done reading request body.", EventName = "RequestBodyDone", SkipEnabledCheck = true)] private static partial void RequestBodyDone(ILogger logger, string connectionId, string traceIdentifier); - public virtual void RequestBodyDone(string connectionId, string traceIdentifier) + public void RequestBodyDone(string connectionId, string traceIdentifier) { RequestBodyDone(_generalLogger, connectionId, traceIdentifier); } @@ -175,7 +175,7 @@ public virtual void RequestBodyDone(string connectionId, string traceIdentifier) [LoggerMessage(27, LogLevel.Debug, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the request timed out because it was not sent by the client at a minimum of {Rate} bytes/second.", EventName = "RequestBodyMinimumDataRateNotSatisfied")] private static partial void RequestBodyMinimumDataRateNotSatisfied(ILogger logger, string connectionId, string? traceIdentifier, double rate); - public virtual void RequestBodyMinimumDataRateNotSatisfied(string connectionId, string? traceIdentifier, double rate) + public void RequestBodyMinimumDataRateNotSatisfied(string connectionId, string? traceIdentifier, double rate) { RequestBodyMinimumDataRateNotSatisfied(_badRequestsLogger, connectionId, traceIdentifier, rate); } @@ -183,7 +183,7 @@ public virtual void RequestBodyMinimumDataRateNotSatisfied(string connectionId, [LoggerMessage(32, LogLevel.Information, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the application completed without reading the entire request body.", EventName = "RequestBodyNotEntirelyRead")] private static partial void RequestBodyNotEntirelyRead(ILogger logger, string connectionId, string traceIdentifier); - public virtual void RequestBodyNotEntirelyRead(string connectionId, string traceIdentifier) + public void RequestBodyNotEntirelyRead(string connectionId, string traceIdentifier) { RequestBodyNotEntirelyRead(_generalLogger, connectionId, traceIdentifier); } @@ -191,7 +191,7 @@ public virtual void RequestBodyNotEntirelyRead(string connectionId, string trace [LoggerMessage(33, LogLevel.Information, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": automatic draining of the request body timed out after taking over 5 seconds.", EventName = "RequestBodyDrainTimedOut")] private static partial void RequestBodyDrainTimedOut(ILogger logger, string connectionId, string traceIdentifier); - public virtual void RequestBodyDrainTimedOut(string connectionId, string traceIdentifier) + public void RequestBodyDrainTimedOut(string connectionId, string traceIdentifier) { RequestBodyDrainTimedOut(_generalLogger, connectionId, traceIdentifier); } @@ -199,7 +199,7 @@ public virtual void RequestBodyDrainTimedOut(string connectionId, string traceId [LoggerMessage(28, LogLevel.Debug, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the connection was closed because the response was not read by the client at the specified minimum data rate.", EventName = "ResponseMinimumDataRateNotSatisfied")] private static partial void ResponseMinimumDataRateNotSatisfied(ILogger logger, string connectionId, string? traceIdentifier); - public virtual void ResponseMinimumDataRateNotSatisfied(string connectionId, string? traceIdentifier) + public void ResponseMinimumDataRateNotSatisfied(string connectionId, string? traceIdentifier) { ResponseMinimumDataRateNotSatisfied(_badRequestsLogger, connectionId, traceIdentifier); } @@ -207,7 +207,7 @@ public virtual void ResponseMinimumDataRateNotSatisfied(string connectionId, str [LoggerMessage(34, LogLevel.Information, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the application aborted the connection.", EventName = "ApplicationAbortedConnection")] private static partial void ApplicationAbortedConnection(ILogger logger, string connectionId, string traceIdentifier); - public virtual void ApplicationAbortedConnection(string connectionId, string traceIdentifier) + public void ApplicationAbortedConnection(string connectionId, string traceIdentifier) { ApplicationAbortedConnection(_connectionsLogger, connectionId, traceIdentifier); } @@ -215,7 +215,7 @@ public virtual void ApplicationAbortedConnection(string connectionId, string tra [LoggerMessage(29, LogLevel.Debug, @"Connection id ""{ConnectionId}"": HTTP/2 connection error.", EventName = "Http2ConnectionError")] private static partial void Http2ConnectionError(ILogger logger, string connectionId, Http2ConnectionErrorException ex); - public virtual void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex) + public void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex) { Http2ConnectionError(_http2Logger, connectionId, ex); } @@ -223,7 +223,7 @@ public virtual void Http2ConnectionError(string connectionId, Http2ConnectionErr [LoggerMessage(36, LogLevel.Debug, @"Connection id ""{ConnectionId}"" is closing.", EventName = "Http2ConnectionClosing")] private static partial void Http2ConnectionClosing(ILogger logger, string connectionId); - public virtual void Http2ConnectionClosing(string connectionId) + public void Http2ConnectionClosing(string connectionId) { Http2ConnectionClosing(_http2Logger, connectionId); } @@ -231,7 +231,7 @@ public virtual void Http2ConnectionClosing(string connectionId) [LoggerMessage(48, LogLevel.Debug, @"Connection id ""{ConnectionId}"" is closed. The last processed stream ID was {HighestOpenedStreamId}.", EventName = "Http2ConnectionClosed")] private static partial void Http2ConnectionClosed(ILogger logger, string connectionId, int highestOpenedStreamId); - public virtual void Http2ConnectionClosed(string connectionId, int highestOpenedStreamId) + public void Http2ConnectionClosed(string connectionId, int highestOpenedStreamId) { Http2ConnectionClosed(_http2Logger, connectionId, highestOpenedStreamId); } @@ -239,7 +239,7 @@ public virtual void Http2ConnectionClosed(string connectionId, int highestOpened [LoggerMessage(30, LogLevel.Debug, @"Connection id ""{ConnectionId}"": HTTP/2 stream error.", EventName = "Http2StreamError")] private static partial void Http2StreamError(ILogger logger, string connectionId, Http2StreamErrorException ex); - public virtual void Http2StreamError(string connectionId, Http2StreamErrorException ex) + public void Http2StreamError(string connectionId, Http2StreamErrorException ex) { Http2StreamError(_http2Logger, connectionId, ex); } @@ -255,7 +255,7 @@ public void Http2StreamResetAbort(string traceIdentifier, Http2ErrorCode error, [LoggerMessage(31, LogLevel.Debug, @"Connection id ""{ConnectionId}"": HPACK decoding error while decoding headers for stream ID {StreamId}.", EventName = "HPackDecodingError")] private static partial void HPackDecodingError(ILogger logger, string connectionId, int streamId, Exception ex); - public virtual void HPackDecodingError(string connectionId, int streamId, Exception ex) + public void HPackDecodingError(string connectionId, int streamId, Exception ex) { HPackDecodingError(_http2Logger, connectionId, streamId, ex); } @@ -263,7 +263,7 @@ public virtual void HPackDecodingError(string connectionId, int streamId, Except [LoggerMessage(38, LogLevel.Information, @"Connection id ""{ConnectionId}"": HPACK encoding error while encoding headers for stream ID {StreamId}.", EventName = "HPackEncodingError")] private static partial void HPackEncodingError(ILogger logger, string connectionId, int streamId, Exception ex); - public virtual void HPackEncodingError(string connectionId, int streamId, Exception ex) + public void HPackEncodingError(string connectionId, int streamId, Exception ex) { HPackEncodingError(_http2Logger, connectionId, streamId, ex); } @@ -374,7 +374,7 @@ public void Http3OutboundControlStreamError(string connectionId, Exception ex) [LoggerMessage(51, LogLevel.Debug, @"Connection id ""{ConnectionId}"": QPACK decoding error while decoding headers for stream ID {StreamId}.", EventName = "QPackDecodingError")] private static partial void QPackDecodingError(ILogger logger, string connectionId, long streamId, Exception ex); - public virtual void QPackDecodingError(string connectionId, long streamId, Exception ex) + public void QPackDecodingError(string connectionId, long streamId, Exception ex) { QPackDecodingError(_http3Logger, connectionId, streamId, ex); } @@ -382,7 +382,7 @@ public virtual void QPackDecodingError(string connectionId, long streamId, Excep [LoggerMessage(52, LogLevel.Information, @"Connection id ""{ConnectionId}"": QPACK encoding error while encoding headers for stream ID {StreamId}.", EventName = "QPackEncodingError")] private static partial void QPackEncodingError(ILogger logger, string connectionId, long streamId, Exception ex); - public virtual void QPackEncodingError(string connectionId, long streamId, Exception ex) + public void QPackEncodingError(string connectionId, long streamId, Exception ex) { QPackEncodingError(_http3Logger, connectionId, streamId, ex); } @@ -395,11 +395,11 @@ public void Http3GoAwayStreamId(string connectionId, long goAwayStreamId) Http3GoAwayStreamId(_http3Logger, connectionId, goAwayStreamId); } - public virtual void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) => _generalLogger.Log(logLevel, eventId, state, exception, formatter); - public virtual bool IsEnabled(LogLevel logLevel) => _generalLogger.IsEnabled(logLevel); + public bool IsEnabled(LogLevel logLevel) => _generalLogger.IsEnabled(logLevel); - public virtual IDisposable BeginScope(TState state) => _generalLogger.BeginScope(state); + public IDisposable BeginScope(TState state) => _generalLogger.BeginScope(state); } } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/PipeWriterHelpers/TimingPipeFlusher.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/PipeWriterHelpers/TimingPipeFlusher.cs index 0753e3230364..29e3d2beb9c1 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/PipeWriterHelpers/TimingPipeFlusher.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/PipeWriterHelpers/TimingPipeFlusher.cs @@ -21,11 +21,11 @@ internal class TimingPipeFlusher { private PipeWriter _writer = default!; private readonly ITimeoutControl? _timeoutControl; - private readonly IKestrelTrace _log; + private readonly KestrelTrace _log; public TimingPipeFlusher( ITimeoutControl? timeoutControl, - IKestrelTrace log) + KestrelTrace log) { _timeoutControl = timeoutControl; _log = log; diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs index 2c34795cf13d..2f5fdf3c246a 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/TransportManager.cs @@ -30,7 +30,7 @@ public TransportManager( } private ConnectionManager ConnectionManager => _serviceContext.ConnectionManager; - private IKestrelTrace Trace => _serviceContext.Log; + private KestrelTrace Trace => _serviceContext.Log; public async Task BindAsync(EndPoint endPoint, ConnectionDelegate connectionDelegate, EndpointConfig? endpointConfig, CancellationToken cancellationToken) { diff --git a/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs b/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs index eca9f357fb44..986e5182ba4f 100644 --- a/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs +++ b/src/Servers/Kestrel/Core/src/Internal/KestrelServerImpl.cs @@ -145,7 +145,7 @@ private static ServiceContext CreateServiceContext(IOptions ServiceContext.Log; + private KestrelTrace Trace => ServiceContext.Log; private AddressBindContext? AddressBindContext { get; set; } @@ -417,7 +417,7 @@ private void ValidateOptions() } } - private static ConnectionDelegate EnforceConnectionLimit(ConnectionDelegate innerDelegate, long? connectionLimit, IKestrelTrace trace) + private static ConnectionDelegate EnforceConnectionLimit(ConnectionDelegate innerDelegate, long? connectionLimit, KestrelTrace trace) { if (!connectionLimit.HasValue) { @@ -427,7 +427,7 @@ private static ConnectionDelegate EnforceConnectionLimit(ConnectionDelegate inne return new ConnectionLimitMiddleware(c => innerDelegate(c), connectionLimit.Value, trace).OnConnectionAsync; } - private static MultiplexedConnectionDelegate EnforceConnectionLimit(MultiplexedConnectionDelegate innerDelegate, long? connectionLimit, IKestrelTrace trace) + private static MultiplexedConnectionDelegate EnforceConnectionLimit(MultiplexedConnectionDelegate innerDelegate, long? connectionLimit, KestrelTrace trace) { if (!connectionLimit.HasValue) { diff --git a/src/Servers/Kestrel/Core/src/Internal/ServiceContext.cs b/src/Servers/Kestrel/Core/src/Internal/ServiceContext.cs index 6ceddc9c6568..1413373e0402 100644 --- a/src/Servers/Kestrel/Core/src/Internal/ServiceContext.cs +++ b/src/Servers/Kestrel/Core/src/Internal/ServiceContext.cs @@ -13,7 +13,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal // Changing this type would be a lot of work. internal class ServiceContext { - public IKestrelTrace Log { get; set; } = default!; + public KestrelTrace Log { get; set; } = default!; public PipeScheduler Scheduler { get; set; } = default!; diff --git a/src/Servers/Kestrel/Core/src/Middleware/ConnectionLimitMiddleware.cs b/src/Servers/Kestrel/Core/src/Middleware/ConnectionLimitMiddleware.cs index b1055bb5ec06..5d4c049a3d02 100644 --- a/src/Servers/Kestrel/Core/src/Middleware/ConnectionLimitMiddleware.cs +++ b/src/Servers/Kestrel/Core/src/Middleware/ConnectionLimitMiddleware.cs @@ -13,15 +13,15 @@ internal class ConnectionLimitMiddleware where T : BaseConnectionContext { private readonly Func _next; private readonly ResourceCounter _concurrentConnectionCounter; - private readonly IKestrelTrace _trace; + private readonly KestrelTrace _trace; - public ConnectionLimitMiddleware(Func next, long connectionLimit, IKestrelTrace trace) + public ConnectionLimitMiddleware(Func next, long connectionLimit, KestrelTrace trace) : this(next, ResourceCounter.Quota(connectionLimit), trace) { } // For Testing - internal ConnectionLimitMiddleware(Func next, ResourceCounter concurrentConnectionCounter, IKestrelTrace trace) + internal ConnectionLimitMiddleware(Func next, ResourceCounter concurrentConnectionCounter, KestrelTrace trace) { _next = next; _concurrentConnectionCounter = concurrentConnectionCounter; diff --git a/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs b/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs index 86673ee235a9..94091237208d 100644 --- a/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs +++ b/src/Servers/Kestrel/Core/test/ConnectionDispatcherTests.cs @@ -18,12 +18,15 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { - public class ConnectionDispatcherTests + public class ConnectionDispatcherTests : LoggedTest { [Fact] public async Task OnConnectionCreatesLogScopeWithConnectionId() { - var serviceContext = new TestServiceContext(); + var testLogger = new TestApplicationErrorLogger(); + var loggerFactory = new LoggerFactory(new[] { new KestrelTestLoggerProvider(testLogger) }); + + var serviceContext = new TestServiceContext(loggerFactory); // This needs to run inline var tcs = new TaskCompletionSource(); @@ -36,11 +39,7 @@ public async Task OnConnectionCreatesLogScopeWithConnectionId() var task = kestrelConnection.ExecuteAsync(); // The scope should be created - var scopeObjects = ((TestKestrelTrace)serviceContext.Log) - .Logger - .Scopes - .OfType>>() - .ToList(); + var scopeObjects = testLogger.Scopes.OfType>>().ToList(); Assert.Single(scopeObjects); var pairs = scopeObjects[0].ToDictionary(p => p.Key, p => p.Value); @@ -52,22 +51,19 @@ public async Task OnConnectionCreatesLogScopeWithConnectionId() await task; // Verify the scope was disposed after request processing completed - Assert.True(((TestKestrelTrace)serviceContext.Log).Logger.Scopes.IsEmpty); + Assert.True(testLogger.Scopes.IsEmpty); } [Fact] public async Task StartAcceptingConnectionsAsyncLogsIfAcceptAsyncThrows() { - var serviceContext = new TestServiceContext(); - var logger = ((TestKestrelTrace)serviceContext.Log).Logger; - logger.ThrowOnCriticalErrors = false; + var serviceContext = new TestServiceContext(LoggerFactory); var dispatcher = new ConnectionDispatcher(serviceContext, _ => Task.CompletedTask, new TransportConnectionManager(serviceContext.ConnectionManager)); await dispatcher.StartAcceptingConnections(new ThrowingListener()); - Assert.Equal(1, logger.CriticalErrorsLogged); - var critical = logger.Messages.SingleOrDefault(m => m.LogLevel == LogLevel.Critical); + var critical = TestSink.Writes.SingleOrDefault(m => m.LogLevel == LogLevel.Critical); Assert.NotNull(critical); Assert.IsType(critical.Exception); Assert.Equal("Unexpected error listening", critical.Exception.Message); @@ -98,8 +94,7 @@ public async Task OnConnectionFiresOnCompleted() [Fact] public async Task OnConnectionOnCompletedExceptionCaught() { - var serviceContext = new TestServiceContext(); - var logger = ((TestKestrelTrace)serviceContext.Log).Logger; + var serviceContext = new TestServiceContext(LoggerFactory); var connection = new Mock { CallBase = true }.Object; connection.ConnectionClosed = new CancellationToken(canceled: true); var transportConnectionManager = new TransportConnectionManager(serviceContext.ConnectionManager); @@ -115,7 +110,7 @@ public async Task OnConnectionOnCompletedExceptionCaught() await kestrelConnection.ExecuteAsync(); Assert.Equal(stateObject, callbackState); - var errors = logger.Messages.Where(e => e.LogLevel >= LogLevel.Error).ToArray(); + var errors = TestSink.Writes.Where(e => e.LogLevel >= LogLevel.Error).ToArray(); Assert.Single(errors); Assert.Equal("An error occurred running an IConnectionCompleteFeature.OnCompleted callback.", errors[0].Message); } diff --git a/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs b/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs index 92d28485e052..373ff992490d 100644 --- a/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs +++ b/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs @@ -5,6 +5,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging.Abstractions; using Moq; using Xunit; @@ -44,7 +45,7 @@ public void GetDateHeaderValue_ReturnsCachedValueBetweenTimerTicks() var dateHeaderValueManager = new DateHeaderValueManager(); dateHeaderValueManager.OnHeartbeat(now); - var testKestrelTrace = new TestKestrelTrace(); + var testKestrelTrace = new KestrelTrace(NullLoggerFactory.Instance); using (var heartbeat = new Heartbeat(new IHeartbeatHandler[] { dateHeaderValueManager }, systemClock, DebuggerWrapper.Singleton, testKestrelTrace)) { @@ -69,7 +70,7 @@ public void GetDateHeaderValue_ReturnsUpdatedValueAfterHeartbeat() var dateHeaderValueManager = new DateHeaderValueManager(); dateHeaderValueManager.OnHeartbeat(now); - var testKestrelTrace = new TestKestrelTrace(); + var testKestrelTrace = new KestrelTrace(NullLoggerFactory.Instance); var mockHeartbeatHandler = new Mock(); @@ -102,7 +103,7 @@ public void GetDateHeaderValue_ReturnsLastDateValueAfterHeartbeatDisposed() var dateHeaderValueManager = new DateHeaderValueManager(); dateHeaderValueManager.OnHeartbeat(now); - var testKestrelTrace = new TestKestrelTrace(); + var testKestrelTrace = new KestrelTrace(NullLoggerFactory.Instance); using (var heartbeat = new Heartbeat(new IHeartbeatHandler[] { dateHeaderValueManager }, systemClock, DebuggerWrapper.Singleton, testKestrelTrace)) { diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index f6540f2b9694..97ebdbca5b0e 100644 --- a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs +++ b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs @@ -14,7 +14,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { - public class HeartbeatTests + public class HeartbeatTests : LoggedTest { [Fact] public void HeartbeatIntervalIsOneSecond() @@ -28,7 +28,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsWarning() var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); var debugger = new Mock(); - var kestrelTrace = new TestKestrelTrace(); + var kestrelTrace = new KestrelTrace(LoggerFactory); var handlerMre = new ManualResetEventSlim(); var handlerStartedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var now = systemClock.UtcNow; @@ -59,7 +59,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsWarning() heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once()); - var warningMessage = kestrelTrace.Logger.Messages.Single(message => message.LogLevel == LogLevel.Warning).Message; + var warningMessage = TestSink.Writes.Single(message => message.LogLevel == LogLevel.Warning).Message; Assert.Equal($"As of \"{now.ToString(CultureInfo.InvariantCulture)}\", the heartbeat has been running for " + $"\"{heartbeatDuration.ToString("c", CultureInfo.InvariantCulture)}\" which is longer than " + $"\"{Heartbeat.Interval.ToString("c", CultureInfo.InvariantCulture)}\". " @@ -72,7 +72,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedIfDebuggerAttached var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); var debugger = new Mock(); - var kestrelTrace = new Mock(); + var kestrelTrace = new KestrelTrace(LoggerFactory); var handlerMre = new ManualResetEventSlim(); var handlerStartedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var now = systemClock.UtcNow; @@ -87,7 +87,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedIfDebuggerAttached Task blockedHeartbeatTask; - using (var heartbeat = new Heartbeat(new[] { heartbeatHandler.Object }, systemClock, debugger.Object, kestrelTrace.Object)) + using (var heartbeat = new Heartbeat(new[] { heartbeatHandler.Object }, systemClock, debugger.Object, kestrelTrace)) { blockedHeartbeatTask = Task.Run(() => heartbeat.OnHeartbeat()); @@ -102,7 +102,8 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedIfDebuggerAttached await blockedHeartbeatTask.DefaultTimeout(); heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once()); - kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.FromSeconds(2), Heartbeat.Interval, now), Times.Never()); + + Assert.Empty(TestSink.Writes.Where(w => w.EventId.Name == "HeartbeatSlow")); } [Fact] @@ -110,7 +111,7 @@ public void ExceptionFromHeartbeatHandlerIsLoggedAsError() { var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); - var kestrelTrace = new TestKestrelTrace(); + var kestrelTrace = new KestrelTrace(LoggerFactory); var ex = new Exception(); heartbeatHandler.Setup(h => h.OnHeartbeat(systemClock.UtcNow)).Throws(ex); @@ -120,7 +121,7 @@ public void ExceptionFromHeartbeatHandlerIsLoggedAsError() heartbeat.OnHeartbeat(); } - Assert.Equal(ex, kestrelTrace.Logger.Messages.Single(message => message.LogLevel == LogLevel.Error).Exception); + Assert.Equal(ex, TestSink.Writes.Single(message => message.LogLevel == LogLevel.Error).Exception); } } } diff --git a/src/Servers/Kestrel/Core/test/Http1ConnectionTests.cs b/src/Servers/Kestrel/Core/test/Http1ConnectionTests.cs index bb3071ef4a99..cf4c9c07ad4b 100644 --- a/src/Servers/Kestrel/Core/test/Http1ConnectionTests.cs +++ b/src/Servers/Kestrel/Core/test/Http1ConnectionTests.cs @@ -1,85 +1,24 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. -using System; using System.Buffers; using System.Collections; -using System.Collections.Generic; -using System.IO; -using System.IO.Pipelines; -using System.Linq; using System.Text; -using System.Threading; -using System.Threading.Tasks; using Microsoft.AspNetCore.Connections; -using Microsoft.AspNetCore.Connections.Features; using Microsoft.AspNetCore.Http; using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Server.Kestrel.Core.Features; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; -using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using Microsoft.Extensions.Primitives; -using Microsoft.Net.Http.Headers; using Moq; -using Xunit; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { - public class Http1ConnectionTests : IDisposable + public class Http1ConnectionTests : Http1ConnectionTestsBase { - private readonly IDuplexPipe _transport; - private readonly IDuplexPipe _application; - private readonly TestHttp1Connection _http1Connection; - private readonly ServiceContext _serviceContext; - private readonly HttpConnectionContext _http1ConnectionContext; - private readonly MemoryPool _pipelineFactory; - private SequencePosition _consumed; - private SequencePosition _examined; - private readonly Mock _timeoutControl; - - public Http1ConnectionTests() - { - _pipelineFactory = PinnedBlockMemoryPoolFactory.Create(); - var options = new PipeOptions(_pipelineFactory, readerScheduler: PipeScheduler.Inline, writerScheduler: PipeScheduler.Inline, useSynchronizationContext: false); - var pair = DuplexPipe.CreateConnectionPair(options, options); - - _transport = pair.Transport; - _application = pair.Application; - - var connectionFeatures = new FeatureCollection(); - connectionFeatures.Set(Mock.Of()); - - _serviceContext = new TestServiceContext() - { - Scheduler = PipeScheduler.Inline - }; - - _timeoutControl = new Mock(); - _http1ConnectionContext = TestContextFactory.CreateHttpConnectionContext( - serviceContext: _serviceContext, - connectionContext: Mock.Of(), - transport: pair.Transport, - timeoutControl: _timeoutControl.Object, - memoryPool: _pipelineFactory, - connectionFeatures: connectionFeatures); - - _http1Connection = new TestHttp1Connection(_http1ConnectionContext); - } - - public void Dispose() - { - _transport.Input.Complete(); - _transport.Output.Complete(); - - _application.Input.Complete(); - _application.Output.Complete(); - - _pipelineFactory.Dispose(); - } - [Fact] public async Task TakeMessageHeadersSucceedsWhenHeaderValueContainsUTF8() { @@ -825,12 +764,7 @@ public async Task ExceptionDetailNotIncludedWhenLogLevelInformationNotEnabled() try { - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(false); - - _serviceContext.Log = mockTrace.Object; + _serviceContext.Log = new KestrelTrace(NullLoggerFactory.Instance); await _application.Output.WriteAsync(Encoding.ASCII.GetBytes($"GET /%00 HTTP/1.1\r\n")); var readableBuffer = (await _transport.Input.ReadAsync()).Buffer; diff --git a/src/Servers/Kestrel/Core/test/Http1ConnectionTestsBase.cs b/src/Servers/Kestrel/Core/test/Http1ConnectionTestsBase.cs new file mode 100644 index 000000000000..46a145c94732 --- /dev/null +++ b/src/Servers/Kestrel/Core/test/Http1ConnectionTestsBase.cs @@ -0,0 +1,74 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +using System.Buffers; +using System.IO.Pipelines; +using System.Reflection; +using Microsoft.AspNetCore.Connections; +using Microsoft.AspNetCore.Connections.Features; +using Microsoft.AspNetCore.Http.Features; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; +using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; +using Microsoft.AspNetCore.Testing; +using Moq; +using Xunit.Abstractions; + +namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests +{ + public class Http1ConnectionTestsBase : LoggedTest, IDisposable + { + internal IDuplexPipe _transport; + internal IDuplexPipe _application; + internal TestHttp1Connection _http1Connection; + internal ServiceContext _serviceContext; + internal HttpConnectionContext _http1ConnectionContext; + internal MemoryPool _pipelineFactory; + internal SequencePosition _consumed; + internal SequencePosition _examined; + internal Mock _timeoutControl; + + public override void Initialize(TestContext context, MethodInfo methodInfo, object[] testMethodArguments, ITestOutputHelper testOutputHelper) + { + base.Initialize(context, methodInfo, testMethodArguments, testOutputHelper); + + _pipelineFactory = PinnedBlockMemoryPoolFactory.Create(); + var options = new PipeOptions(_pipelineFactory, readerScheduler: PipeScheduler.Inline, writerScheduler: PipeScheduler.Inline, useSynchronizationContext: false); + var pair = DuplexPipe.CreateConnectionPair(options, options); + + _transport = pair.Transport; + _application = pair.Application; + + var connectionFeatures = new FeatureCollection(); + connectionFeatures.Set(Mock.Of()); + + _serviceContext = new TestServiceContext(LoggerFactory) + { + Scheduler = PipeScheduler.Inline + }; + + _timeoutControl = new Mock(); + _http1ConnectionContext = TestContextFactory.CreateHttpConnectionContext( + serviceContext: _serviceContext, + connectionContext: Mock.Of(), + transport: pair.Transport, + timeoutControl: _timeoutControl.Object, + memoryPool: _pipelineFactory, + connectionFeatures: connectionFeatures); + + _http1Connection = new TestHttp1Connection(_http1ConnectionContext); + } + + void IDisposable.Dispose() + { + base.Dispose(); + + _transport.Input.Complete(); + _transport.Output.Complete(); + + _application.Input.Complete(); + _application.Output.Complete(); + + _pipelineFactory.Dispose(); + } + } +} diff --git a/src/Servers/Kestrel/Core/test/Http1OutputProducerTests.cs b/src/Servers/Kestrel/Core/test/Http1OutputProducerTests.cs index 272fca477865..d391e0174599 100644 --- a/src/Servers/Kestrel/Core/test/Http1OutputProducerTests.cs +++ b/src/Servers/Kestrel/Core/test/Http1OutputProducerTests.cs @@ -181,7 +181,7 @@ private TestHttpOutputProducer CreateOutputProducer( private class TestHttpOutputProducer : Http1OutputProducer { - public TestHttpOutputProducer(Pipe pipe, string connectionId, ConnectionContext connectionContext, MemoryPool memoryPool, IKestrelTrace log, ITimeoutControl timeoutControl, IHttpMinResponseDataRateFeature minResponseDataRateFeature, IHttpOutputAborter outputAborter) + public TestHttpOutputProducer(Pipe pipe, string connectionId, ConnectionContext connectionContext, MemoryPool memoryPool, KestrelTrace log, ITimeoutControl timeoutControl, IHttpMinResponseDataRateFeature minResponseDataRateFeature, IHttpOutputAborter outputAborter) : base(pipe.Writer, connectionId, connectionContext, memoryPool, log, timeoutControl, minResponseDataRateFeature, outputAborter) { Pipe = pipe; diff --git a/src/Servers/Kestrel/Core/test/Http2FrameWriterTests.cs b/src/Servers/Kestrel/Core/test/Http2FrameWriterTests.cs index f25eaf1375b7..0faef444e41b 100644 --- a/src/Servers/Kestrel/Core/test/Http2FrameWriterTests.cs +++ b/src/Servers/Kestrel/Core/test/Http2FrameWriterTests.cs @@ -55,7 +55,7 @@ public async Task WriteWindowUpdate_UnsetsReservedBit() private Http2FrameWriter CreateFrameWriter(Pipe pipe) { - var serviceContext = TestContextFactory.CreateServiceContext(new KestrelServerOptions(), log: Mock.Of()); + var serviceContext = TestContextFactory.CreateServiceContext(new KestrelServerOptions()); return new Http2FrameWriter(pipe.Writer, null, null, null, null, null, null, _dirtyMemoryPool, serviceContext); } diff --git a/src/Servers/Kestrel/Core/test/HttpConnectionManagerTests.cs b/src/Servers/Kestrel/Core/test/HttpConnectionManagerTests.cs index 09c395b3f82d..8dec9d56ea2b 100644 --- a/src/Servers/Kestrel/Core/test/HttpConnectionManagerTests.cs +++ b/src/Servers/Kestrel/Core/test/HttpConnectionManagerTests.cs @@ -13,14 +13,14 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { - public class HttpConnectionManagerTests + public class HttpConnectionManagerTests : LoggedTest { [Fact] public void UnrootedConnectionsGetRemovedFromHeartbeat() { + var trace = new KestrelTrace(LoggerFactory); var connectionId = "0"; - var trace = new Mock(); - var httpConnectionManager = new ConnectionManager(trace.Object, ResourceCounter.Unlimited); + var httpConnectionManager = new ConnectionManager(trace, ResourceCounter.Unlimited); // Create HttpConnection in inner scope so it doesn't get rooted by the current frame. UnrootedConnectionsGetRemovedFromHeartbeatInnerScope(connectionId, httpConnectionManager, trace); @@ -32,27 +32,28 @@ public void UnrootedConnectionsGetRemovedFromHeartbeat() httpConnectionManager.Walk(_ => connectionCount++); Assert.Equal(0, connectionCount); - trace.Verify(t => t.ApplicationNeverCompleted(connectionId), Times.Once()); + + Assert.Single(TestSink.Writes.Where(c => c.EventId.Name == "ApplicationNeverCompleted")); } [MethodImpl(MethodImplOptions.NoInlining)] private void UnrootedConnectionsGetRemovedFromHeartbeatInnerScope( string connectionId, ConnectionManager httpConnectionManager, - Mock trace) + KestrelTrace trace) { var serviceContext = new TestServiceContext(); var mock = new Mock() { CallBase = true }; mock.Setup(m => m.ConnectionId).Returns(connectionId); var transportConnectionManager = new TransportConnectionManager(httpConnectionManager); - var httpConnection = new KestrelConnection(0, serviceContext, transportConnectionManager, _ => Task.CompletedTask, mock.Object, Mock.Of()); + var httpConnection = new KestrelConnection(0, serviceContext, transportConnectionManager, _ => Task.CompletedTask, mock.Object, trace); transportConnectionManager.AddConnection(0, httpConnection); var connectionCount = 0; httpConnectionManager.Walk(_ => connectionCount++); Assert.Equal(1, connectionCount); - trace.Verify(t => t.ApplicationNeverCompleted(connectionId), Times.Never()); + Assert.Empty(TestSink.Writes.Where(c => c.EventId.Name == "ApplicationNeverCompleted")); // Ensure httpConnection doesn't get GC'd before this point. GC.KeepAlive(httpConnection); diff --git a/src/Servers/Kestrel/Core/test/HttpParserTests.cs b/src/Servers/Kestrel/Core/test/HttpParserTests.cs index c3c4c84d0a24..4acac90aec2b 100644 --- a/src/Servers/Kestrel/Core/test/HttpParserTests.cs +++ b/src/Servers/Kestrel/Core/test/HttpParserTests.cs @@ -12,15 +12,17 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; using Moq; using Xunit; using HttpMethod = Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpMethod; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { - public class HttpParserTests + public class HttpParserTests : LoggedTest { - private static readonly IKestrelTrace _nullTrace = Mock.Of(); + private static readonly KestrelTrace _nullTrace = new KestrelTrace(NullLoggerFactory.Instance); + private KestrelTrace CreateEnabledTrace() => new KestrelTrace(LoggerFactory); [Theory] [MemberData(nameof(RequestLineValidData))] @@ -81,12 +83,7 @@ public void ParseRequestLineDoesNotConsumeIncompleteRequestLine(string requestLi [MemberData(nameof(RequestLineInvalidData))] public void ParseRequestLineThrowsOnInvalidRequestLine(string requestLine) { - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(true); - - var parser = CreateParser(mockTrace.Object); + var parser = CreateParser(CreateEnabledTrace()); var buffer = new ReadOnlySequence(Encoding.ASCII.GetBytes(requestLine)); var requestHandler = new RequestHandler(); @@ -105,12 +102,7 @@ public void ParseRequestLineThrowsOnNonTokenCharsInCustomMethod(string method) { var requestLine = $"{method} / HTTP/1.1\r\n"; - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(true); - - var parser = CreateParser(mockTrace.Object); + var parser = CreateParser(CreateEnabledTrace()); var buffer = new ReadOnlySequence(Encoding.ASCII.GetBytes(requestLine)); var requestHandler = new RequestHandler(); @@ -129,12 +121,7 @@ public void ParseRequestLineThrowsOnUnrecognizedHttpVersion(string httpVersion) { var requestLine = $"GET / {httpVersion}\r\n"; - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(true); - - var parser = CreateParser(mockTrace.Object); + var parser = CreateParser(CreateEnabledTrace()); var buffer = new ReadOnlySequence(Encoding.ASCII.GetBytes(requestLine)); var requestHandler = new RequestHandler(); @@ -325,12 +312,7 @@ public void ParseHeadersConsumesBytesCorrectlyAtEnd() [MemberData(nameof(RequestHeaderInvalidData))] public void ParseHeadersThrowsOnInvalidRequestHeaders(string rawHeaders, string expectedExceptionMessage) { - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(true); - - var parser = CreateParser(mockTrace.Object); + var parser = CreateParser(CreateEnabledTrace()); var buffer = new ReadOnlySequence(Encoding.ASCII.GetBytes(rawHeaders)); var requestHandler = new RequestHandler(); @@ -349,12 +331,7 @@ public void ParseHeadersThrowsOnInvalidRequestHeaders(string rawHeaders, string [Fact] public void ExceptionDetailNotIncludedWhenLogLevelInformationNotEnabled() { - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(false); - - var parser = CreateParser(mockTrace.Object); + var parser = CreateParser(_nullTrace); // Invalid request line var buffer = new ReadOnlySequence(Encoding.ASCII.GetBytes("GET % HTTP/1.1\r\n")); @@ -433,12 +410,7 @@ public void ParseRequestLineTlsOverHttp() [MemberData(nameof(RequestHeaderInvalidData))] public void ParseHeadersThrowsOnInvalidRequestHeadersWithGratuitouslySplitBuffers(string rawHeaders, string expectedExceptionMessage) { - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(true); - - var parser = CreateParser(mockTrace.Object); + var parser = CreateParser(CreateEnabledTrace()); var buffer = BytePerSegmentTestSequenceFactory.Instance.CreateWithContent(rawHeaders); var requestHandler = new RequestHandler(); @@ -536,7 +508,7 @@ private void VerifyRawHeaders(string rawHeaders, IEnumerable expectedHea Assert.True(buffer.Slice(reader.Position).IsEmpty); } - private IHttpParser CreateParser(IKestrelTrace log) => new HttpParser(log.IsEnabled(LogLevel.Information)); + private IHttpParser CreateParser(KestrelTrace log) => new HttpParser(log.IsEnabled(LogLevel.Information)); public static IEnumerable RequestLineValidData => HttpParsingData.RequestLineValidData; diff --git a/src/Servers/Kestrel/Core/test/MessageBodyTests.cs b/src/Servers/Kestrel/Core/test/MessageBodyTests.cs index 97ed21b15452..a190a92db594 100644 --- a/src/Servers/Kestrel/Core/test/MessageBodyTests.cs +++ b/src/Servers/Kestrel/Core/test/MessageBodyTests.cs @@ -13,13 +13,14 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging.Testing; using Moq; using Xunit; using Xunit.Sdk; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests { - public class MessageBodyTests + public class MessageBodyTests : LoggedTest { [Theory] [InlineData((int)HttpVersion.Http10)] @@ -758,9 +759,8 @@ public async Task ReadAsyncThrowsOnTimeout() public async Task ConsumeAsyncCompletesAndDoesNotThrowOnTimeout() { var mockTimeoutControl = new Mock(); - var mockLogger = new Mock(); - using (var input = new TestInput(log: mockLogger.Object, timeoutControl: mockTimeoutControl.Object)) + using (var input = new TestInput(log: new KestrelTrace(LoggerFactory), timeoutControl: mockTimeoutControl.Object)) { var body = Http1MessageBody.For(HttpVersion.Http11, new HttpRequestHeaders { HeaderContentLength = "5" }, input.Http1Connection); @@ -777,10 +777,11 @@ public async Task ConsumeAsyncCompletesAndDoesNotThrowOnTimeout() await body.ConsumeAsync(); - mockLogger.Verify(logger => logger.ConnectionBadRequest( - It.IsAny(), #pragma warning disable CS0618 // Type or member is obsolete - It.Is(ex => ex.Reason == RequestRejectionReason.RequestBodyTimeout))); + Assert.Contains(TestSink.Writes, + m => m.EventId.Name == "ConnectionBadRequest" && + m.Exception is BadHttpRequestException ex && + ex.Reason == RequestRejectionReason.RequestBodyTimeout); #pragma warning restore CS0618 // Type or member is obsolete await body.StopAsync(); @@ -822,12 +823,7 @@ public async Task CopyToAsyncThrowsOnTimeout() [Fact] public async Task LogsWhenStartsReadingRequestBody() { - var mockLogger = new Mock(); - mockLogger - .Setup(logger => logger.IsEnabled(Extensions.Logging.LogLevel.Debug)) - .Returns(true); - - using (var input = new TestInput(log: mockLogger.Object)) + using (var input = new TestInput(log: new KestrelTrace(LoggerFactory))) { input.Http1Connection.ConnectionIdFeature = "ConnectionId"; input.Http1Connection.TraceIdentifier = "RequestId"; @@ -841,7 +837,9 @@ public async Task LogsWhenStartsReadingRequestBody() input.Add("a"); Assert.Equal(1, await stream.ReadAsync(new byte[1], 0, 1)); - mockLogger.Verify(logger => logger.RequestBodyStart("ConnectionId", "RequestId")); + Assert.Contains(TestSink.Writes, + m => m.EventId.Name == "RequestBodyStart" && + m.Message.Contains(@"Connection id ""ConnectionId"", Request id ""RequestId"": started reading request body.")); input.Fin(); @@ -853,15 +851,16 @@ public async Task LogsWhenStartsReadingRequestBody() public async Task LogsWhenStopsReadingRequestBody() { var logEvent = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockLogger = new Mock(); - mockLogger - .Setup(logger => logger.RequestBodyDone("ConnectionId", "RequestId")) - .Callback(() => logEvent.SetResult()); - mockLogger - .Setup(logger => logger.IsEnabled(Extensions.Logging.LogLevel.Debug)) - .Returns(true); - - using (var input = new TestInput(log: mockLogger.Object)) + + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "RequestBodyDone") + { + logEvent.SetResult(); + } + }; + + using (var input = new TestInput(log: new KestrelTrace(LoggerFactory))) { input.Http1Connection.ConnectionIdFeature = "ConnectionId"; input.Http1Connection.TraceIdentifier = "RequestId"; diff --git a/src/Servers/Kestrel/Core/test/StartLineTests.cs b/src/Servers/Kestrel/Core/test/StartLineTests.cs index 4c65611e95e4..2febdf2194de 100644 --- a/src/Servers/Kestrel/Core/test/StartLineTests.cs +++ b/src/Servers/Kestrel/Core/test/StartLineTests.cs @@ -12,6 +12,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging.Abstractions; using Moq; using Xunit; @@ -19,8 +20,6 @@ namespace Microsoft.AspNetCore.Server.Kestrel.InMemory.FunctionalTests { public class StartLineTests : IDisposable { - private static readonly IKestrelTrace _trace = Mock.Of(); - private IDuplexPipe Transport { get; } private MemoryPool MemoryPool { get; } private Http1Connection Http1Connection { get; } @@ -525,8 +524,7 @@ public StartLineTests() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), - httpParser: new HttpParser(), - log: _trace); + httpParser: new HttpParser()); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/Core/test/TestHelpers/TestInput.cs b/src/Servers/Kestrel/Core/test/TestHelpers/TestInput.cs index f6faff3de0d6..d559959741b3 100644 --- a/src/Servers/Kestrel/Core/test/TestHelpers/TestInput.cs +++ b/src/Servers/Kestrel/Core/test/TestHelpers/TestInput.cs @@ -13,6 +13,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging.Abstractions; using Moq; namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests @@ -21,7 +22,7 @@ class TestInput : IDisposable { private readonly MemoryPool _memoryPool; - public TestInput(IKestrelTrace log = null, ITimeoutControl timeoutControl = null) + public TestInput(KestrelTrace log = null, ITimeoutControl timeoutControl = null) { _memoryPool = PinnedBlockMemoryPoolFactory.Create(); var options = new PipeOptions(pool: _memoryPool, readerScheduler: PipeScheduler.Inline, writerScheduler: PipeScheduler.Inline, useSynchronizationContext: false); @@ -35,7 +36,7 @@ public TestInput(IKestrelTrace log = null, ITimeoutControl timeoutControl = null Http1ConnectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: new TestServiceContext { - Log = log ?? Mock.Of() + Log = log ?? new KestrelTrace(NullLoggerFactory.Instance) }, connectionContext: Mock.Of(), transport: Transport, diff --git a/src/Servers/Kestrel/Transport.Libuv/test/LibuvOutputConsumerTests.cs b/src/Servers/Kestrel/Transport.Libuv/test/LibuvOutputConsumerTests.cs index 7cff460e2d9f..2957bebf3e19 100644 --- a/src/Servers/Kestrel/Transport.Libuv/test/LibuvOutputConsumerTests.cs +++ b/src/Servers/Kestrel/Transport.Libuv/test/LibuvOutputConsumerTests.cs @@ -18,6 +18,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal.Networking; using Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Tests.TestHelpers; using Microsoft.AspNetCore.Testing; +using Microsoft.Extensions.Logging.Abstractions; using Moq; using Xunit; @@ -732,13 +733,12 @@ private LibuvOuputProcessor CreateOutputProducer(PipeOptions pipeOptions, Cancel { var pair = DuplexPipe.CreateConnectionPair(pipeOptions, pipeOptions); - var logger = new TestApplicationErrorLogger(); var serviceContext = new TestServiceContext { - Log = new TestKestrelTrace(logger), + Log = new KestrelTrace(NullLoggerFactory.Instance), Scheduler = PipeScheduler.Inline }; - var transportContext = new TestLibuvTransportContext { Log = new LibuvTrace(logger) }; + var transportContext = new TestLibuvTransportContext { Log = new LibuvTrace(NullLogger.Instance) }; var socket = new MockSocket(_mockLibuv, _libuvThread.Loop.ThreadId, transportContext.Log); var consumer = new LibuvOutputConsumer(pair.Application.Input, _libuvThread, socket, "0", transportContext.Log); diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/HeaderCollectionBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/HeaderCollectionBenchmark.cs index 8586292139b0..1f5910e0eb0f 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/HeaderCollectionBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/HeaderCollectionBenchmark.cs @@ -332,8 +332,7 @@ public void Setup() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: _dateHeaderValueManager, - log: new MockTrace()); + dateHeaderValueManager: _dateHeaderValueManager); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Http1LargeWritingBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Http1LargeWritingBenchmark.cs index 1275d200e42a..82f0d426125b 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Http1LargeWritingBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Http1LargeWritingBenchmark.cs @@ -71,8 +71,7 @@ private TestHttp1Connection MakeHttp1Connection() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: new DateHeaderValueManager(), - log: new MockTrace()); + dateHeaderValueManager: new DateHeaderValueManager()); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Http1ReadingBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Http1ReadingBenchmark.cs index b83ca8448621..b85256194089 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Http1ReadingBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Http1ReadingBenchmark.cs @@ -100,8 +100,7 @@ private TestHttp1Connection MakeHttp1Connection() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: new DateHeaderValueManager(), - log: new MockTrace()); + dateHeaderValueManager: new DateHeaderValueManager()); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Http1WritingBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Http1WritingBenchmark.cs index 306512ee75a4..3ca4c1124048 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Http1WritingBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Http1WritingBenchmark.cs @@ -105,8 +105,7 @@ private TestHttp1Connection MakeHttp1Connection() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: new DateHeaderValueManager(), - log: new MockTrace()); + dateHeaderValueManager: new DateHeaderValueManager()); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2ConnectionBenchmarkBase.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2ConnectionBenchmarkBase.cs index 561e5ed001ad..50749e772f42 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2ConnectionBenchmarkBase.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2ConnectionBenchmarkBase.cs @@ -61,8 +61,7 @@ public virtual void GlobalSetup() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), dateHeaderValueManager: new DateHeaderValueManager(), - systemClock: new MockSystemClock(), - log: new MockTrace()); + systemClock: new MockSystemClock()); serviceContext.DateHeaderValueManager.OnHeartbeat(default); var connectionContext = TestContextFactory.CreateHttpConnectionContext( diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2FrameWriterBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2FrameWriterBenchmark.cs index b1da9ce2d783..cf797e4b8d6d 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2FrameWriterBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Http2/Http2FrameWriterBenchmark.cs @@ -32,8 +32,7 @@ public void GlobalSetup() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: new DateHeaderValueManager(), - log: new MockTrace()); + dateHeaderValueManager: new DateHeaderValueManager()); _frameWriter = new Http2FrameWriter( new NullPipeWriter(), diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Http3/Http3ConnectionBenchmarkBase.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Http3/Http3ConnectionBenchmarkBase.cs index a932a7d7d374..0f150f6808c6 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Http3/Http3ConnectionBenchmarkBase.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Http3/Http3ConnectionBenchmarkBase.cs @@ -56,8 +56,7 @@ public virtual void GlobalSetup() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), dateHeaderValueManager: new DateHeaderValueManager(), - systemClock: new MockSystemClock(), - log: new MockTrace()); + systemClock: new MockSystemClock()); serviceContext.DateHeaderValueManager.OnHeartbeat(default); var mockSystemClock = new Microsoft.AspNetCore.Testing.MockSystemClock(); diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/HttpProtocolFeatureCollection.cs b/src/Servers/Kestrel/perf/Microbenchmarks/HttpProtocolFeatureCollection.cs index 53f53df6e27f..9f0b2371873f 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/HttpProtocolFeatureCollection.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/HttpProtocolFeatureCollection.cs @@ -233,8 +233,7 @@ public HttpProtocolFeatureCollection() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: new DateHeaderValueManager(), - log: new MockTrace()); + dateHeaderValueManager: new DateHeaderValueManager()); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Microsoft.AspNetCore.Server.Kestrel.Microbenchmarks.csproj b/src/Servers/Kestrel/perf/Microbenchmarks/Microsoft.AspNetCore.Server.Kestrel.Microbenchmarks.csproj index f7bfa926cc67..5d99ee07c22f 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Microsoft.AspNetCore.Server.Kestrel.Microbenchmarks.csproj +++ b/src/Servers/Kestrel/perf/Microbenchmarks/Microsoft.AspNetCore.Server.Kestrel.Microbenchmarks.csproj @@ -19,7 +19,6 @@ - diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/Mocks/MockTrace.cs b/src/Servers/Kestrel/perf/Microbenchmarks/Mocks/MockTrace.cs deleted file mode 100644 index 7a87e2ee4041..000000000000 --- a/src/Servers/Kestrel/perf/Microbenchmarks/Mocks/MockTrace.cs +++ /dev/null @@ -1,75 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Net.Http; -using System.Net.Http.HPack; -using System.Net.Http.QPack; -using Microsoft.AspNetCore.Connections; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; -using Microsoft.Extensions.Logging; - -namespace Microsoft.AspNetCore.Server.Kestrel.Microbenchmarks -{ - internal class MockTrace : IKestrelTrace - { - public void ApplicationError(string connectionId, string requestId, Exception ex) { } - public IDisposable BeginScope(TState state) => null; - public void ConnectionAccepted(string connectionId) { } - public void ConnectionBadRequest(string connectionId, Microsoft.AspNetCore.Http.BadHttpRequestException ex) { } - public void ConnectionDisconnect(string connectionId) { } - public void ConnectionError(string connectionId, Exception ex) { } - public void ConnectionHeadResponseBodyWrite(string connectionId, long count) { } - public void ConnectionKeepAlive(string connectionId) { } - public void ConnectionPause(string connectionId) { } - public void ConnectionRead(string connectionId, int count) { } - public void ConnectionReadFin(string connectionId) { } - public void ConnectionReset(string connectionId) { } - public void ConnectionResume(string connectionId) { } - public void ConnectionRejected(string connectionId) { } - public void ConnectionStart(string connectionId) { } - public void ConnectionStop(string connectionId) { } - public void ConnectionWrite(string connectionId, int count) { } - public void ConnectionWriteCallback(string connectionId, int status) { } - public void ConnectionWriteFin(string connectionId) { } - public void ConnectionWroteFin(string connectionId, int status) { } - public bool IsEnabled(LogLevel logLevel) => false; - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { } - public void NotAllConnectionsAborted() { } - public void NotAllConnectionsClosedGracefully() { } - public void RequestProcessingError(string connectionId, Exception ex) { } - public void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now) { } - public void ApplicationNeverCompleted(string connectionId) { } - public void RequestBodyStart(string connectionId, string traceIdentifier) { } - public void RequestBodyDone(string connectionId, string traceIdentifier) { } - public void RequestBodyNotEntirelyRead(string connectionId, string traceIdentifier) { } - public void RequestBodyDrainTimedOut(string connectionId, string traceIdentifier) { } - public void RequestBodyMinimumDataRateNotSatisfied(string connectionId, string traceIdentifier, double rate) { } - public void ResponseMinimumDataRateNotSatisfied(string connectionId, string traceIdentifier) { } - public void ApplicationAbortedConnection(string connectionId, string traceIdentifier) { } - public void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex) { } - public void Http2StreamError(string connectionId, Http2StreamErrorException ex) { } - public void HPackDecodingError(string connectionId, int streamId, Exception ex) { } - public void HPackEncodingError(string connectionId, int streamId, Exception ex) { } - public void Http2StreamResetAbort(string traceIdentifier, Http2ErrorCode error, ConnectionAbortedException abortReason) { } - public void Http2ConnectionClosing(string connectionId) { } - public void Http2ConnectionClosed(string connectionId, int highestOpenedStreamId) { } - public void Http2FrameReceived(string connectionId, Http2Frame frame) { } - public void Http2FrameSending(string connectionId, Http2Frame frame) { } - public void Http2MaxConcurrentStreamsReached(string connectionId) { } - public void InvalidResponseHeaderRemoved() { } - public void Http3ConnectionError(string connectionId, Http3ConnectionErrorException ex) { } - public void Http3ConnectionClosing(string connectionId) { } - public void Http3ConnectionClosed(string connectionId, long? highestOpenedStreamId) { } - public void Http3StreamAbort(string traceIdentifier, Http3ErrorCode error, ConnectionAbortedException abortReason) { } - public void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame) { } - public void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame) { } - public void QPackDecodingError(string connectionId, long streamId, Exception ex) { } - public void QPackEncodingError(string connectionId, long streamId, Exception ex) { } - public void Http3OutboundControlStreamError(string connectionId, Exception ex) { } - public void Http3GoAwayStreamId(string connectionId, long goAwayStreamId) { } - } -} diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/RequestParsingBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/RequestParsingBenchmark.cs index 5c10a5585e39..9918e22ec537 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/RequestParsingBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/RequestParsingBenchmark.cs @@ -31,8 +31,7 @@ public void Setup() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: new DateHeaderValueManager(), - log: new MockTrace()); + dateHeaderValueManager: new DateHeaderValueManager()); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/perf/Microbenchmarks/ResponseHeaderCollectionBenchmark.cs b/src/Servers/Kestrel/perf/Microbenchmarks/ResponseHeaderCollectionBenchmark.cs index e8f353d21d83..6b754bc38e0b 100644 --- a/src/Servers/Kestrel/perf/Microbenchmarks/ResponseHeaderCollectionBenchmark.cs +++ b/src/Servers/Kestrel/perf/Microbenchmarks/ResponseHeaderCollectionBenchmark.cs @@ -179,8 +179,7 @@ public void Setup() var serviceContext = TestContextFactory.CreateServiceContext( serverOptions: new KestrelServerOptions(), httpParser: new HttpParser(), - dateHeaderValueManager: _dateHeaderValueManager, - log: new MockTrace()); + dateHeaderValueManager: _dateHeaderValueManager); var connectionContext = TestContextFactory.CreateHttpConnectionContext( serviceContext: serviceContext, diff --git a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs deleted file mode 100644 index 523e77a059ac..000000000000 --- a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs +++ /dev/null @@ -1,309 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System; -using System.Net.Http; -using System.Net.Http.HPack; -using System.Net.Http.QPack; -using Microsoft.AspNetCore.Connections; -using Microsoft.AspNetCore.Server.Kestrel.Core; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http2; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3; -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; -using Microsoft.Extensions.Logging; - -namespace Microsoft.AspNetCore.Testing -{ - internal class CompositeKestrelTrace : IKestrelTrace - { - private readonly IKestrelTrace _trace1; - private readonly IKestrelTrace _trace2; - - public CompositeKestrelTrace(IKestrelTrace kestrelTrace, KestrelTrace kestrelTrace1) - { - _trace1 = kestrelTrace; - _trace2 = kestrelTrace1; - } - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) - { - _trace1.Log(logLevel, eventId, state, exception, formatter); - _trace2.Log(logLevel, eventId, state, exception, formatter); - } - - public bool IsEnabled(LogLevel logLevel) - { - return _trace1.IsEnabled(logLevel) || _trace2.IsEnabled(logLevel); - } - - public void ConnectionAccepted(string connectionId) - { - _trace1.ConnectionAccepted(connectionId); - _trace2.ConnectionAccepted(connectionId); - } - - public IDisposable BeginScope(TState state) - { - return _trace1.BeginScope(state); - } - - public void ConnectionStart(string connectionId) - { - _trace1.ConnectionStart(connectionId); - _trace2.ConnectionStart(connectionId); - } - - public void ConnectionStop(string connectionId) - { - _trace1.ConnectionStop(connectionId); - _trace2.ConnectionStop(connectionId); - } - - public void ConnectionPause(string connectionId) - { - _trace1.ConnectionPause(connectionId); - _trace2.ConnectionPause(connectionId); - } - - public void ConnectionResume(string connectionId) - { - _trace1.ConnectionResume(connectionId); - _trace2.ConnectionResume(connectionId); - } - - public void ConnectionRejected(string connectionId) - { - _trace1.ConnectionRejected(connectionId); - _trace2.ConnectionRejected(connectionId); - } - - public void ConnectionKeepAlive(string connectionId) - { - _trace1.ConnectionKeepAlive(connectionId); - _trace2.ConnectionKeepAlive(connectionId); - } - - public void ConnectionDisconnect(string connectionId) - { - _trace1.ConnectionDisconnect(connectionId); - _trace2.ConnectionDisconnect(connectionId); - } - - public void RequestProcessingError(string connectionId, Exception ex) - { - _trace1.RequestProcessingError(connectionId, ex); - _trace2.RequestProcessingError(connectionId, ex); - } - - public void ConnectionHeadResponseBodyWrite(string connectionId, long count) - { - _trace1.ConnectionHeadResponseBodyWrite(connectionId, count); - _trace2.ConnectionHeadResponseBodyWrite(connectionId, count); - } - - public void NotAllConnectionsClosedGracefully() - { - _trace1.NotAllConnectionsClosedGracefully(); - _trace2.NotAllConnectionsClosedGracefully(); - } - - public void ConnectionBadRequest(string connectionId, Microsoft.AspNetCore.Http.BadHttpRequestException ex) - { - _trace1.ConnectionBadRequest(connectionId, ex); - _trace2.ConnectionBadRequest(connectionId, ex); - } - - public void ApplicationError(string connectionId, string traceIdentifier, Exception ex) - { - _trace1.ApplicationError(connectionId, traceIdentifier, ex); - _trace2.ApplicationError(connectionId, traceIdentifier, ex); - } - - public void NotAllConnectionsAborted() - { - _trace1.NotAllConnectionsAborted(); - _trace2.NotAllConnectionsAborted(); - } - - public void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now) - { - _trace1.HeartbeatSlow(heartbeatDuration, interval, now); - _trace2.HeartbeatSlow(heartbeatDuration, interval, now); - } - - public void ApplicationNeverCompleted(string connectionId) - { - _trace1.ApplicationNeverCompleted(connectionId); - _trace2.ApplicationNeverCompleted(connectionId); - } - - public void RequestBodyStart(string connectionId, string traceIdentifier) - { - _trace1.RequestBodyStart(connectionId, traceIdentifier); - _trace2.RequestBodyStart(connectionId, traceIdentifier); - } - - public void RequestBodyDone(string connectionId, string traceIdentifier) - { - _trace1.RequestBodyDone(connectionId, traceIdentifier); - _trace2.RequestBodyDone(connectionId, traceIdentifier); - } - - public void RequestBodyNotEntirelyRead(string connectionId, string traceIdentifier) - { - _trace1.RequestBodyNotEntirelyRead(connectionId, traceIdentifier); - _trace2.RequestBodyNotEntirelyRead(connectionId, traceIdentifier); - } - - public void RequestBodyDrainTimedOut(string connectionId, string traceIdentifier) - { - _trace1.RequestBodyDrainTimedOut(connectionId, traceIdentifier); - _trace2.RequestBodyDrainTimedOut(connectionId, traceIdentifier); - } - - public void RequestBodyMinimumDataRateNotSatisfied(string connectionId, string traceIdentifier, double rate) - { - _trace1.RequestBodyMinimumDataRateNotSatisfied(connectionId, traceIdentifier, rate); - _trace2.RequestBodyMinimumDataRateNotSatisfied(connectionId, traceIdentifier, rate); - } - - public void ResponseMinimumDataRateNotSatisfied(string connectionId, string traceIdentifier) - { - _trace1.ResponseMinimumDataRateNotSatisfied(connectionId, traceIdentifier); - _trace2.ResponseMinimumDataRateNotSatisfied(connectionId, traceIdentifier); - } - - public void ApplicationAbortedConnection(string connectionId, string traceIdentifier) - { - _trace1.ApplicationAbortedConnection(connectionId, traceIdentifier); - _trace2.ApplicationAbortedConnection(connectionId, traceIdentifier); - } - - public void Http2ConnectionError(string connectionId, Http2ConnectionErrorException ex) - { - _trace1.Http2ConnectionError(connectionId, ex); - _trace2.Http2ConnectionError(connectionId, ex); - } - - public void Http2StreamError(string connectionId, Http2StreamErrorException ex) - { - _trace1.Http2StreamError(connectionId, ex); - _trace2.Http2StreamError(connectionId, ex); - } - - public void HPackDecodingError(string connectionId, int streamId, Exception ex) - { - _trace1.HPackDecodingError(connectionId, streamId, ex); - _trace2.HPackDecodingError(connectionId, streamId, ex); - } - - public void HPackEncodingError(string connectionId, int streamId, Exception ex) - { - _trace1.HPackEncodingError(connectionId, streamId, ex); - _trace2.HPackEncodingError(connectionId, streamId, ex); - } - - public void Http2StreamResetAbort(string traceIdentifier, Http2ErrorCode error, ConnectionAbortedException abortReason) - { - _trace1.Http2StreamResetAbort(traceIdentifier, error, abortReason); - _trace2.Http2StreamResetAbort(traceIdentifier, error, abortReason); - } - - public void Http2ConnectionClosing(string connectionId) - { - _trace1.Http2ConnectionClosing(connectionId); - _trace2.Http2ConnectionClosing(connectionId); - } - - public void Http2ConnectionClosed(string connectionId, int highestOpenedStreamId) - { - _trace1.Http2ConnectionClosed(connectionId, highestOpenedStreamId); - _trace2.Http2ConnectionClosed(connectionId, highestOpenedStreamId); - } - - public void Http2FrameReceived(string connectionId, Http2Frame frame) - { - _trace1.Http2FrameReceived(connectionId, frame); - _trace2.Http2FrameReceived(connectionId, frame); - } - - public void Http2FrameSending(string connectionId, Http2Frame frame) - { - _trace1.Http2FrameSending(connectionId, frame); - _trace2.Http2FrameSending(connectionId, frame); - } - - public void Http2MaxConcurrentStreamsReached(string connectionId) - { - _trace1.Http2MaxConcurrentStreamsReached(connectionId); - _trace2.Http2MaxConcurrentStreamsReached(connectionId); - } - - public void InvalidResponseHeaderRemoved() - { - _trace1.InvalidResponseHeaderRemoved(); - _trace2.InvalidResponseHeaderRemoved(); - } - - public void Http3ConnectionError(string connectionId, Http3ConnectionErrorException ex) - { - _trace1.Http3ConnectionError(connectionId, ex); - _trace2.Http3ConnectionError(connectionId, ex); - } - - public void Http3ConnectionClosing(string connectionId) - { - _trace1.Http3ConnectionClosing(connectionId); - _trace2.Http3ConnectionClosing(connectionId); - } - - public void Http3ConnectionClosed(string connectionId, long? highestOpenedStreamId) - { - _trace1.Http3ConnectionClosed(connectionId, highestOpenedStreamId); - _trace2.Http3ConnectionClosed(connectionId, highestOpenedStreamId); - } - - public void Http3StreamAbort(string traceIdentifier, Http3ErrorCode error, ConnectionAbortedException abortReason) - { - _trace1.Http3StreamAbort(traceIdentifier, error, abortReason); - _trace2.Http3StreamAbort(traceIdentifier, error, abortReason); - } - - public void Http3FrameReceived(string connectionId, long streamId, Http3RawFrame frame) - { - _trace1.Http3FrameReceived(connectionId, streamId, frame); - _trace1.Http3FrameReceived(connectionId, streamId, frame); - } - - public void Http3FrameSending(string connectionId, long streamId, Http3RawFrame frame) - { - _trace1.Http3FrameSending(connectionId, streamId, frame); - _trace2.Http3FrameSending(connectionId, streamId, frame); - } - - public void QPackDecodingError(string connectionId, long streamId, Exception ex) - { - _trace1.QPackDecodingError(connectionId, streamId, ex); - _trace2.QPackDecodingError(connectionId, streamId, ex); - } - - public void QPackEncodingError(string connectionId, long streamId, Exception ex) - { - _trace1.QPackEncodingError(connectionId, streamId, ex); - _trace2.QPackEncodingError(connectionId, streamId, ex); - } - - public void Http3OutboundControlStreamError(string connectionId, Exception ex) - { - _trace1.Http3OutboundControlStreamError(connectionId, ex); - _trace2.Http3OutboundControlStreamError(connectionId, ex); - } - - public void Http3GoAwayStreamId(string connectionId, long goAwayStreamId) - { - _trace1.Http3GoAwayStreamId(connectionId, goAwayStreamId); - _trace2.Http3GoAwayStreamId(connectionId, goAwayStreamId); - } - } -} diff --git a/src/Servers/Kestrel/shared/test/TestContextFactory.cs b/src/Servers/Kestrel/shared/test/TestContextFactory.cs index 6bda9867fbe8..9f470f871f9a 100644 --- a/src/Servers/Kestrel/shared/test/TestContextFactory.cs +++ b/src/Servers/Kestrel/shared/test/TestContextFactory.cs @@ -18,6 +18,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http3; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Microsoft.AspNetCore.Testing { @@ -26,7 +27,6 @@ internal static class TestContextFactory public static ServiceContext CreateServiceContext( KestrelServerOptions serverOptions, IHttpParser httpParser = null, - IKestrelTrace log = null, PipeScheduler scheduler = null, ISystemClock systemClock = null, DateHeaderValueManager dateHeaderValueManager = null, @@ -35,7 +35,7 @@ public static ServiceContext CreateServiceContext( { var context = new ServiceContext { - Log = log, + Log = new KestrelTrace(NullLoggerFactory.Instance), Scheduler = scheduler, HttpParser = httpParser, SystemClock = systemClock, diff --git a/src/Servers/Kestrel/shared/test/TestKestrelTrace.cs b/src/Servers/Kestrel/shared/test/TestKestrelTrace.cs deleted file mode 100644 index f8be90711c11..000000000000 --- a/src/Servers/Kestrel/shared/test/TestKestrelTrace.cs +++ /dev/null @@ -1,28 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; -using Microsoft.Extensions.Logging; - -namespace Microsoft.AspNetCore.Testing -{ - internal class TestKestrelTrace : KestrelTrace - { - public TestKestrelTrace() : this(new TestApplicationErrorLogger()) - { - } - - public TestKestrelTrace(TestApplicationErrorLogger testLogger) : this(new LoggerFactory(new[] { new KestrelTestLoggerProvider(testLogger) })) - { - Logger = testLogger; - } - - private TestKestrelTrace(ILoggerFactory loggerFactory) : base(loggerFactory) - { - LoggerFactory = loggerFactory; - } - - public TestApplicationErrorLogger Logger { get; } - public ILoggerFactory LoggerFactory { get; } - } -} diff --git a/src/Servers/Kestrel/shared/test/TestServiceContext.cs b/src/Servers/Kestrel/shared/test/TestServiceContext.cs index 6825840ba012..2e7507c5bf5d 100644 --- a/src/Servers/Kestrel/shared/test/TestServiceContext.cs +++ b/src/Servers/Kestrel/shared/test/TestServiceContext.cs @@ -9,6 +9,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; namespace Microsoft.AspNetCore.Testing { @@ -16,10 +17,7 @@ internal class TestServiceContext : ServiceContext { public TestServiceContext() { - var logger = new TestApplicationErrorLogger(); - var kestrelTrace = new TestKestrelTrace(logger); - - Initialize(kestrelTrace.LoggerFactory, kestrelTrace); + Initialize(NullLoggerFactory.Instance, CreateLoggingTrace(NullLoggerFactory.Instance)); } public TestServiceContext(ILoggerFactory loggerFactory) @@ -27,9 +25,9 @@ public TestServiceContext(ILoggerFactory loggerFactory) Initialize(loggerFactory, CreateLoggingTrace(loggerFactory)); } - public TestServiceContext(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace) + public TestServiceContext(ILoggerFactory loggerFactory, KestrelTrace kestrelTrace) { - Initialize(loggerFactory, new CompositeKestrelTrace(kestrelTrace, CreateLoggingTrace(loggerFactory))); + Initialize(loggerFactory, kestrelTrace); } private static KestrelTrace CreateLoggingTrace(ILoggerFactory loggerFactory) @@ -51,7 +49,7 @@ public void InitializeHeartbeat() SystemClock = heartbeatManager; } - private void Initialize(ILoggerFactory loggerFactory, IKestrelTrace kestrelTrace) + private void Initialize(ILoggerFactory loggerFactory, KestrelTrace kestrelTrace) { LoggerFactory = loggerFactory; Log = kestrelTrace; diff --git a/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs b/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs index 1a12f4629e44..eec66a626d85 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/Http2/ShutdownTests.cs @@ -53,15 +53,17 @@ public async Task GracefulShutdownWaitsForRequestsToFinish() var requestStarted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var requestUnblocked = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var requestStopping = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(LoggerFactory) + + TestSink.MessageLogged += context => { - CallBase = true + + if (context.EventId.Name == "Http2ConnectionClosing") + { + requestStopping.SetResult(); + } }; - mockKestrelTrace - .Setup(m => m.Http2ConnectionClosing(It.IsAny())) - .Callback(() => requestStopping.SetResult()); - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object); + var testContext = new TestServiceContext(LoggerFactory); testContext.InitializeHeartbeat(); diff --git a/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs b/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs index ff6df725c4ba..a8c5cbb6b570 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/RequestTests.cs @@ -762,8 +762,7 @@ public async Task ServerCanAbortConnectionAfterUnobservedClose(string listenOpti } }; - var mockKestrelTrace = new Mock(); - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -809,7 +808,7 @@ await connection.Send( await appFuncCompleted.Task.DefaultTimeout(); } - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); + Assert.Single(TestSink.Writes.Where(c => c.EventId.Name == "ConnectionStop")); } [Theory] @@ -820,8 +819,7 @@ public async Task AppCanHandleClientAbortingConnectionMidRequest(string listenOp var readTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var appStartedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object); + var testContext = new TestServiceContext(LoggerFactory); var scratchBuffer = new byte[4096]; @@ -862,7 +860,7 @@ await connection.Send( await Assert.ThrowsAnyAsync(() => readTcs.Task).DefaultTimeout(); } - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); + Assert.Single(TestSink.Writes.Where(c => c.EventId.Name == "ConnectionStop")); } private async Task TestRemoteIPAddress(string registerAddress, string requestAddress, string expectAddress) diff --git a/src/Servers/Kestrel/test/FunctionalTests/ResponseTests.cs b/src/Servers/Kestrel/test/FunctionalTests/ResponseTests.cs index d869ac551251..1cb635a95cbf 100644 --- a/src/Servers/Kestrel/test/FunctionalTests/ResponseTests.cs +++ b/src/Servers/Kestrel/test/FunctionalTests/ResponseTests.cs @@ -287,9 +287,7 @@ public async Task WritingToConnectionAfterUnobservedCloseTriggersRequestAbortedT } }; - var mockKestrelTrace = new Mock(); - - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -351,7 +349,7 @@ await connection.Send( await Assert.ThrowsAnyAsync(() => writeTcs.Task).DefaultTimeout(); } - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); + Assert.Equal(1, TestSink.Writes.Count(w => w.EventId.Name == "ConnectionStop")); Assert.True(requestAborted.Task.IsCompleted); } @@ -479,15 +477,19 @@ public async Task ConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate() var requestAborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - mockKestrelTrace - .Setup(trace => trace.ResponseMinimumDataRateNotSatisfied(It.IsAny(), It.IsAny())) - .Callback(() => responseRateTimeoutMessageLogged.SetResult()); - mockKestrelTrace - .Setup(trace => trace.ConnectionStop(It.IsAny())) - .Callback(() => connectionStopMessageLogged.SetResult()); + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ResponseMinimumDataRateNotSatisfied") + { + responseRateTimeoutMessageLogged.SetResult(); + } + if (context.EventId.Name == "ConnectionStop") + { + connectionStopMessageLogged.SetResult(); + } + }; - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -579,15 +581,19 @@ public async Task HttpsConnectionClosedWhenResponseDoesNotSatisfyMinimumDataRate var aborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var appFuncCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - mockKestrelTrace - .Setup(trace => trace.ResponseMinimumDataRateNotSatisfied(It.IsAny(), It.IsAny())) - .Callback(() => responseRateTimeoutMessageLogged.SetResult()); - mockKestrelTrace - .Setup(trace => trace.ConnectionStop(It.IsAny())) - .Callback(() => connectionStopMessageLogged.SetResult()); + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ResponseMinimumDataRateNotSatisfied") + { + responseRateTimeoutMessageLogged.SetResult(); + } + if (context.EventId.Name == "ConnectionStop") + { + connectionStopMessageLogged.SetResult(); + } + }; - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -666,15 +672,19 @@ public async Task ConnectionClosedWhenBothRequestAndResponseExperienceBackPressu var requestAborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var copyToAsyncCts = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - mockKestrelTrace - .Setup(trace => trace.ResponseMinimumDataRateNotSatisfied(It.IsAny(), It.IsAny())) - .Callback(() => responseRateTimeoutMessageLogged.SetResult()); - mockKestrelTrace - .Setup(trace => trace.ConnectionStop(It.IsAny())) - .Callback(() => connectionStopMessageLogged.SetResult()); + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ResponseMinimumDataRateNotSatisfied") + { + responseRateTimeoutMessageLogged.SetResult(); + } + if (context.EventId.Name == "ConnectionStop") + { + connectionStopMessageLogged.SetResult(); + } + }; - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -756,9 +766,8 @@ public async Task ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLarg var requestAborted = false; var appFuncCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -819,8 +828,8 @@ await connection.Receive( } } - mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny(), It.IsAny()), Times.Never()); - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); + Assert.Equal(0, TestSink.Writes.Count(w => w.EventId.Name == "ResponseMinimumDataRateNotSatisfied")); + Assert.Equal(1, TestSink.Writes.Count(w => w.EventId.Name == "ConnectionStop")); Assert.False(requestAborted); } @@ -836,9 +845,8 @@ public async Task ConnectionNotClosedWhenClientSatisfiesMinimumDataRateGivenLarg var headerStringValues = new StringValues(Enumerable.Repeat(headerValue, headerCount).ToArray()); var requestAborted = false; - var mockKestrelTrace = new Mock(); - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -907,8 +915,8 @@ await connection.Receive( } } - mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny(), It.IsAny()), Times.Never()); - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); + Assert.Equal(0, TestSink.Writes.Count(w => w.EventId.Name == "ResponseMinimumDataRateNotSatisfied")); + Assert.Equal(1, TestSink.Writes.Count(w => w.EventId.Name == "ConnectionStop")); Assert.False(requestAborted); } @@ -921,9 +929,8 @@ public async Task ClientCanReceiveFullConnectionCloseResponseWithoutErrorAtALowD var requestAborted = false; var appFuncCompleted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - var testContext = new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) + var testContext = new TestServiceContext(LoggerFactory) { ServerOptions = { @@ -983,8 +990,8 @@ await connection.Receive( } } - mockKestrelTrace.Verify(t => t.ResponseMinimumDataRateNotSatisfied(It.IsAny(), It.IsAny()), Times.Never()); - mockKestrelTrace.Verify(t => t.ConnectionStop(It.IsAny()), Times.Once()); + Assert.Equal(0, TestSink.Writes.Count(w => w.EventId.Name == "ResponseMinimumDataRateNotSatisfied")); + Assert.Equal(1, TestSink.Writes.Count(w => w.EventId.Name == "ConnectionStop")); Assert.False(requestAborted); } diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/BadHttpRequestTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/BadHttpRequestTests.cs index fffb7b89eb1b..d8e12ee94554 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/BadHttpRequestTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/BadHttpRequestTests.cs @@ -224,13 +224,13 @@ private async Task TestBadRequest(string request, string expectedResponseStatusC { BadHttpRequestException loggedException = null; - var mockKestrelTrace = new Mock(); - mockKestrelTrace - .Setup(trace => trace.IsEnabled(LogLevel.Information)) - .Returns(true); - mockKestrelTrace - .Setup(trace => trace.ConnectionBadRequest(It.IsAny(), It.IsAny())) - .Callback((connectionId, exception) => loggedException = exception); + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ConnectionBadRequest" && context.Exception is BadHttpRequestException ex) + { + loggedException = ex; + } + }; // Set up a listener to catch the BadRequest event var diagListener = new DiagnosticListener("BadRequestTestsDiagListener"); @@ -246,7 +246,7 @@ private async Task TestBadRequest(string request, string expectedResponseStatusC } }); - await using (var server = new TestServer(context => Task.CompletedTask, new TestServiceContext(LoggerFactory, mockKestrelTrace.Object) { DiagnosticSource = diagListener })) + await using (var server = new TestServer(context => Task.CompletedTask, new TestServiceContext(LoggerFactory) { DiagnosticSource = diagListener })) { using (var connection = server.CreateConnection()) { @@ -255,7 +255,7 @@ private async Task TestBadRequest(string request, string expectedResponseStatusC } } - mockKestrelTrace.Verify(trace => trace.ConnectionBadRequest(It.IsAny(), It.IsAny())); + Assert.NotNull(loggedException); Assert.Equal(expectedExceptionMessage, loggedException.Message); // Verify DiagnosticSource event for bad request diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs index e0d92c63c8bb..061a414a4dd0 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/Http2/Http2TestBase.cs @@ -127,7 +127,6 @@ protected static IEnumerable> ReadRateRequestHeader private readonly byte[] _headerEncodingBuffer = new byte[Http2PeerSettings.MinAllowedMaxFrameSize]; internal readonly TimeoutControl _timeoutControl; - internal readonly Mock _mockKestrelTrace = new Mock(); protected readonly Mock _mockConnectionContext = new Mock(); internal readonly Mock _mockTimeoutHandler = new Mock(); internal readonly Mock _mockTimeoutControl; @@ -175,13 +174,6 @@ public Http2TestBase() _mockTimeoutControl = new Mock(_timeoutControl) { CallBase = true }; _timeoutControl.Debugger = Mock.Of(); - _mockKestrelTrace - .Setup(m => m.Http2ConnectionClosing(It.IsAny())) - .Callback(() => _closingStateReached.SetResult()); - _mockKestrelTrace - .Setup(m => m.Http2ConnectionClosed(It.IsAny(), It.IsAny())) - .Callback(() => _closedStateReached.SetResult()); - _mockConnectionContext.Setup(c => c.Abort(It.IsAny())).Callback(ex => { // Emulate transport abort so the _connectionTask completes. @@ -401,10 +393,22 @@ public override void Initialize(TestContext context, MethodInfo methodInfo, obje { base.Initialize(context, methodInfo, testMethodArguments, testOutputHelper); - _serviceContext = new TestServiceContext(LoggerFactory, _mockKestrelTrace.Object) + _serviceContext = new TestServiceContext(LoggerFactory) { Scheduler = PipeScheduler.Inline, }; + + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "Http2ConnectionClosing") + { + _closingStateReached.SetResult(); + } + if (context.EventId.Name == "Http2ConnectionClosed") + { + _closedStateReached.SetResult(); + } + }; } public override void Dispose() diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpConnectionManagerTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpConnectionManagerTests.cs index db2b0751a7be..c90903d4785f 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpConnectionManagerTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/HttpConnectionManagerTests.cs @@ -31,15 +31,20 @@ public async Task CriticalErrorLoggedIfApplicationDoesntComplete() var logWh = new SemaphoreSlim(0); var appStartedWh = new SemaphoreSlim(0); - var mockTrace = new Mock(LoggerFactory) { CallBase = true }; - mockTrace - .Setup(trace => trace.ApplicationNeverCompleted(It.IsAny())) - .Callback(() => + var factory = new LoggerFactory(); + + // Use a custom logger for callback instead of TestSink because TestSink keeps references + // to types when logging, prevents garbage collection, and makes the test fail. + factory.AddProvider(new CallbackLoggerProvider(eventId => + { + if (eventId.Name == "ApplicationNeverCompleted") { + Logger.LogInformation("Releasing ApplicationNeverCompleted log wait handle."); logWh.Release(); - }); + } + })); - var testContext = new TestServiceContext(new LoggerFactory(), mockTrace.Object); + var testContext = new TestServiceContext(factory); testContext.InitializeHeartbeat(); await using (var server = new TestServer(context => @@ -70,6 +75,40 @@ public async Task CriticalErrorLoggedIfApplicationDoesntComplete() Assert.True(logWaitAttempts < 10); } } + + private class CallbackLoggerProvider : ILoggerProvider + { + private readonly Action _logAction; + + public CallbackLoggerProvider(Action logAction) + { + _logAction = logAction; + } + + public ILogger CreateLogger(string categoryName) => new CallbackLogger(_logAction); + + public void Dispose() + { + } + + private class CallbackLogger : ILogger + { + private readonly Action _logAction; + + public CallbackLogger(Action logAction) + { + _logAction = logAction; + } + + public IDisposable BeginScope(TState state) => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) + { + _logAction(eventId); + } + } + } #endif private class NoDebuggerConditionAttribute : Attribute, ITestCondition diff --git a/src/Servers/Kestrel/test/InMemory.FunctionalTests/ResponseTests.cs b/src/Servers/Kestrel/test/InMemory.FunctionalTests/ResponseTests.cs index bb40ed8fd2ae..f106f93683e6 100644 --- a/src/Servers/Kestrel/test/InMemory.FunctionalTests/ResponseTests.cs +++ b/src/Servers/Kestrel/test/InMemory.FunctionalTests/ResponseTests.cs @@ -646,16 +646,20 @@ public async Task ResponseBodyNotWrittenOnHeadResponseAndLoggedOnlyOnce() const string response = "hello, world"; var logTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockKestrelTrace = new Mock(); - mockKestrelTrace - .Setup(trace => trace.ConnectionHeadResponseBodyWrite(It.IsAny(), response.Length)) - .Callback((connectionId, count) => logTcs.SetResult()); + + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ConnectionHeadResponseBodyWrite") + { + logTcs.SetResult(); + } + }; await using (var server = new TestServer(async httpContext => { await httpContext.Response.WriteAsync(response); await httpContext.Response.BodyWriter.FlushAsync(); - }, new TestServiceContext(LoggerFactory, mockKestrelTrace.Object))) + }, new TestServiceContext(LoggerFactory))) { using (var connection = server.CreateConnection()) { @@ -677,8 +681,11 @@ await connection.Receive( } } - mockKestrelTrace.Verify(kestrelTrace => - kestrelTrace.ConnectionHeadResponseBodyWrite(It.IsAny(), response.Length), Times.Once); + var logMessage = Assert.Single(LogMessages, message => message.EventId.Name == "ConnectionHeadResponseBodyWrite"); + + Assert.Contains( + @"write of ""12"" body bytes to non-body HEAD response.", + logMessage.Message); } [Fact] @@ -719,7 +726,6 @@ await connection.Receive( Assert.Equal( $"Response Content-Length mismatch: too many bytes written (12 of 11).", logMessage.Exception.Message); - } [Fact] @@ -833,19 +839,20 @@ await connection.ReceiveEnd( public async Task WhenAppWritesLessThanContentLengthErrorLogged() { var logTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.ApplicationError(It.IsAny(), It.IsAny(), It.IsAny())) - .Callback((connectionId, requestId, ex) => + + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ApplicationError") { logTcs.SetResult(); - }); + } + }; await using (var server = new TestServer(async httpContext => { httpContext.Response.ContentLength = 13; await httpContext.Response.WriteAsync("hello, world"); - }, new TestServiceContext(LoggerFactory, mockTrace.Object))) + }, new TestServiceContext(LoggerFactory))) { using (var connection = server.CreateConnection()) { @@ -874,12 +881,10 @@ await connection.Receive( } } - mockTrace.Verify(trace => - trace.ApplicationError( - It.IsAny(), - It.IsAny(), - It.Is(ex => - ex.Message.Equals(CoreStrings.FormatTooFewBytesWritten(12, 13), StringComparison.Ordinal)))); + Assert.Contains(TestSink.Writes, + m => m.EventId.Name == "ApplicationError" && + m.Exception is InvalidOperationException ex && + ex.Message.Equals(CoreStrings.FormatTooFewBytesWritten(12, 13), StringComparison.Ordinal)); } [Fact] @@ -888,13 +893,14 @@ public async Task WhenAppWritesLessThanContentLengthCompleteThrowsAndErrorLogged InvalidOperationException completeEx = null; var logTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockTrace = new Mock(); - mockTrace - .Setup(trace => trace.ApplicationError(It.IsAny(), It.IsAny(), It.IsAny())) - .Callback((connectionId, requestId, ex) => + + TestSink.MessageLogged += context => + { + if (context.EventId.Name == "ApplicationError") { logTcs.SetResult(); - }); + } + }; await using (var server = new TestServer(async httpContext => { @@ -903,7 +909,7 @@ public async Task WhenAppWritesLessThanContentLengthCompleteThrowsAndErrorLogged completeEx = Assert.Throws(() => httpContext.Response.BodyWriter.Complete()); - }, new TestServiceContext(LoggerFactory, mockTrace.Object))) + }, new TestServiceContext(LoggerFactory))) { using (var connection = server.CreateConnection()) { @@ -932,12 +938,10 @@ await connection.Receive( } } - mockTrace.Verify(trace => - trace.ApplicationError( - It.IsAny(), - It.IsAny(), - It.Is(ex => - ex.Message.Equals(CoreStrings.FormatTooFewBytesWritten(12, 13), StringComparison.Ordinal)))); + Assert.Contains(TestSink.Writes, + m => m.EventId.Name == "ApplicationError" && + m.Exception is InvalidOperationException ex && + ex.Message.Equals(CoreStrings.FormatTooFewBytesWritten(12, 13), StringComparison.Ordinal)); Assert.NotNull(completeEx); } @@ -946,7 +950,6 @@ await connection.Receive( public async Task WhenAppWritesLessThanContentLengthButRequestIsAbortedErrorNotLogged() { var requestAborted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); - var mockTrace = new Mock(); await using (var server = new TestServer(async httpContext => { @@ -960,7 +963,7 @@ public async Task WhenAppWritesLessThanContentLengthButRequestIsAbortedErrorNotL // Wait until the request is aborted so we know HttpProtocol will skip the response content length check. await requestAborted.Task.DefaultTimeout(); - }, new TestServiceContext(LoggerFactory, mockTrace.Object))) + }, new TestServiceContext(LoggerFactory))) { using (var connection = server.CreateConnection()) { @@ -987,7 +990,7 @@ await connection.Receive( } // With the server disposed we know all connections were drained and all messages were logged. - mockTrace.Verify(trace => trace.ApplicationError(It.IsAny(), It.IsAny(), It.IsAny()), Times.Never); + Assert.Empty(TestSink.Writes.Where(c => c.EventId.Name == "ApplicationError")); } [Fact]