No Log Entries in Level Filtered Factory / Empty Scope Properties :(

[CodeRedPaul]

Hi there

Let me start with saying that I think this is an amazing project! I wasn't holding out much hope that I could test my log scopes, but there this was, sitting in third place in that repository of all human knowledge, Google.

I'm experiencing an issue though. Following the quickstart would seem to indicate all I need to do is:

1. Create a factory, like this: var loggerFactory = TestLoggerFactory.Create();
2. Create a logger, like this: var logger = loggerFactory.CreateLogger<TestClass>();

I'm then creating a new instance of the service I wish to test and calling the appropriate method with my mocks and logger etc.

Here's the full test:

[Fact]
public async Task ScopeTest()
{
    var loggerFactory = TestLoggerFactory.Create();
    var logger = loggerFactory.CreateLogger<TestClass>();

    var listenerServiceHelper = new ListenerServiceHelper<TestClass, TestEnum>(
            _context.MessageHandlerMock.Object,
            _context.ConfigurationMock.Object,
            logger,
            _context.RequiredConfigResolverMock.Object
        );

    var message = new Message
    {
        MessageId = MESSAGE_ID
    };

    var cancellationToken = new CancellationToken(false);

    await listenerServiceHelper.HandleMessage(message, _context.TopicCollectorMock.Object, cancellationToken);

    var logEntry = Assert.Single(loggerFactory.Sink.LogEntries);
}

What I'm confused about is that the log factory assert fails despite the fact that I've stepped through the code in debug mode and confirmed that my function is setting a scope and also calling the log.LogTrace extension method:

using (_log.BeginScope(new Dictionary<string, object>
{
    {"messageId", message.MessageId}
}))
{

    _log.LogTrace(
        $"Azure Function successfully triggered for a message with a MessageId of '{message.MessageId}' "
        + $"via the '{GetRequiredConfig(RequiredConfigKeys.TopicName)}' subscription on the '{GetRequiredConfig(RequiredConfigKeys.TopicName)}' topic.");

    await MessageHandler.HandleMessage(message, topicCollector);

}

The result is thus:

The quickstart is pretty simple and I'm fairly confident I've not stuffed it up. I've also checked the version of Microsoft.Extensions.Logging and it's 2.1.0.

Is there something that I'm missing?

Cheers,

Paul

[CodeRedPaul]

Ok, so I just read a different issue logged here and I realised what I was missing... The log level! As my function is calling _log.LogTrace the logger is correctly bypassing it, so there's no log items or scope.

There still appears to be an issue though...

If I change my function to log Information instead, _log.LogInformation and set the factory logger options to have a minimum level of 'information', TestLoggerFactory.Create(options => options.FilterByMinimumLevel(LogLevel.Information)), then my test case passes:

However, if I revert my function back to _log.LogTrace and set the minimum log level to LogLevel.Trace then the logger appears to not put the log into the sink:

Any ideas what's going on here?

Cheers,

Paul

[CodeRedPaul]

And... Sorry, but I have another challenge and rather than create a whole new issue and have to set the context again, I'm being lazy and adding it here...

I can't seem to verify the scope properties. I've tried a few ways of getting scope, but the properties collection returned just appears to be empty each time.

As you can see from the below screenshot, the logEntry.Scope.Properties has a count of 0, but if I inspect the private members, I can clearly see the 'messageId' and 'policyId' items that we defined in the scope in my function:

For clarity, here's an excerpt of my test case code:

var logEntry = Assert.Single(loggerFactory.GetTestLoggerSink().LogEntries);

// ReSharper disable once PossibleNullReferenceException
LoggingAssert.Contains("messageId", MESSAGE_ID, logEntry.Scope.Properties);

I've used loggerFactory.GetTestLoggerSink() above as that's what's used in the sample code.

Ultimately I've tested various ways of getting the scope and in each case the properties are empty:

Can anyone please explain why in each case the scope properties is empty whilst the private _scope collection contains the defined items?

Cheers,

Paul

[alefranz]

Hi Paul, I'm glad you have found this library useful! and I'm sorry for all the problems you had with it.

I've released a preview version to address both issues as with all the context you provided it was really easy to get to the bottom of it.

The log level issue is due to an implicit default of the minimum level of the LoggerFactory at Information level. The scope issue is due to the wrapper, used to simplify testing the scope, casting to IReadOnlyList<KeyValuePair> instead of IEnumerable<KeyValuePair>, which of course was failing for a dictionary.

Please let me know how if goes if you have a chance to test 0.6.0-preview.1

I need a few days to review it properly before release as it contains a breaking change.

Thank you, Alessio

[CodeRedPaul]

Hi Alessio

LOOK AT ALL THE GREEN!

Awesome work Alessio!

Seriously, this is a super amazing project. In production we're likely to be getting c. 500,000 log events per day, so being able to test that the structed logging for this is behaving as expected is going to be critical. But over and above that, I just plain love what you've done here.

Thanks so much Alessio for getting on it and making the fixes so quickly. Where do I give the 5 start rating? Hmm... this will have to do: 🥇

Thanks again,

Paul

[alefranz]

😂 I'm glad it worked!

Thanks to you to giving it a shot. It's based on the testing code in use internally in the ASP.NET Core project, I've simply made it a bit easier to use and repackaged it.

I'll update the issue once I release the fix.

[menees]

Thanks! The Scope.Properties fix in 0.6.0-preview.1 was just what I needed too!

[alefranz]

I've finally released 0.6.0!!! 🥳 🎈

[CodeRedPaul]

Love your work Alessio! Thanks so much.