Moq.VerifyLogUnexpectedException

[kippermand]

When running unit tests to verify logger is called as expected, Moq.ILogger threw this exception:

Moq.VerifyLogUnexpectedException : Moq.ILogger found an unexpected exception.
----> System.ArgumentNullException : Value cannot be null. (Parameter 'body')

Stack Trace:

    VerifyLogExtensions.Verify[T](Mock`1 loggerMock, Expression`1 expression, Nullable`1 times, Func`1 timesFunc, String failMessage)
    VerifyLogExtensions.VerifyLog(Mock`1 loggerMock, Expression`1 expression, Func`1 times)
    <>c__DisplayClass22_0.<ExampleAsync_HallOfFameInducteesNotEmpty_NoDuplicateIds_ValidatorIsValidTrue_RetrieveBOExecuteSuccessful_NewEntryAlreadyInSameCategory_ErrorSet>b__1() line 250
    Assert.Multiple(TestDelegate testDelegate)
    BusinessLogic.ExampleAsync_HallOfFameInducteesNotEmpty_NoDuplicateIds_ValidatorIsValidTrue_RetrieveBOExecuteSuccessful_NewEntryAlreadyInSameCategory_ErrorSet() line 248
    GenericAdapter`1.GetResult()
    AsyncToSyncAdapter.Await(Func`1 invoke)
    TestMethodCommand.RunTestMethod(TestExecutionContext context)
    TestMethodCommand.Execute(TestExecutionContext context)
    <>c__DisplayClass1_0.<Execute>b__0()
    DelegatingTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)
    --ArgumentNullException
    ContractUtils.RequiresNotNull(Object value, String paramName, Int32 index)
    ExpressionUtils.RequiresCanRead(Expression expression, String paramName, Int32 idx)
    Expression.ValidateLambdaArgs(Type delegateType, Expression& body, ReadOnlyCollection`1 parameters, String paramName)
    Expression.Lambda[TDelegate](Expression body, String name, Boolean tailCall, IEnumerable`1 parameters)
    Expression.Lambda[TDelegate](Expression body, Boolean tailCall, IEnumerable`1 parameters)
    VerifyLogExpressionArgs.From(Expression expression)
    VerifyLogExpression.From(Expression expression)
    VerifyLogExtensions.Verify[T](Mock`1 loggerMock, Expression`1 expression, Nullable`1 times, Func`1 timesFunc, String failMessage)

Code:

public async Task ExampleAsync(IEnumerable<Models.HallOfFame> hallOfFameInductees, CancellationToken cancellationToken = default)
{
    var currentHallOfFamers = (await RetrieveBO.ExecuteAsync(cancellationToken)).ToList();

    var alreadyInducted = (from current in currentHallOfFamers
                            from inductee in hallOfFameInductees
                            where current.BowlerId == inductee.BowlerId
                            where AlreadyInducted(inductee, current)
                            select inductee).ToList();

    if (alreadyInducted.Count > 0)
    {
        Logger.LogError("Bowler(s) {alreadyInducted} already inducted to hall of fame", alreadyInducted);
        ErrorDetails.Add(new Models.ErrorDetail("Invalid Addition: Bowler already inducted"));

        return;
    }

    DataLayer.Execute(hallOfFameInductees);

    await DataAccess.CommitAsync(LocalTransaction, cancellationToken);
}

private static bool AlreadyInducted(Models.HallOfFame inductee, Models.HallOfFame current)
    => current.Category == Models.HallOfFameTypes.Combined || current.Category == inductee.Category;

Unit Test (hallOfFameInductees and hallOfFamers generated via Bogus, Fluent calls override properties set via Bogus):

[Test]
public async Task ExampleAsync_RetrieveBOExecuteSuccessful_NewEntryAlreadyInSameCategory_LoggerLogError_CalledCorrectly()
{
    var hallOfFameInductees = new[] { new Builders.Models.HallOfFame()
                                            .WithBowlerId(1)
                                            .WithYear(2000)
                                            .WithCategory(NEBA.Models.HallOfFameTypes.Performance)
                                            .Generate()};

    var hallOfFamers = new[] { new Builders.Models.HallOfFame()
                                            .WithBowlerId(1)
                                            .WithYear(1999)
                                            .WithCategory(NEBA.Models.HallOfFameTypes.Performance)
                                            .Generate()};

    _retrieveBO.Setup(retrieveBO => retrieveBO.ExecuteAsync(It.IsAny<CancellationToken>())).ReturnsAsync(hallOfFamers);

    await _businessLogic.ExampleAsync(hallOfFameInductees);

    _logger.VerifyLog(logger => logger.LogError("Bowler(s) {alreadyInducted} already inducted to hall of fame", hallOfFameInductees), Times.Once);
}

Models:

/// <summary>
/// 
/// </summary>
public sealed class HallOfFame
{
    /// <summary>
    /// 
    /// </summary>
    /// <value></value>
    public int Id { get; set; }

    /// <summary>
    /// 
    /// </summary>
    /// <value></value>
    public int BowlerId { get; set; }

    /// <summary>
    /// 
    /// </summary>
    /// <value></value>
    public int Year { get; set; }

    /// <summary>
    /// 
    /// </summary>
    /// <value></value>
    public HallOfFameTypes Category { get; set; }
}

/// <summary>
/// 
/// </summary>
public enum HallOfFameTypes
{
    /// <summary>
    /// 
    /// </summary>
    Performance = 100,

    /// <summary>
    /// 
    /// </summary>
    Service = 200,

    /// <summary>
    /// 
    /// </summary>
    Combined = 300,

    /// <summary>
    /// 
    /// </summary>
    Friend = 500
}

[adrianiftode]

I think the problem might be the usage with the LogError itself.

The signature of any LogXXX is

public static void LogInformation(this ILogger logger, string message, params object[] args)

So the args is a param.

That means if you pass an array, what it actually happens is the following call is actually made

"Bowler(s) alreadyInducted[0] already inducted to hall of fame";

So the first element it will appear in the log.

I see that there is a popular question on Stackoverflow here https://stackoverflow.com/questions/66317482/serilog-only-logs-first-element-of-array and the suggestion is to change the calling code, to cast the array to an object, so the params will be called with one object and not with as many objects the entire alreadyInducted has.

Logger.LogError("Bowler(s) {alreadyInducted} already inducted to hall of fame", (object)alreadyInducted);

But even so, you can't do much with this library, most you can do is

_logger.VerifyLog(logger => logger.LogError("Bowler(s) {alreadyInducted} already inducted to hall of fame", hallOfFameInductees, It.Is<object[]>(s => s.Length == 1))), Times.Once);

Or to use pattern matching

_logger.VerifyLog(logger => logger.LogError("Bowler(s)*{ BowlerId = 1*BowlerId = 2*already inducted to hall of fame"));

You can verify what data is in the "Performed invocations:" section when the test fails.