Use the new Castle.Core CaptureProceedInfo() to make AsyncInterceptor work for reals

[JSkimming]

I plan to release this as an alpha, as we feel some work is required before it is production ready.

[codecov[bot]]

Codecov Report

Merging #54 into master will decrease coverage by 1.73%. The diff coverage is 100%.

@@            Coverage Diff             @@
##           master      #54      +/-   ##
==========================================
- Coverage     100%   98.26%   -1.74%     
==========================================
  Files           5        5              
  Lines         230      231       +1     
  Branches        7       11       +4     
==========================================
- Hits          230      227       -3     
- Partials        0        4       +4

Impacted Files	Coverage Δ
...stle.Core.AsyncInterceptor/AsyncInterceptorBase.cs	96.36% <100%> (-3.64%)	:arrow_down:
...ore.AsyncInterceptor/ProcessingAsyncInterceptor.cs	92% <0%> (-8%)	:arrow_down:

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 12562fa...71a7823. Read the comment docs.

[codecov-io]

Codecov Report

Merging #54 into master will increase coverage by 1.73%. The diff coverage is 100%.

@@           Coverage Diff            @@
##           master    #54      +/-   ##
========================================
+ Coverage   98.26%   100%   +1.73%     
========================================
  Files           5      5              
  Lines         231    232       +1     
  Branches       11     11              
========================================
+ Hits          227    232       +5     
+ Partials        4      0       -4

Impacted Files	Coverage Δ
...stle.Core.AsyncInterceptor/AsyncInterceptorBase.cs	100% <100%> (+3.63%)	:arrow_up:
...ore.AsyncInterceptor/ProcessingAsyncInterceptor.cs	100% <0%> (+8%)	:arrow_up:

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 6537e8f...a81f2fc. Read the comment docs.

[brunoblank]

@JSkimming awesome work here!

I have a lot on my plate atm. But, I will try to find time during the weekend helping out on this!

[JSkimming]

@brunoblank Please do jump in if you can spare the time.

I've made the changes and have managed to get it all working, unfortunately, I'm getting a deadlock unless I disable parallel test execution.

If you edit the file xunit.runner.json on the use-CaptureProceedInfo branch and change parallelizeTestCollections to true, you'll get the problem.

Every 60 seconds the Long Running Tests are displayed. This shows the tests that are deadlocked.

Change longRunningTestSeconds in xunit.runner.json to a smaller number to see the deadlocked tests sooner.

I'd like to bottom out the root cause of the deadlock. It's possible this is not a new problem but is now happening because all the tests are truly executing asynchronously.

[brunoblank]

@JSkimming I tried to reproduce the dead-lock but everything seems to run fine for me done the changes described above.

This is the output:

Test run for C:\projects\Castle.Core.AsyncInterceptor\test\Castle.Core.AsyncInterceptor.Tests\bin\Debug\netcoreapp2.0\Castle.Core.AsyncInterceptor.Tests.dll(.NETCoreApp,Version=v2.0)
Microsoft (R) Test Execution Command Line Tool Version 15.9.0
Copyright (c) Microsoft Corporation.  All rights reserved.

Starting test execution, please wait...
[xUnit.net 00:00:00.54] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendInterfaceProxyGenerator'; falling back to single test case.
[xUnit.net 00:00:00.55] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendClassProxyGenerator'; falling back to single test case.

Total tests: 129. Passed: 129. Failed: 0. Skipped: 0.
Test Run Successful.
Test execution time: 2,3822 Seconds

(dotnet --version: 2.2.105)

[stakx]

Same here btw. No deadlocks for me during test execution with "parallelizeTestCollections": true.

dotnet --info

``` .NET Core SDK (reflecting any global.json): Version: 2.2.202 Commit: 8a7ff6789d Runtime Environment: OS Name: Windows OS Version: 10.0.17134 OS Platform: Windows RID: win10-x64 Base Path: C:\Program Files\dotnet\sdk\2.2.202\ Host (useful for support): Version: 2.2.3 Commit: 6b8ad509b6 .NET Core SDKs installed: 2.2.202 [C:\Program Files\dotnet\sdk] .NET Core runtimes installed: Microsoft.AspNetCore.All 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All] Microsoft.AspNetCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App] Microsoft.NETCore.App 1.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] Microsoft.NETCore.App 2.2.3 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App] ```

dotnet test

``` Test run for C:\Users\stakx\Projects\Castle.Core.AsyncInterceptor\test\Castle.Core.AsyncInterceptor.Tests\bin\Debug\net47\Castle.Core.AsyncInterceptor.Tests.dll(.NETFramework,Version=v4.7) Microsoft (R) Test Execution Command Line Tool Version 16.0.1 Copyright (c) Microsoft Corporation. All rights reserved. Starting test execution, please wait... [xUnit.net 00:00:01.01] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendInterfaceProxyGenerator'; falling back to single test case. [xUnit.net 00:00:01.01] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendClassProxyGenerator'; falling back to single test case. Total tests: 129. Passed: 129. Failed: 0. Skipped: 0. Test Run Successful. Test execution time: 2,5974 Seconds Test run for C:\Users\stakx\Projects\Castle.Core.AsyncInterceptor\test\Castle.Core.AsyncInterceptor.Tests\bin\Debug\netcoreapp1.1\Castle.Core.AsyncInterceptor.Tests.dll(.NETCoreApp,Version=v1.1) Microsoft (R) Test Execution Command Line Tool Version 16.0.1 Copyright (c) Microsoft Corporation. All rights reserved. Starting test execution, please wait... [xUnit.net 00:00:00.57] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendInterfaceProxyGenerator'; falling back to single test case. [xUnit.net 00:00:00.57] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendClassProxyGenerator'; falling back to single test case. Total tests: 129. Passed: 129. Failed: 0. Skipped: 0. Test Run Successful. Test execution time: 2,2768 Seconds Test run for C:\Users\stakx\Projects\Castle.Core.AsyncInterceptor\test\Castle.Core.AsyncInterceptor.Tests\bin\Debug\netcoreapp2.0\Castle.Core.AsyncInterceptor.Tests.dll(.NETCoreApp,Version=v2.0) Microsoft (R) Test Execution Command Line Tool Version 16.0.1 Copyright (c) Microsoft Corporation. All rights reserved. Starting test execution, please wait... [xUnit.net 00:00:00.48] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendInterfaceProxyGenerator'; falling back to single test case. [xUnit.net 00:00:00.48] Castle.Core.AsyncInterceptor.Tests: Non-serializable data ('System.Object[]') found for 'Castle.DynamicProxy.ProxyGeneratorExtensionsShould.ExtendClassProxyGenerator'; falling back to single test case. Total tests: 129. Passed: 129. Failed: 0. Skipped: 0. Test Run Successful. Test execution time: 2,1361 Seconds ```

[JSkimming]

@brunoblank, @stakx thanks for giving it a shot.

I was using .NET Core 2.2.104 though now upgraded to 2.2.202, I still get the deadlock, as does both AppVeyor and Travis.

I've noticed both of your test runs take a little over 2 seconds, whereas mine is about 3.8, maybe there's a timing issue, which my 2-year-old laptop gets because it's slower than yours.

I'm going to see if I can identify where the deadlock is occurring.

[JSkimming]

@brunoblank, @stakx I found it.

xunit defaults maxParallelThreads to the number of processors. 4 on my laptop, 2 on the build servers, and I'm guessing at least 8 on your machines. I've forced it to 8 in the config, and the deadlock is gone.

It's possible this is not a new problem but is now happening because all the tests are genuinely executing asynchronously.

I was right; it was never a problem because async before interception wasn't possible. This deadlock issue does though highlight the flaw in the implementation of AsyncInterceptorBase, or as I suspect, in its design.

It's trying to make it easier to implement an interceptor by requiring a derived class to implement just two methods.

protected abstract Task InterceptAsync(IInvocation invocation, Func<IInvocation, Task> proceed);
protected abstract Task<TResult> InterceptAsync<TResult>(
    IInvocation invocation,
    Func<IInvocation, Task<TResult>> proceed);

But for synchronous interception, it has to transition back from a potentially asynchronous interceptor, and the only safe way (or so I thought) to do that is starting a new thread using Task.Run(). The reason the tests were deadlocking is that the maximum number of threads had been exhausted.

In a real scenario, the maximum number of threads will be far higher, but not unlimited, and this has the potential to deadlock in a production system, something interception is not supposed to do. Sort of like the Hippocratic Oath 😃.

I'm keen to get this out, so I'm thinking of releasing it as an alpha, then I'd like to tackle AsyncInterceptorBase.

[brunoblank]

Glad you found it!

That makes sense now when you identified it. We should remove all blocking calls from the library as it will cause thread exhaustion (or really bad performance when the thread pool is scaling up).

It is important that we realize running synchronous (cpu-bound) interceptions is totally fine even if it return like Thread.FromResult even though there is the cost of an extra Task allocation.

The big problem is running blocking call on async or the slightly better running async and waiting (using a Task.Run). We should not try to safeguard against this.

I'm keen to get this out, so I'm thinking of releasing it as an alpha, then I'd like to tackle AsyncInterceptorBase.

Totally agree