(hangfire): #29 log job start and finish

PiBox.Plugins/Jobs/Hangfire/README.md

@@ -176,6 +176,10 @@ should be kept until it gets deleted
 
 ### Filters
 
+#### LogJobExecutionFilter
+
+This filter logs the start and finish of an job execution.
+
 #### EnabledByFeatureFilter
 
 This filter works in conjunction with the [microsoft feature management system](https://github.com/microsoft/FeatureManagement-Dotnet).

PiBox.Plugins/Jobs/Hangfire/src/PiBox.Plugins.Jobs.Hangfire/Attributes/LogJobExecutionFilter.cs

@@ -0,0 +1,28 @@
+using Hangfire.Common;
+using Hangfire.Server;
+using Microsoft.Extensions.Logging;
+
+namespace PiBox.Plugins.Jobs.Hangfire.Attributes
+{
+    public class LogJobExecutionFilter : JobFilterAttribute,
+        IServerFilter
+    {
+        private readonly ILoggerFactory _loggerFactory;
+
+        public LogJobExecutionFilter(ILoggerFactory loggerFactory)
+        {
+            _loggerFactory = loggerFactory;
+        }
+        public void OnPerforming(PerformingContext context)
+        {
+            _loggerFactory.CreateLogger(context.BackgroundJob.Job.Type)
+                .LogInformation("Job with id {JobId} started executing", context.BackgroundJob.Id);
+        }
+
+        public void OnPerformed(PerformedContext context)
+        {
+            _loggerFactory.CreateLogger(context.BackgroundJob.Job.Type)
+                .LogInformation("Job with id {JobId} finished executing", context.BackgroundJob.Id);
+        }
+    }
+}

PiBox.Plugins/Jobs/Hangfire/src/PiBox.Plugins.Jobs.Hangfire/HangFirePlugin.cs

@@ -16,7 +16,8 @@
 
 namespace PiBox.Plugins.Jobs.Hangfire
 {
-    public class HangFirePlugin : IPluginServiceConfiguration, IPluginApplicationConfiguration, IPluginHealthChecksConfiguration
+    public class HangFirePlugin : IPluginServiceConfiguration, IPluginApplicationConfiguration,
+        IPluginHealthChecksConfiguration
     {
         private readonly IImplementationResolver _implementationResolver;
         private readonly HangfireConfiguration _hangfireConfig;
@@ -50,7 +51,8 @@ public void ConfigureServices(IServiceCollection serviceCollection)
             serviceCollection.AddHangfireServer(options =>
             {
                 if (_hangfireConfig.PollingIntervalInMs.HasValue)
-                    options.SchedulePollingInterval = TimeSpan.FromMilliseconds(_hangfireConfig.PollingIntervalInMs.Value);
+                    options.SchedulePollingInterval =
+                        TimeSpan.FromMilliseconds(_hangfireConfig.PollingIntervalInMs.Value);
 
                 if (_hangfireConfig.WorkerCount.HasValue)
                     options.WorkerCount = _hangfireConfig.WorkerCount.Value;
@@ -60,20 +62,26 @@ public void ConfigureServices(IServiceCollection serviceCollection)
 
         public void ConfigureApplication(IApplicationBuilder applicationBuilder)
         {
+            GlobalJobFilters.Filters.Add(
+                new LogJobExecutionFilter(applicationBuilder.ApplicationServices.GetRequiredService<ILoggerFactory>()));
             if (_hangfireConfig.EnableJobsByFeatureManagementConfig)
             {
                 GlobalJobFilters.Filters.Add(new EnabledByFeatureFilter(
                     applicationBuilder.ApplicationServices.GetRequiredService<IFeatureManager>(),
-                    applicationBuilder.ApplicationServices.GetService<ILogger<EnabledByFeatureFilter>>()));
+                    applicationBuilder.ApplicationServices.GetRequiredService<ILogger<EnabledByFeatureFilter>>()));
             }
 
             var urlAuthFilter = new HostAuthorizationFilter(_hangfireConfig.AllowedDashboardHost);
-            applicationBuilder.UseHangfireDashboard(options: new() { Authorization = new List<IDashboardAuthorizationFilter> { urlAuthFilter } });
+            applicationBuilder.UseHangfireDashboard(options: new()
+            {
+                Authorization = new List<IDashboardAuthorizationFilter> { urlAuthFilter }
+            });
             var jobRegister = applicationBuilder.ApplicationServices.GetRequiredService<IJobRegister>();
             var jobOptions = applicationBuilder.ApplicationServices.GetService<JobOptions>();
             jobOptions?.ConfigureJobs.Invoke(jobRegister, applicationBuilder.ApplicationServices);
             var registerJobMethod = jobRegister.GetType().GetMethod(nameof(IJobRegister.RegisterRecurringAsyncJob))!;
-            foreach (var job in _implementationResolver.FindTypes(f => f.HasAttribute<RecurringJobAttribute>() && f.Implements<IAsyncJob>()))
+            foreach (var job in _implementationResolver.FindTypes(f =>
+                         f.HasAttribute<RecurringJobAttribute>() && f.Implements<IAsyncJob>()))
             {
                 var recurringJobDetails = job.GetAttribute<RecurringJobAttribute>()!;
                 var genericMethod = registerJobMethod.MakeGenericMethod(job);

PiBox.Plugins/Jobs/Hangfire/src/PiBox.Plugins.Jobs.Hangfire/Job/AsyncHangfireJob.cs

@@ -21,8 +21,6 @@ protected async Task<object> InternalExecuteAsync(Func<Task<object>> action)
                 throw;
             }
 
-            Logger.LogInformation("Job executed with {JobResult}", result);
-
             return result;
         }
     }

PiBox.Plugins/Jobs/Hangfire/test/PiBox.Plugins.Jobs.Hangfire.Tests/Attributes/EnabledByFeatureFilterTests.cs

@@ -3,6 +3,7 @@
 using Hangfire.MemoryStorage;
 using Hangfire.Server;
 using Hangfire.Storage;
+using Microsoft.Extensions.Logging;
 using Microsoft.FeatureManagement;
 using NSubstitute;
 using NUnit.Framework;
@@ -11,6 +12,40 @@
 
 namespace PiBox.Plugins.Jobs.Hangfire.Tests.Attributes
 {
+
+    public class LogJobExecutionFilterTests
+    {
+        [Test]
+        public void JobIsNotCancelledWhenMatchingFeatureIsEnabled()
+        {
+            JobStorage.Current = new MemoryStorage();
+            var loggerFactory = Substitute.For<ILoggerFactory>();
+            var fakeLogger = new FakeLogger<TestJobAsync>();
+            loggerFactory.CreateLogger(default!).ReturnsForAnyArgs(fakeLogger);
+            var filter = new LogJobExecutionFilter(loggerFactory);
+
+            var job = new global::Hangfire.Common.Job(typeof(TestJobAsync),
+                typeof(TestJobAsync).GetMethod(nameof(TestJobAsync.ExecuteAsync)), CancellationToken.None);
+            var performContext = new PerformContext(JobStorage.Current,
+                Substitute.For<IStorageConnection>(),
+                new BackgroundJob("id1", job, DateTime.Now),
+                new JobCancellationToken(false)
+            );
+            var context = new PerformingContext(
+                performContext
+            );
+            filter.OnPerforming(
+                context
+            );
+
+            fakeLogger.Entries.Should().Contain(x => x.Message == "Job with id id1 started executing");
+
+            filter.OnPerformed(new PerformedContext(performContext, null, false, null));
+
+            fakeLogger.Entries.Should().Contain(x => x.Message == "Job with id id1 finished executing");
+        }
+    }
+
     public class EnabledByFeatureFilterTests
     {
         [Test]

PiBox.Plugins/Jobs/Hangfire/test/PiBox.Plugins.Jobs.Hangfire.Tests/HangfirePluginTests.cs

@@ -116,6 +116,7 @@ public void ConfigureApplicationTest()
             collection[3].JobType.Should().Be(typeof(TestJobAsync));
 
             GlobalJobFilters.Filters.Should().Contain(x => x.Instance.GetType() == typeof(EnabledByFeatureFilter));
+            GlobalJobFilters.Filters.Should().Contain(x => x.Instance.GetType() == typeof(LogJobExecutionFilter));
         }
 
         [Test]