Test ILogger with FakeItEasy

Question

I'm working on a fun project for myself to learn blazor, a lot of core concepts and just general practice.

I'm trying to implement logger extension for FakeItEasy to easier test Microsofts ILogger. Based on https://dev.azure.com/BrideButler/Bride%20Butler%20Open%20Source/_git/FakeItEasy.DotnetCore.LoggerExtensions?path=%2FFakeItEasy.DotnetCore.LoggerExtensions%2FLoggerExtensions.cs but now trying to get it to work for .NET 5. Now that FormattedLogValues is internal this code doesn't work anymore.

The goal is to have something like this in my test (and not use Moq) _logger.VerifyLog(LogLevel.Information, "Get Weather Called").MustHaveHappenedOnceExactly(); or A.CallTo(() => _logger.Log(LogLevel.Information, "Get Weather Called").MustHaveHappenedOnceExactly(); It doesn't have to have syntactic sugar but I would like to get it to work with FakeItEasy instead of Moq.

Below is all the involved code. Ofcourse I see some difference in the first line Microsoft.Extensions.Logging.ILogger.Log1[System.Object]vsMicrosoft.Extensions.Logging.ILogger1[Server.Controllers.WeatherForecastController].Log1[Microsoft.Extensions.Logging.FormattedLogValues]` but I've no clue how to "fix" this since I dont fully understand what is going wrong.

My question is obviously, what should I do to fix it, but also curious what part i'm missing.

My error is the following:

  Assertion failed for the following call:
        Microsoft.Extensions.Logging.ILogger.Log`1[System.Object]
        (
            logLevel: Information,
            eventId: <Ignored>, 
            state: <e => e.ToString().Contains(value(Server.Tests.Extensions.LoggerExtensions+<>c__DisplayClass2_0`1[Server.Controllers.WeatherForecastController]).message)>,
            exception: <Ignored>, 
            formatter: <Ignored>
        )
      Expected to find it once exactly but didn't find it among the calls:
        1: Microsoft.Extensions.Logging.ILogger`1[Server.Controllers.WeatherForecastController].Log`1[Microsoft.Extensions.Logging.FormattedLogValues]
        (
            logLevel: Information,
            eventId: 0,
            state: [[{OriginalFormat}, Get Weather Called]],
            exception: NULL,
            formatter: System.Func`3[Microsoft.Extensions.Logging.FormattedLogValues,System.Exception,System.String]
      )

Tests: (using xUnit, FakeItEasy, Fixture)

LoggerExtensions

public static class LoggerExtensions
    {
        public static void VerifyLogMustHaveHappened<T>(this ILogger<T> logger, LogLevel level, string message)
        {
            try
            {
                logger.VerifyLog(level, message)
                    .MustHaveHappened();
            }
            catch (Exception e)
            {
                throw new ExpectationException($"while verifying a call to log with message: \"{message}\"", e);
            }
        }

        public static void VerifyLogMustNotHaveHappened<T>(this ILogger<T> logger, LogLevel level, string message)
        {
            try
            {
                logger.VerifyLog(level, message)
                    .MustNotHaveHappened();
            }
            catch (Exception e)
            {
                throw new ExpectationException($"while verifying a call to log with message: \"{message}\"", e);
            }
        }

        public static IVoidArgumentValidationConfiguration VerifyLog<T>(this ILogger<T> logger, LogLevel level,
            string message)
        {
            return A.CallTo(() => logger.Log(
                    level, 
                    A<EventId>._,
                    A<object>.That.Matches(e => e.ToString().Contains(message)),
                    A<Exception>._,
                    A<Func<object, Exception, string>>._)
                );
        }
    }

TestConstructor:

private readonly IFixture _fixture;
private readonly ILogger<WeatherForecastController> _logger;

public WeatherForecastControllerTests()
{
    _fixture = new Fixture().Customize(new AutoFakeItEasyCustomization());
    _logger = _fixture.Freeze<Fake<ILogger<WeatherForecastController>>>().FakedObject;
}

Test:

[Fact]
public void WeatherForecast_Get_Should_Log()
{
    // Arrange
    var weatherController = new WeatherForecastController(_logger);

    // Act
    weatherController.Get();

    // Assert
    _logger.VerifyLog(LogLevel.Information, "Get Weather Called").MustHaveHappenedOnceExactly();
}

Controller:

public class WeatherForecastController : ControllerBase
{
    private readonly ILogger _logger;

    public WeatherForecastController(ILogger<WeatherForecastController> logger)
    {
        _logger = logger;
    }

    [HttpGet]
    public IEnumerable<WeatherForecast> Get()
    {
        // Left out other code then logging
        _logger.Log(LogLevel.Information, "Get Weather Called");
    }
}

Update: Options found

Only test if logger was called with correct log level:

   public static IVoidArgumentValidationConfiguration VerifyLog<T>(this ILogger<T> logger, LogLevel level, string message)
        {
            return A.CallTo(logger).Where(call => call.Method.Name == "Log" && call.GetArgument<LogLevel>(0) == level);
        }

Switch to Moq:

https://stackoverflow.com/a/59182490/1112413
https://stackoverflow.com/a/56728528/1112413

Answer 1

After reading https://stackoverflow.com/users/4728685/pavel-anikhouski comment on the post. I "got" what was wrong. Went to countless topics and made a solution that "works" tho probably could use some better coding standards. Hope it helps anyone else!

Edit: Some explaining.

Found this github comment that is the base of the solution. Then found this github pr where they mentioned to change Microsoft.Extensions.Logging.FormattedLogValues to IReadOnlyList<KeyValuePair<string, object>> This can be extracted from GetArgument(2). (Source: https://stackoverflow.com/a/63701968/1112413)

  public static class LoggerExtensions
    {
        public static void VerifyLogMustHaveHappened<T>(this ILogger<T> logger, LogLevel level, string message)
        {
            try
            {
                logger.VerifyLog(level, message)
                    .MustHaveHappened();
            }
            catch (Exception e)
            {
                throw new ExpectationException($"while verifying a call to log with message: \"{message}\"", e);
            }
        }

        public static void VerifyLogMustNotHaveHappened<T>(this ILogger<T> logger, LogLevel level, string message)
        {
            try
            {
                logger.VerifyLog(level, message)
                    .MustNotHaveHappened();
            }
            catch (Exception e)
            {
                throw new ExpectationException($"while verifying a call to log with message: \"{message}\"", e);
            }
        }

        public static IVoidArgumentValidationConfiguration VerifyLog<T>(this ILogger<T> logger, LogLevel level, string message)
        {
            return A.CallTo(logger)
                .Where(call => call.Method.Name == "Log" 
                    && call.GetArgument<LogLevel>(0) == level 
                    && CheckLogMessages(call.GetArgument<IReadOnlyList<KeyValuePair<string, object>>>(2), message));
        }

        private static bool CheckLogMessages(IReadOnlyList<KeyValuePair<string, object>> readOnlyLists, string message)
        {
            foreach(var kvp in readOnlyLists)
            {
                if (kvp.Value.ToString().Contains(message))
                {
                    return true;
                }
            }

            return false;
        }
    }

Answer 2

Based on the same comments of Github

I ended up with a solution like that:

public class MyClassWithLoggerTests
{
    private readonly MyClassWithLogger _sut;
    private readonly ILogger<MyClassWithLogger> _logger;

    public MyClassWithLoggerTests()
    {
        this._logger = A.Fake<ILogger<MyClassWithLogger>>();
        this._sut = new MyClassWithLogger(this._logger);
    }
    
    [Fact]
    public ATestMethodTitle()
    {
        this._sut.MethodToTest();
        A.CallTo(_logger).Where(
                call => call.Method.Name == "Log" && call.GetArgument<LogLevel>(0) == LogLevel.Information) // Modify with your type of log
            .MustHaveHappened(1, Times.Exactly); // Modify with the number of times log is called
    }
}

Answer 3

For people finding this page, are using FakeItEasy and are looking for a way to validate the log action object?[] arguments passed to it can use this (mind the horizontal scrollbar):

A.CallTo(logger).Where(call => call.Method.Name == nameof(ILogger.Log)
                                       && call.GetArgument<LogLevel>(0) == LogLevel.Error
                                       && (call.GetArgument<IReadOnlyList<KeyValuePair<string, object>>>(2) ?? Array.Empty<KeyValuePair<string, object>>()).Any(e => e.Value.Equals(orderId))
                                       && call.GetArgument<Exception>(3) == exception)
            .MustHaveHappened(1, Times.Exactly);

I know it's a bit raw but one could easily muffle this away in an extension method.