NSubstitute ILogger .NET Core

Question

I am trying to write unit tests around my exception handling so that I can verify the my logger is properly logging the exception. I am using NSubstitute as a mocking framework and Microsoft.Extensions.Logging.ILogger I have to following for my test:

[Fact]
public void LogsExcpetionWhenErrorOccursInCreate()
{
   var newUser = new UserDataModel
   {
      FirstName = "Rick",
      MiddleName = "Jason",
      LastName = "Grimes",
      Email = "rick.grimes@thedead.com",
      Created = new DateTime(2007, 8, 15)
   };
   var exception = new Exception("Test Exception");
   // configure InsertOne to throw a generic excpetion
   _mongoContext.InsertOne(newUser).Returns(x => { throw exception; });

   try
   {
      _collection.Create(newUser);
   }
   catch
   {
      // validate that the logger logs the exception as an error
      _logger.Received().LogError(exception.Message);
   }
}

to test the logging in the following method:

public UserDataModel Create(UserDataModel user)
{
     try
     {
          return MongoContext.InsertOne(user);                
     }
     catch(Exception e)
     {
           _logger?.LogError(e.Message);
           throw new DataAccessException("An error occurred while attempting to create a user.", e);
      }

}

My test fails with the following error:

Message: NSubstitute.Exceptions.ReceivedCallsException : Expected to receive a call matching:
    Log<Object>(Error, 0, Test Exception, <null>, Func<Object, Exception, String>)
Actually received no matching calls.
Received 1 non-matching call (non-matching arguments indicated with '*' characters):
    Log<Object>(Error, 0, *Test Exception*, <null>, Func<Object, Exception, String>)

I'm not sure why this is failing because even in then error message the calls are the same.

Thanks in advance!

Update:

Here is the constructor for the test, this is where I am injecting the logger mock:

public UserCollectionTest()
{
   _mongoContext = Substitute.For<IMongoContext<UserDataModel>>();
   _logger = Substitute.For<ILogger>();
   // create UserCollection with our mock client
   _collection = new UserCollection(_mongoContext, _logger);
}

Answer 1

LogError is not a ILogger method, so when you try to check that this method was called with certain parameters NSubstitute tries to handle it somehow(I do not know how exactly) and fails.

The code of LogError extension method is:

public static void LogError(this ILogger logger, string message, params object[] args)
{
  if (logger == null)
    throw new ArgumentNullException("logger");
  logger.Log<object>(LogLevel.Error, (EventId) 0, (object) new FormattedLogValues(message, args), (Exception) null, LoggerExtensions._messageFormatter);
}

So you have to check that Log method was called.

I simplified your example a bit. I think idea should be clear.

public partial class MainWindow : Window
{
    public MainWindow()
    {
        InitializeComponent();

        var logger = Substitute.For<ILogger>();
        try
        {
            Create(logger);
        }
        catch
        {
            logger.CheckErrorMessage("My Message");
        }
    }

    public string Create(ILogger logger)
    {
        try
        {
            throw new Exception("My Message");
        }
        catch (Exception e)
        {
            logger?.LogError(e.Message);
            throw new Exception("An error occurred while attempting to create a user.", e);
        }
    }
}

public static class TestExtensions
{
    public static void CheckErrorMessage(this ILogger logger, string message)
    {
        logger.Received().Log(
            LogLevel.Error,
            Arg.Any<EventId>(),
            Arg.Is<object>(o => o.ToString() == message),
            null,
            Arg.Any<Func<object, Exception, string>>());
    }
}

Answer 2

Looks like the accepted answer does not work in .NET Core 3 or .NET 5.

Here is the workaround found in the github issue

Create a new MockLogger class

public abstract class MockLogger : ILogger
{
    void ILogger.Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter) => 
        Log(logLevel, formatter(state, exception));

    public abstract void Log(LogLevel logLevel, string message);

    public virtual bool IsEnabled(LogLevel logLevel) => true;

    public abstract IDisposable BeginScope<TState>(TState state);
}

Replace your mocked logger with the new mock logger

// Old 
// var logger = Substitute.For<ILogger>();
// New
var logger = Substitute.For<MockLogger>();

Use the new logger to check calls

logger.Received().Log(LogLevel.Error, Arg.Is<string>(s => s.Contains("some log message")));

To use with a generic ILogger<T>, simply change the class to

public abstract class MockLogger<T> : ILogger<T>

Answer 3

And here is my approach that is going a bit further. And extending Githhub issue.

First logger:

using Microsoft.Extensions.Logging;

public abstract class MockLogger<T> : ILogger<T>
{
    void ILogger.Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
    {
        var unboxed = (IReadOnlyList<KeyValuePair<string, object>>)state!;
        string message = formatter(state, exception);

        this.Log();
        this.Log(logLevel, message, exception);
        this.Log(logLevel, unboxed.ToDictionary(k => k.Key, v => v.Value), exception);
    }

    public abstract void Log();

    public abstract void Log(LogLevel logLevel, string message, Exception? exception = null);

    public abstract void Log(LogLevel logLevel, IDictionary<string, object> state, Exception? exception = null);

    public virtual bool IsEnabled(LogLevel logLevel)
    {
        return true;
    }

    public abstract IDisposable BeginScope<TState>(TState state);
}

Now usage:

MockLogger<Service> logger = Substitute.For<MockLogger<Service>>();
logger.IsEnabled(LogLevel.Error).Returns(true);

string originalFormat = "Service returned error with code: '{statusCode}' and reason: '{reason}'";
var statusCode = HttpStatusCode.BadRequest;
string reason = "The reason...";

string message = $"Service returned error with code: '{(int)statusCode}' and reason: '{reason}'";

// Assert
logger.Received(1).Log(
            LogLevel.Error,
            Arg.Is<IDictionary<string, object>>(
                dict =>
                    dict.Any(kv => kv.Key == "{OriginalFormat}" && (string)kv.Value == originalFormat) &&
                    dict.Any(kv => kv.Key == "statusCode" && (int)kv.Value == (int)statusCode) &&
                    dict.Any(kv => kv.Key == "reason" && (string)kv.Value == reason)));

logger.Received(1).Log(LogLevel.Error, message);
logger.Received(1).Log();

It allows testing log parameters separately.

Answer 4

Use name space below

using NSubstitute.ExceptionExtensions;

And update code to throw exception instead of returning it.

_mongoContext.InsertOne(newUser).Throw(exception);