diff --git a/README.md b/README.md index 8b72a96..cd5765f 100644 --- a/README.md +++ b/README.md @@ -159,6 +159,8 @@ builder.Host.UseSerilog( Because Sheddueller's capture is a Microsoft `ILoggerProvider`, Microsoft logging filters still apply. Configure `Logging`/`ILoggingBuilder` filters alongside any Serilog filtering rules if you want to control which job logs are stored by Sheddueller. +Set `ShedduellerOptions.EnableJobLogCapture = true` to enable durable capture of `ILogger` job logs. This is disabled by default. The worker still opens the job logging scope, so external providers can continue receiving `ShedduellerJobId`, `ShedduellerAttemptNumber`, and `ShedduellerNodeId`. + Use `NotBeforeUtc` for delayed jobs. Use `JobIdempotencyKind.MethodAndArguments` to reuse an existing queued job with the same target method and serialized arguments. ## Recurring Schedules diff --git a/src/Sheddueller.Worker/Internal/ShedduellerJobLoggerProvider.cs b/src/Sheddueller.Worker/Internal/ShedduellerJobLoggerProvider.cs index ba2cf9f..988d6cf 100644 --- a/src/Sheddueller.Worker/Internal/ShedduellerJobLoggerProvider.cs +++ b/src/Sheddueller.Worker/Internal/ShedduellerJobLoggerProvider.cs @@ -4,13 +4,17 @@ namespace Sheddueller.Worker.Internal; using System.Globalization; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Options; +using Sheddueller; using Sheddueller.Storage; -internal sealed class ShedduellerJobLoggerProvider(ShedduellerJobLogEventQueue eventQueue) : ILoggerProvider +internal sealed class ShedduellerJobLoggerProvider( + ShedduellerJobLogEventQueue eventQueue, + IOptions options) : ILoggerProvider { public ILogger CreateLogger(string categoryName) - => new JobLogger(eventQueue, categoryName); + => new JobLogger(eventQueue, options.Value.EnableJobLogCapture, categoryName); public void Dispose() { @@ -18,6 +22,7 @@ public void Dispose() private sealed class JobLogger( ShedduellerJobLogEventQueue eventQueue, + bool enableJobLogCapture, string categoryName) : ILogger { public IDisposable BeginScope(TState state) @@ -25,7 +30,8 @@ public IDisposable BeginScope(TState state) => NullScope.Instance; public bool IsEnabled(LogLevel logLevel) - => logLevel != LogLevel.None && JobLogCaptureContext.Active is not null; + => logLevel != LogLevel.None + && enableJobLogCapture; [SuppressMessage("Design", "CA1031:Do not catch general exception types", Justification = "Captured job logging is best-effort and must not fail jobs.")] public void Log( @@ -35,7 +41,7 @@ public void Log( Exception? exception, Func formatter) { - if (logLevel == LogLevel.None) + if (logLevel == LogLevel.None || !enableJobLogCapture) { return; } diff --git a/src/Sheddueller/ShedduellerOptions.cs b/src/Sheddueller/ShedduellerOptions.cs index 18d6a7e..b46e9df 100644 --- a/src/Sheddueller/ShedduellerOptions.cs +++ b/src/Sheddueller/ShedduellerOptions.cs @@ -45,6 +45,11 @@ public sealed class ShedduellerOptions /// public RetryPolicy? DefaultRetryPolicy { get; set; } + /// + /// Gets or sets whether Microsoft ILogger messages written during job execution are captured as durable job log events. + /// + public bool EnableJobLogCapture { get; set; } + /// /// Gets the effective stale worker node threshold. /// diff --git a/test/Sheddueller.Worker.Tests/WorkerJobLoggerTests.cs b/test/Sheddueller.Worker.Tests/WorkerJobLoggerTests.cs index 8d0bacb..d3954a3 100644 --- a/test/Sheddueller.Worker.Tests/WorkerJobLoggerTests.cs +++ b/test/Sheddueller.Worker.Tests/WorkerJobLoggerTests.cs @@ -21,7 +21,10 @@ public async Task JobExecution_LoggerWritesDuringJob_RecordsDurableLogEvent() var job = CreateClaimedJob(nameof(LoggingJob.RunAsync)); var store = new SingleClaimJobStore(job); var eventSink = new RecordingJobEventSink(); - await using var provider = CreateProvider(store, eventSink); + await using var provider = CreateProvider( + store, + eventSink, + configureOptions: options => options.EnableJobLogCapture = true); var outsideLogger = provider.GetRequiredService>(); OutsideLog(outsideLogger, null); var hostedServices = await StartHostedServicesAsync(provider, cancellationTokenSource.Token); @@ -29,7 +32,8 @@ public async Task JobExecution_LoggerWritesDuringJob_RecordsDurableLogEvent() await store.Completed.Task.WaitAsync(cancellationTokenSource.Token); await StopHostedServicesAsync(hostedServices, cancellationTokenSource.Token); - var request = eventSink.Requests.ShouldHaveSingleItem(); + eventSink.Requests.Any(request => HasEventId(request, "41")).ShouldBeFalse(); + var request = eventSink.Requests.Single(request => HasEventId(request, "42")); request.JobId.ShouldBe(job.JobId); request.Kind.ShouldBe(JobEventKind.Log); request.AttemptNumber.ShouldBe(job.AttemptCount); @@ -61,6 +65,27 @@ public async Task JobExecution_LoggerWritesDuringJob_AddsJobMetadataScopeToExter entry.ScopeProperties["ShedduellerNodeId"].ShouldBe("worker-logger"); } + [Fact] + public async Task JobExecution_LogCaptureDisabledByDefault_DoesNotRecordDurableLogEventButKeepsExternalScope() + { + using var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(5)); + var job = CreateClaimedJob(nameof(LoggingJob.RunAsync)); + var store = new SingleClaimJobStore(job); + var eventSink = new RecordingJobEventSink(); + using var logs = new ScopeRecordingLoggerProvider(); + await using var provider = CreateProvider(store, eventSink, loggerProvider: logs); + var hostedServices = await StartHostedServicesAsync(provider, cancellationTokenSource.Token); + + await store.Completed.Task.WaitAsync(cancellationTokenSource.Token); + await StopHostedServicesAsync(hostedServices, cancellationTokenSource.Token); + + eventSink.Requests.ShouldBeEmpty(); + var entry = logs.Entries.Single(log => log.EventId.Id == 42); + entry.ScopeProperties["ShedduellerJobId"].ShouldBe(job.JobId); + entry.ScopeProperties["ShedduellerAttemptNumber"].ShouldBe(job.AttemptCount); + entry.ScopeProperties["ShedduellerNodeId"].ShouldBe("worker-logger"); + } + [Fact] public async Task JobExecution_FireAndForgetLoggerAfterCompletion_DoesNotRecordDurableLogEvent() { @@ -69,7 +94,11 @@ public async Task JobExecution_FireAndForgetLoggerAfterCompletion_DoesNotRecordD var store = new SingleClaimJobStore(job); var eventSink = new RecordingJobEventSink(); var coordinator = new LateLogCoordinator(); - await using var provider = CreateProvider(store, eventSink, coordinator); + await using var provider = CreateProvider( + store, + eventSink, + coordinator, + configureOptions: options => options.EnableJobLogCapture = true); var hostedServices = await StartHostedServicesAsync(provider, cancellationTokenSource.Token); await store.Completed.Task.WaitAsync(cancellationTokenSource.Token); @@ -86,7 +115,10 @@ public async Task JobExecution_LoggerSinkFails_StillCompletesJob() using var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(5)); var job = CreateClaimedJob(nameof(LoggingJob.RunAsync)); var store = new SingleClaimJobStore(job); - await using var provider = CreateProvider(store, new ThrowingJobEventSink()); + await using var provider = CreateProvider( + store, + new ThrowingJobEventSink(), + configureOptions: options => options.EnableJobLogCapture = true); var hostedServices = await StartHostedServicesAsync(provider, cancellationTokenSource.Token); var completed = await store.Completed.Task.WaitAsync(cancellationTokenSource.Token); @@ -101,7 +133,10 @@ public async Task JobExecution_LoggerFormatterFails_StillCompletesJob() using var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(5)); var job = CreateClaimedJob(nameof(ThrowingFormatterJob.RunAsync)); var store = new SingleClaimJobStore(job); - await using var provider = CreateProvider(store, new RecordingJobEventSink()); + await using var provider = CreateProvider( + store, + new RecordingJobEventSink(), + configureOptions: options => options.EnableJobLogCapture = true); var hostedServices = await StartHostedServicesAsync(provider, cancellationTokenSource.Token); var completed = await store.Completed.Task.WaitAsync(cancellationTokenSource.Token); @@ -117,7 +152,10 @@ public async Task JobExecution_LoggerSinkBlocks_StillCompletesJob() var job = CreateClaimedJob(nameof(LoggingJob.RunAsync)); var store = new SingleClaimJobStore(job); var eventSink = new BlockingJobEventSink(); - await using var provider = CreateProvider(store, eventSink); + await using var provider = CreateProvider( + store, + eventSink, + configureOptions: options => options.EnableJobLogCapture = true); var hostedServices = await StartHostedServicesAsync(provider, cancellationTokenSource.Token); var completed = await store.Completed.Task.WaitAsync(cancellationTokenSource.Token); @@ -131,7 +169,8 @@ private static ServiceProvider CreateProvider( SingleClaimJobStore store, IJobEventSink eventSink, LateLogCoordinator? coordinator = null, - ILoggerProvider? loggerProvider = null) + ILoggerProvider? loggerProvider = null, + Action? configureOptions = null) where TJob : class { var services = new ServiceCollection(); @@ -158,11 +197,17 @@ private static ServiceProvider CreateProvider( options.IdlePollingInterval = TimeSpan.FromMilliseconds(10); options.HeartbeatInterval = TimeSpan.FromSeconds(5); options.LeaseDuration = TimeSpan.FromSeconds(30); + configureOptions?.Invoke(options); })); return services.BuildServiceProvider(); } + private static bool HasEventId(AppendJobEventRequest request, string eventId) + => request.Fields is not null + && request.Fields.TryGetValue("EventId", out var actualEventId) + && string.Equals(actualEventId, eventId, StringComparison.Ordinal); + private static async Task> StartHostedServicesAsync( ServiceProvider provider, CancellationToken cancellationToken)