Expose BackgroundService.ExecuteTask (#42981)

* Expose BackgroundService.ExecuteTask Expose the task that executes the background service, so consumers can check if it is running and/or has ran to competition or faulted. Use the new ExecuteTask to log exceptions when a BackgroundService fails after await, instead of appearing to hang. Fix #35991 Fix #36017
dotnet · Oct 6, 2020 · e18d25e · e18d25e
1 parent d4c2860
commit e18d25e
Show file tree

Hide file tree

Showing 11 changed files with 158 additions and 54 deletions.
diff --git a/...icrosoft.Extensions.Hosting.Abstractions/ref/Microsoft.Extensions.Hosting.Abstractions.cs b/...icrosoft.Extensions.Hosting.Abstractions/ref/Microsoft.Extensions.Hosting.Abstractions.cs
@@ -17,6 +17,7 @@ namespace Microsoft.Extensions.Hosting
     public abstract partial class BackgroundService : Microsoft.Extensions.Hosting.IHostedService, System.IDisposable
     {
         protected BackgroundService() { }
+        public virtual System.Threading.Tasks.Task ExecuteTask { get { throw null; } }
         public virtual void Dispose() { }
         protected abstract System.Threading.Tasks.Task ExecuteAsync(System.Threading.CancellationToken stoppingToken);
         public virtual System.Threading.Tasks.Task StartAsync(System.Threading.CancellationToken cancellationToken) { throw null; }

diff --git a/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/BackgroundService.cs b/src/libraries/Microsoft.Extensions.Hosting.Abstractions/src/BackgroundService.cs
@@ -12,9 +12,17 @@ namespace Microsoft.Extensions.Hosting
     /// </summary>
     public abstract class BackgroundService : IHostedService, IDisposable
     {
-        private Task _executingTask;
+        private Task _executeTask;
         private CancellationTokenSource _stoppingCts;
 
+        /// <summary>
+        /// Gets the Task that executes the background operation.
+        /// </summary>
+        /// <remarks>
+        /// Will return <see langword="null"/> if the background operation hasn't started.
+        /// </remarks>
+        public virtual Task ExecuteTask => _executeTask;
+
         /// <summary>
         /// This method is called when the <see cref="IHostedService"/> starts. The implementation should return a task that represents
         /// the lifetime of the long running operation(s) being performed.
@@ -33,12 +41,12 @@ public virtual Task StartAsync(CancellationToken cancellationToken)
             _stoppingCts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken);
 
             // Store the task we're executing
-            _executingTask = ExecuteAsync(_stoppingCts.Token);
+            _executeTask = ExecuteAsync(_stoppingCts.Token);
 
             // If the task is completed then return it, this will bubble cancellation and failure to the caller
-            if (_executingTask.IsCompleted)
+            if (_executeTask.IsCompleted)
             {
-                return _executingTask;
+                return _executeTask;
             }
 
             // Otherwise it's running
@@ -52,7 +60,7 @@ public virtual Task StartAsync(CancellationToken cancellationToken)
         public virtual async Task StopAsync(CancellationToken cancellationToken)
         {
             // Stop called without start
-            if (_executingTask == null)
+            if (_executeTask == null)
             {
                 return;
             }
@@ -65,7 +73,7 @@ public virtual async Task StopAsync(CancellationToken cancellationToken)
             finally
             {
                 // Wait until the task completes or the stop token triggers
-                await Task.WhenAny(_executingTask, Task.Delay(Timeout.Infinite, cancellationToken)).ConfigureAwait(false);
+                await Task.WhenAny(_executeTask, Task.Delay(Timeout.Infinite, cancellationToken)).ConfigureAwait(false);
             }
 
         }

diff --git a/src/libraries/Microsoft.Extensions.Hosting/Microsoft.Extensions.Hosting.sln b/src/libraries/Microsoft.Extensions.Hosting/Microsoft.Extensions.Hosting.sln
@@ -25,7 +25,11 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Hostin
 EndProject
 Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Hosting.Functional.Tests", "tests\FunctionalTests\Microsoft.Extensions.Hosting.Functional.Tests.csproj", "{49ED668A-7FCB-455B-B3B4-26C004172531}"
 EndProject
-Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "TestUtilities", "..\Common\tests\TestUtilities\TestUtilities.csproj", "{602F282E-2829-4C7D-B960-A8D31F326E9F}"
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "TestUtilities", "..\Common\tests\TestUtilities\TestUtilities.csproj", "{602F282E-2829-4C7D-B960-A8D31F326E9F}"
+EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Hosting.Abstractions", "..\Microsoft.Extensions.Hosting.Abstractions\ref\Microsoft.Extensions.Hosting.Abstractions.csproj", "{BAD57E10-C310-4BED-A4BF-7B02B1AC35BC}"
+EndProject
+Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "Microsoft.Extensions.Hosting.Abstractions", "..\Microsoft.Extensions.Hosting.Abstractions\src\Microsoft.Extensions.Hosting.Abstractions.csproj", "{0468E166-54DE-4DB7-A2DF-42214A39C392}"
 EndProject
 Global
 	GlobalSection(SolutionConfigurationPlatforms) = preSolution
@@ -57,6 +61,14 @@ Global
 		{602F282E-2829-4C7D-B960-A8D31F326E9F}.Debug|Any CPU.Build.0 = Debug|Any CPU
 		{602F282E-2829-4C7D-B960-A8D31F326E9F}.Release|Any CPU.ActiveCfg = Release|Any CPU
 		{602F282E-2829-4C7D-B960-A8D31F326E9F}.Release|Any CPU.Build.0 = Release|Any CPU
+		{BAD57E10-C310-4BED-A4BF-7B02B1AC35BC}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{BAD57E10-C310-4BED-A4BF-7B02B1AC35BC}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{BAD57E10-C310-4BED-A4BF-7B02B1AC35BC}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{BAD57E10-C310-4BED-A4BF-7B02B1AC35BC}.Release|Any CPU.Build.0 = Release|Any CPU
+		{0468E166-54DE-4DB7-A2DF-42214A39C392}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
+		{0468E166-54DE-4DB7-A2DF-42214A39C392}.Debug|Any CPU.Build.0 = Debug|Any CPU
+		{0468E166-54DE-4DB7-A2DF-42214A39C392}.Release|Any CPU.ActiveCfg = Release|Any CPU
+		{0468E166-54DE-4DB7-A2DF-42214A39C392}.Release|Any CPU.Build.0 = Release|Any CPU
 	EndGlobalSection
 	GlobalSection(SolutionProperties) = preSolution
 		HideSolutionNode = FALSE
@@ -71,6 +83,8 @@ Global
 		{4E52FAB8-83A4-4F81-AFED-072BF13D0F46} = {FE4AAEDA-1D08-4C9A-B61C-8A7156000E43}
 		{49ED668A-7FCB-455B-B3B4-26C004172531} = {EB3CB906-BAB0-4A90-BE2F-BBFE47B036C3}
 		{602F282E-2829-4C7D-B960-A8D31F326E9F} = {635786A7-1A3B-46BB-9367-DE57F7032900}
+		{BAD57E10-C310-4BED-A4BF-7B02B1AC35BC} = {23DF8E80-C5C7-4D64-B0D4-F4D33A9646A1}
+		{0468E166-54DE-4DB7-A2DF-42214A39C392} = {2BCD92F1-BA65-4145-A650-8BADD26EE5D9}
 	EndGlobalSection
 	GlobalSection(ExtensibilityGlobals) = postSolution
 		SolutionGuid = {137EEE14-A353-4DA8-98CB-214FD8EBAF33}

diff --git a/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs b/src/libraries/Microsoft.Extensions.Hosting/src/Internal/Host.cs
@@ -52,6 +52,11 @@ public async Task StartAsync(CancellationToken cancellationToken = default)
             {
                 // Fire IHostedService.Start
                 await hostedService.StartAsync(combinedCancellationToken).ConfigureAwait(false);
+
+                if (hostedService is BackgroundService backgroundService)
+                {
+                    _ = HandleBackgroundException(backgroundService);
+                }
             }
 
             // Fire IHostApplicationLifetime.Started
@@ -60,6 +65,18 @@ public async Task StartAsync(CancellationToken cancellationToken = default)
             _logger.Started();
         }
 
+        private async Task HandleBackgroundException(BackgroundService backgroundService)
+        {
+            try
+            {
+                await backgroundService.ExecuteTask.ConfigureAwait(false);
+            }
+            catch (Exception ex)
+            {
+                _logger.BackgroundServiceFaulted(ex);
+            }
+        }
+
         public async Task StopAsync(CancellationToken cancellationToken = default)
         {
             _logger.Stopping();

diff --git a/src/libraries/Microsoft.Extensions.Hosting/src/Internal/HostingLoggerExtensions.cs b/src/libraries/Microsoft.Extensions.Hosting/src/Internal/HostingLoggerExtensions.cs
@@ -2,9 +2,6 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 
 using System;
-using System.Collections;
-using System.Collections.Generic;
-using System.Globalization;
 using System.Reflection;
 using Microsoft.Extensions.Logging;
 
@@ -79,5 +76,16 @@ public static void StoppedWithException(this ILogger logger, Exception ex)
                     message: "Hosting shutdown exception");
             }
         }
+
+        public static void BackgroundServiceFaulted(this ILogger logger, Exception ex)
+        {
+            if (logger.IsEnabled(LogLevel.Error))
+            {
+                logger.LogError(
+                    eventId: LoggerEventIds.BackgroundServiceFaulted,
+                    exception: ex,
+                    message: "BackgroundService failed");
+            }
+        }
     }
 }
diff --git a/src/libraries/Microsoft.Extensions.Hosting/src/Internal/LoggerEventIds.cs b/src/libraries/Microsoft.Extensions.Hosting/src/Internal/LoggerEventIds.cs
@@ -15,5 +15,6 @@ internal static class LoggerEventIds
         public static readonly EventId ApplicationStartupException = new EventId(6, "ApplicationStartupException");
         public static readonly EventId ApplicationStoppingException = new EventId(7, "ApplicationStoppingException");
         public static readonly EventId ApplicationStoppedException = new EventId(8, "ApplicationStoppedException");
+        public static readonly EventId BackgroundServiceFaulted = new EventId(9, "BackgroundServiceFaulted");
     }
 }
diff --git a/...UnitTests/BackgroundHostedServiceTests.cs → ...tests/UnitTests/BackgroundServiceTests.cs b/...UnitTests/BackgroundHostedServiceTests.cs → ...tests/UnitTests/BackgroundServiceTests.cs
@@ -2,15 +2,13 @@
 // The .NET Foundation licenses this file to you under the MIT license.
 
 using System;
-using System.Collections.Generic;
-using System.Text;
 using System.Threading;
 using System.Threading.Tasks;
 using Xunit;
 
 namespace Microsoft.Extensions.Hosting.Tests
 {
-    public class BackgroundHostedServiceTests
+    public class BackgroundServiceTests
     {
         [Fact]
         public void StartReturnsCompletedTaskIfLongRunningTaskIsIncomplete()
@@ -23,7 +21,7 @@ public void StartReturnsCompletedTaskIfLongRunningTaskIsIncomplete()
             Assert.True(task.IsCompleted);
             Assert.False(tcs.Task.IsCompleted);
 
-            // Complete the tsk
+            // Complete the task
             tcs.TrySetResult(null);
         }
 
@@ -37,6 +35,7 @@ public void StartReturnsCompletedTaskIfCancelled()
             var task = service.StartAsync(CancellationToken.None);
 
             Assert.True(task.IsCompleted);
+            Assert.Same(task, service.ExecuteTask);
         }
 
         [Fact]
@@ -175,17 +174,14 @@ private class MyBackgroundService : BackgroundService
         {
             private readonly Task _task;
 
-            public Task ExecuteTask { get; set; }
-
             public MyBackgroundService(Task task)
             {
                 _task = task;
             }
 
             protected override async Task ExecuteAsync(CancellationToken stoppingToken)
             {
-                ExecuteTask = ExecuteCore(stoppingToken);
-                await ExecuteTask;
+                await ExecuteCore(stoppingToken);
             }
 
             private async Task ExecuteCore(CancellationToken stoppingToken)

diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostBuilderTests.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostBuilderTests.cs
@@ -4,7 +4,6 @@
 using System;
 using System.Collections.Generic;
 using System.IO;
-using System.Reflection;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.FileProviders;
@@ -13,7 +12,7 @@
 using Microsoft.Extensions.Options;
 using Xunit;
 
-namespace Microsoft.Extensions.Hosting
+namespace Microsoft.Extensions.Hosting.Tests
 {
     public class HostBuilderTests
     {

diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostTests.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/HostTests.cs
@@ -2,10 +2,8 @@
 // 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.Threading;
@@ -15,7 +13,7 @@
 using Microsoft.Extensions.Logging;
 using Xunit;
 
-namespace Microsoft.Extensions.Hosting
+namespace Microsoft.Extensions.Hosting.Tests
 {
     public partial class HostTests
     {
@@ -275,36 +273,5 @@ 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();
-            }
-        }
     }
 }
diff --git a/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs b/src/libraries/Microsoft.Extensions.Hosting/tests/UnitTests/Internal/HostTests.cs
@@ -3,13 +3,16 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics.Tracing;
 using System.Linq;
 using System.Threading;
 using System.Threading.Tasks;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Hosting.Fakes;
+using Microsoft.Extensions.Hosting.Tests;
 using Microsoft.Extensions.Hosting.Tests.Fakes;
+using Microsoft.Extensions.Logging;
 using Moq;
 using Xunit;
 
@@ -1215,6 +1218,46 @@ public void ThrowExceptionForCustomImplementationOfIHostApplicationLifetime()
             });
         }
 
+        /// <summary>
+        /// Tests when a BackgroundService throws an exception asynchronously
+        /// (after an await), the exception gets logged correctly.
+        /// </summary>
+        [Fact]
+        public void BackgroundServiceAsyncExceptionGetsLogged()
+        {
+            using TestEventListener listener = new TestEventListener();
+
+            using IHost host = CreateBuilder()
+                .ConfigureLogging(logging =>
+                {
+                    logging.AddEventSourceLogger();
+                })
+                .ConfigureServices((hostContext, services) =>
+                {
+                    services.AddHostedService<AsyncThrowingService>();
+                })
+                .Start();
+
+            // give the background service 5 seconds to log the failure
+            Task timeout = Task.Delay(new TimeSpan(0, 0, 5));
+
+            while (true)
+            {
+                EventWrittenEventArgs[] events = listener.EventData.ToArray();
+                if (events.Any(e =>
+                    e.EventSource.Name == "Microsoft-Extensions-Logging" &&
+                    e.Payload.OfType<string>().Any(p => p.Contains("BackgroundService failed"))))
+                {
+                    break;
+                }
+
+                if (timeout.IsCompleted)
+                {
+                    Assert.True(false, "'BackgroundService failed' did not get logged");
+                }
+            }
+        }
+
         private IHostBuilder CreateBuilder(IConfiguration config = null)
         {
             return new HostBuilder().ConfigureHostConfiguration(builder => builder.AddConfiguration(config ?? new ConfigurationBuilder().Build()));
@@ -1324,5 +1367,15 @@ public ValueTask DisposeAsync()
                 return default;
             }
         }
+
+        private class AsyncThrowingService : BackgroundService
+        {
+            protected override async Task ExecuteAsync(CancellationToken stoppingToken)
+            {
+                await Task.Delay(1);
+
+                throw new Exception("Background Exception");
+            }
+        }
     }
 }