Items with configured expiration stored in IDistributedCache (using RedisCache) end up non-expiring in Redis

[CaringDev]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

When I store items using e.g.

// ...
services.AddStackExchangeRedisCache(_ => { })
// ...
IDistributedCache cache = // from DI
cache.SetAsync(
    "key",
    "Test"u8.ToArray(),
    new() { AbsoluteExpirationRelativeToNow = TimeSpan.FromMinutes(10) })

the key ends up as non-expiring in Redis.

Expected Behavior

Keys should be set to expire in Redis if configured accordingly.

Steps To Reproduce

Unfortunately I can only reproduce this in a very specific environment:

• client with Microsoft.Extensions.Caching.StackExchangeRedis @ 9.0.0 (SE.Redis @ 2.7.27 or 2.8.22) on Suse CloudFoundry
• Bitnami Redis v7.0.4 (yes, outdated)

Connecting to the same cluster from my development environment (Ubuntu) or downgrading Microsoft.Extensions.Caching.StackExchangeRedis @ 8.0.11 does not trigger the bug (regardless of the SE.Redis version).

Exceptions (if any)

No response

.NET Version

SDK 9.0.100, targeting net9.0

[mgravell]

I'm not using Bitnami yet (I'll need to investigate), but: initial attempts to reproduce a failure here at either the raw SE.Redis layer or the M.E.C.SER layer have been unsuccessful; so that we investigate and fix (as necessary) the correct problem, can you perhaps eyeball my test below, and/or see whether something similar to this can reproduce the problem in your setup?

At the API layer: the code is not wrong as far as I can see, in that SE.Redis is meant to allow this form of pipelining, and does indeed seem to be. Right now, I'm wondering whether, for example, it is the case that Bitnami itself doesn't respect pipelining.

using Microsoft.Extensions.Caching.Distributed;
using Microsoft.Extensions.DependencyInjection;
using StackExchange.Redis;
using System.Text;

var services = new ServiceCollection();
using var muxer = await ConnectionMultiplexer.ConnectAsync("127.0.0.1:6379");
var db = muxer.GetDatabase();
services.AddStackExchangeRedisCache(options =>
{
    options.ConnectionMultiplexerFactory = () => Task.FromResult<IConnectionMultiplexer>(muxer);
});
var options = new DistributedCacheEntryOptions { AbsoluteExpirationRelativeToNow = TimeSpan.FromMinutes(2) };
using var provider = services.BuildServiceProvider();
var cache = provider.GetRequiredService<IDistributedCache>();
var testkey = Guid.NewGuid().ToString();
cache.SetString(testkey, DateTime.UtcNow.ToString(), options);
var rand = new Random();
// prove setup correctly
Console.WriteLine($"cache: {cache.GetType().Name} ({cache.GetString(testkey)})");


int WORKER_COUNT = 20, PASSES = 1000, OPS_PER_PASS = 200;
var workers = Enumerable.Range(0, WORKER_COUNT).Select(StartWorker).ToArray();

var start = DateTime.UtcNow;
await Task.WhenAll(workers);
var end = DateTime.UtcNow;
Console.WriteLine($"Total ops: {WORKER_COUNT * PASSES * OPS_PER_PASS * 2}, time: {end - start}");
async Task StartWorker(int id)
{
    var skeys = new string[OPS_PER_PASS];
    for (int i = 0; i < skeys.Length; i++)
    {
        skeys[i] = Guid.NewGuid().ToString();
    }
    byte[] value = new byte[128];
    rand.NextBytes(value);
    var rkeys = Array.ConvertAll(skeys, key => (RedisKey)key);
    var ttls = new Task<TimeSpan?>[skeys.Length];

    async Task<int> CheckMissingExpirationsAsync()
    {
        for (int i = 0; i < ttls.Length; i++)
        {
            ttls[i] = db.KeyTimeToLiveAsync(rkeys[i]);
        }
        await Task.WhenAll(ttls);
        int failures = 0;
        for (int i = 0; i < ttls.Length; i++)
        {
            if ((await ttls[i]) is null) failures++;
        }
        return failures;
    }

    var counts = new Task<long>[OPS_PER_PASS];
    int totalFailures = 0;
    for (int pass = 0; pass < PASSES; pass++)
    {
        // reset and set via async
        await db.KeyDeleteAsync(rkeys);
        for (int i = 0; i < skeys.Length; i++)
        {
            await cache.SetAsync(skeys[i], value, options);
        }
        var failures = await CheckMissingExpirationsAsync();
        if (failures != 0)
        {
            Console.WriteLine($"Worker {id}, async, failures: {failures}");
            totalFailures += failures;
        }

        // reset and set via sync
        await db.KeyDeleteAsync(rkeys);
        for (int i = 0; i < skeys.Length; i++)
        {
            cache.Set(skeys[i], value, options);
        }
        failures = await CheckMissingExpirationsAsync();
        if (failures != 0)
        {
            Console.WriteLine($"Worker {id}, sync, failures: {failures}");
            totalFailures += failures;
        }
    }
    await db.KeyDeleteAsync(rkeys);
    Console.WriteLine($"Worker {id} complete, {PASSES} passes of {OPS_PER_PASS} async and {OPS_PER_PASS} sync, failures: {totalFailures}");
}

My output locally:

cache: RedisCacheImpl (02/12/2024 11:07:13)
Worker 5 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 11 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 12 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 7 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 13 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 15 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 0 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 16 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 19 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 2 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 9 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 6 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 1 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 8 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 3 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 17 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 4 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 18 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 10 complete, 1000 passes of 200 async and 200 sync, failures: 0
Worker 14 complete, 1000 passes of 200 async and 200 sync, failures: 0
Total ops: 8000000, time: 00:01:06.5413181

[mgravell]

Current status here is: I'm struggling to find a repro on any standard redis setup, and have investigated aspnetcore and se.redis internals; I'm very concerned about the possibility of a problem here, and I'm not saying there isn't one - but I don't want to leap into kneejerk fixes until we have a confirmed repro.

[mgravell]

I have zero knowledge of cloudfoundry; if there is anything you can do to help guide me producing this in that environment? my concern is that if I hack at it like so-many-monkeys, I end up with either a: something that doesn't work at all, or b: something that doesn't represent the failing scenario.

[CaringDev]

@mgravell thank you for the continued effort. I tried to run your test suite with M.E.C.SER @ 9.0.0, SE.R @ 2.8.22 on the dev env and got (first line logged / redacted by me):

Connection string: redis-1:443,redis-2:443,redis-3:443,allowAdmin=True,password=<REDACTED>,ssl=True,abortConnect=False

cache: RedisCacheImpl (12/05/2024 17:07:26)
Unhandled exception. StackExchange.Redis.RedisCommandException: Multi-key operations must involve a single slot; keys can use 'hash tags' to help this, i.e. '{/users/12345}/account' and '{/users/12345}/contacts' will always be in the same slot
   at StackExchange.Redis.ConnectionMultiplexer.PrepareToPushMessageToBridge[T](Message message, ResultProcessor`1 processor, IResultBox`1 resultBox, ServerEndPoint& server) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 1969
   at StackExchange.Redis.ConnectionMultiplexer.TryPushMessageToBridgeAsync[T](Message message, ResultProcessor`1 processor, IResultBox`1 resultBox, ServerEndPoint& server) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2007
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server) in /_/src/StackExchange.Redis/ConnectionMultiplexer.cs:line 2188
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server) in /_/src/StackExchange.Redis/RedisBase.cs:line 54
   at StackExchange.Redis.RedisDatabase.KeyDeleteAsync(RedisKey[] keys, CommandFlags flags) in /_/src/StackExchange.Redis/RedisDatabase.cs:line 862
   at Redis.Test.<>c__DisplayClass0_0.<<It>g__StartWorker|1>d.MoveNext() in /home/dev/src/Redis/Test.cs:line 74
--- End of stack trace from previous location ---
   at Redis.Test.It(String connectionString) in /home/dev/src/Redis/Test.cs:line 35
   at Program.<Main>$(String[] args) in /home/dev/src/Redis/Program.cs:line 30
   at Program.<Main>(String[] args)

Process finished with exit code 134.

The exception surfaces from await Task.WhenAll(workers);