[BUG] Redis Distributed Lock acquisition timeout error log spam

[jgshowpad]

Describe the bug

During load testing the Redis distributed lock library appears to have some trouble, claiming it times out acquiring the lock, but the request has only been going for 12ms, the cached item (permission tokens) resolve instantly, and the requests go on to complete successfully. I'm wondering if it's some strange race condition in the locking code that causes an error log when the cache item is resolved too quickly.

Here is an example:

I can't see any configuration to set this acquisition timeout either. But I believe that if it was really 12ms then it would be happening a lot more often.

Expected behavior

Don't expect to see this log so often.

Versions

I've encountered this issue on:

• FusionCache version: 2.5.0
• .NET version: 8
• OS version: mcr.microsoft.com/dotnet/sdk:8.0 docker image
• Redis: 7.0.7

[jodydonetti]

Hi @jgshowpad , thanks for reporting.

Can you also share the FusionCache setup? Of course redact any connection string and private stuff.

I'll take a better look at it during the next few days.

Thanks.

[ray831]

Hi @jodydonetti
We are using a different version and configuration from @jgshowpad posted, but we are encountering the same error log as well.
Below are the version and FusionCache configuration we are using.

Version:
NET version: 9
OS version: Linux
Redis: 6.2.3

<PackageReference Include="ZiggyCreatures.FusionCache" Version="2.5.0" />
<PackageReference Include="ZiggyCreatures.FusionCache.Locking.Distributed.Redis" Version="2.5.0" />
<PackageReference Include="ZiggyCreatures.FusionCache.Serialization.SystemTextJson" Version="2.5.0" />

services.AddFusionCache()
    .WithOptions(opt =>
    {
        opt.DisableTagging = true;
    })
    .WithDefaultEntryOptions(opt =>
    {
        opt.Duration = TimeSpan.FromMinutes(1);
        opt.JitterMaxDuration = TimeSpan.FromSeconds(5);
        
        opt.IsFailSafeEnabled = true;
        opt.FailSafeMaxDuration = TimeSpan.FromMinutes(30);
        opt.FailSafeThrottleDuration = TimeSpan.FromSeconds(10);
        
        opt.EagerRefreshThreshold = 0.8f;
        
        opt.FactorySoftTimeout = TimeSpan.FromSeconds(1.5);
        opt.AllowTimedOutFactoryBackgroundCompletion = true;
    })
    .WithSystemTextJsonSerializer(new JsonSerializerOptions()
    {
        PropertyNameCaseInsensitive = true,
        PropertyNamingPolicy = JsonNamingPolicy.CamelCase,
        AllowTrailingCommas = true,
        NumberHandling = JsonNumberHandling.AllowReadingFromString,
    })
    .WithDistributedCache(provider => new RedisCache(new RedisCacheOptions
    {
        ConnectionMultiplexerFactory = () => ***,
    }))
    .WithDistributedLocker(provider => new RedisDistributedLocker(new RedisDistributedLockerOptions
    {
        Configuration = ***,
    }))

[jodydonetti]

Hi @jgshowpad

During load testing the Redis distributed lock library appears to have some trouble, claiming it times out acquiring the lock, but the request has only been going for 12ms, the cached item (permission tokens) resolve instantly, and the requests go on to complete successfully. I'm wondering if it's some strange race condition in the locking code that causes an error log when the cache item is resolved too quickly.

Can you shre the options/entry options you are using?
Maybe there's something there that is affecting this part.

I can't see any configuration to set this acquisition timeout either.

There is LockTimeout (general) and DistributedLockTimeout, but you probably id not set them I suppose.

But I believe that if it was really 12ms then it would be happening a lot more often.

Yeah that's strange.

Is there an exception detail you can share?

Thanks!

[jodydonetti]

Hi @ray831

We are using a different version and configuration from @jgshowpad posted, but we are encountering the same error log as well. Below are the version and FusionCache configuration we are using.

I see you are using Eager Refresh: that is of course fully supported, but I'm thinking it may be related to that.
Let me check locally, will update you later.

Is there an exception detail you can share?

Thanks!

[jgshowpad]

Sorry for delayed reply -

Can you also share the FusionCache setup? Of course redact any connection string and private stuff.

var cacheSerializerOptions = new JsonSerializerOptions
{
    Converters =
    {
        new ClaimJsonConverter(),
    }
};

var multiplexerFactory = () => Task.FromResult<IConnectionMultiplexer>(multiplexerManager.GetConnectionMultiplexer());

services
    .AddFusionCacheSystemTextJsonSerializer(cacheSerializerOptions)
    .AddStackExchangeRedisCache(o => o.ConnectionMultiplexerFactory = multiplexerFactory)
    .AddFusionCacheStackExchangeRedisBackplane(o => o.ConnectionMultiplexerFactory = multiplexerFactory)
    .AddSingleton<IFusionCacheDistributedLocker>(new RedisDistributedLocker(new RedisDistributedLockerOptions { ConnectionMultiplexerFactory = multiplexerFactory }))
;

services
    .AddFusionCache()
    .WithCacheKeyPrefix(instanceKey)
    .WithRegisteredSerializer()
    .WithRegisteredDistributedCache()
    .WithRegisteredBackplane()
    .WithRegisteredDistributedLocker()
;

...

new FusionCacheEntryOptions()
    .SetDuration(1.Minutes())
    .SetFailSafe(false)
    .SetEagerRefresh(0.5f)
    .SetFactoryTimeouts()
    .SetSkipDistributedLocker(false)
;

Looks like both myself and @ray831 are using eager refresh.

Is there an exception detail you can share?

System.TimeoutException: Timeout exceeded when trying to acquire the lock
   at Medallion.Threading.Internal.DistributedLockHelpers.ThrowTimeoutIfNull[T](ValueTask`1 task, String object) in /_/src/DistributedLock.Core/Internal/DistributedLockHelpers.cs:line 139
   at Medallion.Threading.Internal.Helpers.Convert[TDerived,TBase](ValueTask`1 task, ValueTaskConversion _)
   at ZiggyCreatures.Caching.Fusion.Locking.Distributed.Redis.RedisDistributedLocker.AcquireLockAsync(String cacheName, String cacheInstanceId, String operationId, String key, String lockName, TimeSpan timeout, ILogger logger, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache.Locking.Distributed.Redis/RedisDistributedLocker_Async.cs:line 16
   at ZiggyCreatures.Caching.Fusion.Internals.DistributedLocker.DistributedLockerAccessor.AcquireLockAsync(String operationId, String key, TimeSpan timeout, CancellationToken token) in /_/src/ZiggyCreatures.FusionCache/Internals/DistributeLocker/DistributedLockerAccessor_Async.cs:line 14

[jgshowpad]

I threw Claude Opus 4.5 at the issue and it had this opinion:

---

Bug Analysis

Root Cause:

The bug is in the RedisDistributedLocker implementation. Looking at the code:

public async ValueTask<object?> AcquireLockAsync(string cacheName, string cacheInstanceId, string operationId, string key, string lockName, TimeSpan timeout, ILogger? logger, CancellationToken token)
{
    await EnsureConnectionAsync(token).ConfigureAwait(false);

    if (_provider is null)
        return null;

    return await _provider.AcquireLockAsync(lockName, timeout, token).ConfigureAwait(false);
}

The problem is that the RedisDistributedLocker is calling _provider.AcquireLockAsync() from the Medallion.Threading library. According to the Medallion.Threading documentation:

• AcquireLockAsync - blocks until the lock is available, and throws a TimeoutException if the timeout expires
• TryAcquireLockAsync - returns null if the lock could not be acquired within the timeout (no exception)

The IFusionCacheDistributedLocker interface expects the AcquireLockAsync method to return null when the lock cannot be acquired (similar to TryAcquire semantics), as evidenced by:

1. The MemoryDistributedLocker implementation which returns null on timeout:

public async ValueTask<object?> AcquireLockAsync(...)
{
    var semaphore = GetSemaphore(cacheName, cacheInstanceId, key, lockName, logger);
    var acquired = await semaphore.WaitAsync(timeout, token).ConfigureAwait(false);
    return acquired ? semaphore : null;
}

2. The DistributedLockerAccessor which expects null on timeout (not an exception):

if (lockObj is not null)
{
    // LOCK ACQUIRED
}
else
{
    // LOCK TIMEOUT
    if (_logger?.IsEnabled(LogLevel.Trace) ?? false)
        _logger.Log(LogLevel.Trace, "... [DL] DISTRIBUTED LOCK timeout", ...);
}

Why this causes the bug:

When Eager Refresh is enabled, FusionCache calls AcquireDistributedLockAsync with TimeSpan.Zero timeout to try to acquire the lock without waiting:

// TRY TO GET THE DISTRIBUTED LOCK WITHOUT WAITING, SO THAT ONLY THE FIRST NODE WILL ACTUALLY REFRESH THE ENTRY
distributedLockObj = await AcquireDistributedLockAsync(operationId, key, TimeSpan.Zero, options, token).ConfigureAwait(false);

With TimeSpan.Zero, the Medallion library's AcquireLockAsync immediately throws a TimeoutException if the lock is not immediately available. This exception is caught by DistributedLockerAccessor and logged at LogLevel.Error, causing the error log spam.

The Fix:

The RedisDistributedLocker should use TryAcquireLockAsync instead of AcquireLockAsync from the Medallion.Threading library. The TryAcquireLockAsync method returns null when the lock cannot be acquired within the timeout, which matches the expected behavior of the IFusionCacheDistributedLocker interface.

[timothyeckert]

I would just like to echo that we are also seeing this issue with free and open threads, just doesn't seem to aquire a lock.