Race condition (probably) in Ninject + Ninject.MVC under medium/high load

[a.loker]

Hi,

I'm currently load testing a website using WCat* and I'm experiencing
severe race conditions during the resolution of dependencies.

It can be easily reproduced with the tiniest MVC 3 web app. I've
uploaded such an app here: https://github.com/aloker/ninject-issue

What I did:
- create a new empty MVC 3 web app
- remove content, scripts, view and model folders
- add a trivial HomeController with an Index action that returns a
literal string
- then add Ninject.MVC3 through the nuget console (Install-Package -Id
Ninject.MVC3)
- Stat the app. So far everything works fine, the home/index action
simply displays the literal string.

Now I fire up WCat and have it stress test this app with 100 virtual
clients. Very soon, all requests will fail.
I've created another simple app that writes the exceptions to a log
file, and here's the first error that occurs:

ERROR 2011-02-28 21:17:19.6100 [24] App Application error
System.InvalidOperationException: Collection was modified after the
enumerator was instantiated.
bei
System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource
resource)
bei System.Collections.Generic.Stack`1.Enumerator.MoveNext()
bei System.Collections.Generic.Stack`1..ctor(IEnumerable`1
collection)
bei Ninject.Activation.Request..ctor(IContext parentContext, Type
service, ITarget target, Func`1 scopeCallback)
bei Ninject.Activation.Request.CreateChild(Type service, IContext
parentContext, ITarget target)
bei Ninject.Planning.Targets.Target`1.GetValue(Type service,
IContext parent)
bei Ninject.Planning.Targets.Target`1.ResolveWithin(IContext
parent)
bei Ninject.Activation.Providers.StandardProvider.GetValue(IContext
context, ITarget target)
bei
Ninject.Activation.Providers.StandardProvider.<>c__DisplayClass2.<Create>b__1(ITarget
target)
bei System.Linq.Enumerable.WhereSelectArrayIterator`2.MoveNext()
bei System.Linq.Buffer`1..ctor(IEnumerable`1 source)
bei System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
bei Ninject.Activation.Providers.StandardProvider.Create(IContext
context)
bei Ninject.Activation.Context.Resolve()
bei Ninject.KernelBase.<Resolve>b__7(IContext context)
bei
System.Linq.Enumerable.<>c__DisplayClass12`3.<CombineSelectors>b__11(TSource
x)
bei
System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
bei System.Linq.Enumerable.<CastIterator>d__b1`1.MoveNext()
bei System.Linq.Enumerable.<ConcatIterator>d__71`1.MoveNext()
bei System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
bei System.Linq.Buffer`1..ctor(IEnumerable`1 source)
bei System.Linq.OrderedEnumerable`1.<GetEnumerator>d__0.MoveNext()
bei System.Linq.Buffer`1..ctor(IEnumerable`1 source)
bei System.Linq.Enumerable.<ReverseIterator>d__a0`1.MoveNext()
bei
System.Web.Mvc.FilterProviderCollection.<RemoveDuplicates>d__b.MoveNext()
bei System.Linq.Buffer`1..ctor(IEnumerable`1 source)
bei System.Linq.Enumerable.<ReverseIterator>d__a0`1.MoveNext()
bei
System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
bei System.Collections.Generic.List`1..ctor(IEnumerable`1
collection)
bei System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
bei System.Web.Mvc.FilterInfo..ctor(IEnumerable`1 filters)
bei
System.Web.Mvc.ControllerActionInvoker.GetFilters(ControllerContext
controllerContext, ActionDescriptor actionDescriptor)
bei
System.Web.Mvc.ControllerActionInvoker.InvokeAction(ControllerContext
controllerContext, String actionName)
bei System.Web.Mvc.Controller.ExecuteCore()
bei System.Web.Mvc.ControllerBase.Execute(RequestContext
requestContext)
bei
System.Web.Mvc.ControllerBase.System.Web.Mvc.IController.Execute(RequestContext
requestContext)
bei
System.Web.Mvc.MvcHandler.<>c__DisplayClass6.<>c__DisplayClassb.<BeginProcessRequest>b__5()
bei
System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass1.<MakeVoidDelegate>b__0()
bei
System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass8`1.<BeginSynchronous>b__7(IAsyncResult
_)
bei
System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.End()
bei
System.Web.Mvc.MvcHandler.<>c__DisplayClasse.<EndProcessRequest>b__d()
bei System.Web.Mvc.SecurityUtil.<GetCallInAppTrustThunk>b__0(Action
f)
bei System.Web.Mvc.SecurityUtil.ProcessInApplicationTrust(Action
action)
bei System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult
asyncResult)
bei
System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult
result)
bei
System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
bei System.Web.HttpApplication.ExecuteStep(IExecutionStep step,
Boolean& completedSynchronously)

So it looks as if Request.ActiveBindings is accessed concurrently. By
the way, subsequent request fail with various errors, such as " Error
activating IFilterProvider using binding from IFilterProvider to
NinjectFilterAttributeFilterProvider.A cyclical dependency was
detected between the constructors of two services." or "Error loading
Ninject component ICache. No such component has been registered in the
kernel's component container." (looks like
http://groups.google.com/group/ninject/browse_thread/thread/3084be8ba9e48248
is related)

The problem is not specific to the NuGet version, as I've tested it
with Ninject 2.1 as well. I'd highly appreciate if someone could look
into this soon. It is a serious flaw that keeps the web application in
an unusable state (AppPool needs to be recycled).

Regards,
Andre

*http://www.iis.net/community/default.aspx?tabid=34&i=1467&g=6

[Remo Gloor]

Hi Andre

The application you linked has a problem. As I mentioned in the other
thread you have to remove the code in the Dispose method of
NinjectHttpApplicationModule. I'm currently in contact with David
Ebbo. He currently adds support for a propper Application End event to
the WebActivator so that disposing of the kernel will be available
soon again. If you want to use it in a production environment I
suggest to use the none nuget way and derive from
NinjectHttpApplication at the moment.

Please let me know if you still have the same problem if you are using
one of the proposed workaround above.

-Remo

> kernel's component container." (looks likehttp://groups.google.com/group/ninject/browse_thread/thread/3084be8ba...

[a.loker]

Hi Remo,

Thanks for you answer. The issue is NOT related to the NuGet version.
As I mentioned, I first found this issue in an application running
Ninject/Ninject.Web.Mvc 3 at version 2.1.x.x. I've updated
https://github.com/aloker/ninject-issue to use the current 2.2
release. The issue also exists in this version. I've added some
logging output below, maybe it helps (format is SEVERITY timestamp
[threadid] logger message). Note how three requests are made almost at
the same time, that's why I guess it is a race condition.

... (about 350 successful accesses at about 370 requests per second)
INFO 2011-03-01 09:19:18.0305 [43] NinjectIssue.MvcApplication BEGIN
http://localhost:80/
INFO 2011-03-01 09:19:18.0305 [42] NinjectIssue.MvcApplication BEGIN
http://localhost:80/
INFO 2011-03-01 09:19:18.0305 [27] NinjectIssue.MvcApplication BEGIN
http://localhost:80/
ERROR 2011-03-01 09:19:18.0305 [42] NinjectIssue.MvcApplication
ERROR http://localhost:80/ System.InvalidOperationException:

Collection was modified after the enumerator was instantiated.

at
System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource
resource)
at System.Collections.Generic.Stack`1.Enumerator.MoveNext()
at System.Collections.Generic.Stack`1..ctor(IEnumerable`1
collection)
at Ninject.Activation.Request..ctor(IContext parentContext, Type

service, ITarget target, Func`1 scopeCallback)

at Ninject.Activation.Request.CreateChild(Type service, IContext
parentContext, ITarget target)
at Ninject.Planning.Targets.Target`1.GetValue(Type service,
IContext parent)
at Ninject.Planning.Targets.Target`1.ResolveWithin(IContext parent)
at Ninject.Activation.Providers.StandardProvider.GetValue(IContext
context, ITarget target)
at

Ninject.Activation.Providers.StandardProvider.<>c__DisplayClass2.<Create>b__1(ITarget
target)

at System.Linq.Enumerable.WhereSelectArrayIterator`2.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)
at Ninject.Activation.Providers.StandardProvider.Create(IContext
context)
at Ninject.Activation.Context.Resolve()
at Ninject.KernelBase.<Resolve>b__7(IContext context)
at

System.Linq.Enumerable.<>c__DisplayClass12`3.<CombineSelectors>b__11(TSource
x)

at
System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.<CastIterator>d__b1`1.MoveNext()
at System.Linq.Enumerable.<ConcatIterator>d__71`1.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.OrderedEnumerable`1.<GetEnumerator>d__0.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.Enumerable.<ReverseIterator>d__a0`1.MoveNext()
at
System.Web.Mvc.FilterProviderCollection.<RemoveDuplicates>d__b.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.Enumerable.<ReverseIterator>d__a0`1.MoveNext()
at
System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Collections.Generic.List`1..ctor(IEnumerable`1
collection)
at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
at System.Web.Mvc.FilterInfo..ctor(IEnumerable`1 filters)
at
System.Web.Mvc.ControllerActionInvoker.GetFilters(ControllerContext
controllerContext, ActionDescriptor actionDescriptor)
at
System.Web.Mvc.ControllerActionInvoker.InvokeAction(ControllerContext
controllerContext, String actionName)
at System.Web.Mvc.Controller.ExecuteCore()
at System.Web.Mvc.ControllerBase.Execute(RequestContext
requestContext)
at
System.Web.Mvc.ControllerBase.System.Web.Mvc.IController.Execute(RequestContext
requestContext)
at

System.Web.Mvc.MvcHandler.<>c__DisplayClass6.<>c__DisplayClassb.<BeginProcessRequest>b__5()

at
System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass1.<MakeVoidDelegate>b__0()
at

System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass8`1.<BeginSynchronous>b__7(IAsyncResult
_)

at
System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.End()
at
System.Web.Mvc.MvcHandler.<>c__DisplayClasse.<EndProcessRequest>b__d()
at System.Web.Mvc.SecurityUtil.<GetCallInAppTrustThunk>b__0(Action
f)
at System.Web.Mvc.SecurityUtil.ProcessInApplicationTrust(Action
action)
at System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult
asyncResult)
at
System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult
result)
at
System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step,
Boolean& completedSynchronously)
...



From now on, every request fails like this:

ERROR 2011-03-01 09:19:18.0305 [27] NinjectIssue.MvcApplication
ERROR http://localhost:80/ Ninject.ActivationException: Error

activating IFilterProvider using binding from IFilterProvider to
NinjectFilterAttributeFilterProvider

A cyclical dependency was detected between the constructors of two
services.

Activation path:
1) Request for IFilterProvider

Suggestions:
1) Ensure that you have not declared a dependency for
IFilterProvider on any implementations of the service.
2) Consider combining the services into a single one to remove the
cycle.
3) Use property injection instead of constructor injection, and
implement IInitializable
if you need initialization logic to be run after property values
have been injected.

at Ninject.Activation.Context.Resolve()
at Ninject.KernelBase.<Resolve>b__7(IContext context)
at

System.Linq.Enumerable.<>c__DisplayClass12`3.<CombineSelectors>b__11(TSource
x)

at
System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Linq.Enumerable.<CastIterator>d__b1`1.MoveNext()
at System.Linq.Enumerable.<ConcatIterator>d__71`1.MoveNext()
at System.Linq.Enumerable.<SelectManyIterator>d__14`2.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.OrderedEnumerable`1.<GetEnumerator>d__0.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.Enumerable.<ReverseIterator>d__a0`1.MoveNext()
at
System.Web.Mvc.FilterProviderCollection.<RemoveDuplicates>d__b.MoveNext()
at System.Linq.Buffer`1..ctor(IEnumerable`1 source)
at System.Linq.Enumerable.<ReverseIterator>d__a0`1.MoveNext()
at
System.Linq.Enumerable.WhereSelectEnumerableIterator`2.MoveNext()
at System.Collections.Generic.List`1..ctor(IEnumerable`1
collection)
at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
at System.Web.Mvc.FilterInfo..ctor(IEnumerable`1 filters)
at
System.Web.Mvc.ControllerActionInvoker.GetFilters(ControllerContext
controllerContext, ActionDescriptor actionDescriptor)
at
System.Web.Mvc.ControllerActionInvoker.InvokeAction(ControllerContext
controllerContext, String actionName)
at System.Web.Mvc.Controller.ExecuteCore()
at System.Web.Mvc.ControllerBase.Execute(RequestContext
requestContext)
at
System.Web.Mvc.ControllerBase.System.Web.Mvc.IController.Execute(RequestContext
requestContext)
at

System.Web.Mvc.MvcHandler.<>c__DisplayClass6.<>c__DisplayClassb.<BeginProcessRequest>b__5()

at
System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass1.<MakeVoidDelegate>b__0()
at

System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass8`1.<BeginSynchronous>b__7(IAsyncResult
_)

at
System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.End()
at
System.Web.Mvc.MvcHandler.<>c__DisplayClasse.<EndProcessRequest>b__d()
at System.Web.Mvc.SecurityUtil.<GetCallInAppTrustThunk>b__0(Action
f)
at System.Web.Mvc.SecurityUtil.ProcessInApplicationTrust(Action
action)
at System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult
asyncResult)
at
System.Web.Mvc.MvcHandler.System.Web.IHttpAsyncHandler.EndProcessRequest(IAsyncResult
result)
at
System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step,
Boolean& completedSynchronously)
INFO 2011-03-01 09:19:18.0445 [27] NinjectIssue.MvcApplication END
http://localhost:80/


Regards,
Andre

> > System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass1.<MakeVoidDelegat e>b__0()
> >    bei
> > System.Web.Mvc.Async.AsyncResultWrapper.<>c__DisplayClass8`1.<BeginSynchron ous>b__7(IAsyncResult

[a.loker]

A few more findings:

- when the error occurs, it always happens when requesting an IKernel
for injection into the ctor of an IFilterProvider
- the error only seems to occur when multiple implementations are
present and resolved, which is the case for the two IFilterProvider
implementations. If I remove the two filter providers and add only a
single one back I cannot reproduce the error anymore:

Kernel.Unbind<IFilterProvider>();
Kernel.Bind<IFilterProvider>().To<NinjectFilterAttributeFilterProvider>();

See https://github.com/aloker/ninject-issue/tree/test-only-single-implementations

[a.loker]

More findings:

The issue seems to be related to the deferred/lazy evaluation of
KernelBase.Resolve. I cannot reproduce the issue if I either:

- implement a custom IDependencyResolver with a GetServices method
that calls ToList() on the result of IResolutionRoot.Resolve. See
https://github.com/aloker/ninject-issue/blob/test-non-lazy-resolver/NinjectIssue/NonDeferredResolver.cs#L35
- the only change wrt NinjectDependencyResolver is the added .ToList()
in line 35.

- similarly, call ToList() in KernelBase.Resolve() on the result
enumeration, effectively causing the resolution of all implementations
(see patch below). Interestingly, this causes several unit tests to
fail. I don't know whether relying on the laziness of Resolve is
intentional or an error.


diff --git a/src/Ninject/KernelBase.cs b/src/Ninject/KernelBase.cs
index 12e1edb..aac5d91 100644
--- a/src/Ninject/KernelBase.cs
+++ b/src/Ninject/KernelBase.cs
@@ -372,7 +372,7 @@ namespace Ninject
throw new
ActivationException(ExceptionFormatter.CouldNotUniquelyResolveBinding(request));
}

- return bindings.Select(binding =>
this.CreateContext(request, binding)).Select(context =>
context.Resolve());
+ return bindings.Select(binding =>
this.CreateContext(request, binding)).Select(context =>
context.Resolve()).ToList();
}

/// <summary>

[Remo Gloor]

Hi Andre

I can't reproduce the exception myself. Can you please provide the
wcat configuration and an instruction how you run it?

Remo

On Mar 1, 10:42 am, "a.loker" <m...@andreloker.de> wrote:
> More findings:
>
> The issue seems to be related to the deferred/lazy evaluation of
> KernelBase.Resolve. I cannot reproduce the issue if I either:
>
> - implement a custom IDependencyResolver with a GetServices method

> that calls ToList() on the result of IResolutionRoot.Resolve. Seehttps://github.com/aloker/ninject-issue/blob/test-non-lazy-resolver/N...

[a.loker]

Hi Remo,

I uploaded the scripts I use to run wcat and some instructions:
https://github.com/aloker/ninject-issue/tree/master/wcat

BTW, I tested a bit more and I can confirm that with the modified
dependency resolver I cannot reproduce the problem. I justed tested
500 virtual clients in a 120 second stress test, firing 75135 requests
at 600 requests per second. No issues.

Also, the issue does not relate to WebDev server vs. IIS, I ran wcat
against a website on the internet and successfully killed it (one of
my own sites, of course!).

Regards,
Andre

[Remo Gloor]

Hi Andre

I'm still not able to reproduce the issue. Even with a higher client
count (500 and for a long period). What hardware/software
configurations do you have? e.g.
Server: How many cores, CPU speed, Memory? OS? (e.g. 4 Cores + 4
Hyperthreading @3GHz, 4GB Memory) Which server software version. e.g
Dev Server 4.0.30319.206, Or IIS xxx
Test Client: Core count, speed.

Remo

[a.loker]

Hi Remo,

I can reliably reproduce it with any setup I try.

Setup 1:
Server:
my personal development machine
Intel Core2Duo E6750 2 cores @2.67 GHz, no hyper threading
4GB RAM
OS: Windows 7 Professional x64, SP1
Webserver: VS DevServer (4.0.30319.206)
Client:
the same machine, so everything runs locally
=> error occurs reliably in debug and release builds

Setup 2:
Server:
virtual server hosted on a 2x Intel Xeon X5670 @ 2.93 GHz (6 cores
each + hyper threading = 24 hardware threads) machine
physical size of RAM unknown, virtual server has 4 GB RAM assigned
OS: Windows Server 2003 R2 Datacenter x64 SP 2
Webserver: IIS 6
Client:
My local dev machine as described above, connected with 16mbit down/
1mbit upstream ADSL2+
=> error occurs most of the time in debug builds, sometimes in release
builds. I guess I can't push enough requests from my computer to the
server to cause the error reliably

Setup 3:
Server:
Same virtual server as above
Client:
The virtual server, that is: all is running on the server
=> error occurs reliably in debug and release builds

Setup 4:
Server:
Local IIS 7.5.7600.16385 on my dev machine
Client:
Local dev machine
=> error occurs reliably in debug and release builds

Setup 5:
Server:
Another virtual server, hosted on a 2x Xeon E5520 @2.26 GHz (4 cores
each + HT => 16 hardware threads)
1 GB available RAM
WinServer 2003 x64 R2 SP2 again
Client:
Local dev machine
=> error occurs pretty reliably in debug and release mode (the server
is slightly slower)


You see, I can more or less reproduce it anywhere.


Regards,
Andre

On 1 Mrz., 17:20, Remo Gloor <remo.gl...@bbv.ch> wrote:
> Hi Andre
>

[Remo Gloor]

Hi Andy

This is fixed in Ninject.Web.MVC3 2.2.1.0. See
http://www.planetgeek.ch/2011/03/01/ninject-2-2-1-0-and-ninject-mvc3-2-2-1-0-released/
for more information

Thanks for you support.
Remo