Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Intermittent AmbiguousArgumentsException when running tests in parallel #260

Closed
luciobemquerer opened this issue Nov 16, 2016 · 29 comments
Closed

Comments

@luciobemquerer
Copy link

luciobemquerer commented Nov 16, 2016

We have a set of 1.5k xUnit tests which heavily rely NSubstitute. When running all tests, xUnit executes tests in parallel, and we are frequently having a random one or two of them failing intermittently. If we run the tests separately, they succeed every time.

Tests runs don't fail every time, and it don't always fail with the same tests, but some tests are frequently failing for a time. When we add or remove tests from the code base, or when we try to fix the tests that are failing, usually the problem moves around, and start showing up in a different test.

Bottom line, the issue fluctuates randomly around our test base, and we could not confidently reproduce it, or identify the cause. We are using AutofacContrib.NSubstitute.AutoSubstitute to resolve dependencies.

One particular line that is failing often recently is the second one here:

_searchGrainIndexer = TestSubst.Resolve<ISearchProxyGrain>();
TestSubst.Resolve<IGrainFactory>().GetGrain<ISearchProxyGrain>(Arg.Any<long>()).ReturnsForAnyArgs(_searchGrainIndexer);

The exception we receive is:

NSubstitute.Exceptions.AmbiguousArgumentsException : Cannot determine argument specifications to use.
Please use specifications for all arguments of the same type.
Stack Trace:
     at NSubstitute.Core.Arguments.NonParamsArgumentSpecificationFactory.Create(Object argument, IParameterInfo parameterInfo, ISuppliedArgumentSpecifications suppliedArgumentSpecifications)
     at System.Linq.Enumerable.<SelectIterator>d__5`2.MoveNext()
     at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
     at NSubstitute.Core.Arguments.MixedArgumentSpecificationsFactory.Create(IList`1 argumentSpecs, Object[] arguments, IParameterInfo[] parameterInfos)
     at NSubstitute.Core.Arguments.ArgumentSpecificationsFactory.Create(IList`1 argumentSpecs, Object[] arguments, IParameterInfo[] parameterInfos, MatchArgs matchArgs)
     at NSubstitute.Core.CallSpecificationFactory.CreateFrom(ICall call, MatchArgs matchArgs)
     at NSubstitute.Routing.Handlers.RecordCallSpecificationHandler.Handle(ICall call)
     at System.Linq.Enumerable.WhereSelectArrayIterator`2.MoveNext()
     at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source, Func`2 predicate)
     at NSubstitute.Routing.Route.Handle(ICall call)
     at NSubstitute.Proxies.CastleDynamicProxy.CastleForwardingInterceptor.Intercept(IInvocation invocation)
     at Castle.DynamicProxy.AbstractInvocation.Proceed()
     at Castle.Proxies.IGrainFactoryProxy.GetGrain[TGrainInterface](Int64 primaryKey, String grainClassNamePrefix)
     at DBCloud.UnitTests.Controllers.SearchControllerTests..ctor()

The signature of the GetGrain() method (from Microsoft.Orleans) is:
public TGrainInterface GetGrain<TGrainInterface>(long primaryKey, string grainClassNamePrefix = null) where TGrainInterface: IGrainWithIntegerKey

@dtchepak
Copy link
Member

Thanks for this report.

I'm not sure what's happening here. Argument specs are queued and retrieved using threadlocal storage, so I'm not entirely sure the threading is the problem. If you run it single-threaded do you sometimes get the issue? I have a suspicion that there is a test that is queuing up an arg matcher that under certain orderings is causing this problem. (Does xunit randomise the order of tests? It might be worth checking which test precedes the broken one in a test runner log.)

@luciobemquerer
Copy link
Author

luciobemquerer commented Nov 17, 2016

Thank you for the attention.

  1. Yes, xUnit does randomize the execution order of the tests, which I believe is the reason why it is hard for us to identify the cause.
  2. So far, running test without parallelism have not caused the exception (but is slow).
  3. I started to keep logs of the order that tests start and end, start and end time, and the thread in which tests start and end. It is clear that tests begin and end on the same thread and also that a single thread executes only one test at a time.
  4. I'm not sure whether a test could be partially running in a different thread due to an async/await call. We have plenty of async/await calls in our tests. If an async call is executed in a different thread, would it cause an issue with NSubstitute?
  5. If a test was able to accidentally access the thread of another test, could it cause the behavior described above?
  6. Also, looking at the tests, its is clear that multiple tests run in parallel, and that many of them use the Arg.Any() method, many times with the same type T.
  7. In the logs, so far, I could not see any pattern on the tests that preceded the failing test.

Thanks,

@dtchepak
Copy link
Member

For 5 I think the answer is "yes". For 4 I think it should be ok unless async code is accessing the substitute at the same time as another thread is trying to configure it or assert on it (see #256 for example).

For a call like sub.GetFoo(Arg.Any<int>()).Returns(foo) we get the following:

  1. Arg.Any<int>() runs, pushing an arg matcher on to a collection that is global for a single thread (threadlocal storage).
  2. GetFoo runs, which records the call on the sub substitute, and also stores which substitute was last called (more accurately, CallRouter) in thread local storage.
  3. .Returns(foo) runs, which looks up the last substitute called and the queued up arg matchers from threadlocal storage, then asks that substitute to configure its last recorded call (GetFoo) to return foo.

All the above steps should take place on a single thread, as they rely on threadlocal storage. Other threads running at the same time and configuring other substitutes should (as far as I can tell) be ok.

It does mean there could be a problem if substitute instances are shared between threads. If a substitute is being configured/asserted on at the same time as production code (or other test code) is accessing the substitute then step 3 might look up the last recorded call, and find DoBar instead of GetFoo (if another thread called DoBar between step 2 and 3). I'm pretty sure this could cause the symptoms you're experiencing. (I'm not sure how TestSubst.Resolve works with regard to sharing instances?)

Another thing to check is anywhere you are substituting for classes. If you have accidentally used an arg matcher with a non-virtual method that can cause these problems.


As an aside, you don't need to use Arg.Any if you are already using ReturnsForAnyArgs:

x.GetGrain<ISearchProxyGrain>(0).ReturnsForAnyArgs(_searchGrainIndexer);

This won't help cases where you need a mix of Arg.Any and Arg.Is, but should eliminate one potential source of these errors (mismatch between the arg matcher collection and the call being made).


Finally, I'm really sorry for the troubles you are experiencing here. These are terrible cases to debug. 😞

@zvirja
Copy link
Contributor

zvirja commented Nov 17, 2016

@dtchepak BTW, isn't that something that NSubstitute should handle? Of course, it might be out of scope that we setup fixture and use it concurrently (it's supposed that it's configured and then is used). However, given the fact that we heavily rely on previous call information, shouldn't we ensure that NSubstitute doesn't fail for such scenario?

My concern is that if we have solution with 2k tests, it might be a nightmare to find exact place where you configure and use substitute concurrently (and sometimes even not possible to avoid that, if it's used in constructor e.g.).

I could try to fix that by storing a copy of "last call information" in thread local storage, rather than rely on shared state. Of course, we should be veeeery careful to not break anything, but as far as I can see, not too much places should be adjusted. I'm interested in this because in our project we also use xUnit and I also saw concurrency issues. I want NSubstitute to be multi-threading resistant as much as possible.

P.S. It would be a cool change for v 2.0 😉

@dtchepak
Copy link
Member

@zvirja Happy to give it a try. :) I've got a few thousand tests I can try it out on to test for regressions. :)

Btw, we don't need to rush things out for a particular release. I'm happy to release whenever a new feature hits (with a little delay to let me test out the version on a few test suites.)

@zvirja
Copy link
Contributor

zvirja commented Nov 17, 2016

@dtchepak The reason why I want that for 2.0 is that it might bring some potential breaking changes, so it would be much expected. But I hope to avoid them :)

@luciobemquerer
Copy link
Author

@dtchepak @zvirja Thank you very much for your comments, guys. It would be awesome to have it fixed for a future release. I don't feel confident to make changes to NSubstitute myself for now, but I'll be glad to run my current tests on top of a beta version to help testing.

Even though it seems like a problem I cannot fix myself , your comments will certainly help me take measures to avoid the problem. For example, removing unnecessary Args from the test base greatly reduced the frequency of failures already.

A simple measure that would help a lot in detecting the issue would be to provide more info in the AmbiguousArgumentsException of what Args were being matched to which method, and why is it ambiguous.

If we had a log of the stack built into the thread storage it would also be helpful to track down the source of the problem. I don't know, however, how much impact that could have in performance.

@dtchepak
Copy link
Member

dtchepak commented Nov 19, 2016

@luciobemquerer: I like the idea of adding more info to the AmbiguousArgumentsException. Is that info already in the callstack when the exception gets thrown though? (first non-NSubstitute line?) Even so, it would still be more convenient to but that info in the message though.

Added #262 to track this.

@zvirja
Copy link
Contributor

zvirja commented Nov 22, 2016

P.S. Reply is a "long-read", but please read it and try the suggested diagnostics.

I've thought more about this and wasn't able to imagine the scenario how that could happen due to concurrency WITH valid usage. Specs are pushed to thread local storage, therefore other threads would not affect that. Also, this issue happens before the ReturnsForAnyArgs is invoked, so that isn't something about "memory" about the last call.

Now let's analyze the signature:

TGrainInterface GetGrain<TGrainInterface>(long primaryKey, string grainClassNamePrefix = null) 

Issue cannot happen for the grainClassNamePrefix argument, because this parameter is optional and NSubstitute could never throw such an exception for it. Therefore, issue could happen only for the first parameter - primaryKey. Given your code and how you use it, the lines itself cannot cause the issue - no matter in how many threads this code is executed. However, the following code will fail:

Arg.Any<string>();
factory.GetGrain<IValueSource>(Arg.Any<long>()).ReturnsForAnyArgs(valueSource);

You might note, if there is any specification is present in the queue before current invocation and it isn't for long type, you will get the issue. (BTW, @dtchepak, shouldn't we fast fail here if we have more specifications than arguments?)

Likely, happened something @dtchepak mentioned above:

Another thing to check is anywhere you are substituting for classes. If you have accidentally used an arg matcher with a non-virtual method that can cause these problems.

I would imagine that something like following happens:
Thread code before:

subs.NonVirtualMethod(Arg.Any<non-long-type>());

Thread code now:

factory.GetGrain<IValueSource>(Arg.Any<long>()).ReturnsForAnyArgs(valueSource);

In this case thread still "remember" previous specification queued and we cannot fix that somehow.
Even if we introduce extended exception message by issue #262, that might not help much - it might be still unclear who pushed that spec :(

I'm currently working on improving NSubstitute for concurrency, so it would be useful to investigate why that happens. To do that I would like to ask you to run the diagnostics code and provide us with issue root cause.

Steps:

  1. Add DiagnosticsSubstitutionContext to your test project.
  2. Modify the class and add logging (or put breakpoint and execute tests in debug) here.
  3. Ensure that DiagnosticsSubstitutionContext.Init(); method in invoked at least one time before all tests execution, so that hook is installed. E.g. add it to static constructor for TestSubst class or add module initializer to the test project.
  4. Reproduce the issue.
  5. Analyze the captured diagnostics info. You should be able to see exact place that queued wrong specification in the captured stack traces.

Let us know whether that was a mistake in your code our whether this is NSubstitute issue.

Thank you a lot for your efforts! :)

@dtchepak
Copy link
Member

@zvirja: yes i think it should fail fast there.

As an aside, I've always wanted to completely rip out the arg matching stuff and replace it with something that evaluates all the possible combinations and throws if there is more than one. (I don't think it would be any slower than the current implementation.) Never got around to it though because the current one works so not sure it is worth the time.

@luciobemquerer
Copy link
Author

luciobemquerer commented Nov 28, 2016

@zvirja, thanks a lot for the attention. I managed to reproduce the error while using the diagnostic tool you suggested. I'm outputting logs to a file with the following implementation:

if (args.Exception is AmbiguousArgumentsException)
{
	var lastList = LastDequeuedList;
	var enqueueInfo = lastList.Select(x => new
	{
		Spec = x,
		Stack = CreationStacks[x]
	}).ToArray();

	Trace.WriteLine(args.Exception.ToString());
	foreach (var x in enqueueInfo)
	{
		Trace.WriteLine($"Spec.ForType: {x.Spec.ForType}");
		Trace.WriteLine($"Spec: {x.Spec}");
		Trace.WriteLine($"Stack: {x.Stack}");
	}
}

I captured the same error two times.

EXAMPLE 1
Logs:

NSubstitute.Exceptions.AmbiguousArgumentsException: Cannot determine argument specifications to use.
Please use specifications for all arguments of the same type.
   at NSubstitute.Core.Arguments.NonParamsArgumentSpecificationFactory.Create(Object argument, IParameterInfo parameterInfo, ISuppliedArgumentSpecifications suppliedArgumentSpecifications)
Spec.ForType: DBCloud.ActorInterfaces.Tags.TagSuggestQuery
Spec: any TagSuggestQuery
Stack:  [...]  at DBCloud.UnitTests.Controllers.TagControllerTests.<GetTags_WhenBadData_ThenThrows>d__19.MoveNext() [...]

Spec.ForType: System.Int64
Spec: any Int64
Stack:  [...]  at DBCloud.UnitTests.Controllers.SearchControllerTests..ctor() in  [...]

The line where the exception is thrown is the same I mentioned in the opening of this issue.

TestSubst.Resolve<IGrainFactory>().GetGrain<ISearchProxyGrain>(Arg.Any<long>()).ReturnsForAnyArgs(_searchGrainIndexer);

Obviously, the Int64 matcher is the Arg.Any<long>() that is being requested in the line above.

The TagSuggestQuery matcher is coming from another test, called GetTags_WhenBadData_ThenThrows, and the line that is enqueueing this matcher is the following:

_tagProxyGrain.DidNotReceiveWithAnyArgs().ExecuteQuery(Arg.Any<TagSuggestQuery>()).FixAwaitProblem();

In the line above, _tagProxyGrain is the substitute of the ITagProxyGrain interface. FixAwaitProblem() is a legacy method that was being used to suppress Visual Studio warnings of non-awaited tasks, as recommended in this post. The implementation of FixAwaitProblem() is as follows:

public static void FixAwaitProblem(this Task task) { }

The signature of ExecuteQuery is:

Task<GrainQueryBase> ExecuteQuery(GrainQueryBase query);

EXAMPLE 2
Logs:

NSubstitute.Exceptions.AmbiguousArgumentsException: Cannot determine argument specifications to use.
Please use specifications for all arguments of the same type.
   at NSubstitute.Core.Arguments.NonParamsArgumentSpecificationFactory.Create(Object argument, IParameterInfo parameterInfo, ISuppliedArgumentSpecifications suppliedArgumentSpecifications)
Spec.ForType: DBCloud.ActorInterfaces.Notifications.NotificationListQuery
Spec: any NotificationListQuery
Stack:  [...]   at DBCloud.UnitTests.Controllers.NotificationControllerTests.<GetCurrentNotificationSettings_WhenCalled_ThenCallsReceiveRequest>d__10.MoveNext() in  [...]

Spec.ForType: System.Int64
Spec: any Int64
Stack:  [...]  at DBCloud.UnitTests.Controllers.SearchControllerTests..ctor() in  [...]

Exception is thrown is the same line as the previous example, and the Int64 matcher is the Arg.Any<long>() that is requested on that line.

The NotificationListQuery matcher is coming from another test, called GetCurrentNotificationSettings_WhenCalled_ThenCallsReceiveRequest, and the line that is enqueueing this matcher is the following:

_INotificationsProxyGrain.Received(1).Query(Arg.Any<NotificationListQuery>()).FixAwaitProblem();

In the line above, _INotificationsProxyGrain is the substitute of the INotificationsProxyGrain interface.

The signature of ExecuteQuery is the same as above:

Task<GrainQueryBase> ExecuteQuery(GrainQueryBase query);

CONCLUSION

  1. It is clear that argument matchers from one test are spilling over to another test, and causing the problem.

  2. Although the usage of NSubstitute methods above is not ideal (that is, not following recommended practices), it seems to me that both cases are valid use cases. Particularly, the second one seems quite correct to me.

  3. I'm aware that to work around the problem all I need to do is replace the Arg.Any() matcher by a default(T).

I hope this information help you guys to identify the problem. Please let me know if you need more info.

@zvirja
Copy link
Contributor

zvirja commented Nov 28, 2016

@luciobemquerer HUGE thanks for your try and for such a verbose reply!
To be honest, I'm totally frustrated by your answer. I don't see any potential way how that could happen. The only way I can imagine that it is to assume that you identified places wrongly or that are not real substitutes - it's always to simpler to believe in human mistake than to become crazy :) But I trust you, of course, and likely we are just missing something >_>

Therefore, I would like you to give it another try.

  1. Please triple check that you identified places which enqueues specifications correctly (it would be very pity if it appears later that places are different).

  2. Provide me with signature for the following method from Example 2 (you specified signature for the ExecuteQuery method instead):
    _INotificationsProxyGrain.Received(1).Query(Arg.Any<NotificationListQuery>()).FixAwaitProblem();

  3. Ensure that you execute diagnostics initialization before any potential test execution. Use module initializer approach if you didn't follow it before. We should exclude any potential code which could sneak out of our diagnostics.

  4. Do you build tests in Debug or Release mode?

Also, I would like to ask you to repeat your test session again using the updated diagnostics. I've extended logging, so please log all the properties.

If that might be possible, please provide me with listings for both tests (failing and enqueuing ones). It could happen that some important detail eludes us. However, if that is not possible - provide us with results like you did in your previous reply.

Thank you in advance. In the meanwhile I'll continue to think about that and imagine how that could happen...

@luciobemquerer
Copy link
Author

luciobemquerer commented Nov 29, 2016

@zvirja I believe I finally spotted the problem. The item 2 in your previous response called my attention to it, because the method being called was Query(), instead of ExecuteQuery(). The first one is static extension method that wraps around the second one to validate the input query parameter, and cast the result to a strongly typed object. It is the combination of this with the FixAwaitProblem() method that caused the issue.

Consider the following code:

_INotificationsProxyGrain.Received(1).Query(Arg.Any<NotificationListQuery>()).FixAwaitProblem();

The problem happens like this:

  1. The Received() method is called and returns the proxy? that will test for received calls.
  2. Query() is called with the parameter Arg.Any<TQuery>(), causing the argument matcher to be pushed to the threadlocal queue.
  3. The Query() method validates the parameter, which is null (default(TQuery)), and throws an exception.
  4. The ExecuteQuery() method (which belongs to the substitute) is never called inside Query(), therefore, the argument matcher is abandoned in the queue.
  5. The exception is captured in the Task context.
  6. The Task context is passed into the FixAwaitProblem() method, and is discarded, without throwing the exception.
  7. The test succeeds, because no exception is thrown.
  8. The thread ends the test, and is assigned to execute another test.
  9. As soon as a method reads argument matchers in the threadlocal queue, the abandoned argument matcher is retrieved, and the AmbiguousArgumentsException is thrown.

The code bellow will reproduce the error consistently:

using System;
using System.Threading.Tasks;
using NSubstitute;
using Xunit;

namespace DBCloud.ActorTests.Projects
{
	public class SubstituteErrorRepro
	{
		[Fact]
		public async Task Test_01()
		{
			var substitute = Substitute.For<ISomeInterface>();
			substitute.ExecuteQuery(default(object)).Returns(Task.FromResult("Hi!"));
			await substitute.ExecuteQuery("Hey!");
			var task = substitute.Received().Query(Arg.Any<object>());
		}

		[Fact]
		public async Task Test_02()
		{
			var substitute = Substitute.For<ISomeInterface>();
			substitute.OtherMethod(Arg.Any<long>()).Returns(Task.FromResult("Hi!"));
			await substitute.ExecuteQuery("Hey!");
		}
	}

	public interface ISomeInterface
	{
		Task ExecuteQuery(object query);
		Task OtherMethod(long value);
	}

	public static class InterfaceExtension
	{
		public static Task Query(this ISomeInterface target, object query)
		{
			if (query == null)
			{
				return Task.FromException(new ArgumentNullException());
			}
			return target.ExecuteQuery(query);
		}
	}
}

In conclusion:

  1. First of all, I want to thank you very much for all the help and support. I wouldn't be able to identify this problem without the insights and tools you provided.
  2. The problem was, in fact, related to improper usage of NSubstitute. My apologies for that, because the test base was developed by many hands, using different approaches and practices along the way.
  3. That said, it requires a deep understanding of the internals of NSubstitute to track down the source of the symptoms, which cannot be expected from every developer consuming the library.
  4. Some suggestions that would allow these situations to be more easily avoided/diagnosed:
  • provide information on AmbiguousArgumentsException on the arguments being matched.
  • provide a method to allow cleaning up data in the ThreadStorage in the initialization of each test (possibly throwing exceptions if anything is left there).
  • use an instance class, instead of ThreadStorage, to store argument matchers during test execution, allowing developers to control the lifetime of the storage (and causing it to be disposed in the end of each test). I know there is performance consequences on adopting this approach, but then it would be a decision of the developer to use or not a shared storage instance across multiple tests.

Once more, thank you very much for all the support. Please let me know if you need more info.

@dtchepak
Copy link
Member

The problem was, in fact, related to improper usage of NSubstitute. My apologies for that...

Please don't apologise. It's NSubstitute's job to make your life easier, this is one area where it has definitely failed you. Sorry for the hassle it's caused. And thanks for going to the effort to collect information for us and for posting the source of the problem. @zvirja, thanks so much for your efforts with this task too!

@zvirja
Copy link
Contributor

zvirja commented Nov 29, 2016

@luciobemquerer Cool, so happy to figure out the root cause of the issue. I wasn't able to stop thinking about this, because it was really curious issue ;) Now I can have a rest 😫

I'd like to thank you for your involvement and for the job you did from your side. It would be just one more unresolved issue without your investigation! I suspected that it's something task related (because they were present in both cases), but the whole picture appeared to be a combination of a few places. Really interesting case :)

As for the solution here, it becomes complicated. I don't see how we could avoid it gracefully. When we call Arg.Any<>, we knows nothing about context so the static context is the only place we could put information to. Otherwise, API wouldn't be such clear if we start to use some context (at least, we'll need to pass it for each time). And the current API is the killer-feature why we prefer NSubstitute over Moq (e.g.).

provide a method to allow cleaning up data in the ThreadStorage in the initialization of each test (possibly throwing exceptions if anything is left there).

There is such an API currently. Just call SubstitutionContext.Current.DequeueAllArgumentSpecifications() and if result is not empty - that indicates about leaked specifications. But this issue is so specific that it might doesn't worth it to put a guards against it.

What we could really do, is the following:

  1. As it was mentioned above, add more information to exception about current specs.
  2. Fail during call dispatch if queue contains more arguments than number of parameters. That would be a fast fail and it's really better than fail in some unpredictable place.
    Alternatively, add some "smart behavior" to specification matching and try skip all non-matching specifications at the beginning. But that might be tricky and even impossible given the variety of potential cases.
  3. Add support for some "strict mode" for SubstitutionContext which will fail each time it finds leaked specifications. I mean ClearUnusedCallSpecHandler, which could fail if it finds unused specs. But again it's unclear whether false positive could happen there.
    This feature will not allow us to detect current issue thought if there are no subsequent calls.

Thank you all for this collaboration 😉

@dtchepak
Copy link
Member

Hi @luciobemquerer,
@zvirja's efforts to improve thread safety are in the latest release 2.0.1-rc. Hope these changes help! (If not, please re-open this.)

#262 is still open to improve the message for this case.

@cbp123
Copy link

cbp123 commented Apr 20, 2018

Hi, I am receiving a similar issue using v3.1.0.
Running a lot of xUnit tests in parallel results in arguments "jumping across" into the wrong call.

For example, I may have a substitution that looks like this:
fooFactory.Get(Arg.Any<string>()) .Returns(foo);

But I receive an AmbiguousArgumentsException thrown from within NonParamsArgumentSpecificationFactory.

I've downloaded the source for 3.1.0 and attached the debugger inside NonParamsArgumentSpecificationFactory. What I noticed is that when the AmbiguousArgumentsException is thrown, suppliedArgumentSpecifications contains an extra argument that has appeared out of nowhere. The behaviour is random, and the argument could be anything. It has obviously leaked across from another test.

@dtchepak
Copy link
Member

@cbp123 The arg matchers are threadlocal, so it could be added by whatever test is run previously on that thread. Is it possible to log/find out what test is being run on that same thread immediately prior to this one? My suspicion is that an arg matcher is added to a non-virtual call or not as part of a call specification in another test, and that depending on execution order it sometimes will cause a problem.

If you are able to try the current repository head it has some improved detection for these cases that may make it easier to track down. (Otherwise it will be in v4.0)

@krilbe
Copy link

krilbe commented Sep 17, 2018

Hi, I have a similar problem, I think, but I'm a real novice, so might just be doing things thw wrong way.

I consistently receive the ambiguity exception when running these two tests (located in separate test classes:

public void SkaparRegexsubstitutionMedRättArgument()
{
    string regex = @"\d+";
    string ersättMed = "NNN";
    XElement elt = new XElement("ersätt");
    elt.SetAttributeValue("regex", regex);
    elt.SetAttributeValue("med", ersättMed);
    var fabrik = Substitute.ForPartsOf<Substitutionsfabrik>();
    fabrik.SkapaSubstitution(elt);
    fabrik.Received(1).SkapaRegexsubstitution(elt);
    fabrik.Received(1).SkapaRegexsubstitution(Arg.Is<Regex>(r => r.ToString() == regex), ersättMed);
}

[TestMethod]
public void SkaparKolumnspecarna()
{
    XDocument dok = new XDocument(new XElement("kolumner"));
    dok.Root.Add(new XElement("kolumn"));
    dok.Root.Add(new XElement("kolumn"));
    dok.Root.Add(new XElement("kolumn"));
    dok.Root.Add(new XElement("kolumn"));
    dok.Root.Add(new XElement("kolumn"));
    dok.Root.Add(new XElement("kolumn"));
    var kolspecfabrikMock = Substitute.For<IKolumnspecfabrik>();
    var kolspec = new Kolumnspec(new XElement("kolumn"), null, null);
    // Exception on next line.
    kolspecfabrikMock.SkapaKolumnspec(Arg.Any<XElement>()).Returns(kolspec);
    Konfigläsare läsare = new Konfigläsare(kolspecfabrikMock);
    läsare.LäsFrånXML(dok);
    kolspecfabrikMock.Received(dok.Root.Elements().Count()).SkapaKolumnspec(Arg.Any<XElement>());
}

It's the second test that throws the exception at the indicated point.

For the first test, Substitutionsfabrik is a concrete class, the one I'm trying to test. The test is intended to track that the method public Substitution SkapaSubstitution(XElement elt) calls the two other (overloaded) methods SkapaRegexsubstitution(...). This test always succeeds.

For the second test, the class I want to test is Konfigläsare, and its method LäsFrånXML. In particular, I want to see that it calls IKolumnspecfabrik.SkapaKolumnspec(...) once for each "kolumn" XML element. The mocked SkapaKolumnspec(...) method needs to return an object, not null, because it is added to a list. Null would throw an exception. But it's fine if the same object is returned every time, so I create an object kolspec to be returned by the mock on every call.

The second test succeeds if I run it by itself or in combination with all other tests in the solution, but fails as soon as the first test is also included in the same test run.

AM I doing something inappropriate in any of these tests? How can I change the tests to avoid the problem?

@dtchepak
Copy link
Member

dtchepak commented Sep 17, 2018

Hi @krilbe,

Please ensure the SkapaRegexsubstitution methods are virtual. NSubstitute can only work with virtual methods for classes and this may be causing the problem with the second test.

If you install NSubstitute.Analyzers.CSharp into your test project it will help pick up cases likes this that can cause problems for NSubstitute. The Analyzers are still in beta so appreciate any feedback you can provide.

Please let me know if that helps. I'm happy to look into this further if it is still not working for you!

@krilbe
Copy link

krilbe commented Sep 18, 2018

Thanks! Installed it and it shows the following messages.

bild

The interface and class ISubstitutionsfabrik and Substitutionsfabrik : ISubstitutionsfabrik are internal, but I already have [assembly: InternalsVisibleTo("DynamicProxyGenAssembly2")] in AssemblyInfo.cs of the tested assembly. The methods SkapaSträngsubstitution(XElement elt) and SkapaRegexsubstitution(XElement elt) are both interface members, which should work.

Please notice the exception from the analyzer, code AD0001, at the first message line.

I can't really see anything wrong with my code so far.

@krilbe
Copy link

krilbe commented Sep 18, 2018

This is the complete code for ISubstitutionsfabrik and Substitutionsfabrik:

internal interface ISubstitutionsfabrik
{
    Strängsubstitution SkapaSträngsubstitution(string sökvärde, string ersättMed);
    Regexsubstitution SkapaRegexsubstitution(Regex regex, string ersättMed);
    Strängsubstitution SkapaSträngsubstitution(XElement elt);
    Regexsubstitution SkapaRegexsubstitution(XElement elt);
    Substitution SkapaSubstitution(XElement elt);
}

internal class Substitutionsfabrik : ISubstitutionsfabrik
{
    public Strängsubstitution SkapaSträngsubstitution(string sökvärde, string ersättMed)
    {
        return new Strängsubstitution(sökvärde, ersättMed);
    }

    public Regexsubstitution SkapaRegexsubstitution(Regex regex, string ersättMed)
    {
        return new Regexsubstitution(regex, ersättMed);
    }

    public Strängsubstitution SkapaSträngsubstitution(XElement elt)
    {
        if (string.IsNullOrEmpty(elt.Attribute("sökvärde").Value))
            throw new ArgumentException($"Strängsubstitution kräver att attributet \"sökvärde\" är ifyllt (inte tom sträng).");
        if (elt.Attribute("med") == null)
            throw new ArgumentException($"Substitution kräver attributet \"med\" (men det får vara tomt).");
        return SkapaSträngsubstitution(elt.Attribute("sökvärde").Value, elt.Attribute("med").Value);
    }

    public Regexsubstitution SkapaRegexsubstitution(XElement elt)
    {
        if (string.IsNullOrEmpty(elt.Attribute("regex").Value))
            throw new ArgumentException($"Regexsubstitution kräver att attributet \"sökvärde\" är ifyllt (inte tom sträng).");
        if (elt.Attribute("med") == null)
            throw new ArgumentException($"Substitution kräver attributet \"med\" (men det får vara tomt).");
        Regex regex = new Regex(elt.Attribute("regex").Value);
        return new Regexsubstitution(regex, elt.Attribute("med").Value);
    }

    public Substitution SkapaSubstitution(XElement elt)
    {
        if (elt.Name != "ersätt")
            throw new ArgumentException($"Hittade underelement av okänd typ \"{elt}\".");
        if (elt.Attribute("sökvärde") != null)
            return SkapaSträngsubstitution(elt);
        if (elt.Attribute("regex") != null)
            return SkapaRegexsubstitution(elt);
        throw new ArgumentException($"Verkar inte vara ett giltigt ersätt-element: {elt.ToString(SaveOptions.DisableFormatting)}");
    }
}

@dtchepak
Copy link
Member

dtchepak commented Sep 18, 2018

Thanks @krilbe.
The SkapaRegexsubstitution method is on the interface, but the substitute is for the Substitutionsfabrik class (not the ISubstitutionsfabrik interface), and that class does not declare these as virtual. You can see this in the last messages of the Analyzer output. (If you'd like more explanation about why this is necessary please let me know.)

@tpodolak, do you have any guesses about the exception @krilbe found in this comment? I'm also wondering if I need to update the messaging about "interface members" in the analyzers and in the docs as I think that has caused confusion in this case. 🤔 (cc: @zvirja )

@krilbe
Copy link

krilbe commented Sep 18, 2018

Thanks! That solved the problem. Now I just have to decide if testability is worth making the methods virtual, which is not otherwise required.

I also wonder why the warnings about internal type are there, considering I do have [assembly: InternalsVisibleTo("DynamicProxyGenAssembly2")] in AssemblyInfo.cs. Analyzer unable to detect that it's there?

Also, the exception remains.

@dtchepak
Copy link
Member

dtchepak commented Sep 18, 2018

In terms of avoiding putting virtual everywhere, it might be easier to avoid mocking entirely here and instead test the required behaviour? Alternatively you could consider splitting out the SkapaRegexsubstitution code into a separate dependency which might make it easier to switch out that behaviour (for testing or extension), at the price of a bit more complexity.

I'm not sure why InternalsVisibleTo is not being picked up by the Analyzer (@tpodolak: I didn't notice this in the previous comment. Do you know what could be causing this?)

It is possible to manually suppress this message:

  • create an nsubstitute.json file in the test project
  • set its Build Action to additional analyzer file (as per this comment)
  • You can then use a Quick Fix to suppress this error in nsubstitute.json as shown here.

The manual step of creating the file is unfortunately necessary due to a Roslyn bug.

We'll look into that and the exception. Thanks for the feedback!

@krilbe
Copy link

krilbe commented Sep 18, 2018

Thanks! Good work and very nice with the quick action! :-)

The entire class is already "factored out" for testability, i.e. enabling DI for creation of instances, so yet another such step isn't 100 % appealing. :-) Anyway, I'll evaluate my options again and then decide.

@tpodolak
Copy link
Member

tpodolak commented Sep 22, 2018

Hi @krilbe, regarding InternalsVisibleTo issue, did you place the attribute in the assembly which contains the internal type or in the test assembly?
When it comes to the exception thrown from the analyzer, is this code #260 (comment) enough to reproduce it? If no, is your repository publicly available, so I can test it locally?
@dtchepak I suspect that ReEntrantCallAnalyzer left the scope of given syntax tree (usually the scope of the file) when finding reentrant calls, that's why it has thrown the exception. I will try to prepare a repro for that and try to fix it.
EDIT
Fix for the exception is awaiting review nsubstitute/NSubstitute.Analyzers#37

@dtchepak
Copy link
Member

@tpodolak @krilbe The Analyzer fix is in. 👍 Should be in the next release. Thanks for reporting @krilbe , and thanks for the quick fix @tpodolak !

@tpodolak
Copy link
Member

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants