From 4d26112c07391f563cb0ca46af1993635399007e Mon Sep 17 00:00:00 2001 From: Eric Erhardt Date: Tue, 10 Aug 2021 10:18:28 -0500 Subject: [PATCH] Don't log an error when a BackgroundService is canceled due to the host being stopped. (#57005) * Don't log an error when a BackgroundService is canceled due to the host being stopped. Fix #56032 * Add volatile to stopping field. * Convert HostTests to use a logger instead of depending on EventSource. * Make it obvious the test is using the default worker template --- .../src/Internal/Host.cs | 9 +++ .../tests/UnitTests/HostTests.cs | 33 +++++++++++ .../tests/UnitTests/Internal/HostTests.cs | 65 +++++++++++++++++++--- .../tests/UnitTests/TestEventListener.cs | 40 ------------- .../tests/UnitTests/TestLoggerProvider.cs | 61 ++++++++++++++++++++ 5 files changed, 160 insertions(+), 48 deletions(-) delete mode 100644 src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestEventListener.cs create mode 100644 src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestLoggerProvider.cs diff --git a/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs b/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs index bcaed33..4041133 100644 --- a/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs +++ b/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs @@ -22,6 +22,7 @@ namespace Microsoft.Extensions.Hosting.Internal private readonly IHostEnvironment _hostEnvironment; private readonly PhysicalFileProvider _defaultProvider; private IEnumerable _hostedServices; + private volatile bool _stopCalled; public Host(IServiceProvider services, IHostEnvironment hostEnvironment, @@ -84,6 +85,13 @@ namespace Microsoft.Extensions.Hosting.Internal } 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) { @@ -95,6 +103,7 @@ namespace Microsoft.Extensions.Hosting.Internal public async Task StopAsync(CancellationToken cancellationToken = default) { + _stopCalled = true; _logger.Stopping(); using (var cts = new CancellationTokenSource(_options.ShutdownTimeout)) diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostTests.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostTests.cs index 7fe9cec..69f69b1 100644 --- a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostTests.cs +++ b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostTests.cs @@ -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; @@ -403,5 +405,36 @@ namespace Microsoft.Extensions.Hosting.Tests } } } + + private class TestEventListener : EventListener + { + private volatile bool _disposed; + + private ConcurrentQueue _events = new ConcurrentQueue(); + + public IEnumerable 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(); + } + } } } diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs index e98aa45..d07c2bc 100644 --- a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs +++ b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs @@ -1325,13 +1325,13 @@ namespace Microsoft.Extensions.Hosting.Internal BackgroundServiceExceptionBehavior testBehavior, params string[] expectedExceptionMessages) { - using TestEventListener listener = new TestEventListener(); + TestLoggerProvider logger = new TestLoggerProvider(); var backgroundDelayTaskSource = new TaskCompletionSource(); using IHost host = CreateBuilder() .ConfigureLogging(logging => { - logging.AddEventSourceLogger(); + logging.AddProvider(logger); }) .ConfigureServices((hostContext, services) => { @@ -1350,14 +1350,10 @@ namespace Microsoft.Extensions.Hosting.Internal 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().Any( - p => p.Contains(expectedMessage))))) + e => e.Message.Contains(expectedMessage)))) { break; } @@ -1367,6 +1363,37 @@ namespace Microsoft.Extensions.Hosting.Internal } } + /// + /// Tests that when a BackgroundService is canceled when stopping the host, + /// no error is logged. + /// + [Fact] + public async Task HostNoErrorWhenServiceIsCanceledAsPartOfStop() + { + TestLoggerProvider logger = new TestLoggerProvider(); + + using IHost host = CreateBuilder() + .ConfigureLogging(logging => + { + logging.AddProvider(logger); + }) + .ConfigureServices(services => + { + services.AddHostedService(); + }) + .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())); @@ -1513,5 +1540,27 @@ namespace Microsoft.Extensions.Hosting.Internal throw new Exception("Background Exception"); } } + + /// + /// A copy of the default "Worker" template. + /// + private class WorkerTemplateService : BackgroundService + { + private readonly ILogger _logger; + + public WorkerTemplateService(ILogger 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); + } + } + } } } diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestEventListener.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestEventListener.cs deleted file mode 100644 index bb17dfd..0000000 --- a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestEventListener.cs +++ /dev/null @@ -1,40 +0,0 @@ -// Licensed to the .NET Foundation under one or more agreements. -// The .NET Foundation licenses this file to you under the MIT license. - -using System.Collections.Concurrent; -using System.Collections.Generic; -using System.Diagnostics.Tracing; - -namespace Microsoft.Extensions.Hosting.Tests -{ - internal class TestEventListener : EventListener - { - private volatile bool _disposed; - - private ConcurrentQueue _events = new ConcurrentQueue(); - - public IEnumerable 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(); - } - } -} diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestLoggerProvider.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestLoggerProvider.cs new file mode 100644 index 0000000..85cbdce --- /dev/null +++ b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/TestLoggerProvider.cs @@ -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(); + + /// + /// Provides a snapshot of the current events. + /// + public LogEvent[] GetEvents() => _logger.GetEvents(); + + public ILogger CreateLogger(string categoryName) + { + return _logger; + } + + public void Dispose() { } + + private class TestLogger : ILogger + { + private readonly ConcurrentQueue _events = new(); + + internal LogEvent[] GetEvents() => _events.ToArray(); + + public IDisposable BeginScope(TState state) => new Scope(); + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func 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; } + } +} -- 2.7.4