Mock Microsoft.Extensions.Logging and test logging in .Net core 3

[tharaka-wanigasekera]

Mock Microsoft.Extensions.Logging in .Net core 3
Following code is working in .Net core 2.2 but .Net Core 3

Environments

• Microsoft.Extensions.Logging Version="3.0.0"
• NSubstitute Version="4.2.1"
• Xunit "2.4.0"

Domain Class

public class Service
    {
        private readonly ILogger<Service> _logger;
        public Service(ILogger<Service> logger)
        {
            _logger = logger;
        }

        public void TestLogger()
        {
            _logger.LogInformation("Testing");
        }
    }

Test Class

public class ServiceTests
    {
        private readonly ILogger<Service> _logger;
        private readonly Service _service;
        public ServiceTests()
        {
            _logger = Substitute.For<ILogger<Service>>();
            _service = new Service(_logger);
        }

        [Fact]
        public void TestLogger_ShouldLogInformation()
        {
            // Act
            _service.TestLogger();

            // Assert
            _logger.Received().Log(LogLevel.Information, Arg.Any<EventId>(), Arg.Any<object>(),
                Arg.Any<Exception>(), Arg.Any<Func<object, Exception, string>>());
        }
    }
}

Not sure whether this is a bug. Any support would be appreciated.

[dtchepak]

Hi @tharaka-wanigasekera ,

Before the assert I added this code which shows the nature of the issue:

            // Assert
            foreach (var c in _logger.ReceivedCalls()) {
                System.Console.WriteLine(c.GetMethodInfo());
            }
/* Output:
Void Log[FormattedLogValues](Microsoft.Extensions.Logging.LogLevel,
    Microsoft.Extensions.Logging.EventId,
    Microsoft.Extensions.Logging.FormattedLogValues,
    System.Exception,
    System.Func`3[Microsoft.Extensions.Logging.FormattedLogValues,System.Exception,System.String])
*/

The exception thrown from the assertion is:

   NSubstitute.Exceptions.ReceivedCallsException : Expected to receive a call matching:
        Log<Object>(Information, any EventId, any Object, any Exception, any Func<Object, Exception, String>)

So it looks like there is a mismatch between the generic type Object vs FormattedLogValues. FormattedLogValues is internal so it is not straightforward to fix (we can't assert on Log<FormattedLogValues>(...)).

Looks like the same issue has reported here devlooped/moq#918, but NSubstitute does not have an equivalent for Moq's It.IsAnyType. (See also: dotnet/extensions#1319)

One option here is to cheat and use:

_logger.Received().LogInformation("Testing");

Even though LogInformation isn't properly substitutable because it is an extension method, it will call the underlying Log<TState> member and will give you the correct result. It's a bit hacky though.

Another option is to use a wrapper that forces logging to be done with TState as object:

    public class ObjectLogger<T> : ILogger<T>
    {
        ILogger<T> _log;
        public ObjectLogger(ILogger<T> log) {
            _log = log;
        }
        public IDisposable BeginScope<TState>(TState state) => _log.BeginScope<object>(state);
        public bool IsEnabled(LogLevel logLevel) => _log.IsEnabled(logLevel);
        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        {
            _log.Log<object>(logLevel, eventId, state, exception, (st, ex) => "");
        }
    }

We can wrap the substitute logger with this type:

        public ServiceTests()
        {
            _logger = Substitute.For<ILogger<Service>>();
            _service = new Service(new ObjectLogger<Service>(_logger));
        }

And then your original assertion passes as the generic types match.

Another thing to consider, especially if you are doing lots of logging tests, is to implement a custom ILogger (without NSubstitute) that stores all logs, and then assert on those results.

Hope this helps.
Regards,
David

[natalie-o-perret]

@dtchepak your ext. method trick might work for LogInformation but fails for LogCritical

[dtchepak]

Thanks for pointing this out @ehouarn-perret !

In cases like this where an API design is not easily testable with an automatically-generated substitute, then I think we're better off manually creating an ILogger implementation and asserting on that. This frees us from having to worry about unmockable static methods. It also means we can use powerful assertion libraries that come with xunit and nunit to assert results, rather than having than asserting specific interactions with the logging api.

If you need any assistance with this please let me know.

[ilya-spv]

Here is a mini version to verify the basics that can be extended further if anyone is interested:

 public class LoggerMock<T> : ILogger<T>
 {
     readonly Stack<ReceivedLogEvent> _events = new Stack<ReceivedLogEvent>();

     public IDisposable BeginScope<TState>(TState state)
     {
         return null;
     }

     public bool IsEnabled(LogLevel logLevel)
     {
         return false;
     }

     public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
     {
         _events.Push(new ReceivedLogEvent {Level = logLevel, Message = state.ToString()});
     }

     public void ReceivedOnce(LogLevel level, string message)
     {
         var matchedEventsCount = _events.Count(e => e.Level == level && e.Message == message);

         if (matchedEventsCount != 1)
         {
             throw new Exception($"Expected one call to Log with the following arguments: {level}, \"{message}\". Actual received count: {matchedEventsCount}");
         }
     }
 }

 class ReceivedLogEvent
 {
     public LogLevel Level { get; set; }

     public string Message { get; set; }
 }

P.S. It's so frustrating Microsoft has made this interface virtually untestable though it's not that hard I think to allow it...

P.P.S. Don't know if it covers all the use cases, but it works fine for my simple uses and can easily be extended, just a reference point really.

[dtchepak]

Thanks @ilya-spv! 👍

[SeanFarrow]

I solved this in two ways:
Firstly, by writing an extension method for Arg, Arg.IsAnyType that itself uses the Arg.Is(Expression<type, bool>) method and just returns true.
Secondly, Given that the FormattedLogValues type is a structure I wrote an Arg.IsStructure method with a corresponding argument matcher.

I'd be happy to contribute either or both of these solutions.

[dtchepak]

Hi @SeanFarrow, this sounds interesting! If it's not too much work could you please push the code somewhere or just copy/paste some snippets here for us to take a look at? It would be good to see a bit more info to make sure it is something we should include before you spend time putting this into a PR.

(As an aside, I think for this particular issue the best approach is not to mock Microsoft.Extensions.Logging, but these arg matchers might be useful for other situations.)

[ilya-spv]

I have found out that actually testing on extension method does work out of the box:

_logger
    .Received(1)
    .LogError(myException, "Exception happened");

I am actually not sure why. It did not work before, that was the reason everyone had to do something to mock the call to Log() with multiple parameters.

I have checked that it's not the update to .netcore 3.1, but the Microsoft.Extensions.Logging.Configuration and all the packages it needs that makes tests work.

Is there some new feature from .NetCore 3 that makes it possible @dtchepak? I am really wondering if we can "trust" this behaviour or is it something that can just be damaged since it did not work before...

[dtchepak]

I am really wondering if we can "trust" this behaviour or is it something that can just be damaged since it did not work before...

@ilya-spv I definitely wouldn't trust/rely on this behaviour. NSubstitute cannot mock static members; the options described here rely on a particular implementation detail that Microsoft is quite within their rights to change whenever they see fit. I personally try to never mock types I don't own, but attempting to mock static methods is even more dangerous as it should be fine to change the static method implementation without it being a breaking change/requiring a major version update.

I think the cost of implementing a small, app/library-specific logging interface wrapper is fairly small, and may provide options to simplify client code (e.g. API with strongly typed logging events) in addition to being reliably testable.

[ilya-spv]

Thanks for the answer, I guess it's wise to follow your advise. I am curious though on why it suddenly started working? Since methods are still static and Nubstitute cannot mock these methods, yet it just works somehow...

[moikot]

@ilya-spv it's working in 3.1 probably because FormattedLogValues was changed from being a class to a struct, and now it is possible to assert some calls if parameters match precisely. NSubstitute is not mocking statics, it's just your call to the extension method gets propagated to the mocked interface if you see what I mean.

@dtchepak I can't believe that we need to implement some wrappers over ILogger to make our code testable. Doesn't it diminish the whole idea of "Microsoft.Extensions.Logging.Abstractions" library?

[ilya-spv]

@moikot Yes, thanks for the explanation, I guess I understand how it works.

Maybe Microsoft will switch from using extension methods to the interface with default implementation in C#8, that would fix at least these problems nicely

[dtchepak]

@moikot

I can't believe that we need to implement some wrappers over ILogger to make our code testable. Doesn't it diminish the whole idea of "Microsoft.Extensions.Logging.Abstractions" library?

It seems it does diminish it a bit. But if we are using a library that is not easily testable, then I guess we only have the choice of wrapping it or switching to a different library.

AFAICT it will still allow us to change which underlying logger implementation is used, so maybe that is still useful? I haven't used it so I'm not sure, but if it allows us to use a in-memory logger that we can then query in our tests then I think that is better than mocking it.

[SeanFarrow]

I recently found Melt: https://github.com/alefranz/MELT.git This makes writing integration tests that check what is logged really easy with the TestSink. From: David Tchepak [mailto:[email protected]] Sent: 14 January 2020 21:44 To: nsubstitute/NSubstitute <[email protected]> Cc: Sean Farrow <[email protected]>; Mention <[email protected]> Subject: Re: [nsubstitute/NSubstitute] Mock Microsoft.Extensions.Logging and test logging in .Net core 3 (#597) @moikot<https://github.com/moikot> I can't believe that we need to implement some wrappers over ILogger to make our code testable. Doesn't it diminish the whole idea of "Microsoft.Extensions.Logging.Abstractions" library? It seems it does diminish it a bit. But if we are using a library that is not easily testable, then I guess we only have the choice of wrapping it or switching to a different library. AFAICT it will still allow us to change which underlying logger implementation is used, so maybe that is still useful? I haven't used it so I'm not sure, but if it allows us to use a in-memory logger that we can then query in our tests then I think that is better than mocking it. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub<#597?email_source=notifications&email_token=AALDK7RQOZ72IN55ZZ4ZRZDQ5YW2BA5CNFSM4JNVCU2KYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEI6HQWI#issuecomment-574388313>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AALDK7WAAUBOUK3MGK4L6NDQ5YW2BANCNFSM4JNVCU2A>.

[dtchepak]

Thanks @SeanFarrow , that looks perfect!

I strongly advise everyone looking at this issue to try a library like MELT rather than mocking Microsoft.Extensions.Logging.

[pmaytak]

Hello. I also just had a fun time researching this topic.

I used similar test code to the one in the first post. When comparing the parameter types for actual and expected calls in CallSpecification.cs in private static bool TypesAreAllEquivalent(Type[] aArgs, Type[] bArgs), this line (80) var areEquivalent = first.IsAssignableFrom(second) || second.IsAssignableFrom(first); results in false when comparing the Func parameters, Func<Object, Exception, String> and Func<FormattedLogValues, Exception, String>. It does result in true when comparing just Object and FormattedLogValues parameter types.

@dtchepak, it seems like when comparing Func types for equivalency, .NET doesn't check each generic type parameter? Would it be correct or appropriate to update that method to check the generic parameters if the type is something like a Func?

[dtchepak]

@pmaytak Thanks for the detective work! I'm not confident that this won't cause other problems (for example, if we're trying to resolve overloads with different Func arguments), but it seems worth a look!

@zvirja , @alexandrnikitin : do you have any thoughts about the safety of supporting co- and contravariance for Func types here? Maybe we just need to relax the a == b && b == a constraint to just check one direction?

NSubstitute/src/NSubstitute/Core/CallSpecification.cs

Lines 72 to 84 in 5b182fc

	private static bool TypesAreAllEquivalent(Type[] aArgs, Type[] bArgs)
	{
	if (aArgs.Length != bArgs.Length) return false;
	for (var i = 0; i < aArgs.Length; i++)
	{
	var first = aArgs[i];
	var second = bArgs[i];
	var areEquivalent = first.IsAssignableFrom(second) || second.IsAssignableFrom(first);
	if (!areEquivalent) return false;
	}
	return true;
	}

[alexandrnikitin]

@dtchepak that's a good catch. I would expect that Arg.Any<>() takes co- and contravariance types into account. But that's definitely a breaking change and we need to be careful with it. And NSub should be consistent with other frameworks too.
Surprisingly I have never encountered that issue. I think it's because in tests we know types and it's natural to specify them in argument assertion.

[zvirja]

@dtchepak Yes, I would also say that NSub should support Func co-and contravariance in accordance with the language rules. The only question is how to implement it in a way that it doesn't affect performance, as for vast majority of cases isn't not required.

[AlexVallat]

Best approach I have found so far is to do a minimal abstract logger:

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

Then use NSubstitute to do its thing on that, taking advantage of all the existing Received functionality, eg:

var logger = Substitute.For<MockLogger>();
new UnderTest(logger).DoSomething();

logger.Received().Log(Arg.Any<LogLevel>(), Arg.Is<string>(s => s.Contains("some log message")));

[nikolic-bojan]

@AlexVallat I just had to change first line in order to have a typed logger, but all works as advertised. Thanks! :)

public abstract class MockLogger<T> : ILogger<T>

[AlbertoMonteiro]

Thanks for the insight @AlexVallat
I've made a simple change to be able to verify logged errors with that version

public abstract class MockLogger<T> : ILogger<T>
{
    void ILogger.Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
        => Log(logLevel, formatter(state, exception), exception);

    public abstract void Log(LogLevel logLevel, object state, Exception exception = null);

    public virtual bool IsEnabled(LogLevel logLevel) => true;

    public abstract IDisposable BeginScope<TState>(TState state);
}

Then I can use

logger.Received().Log(LogLevel.Error, "Message", exception);
// or
logger.Received().Log(LogLevel.Error, "Message", Arg.Is<ExceptionType>(ex => ex.Message == ""));

[SeanFarrow]

What I’ve taken to doing is splitting this up: In the unit tests, I test that the logger was call (or not depending on the test) the number of times I expect. Then, in a separate integration test using Melt: https://github.com/alefranz/MELT I test that the output is what I expect. This gives me the best of both worlds imo. Sean. From: murven ***@***.***> Sent: 02 March 2022 19:56 To: nsubstitute/NSubstitute ***@***.***> Cc: Sean Farrow ***@***.***>; Mention ***@***.***> Subject: Re: [nsubstitute/NSubstitute] Mock Microsoft.Extensions.Logging and test logging in .Net core 3 (#597) I was able to work around the issue this way: var receivedCalls = logger.ReceivedCalls(); receivedCalls .ShouldContain( c => c.GetArguments() .Any(a => a is object && a.ToString() == "The string after the formatting is applied")); Can anyone think of any objections to this approach? I know there are more sophisticated workarounds in this thread, but this one also gets the work done, so I would like to know if this is bad practice and why. — Reply to this email directly, view it on GitHub<#597 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AALDK7XXADS7ZFVZ4TJ2HL3U57BTNANCNFSM4JNVCU2A>. You are receiving this because you were mentioned.Message ID: ***@***.***>

[msmolka]

A bit further with mocking 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);
}

And the usage with specific params:

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

[JonathonRP]

I solved this in two ways: Firstly, by writing an extension method for Arg, Arg.IsAnyType that itself uses the Arg.Is(Expression<type, bool>) method and just returns true. Secondly, Given that the FormattedLogValues type is a structure I wrote an Arg.IsStructure method with a corresponding argument matcher.

I'd be happy to contribute either or both of these solutions.

@SeanFarrow,
Can you please share code snippets for this?

[rklec]

.NET 8 seems to have a new FakeLogger, which may be the best solution to use when verifying/testing log calls nowadays: https://devblogs.microsoft.com/dotnet/fake-it-til-you-make-it-to-production/

Ref #539 #565

[304NotModified]

I don't really see something we should do here (correct me if wrong!), so closing this issue.