Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fix cache lock provider allowing multiple locks to be acquired. #299

Merged
merged 28 commits into from
Mar 20, 2024
Merged

Fix cache lock provider allowing multiple locks to be acquired. #299

merged 28 commits into from
Mar 20, 2024

Conversation

niemyjski
Copy link
Member

@niemyjski niemyjski commented Mar 18, 2024 •
edited
Loading

I noticed that multiple locks could be acquired. I've added more test coverage to try and expose the issue.

Here are some logs that lead me down this path:

44:28.293 T: Got lock released message: test (fvT2ltV31jWIJVbh) - CacheLockProvider
44:28.293 T: Finished calling subscriber action: 65b73751c9eb4a7aa8333f26345b816d - InMemoryMessageBus
44:28.293 T: Done enqueueing message to 1 subscribers for message type Foundatio.Lock.CacheLockReleased, Foundatio - InMemoryMessageBus
44:28.293 T: Added cache key: lock:test Updated=True - InMemoryCacheClient
44:28.293 D: Removing expired cache entry lock:test - InMemoryCacheClient
44:28.293 D: Released lock: test (fvT2ltV31jWIJVbh) - CacheLockProvider
44:28.293 T: Disposed lock (fvT2ltV31jWIJVbh) test - CacheLockProvider
44:28.293 T: Added cache key: lock:test - InMemoryCacheClient
44:28.293 D: Attempting to acquire lock (rMPQS00k5jriIlwD): test - CacheLockProvider
44:28.293 D: Acquired lock (CtO2HC1SbCLWHUWx) test after 0:00:00.1030847 - CacheLockProvider
44:28.293 T: Added cache key: lock:test - InMemoryCacheClient
44:28.293 D: Acquired lock (rMPQS00k5jriIlwD) test after 0:00:00.0000115 - CacheLockProvider
44:28.294 T: Disposing lock (rMPQS00k5jriIlwD) test - CacheLockProvider

After some more fixes to how we update AddAsync

09:53.915 D: Released lock: test (xtpVPARC2g7Rd0Vk) - CacheLockProvider
09:53.915 T: Disposed lock (xtpVPARC2g7Rd0Vk) test - CacheLockProvider
09:53.915 D: Attempting to acquire lock (sBxxiPzf8fHqLLQO): test - CacheLockProvider
09:53.915 T: Added cache key: lock:test Replacing existing expired entry - InMemoryCacheClient
09:53.915 T: Added cache key: lock:test Replacing existing expired entry - InMemoryCacheClient
09:53.915 D: Acquired lock (sBxxiPzf8fHqLLQO) test after 0:00:00.0000345 - CacheLockProvider
09:53.915 D: Acquired lock (cCUuUXR3vPpxuoTd) test after 0:00:00.099548 - CacheLockProvider

Investigated further and saw that it was way more stable, but it failed when maintenance is run

56:59.834 T: DoMaintenance - InMemoryCacheClient
56:59.834 T: Calling subscriber action: 28842d366dca40a694ac2ee823330f5b - InMemoryMessageBus
56:59.834 D: DoMaintenance: Removing expired key lock:test OriginalExpiresAt=uhoLiJcnts5dI5W6 CurrentExpiresAt=uhoLiJcnts5dI5W6 - InMemoryCacheClient
56:59.834 T: Got lock released message: test (uhoLiJcnts5dI5W6) - CacheLockProvider
56:59.834 T: Finished calling subscriber action: 28842d366dca40a694ac2ee823330f5b - InMemoryMessageBus
56:59.834 T: Replacing expired cache key: lock:test Value=O3AMARH32E61q77i ExistingValue=uhoLiJcnts5dI5W6 - InMemoryCacheClient
56:59.834 T: Added cache key: lock:test - InMemoryCacheClient
56:59.834 T: Done enqueueing message to 1 subscribers for message type Foundatio.Lock.CacheLockReleased, Foundatio - InMemoryMessageBus
56:59.834 D: Released lock: test (uhoLiJcnts5dI5W6) - CacheLockProvider
56:59.834 D: Acquired lock (O3AMARH32E61q77i) test after 0:00:00.1024995 - CacheLockProvider
56:59.834 T: Disposed lock (uhoLiJcnts5dI5W6) test - CacheLockProvider
56:59.834 D: Attempting to acquire lock (SHmUz8gq3wswz4cW): test - CacheLockProvider
56:59.834 D: Removing expired cache entry lock:test - InMemoryCacheClient
56:59.834 T: Added cache key: lock:test - InMemoryCacheClient

This led me to rework how maintenance removes expired items.

@niemyjski niemyjski added the bug label Mar 18, 2024
@niemyjski niemyjski self-assigned this Mar 18, 2024
niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Lock/DisposableLock.cs

lock (_lock)
using (await _lock.LockAsync().AnyContext())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Use async locks: https://stackoverflow.com/a/20085260

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Lock/DisposableLockCollection.cs

lock (_lock)
using (await _lock.LockAsync().AnyContext())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Use async locks: https://stackoverflow.com/a/20085260

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Lock/CacheLockProvider.cs
@@ -83,16 +83,15 @@ public async Task<ILock> AcquireAsync(string resource, TimeSpan? timeUntilExpire
bool isTraceLogLevelEnabled = _logger.IsEnabled(LogLevel.Trace);
bool isDebugLogLevelEnabled = _logger.IsEnabled(LogLevel.Debug);
bool shouldWait = !cancellationToken.IsCancellationRequested;
if (isDebugLogLevelEnabled)
_logger.LogDebug("Attempting to acquire lock: {Resource}", resource);
string lockId = GenerateNewLockId();
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

moved this up so all lock messages can have LockId.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
@@ -907,7 +940,7 @@ public void Dispose()
ItemExpired?.Dispose();
}

private class CacheEntry
private record CacheEntry
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Made this into a record, I had a hunch this could be causing an issue with ConcurrentDictionary.TryUpdate() as it uses a comparison value with IEquatable... https://learn.microsoft.com/en-us/dotnet/api/system.collections.concurrent.concurrentdictionary-2.tryupdate?view=net-8.0

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
@@ -884,13 +911,19 @@ private async Task DoMaintenanceAsync()

var utcNow = SystemClock.UtcNow.AddMilliseconds(50);

// Remove expired items and items that are infrequently accessed as they may be updated by add.
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For cache entries that are very recently modified, there might be a high churn rate and the cache value might get overridden via Add/Set. So don't touch it in the background clean up job for a little bit. This made the tests much more stable.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs

(string Key, long LastAccessTicks, long InstanceNumber) oldest = (null, Int64.MaxValue, 0);
foreach (var kvp in _memory)
{
if (kvp.Value.LastAccessTicks < oldest.LastAccessTicks
|| (kvp.Value.LastAccessTicks == oldest.LastAccessTicks && kvp.Value.InstanceNumber < oldest.InstanceNumber))
bool isExpired = kvp.Value.ExpiresAt < SystemClock.UtcNow;
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Optimized this to grab the first expired one (and break), this doesn't take into account the frequency period like maintenance loop.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs

string expiredKey = null;
lock (_lock)
using (await _lock.LockAsync().AnyContext())
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Use async locks: https://stackoverflow.com/a/20085260

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
@@ -825,9 +849,9 @@ public async Task SetExpirationAsync(string key, TimeSpan expiresIn)
}

Interlocked.Increment(ref _writes);
if (_memory.TryGetValue(key, out var value))
if (_memory.TryGetValue(key, out var existingEntry))
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I renamed them as there was like 3 or 4 different names for existing cache entries and it was driving me crazy while debugging.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
if (cacheEntry.ExpiresAt < SystemClock.UtcNow)
if (existingEntry.ExpiresAt < SystemClock.UtcNow)
{
Interlocked.Increment(ref _misses);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a miss, not a hit.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
if (addOnly)
{
if (!_memory.TryAdd(key, entry))
_memory.AddOrUpdate(key, entry, (_, existingEntry) =>
Copy link
Member Author

@niemyjski niemyjski Mar 19, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Converted this to an AddOrUpdate as it can better handle concurrent attempts. Learned a few things from https://medium.com/gft-engineering/correctly-using-concurrentdictionarys-addorupdate-method-94b7b41719d6

Add call back can be hit multiple times, so just pass it in and update in the update value callback to reset wasUpdated.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
return entry;
}
if (isTraceLogLevelEnabled)
_logger.LogTrace("Replacing expired cache key: {Key}", key);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Added logging to detect this, which was very helpful

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
Comment on lines +199 to +204
if (_memory.TryGetValue(key, out var existingEntry) && existingEntry.ExpiresAt < SystemClock.UtcNow)
{
if (_memory.TryRemove(key, out var removedEntry))
{
if (removedEntry.ExpiresAt >= SystemClock.UtcNow)
throw new Exception("Removed item was not expired");
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This was actively removing expired items because this method wouldn't get inlined / executed synchronously all the time when this method was called. So concurrent Add/Set calls could update the expired value causing issues. I think this could be better reworked to have a single point for all removes.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
{
RemoveExpiredKey(key);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just let maintenance remove the item to cut down on the number concurrent updates.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
if (value.ExpiresAt >= SystemClock.UtcNow)
return Task.FromResult<TimeSpan?>(value.ExpiresAt.Subtract(SystemClock.UtcNow));

RemoveExpiredKey(key);
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just let maintenance remove the item to cut down on the number concurrent updates.

niemyjski
niemyjski commented Mar 19, 2024
View reviewed changes
src/Foundatio/Caching/InMemoryCacheClient.cs
@@ -189,26 +195,33 @@ public Task<int> RemoveByPrefixAsync(string prefix)

internal void RemoveExpiredKey(string key, bool sendNotification = true)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I tried to only call this if we call a method with a past expiration and we return immediately. Otherwise just let maintenance remove the item to cut down on the number concurrent updates.

@niemyjski
Copy link
Member Author

niemyjski commented Mar 20, 2024 •
edited
Loading

minimum-changes.patch

@ejsmith Here is the minimum changes required to fix this.

image image image image

niemyjski added 17 commits March 20, 2024 11:55
@niemyjski
Fixed deprecations and other warnings
88a693f
@niemyjski
Fixed flakey test
d5303a2
@niemyjski
Updated minver
50423c4
@niemyjski
Cleanup test options
fb90e45
@niemyjski
Move scheduling maintenance before dequeued, otherwise a handler coul…
a8348a2 
…d consume all the time and maintenance to auto abandon never happens.
@niemyjski
Try and schedule maintenance before renewing lock
8d8efd9
@niemyjski
Change it back.
bc21f1a
@niemyjski
Changed where scheduling maintenance gets called
2350f41
@niemyjski
Fixed a flakey test where expires might be called right at the same t…
12051a3 
…ime as the key was set to expire
@niemyjski
Pass cancellation token through test
3b19ba3
@niemyjski
Removed retry fact from can run jobs with locks
3b44a78
@niemyjski
Added logging to get more info from test run on ci.
19af803
@niemyjski
Add a small buffer to DoMaintenanceAsync to account for system clock …
01c723b 
…drift, see if this fixes flakey ci test.
@niemyjski
Try 15 second buffer for timer drift
0ea6061
@niemyjski
Changed message to be date time which is more readable...
57ac047
@niemyjski
Try and fix a edge case where a timer could be fired earlier than the…
499dbb4 
… next run time and it scheduling was cancelled.
@niemyjski
Removed extra trace logging
40e03ab
@niemyjski niemyjski marked this pull request as ready for review March 20, 2024 21:22
ejsmith
ejsmith approved these changes Mar 20, 2024
View reviewed changes
Copy link
Contributor

@ejsmith ejsmith left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just kind of skimming through and not seeing any issues. Will take your word and the tests passing as proof.

@niemyjski niemyjski merged commit da124a7 into master Mar 20, 2024
3 checks passed
@niemyjski niemyjski deleted the bug/cache-lock-provider-acquiring-mutliple-locks branch March 20, 2024 23:04
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@scharde-encora scharde-encora scharde-encora left review comments

@ejsmith ejsmith ejsmith approved these changes

Assignees

@niemyjski niemyjski

Labels
bug
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
3 participants
@niemyjski @ejsmith @scharde-encora