diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index 5a85007aab30..cf7ab76ac511 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs @@ -47,8 +47,8 @@ internal class KestrelTrace : IKestrelTrace private static readonly Action _notAllConnectionsAborted = 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, new EventId(22, nameof(HeartbeatSlow)), @"As of ""{now}"", the heartbeat has been running for ""{heartbeatDuration}"" which is longer than ""{interval}"". This could be caused by thread pool starvation."); + private static readonly Action _heartbeatSlow = + LoggerMessage.Define(LogLevel.Warning, new EventId(22, "HeartbeatSlow"), @"As of ""{now}"", the heartbeat has been running for ""{heartbeatDuration}"" which is longer than ""{interval}"". This could be caused by thread pool starvation."); private static readonly Action _applicationNeverCompleted = LoggerMessage.Define(LogLevel.Critical, new EventId(23, nameof(ApplicationNeverCompleted)), @"Connection id ""{ConnectionId}"" application never completed"); @@ -196,7 +196,7 @@ public virtual void NotAllConnectionsAborted() public virtual void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now) { - _heartbeatSlow(_logger, heartbeatDuration, interval, now, null); + _heartbeatSlow(_logger, now, heartbeatDuration, interval, null); } public virtual void ApplicationNeverCompleted(string connectionId) diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index 1af0a541a49d..49e7953715df 100644 --- a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs +++ b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Globalization; using System.Linq; using System.Threading; using System.Threading.Tasks; @@ -22,15 +23,16 @@ public void HeartbeatIntervalIsOneSecond() } [Fact] - public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() + public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsWarning() { var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); var debugger = new Mock(); - var kestrelTrace = new Mock(); + var kestrelTrace = new TestKestrelTrace(); var handlerMre = new ManualResetEventSlim(); var handlerStartedTcs = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); var now = systemClock.UtcNow; + var heartbeatDuration = TimeSpan.FromSeconds(2); heartbeatHandler.Setup(h => h.OnHeartbeat(now)).Callback(() => { @@ -41,7 +43,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() 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()); @@ -56,11 +58,16 @@ public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() await blockedHeartbeatTask.DefaultTimeout(); heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once()); - kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.FromSeconds(2), Heartbeat.Interval, now), Times.Once()); + + var warningMessage = kestrelTrace.Logger.Messages.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)}\". " + + "This could be caused by thread pool starvation.", warningMessage); } [Fact] - public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerAttached() + public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedIfDebuggerAttached() { var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock();