Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix arguments order for call of HeartbeatSlow #28698

Merged
merged 4 commits into from
Jan 8, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -47,8 +47,8 @@ internal class KestrelTrace : IKestrelTrace
private static readonly Action<ILogger, Exception?> _notAllConnectionsAborted =
LoggerMessage.Define(LogLevel.Debug, new EventId(21, "NotAllConnectionsAborted"), "Some connections failed to abort during server shutdown.");

private static readonly Action<ILogger, TimeSpan, TimeSpan, DateTimeOffset, Exception?> _heartbeatSlow =
LoggerMessage.Define<TimeSpan, TimeSpan, DateTimeOffset>(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<ILogger, DateTimeOffset, TimeSpan, TimeSpan, Exception?> _heartbeatSlow =
LoggerMessage.Define<DateTimeOffset, TimeSpan, TimeSpan>(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<ILogger, string, Exception?> _applicationNeverCompleted =
LoggerMessage.Define<string>(LogLevel.Critical, new EventId(23, "ApplicationNeverCompleted"), @"Connection id ""{ConnectionId}"" application never completed");
Expand Down Expand Up @@ -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)
Expand Down
17 changes: 12 additions & 5 deletions src/Servers/Kestrel/Core/test/HeartbeatTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -22,15 +23,16 @@ public void HeartbeatIntervalIsOneSecond()
}

[Fact]
public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError()
public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsWarning()
{
var systemClock = new MockSystemClock();
var heartbeatHandler = new Mock<IHeartbeatHandler>();
var debugger = new Mock<IDebugger>();
var kestrelTrace = new Mock<IKestrelTrace>();
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(() =>
{
Expand All @@ -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());

Expand All @@ -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<IHeartbeatHandler>();
Expand Down