diff --git a/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs b/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs index 1c31f4394c..13ad97fa11 100644 --- a/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Kestrel.Core/Internal/Infrastructure/KestrelTrace.cs @@ -12,70 +12,70 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal public class KestrelTrace : IKestrelTrace { private static readonly Action _connectionStart = - LoggerMessage.Define(LogLevel.Debug, 1, @"Connection id ""{ConnectionId}"" started."); + LoggerMessage.Define(LogLevel.Debug, new EventId(1, nameof(ConnectionStart)), @"Connection id ""{ConnectionId}"" started."); private static readonly Action _connectionStop = - LoggerMessage.Define(LogLevel.Debug, 2, @"Connection id ""{ConnectionId}"" stopped."); + LoggerMessage.Define(LogLevel.Debug, new EventId(2, nameof(ConnectionStop)), @"Connection id ""{ConnectionId}"" stopped."); private static readonly Action _connectionPause = - LoggerMessage.Define(LogLevel.Debug, 4, @"Connection id ""{ConnectionId}"" paused."); + LoggerMessage.Define(LogLevel.Debug, new EventId(4, nameof(ConnectionPause)), @"Connection id ""{ConnectionId}"" paused."); private static readonly Action _connectionResume = - LoggerMessage.Define(LogLevel.Debug, 5, @"Connection id ""{ConnectionId}"" resumed."); + LoggerMessage.Define(LogLevel.Debug, new EventId(5, nameof(ConnectionResume)), @"Connection id ""{ConnectionId}"" resumed."); private static readonly Action _connectionKeepAlive = - LoggerMessage.Define(LogLevel.Debug, 9, @"Connection id ""{ConnectionId}"" completed keep alive response."); + LoggerMessage.Define(LogLevel.Debug, new EventId(9, nameof(ConnectionKeepAlive)), @"Connection id ""{ConnectionId}"" completed keep alive response."); private static readonly Action _connectionDisconnect = - LoggerMessage.Define(LogLevel.Debug, 10, @"Connection id ""{ConnectionId}"" disconnecting."); + LoggerMessage.Define(LogLevel.Debug, new EventId(10, nameof(ConnectionDisconnect)), @"Connection id ""{ConnectionId}"" disconnecting."); private static readonly Action _applicationError = - LoggerMessage.Define(LogLevel.Error, 13, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": An unhandled exception was thrown by the application."); + LoggerMessage.Define(LogLevel.Error, new EventId(13, nameof(ApplicationError)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": An unhandled exception was thrown by the application."); private static readonly Action _notAllConnectionsClosedGracefully = - LoggerMessage.Define(LogLevel.Debug, 16, "Some connections failed to close gracefully during server shutdown."); + LoggerMessage.Define(LogLevel.Debug, new EventId(16, nameof(NotAllConnectionsClosedGracefully)), "Some connections failed to close gracefully during server shutdown."); private static readonly Action _connectionBadRequest = - LoggerMessage.Define(LogLevel.Information, 17, @"Connection id ""{ConnectionId}"" bad request data: ""{message}"""); + LoggerMessage.Define(LogLevel.Information, new EventId(17, nameof(ConnectionBadRequest)), @"Connection id ""{ConnectionId}"" bad request data: ""{message}"""); private static readonly Action _connectionHeadResponseBodyWrite = - LoggerMessage.Define(LogLevel.Debug, 18, @"Connection id ""{ConnectionId}"" write of ""{count}"" body bytes to non-body HEAD response."); + LoggerMessage.Define(LogLevel.Debug, new EventId(18, nameof(ConnectionHeadResponseBodyWrite)), @"Connection id ""{ConnectionId}"" write of ""{count}"" body bytes to non-body HEAD response."); private static readonly Action _requestProcessingError = - LoggerMessage.Define(LogLevel.Information, 20, @"Connection id ""{ConnectionId}"" request processing ended abnormally."); + LoggerMessage.Define(LogLevel.Information, new EventId(20, nameof(RequestProcessingError)), @"Connection id ""{ConnectionId}"" request processing ended abnormally."); private static readonly Action _notAllConnectionsAborted = - LoggerMessage.Define(LogLevel.Debug, 21, "Some connections failed to abort during server shutdown."); + LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown."); private static readonly Action _heartbeatSlow = - LoggerMessage.Define(LogLevel.Warning, 22, @"Heartbeat took longer than ""{interval}"" at ""{now}""."); + LoggerMessage.Define(LogLevel.Warning, new EventId(22, nameof(HeartbeatSlow)), @"Heartbeat took longer than ""{interval}"" at ""{now}""."); private static readonly Action _applicationNeverCompleted = - LoggerMessage.Define(LogLevel.Critical, 23, @"Connection id ""{ConnectionId}"" application never completed"); + LoggerMessage.Define(LogLevel.Critical, new EventId(23, nameof(ApplicationNeverCompleted)), @"Connection id ""{ConnectionId}"" application never completed"); private static readonly Action _connectionRejected = - LoggerMessage.Define(LogLevel.Warning, 24, @"Connection id ""{ConnectionId}"" rejected because the maximum number of concurrent connections has been reached."); + LoggerMessage.Define(LogLevel.Warning, new EventId(24, nameof(ConnectionRejected)), @"Connection id ""{ConnectionId}"" rejected because the maximum number of concurrent connections has been reached."); private static readonly Action _requestBodyStart = - LoggerMessage.Define(LogLevel.Debug, 25, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": started reading request body."); + LoggerMessage.Define(LogLevel.Debug, new EventId(25, nameof(RequestBodyStart)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": started reading request body."); private static readonly Action _requestBodyDone = - LoggerMessage.Define(LogLevel.Debug, 26, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": done reading request body."); + LoggerMessage.Define(LogLevel.Debug, new EventId(26, nameof(RequestBodyDone)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": done reading request body."); private static readonly Action _requestBodyMinimumDataRateNotSatisfied = - LoggerMessage.Define(LogLevel.Information, 27, @"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."); + LoggerMessage.Define(LogLevel.Information, new EventId(27, nameof(RequestBodyMininumDataRateNotSatisfied)), @"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."); private static readonly Action _responseMinimumDataRateNotSatisfied = - LoggerMessage.Define(LogLevel.Information, 28, @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the connection was closed becuase the response was not read by the client at the specified minimum data rate."); + LoggerMessage.Define(LogLevel.Information, new EventId(28, nameof(ResponseMininumDataRateNotSatisfied)), @"Connection id ""{ConnectionId}"", Request id ""{TraceIdentifier}"": the connection was closed becuase the response was not read by the client at the specified minimum data rate."); private static readonly Action _http2ConnectionError = - LoggerMessage.Define(LogLevel.Information, 29, @"Connection id ""{ConnectionId}"": HTTP/2 connection error."); + LoggerMessage.Define(LogLevel.Information, new EventId(29, nameof(Http2ConnectionError)), @"Connection id ""{ConnectionId}"": HTTP/2 connection error."); private static readonly Action _http2StreamError = - LoggerMessage.Define(LogLevel.Information, 30, @"Connection id ""{ConnectionId}"": HTTP/2 stream error."); + LoggerMessage.Define(LogLevel.Information, new EventId(30, nameof(Http2StreamError)), @"Connection id ""{ConnectionId}"": HTTP/2 stream error."); private static readonly Action _hpackDecodingError = - LoggerMessage.Define(LogLevel.Information, 31, @"Connection id ""{ConnectionId}"": HPACK decoding error while decoding headers for stream ID {StreamId}."); + LoggerMessage.Define(LogLevel.Information, new EventId(31, nameof(HPackDecodingError)), @"Connection id ""{ConnectionId}"": HPACK decoding error while decoding headers for stream ID {StreamId}."); protected readonly ILogger _logger; diff --git a/src/Kestrel.Transport.Libuv/Internal/LibuvTrace.cs b/src/Kestrel.Transport.Libuv/Internal/LibuvTrace.cs index 7e938211fb..96f3338821 100644 --- a/src/Kestrel.Transport.Libuv/Internal/LibuvTrace.cs +++ b/src/Kestrel.Transport.Libuv/Internal/LibuvTrace.cs @@ -1,4 +1,4 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; @@ -11,19 +11,19 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Libuv.Internal // ConnectionRead: Reserved: 3 private static readonly Action _connectionPause = - LoggerMessage.Define(LogLevel.Debug, 4, @"Connection id ""{ConnectionId}"" paused."); + LoggerMessage.Define(LogLevel.Debug, new EventId(4, nameof(ConnectionPause)), @"Connection id ""{ConnectionId}"" paused."); private static readonly Action _connectionResume = - LoggerMessage.Define(LogLevel.Debug, 5, @"Connection id ""{ConnectionId}"" resumed."); + LoggerMessage.Define(LogLevel.Debug, new EventId(5, nameof(ConnectionResume)), @"Connection id ""{ConnectionId}"" resumed."); private static readonly Action _connectionReadFin = - LoggerMessage.Define(LogLevel.Debug, 6, @"Connection id ""{ConnectionId}"" received FIN."); + LoggerMessage.Define(LogLevel.Debug, new EventId(6, nameof(ConnectionReadFin)), @"Connection id ""{ConnectionId}"" received FIN."); private static readonly Action _connectionWriteFin = - LoggerMessage.Define(LogLevel.Debug, 7, @"Connection id ""{ConnectionId}"" sending FIN."); + LoggerMessage.Define(LogLevel.Debug, new EventId(7, nameof(ConnectionWriteFin)), @"Connection id ""{ConnectionId}"" sending FIN."); private static readonly Action _connectionWroteFin = - LoggerMessage.Define(LogLevel.Debug, 8, @"Connection id ""{ConnectionId}"" sent FIN with status ""{Status}""."); + LoggerMessage.Define(LogLevel.Debug, new EventId(8, nameof(ConnectionWroteFin)), @"Connection id ""{ConnectionId}"" sent FIN with status ""{Status}""."); // ConnectionWrite: Reserved: 11 diff --git a/src/Kestrel.Transport.Sockets/Internal/SocketsTrace.cs b/src/Kestrel.Transport.Sockets/Internal/SocketsTrace.cs index 2757bcf4ce..e8aa5fa286 100644 --- a/src/Kestrel.Transport.Sockets/Internal/SocketsTrace.cs +++ b/src/Kestrel.Transport.Sockets/Internal/SocketsTrace.cs @@ -1,4 +1,4 @@ -// Copyright (c) .NET Foundation. All rights reserved. +// Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; @@ -11,22 +11,22 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Transport.Sockets.Internal // ConnectionRead: Reserved: 3 private static readonly Action _connectionPause = - LoggerMessage.Define(LogLevel.Debug, 4, @"Connection id ""{ConnectionId}"" paused."); + LoggerMessage.Define(LogLevel.Debug, new EventId(4, nameof(ConnectionPause)), @"Connection id ""{ConnectionId}"" paused."); private static readonly Action _connectionResume = - LoggerMessage.Define(LogLevel.Debug, 5, @"Connection id ""{ConnectionId}"" resumed."); + LoggerMessage.Define(LogLevel.Debug, new EventId(5, nameof(ConnectionResume)), @"Connection id ""{ConnectionId}"" resumed."); private static readonly Action _connectionReadFin = - LoggerMessage.Define(LogLevel.Debug, 6, @"Connection id ""{ConnectionId}"" received FIN."); + LoggerMessage.Define(LogLevel.Debug, new EventId(6, nameof(ConnectionReadFin)), @"Connection id ""{ConnectionId}"" received FIN."); private static readonly Action _connectionWriteFin = - LoggerMessage.Define(LogLevel.Debug, 7, @"Connection id ""{ConnectionId}"" sending FIN."); + LoggerMessage.Define(LogLevel.Debug, new EventId(7, nameof(ConnectionWriteFin)), @"Connection id ""{ConnectionId}"" sending FIN."); private static readonly Action _connectionError = - LoggerMessage.Define(LogLevel.Information, 14, @"Connection id ""{ConnectionId}"" communication error."); + LoggerMessage.Define(LogLevel.Information, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error."); private static readonly Action _connectionReset = - LoggerMessage.Define(LogLevel.Debug, 19, @"Connection id ""{ConnectionId}"" reset."); + LoggerMessage.Define(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset."); private readonly ILogger _logger; diff --git a/test/Kestrel.FunctionalTests/BadHttpRequestTests.cs b/test/Kestrel.FunctionalTests/BadHttpRequestTests.cs index af8e3916c3..be64faeaf4 100644 --- a/test/Kestrel.FunctionalTests/BadHttpRequestTests.cs +++ b/test/Kestrel.FunctionalTests/BadHttpRequestTests.cs @@ -10,6 +10,7 @@ using Microsoft.AspNetCore.Server.Kestrel.Core.Internal; using Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure; using Microsoft.AspNetCore.Testing; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Testing; using Moq; using Xunit; @@ -135,23 +136,13 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests [Fact] public async Task BadRequestLogsAreNotHigherThanInformation() { - var maxLogLevel = LogLevel.Trace; - - var mockLogger = new Mock(); - mockLogger - .Setup(logger => logger.IsEnabled(It.IsAny())) - .Returns(true); - mockLogger - .Setup(logger => logger.Log(It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())) - .Callback>((logLevel, eventId, state, ex, formatter) => - { - maxLogLevel = logLevel > maxLogLevel ? logLevel : maxLogLevel; - }); + var sink = new TestSink(); + var logger = new TestLogger("TestLogger", sink, enabled: true); using (var server = new TestServer(async context => { await context.Request.Body.ReadAsync(new byte[1], 0, 1); - }, new TestServiceContext { Log = new KestrelTrace(mockLogger.Object) })) + }, new TestServiceContext { Log = new KestrelTrace(logger) })) { using (var connection = new TestConnection(server.Port)) { @@ -163,10 +154,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.FunctionalTests } } - const int badRequestEventId = 17; - mockLogger.Verify(logger => logger.Log(LogLevel.Information, badRequestEventId, It.IsAny(), It.IsAny(), It.IsAny>())); - - Assert.Equal(LogLevel.Information, maxLogLevel); + Assert.All(sink.Writes, w => Assert.InRange(w.LogLevel, LogLevel.Trace, LogLevel.Information)); + Assert.Contains(sink.Writes, w => w.EventId.Id == 17 && w.LogLevel == LogLevel.Information); } [Fact]