From c4a19100f27c0470992d03b3c673bf1106690a1e Mon Sep 17 00:00:00 2001
From: Blake Niemyjski <bniemyjski@gmail.com>
Date: Tue, 26 Mar 2024 20:15:14 -0500
Subject: [PATCH] Improved log messages and added renew time checks

---
 src/Foundatio/Caching/InMemoryCacheClient.cs  |  3 ++-
 src/Foundatio/Lock/ILockProvider.cs           | 23 ++++++++++++-------
 .../Locks/InMemoryLockTests.cs                |  2 +-
 3 files changed, 18 insertions(+), 10 deletions(-)

diff --git a/src/Foundatio/Caching/InMemoryCacheClient.cs b/src/Foundatio/Caching/InMemoryCacheClient.cs
index 2d2b0fa2..d6c00336 100644
--- a/src/Foundatio/Caching/InMemoryCacheClient.cs
+++ b/src/Foundatio/Caching/InMemoryCacheClient.cs
@@ -622,13 +622,14 @@ private async Task<bool> SetInternalAsync(string key, CacheEntry entry, bool add
         {
             _memory.AddOrUpdate(key, entry, (existingKey, existingEntry) =>
             {
+                // NOTE: This update factory method will run multiple times if the key is already in the cache, especially during lock contention.
                 wasUpdated = false;
 
                 // check to see if existing entry is expired
                 if (existingEntry.ExpiresAt < SystemClock.UtcNow)
                 {
                     if (isTraceLogLevelEnabled)
-                        _logger.LogTrace("Replacing expired cache key: {Key}", existingKey);
+                        _logger.LogTrace("Attempting to replacing expired cache key: {Key}", existingKey);
 
                     wasUpdated = true;
                     return entry;
diff --git a/src/Foundatio/Lock/ILockProvider.cs b/src/Foundatio/Lock/ILockProvider.cs
index bacfd1f6..ff2928a3 100644
--- a/src/Foundatio/Lock/ILockProvider.cs
+++ b/src/Foundatio/Lock/ILockProvider.cs
@@ -1,4 +1,4 @@
-using System;
+using System;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Linq;
@@ -144,15 +144,16 @@ public static async Task<ILock> AcquireAsync(this ILockProvider provider, IEnume
             return new EmptyLock();
 
         var logger = provider.GetLogger();
-        bool isTraceLogLevelEnabled = logger.IsEnabled(LogLevel.Trace);
-        if (isTraceLogLevelEnabled)
-            logger.LogTrace("Acquiring {LockCount} locks {Resource}", resourceList.Length, resourceList);
 
         // If renew time is greater than 0, then cut the time in half with max time of 1 minute.
         var renewTime = timeUntilExpires.GetValueOrDefault(TimeSpan.FromMinutes(1));
         if (renewTime > TimeSpan.Zero)
             renewTime = TimeSpan.FromTicks(renewTime.Ticks / 2) > TimeSpan.FromMinutes(1) ? TimeSpan.FromMinutes(1) : TimeSpan.FromTicks(renewTime.Ticks / 2);
 
+        bool isTraceLogLevelEnabled = logger.IsEnabled(LogLevel.Trace);
+        if (isTraceLogLevelEnabled)
+            logger.LogTrace("Acquiring {LockCount} locks {Resource} RenewTime={RenewTime:g}", resourceList.Length, resourceList, renewTime);
+
         var sw = Stopwatch.StartNew();
 
         var acquiredLocks = new List<(ILock Lock, DateTime LastRenewed)>(resourceList.Length);
@@ -165,12 +166,18 @@ public static async Task<ILock> AcquireAsync(this ILockProvider provider, IEnume
             }
 
             // Renew any acquired locks so they stay alive until we have all locks
-            if (acquiredLocks.Count > 0)
+            if (acquiredLocks.Count > 0 && renewTime > TimeSpan.Zero)
             {
                 var utcNow = SystemClock.UtcNow;
-                var locksToRenew = acquiredLocks.Where(al => al.LastRenewed < utcNow.Subtract(renewTime)).ToList();
-                await Task.WhenAll(locksToRenew.Select(al => al.Lock.RenewAsync(timeUntilExpires))).AnyContext();
-                locksToRenew.ForEach(al => al.LastRenewed = utcNow);
+                var locksToRenew = acquiredLocks.Where(al => al.LastRenewed < utcNow.Subtract(renewTime)).ToArray();
+                if (locksToRenew.Length > 0)
+                {
+                    await Task.WhenAll(locksToRenew.Select(al => al.Lock.RenewAsync(timeUntilExpires))).AnyContext();
+                    locksToRenew.ForEach(al => al.LastRenewed = utcNow);
+
+                    if (isTraceLogLevelEnabled)
+                        logger.LogTrace("Renewed {LockCount} locks {Resource} RenewTime={RenewTime:g}", locksToRenew.Length, locksToRenew.Select(al => al.Lock.Resource), renewTime);
+                }
             }
 
             acquiredLocks.Add((l, SystemClock.UtcNow));
diff --git a/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs b/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs
index db3cd774..f5535f44 100644
--- a/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs
+++ b/tests/Foundatio.Tests/Locks/InMemoryLockTests.cs
@@ -1,4 +1,4 @@
-using System;
+using System;
 using System.Threading.Tasks;
 using Foundatio.Caching;
 using Foundatio.Lock;