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 = "[email protected]",
      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);
}

Impasto

Please clarify how you create and inject ILogger substitute. – Baty

I have updated the post with the constructor for the test, this is where I am injecting the sub. – Impasto

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>>());
    }
}

Scutum

Did not work for me. It simply doesn't match. – Floss

What doesn't match. Maybe it's because newer version of NSubstitute. Can you please be more specific? – Scutum

@AndreSoares looks like this solution doesn't work anymore in newer version of .NET which didn't exists at the time the answer was posted. github.com/nsubstitute/NSubstitute/issues/597 – Overtone

Same problem here. It does not work anymore for me either. Bummer. – Steamroller

logger.ReceivedWithAnyArgs(1).Log(LogLevel.Information, default, default, default, default); works for me but it has the obvious limitation of not asserting the info message (only that 1 info msg has taken place). – Krum

I think the reason this doesn't match is for projects where "nullability" is being used. Change Arg.Any<Func<object, Exception, string>>() to be Arg.Any<Func<object, Exception?, string>>() – Nadabus

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>

Overtone

With the MockLogger I could use the LogWarning in the assert: _logProvider.Received().LogWarning("message"); – Mediatorial

Just verified that this solution works with new the newest libraries at the moment. For those who have to use explicit types, the type of the instance should be MockLogger rather than ILogger, e.g: MockLogger<IMyService> logger = Substitute.For<MockLogger<IMyService>>();. Otherwise, a test will be failing. – Toro

Answer 3

I created an extension method for situations where I just want to know that a certain type of log was called. This is useful to hide all the extra Arg.Any that clutters tests and makes them hard to read. It's working in .NET 7 with NSubstitute 5.1.0.

public static class LoggerTestExtensions
{
    public static void AnyLogOfType<T>(this ILogger<T> logger, LogLevel level) where T : class
    {
        logger.Log(level, Arg.Any<EventId>(), Arg.Any<object>(), Arg.Any<Exception>(),
            Arg.Any<Func<object, Exception?, string>>());
    }
}

It can be used like so

logger.Received(1).AnyLogOfType(LogLevel.Error);

Madeleinemadelena

I would also add the eventId and suppress the generic T type. Here my version: public static void AnyLogOfType(this ILogger logger, LogLevel level, int eventId) { logger.Log(level, new EventId(eventId), Arg.Any<object>(), Arg.Any<Exception>(), Arg.Any<Func<object, Exception?, string>>()); } – Affright

Answer 4

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.

Orthostichy

Answer 5

Not sure if they changed something once again but this worked in 2024 with NSubstitute for asserting log message:

    Assert.Contains($"your log here", logger?.ReceivedCalls()?
                                             .SelectMany(x => x.GetArguments())?
                                             .Select(x => x?.ToString());

Lindberg

can add a check for level as well: ReceivedCalls()?.Where(call => call.GetMethodInfo().Name == "LogDebug").SelectMany(... – Overwind

Answer 6

Use name space below

using NSubstitute.ExceptionExtensions;

And update code to throw exception instead of returning it.

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

Inelegance