TState in ILogger.Log<TState> used to be object, now FormattedLogValues

[helloserve]

Probably not a bug per se, so perhaps just to clarify my understanding of why this change happened, and to explain how this change is breaking us.

In 2.2 I have an assert that verify my code would log in a specific scenario using Moq:

_loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<object>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>())));

If I substitute object here with FormattedLogValues (which I can do in 2.2 because it's a public class), Moq throws an exception and tells me that the actual invocation was with TState as object.

When I switch to 3.0 preview, the above Verify() call no longer works and Moq throws the same exception, except now showing that the actual invocation was with TState as FormattedLogValues. Unfortunately this class has now become an internal struct, and I cannot substitute it in place of object in my assert to get my tests working again, e.g. I cannot write

_loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<FormattedLogValues>(), It.IsAny<Exception>(), It.IsAny<Func<FormattedLogValues, Exception, string>>()));

What would be a way around this? This is breaking a lot of unit tests for us. Can FormattedLogValues be changed back to be public perhaps? I assume that when you use the simple extension methods like LogWarning(), this is the TState object that it uses, as opposed to me using the ILogger.Log() directly and providing my own state object. Except that this would involve so much change of existing code.

[Eilon]

@helloserve can you show an example of "regular" code that would demonstrate this as a breaking change? Please note that if any types from a .Internal namespace were used, those are not supported.

[helloserve]

@Eilon , currently our in-production solutions on .NET Core 2.2 have unit tests that verify as per my first example:

_loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<object>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>())));

This unit test code breaks by simply upgrading to .NET Core 3.0.

We don't use FormattedLogValues at all. I simply indicated that I can make use of it in 2.2 since it is public, even though it is in a .Internal namespace. But of course there is no point, because in 2.2 Moq only matches the invocation when I type TState as object. I apologise if this wasn't clear.

In my 3.0 branch the same line fails, and the exception report from Moq in the test panel shows that the invocation can now only be matched when typing TState as FormattedLogValues. So in an effort to resolve it I attempted to rely on this internal object, but it's since been changed to be internal.

I guess something changed in the extension methods (.LogWarning()) that causes the invocation to be specifically type set to FormattedLogValues now in 3.0, instead of just being passed object. This change is what is breaking us.

Here is a complete sample:

    public class TestService
    {
        readonly ILogger _logger;

        public TestService(ILoggerFactory loggerFactory)
        {
            _logger = loggerFactory?.CreateLogger<TestService>();
        }

        public void TestLog()
        {
            _logger?.LogWarning("message");
        }
    }

    [TestClass]
    public class TestServiceTests
    {
        readonly Mock<ILoggerFactory> _loggerFactoryMock = new Mock<ILoggerFactory>();
        readonly Mock<ILogger> _loggerMock = new Mock<ILogger>();

        public TestService Service => new TestService(_loggerFactoryMock.Object);

        public TestServiceTests()
        {
            _loggerFactoryMock.Setup(x => x.CreateLogger(It.IsAny<string>())).Returns(_loggerMock.Object);
        }

        [TestMethod]
        public void TestLog_Verify()
        {
            //act
            Service.TestLog();

            //assert
            _loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<object>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>()));
        }
    }

This unit test passes when I reference Microsoft.Extensions.Logging.Abstractions version 2.2.0, but fails when I change that reference to 3.0.0-preview3.19153.1

[dzmitry-lahoda]

It is very good that logging moved towards more typed solution.

I guess, Moq, somehow, should be instructed to match x.Log<FormattedLogValues> by x.Log<object>. Kind of x.Log<TAny> (variance)?

I doubt this is issue of aspnet, more of Moq. And it is good that ""breaking"" changes in major version bump. Seems issue should be closed.

[helloserve]

I agree and I prefer more strictly typed solutions, but then those types should be available to reference and perhaps even extend. I don't exactly understand why FormattedLogValues were deemed to be internal in the first place. I mean, there is real value in exposing it to your consumers. I've seen many issues here (and on the old, archived repo) where users are attempting to work with this object and its properties, be it building custom loggers or whatnot.

-Edit-

Perhaps I should elaborate on why I don't understand. In this case I'm dealing with the abstraction ILogger at face value. I'm not attempting to reach behind it - I don't want to have a dependency on anything behind it. But TState (whatever it is) is at the level of the abstraction itself. Whatever ends up as TState should be at the same level as that. And since these easy extension methods we use are shipped as part of the .Abstractions package, I consider it incorrect that they should be using a type that is internal. It feels like how it is now doesn't fit the philosophy of "commonly used types" in a .Abstractions package.

[dzmitry-lahoda]

Readonly struct FormattedLogValues is internal. It never leaks behind LoggerExtensions and hidden by _messageFormatter. So it is very interesting pattern of abstraction and information hiding.
When it was casted to object it did GC and boxing previously. FormattedLogValues is not class, and it is harder to evolve struct backward compatible than class. So we get ILogger which is possibly zero GC, but some conveniences LoggerExtensions which are less GC, but still GC (because of params). I guess next steps is to have FormattedLogValues1, ..., FormattedLogValues4 to avoid GC(may be other type of cache or parser or what ever or do stuff more lazy) at all in LoggerExtensions(aspnet core targets not only HTTP now but HPC TPC), but all this will work without real breaking changes I guess.

So question is if LoggerExtensions abstraction? I guess it is abstraction like string. At least I always can write my own.

Let go deeper.
Could we get FormattedLogValues key-values if logging level does suffice? Yes, we can in MyLogger cast TState into IReadOnlyList<KeyValuePair<string, object>>. I do not need FormattedLogValues to be public. They may end up to more Span or struct oriented versions, still having IReadOnlyList for one release.

I do not say that I am right, but I feel good about what is going on. Not classes are Abstractions, but the whole layered pattern is Abstraction.

So seems issues should be closed :)

[helloserve]

No. The stuff about GC is interesting, and makes a lot of sense. The performance impact will obviously be massive compared to dealing with it boxed or as a class. But when you're talking about MyLogger and casting TState, you are on the other side of the abstraction, you are building something that implements the abstraction. I'm simply trying to use the abstraction, and test that my team is using it correctly and in the required branches in code.

So having FormattedLogValues internal while it is also on my side of the abstraction "wall" doesn't jive. And I don't see the convenience methods as part of the abstraction layer, anyway. They are simply shared code to make use of the abstraction, and my code is just as dependent on them as it would be if I wrote my own set of shared convenience methods. Except with these now I can't see half of what I'm depending on.

And whether these methods now use IReadOnlyList and later Span should make no difference, we as consumers still need to be able to test through these dependent implementations against the abstraction boundaries.

In your previous comment you suggested that Moq be made able to somehow match x.Log<FormattedLogValues> by x.Log<object>. I think there is a specific design philosophy in Moq (and other substitute frameworks) to only match exact on type. There are lots of cases where polymorphic behavior would result in false-positive unit testing otherwise.

So this leaves us stuck, unable to verify and unable to automate.

[dzmitry-lahoda]

It looks like Moq should support bottom-nothing-never like type in its generic type parameter DSL dotnet/csharplang#538 to allow match any generic (and they can do that with no language level support). It will be possible match that call happen. As soon as call happened, Moq should allow cast instance into (enforce cast as bottom cannot have instance) object or IReadOnlyList. IReadOnlyList you can check all params inside it. That looks like correct design for Moq, and nothing precludes Moq from doing so.

[helloserve]

I guess I'll go knock on their door, then. Thanks.

[stakx]

It looks like Moq should support [...]

FYI to anyone interested, Moq 4.13 (to be released shortly) will have support for generic type parameter matching. The above Verify can be written as:

_loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>())));

Note the use of It.IsAnyType, which will act as a type wildcard and match the (now internal) FormattedLogValues.

[thomaslevesque]

@Eilon

@helloserve can you show an example of "regular" code that would demonstrate this as a breaking change? Please note that if any types from a .Internal namespace were used, those are not supported.

The fact that it's not longer possible to assert the calls to ILogger.Log<TState> is a breaking change. Sure, there are workarounds, but they're not very convenient. Making FormattedLogValues public would be more pragmatic, even though it's conceptually an implementation detail.

[davidmilligan]

I agree with @thomaslevesque , just came across a similar issue. IMO it is a breaking change.

Please don't just brush this problem off as "well Moq should just get their stuff together". Moq has almost as many nuget downloads as Microsoft.Extensions.Logging.

@stakx That doesn't actually work :(

[stakx]

@davidmilligan - My apologies, I think I made a mistake with the last parameter. As per devlooped/moq#918 (comment), Moq doesn't support "nested" type matchers just yet, so for now you may be more lucky with:

-_loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), It.IsAny<Func<object, Exception, string>>())));
+_loggerMock.Verify(x => x.Log(LogLevel.Warning, It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()))));

[crgolden]

@stakx That worked for me - thanks!