add Hangfire task logging

Author: Pathoschild

src/SMAPI.Web/BackgroundService.cs

@@ -3,14 +3,16 @@
 using System.Threading;
 using System.Threading.Tasks;
 using Hangfire;
+using Hangfire.Console;
+using Hangfire.Server;
+using Humanizer;
 using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Options;
 using StardewModdingAPI.Toolkit;
 using StardewModdingAPI.Toolkit.Framework.Clients.CurseForgeExport;
-using StardewModdingAPI.Toolkit.Framework.Clients.CurseForgeExport.ResponseModels;
 using StardewModdingAPI.Toolkit.Framework.Clients.NexusExport;
-using StardewModdingAPI.Toolkit.Framework.Clients.NexusExport.ResponseModels;
 using StardewModdingAPI.Toolkit.Framework.Clients.Wiki;
+using StardewModdingAPI.Web.Framework.Caching;
 using StardewModdingAPI.Web.Framework.Caching.CurseForgeExport;
 using StardewModdingAPI.Web.Framework.Caching.Mods;
 using StardewModdingAPI.Web.Framework.Caching.NexusExport;
@@ -108,19 +110,19 @@ public Task StartAsync(CancellationToken cancellationToken)
             bool enableNexusExport = BackgroundService.NexusExportApiClient is not DisabledNexusExportApiClient;
 
             // set startup tasks
-            BackgroundJob.Enqueue(() => BackgroundService.UpdateWikiAsync());
+            BackgroundJob.Enqueue(() => BackgroundService.UpdateWikiAsync(null));
             if (enableCurseForgeExport)
-                BackgroundJob.Enqueue(() => BackgroundService.UpdateCurseForgeExportAsync());
+                BackgroundJob.Enqueue(() => BackgroundService.UpdateCurseForgeExportAsync(null));
             if (enableNexusExport)
-                BackgroundJob.Enqueue(() => BackgroundService.UpdateNexusExportAsync());
+                BackgroundJob.Enqueue(() => BackgroundService.UpdateNexusExportAsync(null));
             BackgroundJob.Enqueue(() => BackgroundService.RemoveStaleModsAsync());
 
             // set recurring tasks
-            RecurringJob.AddOrUpdate("update wiki data", () => BackgroundService.UpdateWikiAsync(), "*/10 * * * *");      // every 10 minutes
+            RecurringJob.AddOrUpdate("update wiki data", () => BackgroundService.UpdateWikiAsync(null), "*/10 * * * *");      // every 10 minutes
             if (enableCurseForgeExport)
-                RecurringJob.AddOrUpdate("update CurseForge export", () => BackgroundService.UpdateCurseForgeExportAsync(), "*/10 * * * *");
+                RecurringJob.AddOrUpdate("update CurseForge export", () => BackgroundService.UpdateCurseForgeExportAsync(null), "*/10 * * * *");
             if (enableNexusExport)
-                RecurringJob.AddOrUpdate("update Nexus export", () => BackgroundService.UpdateNexusExportAsync(), "*/10 * * * *");
+                RecurringJob.AddOrUpdate("update Nexus export", () => BackgroundService.UpdateNexusExportAsync(null), "*/10 * * * *");
             RecurringJob.AddOrUpdate("remove stale mods", () => BackgroundService.RemoveStaleModsAsync(), "2/10 * * * *"); // offset by 2 minutes so it runs after updates (e.g. 00:02, 00:12, etc)
 
             BackgroundService.IsStarted = true;
@@ -150,54 +152,48 @@ public void Dispose()
         ** Tasks
         ****/
         /// <summary>Update the cached wiki metadata.</summary>
-        [AutomaticRetry(Attempts = 3, DelaysInSeconds = new[] { 30, 60, 120 })]
-        public static async Task UpdateWikiAsync()
+        /// <param name="context">Information about the context in which the job is performed. This is injected automatically by Hangfire.</param>
+        [AutomaticRetry(Attempts = 3, DelaysInSeconds = [30, 60, 120])]
+        public static async Task UpdateWikiAsync(PerformContext? context)
         {
             if (!BackgroundService.IsStarted)
                 throw new InvalidOperationException($"Must call {nameof(BackgroundService.StartAsync)} before scheduling tasks.");
 
+            context.WriteLine("Fetching data from wiki...");
             WikiModList wikiCompatList = await new ModToolkit().GetWikiCompatibilityListAsync();
+
+            context.WriteLine("Saving data...");
             BackgroundService.WikiCache.SaveWikiData(wikiCompatList.StableVersion, wikiCompatList.BetaVersion, wikiCompatList.Mods);
+
+            context.WriteLine("Done!");
         }
 
         /// <summary>Update the cached CurseForge mod dump.</summary>
-        [AutomaticRetry(Attempts = 3, DelaysInSeconds = new[] { 30, 60, 120 })]
-        public static async Task UpdateCurseForgeExportAsync()
+        /// <param name="context">Information about the context in which the job is performed. This is injected automatically by Hangfire.</param>
+        [AutomaticRetry(Attempts = 3, DelaysInSeconds = [30, 60, 120])]
+        public static async Task UpdateCurseForgeExportAsync(PerformContext? context)
         {
-            if (!BackgroundService.IsStarted)
-                throw new InvalidOperationException($"Must call {nameof(BackgroundService.StartAsync)} before scheduling tasks.");
-
-            var cache = BackgroundService.CurseForgeExportCache;
-            var client = BackgroundService.CurseForgeExportApiClient;
-
-            if (await cache.CanRefreshFromAsync(client, BackgroundService.ExportStaleAge))
-            {
-                CurseForgeFullExport data = await client.FetchExportAsync();
-                cache.SetData(data);
-            }
-
-            if (cache.IsStale(BackgroundService.ExportStaleAge))
-                cache.SetData(null); // if the export is too old, fetch fresh mod data from the API instead
+            await UpdateExportAsync(
+                context,
+                BackgroundService.CurseForgeExportCache!,
+                BackgroundService.CurseForgeExportApiClient!,
+                client => client.FetchLastModifiedDateAsync(),
+                async (cache, client) => cache.SetData(await client.FetchExportAsync())
+            );
         }
 
         /// <summary>Update the cached Nexus mod dump.</summary>
-        [AutomaticRetry(Attempts = 3, DelaysInSeconds = new[] { 30, 60, 120 })]
-        public static async Task UpdateNexusExportAsync()
+        /// <param name="context">Information about the context in which the job is performed. This is injected automatically by Hangfire.</param>
+        [AutomaticRetry(Attempts = 3, DelaysInSeconds = [30, 60, 120])]
+        public static async Task UpdateNexusExportAsync(PerformContext? context)
         {
-            if (!BackgroundService.IsStarted)
-                throw new InvalidOperationException($"Must call {nameof(BackgroundService.StartAsync)} before scheduling tasks.");
-
-            var cache = BackgroundService.NexusExportCache;
-            var client = BackgroundService.NexusExportApiClient;
-
-            if (await cache.CanRefreshFromAsync(client, BackgroundService.ExportStaleAge))
-            {
-                NexusFullExport data = await client.FetchExportAsync();
-                cache.SetData(data);
-            }
-
-            if (cache.IsStale(BackgroundService.ExportStaleAge))
-                cache.SetData(null); // if the export is too old, fetch fresh mod data from the site/API instead
+            await UpdateExportAsync(
+                context,
+                BackgroundService.NexusExportCache!,
+                BackgroundService.NexusExportApiClient!,
+                client => client.FetchLastModifiedDateAsync(),
+                async (cache, client) => cache.SetData(await client.FetchExportAsync())
+            );
         }
 
         /// <summary>Remove mods which haven't been requested in over 48 hours.</summary>
@@ -209,10 +205,6 @@ public static Task RemoveStaleModsAsync()
             // remove mods in mod cache
             BackgroundService.ModCache.RemoveStaleMods(TimeSpan.FromHours(48));
 
-            // remove stale export cache
-            if (BackgroundService.NexusExportCache.IsStale(BackgroundService.ExportStaleAge))
-                BackgroundService.NexusExportCache.SetData(null);
-
             return Task.CompletedTask;
         }
 
@@ -229,5 +221,74 @@ private void TryInit()
 
             BackgroundService.JobServer = new BackgroundJobServer();
         }
+
+        /// <summary>Update the cached mods export for a site.</summary>
+        /// <typeparam name="TCacheRepository">The export cache repository type.</typeparam>
+        /// <typeparam name="TExportApiClient">The export API client.</typeparam>
+        /// <param name="context">Information about the context in which the job is performed. This is injected automatically by Hangfire.</param>
+        /// <param name="cache">The export cache to update.</param>
+        /// <param name="client">The export API with which to fetch data from the remote API.</param>
+        /// <param name="fetchLastModifiedDateAsync">Fetch the date when the export on the server was last modified.</param>
+        /// <param name="fetchDataAsync">Fetch the latest export file from the Nexus Mods export API.</param>
+        /// <exception cref="InvalidOperationException">The <see cref="StartAsync"/> method wasn't called before running this task.</exception>
+        private static async Task UpdateExportAsync<TCacheRepository, TExportApiClient>(PerformContext? context, TCacheRepository cache, TExportApiClient client, Func<TExportApiClient, Task<DateTimeOffset>> fetchLastModifiedDateAsync, Func<TCacheRepository, TExportApiClient, Task> fetchDataAsync)
+            where TCacheRepository : IExportCacheRepository
+        {
+            if (!BackgroundService.IsStarted)
+                throw new InvalidOperationException($"Must call {nameof(BackgroundService.StartAsync)} before scheduling tasks.");
+
+            // refresh data
+            context.WriteLine("Checking if we can refresh the data...");
+            if (BackgroundService.CanRefreshFromExportApi(await fetchLastModifiedDateAsync(client), cache, out string? failReason))
+            {
+                context.WriteLine("Fetching data...");
+                await fetchDataAsync(cache, client);
+                context.WriteLine($"Cache updated. The data was last modified {BackgroundService.FormatDateModified(cache.GetLastModified())}.");
+            }
+            else
+                context.WriteLine($"Skipped data fetch: {failReason}.");
+
+            // clear if stale
+            if (cache.IsStale(BackgroundService.ExportStaleAge))
+            {
+                context.WriteLine("The cached data is stale, clearing cache...");
+                cache.Clear();
+            }
+
+            context.WriteLine("Done!");
+        }
+
+        /// <summary>Get whether newer non-stale data can be fetched from the server.</summary>
+        /// <param name="serverModified">The last-modified data from the remote API.</param>
+        /// <param name="repository">The repository to update.</param>
+        /// <param name="failReason">The reason to log if we can't fetch data.</param>
+        private static bool CanRefreshFromExportApi(DateTimeOffset serverModified, IExportCacheRepository repository, [NotNullWhen(false)] out string? failReason)
+        {
+            if (repository.IsStale(serverModified, BackgroundService.ExportStaleAge))
+            {
+                failReason = $"server was last modified {BackgroundService.FormatDateModified(serverModified)}, which exceeds the {BackgroundService.ExportStaleAge}-minute-stale limit";
+                return false;
+            }
+
+            if (repository.IsLoaded())
+            {
+                DateTimeOffset localModified = repository.GetLastModified();
+                if (localModified >= serverModified)
+                {
+                    failReason = $"server was last modified {BackgroundService.FormatDateModified(serverModified)}, which {(serverModified == localModified ? "matches our cached data" : $"is older than our cached {BackgroundService.FormatDateModified(localModified)}")}";
+                    return false;
+                }
+            }
+
+            failReason = null;
+            return true;
+        }
+
+        /// <summary>Format a 'date modified' value for the task logs.</summary>
+        /// <param name="date">The date to log.</param>
+        private static string FormatDateModified(DateTimeOffset date)
+        {
+            return $"{date:O} (age: {(DateTimeOffset.UtcNow - date).Humanize()})";
+        }
     }
 }

src/SMAPI.Web/Framework/Caching/BaseCacheRepository.cs

@@ -3,14 +3,12 @@
 namespace StardewModdingAPI.Web.Framework.Caching
 {
     /// <summary>The base logic for a cache repository.</summary>
-    internal abstract class BaseCacheRepository
+    internal abstract class BaseCacheRepository : ICacheRepository
     {
         /*********
         ** Public methods
         *********/
-        /// <summary>Whether cached data is stale.</summary>
-        /// <param name="lastUpdated">The date when the data was updated.</param>
-        /// <param name="staleMinutes">The age in minutes before data is considered stale.</param>
+        /// <inheritdoc />
         public bool IsStale(DateTimeOffset lastUpdated, int staleMinutes)
         {
             return lastUpdated < DateTimeOffset.UtcNow.AddMinutes(-staleMinutes);

src/SMAPI.Web/Framework/Caching/BaseExportCacheRepository.cs

@@ -0,0 +1,26 @@
+using System;
+
+namespace StardewModdingAPI.Web.Framework.Caching
+{
+    /// <summary>The base logic for an export cache repository.</summary>
+    internal abstract class BaseExportCacheRepository : BaseCacheRepository, IExportCacheRepository
+    {
+        /*********
+         ** Public methods
+         *********/
+        /// <inheritdoc />
+        public abstract bool IsLoaded();
+
+        /// <inheritdoc />
+        public abstract DateTimeOffset GetLastModified();
+
+        /// <inheritdoc />
+        public bool IsStale(int staleMinutes)
+        {
+            return this.IsStale(this.GetLastModified(), staleMinutes);
+        }
+
+        /// <inheritdoc />
+        public abstract void Clear();
+    }
+}

src/SMAPI.Web/Framework/Caching/CurseForgeExport/CurseForgeExportCacheMemoryRepository.cs

@@ -1,13 +1,11 @@
 using System;
 using System.Diagnostics.CodeAnalysis;
-using System.Threading.Tasks;
-using StardewModdingAPI.Toolkit.Framework.Clients.CurseForgeExport;
 using StardewModdingAPI.Toolkit.Framework.Clients.CurseForgeExport.ResponseModels;
 
 namespace StardewModdingAPI.Web.Framework.Caching.CurseForgeExport
 {
     /// <summary>Manages cached mod data from the CurseForge export API in-memory.</summary>
-    internal class CurseForgeExportCacheMemoryRepository : BaseCacheRepository, ICurseForgeExportCacheRepository
+    internal class CurseForgeExportCacheMemoryRepository : BaseExportCacheRepository, ICurseForgeExportCacheRepository
     {
         /*********
         ** Fields
@@ -21,22 +19,21 @@ internal class CurseForgeExportCacheMemoryRepository : BaseCacheRepository, ICur
         *********/
         /// <inheritdoc />
         [MemberNotNullWhen(true, nameof(CurseForgeExportCacheMemoryRepository.Data))]
-        public bool IsLoaded()
+        public override bool IsLoaded()
         {
             return this.Data?.Mods.Count > 0;
         }
 
         /// <inheritdoc />
-        public async Task<bool> CanRefreshFromAsync(ICurseForgeExportApiClient client, int staleMinutes)
+        public override DateTimeOffset GetLastModified()
         {
-            DateTimeOffset serverLastModified = await client.FetchLastModifiedDateAsync();
+            return this.Data?.LastModified ?? DateTimeOffset.MinValue;
+        }
 
-            return
-                !this.IsStale(serverLastModified, staleMinutes)
-                && (
-                    !this.IsLoaded()
-                    || this.Data.LastModified < serverLastModified
-                );
+        /// <inheritdoc />
+        public override void Clear()
+        {
+            this.SetData(null);
         }
 
         /// <inheritdoc />
@@ -58,13 +55,5 @@ public void SetData(CurseForgeFullExport? export)
         {
             this.Data = export;
         }
-
-        /// <inheritdoc />
-        public bool IsStale(int staleMinutes)
-        {
-            return
-                this.Data is null
-                || this.IsStale(this.Data.LastModified, staleMinutes);
-        }
     }
 }

src/SMAPI.Web/Framework/Caching/CurseForgeExport/ICurseForgeExportCacheRepository.cs

@@ -1,24 +1,14 @@
 using System.Diagnostics.CodeAnalysis;
-using System.Threading.Tasks;
-using StardewModdingAPI.Toolkit.Framework.Clients.CurseForgeExport;
 using StardewModdingAPI.Toolkit.Framework.Clients.CurseForgeExport.ResponseModels;
 
 namespace StardewModdingAPI.Web.Framework.Caching.CurseForgeExport
 {
     /// <summary>Manages cached mod data from the CurseForge export API.</summary>
-    internal interface ICurseForgeExportCacheRepository : ICacheRepository
+    internal interface ICurseForgeExportCacheRepository : IExportCacheRepository
     {
         /*********
         ** Methods
         *********/
-        /// <summary>Get whether the export data is currently available.</summary>
-        bool IsLoaded();
-
-        /// <summary>Get whether newer non-stale data can be fetched from the server.</summary>
-        /// <param name="client">The CurseForge API client.</param>
-        /// <param name="staleMinutes">The age in minutes before data is considered stale.</param>
-        Task<bool> CanRefreshFromAsync(ICurseForgeExportApiClient client, int staleMinutes);
-
         /// <summary>Get the cached data for a mod, if it exists in the export.</summary>
         /// <param name="id">The CurseForge mod ID.</param>
         /// <param name="mod">The fetched metadata.</param>
@@ -27,9 +17,5 @@ internal interface ICurseForgeExportCacheRepository : ICacheRepository
         /// <summary>Set the cached data to use.</summary>
         /// <param name="export">The export received from the CurseForge Mods API, or <c>null</c> to remove it.</param>
         void SetData(CurseForgeFullExport? export);
-
-        /// <summary>Get whether the cached data is stale.</summary>
-        /// <param name="staleMinutes">The age in minutes before data is considered stale.</param>
-        bool IsStale(int staleMinutes);
     }
 }

src/SMAPI.Web/Framework/Caching/IExportCacheRepository.cs

@@ -0,0 +1,24 @@
+using System;
+
+namespace StardewModdingAPI.Web.Framework.Caching
+{
+    /// <summary>Encapsulates logic for accessing data in a cached mod export from a remote API.</summary>
+    internal interface IExportCacheRepository : ICacheRepository
+    {
+        /*********
+        ** Methods
+        *********/
+        /// <summary>Get whether the export data is currently available.</summary>
+        bool IsLoaded();
+
+        /// <summary>Get the date when the cached data was last modified.</summary>
+        DateTimeOffset GetLastModified();
+
+        /// <summary>Get whether the cached data is stale.</summary>
+        /// <param name="staleMinutes">The age in minutes before data is considered stale.</param>
+        bool IsStale(int staleMinutes);
+
+        /// <summary>Clear all data in the cache.</summary>
+        void Clear();
+    }
+}