async TimeoutPolicy even in pessimistic mode cannot time out on a badly-behaved not-truly-async-but-sync-instead API

[joaoasrosa]

Hi,
I'm using Polly framework (namely Circuit Breaker and Retry policies) in an async context. I'm trying to integrate the Timeout policy with it, but it isn't triggered.

I build a little POC, where we can see an example of the policy within a repository, being called by the WebApi.

The policy looks like:

    public class ResiliencePolicy
    {
        public ResiliencePolicy()
        {
            Policy = Init();
        }

        public Policy Policy { get; }

        protected virtual Policy Init()
        {
            var timeoutPolicy = Policy.TimeoutAsync(
                TimeSpan.FromMilliseconds(100),
                TimeoutStrategy.Pessimistic,
                OnTimeoutAsync);

            return timeoutPolicy;
        }

        protected virtual Task OnTimeoutAsync(Context context, TimeSpan timeSpan, Task task)
        {
            return Task.FromResult(0);
        }
    }

and the policy is used within the repository:

    public class DocumentRepository : IDocumentRepository
    {
        private readonly ResiliencePolicy _resiliencePolicy;
        private readonly IAmazonS3 _s3Client;

        public DocumentRepository(IAmazonS3 s3Client, ResiliencePolicy resiliencePolicy)
        {
            _s3Client = s3Client;
            _resiliencePolicy = resiliencePolicy;
        }

        public async Task<Document> GetDocumentAsync(string bucket, string objectName)
        {
            Document document = null;

            var response =
                await _resiliencePolicy.Policy.ExecuteAsync(async () =>
                    await _s3Client.GetObjectAsync(bucket, objectName));

            if (response.HttpStatusCode == HttpStatusCode.OK)
                document = new Document
                {
                    Name = objectName,
                    Version = response.VersionId
                };

            return document;
        }
    }

With unit tests we can try to prove the timeout is triggered:

    public class DocumentRepositoryTests
    {
        public DocumentRepositoryTests()
        {
            _clientMock = new Mock<IAmazonS3>();
            _policy = new ResiliencePolicyStub();
            _sut = new DocumentRepository(_clientMock.Object, _policy);
        }

        private readonly Mock<IAmazonS3> _clientMock;
        private readonly ResiliencePolicyStub _policy;
        private readonly DocumentRepository _sut;

        [Fact]
        public async Task GetDocumentAsync_WhenCallAboveThreshold_TriggersTimeout()
        {
            _clientMock.Setup(x =>
                    x.GetObjectAsync(It.IsAny<string>(), It.IsAny<string>(), It.IsAny<CancellationToken>()))
                .Callback((string b, string o, CancellationToken c) => { Thread.Sleep(2000); })
                .ReturnsAsync(new GetObjectResponse());

            await Record.ExceptionAsync(async () => await _sut.GetDocumentAsync("dummy", "document.json"));

            _policy.TimeoutTriggered.Should().BeTrue();
        }
    }

with the ResiliencePolicyStub as:

    public class ResiliencePolicyStub : ResiliencePolicy
    {
        public bool TimeoutTriggered { get; private set; }

        protected override async Task OnTimeoutAsync(Context context, TimeSpan timeSpan, Task task)
        {
            TimeoutTriggered = true;
            await base.OnTimeoutAsync(context, timeSpan, task);
        }
    }

The IAmazonS3 mock has a callback to enforce the thread sleep, with a value above the timeout threshold. The delegate function is not triggered (the TimeoutTriggered property doesn't change) neither it receives an exception (TimeoutException).

From the samples there is another mechanism in place, however, from an API perspective the calls are async by "default".

What is missing with the timeout policy configuration?

Note: the example was built with dotnet core 2.0.

[reisenberger]

@joaoasrosa Thank you for the detailed repro.

This test within Polly, is intended to demonstrate that the scenario you are using with TimeoutPolicy works.

I note that the IAmazonS3.GetObjectAsync(...) overload you .Setup(...) on the mock has a different signature from the .GetObjectAsync(...) you execute within DocumentRepository. Have you verified the .SetUp() and its Thread.Sleep(2000); is really getting hit when the test executes? How long does the test take to complete?

Maybe you could adapt the test as follows, to check that the .Callback(...) and .ReturnsAsync(...) of your .Setup(...) is really getting invoked:

var stubResponse = new GetObjectResponse();
_clientMock.Setup(x =>
    x.GetObjectAsync(It.IsAny<string>(), It.IsAny<string>(), It.IsAny<CancellationToken>()))
    .Callback((string b, string o, CancellationToken c) => { Thread.Sleep(2000); })
    .ReturnsAsync(stubResponse);

object actualResponse = null;
await Record.ExceptionAsync(async () => { actualResponse = await _sut.GetDocumentAsync("dummy", "document.json"); } );

actualResponse.Should().BeSameAs(stubResponse);
_policy.TimeoutTriggered.Should().BeTrue();

EDIT: If this comment is off the mark, come back, and we'll dig deeper.

[joaoasrosa]

@reisenberger thanks for your quick reply.

From the mentioned test, the code is similar, e.g., use the ExecutyAysnc provided by the Policy object.

Regarding your concerns:

1. The IAmazonS3.GetObjectAsync has 3 overloads, the last one has a default value. That is the reason in the mock everything is specified, however, in the repository code, it is omitted.
2. The tests take 2 seconds to execute

I added a StopWatch around the tests, and also an extra test using your suggestion.

The results are the same, the timeout policy is not triggered.

And your comment is not off the mark. :) Thanks for the help!

[reisenberger]

@joaoasrosa A bit of lunchtime debugging: If you rewrite the test as follows, it passes:

public async Task GetDocumentAsync_WhenCallAboveThreshold_TriggersTimeout()
{
    _clientMock.Setup(x =>
        x.GetObjectAsync(It.IsAny<string>(), It.IsAny<string>(), It.IsAny<CancellationToken>()))
        .Returns(async () =>
            {
                await Task.Delay(2000);
                return new GetObjectResponse();
            });

    await Record.ExceptionAsync(async () => { await _sut.GetDocumentAsync("dummy", "document.json"); });

    _policy.TimeoutTriggered.Should().BeTrue();
}

The reason for your original test failing looks to be to do with the fact that Moq's .CallBack(...) isn't really async-friendly, given how async/await works

(1) Any async method runs synchronously up to the first await. Only at the first await, does it return a Task, returning execution to the caller.

(2) Moq's .Callback(...) doesn't act as an async method in that manner. It looks to be conceived to be used synchronously only (there's no corresponding .CallbackAsync(...), for example - although I'd be interested to learn more if anybody knows different about Moq). So, in your original test, Moq's .Callback(...) runs synchronously, blocking solidly for those 2 seconds and never returning a Task that would allow the calling code (in this case the Polly policy) to continue execution and decide what to do with that Task. In other words, the original .Callback(... => { Thread.Sleep(2000); }) simulates a badly-behaved async API that isn't really async but sync instead. Effectively, the original test with .Callback(...) ends up using an async TimeoutPolicy on a synchronous execution, and it isn't designed for that.

(3) I experimented with writing .Callback(async () => { await Task.Delay(2000); }) but this also left the test failing. In this case, since .Callback() isn't designed to be async, that form was (by my reading) creating an async void delegate. Moq has no intent to await (it has no async intent around .Callback()) and an async void delegate can't be awaited in any case. Double whammy. So execution proceeded immediately to the .ReturnsAsync(stubResponse) in your original, speedier than the timeout would have occurred. So test again failed.

(4) Hence the final version of the test I came up with. Essentially, to simulate a well-written-for-async but slow-responding async call, the test needs to simulate asynchronously waiting for 2 seconds, not synchronously, before returning the delayed response.

Hope that detailed explanation of why the original didn't work, helps.

This does indicate that Polly's TimeoutAsync policy will fail, even in pessimistic mode, if used against a badly behaved async API, that blocks synchronously rather than being truly async. EDIT: For reasons I can go into in more detail, my initial view is that this is the correct behaviour.

[reisenberger]

@joaoasrosa I deduced those points (2) and (3) above about Moq by quick observation of what was happening, but a brief google now seems to bear out my hunches:

https://stackoverflow.com/questions/36583780/async-callback-on-mocked-object-not-awaiting

devlooped/moq#256 (comment)

[reisenberger]

PS Thanks for the explanation:

The IAmazonS3.GetObjectAsync has 3 overloads, the last one has a default value. That is
the reason in the mock everything is specified, however, in the repository code, it is omitted

(I'd missed the last param being optional, meaning the setup did cover the matching signature!)

[joaoasrosa]

@reisenberger Thanks for your lunchtime.
Your explanation makes perfect sense, I was caught by it!
The POC was updated to reflect the way the tests should be written.

Cheers