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

Don't log an error when a BackgroundService is canceled due to the host being stopped. #57005

Merged
merged 6 commits into from
Aug 10, 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 @@ -22,6 +22,7 @@ internal sealed class Host : IHost, IAsyncDisposable
private readonly IHostEnvironment _hostEnvironment;
private readonly PhysicalFileProvider _defaultProvider;
private IEnumerable<IHostedService> _hostedServices;
private volatile bool _stopCalled;

public Host(IServiceProvider services,
IHostEnvironment hostEnvironment,
Expand Down Expand Up @@ -84,6 +85,13 @@ private async Task TryExecuteBackgroundServiceAsync(BackgroundService background
}
catch (Exception ex)
{
// When the host is being stopped, it cancels the background services.
// This isn't an error condition, so don't log it as an error.
if (_stopCalled && backgroundService.ExecuteTask.IsCanceled && ex is OperationCanceledException)
{
return;
}

_logger.BackgroundServiceFaulted(ex);
if (_options.BackgroundServiceExceptionBehavior == BackgroundServiceExceptionBehavior.StopHost)
{
Expand All @@ -95,6 +103,7 @@ private async Task TryExecuteBackgroundServiceAsync(BackgroundService background

public async Task StopAsync(CancellationToken cancellationToken = default)
{
_stopCalled = true;
_logger.Stopping();

using (var cts = new CancellationTokenSource(_options.ShutdownTimeout))
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,10 @@
// The .NET Foundation licenses this file to you under the MIT license.

using System;
using System.Collections.Concurrent;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.IO;
using System.Linq;
using System.Reflection;
Expand Down Expand Up @@ -403,5 +405,36 @@ public void Dispose()
}
}
}

private class TestEventListener : EventListener
{
private volatile bool _disposed;

private ConcurrentQueue<EventWrittenEventArgs> _events = new ConcurrentQueue<EventWrittenEventArgs>();

public IEnumerable<EventWrittenEventArgs> EventData => _events;

protected override void OnEventSourceCreated(EventSource eventSource)
{
if (eventSource.Name == "Microsoft-Extensions-Logging")
{
EnableEvents(eventSource, EventLevel.Informational);
}
}

protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
if (!_disposed)
{
_events.Enqueue(eventData);
}
}

public override void Dispose()
{
_disposed = true;
base.Dispose();
}
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -1325,13 +1325,13 @@ public async Task BackgroundServiceAsyncExceptionGetsLogged(
BackgroundServiceExceptionBehavior testBehavior,
params string[] expectedExceptionMessages)
{
using TestEventListener listener = new TestEventListener();
TestLoggerProvider logger = new TestLoggerProvider();
var backgroundDelayTaskSource = new TaskCompletionSource<bool>();

using IHost host = CreateBuilder()
.ConfigureLogging(logging =>
{
logging.AddEventSourceLogger();
logging.AddProvider(logger);
})
.ConfigureServices((hostContext, services) =>
{
Expand All @@ -1350,14 +1350,10 @@ public async Task BackgroundServiceAsyncExceptionGetsLogged(

while (true)
{
EventWrittenEventArgs[] events =
listener.EventData.Where(
e => e.EventSource.Name == "Microsoft-Extensions-Logging").ToArray();

LogEvent[] events = logger.GetEvents();
if (expectedExceptionMessages.All(
expectedMessage => events.Any(
e => e.Payload.OfType<string>().Any(
p => p.Contains(expectedMessage)))))
e => e.Message.Contains(expectedMessage))))
{
break;
}
Expand All @@ -1367,6 +1363,37 @@ public async Task BackgroundServiceAsyncExceptionGetsLogged(
}
}

/// <summary>
/// Tests that when a BackgroundService is canceled when stopping the host,
/// no error is logged.
/// </summary>
[Fact]
public async Task HostNoErrorWhenServiceIsCanceledAsPartOfStop()
{
TestLoggerProvider logger = new TestLoggerProvider();

using IHost host = CreateBuilder()
.ConfigureLogging(logging =>
{
logging.AddProvider(logger);
})
.ConfigureServices(services =>
{
services.AddHostedService<WorkerTemplateService>();
})
.Build();

host.Start();
await host.StopAsync();

foreach (LogEvent logEvent in logger.GetEvents())
{
Assert.True(logEvent.LogLevel < LogLevel.Error);

Assert.NotEqual("BackgroundServiceFaulted", logEvent.EventId.Name);
}
}

private IHostBuilder CreateBuilder(IConfiguration config = null)
{
return new HostBuilder().ConfigureHostConfiguration(builder => builder.AddConfiguration(config ?? new ConfigurationBuilder().Build()));
Expand Down Expand Up @@ -1513,5 +1540,27 @@ protected override async Task ExecuteAsync(CancellationToken stoppingToken)
throw new Exception("Background Exception");
}
}

/// <summary>
/// A copy of the default "Worker" template.
/// </summary>
private class WorkerTemplateService : BackgroundService
{
private readonly ILogger<WorkerTemplateService> _logger;

public WorkerTemplateService(ILogger<WorkerTemplateService> logger)
{
_logger = logger;
}

protected override async Task ExecuteAsync(CancellationToken stoppingToken)
{
while (!stoppingToken.IsCancellationRequested)
{
_logger.LogInformation("Worker running at: {time}", DateTimeOffset.Now);
await Task.Delay(1000, stoppingToken);
}
}
}
}
}

This file was deleted.

Original file line number Diff line number Diff line change
@@ -0,0 +1,61 @@
// 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.Collections.Concurrent;
using Microsoft.Extensions.Logging;

namespace Microsoft.Extensions.Hosting.Tests
{
internal class TestLoggerProvider : ILoggerProvider
{
private readonly TestLogger _logger = new();

/// <summary>
/// Provides a snapshot of the current events.
/// </summary>
public LogEvent[] GetEvents() => _logger.GetEvents();

public ILogger CreateLogger(string categoryName)
{
return _logger;
}

public void Dispose() { }

private class TestLogger : ILogger
{
private readonly ConcurrentQueue<LogEvent> _events = new();

internal LogEvent[] GetEvents() => _events.ToArray();

public IDisposable BeginScope<TState>(TState state) => new Scope();

public bool IsEnabled(LogLevel logLevel) => true;

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
_events.Enqueue(new LogEvent()
{
LogLevel = logLevel,
EventId = eventId,
Message = formatter(state, exception)
});
}

private class Scope : IDisposable
{
public void Dispose()
{
}
}
}
}

internal class LogEvent
{
public LogLevel LogLevel { get; set; }
public EventId EventId { get; set; }
public string Message { get; set; }
}
}