Moq4: Verify() fails: Expected invocation on the mock once, but the invocation has been done

[ysteiger]

Hi

I have a setup serviceMock.Setup(x => x.SomeProperty).Returns(someValue).
Later, I call serviceMock.Verify(x => x.SomeProperty, Times.Once)

Now after a long time without failing, the test fails with:
Expected invocation on the mock once, but was 0 times: x => x.SomeProperty

Then a list of performed invocations follows. Surprisingly, x.SomeProperty is in the list of performed invocations.
The mock is a member of the test class and is created for every test.
Is this a problem of concurrency?

We use Moq 4.13.1.

[siprbaum]

From what you describe, I sounds likely that it is a cocurrency problem.

Without a minimal reproducer, it is hard to tell!

[ysteiger]

Hi

Attached is a sample project that reflects our production code. I could not reproduce, but I could reproduce the issue again with our production code, by running the tests with R# unit test runner feature "Until failure".

My question is also, if it is by-design impossible that this happens due to concurrency.

Cheers
Yannik
MoqReproduceConcurrencyVerifyIssue.zip

[Ettores88]

I'm experiencing the same problem too mocking ILogger.

My code:

_logger.Verify(x => x.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => LogAndReturn(v))), Times.Once);
_logger.Verify(x => x.Log(LogLevel.Information, It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), It.IsAny<Func<It.IsAnyType, Exception, string>>()), Times.Once);

Where:

private bool LogAndReturn(object v)
{
   Debug.WriteLine(v?.ToString());
   return true;
}

The first one performed well. The second line raises the following exception:

Moq.MockException
HResult=0x80131500
Message=
Expected invocation on the mock once, but was 0 times: x => x.Log(LogLevel.Information, It.IsAny(), It.IsAny(), It.IsAny(), It.IsAny>())

Performed invocations:

Mock:1> (x):

  ILogger.Log<FormattedLogValues>(LogLevel.Information, 0, No users to notify., null, Func<FormattedLogValues, Exception, string>)

Source=Moq
StackTrace:
at Moq.Mock.Verify(Mock mock, LambdaExpression expression, Times times, String failMessage)
at Moq.Mock1.Verify(Expression1 expression, Times times)
at Moq.Mock1.Verify(Expression1 expression, Func`1 times)
at .<>d__7.MoveNext() in **
I'm using Moq 4.14.5. If I change the first line and instead of calling LogAndReturn I use It.IsAny the Verify will throw the same exception as the second line.

This started happening after I migrated the code to DotNetCore 3.1 and upgraded Moq. In DotNetCore 2.2 we haven't the problem but we were using Moq 4.13.0.

[stakx]

@ysteiger, given your repro code, I cannot reproduce the test failure you're describing. There's nothing we can do without a repro. (Actually, that's a lie. Being able to reliably reproduce the failure would be helpful but knowing that this code _can_ fail may still give an indication where things might go wrong.)

@Ettores88, your issue seems unrelated to @ysteiger's. Hint, It.IsAny<Func<It.IsAnyType, Exception, string>>()) is never going to match anything _at present_; see e.g. #919 and the discussion in https://github.com/moq/moq4/issues/918#issuecomment-527647423.

[stakx]

@ysteiger, on a closer look at your repro code, I think I can guess what's going wrong. You originally said:

The mock is a member of the test class and is created for every test.

Yet that is not what you're actually doing. In your tests, you are not creating the mock—you're adding setups to it. Let's randomly pick two tests from the same fixture in your repro code:

        [TestMethod]
        public async Task LoadData1_1()
        {
            _serviceMock.Setup(x => x.MyProperty1).Returns("Mocked_MyProperty1_Result");

            var testee = new Testee(_serviceMock.Object);

            await testee.ReloadDataAsync(LoadOptions.Data1);

            _serviceMock.Verify(x => x.MyProperty1, Times.Once);
            _serviceMock.Verify(x => x.MyProperty2, Times.Never);
        }

        [TestMethod]
        public async Task LoadData1_2()
        {
            _serviceMock.Setup(x => x.MyProperty1).Returns("Mocked_MyProperty1_Result");

            var testee = new Testee(_serviceMock.Object);

            await testee.ReloadDataAsync(LoadOptions.Data1);

            _serviceMock.Verify(x => x.MyProperty1, Times.Once);
            _serviceMock.Verify(x => x.MyProperty2, Times.Never);
        }

Notice that both tests add an identical setup to the same mock. Because they set up the same call, one of those setups will effectively shadow the other. So what can happen is this: test 1 adds setup A, and then invokes that setup. Right after this, test 2 (which depending on your test runner's configuration may be executing concurrently) adds setup B for the same calls, and right after that, test 1 verifies that the call was made. However, that verification step no longer goes against setup A, which is now shadowed by the equivalent setup B (which however hasn't received any calls just yet). And thus verification fails in test 1.

So this isn't a problem in Moq. You're sharing a mock between tests without ensuring that each test has exclusive access while it runs.

If you want to test whether this theory is correct, inspect the mock once verification fails—the latest version of Moq allows you to inspect all the setups configured on a mock by querying its .Setups property. You probably expected to find just one setup, but when a test fails, you should see at least two (if not many more) setups.

The solution is easy: don't share one mock between tests. Let each test instantiate its own mock, and keep a reference to it in a local variable.

[ysteiger]

Hi, thanks for your reply. I cannot agree to your theory. In mstest, for each test the constructor is called, thus, each test should have its own instance of mock. I verified that the constructor is called for each test and that for each test the mock was setup with only the setup of the respective test. Of course we can try with local instances of mocks.
MoqConcurrencyIssueReproductionTest.log

[stakx]

I agree that my above theory was incorrect.

However, if it's truly the case that each test has its own separate mock, then the error must be in your code... since mocks don't share any state when it comes to recording invocations and verifying setups.

I've taken another look and I believe you got your async code wrong.

I've noticed that you've got some delays in the methods that set your mock's properties:

        private Task LoadData1()
        {
            return Task.Factory.StartNew(() =>
                {
                    var result = _service.MyProperty1;
                    Task.Delay(_random.Next(1, 300));
                }
            );
        }

However, the test appear to all pass immediately. Let me make a small change to make this even more obvious:

         private Task LoadData1()
         {
             return Task.Factory.StartNew(() =>
                 {
+                    Task.Delay(5000);
                     var result = _service.MyProperty1;
-                    Task.Delay(_random.Next(1, 300));
                 }
             );
         }

If you have everything set up correctly, the tests checking whether MyProperty1 was queried couldn't possibly succeed before 5 seconds have elapsed, right? However, even after making this change, they still pass immediately.

Which means that Task.Delay isn't actually observed—and the reason for that is that you're never actually awaiting that delay. Let's add the necessary awaits:

         private Task LoadData1()
         {
-            return Task.Factory.StartNew(() =>
+            return Task.Factory.StartNew(async () =>
                 {
-                    Task.Delay(5000);
+                    await Task.Delay(5000);
                     var result = _service.MyProperty1;
                 }
             );
         }

And now, all of your tests fail immediately. This proves they're not actually waiting for the above started task to complete. Let's fix that, too:

-        private Task LoadData1()
+        private async Task LoadData1()
         {
-            return Task.Factory.StartNew(async () =>
-                {
                     await Task.Delay(5000);
                     var result = _service.MyProperty1;
-                }
             );
         }

And now all of your tests take 5 seconds each to complete; and they should all pass because now, they're actually waiting for LoadData1 and LoadData2 to complete.

You should perhaps also fix the compiler warning for Testee.ReloadDataAsync:

CS1998: This async method lacks 'await' operators and will run synchronously. Consider using the 'await' operator to await non-blocking API calls, or 'await Task.Run(...)' to do CPU-bound work on a background thread.

by making this change:

-            Task.WhenAll(loadTasks.ToArray())
-                .ConfigureAwait(true).GetAwaiter().GetResult();
+            await Task.WhenAll(loadTasks.ToArray());

---

TL;DR: You have a race condition between your LoadData1/LoadData2 methods and your calls to _serviceMock.Verify, and that's why you see intermittent failures.

[ysteiger]

Thanks a lot for your inspection and concise explanation