From 127ea8c6a565a2459f9b361806d9de6a2d2a3892 Mon Sep 17 00:00:00 2001 From: KrzysztofPajak Date: Sun, 16 Aug 2026 12:50:01 +0200 Subject: [PATCH] Fix scheduler loop permanently stopping on reversible states BackgroundServiceTask.ExecuteAsync used break for states that can change at runtime: task not yet seeded in the DB, task disabled from the admin panel, and task leased to a machine that no longer holds it. Once hit, the loop ended for good and required a process restart to recover - e.g. QueuedMessagesSendScheduleTask silently stops sending order confirmation e-mails after an admin toggles it off and back on. Extract the scheduling logic into a pure Decide(task, machineName, utcNow) function with no side effects and no terminal outcome: every branch resolves to a delay-and-retry action, so there is no 'stop the loop' outcome to accidentally reach - the break statements are gone from ExecuteAsync entirely, by construction rather than by convention. Decide() is unit-tested directly without any timers, DI, or BackgroundService lifecycle involved. Also log unhandled exceptions from the outer catch instead of swallowing them silently, and resolve the logger once from the root provider so it is available there too. Co-Authored-By: Claude Sonnet 5 --- .../BackgroundServiceTaskTests.cs | 134 +++++++++++ .../Infrastructure/BackgroundServiceTask.cs | 216 ++++++++++-------- 2 files changed, 258 insertions(+), 92 deletions(-) diff --git a/src/Tests/Grand.Web.Common.Tests/Infrastructure/BackgroundServiceTaskTests.cs b/src/Tests/Grand.Web.Common.Tests/Infrastructure/BackgroundServiceTaskTests.cs index eba0394a8..5bfe5830b 100644 --- a/src/Tests/Grand.Web.Common.Tests/Infrastructure/BackgroundServiceTaskTests.cs +++ b/src/Tests/Grand.Web.Common.Tests/Infrastructure/BackgroundServiceTaskTests.cs @@ -3,8 +3,10 @@ using Grand.Infrastructure; using Grand.Web.Common.Infrastructure; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using Microsoft.VisualStudio.TestTools.UnitTesting; using Moq; +using static Grand.Web.Common.Infrastructure.BackgroundServiceTask; namespace Grand.Web.Common.Tests.Infrastructure; @@ -132,6 +134,39 @@ await WaitFor(() => _scheduleTaskServiceMock.Invocations.Any(i => _scheduleTaskMock.Verify(t => t.Execute(), Times.Never); } + [TestMethod] + public async Task ExecuteAsync_UnexpectedExceptionInLoop_LogsError() + { + _scheduleTaskServiceMock.Setup(s => s.GetTaskByName(TaskName)) + .ThrowsAsync(new InvalidOperationException("transient failure")); + + var loggerMock = new Mock>(); + var services = new ServiceCollection(); + services.AddSingleton(_scheduleTaskServiceMock.Object); + services.AddKeyedSingleton(TaskName, _scheduleTaskMock.Object); + services.AddSingleton(Mock.Of()); + services.AddSingleton(Mock.Of()); + services.AddSingleton(Mock.Of()); + services.AddSingleton(loggerMock.Object); + var serviceProvider = services.BuildServiceProvider(); + + var service = new BackgroundServiceTask(TaskName, serviceProvider); + using var cts = new CancellationTokenSource(); + await service.StartAsync(cts.Token); + + await WaitFor(() => loggerMock.Invocations.Any(i => i.Method.Name == "Log")); + cts.Cancel(); + + //the failure must be logged, not swallowed silently + loggerMock.Verify(l => l.Log( + LogLevel.Error, + It.IsAny(), + It.IsAny(), + It.Is(e => e is InvalidOperationException), + It.IsAny>()), + Times.AtLeastOnce); + } + private static async Task WaitFor(Func condition) { for (var i = 0; i < 300; i++) @@ -143,3 +178,102 @@ private static async Task WaitFor(Func condition) Assert.Fail("Condition was not met within the timeout"); } } + +/// +/// Pure unit tests for the scheduling decision - no timers, no DI, no BackgroundService +/// lifecycle. This is what actually proves REL-001 is fixed: every branch resolves to a +/// delay-and-retry, none of them can signal "stop the loop". +/// +[TestClass] +public class BackgroundServiceTaskDecideTests +{ + private static readonly DateTime UtcNow = new(2026, 8, 16, 12, 0, 0, DateTimeKind.Utc); + private const string MachineName = "this-machine"; + + private static ScheduleTask NewTask(bool enabled = true, string leasedBy = null, + int timeInterval = 60, DateTime? lastStartUtc = null) + { + return new ScheduleTask { + Id = "1", + Enabled = enabled, + LeasedByMachineName = leasedBy, + TimeInterval = timeInterval, + LastStartUtc = lastStartUtc + }; + } + + [TestMethod] + public void Decide_TaskNotSeededYet_ReturnsRetryInOneMinute() + { + var decision = Decide(null, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.Retry, decision.Action); + Assert.AreEqual(1, decision.DelayMinutes); + } + + [TestMethod] + public void Decide_TaskDisabled_ReturnsRetryAfterOwnInterval() + { + var task = NewTask(enabled: false, timeInterval: 15); + + var decision = Decide(task, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.Retry, decision.Action); + Assert.AreEqual(15, decision.DelayMinutes); + } + + [TestMethod] + public void Decide_TaskLeasedByAnotherMachine_ReturnsRetryAfterOwnInterval() + { + var task = NewTask(leasedBy: "other-machine", timeInterval: 15); + + var decision = Decide(task, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.Retry, decision.Action); + Assert.AreEqual(15, decision.DelayMinutes); + } + + [TestMethod] + public void Decide_TaskLeasedByOwnMachine_IsEligible() + { + var task = NewTask(leasedBy: MachineName); + + var decision = Decide(task, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.RunNow, decision.Action); + } + + [TestMethod] + public void Decide_EnabledAndNeverRunBefore_ReturnsRunNow() + { + var task = NewTask(timeInterval: 30); + + var decision = Decide(task, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.RunNow, decision.Action); + Assert.AreEqual(30, decision.DelayMinutes); + } + + [TestMethod] + public void Decide_EnabledAndIntervalElapsed_ReturnsRunNow() + { + var task = NewTask(timeInterval: 30, lastStartUtc: UtcNow.AddMinutes(-31)); + + var decision = Decide(task, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.RunNow, decision.Action); + Assert.AreEqual(30, decision.DelayMinutes); + } + + [TestMethod] + public void Decide_EnabledButNotDueYet_ReturnsWaitForRemainingTimeTruncatedToWholeMinutes() + { + //10.5 minutes elapsed of a 30-minute interval -> 19.5 minutes remain + var task = NewTask(timeInterval: 30, lastStartUtc: UtcNow.AddSeconds(-(10 * 60 + 30))); + + var decision = Decide(task, MachineName, UtcNow); + + Assert.AreEqual(ScheduleAction.WaitForNextRun, decision.Action); + Assert.AreEqual(19, decision.DelayMinutes); //truncated, same as the original code + } +} diff --git a/src/Web/Grand.Web.Common/Infrastructure/BackgroundServiceTask.cs b/src/Web/Grand.Web.Common/Infrastructure/BackgroundServiceTask.cs index cc03ed0d6..09985c4f5 100644 --- a/src/Web/Grand.Web.Common/Infrastructure/BackgroundServiceTask.cs +++ b/src/Web/Grand.Web.Common/Infrastructure/BackgroundServiceTask.cs @@ -1,10 +1,13 @@ -using Grand.Business.Core.Interfaces.System.ScheduleTasks; +using System.Runtime.CompilerServices; +using Grand.Business.Core.Interfaces.System.ScheduleTasks; using Grand.Domain.Tasks; using Grand.Infrastructure; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; +[assembly: InternalsVisibleTo("Grand.Web.Common.Tests")] + namespace Grand.Web.Common.Infrastructure; public class BackgroundServiceTask : BackgroundService @@ -22,116 +25,145 @@ public BackgroundServiceTask(string name, IServiceProvider serviceProvider) _serviceProvider = serviceProvider; } + internal enum ScheduleAction + { + //task missing, disabled, or leased to another instance - all reversible, poll again later + Retry, + //own lease (or none), enabled, and due - claim and execute + RunNow, + //own lease, enabled, but not due yet - sleep until it is + WaitForNextRun + } + + internal readonly record struct ScheduleDecision(ScheduleAction Action, int DelayMinutes); + + /// + /// Pure decision of what the loop should do this iteration and how long to sleep + /// afterward. Deliberately has no side effects and no terminal outcome - every branch + /// resolves to a delay-and-retry, never to "stop the loop" - so the reversible states + /// (task not seeded yet, disabled, leased elsewhere) can never end the loop for good. + /// + internal static ScheduleDecision Decide(ScheduleTask task, string machineName, DateTime utcNow) + { + if (task == null) + return new ScheduleDecision(ScheduleAction.Retry, 1); + + var timeInterval = task.TimeInterval > 0 ? task.TimeInterval : 1; + + var eligible = task.Enabled && + (string.IsNullOrEmpty(task.LeasedByMachineName) || machineName == task.LeasedByMachineName); + if (!eligible) + return new ScheduleDecision(ScheduleAction.Retry, timeInterval); + + if (task.LastStartUtc.HasValue) + { + var nextRunUtc = task.LastStartUtc.Value.AddMinutes(task.TimeInterval); + if (utcNow < nextRunUtc) + return new ScheduleDecision(ScheduleAction.WaitForNextRun, (int)(nextRunUtc - utcNow).TotalMinutes); + } + + return new ScheduleDecision(ScheduleAction.RunNow, timeInterval); + } + protected override async Task ExecuteAsync(CancellationToken stoppingToken) { + //resolved once from the root provider (not the per-iteration scope) so it also + //survives to log failures raised before/around a scope, e.g. in the outer catch + var logger = _serviceProvider.GetService>(); + while (!stoppingToken.IsCancellationRequested) try { using var scope = _serviceProvider.CreateScope(); var serviceProvider = scope.ServiceProvider; - var logger = serviceProvider.GetService>(); var scheduleTaskService = serviceProvider.GetService(); var task = await scheduleTaskService.GetTaskByName(Name); + var decision = Decide(task, Environment.MachineName, DateTime.UtcNow); + if (task == null) - { logger.LogInformation("Task {TaskName} is not exists in the database", Name); - break; - } + else if (decision.Action != ScheduleAction.Retry) + await RunTask(serviceProvider, scheduleTaskService, task, + decision.Action == ScheduleAction.RunNow, logger, stoppingToken); - var machineName = Environment.MachineName; - var timeInterval = task.TimeInterval > 0 ? task.TimeInterval : 1; - if (task.Enabled && (string.IsNullOrEmpty(task.LeasedByMachineName) || - machineName == task.LeasedByMachineName)) - { + //every branch above falls through to here - the loop always sleeps and + //retries, it never exits on its own (only cancellation ends it) + await Task.Delay(TimeSpan.FromMinutes(decision.DelayMinutes), stoppingToken); + } + catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) + { + //application shutdown - not a task failure + } + catch (Exception exc) + { + logger.LogError(exc, "Unhandled error in the background loop for task {TaskName}", Name); + await Task.Delay(TimeSpan.FromMinutes(1), stoppingToken); + } + } + + private async Task RunTask(IServiceProvider serviceProvider, IScheduleTaskService scheduleTaskService, + ScheduleTask task, bool due, ILogger logger, CancellationToken stoppingToken) + { + var updateTask = false; + var scheduleTask = serviceProvider.GetRequiredKeyedService(task.ScheduleTaskName); + if (scheduleTask != null) + { + //assign current customer (background task) / current store (from task) + await WorkContext(serviceProvider, task); + + if (!due) + return; - var updateTask = false; - var scheduleTask = serviceProvider.GetRequiredKeyedService(task.ScheduleTaskName); - if (scheduleTask != null) - { - //assign current customer (background task) / current store (from task) - await WorkContext(serviceProvider, task); - var runTask = true; - if (task.LastStartUtc.HasValue) - { - var dateTimeNow = DateTime.UtcNow; - if (dateTimeNow < task.LastStartUtc.Value.AddMinutes(task.TimeInterval)) - { - runTask = false; - timeInterval = - (int)(task.LastStartUtc.Value.AddMinutes(task.TimeInterval) - dateTimeNow) - .TotalMinutes; - } - else - { - runTask = true; - timeInterval = task.TimeInterval > 0 ? task.TimeInterval : 1; - } - } - - if (runTask) - { - //claim this run atomically - when several instances race, - //only one wins and executes the task (no duplicated e-mails etc.) - var runStartUtc = DateTime.UtcNow; - var claimed = await scheduleTaskService.TryClaimTaskRun(task.Id, task.LastStartUtc, - runStartUtc, InstanceId); - if (claimed) - { - updateTask = true; - task.LastStartUtc = runStartUtc; - task.LeasedByInstance = InstanceId; - try - { - logger.LogInformation("Task {TaskName} execute", Name); - await scheduleTask.Execute(); - task.LastSuccessUtc = DateTime.UtcNow; - task.LastNonSuccessEndUtc = null; - } - catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) - { - //application shutdown - do not classify as a task failure - throw; - } - catch (Exception exc) - { - task.LastNonSuccessEndUtc = DateTime.UtcNow; - task.Enabled = !task.StopOnError; - logger.LogError(exc, - "Error while running the \'{TaskScheduleTaskName}\' schedule task", - task.ScheduleTaskName); - } - } - else - { - //another instance executes this run - check again on the next interval - if (logger.IsEnabled(LogLevel.Debug)) - logger.LogDebug("Task {TaskName} claimed by another instance, skipping", Name); - } - } - } - else - { - updateTask = true; - task.Enabled = !task.StopOnError; - task.LastNonSuccessEndUtc = DateTime.UtcNow; - logger.LogError("Type {TaskName} is not registered", Name); - } - - //persist only when this instance actually ran the task - an unconditional - //write would overwrite the claim/results of the winning instance with stale data - if (updateTask) - await scheduleTaskService.UpdateTask(task); - await Task.Delay(TimeSpan.FromMinutes(timeInterval), stoppingToken); + //claim this run atomically - when several instances race, + //only one wins and executes the task (no duplicated e-mails etc.) + var runStartUtc = DateTime.UtcNow; + var claimed = await scheduleTaskService.TryClaimTaskRun(task.Id, task.LastStartUtc, + runStartUtc, InstanceId); + if (claimed) + { + updateTask = true; + task.LastStartUtc = runStartUtc; + task.LeasedByInstance = InstanceId; + try + { + logger.LogInformation("Task {TaskName} execute", Name); + await scheduleTask.Execute(); + task.LastSuccessUtc = DateTime.UtcNow; + task.LastNonSuccessEndUtc = null; } - else + catch (OperationCanceledException) when (stoppingToken.IsCancellationRequested) { - break; + //application shutdown - do not classify as a task failure + throw; + } + catch (Exception exc) + { + task.LastNonSuccessEndUtc = DateTime.UtcNow; + task.Enabled = !task.StopOnError; + logger.LogError(exc, + "Error while running the \'{TaskScheduleTaskName}\' schedule task", + task.ScheduleTaskName); } } - catch (Exception) + else { - await Task.Delay(TimeSpan.FromMinutes(1), stoppingToken); + //another instance executes this run - check again on the next interval + if (logger.IsEnabled(LogLevel.Debug)) + logger.LogDebug("Task {TaskName} claimed by another instance, skipping", Name); } + } + else + { + updateTask = true; + task.Enabled = !task.StopOnError; + task.LastNonSuccessEndUtc = DateTime.UtcNow; + logger.LogError("Type {TaskName} is not registered", Name); + } + + //persist only when this instance actually ran the task - an unconditional + //write would overwrite the claim/results of the winning instance with stale data + if (updateTask) + await scheduleTaskService.UpdateTask(task); } private static async Task WorkContext(IServiceProvider serviceProvider, ScheduleTask scheduleTask)