Nsubstitute: Checking a received call for a string argument value fails for identical strings

[nicolave]

Hi,

I have the following extension method for the Microsoft.Extensions.Logger.Logger.LoggerExtensions class:

public static void LogServiceInitalizationFailed<T>(this ILogger logger, Exception exception)
{
      logger.LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception,
            "The service {ServiceType} failed to initialize.", typeof(T).FullName);
}

I'm trying to check that I'm receiving a call with specific arguments when I this extension method. This is the code I've written:

```
var logger = Substitute.For();
var exception = new Exception("This is a test.");
logger.LogServiceInitalizationFailed(exception);

const string messageTemplate = "The service {ServiceType} failed to initialize.";
logger.Received().LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception, messageTemplate, typeof(string).FullName);
```

When I run the code, I get this exception:

NSubstitute.Exceptions.ReceivedCallsException:
Expected to receive exactly 1 call matching:
Log<Object>(Critical, 1007, The service System.String failed to initialize., System.Exception: This is a test., Func<Object, Exception, String>)
Actually received no matching calls.
Received 1 non-matching call (non-matching arguments indicated with '*' characters):
Log<Object>(Critical, 1007, *The service System.String failed to initialize.*, System.Exception: This is a test., Func<Object, Exception, String>)

And visually this does not make sense. The indicated string parameter seems to contain the exact same value: "The service System.String failed to initialize."

Why does this happen? Am I missing something? I would really appreciate any input on this.

Thank you,
Nicola

[nicolave]

Also, rewriting the the Received call to use Arg.Is<T>

const string message = "The service System.String failed to initialize.";
logger.Received(1).LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception, Arg.Is<string>(x => x.Contains(message)), typeof(string).FullName); 

produces the following exception:

NSubstitute.Exceptions.ReceivedCallsException: Expected to receive exactly 1 call matching:
Log<Object>(Critical, 1007, [null], System.Exception: This is a test., Func<Object, Exception, String>)
Actually received no matching calls.
Received 1 non-matching call (non-matching arguments indicated with '*' characters):
Log<Object>(Critical, 1007, *The service System.String failed to initialize.*, System.Exception: This is a test., Func<Object, Exception, String>)

[dtchepak]

Thanks for the detailed report!

I've tried to reproduce this using the following code, but the test passes for me (NSub 3.1):

namespace NSubWorkshop {

    using Xunit;
    using NSubstitute;
    using System;

    public interface ILogger {
        void LogCritical(ServiceFabricEvent serviceInitializationFailed, Exception exception, string v, string fullName);
    }

    public enum ServiceFabricEvent {
        ServiceInitializationFailed
    }

    public static class Extensions {

        public static void LogServiceInitalizationFailed<T>(this ILogger logger, Exception exception) {
            logger.LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception,
                  "The service {ServiceType} failed to initialize.", typeof(T).FullName);
        }
    }

    public class UnitTest1 {

        [Fact]
        public void Issue384() {
            var logger = Substitute.For<ILogger>();
            var exception = new Exception("This is a test.");
            logger.LogServiceInitalizationFailed<string>(exception);

            const string messageTemplate = "The service {ServiceType} failed to initialize.";
            logger.Received().LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception, messageTemplate, typeof(string).FullName);
        }
    }
}

Maybe try this in a new project to ensure there aren't other confounding factors? Based on the Arg.Is error that shows [null] for the argument matcher, I think there may be an argument matcher left over from another test that may be interfering with this one (probably in the test that executes immediately before this one. Does this test fail when run in isolation?).

[dtchepak]

Closing for now, pending more information.
Please re-open this if able to reproduce it or if you are able to supply more information.

[nicolave]

Sorry for not replying in time. I used your suggestion, that there might be some confounding factors, that something might be interfering with the argument matching. I have not been able to figure out what might be interfering because I have created the test project from scratch.

I have been able to find a workaround that I've been using until now.
The workaround is to wrap the Received() and argument matching calls in a try-catch block:

var logger = Substitute.For<ILogger>();
var exception = new Exception("This is a test.");
logger.LogServiceInitalizationFailed<string>(exception);

const string message = "The service System.String failed to initialize.";
try
{
    logger.Received(1).LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception, Arg.Is<string>(x => x.Contains(message)), typeof(string).FullName);
}
catch
{
    // ignored - Try block required to ensure "Received(1)" calls work as expected.
}

If you have any other tips on what I might look into, that would be great.

[dtchepak]

@nicolave I'd really recommend against the try/catch approach. Received() works by throwing an exception, so this is the same as just commenting out the logger.Received(1)... line.

One thing worth trying is to play around with the argument matchers in the test giving problems. First make sure the problem occurs repeatedly and in isolation (i.e. just running that single test over and over always fails in a predictable way). If this happens then it is very unlikely to be a left-over arg matcher problem.

Next, make sure it passes WithAnyArgs:

logger.ReceivedWithAnyArgs().LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception, messageTemplate, typeof(string).FullName); 

Then try replacing individual matchers, while leaving the rest as Arg.Any:

logger.Received().LogCritical(Arg.Any<...>(), Arg.Is(exception), Arg.Any<string>, Arg.Any<string>); 

// then...
logger.Received().LogCritical(Arg.Any<...>(), Arg.Any<Exception>(), Arg.Is(messageTemplate), Arg.Any<string>); 

If the problem is out-of-place arg matchers (so it does not fail when run in isolation), then I normally suggest these steps for tracking this down.

If you can reproduce the problem in an new project with just that code, please send through the .cs file and the list of nuget packages required and I'll have another try at reproducing this.

[drhoroscope]

I've run into this problem and I've been able to duplicate the issue exactly. The trick is to reference the ILogger interface within .NET Core instead of creating your own interface. Note that LogCritical is an extension method, which may be part of the explanation. In any event, it has something to do with ILogger. Here's the repro:

using System;
using Microsoft.Extensions.Logging;
using Microsoft.VisualStudio.TestTools.UnitTesting;
using NSubstitute;

namespace Weird.Tests
{
    public static class ServiceFabricEvent
    {
        //this must be defined by MS somewhere, but I couldn't find it
        public static readonly EventId ServiceInitializationFailed = new EventId(1);
    }
    public static class Extensions
    {

        public static void LogServiceInitalizationFailed<T>(this ILogger logger, Exception exception)
        {
            logger.LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception,
                  "The service {ServiceType} failed to initialize.", typeof(T).FullName);
        }
    }

    [TestClass]
    public class Weird
    {
        [TestMethod]
        public void Issue384()
        {
            var logger = Substitute.For<ILogger>();
            var exception = new Exception("This is a test.");
            logger.LogServiceInitalizationFailed<string>(exception);

            const string messageTemplate = "The service {ServiceType} failed to initialize.";
            logger.Received().LogCritical(ServiceFabricEvent.ServiceInitializationFailed, exception, messageTemplate, typeof(string).FullName);
        }
    }
}

The output from this test is:

NSubstitute.Exceptions.ReceivedCallsException: Expected to receive a call matching:
    Log<Object>(Critical, 1, The service System.String failed to initialize., System.Exception: This is a test., Func<Object, Exception, String>)
Actually received no matching calls.
Received 1 non-matching call (non-matching arguments indicated with '*' characters):
    Log<Object>(Critical, 1, *The service System.String failed to initialize.*, System.Exception: This is a test., Func<Object, Exception, String>)

[drhoroscope]

After a bit more digging, I've got to the bottom of it: the highlighted non-matching parameter isn't a string, it's a FormattedLogValue object. The reason you see a matching string in the error message is because the ToString() method is being invoked. In order to fix your code, you must use the non-extension method that is called on the ILogger interface and test the FormattedLogValue object to see if its contents are what you expect. Like this:

logger.Received().Log<object>(LogLevel.Critical, Arg.Any<EventId>(), Arg.Is<Microsoft.Extensions.Logging.Internal.FormattedLogValues>(flv => flv.ToString() == message), null, Arg.Any<Func<Object, Exception, string>>());

Thank you @dtchepak for posting this issue! Your similar problem gave me just enough clues to nail the root cause.

[dtchepak]

@drhoroscope Nicely worked out! Thanks for posting the explanation!

[BelRarr]

Thank you @drhoroscope. I just had a similar issue and your solution worked like a charm for me! 👍