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

JSkimming · 2019-04-03T21:15:01Z

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

codecov · 2019-04-03T21:17:03Z

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%)`	⬇️
...ore.AsyncInterceptor/ProcessingAsyncInterceptor.cs	`92% <0%> (-8%)`	⬇️

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 · 2019-04-03T22:03:04Z

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%)`	⬆️
...ore.AsyncInterceptor/ProcessingAsyncInterceptor.cs	`100% <0%> (+8%)`	⬆️

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 · 2019-04-05T12:08:33Z

@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 · 2019-04-05T23:34:40Z

@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 · 2019-04-06T21:38:28Z

@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 · 2019-04-06T22:38:20Z

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 · 2019-04-07T00:24:37Z

@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.

Moq also references Castle.Core, which may be confusing matters.

JSkimming · 2019-04-08T18:37:42Z

@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 · 2019-04-08T20:03:36Z

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

JSkimming mentioned this pull request Apr 3, 2019

Interceptor calling async method before invocation.Proceed() Problem aspnetboilerplate/aspnetboilerplate#4401

Open

JSkimming force-pushed the use-CaptureProceedInfo branch 4 times, most recently from a1dcb25 to d15ff56 Compare April 4, 2019 09:43

JSkimming mentioned this pull request Apr 5, 2019

Housekeeping #55

Merged

JSkimming force-pushed the use-CaptureProceedInfo branch 3 times, most recently from fb02f30 to b814ced Compare April 5, 2019 21:23

JSkimming mentioned this pull request Apr 5, 2019

Testing improvements #56

Merged

JSkimming force-pushed the use-CaptureProceedInfo branch from b814ced to ab1bb63 Compare April 5, 2019 22:04

Introduce an async operation before proceeding

74bd01c

JSkimming force-pushed the use-CaptureProceedInfo branch from ab1bb63 to 74bd01c Compare April 5, 2019 22:50

JSkimming self-assigned this Apr 5, 2019

JSkimming added 2 commits April 8, 2019 19:00

Refactor to make use of CaptureProceedInfo

dc9c0e3

Remove the reference to Moq as it only used in 1 test

8b7fe22

Moq also references Castle.Core, which may be confusing matters.

JSkimming force-pushed the use-CaptureProceedInfo branch from bb76566 to 8b7fe22 Compare April 8, 2019 18:02

JSkimming added 2 commits April 8, 2019 21:11

Sets the permutations of async interception before and after Proceed()

3e07f00

Improve testing of methods that return completed and incomplete tasks

a81f2fc

JSkimming force-pushed the use-CaptureProceedInfo branch 2 times, most recently from 39058d3 to 7af5237 Compare April 8, 2019 21:54

JSkimming force-pushed the use-CaptureProceedInfo branch 3 times, most recently from 86f7b40 to a81f2fc Compare April 8, 2019 22:07

JSkimming merged commit 51ddc0c into master Apr 8, 2019

JSkimming deleted the use-CaptureProceedInfo branch April 8, 2019 22:10

JSkimming mentioned this pull request Apr 9, 2019

Discussion: Directions to take async interception #60

Open

This was referenced Jan 25, 2021

Fix issue 25 #28

Closed

Test demonstrating Issue #25 - Root Cause: Calls to proceed after the first await are intercepted again #26

Closed

JSkimming mentioned this pull request Feb 13, 2023

My AsyncInterceptor which injects an Async Logger is intercepting the Logger requests causing a loop #49

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

JSkimming commented Apr 3, 2019 •

edited

Loading

codecov bot commented Apr 3, 2019 •

edited

Loading

codecov-io commented Apr 3, 2019 •

edited by codecov bot

Loading

brunoblank commented Apr 5, 2019

JSkimming commented Apr 5, 2019

brunoblank commented Apr 6, 2019

stakx commented Apr 6, 2019 •

edited

Loading

JSkimming commented Apr 7, 2019 •

edited

Loading

JSkimming commented Apr 8, 2019

brunoblank commented Apr 8, 2019

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

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

Conversation

JSkimming commented Apr 3, 2019 • edited Loading

codecov bot commented Apr 3, 2019 • edited Loading

Codecov Report

codecov-io commented Apr 3, 2019 • edited by codecov bot Loading

Codecov Report

brunoblank commented Apr 5, 2019

JSkimming commented Apr 5, 2019

brunoblank commented Apr 6, 2019

stakx commented Apr 6, 2019 • edited Loading

JSkimming commented Apr 7, 2019 • edited Loading

JSkimming commented Apr 8, 2019

brunoblank commented Apr 8, 2019

JSkimming commented Apr 3, 2019 •

edited

Loading

codecov bot commented Apr 3, 2019 •

edited

Loading

codecov-io commented Apr 3, 2019 •

edited by codecov bot

Loading

stakx commented Apr 6, 2019 •

edited

Loading

JSkimming commented Apr 7, 2019 •

edited

Loading