Sometimes lock not realeased after leaving using block

[szmcdull]

At first I suspected that there is a deadlock. But I don't know why because I find no reason in my code. Then I added some logs. Then I find out after sometime, the lock is not released even after leaving the using block.

This is the only one method that uses the lock:

        public async Task<T> GetAsync(TimeSpan ttl)
        {
            var lockid = Interlocked.Increment(ref lockID);
            Common.Log.Verbose($"GetAsync entering lock {GetHashCode()}.{lockid} {new StackTrace(1, true)}");

            if ((bool)_lock.GetPrivateFieldOrProperty("_taken"))
            {
                Common.Log.Warning("[ValueCache2] GetAsync: will wait for lock");
                Common.Log.Verbose($"GetAsync leaving lock {lockid}");
                return await DoGet(ttl);
            }

            using (await _lock.LockAsync())
            {
                Common.Log.Verbose($"GetAsync leaving lock {lockid}");
                return await DoGet(ttl);
            }
        }

This is the log:

2020-08-21 14:10:16.316 [VERB] GetAsync entering lock 33189039.4560    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at co.b(TimeSpan A_0)
   at cu.j[a](Func`1 A_0, UInt32 A_1, Object[] A_2) in C:\code\quant\Iwala\Api\Api.cs:line 98
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at cu.j[a](Func`1 A_0, UInt32 A_1, Object[] A_2)
   ...
2020-08-21 14:10:16.316 [VERB] GetAsync leaving lock 4560
   ...
2020-08-21 14:10:19.343 [VERB] GetAsync entering lock 33189039.4561    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at co.b(TimeSpan A_0)
   at cu.j[a](Func`1 A_0, UInt32 A_1, Object[] A_2) in C:\code\quant\Iwala\Api\Api.cs:line 98
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at cu.j[a](Func`1 A_0, UInt32 A_1, Object[] A_2)
   at cu.j(UInt32 A_0) in C:\code\quant\Iwala\Api\Api.cs:line 132
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at cu.j(UInt32 A_0)
  ...
2020-08-21 14:10:19.343 [WARN] [ValueCache2] GetAsync: will wait for lock
2020-08-21 14:10:19.343 [VERB] GetAsync leaving lock 4561
   ...
2020-08-21 14:10:21.364 [VERB] GetAsync entering lock 33189039.4562    at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at co.b(TimeSpan A_0)
   at cu.j[a](Func`1 A_0, UInt32 A_1, Object[] A_2) in C:\code\quant\Iwala\Api\Api.cs:line 98
   at System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[TStateMachine](TStateMachine& stateMachine)
   at cu.j[a](Func`1 A_0, UInt32 A_1, Object[] A_2)
   ...
2020-08-21 14:10:21.364 [WARN] [ValueCache2] GetAsync: will wait for lock
2020-08-21 14:10:21.364 [VERB] GetAsync leaving lock 4562

After that, the lock is not never released. The log always prints will wait for lock.

[StephenCleary]

Could you submit complete code that reproduces the problem?

[szmcdull]

Sorry. It is my fault. DoGet() sometimes never return. I should print log after that call.