Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cannot verify calls to ILogger in .NET Core 3.0 Preview 8 (Generic Type Matcher doesn't work with Verify) #918

Closed
hannahchan opened this issue Sep 3, 2019 · 15 comments
Labels

Comments

@hannahchan
Copy link

@hannahchan hannahchan commented Sep 3, 2019

In .NET Core 2.2, I am able to use Moq to test calls made to an ILogger. For example the following code;

using System.Diagnostics;
using System.Net.Http;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;

namespace WebApi.HttpMessageHandlers
{
    public class RequestLoggingHttpMessageHandler : DelegatingHandler
    {
        private const string MessageTemplate = "Outbound HTTP {HttpMethod} {Uri} responded with {StatusCode} in {ElapsedMilliseconds}ms";

        private readonly ILogger logger;

        public RequestLoggingHttpMessageHandler(ILogger<RequestLoggingHttpMessageHandler> logger)
        {
            this.logger = logger;
        }

        protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            Stopwatch stopwatch = Stopwatch.StartNew();
            HttpResponseMessage response = await base.SendAsync(request, cancellationToken);
            stopwatch.Stop();

            int statusCode = (int)response.StatusCode;
            LogLevel logLevel = LogLevel.Information;

            if (statusCode < 200 || statusCode > 299)
            {
                logLevel = LogLevel.Warning;
            }

            if (statusCode >= 500)
            {
                logLevel = LogLevel.Error;
            }

            this.logger.Log(
                logLevel,
                MessageTemplate,
                request.Method,
                request.RequestUri,
                statusCode,
                stopwatch.ElapsedMilliseconds);

            return response;
        }
    }
}

could be tested with the following Xunit Theory;

using System;
using System.Net;
using System.Net.Http;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Moq;
using Xunit;

namespace WebApi.HttpMessageHandlers
{
    public class RequestLoggingHttpMessageHandlerUnitTests
    {
        [Theory]
        [InlineData(199, LogLevel.Warning)]
        [InlineData(200, LogLevel.Information)]
        [InlineData(299, LogLevel.Information)]
        [InlineData(300, LogLevel.Warning)]
        [InlineData(499, LogLevel.Warning)]
        [InlineData(500, LogLevel.Error)]
        [InlineData(501, LogLevel.Error)]
        public async Task When_SendingAsync_Expect_LogLevel(int statusCode, LogLevel expectedLogLevel)
        {
            // Arrange
            Mock<ILogger<RequestLoggingHttpMessageHandler>> mock = new Mock<ILogger<RequestLoggingHttpMessageHandler>>();

            // Act
            using (RequestLoggingHttpMessageHandler handler = new RequestLoggingHttpMessageHandler(mock.Object)
            {
                InnerHandler = new InnerHandler(statusCode),
            })
            using (HttpClient client = new HttpClient(handler))
            {
                (await client.GetAsync(new Uri("http://localhost"))).Dispose();
            }

            // Assert
            mock.Verify(
                m => m.Log(
                    expectedLogLevel,
                    It.IsAny<EventId>(),
                    It.IsAny<object>(),
                    null,
                    It.IsAny<Func<object, Exception, string>>()),
                Times.Once);
        }

        private class InnerHandler : DelegatingHandler
        {
            private readonly int statusCode;

            public InnerHandler(int statusCode)
            {
                this.statusCode = statusCode;
            }

            protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
            {
                return await Task.FromResult(new HttpResponseMessage { StatusCode = (HttpStatusCode)this.statusCode });
            }
        }
    }
}

However when targeting .NET Core 3.0 (Preview 8), Moq now fails to verify these calls. The reason these calls now fail is because there was a behaviour change in that the Type that is being passed in to the logger.Log() generic has changed. It is now the Internal type FormattedLogValues.

I noticed that Moq 4.13.0 introduced the generic type matcher It.IsAnyType. I tried to use it like this;

            mock.Verify(
                m => m.Log<It.IsAnyType>(
                    expectedLogLevel,
                    It.IsAny<EventId>(),
                    It.IsAny<It.IsAnyType>(),
                    null,
                    It.IsAny<Func<It.IsAnyType, Exception, string>>()),
                Times.Once);

Strangly it works in .NET Core 2.2 but is still failing in .NET Core 3.0 Preview 8.

@stakx

This comment has been minimized.

Copy link
Member

@stakx stakx commented Sep 3, 2019

@hannahchan: Thanks for reporting!

TL;DR: Not yet quite sure why it works in .NET Core 2.2, but with 3.0 Preview 8 it is due to the last parameter It.IsAny<Func<It.IsAnyType, Exception, string>>(), where the It.IsAnyType does not appear as a "top-level" generic type argument, but "inside" of a composite type. I'm planning to add support for that kind of thing eventually; for the moment, there's a fairly easy workaround:

        mock.Verify(
            m => m.Log(
                expectedLogLevel,
                It.IsAny<EventId>(),
                It.IsAny<It.IsAnyType>(),
                null,
-               It.IsAny<Func<It.IsAnyType, Exception, string>>()),
+               (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()),
            Times.Once);

The important bit (for now) is that It.IsAnyType is not used in a nested position in the It.IsAny<> type argument.

The new generic type argument matcher support in Moq is new, and one thing I decided to leave out for the first version (for performance reasons) is support for such "composite" / "nested" types. See #908 (comment), where I wrote:

[ ] Add support for composite types making use of type matchers, e.g. It.IsAnyType?, It.IsAnyType[], It.IsAnyType[,], IEnumerable<It.IsAnyType>, ref/in/out It.IsAnyType, etc. Same for custom matcher types. It's possible that this cannot be made to work with custom argument matchers.

Update: While that would be great, it would also negatively affect performance as every type parameter would have to be decomposed just to discover whether it includes a type matcher. For now, we're going the opposite direction and try to make type matcher discovery as fast as possible.

(Sorry for not making that clearer in the changelog or quickstart. I was quite excited to finally be able to get the feature out there so that people can start using it. But I suppose we could spend some more time on documentation. 😉)

@hannahchan

This comment has been minimized.

Copy link
Author

@hannahchan hannahchan commented Sep 3, 2019

Ah cool, thanks for your quick response. I'm very excited about this feature too. I can confirm that your suggested workaround works and that I'm happy with it. I guess you can close this issue now.

@KyleCraviotto

This comment has been minimized.

Copy link

@KyleCraviotto KyleCraviotto commented Sep 17, 2019

Can it be used also with the It.Is ?
I was using it before like
It.Is<FormattedLogValues>(v => v.ToString().Contains(message))

with .NET Core 3 and Moq 4.13.0

It.Is<It.IsAnyType>(v => v.ToString().Contains(message))

does not seem to work, I get the following: It is impossible to call the provided strongly-typed predicate due to the use of a type matcher. Provide a weakly-typed predicate with two parameters (object, Type) instead. (Parameter 'match')
What are my options if I want to validate the value of the AnyType?

@stakx

This comment has been minimized.

Copy link
Member

@stakx stakx commented Sep 17, 2019

What are my options if I want to validate the value of the AnyType?

Think about it: AnyType is a type placeholder. At runtime, there will never be an actual argument of that type. So it doesn't make sense to have a predicate that tests an AnyType argument... where could such a value possibly come from?

Do what the error message tells you to do and rewrite the It.Is as follows:

-It.Is<It.IsAnyType>(v => v.ToString().Contains(message))
+It.Is<It.IsAnyType>((object v, Type _) => v.ToString().Contains(message))

but it might be simpler in this case to just write It.Is<object>(v => ...).

@KyleCraviotto

This comment has been minimized.

Copy link

@KyleCraviotto KyleCraviotto commented Sep 17, 2019

Thanks for that, just doing It.Is<object>(v => ...) doesn't work because of ambiguity in the method.
Your suggestion It.Is<It.IsAnyType>((object v, Type _) => v.ToString().Contains(message))
works great though, thanks

@nphmuller

This comment has been minimized.

Copy link

@nphmuller nphmuller commented Sep 18, 2019

A bit of information that might be related to why this worked in ASP.NET Core 2.2 and not in ASP.NET Core 3.0: FormattedLogValues was changed from a class to a struct in .NET Core 3.0.

@basslagter

This comment has been minimized.

Copy link

@basslagter basslagter commented Sep 24, 2019

Does not seem to be working:
_loggerMock.Verify(l => l.Log(LogLevel.Error, It.IsAny<EventId>(), It.Is<It.IsAnyType>((object v, Type _) => true), null, It.IsAny<Func<object, Exception, string>>()));

Getting "Expected invocation on the mock at least once, but was never performed: l => l.Log(LogLevel.Error, It.IsAny(), It.Is<It.IsAnyType>((v, _) => True), null, It.IsAny<Func<object, Exception, string>>()))"

@sergiomcalzada

This comment has been minimized.

Copy link

@sergiomcalzada sergiomcalzada commented Sep 25, 2019

The problem is with the "Func<>". Thats works

mock.Verify(
                x => x.Log(
                        It.IsAny<LogLevel>(),
                        It.IsAny<EventId>(),
                        It.Is<It.IsAnyType>((v,t) => true),
                        It.IsAny<Exception>(),
                        It.Is<Func<It.IsAnyType, Exception, string>>((v,t) => true))
@leosvelperez

This comment has been minimized.

Copy link

@leosvelperez leosvelperez commented Oct 16, 2019

I'm trying to setup a callback and it's not working. I tried with different configurations:

  1. The following doesn't execute the callback:
logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), It.IsAny<Func<It.IsAnyType, Exception, string>>()))
    .Callback(
        (LogLevel logLevel, EventId eventId, It.IsAnyType state, Exception error, Func<It.IsAnyType, Exception, string> formatter) =>
        {
            // some code
        });
  1. The following throws System.ArgumentException : Object of type 'Microsoft.Extensions.Logging.FormattedLogValues' cannot be converted to type 'Moq.It+IsAnyType':
logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.Is<It.IsAnyType>((v, t) => true), It.IsAny<Exception>(), It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)))
    .Callback(
        (LogLevel logLevel, EventId eventId, It.IsAnyType state, Exception error, Func<It.IsAnyType, Exception, string> formatter) =>
        {
            // some code
        });
  1. The following throws Invalid callback. Setup on method with parameters (LogLevel, EventId, It.IsAnyType, Exception, Func<It.IsAnyType, Exception, string>) cannot invoke callback with parameters (LogLevel, EventId, object, Exception, Func<object, Exception, string>):
logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), It.IsAny<Func<It.IsAnyType, Exception, string>>()))
    .Callback(
        (LogLevel logLevel, EventId eventId, object state, Exception error, Func<object, Exception, string> formatter) =>
        {
            // some code
        });
  1. The following throws the same Invalid callback. Setup on method with parameters (LogLevel, EventId, It.IsAnyType, Exception, Func<It.IsAnyType, Exception, string>) cannot invoke callback with parameters (LogLevel, EventId, object, Exception, Func<object, Exception, string>):
logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.Is<It.IsAnyType>((v, t) => true), It.IsAny<Exception>(), It.Is<Func<It.IsAnyType, Exception, string>>((v, t) => true)))
    .Callback(
        (LogLevel logLevel, EventId eventId, object state, Exception error, Func<object, Exception, string> formatter) =>
        {
            // some code
        });

Does anyone know what I'm doing wrong or if it's possible to do this at all?

@stakx

This comment has been minimized.

Copy link
Member

@stakx stakx commented Oct 16, 2019

@stakx stakx added the question label Oct 16, 2019
@leosvelperez

This comment has been minimized.

Copy link

@leosvelperez leosvelperez commented Oct 16, 2019

@stakx thanks for pointing to that comment, I missed that. However, I did try the workaround suggested in there and I still can't get it to work. I tried a couple of variations in the Callback signature:

  1. The following throws Invalid callback. Setup on method with parameters (LogLevel, EventId, It.IsAnyType, Exception, Func<It.IsAnyType, Exception, string>) cannot invoke callback with parameters (LogLevel, EventId, object, Exception, Func<object, Exception, string>)
logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()))
    .Callback(
        (LogLevel logLevel, EventId eventId, object state, Exception error, Func<object, Exception, string> formatter) =>
        {
            // some code
        });
  1. The following throws System.ArgumentException : Object of type 'Microsoft.Extensions.Logging.FormattedLogValues' cannot be converted to type 'Moq.It+IsAnyType'.
logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()))
    .Callback(
        (LogLevel logLevel, EventId eventId, It.IsAnyType state, Exception error, Func<It.IsAnyType, Exception, string> formatter) =>
        {
            // some code
        });

Edit: I tried using the InvocationAction and that way the Callback is correctly invoked:

logger
    .Setup(f => f.Log(It.IsAny<LogLevel>(), It.IsAny<EventId>(), It.IsAny<It.IsAnyType>(), It.IsAny<Exception>(), (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()))
    .Callback(new InvocationAction(invocation =>
        {
            // some code
        }));

I'm still not able to use the formatter parameter int the Log function because of the internal struct but I can use the rest of the parameters.

@stakx

This comment has been minimized.

Copy link
Member

@stakx stakx commented Oct 19, 2019

@leosvelperez - I see. You appear to be assuming that Moq lets you use an object parameter in your callback function in places where you use a It.IsAnyType in the setup expression. That is not currently the case... but I'm planning to implement this kind of "type erasure" in the next iteration.

For now, you could specify a .Callback(() => ...) (if you don't need to access the arguments), or .Callback(IInvocation invocation => ...) (if you do need to access arguments).

Again, I am planning to make things a little easier for everyone by allowing object in callbacks for those parameters where matching involves It.IsAnyType (or any other custom matcher, for that matter)... see #953, and look out for the next minor version release.

@stakx

This comment has been minimized.

Copy link
Member

@stakx stakx commented Oct 19, 2019

I'm going to close this issue since this problem has been solved. I'm aware that the new type matcher feature is still a little rough around the edges; however, one Q&A-style issue like this one cannot replace proper documentation (which is sorely needed). Do open new issues if you keep having problems with type matchers. We'll eventually get there.

@granadacoder

This comment has been minimized.

Copy link

@granadacoder granadacoder commented Jan 22, 2020

Has anyone figured out the CallBack magic syntax yet?

I've tried everything leosvelperez tried. Plus all the interfaces in the definition of FormattedLogValues .

Aka, all the thing below.

internal readonly struct FormattedLogValues : IReadOnlyList<KeyValuePair<string, object>>, IEnumerable<KeyValuePair<string, object>>, IEnumerable, IReadOnlyCollection<KeyValuePair<string, object>>

Has anyone gotten .Callback to work yet?

Looping over the IInvocation invocation .Arguments ........seems wrong in today's world (early 2020 at the time of writing this)

@granadacoder

This comment has been minimized.

Copy link

@granadacoder granadacoder commented Jan 22, 2020

If anyone could help, it would be greatly appreciated.

Something else I tried below (uncommented code)... to hopefully avoid looking and casting the invocation.Arguments (commented out code).

        Mock<Microsoft.Extensions.Logging.ILogger<It.IsAnyType>> mockLogger = new Mock<Microsoft.Extensions.Logging.ILogger<It.IsAnyType>>(MockBehavior.Strict);

        mockLogger.Setup(
        m => m.Log<It.IsAnyType>(
                It.IsAny<Microsoft.Extensions.Logging.LogLevel>(),
                It.IsAny<Microsoft.Extensions.Logging.EventId>(),
                It.Is<It.IsAnyType>((v, t) => true),
                It.IsAny<Exception>(),
                (Func<It.IsAnyType, Exception, string>)It.IsAny<object>()))
                .Callback((Microsoft.Extensions.Logging.LogLevel logLevel, Microsoft.Extensions.Logging.EventId eventId, System.Collections.Generic.IEnumerable<System.Collections.Generic.KeyValuePair<string, object>> t, Exception ex, Func<System.Collections.Generic.IEnumerable<System.Collections.Generic.KeyValuePair<string, object>>, Exception, string> formatter) =>
                {
                    Console.WriteLine(logLevel);
                    Console.WriteLine(eventId);

                })
                ////////.Callback(new InvocationAction(invocation =>
                ////////{

                ////////        Console.WriteLine(invocation);

                ////////        if (null != invocation.Arguments[0])
                ////////        {
                ////////            Microsoft.Extensions.Logging.LogLevel enumVal = (Microsoft.Extensions.Logging.LogLevel)Enum.Parse(typeof(Microsoft.Extensions.Logging.LogLevel), Convert.ToString(invocation.Arguments[0]));


                ////////        }


                ////////        if (null != invocation.Arguments[2])
                ////////        {
                ////////            IEnumerable<KeyValuePair<string, object>> castItems = invocation.Arguments[2] as IEnumerable<KeyValuePair<string, object>>;
                ////////            if (null != castItems)
                ////////            {
                ////////                //   foreach (KeyValuePair<string, object> item in castItems)
                ////////                //   {
                ////////                //   }
                ////////            }
                ////////        }

                ////////        if (null != invocation.Arguments[3])
                ////////        {
                ////////            Exception castItem = invocation.Arguments[3] as Exception;
                ////////            if (null != castItem)
                ////////            {

                ////////            }
                ////////}))



                .Verifiable();
ferantivero added a commit to mspnp/microservices-reference-implementation that referenced this issue Feb 3, 2020
…NET Core 3.1

migrate Fabrikam.DroneDelivery.DeliveryService to ASP.NET Core 3.1

- migrate Fabrikam.DroneDelivery.Common to .NET Core 3.1
- migrate Fabrikam.DroneDelivery.DeliveryService to .NET Core 3.1
- remove view support
- migrate Fabrikam.DroneDelivery.DeliveryService.Tests to .NET Core 3.1
- migrate TestServer to .NET Core 3.1
- change assert from NotFound to MethodNotAllowed. For more information: dotnet/aspnetcore#11260 (comment)
- fix unsupported deserialization in the new System.Text.Json. For more information: https://github.com/dotnet/corefx/issues/38569#issuecomment-502957651
- fix global logger middleware tests. For more information: moq/moq4#918

solved: #160880
ferantivero added a commit to mspnp/microservices-reference-implementation that referenced this issue Feb 3, 2020
…NET Core 3.1

migrate Fabrikam.DroneDelivery.DeliveryService to ASP.NET Core 3.1

- migrate Fabrikam.DroneDelivery.Common to .NET Core 3.1
- migrate Fabrikam.DroneDelivery.DeliveryService to .NET Core 3.1
- remove view support
- migrate Fabrikam.DroneDelivery.DeliveryService.Tests to .NET Core 3.1
- migrate TestServer to .NET Core 3.1
- change assert from NotFound to MethodNotAllowed. For more information: dotnet/aspnetcore#11260 (comment)
- fix unsupported deserialization in the new System.Text.Json. For more information: https://github.com/dotnet/corefx/issues/38569#issuecomment-502957651
- fix global logger middleware tests. For more information: moq/moq4#918

solved: #160880
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
8 participants
You can’t perform that action at this time.