在项目中我们一般不会对日志逻辑进行测试，但是对于一些相对重要的场景，希望日志必须被记录，那可以通过单元测试来保证。接下来我们看下如何对logger.Log方法进行单元测试。

实例

首先实现一个简单的Demo类来记录日志，代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
public class Demo
{
    private readonly ILogger<Demo> _logger;

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

    public void DoSomething()
    {
        _logger.LogDebug("This is a debug log");
    }
}

紧接着我们顺手就写了一个xUnit测试类，代码如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
public class DemoTests
{
    [Fact]
    public void TestDoSomething()
    {
        // Given
        Mock<ILogger<Demo>> loggerMock = new();
        var sut = new Demo(loggerMock.Object);

        // When
        sut.DoSomething();

        // Then
        loggerMock.Verify(m => m.LogDebug(It.IsAny<string>()));
    }
}

然鹅执行测试方法却发现报错了。。。。发生了不支持异常，里面说到扩展方法不可以在Moq的setup/verify的表达式里使用。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
System.NotSupportedException: Unsupported expression: m => m.LogDebug(It.IsAny<string>(), new[] {  })

System.NotSupportedException
Unsupported expression: m => m.LogDebug(It.IsAny<string>(), new[] {  })
Extension methods (here: LoggerExtensions.LogDebug) may not be used in setup / verification expressions.
   at Moq.Guard.IsOverridable(MethodInfo method, Expression expression) in C:\projects\moq4\src\Moq\Guard.cs:line 87
   at Moq.MethodExpectation..ctor(LambdaExpression expression, MethodInfo method, IReadOnlyList`1 arguments, Boolean exactGenericTypeArguments, Boolean skipMatcherInitialization, Boolean allowNonOverridable) in C:\projects\moq4\src\Moq\MethodExpectation.cs:line 86
   at Moq.ExpressionExtensions.<Split>g__Split|5_0(Expression e, Expression& r, MethodExpectation& p, Boolean assignment, Boolean allowNonOverridableLastProperty) in C:\projects\moq4\src\Moq\ExpressionExtensions.cs:line 235
   at Moq.ExpressionExtensions.Split(LambdaExpression expression, Boolean allowNonOverridableLastProperty) in C:\projects\moq4\src\Moq\ExpressionExtensions.cs:line 149
   at Moq.Mock.GetMatchingInvocationCount(Mock mock, LambdaExpression expression, List`1& invocationsToBeMarkedAsVerified) in C:\projects\moq4\src\Moq\Mock.cs:line 432
   at Moq.Mock.Verify(Mock mock, LambdaExpression expression, Times times, String failMessage) in C:\projects\moq4\src\Moq\Mock.cs:line 318
   at Moq.Mock`1.Verify(Expression`1 expression) in C:\projects\moq4\src\Moq\Mock`1.cs:line 713
   at aspnetcore_logger_ut_moq.DemoTests.TestDoSomething() in D:\CodeLab\aspnetcore-logger-ut-moq\aspnetcore-logger-ut-moq\aspnetcore-logger-ut-moq\DemoTests.cs:line 20
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)

看下logger.LogDebug()的源码，的确是一个扩展方法，

1
2
3
4
5
6
7
8
9
10
11
12
namespace Microsoft.Extensions.Logging
{
  /// <summary>ILogger extension methods for common scenarios.</summary>
  public static class LoggerExtensions
  {
    /// <summary>Formats and writes a debug log message.</summary>
    /// <param name="logger">The <see cref="T:Microsoft.Extensions.Logging.ILogger" /> to write to.</param>
    /// <param name="message">Format string of the log message in message template format. Example: <c>"User {User} logged in from {Address}"</c></param>
    /// <param name="args">An object array that contains zero or more objects to format.</param>
    public static void LogDebug(this ILogger logger, string? message, params object?[] args) => logger.Log(LogLevel.Debug, message, args);
  }
}

看下来最终是调用了ILogger.Log方法logger.Log<FormattedLogValues>(logLevel, eventId, new FormattedLogValues(message, args), exception, LoggerExtensions._messageFormatter);，那我们就得对这个方法进行Verify。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
namespace Microsoft.Extensions.Logging
{
  /// <summary>Represents a type used to perform logging.</summary>
  public interface ILogger
  {
    /// <summary>Writes a log entry.</summary>
    /// <param name="logLevel">Entry will be written on this level.</param>
    /// <param name="eventId">Id of the event.</param>
    /// <param name="state">The entry to be written. Can be also an object.</param>
    /// <param name="exception">The exception related to this entry.</param>
    /// <param name="formatter">Function to create a <see cref="T:System.String" /> message of the <paramref name="state" /> and <paramref name="exception" />.</param>
    /// <typeparam name="TState">The type of the object to be written.</typeparam>
    void Log<TState>(
      LogLevel logLevel,
      EventId eventId,
      TState state,
      Exception? exception,
      Func<TState, Exception?, string> formatter);
  }
}

于是将单元测试来改造如下后，发现FormattedLogValues报错：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[Fact]
public void TestDoSomething()
{
    // Given
    Mock<ILogger<Demo>> loggerMock = new();
    var sut = new Demo(loggerMock.Object);

    // When
    sut.DoSomething();

    // Then
    loggerMock.Verify(m => m.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<FormattedLogValues>(),
        It.IsAny<Exception?>(), It.IsAny<Func<FormattedLogValues, Exception?, string>>(), Times.Once()));
}

原来FormattedLogValues是一个internal类型，外部无法访问。

1
2
3
4
5
6
7
8
9
10
namespace Microsoft.Extensions.Logging
{
  internal readonly struct FormattedLogValues : 
    IReadOnlyList<KeyValuePair<string, object?>>,
    IEnumerable<KeyValuePair<string, object?>>,
    IEnumerable,
    IReadOnlyCollection<KeyValuePair<string, object?>>
  {
      // 省略具体内容
  }

那有没有办法解决这个internal类型无法访问的问题呢？答案是肯定的。Moq从4.13版本[1]开始支持了 It.IsAnyType, 我们将单元测试再次改造如下：

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[Fact]
public void TestDoSomething()
{
    // Given
    Mock<ILogger<Demo>> loggerMock = new();
    var sut = new Demo(loggerMock.Object);

    // When
    sut.DoSomething();

    // Then
    loggerMock.Verify(m => m.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(),
        It.IsAny<Exception?>(), It.IsAny<Func<It.IsAnyType, Exception?, string>>()));
}

终于单元测试可以跑过了，再仔细一想，是否可以对LogLevel以及message做精确的断言呢？于是可以继续改造。

1
2
3
4
5
6
loggerMock.Verify(m => m.Log(
            It.Is<LogLevel>(level => level == LogLevel.Debug), 
            It.IsAny<EventId>(),
            It.Is<It.IsAnyType>((obj, type) => obj.ToString() == "This is a debug log" && type.Name == "FormattedLogValues"),
            It.IsAny<Exception?>(),
            It.IsAny<Func<It.IsAnyType, Exception?, string>>()));

上面的It.Is<It.IsAnyType>断言使用的不是常用的public static TValue Is<TValue>(Expression<Func<TValue, bool>> match)，而是借助另外一个方法public static TValue Is<TValue>(Expression<Func<object, Type, bool>> match)，object代表传入的参数值，type代表参数的类型，这里就是指FormattedLogValues。

扩展

每次断言都需要写那么行代码，为了调用方便，我们可以将上面的断言代码封装一下。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
public static Mock<ILogger<T>> VerifyLogging<T>(this Mock<ILogger<T>> loggerMock, string expectLogMessage, LogLevel expectLogLevel = LogLevel.Debug, Times? times = null)
{
    times ??= Times.Once();

    Func<object, Type, bool> state = (obj, type) => obj.ToString()!.Equals(expectLogMessage);
    
    loggerMock.Verify(m => m.Log(
        It.Is<LogLevel>(level => level == expectLogLevel), 
        It.IsAny<EventId>(),
        It.Is<It.IsAnyType>((obj, type) => state(obj, type)),
        It.IsAny<Exception?>(),
        It.IsAny<Func<It.IsAnyType, Exception?, string>>()), (Times)times);

    return loggerMock;
}

有了封装的扩展方法后，验证起来就方便多了，将logger Mock返回还可以实现链式调用。比较增加一个info & warning log后：

1
2
3
4
5
6
7
8
public void DoSomething()
{
    _logger.LogDebug("This is a debug log");

    _logger.LogInformation("this is a info log");
    
    _logger.LogWarning("this is a warning log");
}

测试的断言写起来也很简洁：

1
2
3
loggerMock.VerifyLogging("This is a debug log")
        .VerifyLogging("this is a info log", LogLevel.Information)
        .VerifyLogging("this is a warning log", LogLevel.Warning, Times.Once());

结语

本篇探讨了不太常见的对日志的单元测试，借助Moq的It.IsAnyType来实现对无法访问类型的参数指定，并进一步实现了对日志的测试。

源码

Demo代码已上传 https://github.com/jeremyLJ/aspnetcore-logger-ut-moq/tree/master/aspnetcore-logger-ut-moq/aspnetcore-logger-ut-moq

参考资料

  1. https://adamstorr.azurewebsites.net/blog/mocking-ilogger-with-moq
  2. https://stackoverflow.com/questions/66307477/how-to-verify-iloggert-log-extension-method-has-been-called-using-moq

  1. https://github.com/Moq/moq4/wiki/Quickstart#type-matchers-moq-413 ↩︎