A.CallTo(() => ...).MustHaveHappened(2, Times.Exactly) fails for unknown reason after upgrading to netcoreapp3.0

[tonitassimo]

After updating from netcoreapp2.2 to netcoreapp3.0 we're having some issues with fake it easy. I don't know whether or not it's due to fake it easy or netcoreapp. We're using fake it easy 5.2.0.

This is what we are trying to test:

ILogger logger = kernel.RebindLogger<IExporter>();
kernel.Get<IExporter>().Export();
A.CallTo(() => logger.Log(LogLevel.Warning, A<EventId>._, A<object>._, A<Exception>._, A<Func<object, Exception, string>>._)).MustHaveHappened(2, Times.Exactly);

We just want to make sure that the logger is called two times with LogLevel.Warning.

The relevant part of the result is shown in the attached file below.

We're getting the two expected calls. The only difference we can see is:

expected: [...]ILogger.Log[System.Object][...]
actual: [...]ILogger[TXS.Analytics.Export.Interface.IExporter].Log[Microsoft.Extensions.Logging.FormattedLogValues][...]

Until we upgraded from netcoreapp2.2 to netcoreapp3.0 this worked perfectly fine.

Maybe someone has an idea or has encountered similar problems?

Many thanks in advance! :)

  Assertion failed for the following call:
    Microsoft.Extensions.Logging.ILogger.Log`1[System.Object](logLevel: Warning, eventId: <Ignored>, state: <Ignored>, exception: <Ignored>, formatter: <Ignored>)
  Expected to find it twice exactly but didn't find it among the calls:    
    3:  Microsoft.Extensions.Logging.ILogger`1[TXS.Analytics.Export.Interface.IExporter].Log`1[Microsoft.Extensions.Logging.FormattedLogValues](
          logLevel: Warning,
          eventId: 0,
          state: [[{OriginalFormat}, Table/View MICH_GIBT_ES_NICHT does not exist.]],
          exception: NULL,
          formatter: System.Func`3[Microsoft.Extensions.Logging.FormattedLogValues,System.Exception,System.String])
    4:  Microsoft.Extensions.Logging.ILogger`1[TXS.Analytics.Export.Interface.IExporter].Log`1[Microsoft.Extensions.Logging.FormattedLogValues](
          logLevel: Warning,
          eventId: 0,
          state: [[{OriginalFormat}, Table/View V_PFANDOBJEKT has not defined a primary key.]],
          exception: NULL,
          formatter: System.Func`3[Microsoft.Extensions.Logging.FormattedLogValues,System.Exception,System.String])

[blairconrad]

Hi, @tonitassimo. Sorry you're having problems. What version of FakeItEasy are you using? Have you upgraded it lately? If so, from what?

Reading your output, it seems that kernel is actually in possession of a logger with type Microsoft.Extensions.Logging.ILogger<TXS.Analytics.Export.Interface.IExporter>, but you are are treating it as an ILogger in the test. I expect there's an explicit interface implementation for the ILogger.Log method, which makes it effectively a different method from ILogger<TXS.Analytics.Export.Interface.IExporter>.Log, and that's why the calls don't align.

If this is the case, I'm not sure FakeItEasy is misbehaving. Is it possible that the explicit interface implementation is new to the logger with the upgrade to netcoreapp3.0?

[thomaslevesque]

That's because the method that is called is actually ILogger.Log<FormattedLogvalues>. In your test, you pass A<object>._ for the state argument, so TState is inferred to be object, not FormattedLogValues. So the calls don't match, since they use a different generic type argument.

Unfortunately, FormattedLogValues is internal, so you can't just use it as TState... A possible workaround is to check the call like this:

    A.CallTo(logger).Where(call => call.Method.Name == "Log" && call.GetArgument<LogLevel>(0) == LogLevel.Warning)
        .MustHaveHappened(2, Times.Exactly);

It kinda sucks, but I don't see any better alternative

[tonitassimo]

Thanks for your quick answers!

I think FakeItEasy isn't misbehaving. I'll try out your advices!

[thomaslevesque]

As for why it started failing in 3.0, you have to look at the implementation of LoggerExtensions.

In 2.2, _messageFormatter was of type Func<object, Exception, string>, so when it was passed to the Log<TState> method, TState was inferred to be object, even though the state was actually a FormattedLogValues. So your assertion worked, because the method that was called was really Log<object>.

In 3.3, _messageFormatter was changed to type Func<FormattedLogValues, Exception, string>, so when it was passed to the Log<TState> method, TState was inferred to be FormattedLogValues. So your assertion doesn't work, because the method that was called was actually Log<FormattedLogValues>.

Also, FormattedLogValues used to be public, but now it's internal, which doesn't help...

[thomaslevesque]

See also dotnet/extensions#1319

[tonitassimo]

Many thanks for your help. Your workaround definitely works :) if we find any other way, I'll let you know.

[thomaslevesque]

Closing this, since there's a workaround that works for @tonitassimo.

In the future, we might want to introduce some kind of "catch-all" type to deal with that kind of thing.

Maybe something like this:

A.CallTo(() => logger.Log<AnyType>(LogLevel.Warning, A<EventId>._, A<object>._, A<Exception>._, A<Func<AnyTypep, Exception, string>>._)).MustHaveHappened(2, Times.Exactly);

We already have an issue to improve the experience when working with generics: #743

[jonathanantoine]

Thanks for your help @thomaslevesque

[gds03]

I am trying to mock it using the Invokes, but i can't because FormattedLogValues is internal.. :\

[blairconrad]

I'm sorry, @gds03. Can you expand on that? You're trying to mock FormattedLogValues? Can you share your code and explain what's gong wrong (and what you're trying to accomplish)?

[thomaslevesque]

@gds03 have you tried the workaround suggested above?

[gds03]

HI Guys, I have sorted out using object.

ILogger<MyClass> logger = A.Fake<ILogger<MyClass>>();
            A
                .CallTo(logger)
                .Where(call => call.Method.Name == "Log")
                .Invokes(obj =>
                {
                    object o = obj.Arguments.Get<object>("state");
                    string message = o.ToString();
                    loggerString.AppendLine(message);
                });

I wanted to intercept the log method to log to another place in my tests, with the above code it just works OK :)