Skip to content

Unobserved RedisTimeoutException when a handle is disposed while its renewal EVAL is in flight #287

Description

@xirius

Package: DistributedLock.Redis 1.1.1 (with DistributedLock.Core 1.0.8)
Built from: 338025c469c13ba6b4d569344956752707b35a8c (per the package's own repository metadata)
Also tested with: StackExchange.Redis 2.8.37, .NET 10, Linux

Summary

If a RedisDistributedLock handle is disposed while its auto-extension (renewal) EVAL is still in flight, and the Redis server does not answer that EVAL before StackExchange.Redis' asyncTimeout elapses, the extend task faults with RedisTimeoutException and nobody ever observes it. The exception surfaces on the finalizer thread via TaskScheduler.UnobservedTaskException.

This is benign on modern .NET by default, but it is fatal for any host that sets <ThrowUnobservedTaskExceptions>true</ThrowUnobservedTaskExceptions>, and it pollutes UnobservedTaskException telemetry for everyone else. It shows up in production as an unexplained background fault every time Redis has a latency spike longer than the client
timeout.

Repro

Deterministic - 3 out of 3 rounds, every run. Needs a dedicated Redis on localhost:6379, because CLIENT PAUSE is server-global.

repro.csproj:

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <OutputType>Exe</OutputType>
    <TargetFramework>net10.0</TargetFramework>
    <Nullable>enable</Nullable>
    <ImplicitUsings>disable</ImplicitUsings>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="DistributedLock.Redis" Version="1.1.1" />
    <PackageReference Include="StackExchange.Redis" Version="2.8.37" />
  </ItemGroup>
</Project>

Program.cs:

using System;
using System.Threading;
using System.Threading.Tasks;
using Medallion.Threading.Redis;
using StackExchange.Redis;

public static class Program
{
    private static int _unobserved;

    public static async Task Main()
    {
        TaskScheduler.UnobservedTaskException += (_, eventArgs) =>
        {
            Interlocked.Increment(ref _unobserved);
            eventArgs.SetObserved();
            Console.WriteLine("  !! UnobservedTaskException:");
            Console.WriteLine(eventArgs.Exception.ToString());
        };

        var configuration = ConfigurationOptions.Parse("localhost:6379");
        configuration.AllowAdmin = true;      // required for CLIENT PAUSE
        configuration.AbortOnConnectFail = false;

        await using var multiplexer = await ConnectionMultiplexer.ConnectAsync(configuration);
        var database = multiplexer.GetDatabase();

        for (var round = 1; round <= 3; round++)
        {
            Console.WriteLine($"--- round {round} ---");

            // Expiry 30s => a renewal is scheduled at expiry/3 ~= 10s.
            var theLock = new RedisDistributedLock(
                $"repro-lock-{round}",
                database,
                options => options.Expiry(TimeSpan.FromSeconds(30)));

            var handle = await theLock.AcquireAsync(TimeSpan.FromSeconds(5));
            Console.WriteLine("  t=0s  acquired (renewal due at ~10s)");

            // Stall the server just before the renewal is due.
            await Task.Delay(TimeSpan.FromSeconds(8));
            await database.ExecuteAsync("CLIENT", "PAUSE", 7000);
            Console.WriteLine("  t=8s  stalled Redis for 7000ms");

            // Dispose while the renewal EVAL is still in flight.
            await Task.Delay(TimeSpan.FromSeconds(4));
            Console.WriteLine("  t=12s releasing while the renewal is in flight");
            try
            {
                await handle.DisposeAsync();
            }
            catch (Exception ex)
            {
                Console.WriteLine($"  release threw (expected during the stall): {ex.GetType().Name}");
            }

            // Let the abandoned EVAL hit its 5s client timeout, then finalize it.
            await Task.Delay(TimeSpan.FromSeconds(12));
            for (var pass = 0; pass < 3; pass++)
            {
                GC.Collect();
                GC.WaitForPendingFinalizers();
                GC.Collect();
                await Task.Delay(200);
            }

            Console.WriteLine($"  unobserved so far: {Volatile.Read(ref _unobserved)}");
        }

        Console.WriteLine($"=== TOTAL unobserved: {Volatile.Read(ref _unobserved)} ===");
    }
}

Expected: TOTAL unobserved: 0
Actual: TOTAL unobserved: 3

Stack trace

System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread.
 ---> StackExchange.Redis.RedisTimeoutException: Timeout awaiting response
      (outbound=7KiB, inbound=0KiB, 5065ms elapsed, timeout is 5000ms), command=EVAL, ...
   at StackExchange.Redis.RedisDatabase.ScriptEvaluateAsync(String script, RedisKey[] keys,
      RedisValue[] values, CommandFlags flags)
   at Medallion.Threading.Redis.RedLock.RedLockHelper.AsBooleanTask(Task`1 redisResultTask)
      in /_/src/DistributedLock.Redis/RedLock/RedLockHelper.cs:line 63

Where it comes from

RedLockExtend.TryExtendAsync races the in-flight extend tasks against a TimeoutTask built from (_primitive.AcquireTimeout, _cancellationToken):

using TimeoutTask timeout = new TimeoutTask(_primitive.AcquireTimeout, _cancellationToken);
incompleteTasks.Add(timeout.Task);
...
Task task2 = await Task.WhenAny(incompleteTasks);
if (task2 == timeout.Task)
{
    // returns here; the extend tasks are still running and are never observed again
}

Disposing the handle cancels the lease monitor's _disposalSource, which is the _cancellationToken above, so the TimeoutTask wins the race and the method returns while the extend EVAL is still outstanding. When Redis is stalled past asyncTimeout, that task faults and its exception is never read.

LeaseMonitor.CheckLeaseAsync does not catch it either — it awaits through NonThrowingAwaitable ConfigureAwaitOptions.SuppressThrowing), which correctly marks its own task observed, but the faulted task here is the inner extend task one layer below.

Suggested fix

Observe the tasks that are abandoned when the timeout/cancellation branch is taken, e.g. attach a faulted-only continuation that touches Exception before returning:

foreach (var abandoned in incompleteTasks)
{
    if (abandoned != timeout.Task)
    {
        _ = abandoned.ContinueWith(
            static t => { _ = t.Exception; },
            CancellationToken.None,
            TaskContinuationOptions.OnlyOnFaulted | TaskContinuationOptions.ExecuteSynchronously,
            TaskScheduler.Default);
    }
}

RedLockAcquire.WaitForAcquireAsync has the same shape on its completed == timeout.Task branch and looks like it would benefit from the same treatment, though I was not able to make that path produce an unobserved exception with a single database - there, HasTooManyFailuresOrFaults(1, 1) is immediately true, so the faulted acquire task is collected into faultingTasks and observed.

Notes

  • Found via ZiggyCreatures.FusionCache.Locking.Distributed.Redis, which sets Expiry = AbandonTimeout = 30s, giving the ~10s renewal cadence used above. Nothing about the repro requires FusionCache.
  • The trigger is the stall exceeding StackExchange.Redis' asyncTimeout (5000 ms default), not the lock's acquire timeout: varying the acquire timeout across 15s / 5s / 1s under an identical stall produced no trend.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions