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)