AsyncDemo09_Wrap_Fallback_Timeout_WaitAndRetry throws

[virzak]

This doesn't seem to be part of the demo.

Demo was canceled: AsyncDemo09_Wrap_Fallback_Timeout_WaitAndRetry
.Log,then retry: Cannot access a disposed object.
Object name: 'System.Net.Http.HttpClient'.
Demo already stopped.
Unobserved task exception: 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. ---> System.ObjectDisposedException: The CancellationTokenSource has been disposed.
   at System.Threading.CancellationTokenSource.ThrowObjectDisposedException()
   at System.Threading.CancellationTokenSource.InternalRegister(Action`1 callback, Object stateForCallback, SynchronizationContext targetSyncContext, ExecutionContext executionContext)
   at System.Threading.CancellationToken.Register(Action`1 callback, Object state, Boolean useSynchronizationContext, Boolean useExecutionContext)
   at System.Threading.CancellationToken.InternalRegisterWithoutEC(Action`1 callback, Object state)
   at System.Threading.Tasks.Task.Delay(Int32 millisecondsDelay, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Delay(TimeSpan delay, CancellationToken cancellationToken)
   at Polly.Retry.AsyncRetryEngine.<ImplementationAsync>d__0`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.AsyncPolicy.<ExecuteAsync>d__21`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Wrap.AsyncPolicyWrapEngine.<>c__DisplayClass1_0`1.<<ImplementationAsync>b__0>d.MoveNext()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: The CancellationTokenSource has been disposed.
   at System.Threading.CancellationTokenSource.ThrowObjectDisposedException()
   at System.Threading.CancellationTokenSource.InternalRegister(Action`1 callback, Object stateForCallback, SynchronizationContext targetSyncContext, ExecutionContext executionContext)
   at System.Threading.CancellationToken.Register(Action`1 callback, Object state, Boolean useSynchronizationContext, Boolean useExecutionContext)
   at System.Threading.CancellationToken.InternalRegisterWithoutEC(Action`1 callback, Object state)
   at System.Threading.Tasks.Task.Delay(Int32 millisecondsDelay, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Delay(TimeSpan delay, CancellationToken cancellationToken)
   at Polly.Retry.AsyncRetryEngine.<ImplementationAsync>d__0`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.AsyncPolicy.<ExecuteAsync>d__21`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Wrap.AsyncPolicyWrapEngine.<>c__DisplayClass1_0`1.<<ImplementationAsync>b__0>d.MoveNext()<---
.

[reisenberger]

Can you describe when this happened? It sounds like just a possible race condition in closing down the demo; or possible trying to stop a demo that had already been stopped.

[virzak]

@reisenberger

Posting the output. Hoping this will help. I tried this on two different windows machines. Crashes right out of the box:

AsyncDemo09_Wrap_Fallback_Timeout_WaitAndRetry
======

Response: {"Text":"Response from server to request #1"}(after 819ms)
Response: {"Text":"Response from server to request #2"}(after 11ms)
Response: {"Text":"Response from server to request #3"}(after 8ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Fallback catches failed with: The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout. (after 2007ms)
Response: Please try again later [Fallback for timeout](after 2007ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Fallback catches failed with: The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout. (after 2015ms)
Response: Please try again later [Fallback for timeout](after 2015ms)
Response: {"Text":"Response from server to request #6"}(after 6ms)
Response: {"Text":"Response from server to request #7"}(after 6ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Fallback catches failed with: The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout. (after 2003ms)
Response: Please try again later [Fallback for timeout](after 2003ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Fallback catches failed with: The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout. (after 2013ms)
Response: Please try again later [Fallback for timeout](after 2013ms)
Response: {"Text":"Response from server to request #10"}(after 6ms)
Response: {"Text":"Response from server to request #11"}(after 5ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Fallback catches failed with: The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout. (after 2014ms)
Response: Please try again later [Fallback for timeout](after 2014ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Fallback catches failed with: The delegate executed asynchronously through TimeoutPolicy did not complete within the timeout. (after 2002ms)
Response: Please try again later [Fallback for timeout](after 2002ms)
Response: {"Text":"Response from server to request #14"}(after 6ms)
Response: {"Text":"Response from server to request #15"}(after 6ms)
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
.Log,then retry: Response status code does not indicate success: 503 (You have exceeded the maximum number of allowed calls. Please wait until after the cooldown period to try again.).
Total requests made                     : 16
Requests which eventually succeeded     : 15
Retries made to help achieve success    : 9
Requests timed out by timeout policy    : 6
Requests which failed after longer delay: 0
Unobserved task exception: 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. ---> System.ObjectDisposedException: The CancellationTokenSource has been disposed.
   at System.Threading.CancellationTokenSource.ThrowObjectDisposedException()
   at System.Threading.CancellationTokenSource.InternalRegister(Action`1 callback, Object stateForCallback, SynchronizationContext targetSyncContext, ExecutionContext executionContext)
   at System.Threading.CancellationToken.Register(Action`1 callback, Object state, Boolean useSynchronizationContext, Boolean useExecutionContext)
   at System.Threading.CancellationToken.InternalRegisterWithoutEC(Action`1 callback, Object state)
   at System.Threading.Tasks.Task.Delay(Int32 millisecondsDelay, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Delay(TimeSpan delay, CancellationToken cancellationToken)
   at Polly.Retry.RetryStateWaitAndRetryForever`1.<CanRetryAsync>d__8.MoveNext() in C:\projects\polly\src\Polly.Shared\Retry\RetryStateWaitAndRetryForeverAsync.cs:line 29
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Retry.RetryEngine.<ImplementationAsync>d__1`1.MoveNext() in C:\projects\polly\src\Polly.Shared\Retry\RetryEngineAsync.cs:line 52
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Policy.<ExecuteAsync>d__152`1.MoveNext() in C:\projects\polly\src\Polly.Shared\PolicyAsync.cs:line 552
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Wrap.PolicyWrapEngine.<>c__DisplayClass6_0`1.<<ImplementationAsync>b__0>d.MoveNext() in C:\projects\polly\src\Polly.Shared\Wrap\PolicyWrapEngineAsync.cs:line 0
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Policy.<>c__DisplayClass152_0`1.<<ExecuteAsync>b__0>d.MoveNext() in C:\projects\polly\src\Polly.Shared\PolicyAsync.cs:line 0
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Policy.<>c__DisplayClass224_0.<<TimeoutAsync>b__1>d.MoveNext() in C:\projects\polly\src\Polly.Shared\Timeout\TimeoutSyntaxAsync.cs:line 255
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: The CancellationTokenSource has been disposed.
   at System.Threading.CancellationTokenSource.ThrowObjectDisposedException()
   at System.Threading.CancellationTokenSource.InternalRegister(Action`1 callback, Object stateForCallback, SynchronizationContext targetSyncContext, ExecutionContext executionContext)
   at System.Threading.CancellationToken.Register(Action`1 callback, Object state, Boolean useSynchronizationContext, Boolean useExecutionContext)
   at System.Threading.CancellationToken.InternalRegisterWithoutEC(Action`1 callback, Object state)
   at System.Threading.Tasks.Task.Delay(Int32 millisecondsDelay, CancellationToken cancellationToken)
   at System.Threading.Tasks.Task.Delay(TimeSpan delay, CancellationToken cancellationToken)
   at Polly.Retry.RetryStateWaitAndRetryForever`1.<CanRetryAsync>d__8.MoveNext() in C:\projects\polly\src\Polly.Shared\Retry\RetryStateWaitAndRetryForeverAsync.cs:line 29
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Retry.RetryEngine.<ImplementationAsync>d__1`1.MoveNext() in C:\projects\polly\src\Polly.Shared\Retry\RetryEngineAsync.cs:line 52
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Policy.<ExecuteAsync>d__152`1.MoveNext() in C:\projects\polly\src\Polly.Shared\PolicyAsync.cs:line 552
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Wrap.PolicyWrapEngine.<>c__DisplayClass6_0`1.<<ImplementationAsync>b__0>d.MoveNext() in C:\projects\polly\src\Polly.Shared\Wrap\PolicyWrapEngineAsync.cs:line 0
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Policy.<>c__DisplayClass152_0`1.<<ExecuteAsync>b__0>d.MoveNext() in C:\projects\polly\src\Polly.Shared\PolicyAsync.cs:line 0
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Polly.Policy.<>c__DisplayClass224_0.<<TimeoutAsync>b__1>d.MoveNext() in C:\projects\polly\src\Polly.Shared\Timeout\TimeoutSyntaxAsync.cs:line 255<---
.
Fallback catches eventually failed with: A task was canceled. (after 1423ms)
Response: Please try again later [Fallback for any exception](after 1423ms)
Demo was canceled: AsyncDemo09_Wrap_Fallback_Timeout_WaitAndRetry

[reisenberger]

Hi @virzak . So: It's an exact demonstration of the dimension to TimeoutStrategy.Pessimistic which we discuss here in the TimeoutPolicy documentation.

TimeoutStrategy.Pessimistic allows the calling code to walk away from waiting for delegates that haven't responded within the timeout, but those delegates aren't (can't be) unilaterally cancelled by Polly. They carry on running, and if they throw an exception which no user code observes, those exceptions become an UnobservedTaskException.

The timeout policies in these demos (async; sync) don't include the necessary defence to catch those walked-away from tasks with onTimeout: [...] task.ContinueWith(...).

I can add that - or you/anyone feel free to make a PR to do so, if you want to explore it!

For example, the policy in AsyncDemo09_Wrap_Fallback_Timeout_WaitAndRetry should probably be replaced with something like:

        // Define our timeout policy: time out after 2 seconds.  We will use the pessimistic timeout strategy, which forces a timeout - even when the underlying delegate doesn't support it.
        // We attach a handler to show if any walked-away-from (timed-out) tasks later throw an exception.
        var timeoutPolicy = Policy
            .TimeoutAsync(TimeSpan.FromSeconds(2), TimeoutStrategy.Pessimistic,
                onTimeoutAsync: (ctx, span, abandonedTask) =>
                {
                    {
                        abandonedTask.ContinueWith(t =>
                        {
                            // ContinueWith important!: the abandoned task may very well still be executing, when the caller times out on waiting for it! 

                            if (t.IsFaulted)
                            {
                                progress.Report(ProgressWithMessage(".Task walked-away-from previously terminated with exception: " + t.Exception.Message, Color.Yellow));
                            }
                            else if (t.IsCanceled)
                            {
                                // (If the executed delegates do not honour cancellation, this IsCanceled branch may never be hit.  It can be good practice however to include, in case a Policy configured with TimeoutStrategy.Pessimistic is used to execute a delegate honouring cancellation.)  
                                progress.Report(ProgressWithMessage(".Task walked-away-from previously was canceled.", Color.Yellow));
                            }
                            else
                            {
                                // extra logic (if desired) for tasks which complete, despite the caller having 'walked away' earlier due to timeout.
                                progress.Report(ProgressWithMessage(".Task walked-away-from previously eventually completed.", Color.Yellow));
                            }
                        });

                        return Task.FromResult(true);
                    }
                }
            );

Only demo09 (sync and async) is affected.

---

If you're using the wpf version of the demo, we attach a handler for that kind of exception here, and that handler is outputting the exception, then cancelling the demo. The output you posted looks like the result of that.