Issue using NSubstitute with AutoFixture and parallel tests execution

[MichaelLogutov]

We've been facting strange issues when running tests that invokes multiple tasks (to simulate multithreaded environment). I found that the issue is related to AutoConfiguredNSubstituteCustomization but maybe it has something to do with staticness of the Args. Here is the test:

using System;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using NSubstitute;
using Ploeh.AutoFixture;
using Ploeh.AutoFixture.AutoNSubstitute;
using Xunit;

namespace Bug
{
    public interface IServiceA
    {
        IServiceB GetService();
    }

    public interface IServiceB
    {
    }

    public class Tests
    {
        [Theory]
        [InlineData(32), InlineData(64), InlineData(128), InlineData(256)]
        public Task UsingAutoConfiguredNSubstituteCustomization(int dop)
        {
            // arrange
            var fixture = new Fixture();
            fixture.Customize(new AutoConfiguredNSubstituteCustomization());

            var service = fixture.Freeze<IServiceA>();

            // act, assert
            return TestAsync(dop, service);
        }

        [Theory]
        [InlineData(32), InlineData(64), InlineData(128), InlineData(256)]
        public Task AutoNSubstituteCustomization(int dop)
        {
            // arrange
            var fixture = new Fixture();
            fixture.Customize(new AutoNSubstituteCustomization());

            var service = fixture.Freeze<IServiceA>();

            // act, assert
            return TestAsync(dop, service);
        }

        [Theory]
        [InlineData(32), InlineData(64), InlineData(128), InlineData(256)]
        public Task UsingNSubstitute(int dop)
        {
            // arrange
            var service = Substitute.For<IServiceA>(); // no error

            // act, assert
            return TestAsync(dop, service);
        }

        private static async Task TestAsync(int dop, IServiceA service)
        {
            // arrange
            var start = new SemaphoreSlim(0, dop);
            var cts = new CancellationTokenSource(TimeSpan.FromSeconds(1));

            var tasks = Enumerable
                .Range(0, dop)
                .Select(_ => Task.Run
                                 (async () =>
                                        {
                                            await start.WaitAsync(cts.Token).ConfigureAwait(false);
                                            service.GetService();
                                        },
                                  cts.Token));

            // act
            start.Release(dop);
            await Task.WhenAll(tasks).ConfigureAwait(false);

            // assert
            service.Received(dop).GetService();
        }
    }
}

Only the first test UsingAutoConfiguredNSubstituteCustomization failing randomly like this:

Expected to receive exactly 32 calls matching:
    GetService()
Actually received 39 matching calls:
    GetService()
    GetService()
    ...

[dtchepak]

Hi Michael, Sorry for the late reply.

I'm not sure what is happening here. In case there are calls being made while AutoFixture is configuring the service, can you try adding a "clear calls" to TestAsync?

private static async Task TestAsync(int dop, IServiceA service)
        {
            // arrange
            service.ClearReceivedCalls();   // <-- add this line
            var start = new SemaphoreSlim(0, dop);
        ...

[MichaelLogutov]

Unfortunately that didn't help - still got the same kind of error.

[dtchepak]

I'm not sure what is going on here. If a new instance of IServiceA is passed to TestAsync then I'm not sure how that can ever produce additional calls to GetService (I would be less surprised if a race caused less than dop calls).

You could try getting some info from each call using service.When(x => x.GetService()).Do(logging) where logging is some custom code that outputs the thread id or some other info to help pin down where the extra calls are coming from? It might also be worth checking with the AutoFixture/AutoNSubstitute teams as they might be able to pick out the source of this behaviour straight away.

[MichaelLogutov]

I've logged managed thread id and it does not have any correlation with tests outcome.

I've also recreated the same test but with Moq and it works perfectly:

using System;
using System.Linq;
using System.Threading;
using System.Threading.Tasks;
using Moq;
using Ploeh.AutoFixture;
using Ploeh.AutoFixture.AutoMoq;
using Xunit;

namespace Bug
{
    public class MoqTests
    {
        public interface IServiceA
        {
            IServiceB GetService();
        }

        public interface IServiceB
        {
        }

        [Theory]
        [InlineData(32), InlineData(64), InlineData(128), InlineData(256)]
        public Task UsingAutoConfiguredMoqCustomization(int dop)
        {
            // arrange
            var fixture = new Fixture();
            fixture.Customize(new AutoConfiguredMoqCustomization());

            var service = fixture.Freeze<IServiceA>();

            // act, assert
            return TestAsync(dop, service);
        }

        [Theory]
        [InlineData(32), InlineData(64), InlineData(128), InlineData(256)]
        public Task AutoMoqCustomization(int dop)
        {
            // arrange
            var fixture = new Fixture();
            fixture.Customize(new AutoMoqCustomization());

            var service = fixture.Freeze<IServiceA>();

            // act, assert
            return TestAsync(dop, service);
        }

        [Theory]
        [InlineData(32), InlineData(64), InlineData(128), InlineData(256)]
        public Task UsingMoq(int dop)
        {
            // arrange
            var service = new Mock<IServiceA>();

            // act, assert
            return TestAsync(dop, service.Object);
        }

        private static async Task TestAsync(int dop, IServiceA service)
        {
            // arrange
            var start = new SemaphoreSlim(0, dop);
            var cts = new CancellationTokenSource(TimeSpan.FromSeconds(1));

            var tasks = Enumerable
                .Range(0, dop)
                .Select(_ => Task.Run
                                 (async () =>
                                        {
                                            await start.WaitAsync(cts.Token).ConfigureAwait(false);
                                            service.GetService();
                                        },
                                  cts.Token));

            // act
            start.Release(dop);
            await Task.WhenAll(tasks).ConfigureAwait(false);

            // assert
            Mock.Get(service).Verify(x => x.GetService(), Times.Exactly(dop));
        }
    }
}

[dtchepak]

I tried adding some diagnostic code (not sure how reasonable this is):

    public interface IServiceA
    {
        IServiceB GetService (long i);
    }

    public interface IServiceB {}

    public class Tests
    {
        [Theory]
        [InlineData (5)] //, InlineData (64), InlineData (128), InlineData (256)]
        public Task UsingAutoConfiguredNSubstituteCustomization (int dop)
        {
            // arrange
            var fixture = new Fixture ();
            fixture.Customize (new AutoConfiguredNSubstituteCustomization ());

            var service = fixture.Freeze<IServiceA> ();

            // act, assert
            return TestAsync (dop, service, "UsingAutoConfiguredNSubstituteCustomization");
        }

        private static async Task TestAsync (int dop, IServiceA service, string caller)
        {
            // arrange
            var start = new SemaphoreSlim (0, dop);
            var cts = new CancellationTokenSource (TimeSpan.FromSeconds (1));
            long i = 0;

            var tasks = Enumerable
                .Range (0, dop)
                .Select (_ => Task.Run
                                  (async () => {
                                      var ii = Interlocked.Increment(ref i);
                                      Console.WriteLine("Task: " + ii);
                                      await start.WaitAsync (cts.Token).ConfigureAwait (false);
                                      service.GetService (ii);
                                  },
                                   cts.Token));

            // act
            start.Release (dop);
            await Task.WhenAll (tasks).ConfigureAwait (false);

            // assert
            service.Received (dop).GetService (Arg.Any<long>());
        }

And get the following output:

xUnit.net Console Runner (32-bit .NET 4.0.30319.42000)
  Discovering: NSubTest
  Discovered:  NSubTest
  Starting:    NSubTest
Task: 3
Task: 1
Task: 4
Task: 2
Task: 5
    Bug.Tests.UsingAutoConfiguredNSubstituteCustomization(dop: 5) [FAIL]
      NSubstitute.Exceptions.ReceivedCallsException : Expected to receive exactly 5 calls matching:
        GetService(any Int64)
      Actually received 19 matching calls:
        GetService(5)
        GetService(3)
        GetService(1)
        GetService(2)
        GetService(5)
        GetService(3)
        GetService(4)
        GetService(3)
        GetService(5)
        GetService(3)
        GetService(4)
        GetService(3)
        GetService(5)
        GetService(3)
        GetService(3)
        GetService(5)
        GetService(3)
        GetService(5)
        GetService(5)

I'm not familiar with AutoFixture/AutoNSubstitute -- what do AutoConfiguredNSubstituteCustomization and Freeze do? The substitute seems configured to call GetService multiple times for each call originating from the .Select block, but I'm not aware of a way NSubstitute could initiate this behaviour itself (which is supported by the other tests which don't use AutoConfiguredNSubstituteCustomization but which work ok).

[MichaelLogutov]

It makes that all returned values from created object's properties and methods to be created using the fixture and thus can be substituted automatically. It the main feature we're using it.

[dtchepak]

From what I can see this looks like an AutoConfiguredNSubstituteCustomization bug in AutoFixture.AutoNSubstitute. Is there anything I'm overlooking that points to it being in NSubstitute instead?

[MichaelLogutov]

You're probably right but its strange that quite similar implementation of the customization for Moq working correctly.

[dtchepak]

Yes I had a look at the Moq and NSub customisations but I don't know enough about AutoFixture to understand what could be causing the different behaviours.

[dtchepak]

Closing as part of a general cleanup of blocked issues. Please re-open if more information comes to light which will let us proceed with this.