Don't log an error when a BackgroundService is canceled due to the ho…

…st 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/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs

@@ -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,
@@ -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)
  {
@@ -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))

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 @@ 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();
+ }
+ }
  }
 }

src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs

@@ -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) =>
  {
@@ -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;
  }
@@ -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()));
@@ -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);
+ }
+ }
+ }
  }
 }

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();
+
+ /// <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; }
+ }
+}