From 289107edac842b1e5fc1d7beb225d962d283a27f Mon Sep 17 00:00:00 2001 From: James Hickey Date: Thu, 26 Sep 2024 13:54:02 -0300 Subject: [PATCH] ability to log missed ticks + breaking change to API (#407) --- Demo/Startup.cs | 5 ++- Demo/appsettings.json | 3 ++ DocsV2/docs/Scheduler/README.md | 45 ++++++++++--------- Src/Coravel.Mailer/Mail/MessageBody.cs | 2 +- Src/Coravel/Coravel.csproj | 1 + .../Scheduling/HostedService/SchedulerHost.cs | 19 +++++--- .../Interfaces/ISchedulerConfiguration.cs | 3 +- Src/Coravel/Scheduling/Schedule/Scheduler.cs | 30 ++++++++----- .../Stubs/ServiceScopeFactoryStub.cs | 13 +++++- 9 files changed, 77 insertions(+), 44 deletions(-) diff --git a/Demo/Startup.cs b/Demo/Startup.cs index 75b821d4..5a47bf41 100644 --- a/Demo/Startup.cs +++ b/Demo/Startup.cs @@ -52,6 +52,7 @@ public void ConfigureServices(IServiceCollection services) services.AddScoped(); services.AddScoped(); + services.AddScoped(); services.AddEvents(); @@ -93,7 +94,7 @@ public void Configure(IApplicationBuilder app, IHostingEnvironment env) { scheduler.OnWorker("CPUIntensiveTasks"); scheduler - .Schedule().Hourly(); + .Schedule().EveryFifteenSeconds(); scheduler.OnWorker("TestingSeconds"); scheduler.Schedule( @@ -108,7 +109,7 @@ public void Configure(IApplicationBuilder app, IHostingEnvironment env) scheduler.Schedule(() => Thread.Sleep(5000)).EverySecond(); - }); + }).LogScheduledTaskProgress(); app.ApplicationServices .ConfigureQueue() diff --git a/Demo/appsettings.json b/Demo/appsettings.json index 93e423b2..cbe2a81d 100644 --- a/Demo/appsettings.json +++ b/Demo/appsettings.json @@ -24,6 +24,9 @@ }, "Queue": { "ConsummationDelay": 5 + }, + "Schedule": { + "LogTickCatchUp": true } } } diff --git a/DocsV2/docs/Scheduler/README.md b/DocsV2/docs/Scheduler/README.md index 47d04512..93c477d1 100644 --- a/DocsV2/docs/Scheduler/README.md +++ b/DocsV2/docs/Scheduler/README.md @@ -330,34 +330,39 @@ You can, of course, add error handling inside your specific tasks too. ## Logging Executed Task Progress -Coravel uses the `ILogger` .Net Core interface to allow logging scheduled task progress. - -In your `Startup.cs` file, you need to inject an instance of `IServiceProvider` to the constructor and assign it to a member field / property: +If you want Coravel to output log statements about scheduled task progress (usually to debug issues), you can call `LogScheduledTaskProgress()`: ```csharp -public Startup(IConfiguration configuration, /* Add this */ IServiceProvider services) +provider.UseScheduler(scheduler => { - Configuration = configuration; - Services = services; -} + // Assign scheduled tasks... +}) +.LogScheduledTaskProgress(); +``` -public IConfiguration Configuration { get; } +Your logging level should also be set to `Debug` in your `appsettings.json` file. -/* Add this property */ -public IServiceProvider Services { get; } -``` +:::tip +This method had a breaking change in Coravel `6.0.0`. +::: -Next, do the following: +## Logging Tick Catch Up -```csharp -provider.UseScheduler(scheduler => -{ - // Assign scheduled tasks... -}) -.LogScheduledTaskProgress(Services.GetService>()); +Coravel's scheduling runs on an internal `Timer`. Sometimes, due to a lack of resources or an overloaded system (common in small containerized processes), +the next "tick" could occur after 1 second. For example, a constrained container process might be overloaded and the `Timer` misses 10 seconds of ticks. +Coravel will chronologically replay each tick in order to catch up to "now". + +You can enable Coravel to output a log statement by setting the following configuration value in `appsettings.json`: + +```json +"Coravel": { + "Schedule": { + "LogTickCatchUp": true + } +} ``` -The `LogScheduledTaskProgress()` method accepts an instance of `ILogger`, which is available through the service provider. +This will be outputted as an `Informational` log statement. ## Force Run A Task At App Startup @@ -376,8 +381,6 @@ scheduler.Schedule() This will run immediately on application startup - even on weekends. After this initial run, any further runs will respect the assigned schedule of running once an hour only on weekdays. - - ## On App Closing When your app is stopped, Coravel will wait until any running scheduled tasks are completed. This will keep your app running in the background - as long as the parent process is not killed. diff --git a/Src/Coravel.Mailer/Mail/MessageBody.cs b/Src/Coravel.Mailer/Mail/MessageBody.cs index 074067f8..e25d3dfd 100644 --- a/Src/Coravel.Mailer/Mail/MessageBody.cs +++ b/Src/Coravel.Mailer/Mail/MessageBody.cs @@ -5,7 +5,7 @@ public class MessageBody public string Html { get; set; } public string Text { get; set; } - public MessageBody(string? html, string? text) + public MessageBody(string html, string text) { if(html is null && text is null) { diff --git a/Src/Coravel/Coravel.csproj b/Src/Coravel/Coravel.csproj index 67875ac7..567ad623 100644 --- a/Src/Coravel/Coravel.csproj +++ b/Src/Coravel/Coravel.csproj @@ -23,6 +23,7 @@ + diff --git a/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs b/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs index 7f66b981..5b561059 100644 --- a/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs +++ b/Src/Coravel/Scheduling/HostedService/SchedulerHost.cs @@ -1,5 +1,4 @@ using System; -using System.Collections.Generic; using System.Linq; using System.Threading; using System.Threading.Tasks; @@ -7,27 +6,30 @@ using Coravel.Scheduling.Schedule; using Coravel.Scheduling.Schedule.Interfaces; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Configuration; namespace Coravel.Scheduling.HostedService { internal class SchedulerHost : IHostedService, IDisposable { - private Scheduler _scheduler; + private readonly Scheduler _scheduler; + private readonly ILogger _logger; + private readonly IHostApplicationLifetime _lifetime; + private readonly IConfiguration _config; private Timer _timer; private bool _schedulerEnabled = true; - private ILogger _logger; - private IHostApplicationLifetime _lifetime; private object _tickLockObj = new object(); private EnsureContinuousSecondTicks _ensureContinuousSecondTicks; private readonly string ScheduledTasksRunningMessage = "Coravel's Scheduling service is attempting to close but there are tasks still running." + " App closing (in background) will be prevented until all tasks are completed."; - public SchedulerHost(IScheduler scheduler, ILogger logger, IHostApplicationLifetime lifetime) + public SchedulerHost(IScheduler scheduler, ILogger logger, IHostApplicationLifetime lifetime, IConfiguration config) { this._scheduler = scheduler as Scheduler; this._logger = logger; this._lifetime = lifetime; this._ensureContinuousSecondTicks = new EnsureContinuousSecondTicks(DateTime.UtcNow); + this._config = config; } public Task StartAsync(CancellationToken cancellationToken) @@ -62,7 +64,12 @@ private async void RunSchedulerPerSecondAsync(object state) } if (ticks.Length > 0) - { + { + if(this._config.GetValue("Coravel:Schedule:LogTickCatchUp") ?? false) + { + this._logger.LogInformation($"Coravel's scheduler is behind {ticks.Length} ticks and is catching-up to the current tick. Triggered at {now.ToString("o")}."); + } + foreach (var tick in ticks) { await this._scheduler.RunAtAsync(tick); diff --git a/Src/Coravel/Scheduling/Schedule/Interfaces/ISchedulerConfiguration.cs b/Src/Coravel/Scheduling/Schedule/Interfaces/ISchedulerConfiguration.cs index 2020d5d8..fa7a46fc 100644 --- a/Src/Coravel/Scheduling/Schedule/Interfaces/ISchedulerConfiguration.cs +++ b/Src/Coravel/Scheduling/Schedule/Interfaces/ISchedulerConfiguration.cs @@ -18,8 +18,7 @@ public interface ISchedulerConfiguration /// /// Log the progress of scheduled tasks. /// - /// /// - ISchedulerConfiguration LogScheduledTaskProgress(ILogger logger); + ISchedulerConfiguration LogScheduledTaskProgress(); } } \ No newline at end of file diff --git a/Src/Coravel/Scheduling/Schedule/Scheduler.cs b/Src/Coravel/Scheduling/Schedule/Scheduler.cs index befb832d..b13ad820 100644 --- a/Src/Coravel/Scheduling/Schedule/Scheduler.cs +++ b/Src/Coravel/Scheduling/Schedule/Scheduler.cs @@ -18,7 +18,7 @@ public class Scheduler : IScheduler, ISchedulerConfiguration { private ConcurrentDictionary _tasks; private Action _errorHandler; - private ILogger _logger; + private bool _shouldLogProgress = false; private IMutex _mutex; private readonly int EventLockTimeout_24Hours = 1440; private IServiceScopeFactory _scopeFactory; @@ -114,9 +114,9 @@ public ISchedulerConfiguration OnError(Action onError) return this; } - public ISchedulerConfiguration LogScheduledTaskProgress(ILogger logger) + public ISchedulerConfiguration LogScheduledTaskProgress() { - this._logger = logger; + this._shouldLogProgress = true; return this; } @@ -136,16 +136,24 @@ public bool TryUnschedule(string uniqueIdentifier) } private async Task InvokeEventWithLoggerScope(ScheduledEvent scheduledEvent) - { + { + using var scope = this._scopeFactory.CreateAsyncScope(); + ILogger logger = null; + + if(this._shouldLogProgress) + { + logger = scope.ServiceProvider.GetRequiredService>(); + } + var eventInvocableTypeName = scheduledEvent.InvocableType()?.Name; - using (_logger != null && eventInvocableTypeName != null ? - _logger.BeginScope($"Invocable Type : {eventInvocableTypeName}") : null) + using (logger != null && eventInvocableTypeName != null ? + logger.BeginScope($"Invocable Type : {eventInvocableTypeName}") : null) { - await InvokeEvent(scheduledEvent); + await InvokeEvent(scheduledEvent, logger); } } - private async Task InvokeEvent(ScheduledEvent scheduledEvent) + private async Task InvokeEvent(ScheduledEvent scheduledEvent, ILogger logger) { try { @@ -153,9 +161,9 @@ private async Task InvokeEvent(ScheduledEvent scheduledEvent) async Task Invoke() { - this._logger?.LogDebug("Scheduled task started..."); + logger?.LogDebug("Scheduled task started..."); await scheduledEvent.InvokeScheduledEvent(this._cancellationTokenSource.Token); - this._logger?.LogDebug("Scheduled task finished..."); + logger?.LogDebug("Scheduled task finished..."); }; if (scheduledEvent.ShouldPreventOverlapping()) @@ -183,7 +191,7 @@ async Task Invoke() { await this.TryDispatchEvent(new ScheduledEventFailed(scheduledEvent, e)); - this._logger?.LogError(e, "A scheduled task threw an Exception: "); + logger?.LogError(e, "A scheduled task threw an Exception: "); this._errorHandler?.Invoke(e); } diff --git a/Src/UnitTests/CoravelUnitTests/Scheduling/Stubs/ServiceScopeFactoryStub.cs b/Src/UnitTests/CoravelUnitTests/Scheduling/Stubs/ServiceScopeFactoryStub.cs index 0e79d9a6..8a822124 100644 --- a/Src/UnitTests/CoravelUnitTests/Scheduling/Stubs/ServiceScopeFactoryStub.cs +++ b/Src/UnitTests/CoravelUnitTests/Scheduling/Stubs/ServiceScopeFactoryStub.cs @@ -1,3 +1,4 @@ +using System; using Microsoft.Extensions.DependencyInjection; namespace CoravelUnitTests.Scheduling.Stubs @@ -6,7 +7,17 @@ public class ServiceScopeFactoryStub : IServiceScopeFactory { public IServiceScope CreateScope() { - throw new System.NotImplementedException(); + return new AsyncServiceScope(new ServiceScopeStub()); + } + } + + public class ServiceScopeStub : IServiceScope + { + public IServiceProvider ServiceProvider => throw new NotImplementedException(); + + public void Dispose() + { + // no-op } } } \ No newline at end of file