From a187382756252b10ac27ae27a3785a28e7343c57 Mon Sep 17 00:00:00 2001 From: Roma Marusyk Date: Thu, 17 Dec 2020 01:45:11 +0200 Subject: [PATCH 1/4] Fix arguments order for call of HeartbeatSlow --- .../Core/src/Internal/Infrastructure/KestrelTrace.cs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index 30ad70e1df7b..34de42fe3e0c 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, "NotAllConnectionsAborted"), "Some connections failed to abort during server shutdown."); - 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 _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, "ApplicationNeverCompleted"), @"Connection id ""{ConnectionId}"" application never completed"); @@ -200,7 +200,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) From 734c127cfc91dc3c3c2053e79cebf83e33a2a924 Mon Sep 17 00:00:00 2001 From: Roma Marusyk Date: Thu, 17 Dec 2020 03:03:23 +0200 Subject: [PATCH 2/4] Add unit test --- src/Servers/Kestrel/Core/test/HeartbeatTests.cs | 14 ++++++++------ 1 file changed, 8 insertions(+), 6 deletions(-) diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index 1af0a541a49d..cb1f2ad81f80 100644 --- a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs +++ b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs @@ -27,10 +27,11 @@ public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() 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 +42,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,7 +57,7 @@ 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()); + Assert.Equal($"As of\"{now}\", the heartbeat has been running for \"{heartbeatDuration}\" which is longer than \"{Heartbeat.Interval}\". This could be caused by thread pool starvation.", kestrelTrace.Logger.Messages.Single(message => message.LogLevel == LogLevel.Warning).Message); } [Fact] @@ -65,10 +66,11 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerA 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(() => { @@ -80,7 +82,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerA 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()); @@ -95,7 +97,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerA 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.Equal($"As of\"{now}\", the heartbeat has been running for \"{heartbeatDuration}\" which is longer than \"{Heartbeat.Interval}\". This could be caused by thread pool starvation.", kestrelTrace.Logger.Messages.Single(message => message.LogLevel == LogLevel.Warning).Message); } [Fact] From f6167f83418d90cac48e1647d94ca66264855af3 Mon Sep 17 00:00:00 2001 From: Roma Marusyk Date: Tue, 29 Dec 2020 00:06:49 +0200 Subject: [PATCH 3/4] Fix unit test --- src/Servers/Kestrel/Core/test/HeartbeatTests.cs | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index cb1f2ad81f80..1926cb97f1e7 100644 --- a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs +++ b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs @@ -66,11 +66,10 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerA var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); var debugger = new Mock(); - var kestrelTrace = new TestKestrelTrace(); + var kestrelTrace = new Mock(); 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(() => { @@ -82,7 +81,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerA Task blockedHeartbeatTask; - using (var heartbeat = new Heartbeat(new[] { heartbeatHandler.Object }, systemClock, debugger.Object, kestrelTrace)) + using (var heartbeat = new Heartbeat(new[] { heartbeatHandler.Object }, systemClock, debugger.Object, kestrelTrace.Object)) { blockedHeartbeatTask = Task.Run(() => heartbeat.OnHeartbeat()); @@ -97,7 +96,7 @@ public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerA await blockedHeartbeatTask.DefaultTimeout(); heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once()); - Assert.Equal($"As of\"{now}\", the heartbeat has been running for \"{heartbeatDuration}\" which is longer than \"{Heartbeat.Interval}\". This could be caused by thread pool starvation.", kestrelTrace.Logger.Messages.Single(message => message.LogLevel == LogLevel.Warning).Message); + kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.FromSeconds(2), Heartbeat.Interval, now), Times.Never()); } [Fact] From 13b6369aeff76011d6d494fd9a68bb9374a6e1b2 Mon Sep 17 00:00:00 2001 From: Stephen Halter Date: Wed, 30 Dec 2020 14:07:58 -0800 Subject: [PATCH 4/4] fixup --- src/Servers/Kestrel/Core/test/HeartbeatTests.cs | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index 1926cb97f1e7..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,7 +23,7 @@ public void HeartbeatIntervalIsOneSecond() } [Fact] - public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() + public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsWarning() { var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); @@ -57,11 +58,16 @@ public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() await blockedHeartbeatTask.DefaultTimeout(); heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once()); - Assert.Equal($"As of\"{now}\", the heartbeat has been running for \"{heartbeatDuration}\" which is longer than \"{Heartbeat.Interval}\". This could be caused by thread pool starvation.", kestrelTrace.Logger.Messages.Single(message => message.LogLevel == LogLevel.Warning).Message); + + 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();