LogEntry.Scope returns the most recent scope rather than the current scope.

[wainwrightmark]

Hi, first of all I love the library and the documentation. Thanks for making it.

The scope property on the LogEntry doesn't seem to be doing quite the right thing. The documentation says it should return the most inner scope but it actually seems to return the most recent scope, even if that scope has been closed.

I think the following test should pass (using MELT.Xunit 0.6.0 and also FluentAssertions)

[Fact]
public void LogEntryScopeShouldBeMostInnerOpenScope()
{
    var loggerFactory = TestLoggerFactory.Create();
    loggerFactory.AddXunit(TestOutputHelper);

    var logger = loggerFactory.CreateLogger("Test");

    using (logger.BeginScope("Outer Scope"))
    {
        logger.LogInformation("Message 1");
        using (logger.BeginScope("Inner Scope"))
        {
            logger.LogInformation("Message 2");
        }
        logger.LogInformation("Message 3");
    }

    loggerFactory.Sink.LogEntries
        .Should()
        .SatisfyRespectively(
            CheckMessageAndScope("Message 1", "Outer Scope"),
            CheckMessageAndScope("Message 2", "Inner Scope"),
            CheckMessageAndScope("Message 3", "Outer Scope")
        );

    static Action<LogEntry> CheckMessageAndScope(string expectedMessage, string expectedScope)
    {
        return entry =>
        {
            entry.Message.Should().Be(expectedMessage);
            entry.Scope.Message.Should().Be(expectedScope);
        };
    }
}

I get

Xunit.Sdk.XunitException
Expected collection to satisfy all inspectors, but some inspectors are not satisfied:
    At index 2:
        Expected entry.Scope.Message to be 
        "Outer Scope", but 
        "Inner Scope" differs near "Inn" (index 0)
...

<Scope: Outer Scope>
   Information [0]: Message 1
   <Scope: Inner Scope>
      Information [0]: Message 2
   </Scope: Inner Scope>
   Information [0]: Message 3
</Scope: Outer Scope>

Is this a legitimate issue or am I missing something. I would be willing to try and fix the issue myself if necessary.

Thanks

[alefranz]

Hi Mark, Thanks for reaching out.

That is the implemented behaviour and the documentation is incorrect, and should probably be rephrased as you titled this issue. The logger doesn't keep track of the lifecycle off all the scopes, it only captures the latest one. I had a look at implementing this a while back, but I had the impression it would have required an overhaul of the library to implement it properly, as it would require to track scopes across multiple loggers (in a thread-safe manner), while currently the scope is captured by the logger itself. I didn't feel confident to have a simple implementation which would not have handled more complex scenarios which multiple loggers involved, but I guess from your raised issue that even the current behavior it is a bit surprising.

There is support to test the invocation of BeginScope, but even that would not allow you to achieve the test coverage you are looking for.

I will have a look at some possible ways to implement this, but feel free to chime in if you have any suggestion.

Thank you, Alessio

[wainwrightmark]

Ah, I had a suspicion that might be the case. If we can't fix this issue it might be worth making that explicit in the documentation.

Just looking at the code, my instinct would be to change the _scope object on the TestLogger to be an ImmutableStack<object> and to give the scope object a callback that pops the stack when it is disposed.

I'll try making those changes and see if that works for my use case but there would still be more work to be done

• There's a potential race condition if the same ILogger is being used on different threads
• I don't know what the behaviour is supposed to be if scopes are exited in the wrong order
• There are probably issues that I haven't thought of

[alefranz]

The list of active scopes needs to be maintained in a shared place (e.g. sink) as scopes can be created on different loggers and when a log entry is captured you would need to sort of snapshot the stack of scopes. Yes, it needs to be a thread safe data structure. Disposing out of order is not necessarily a problem to handle (but maybe nice to fail the tests when that happen?) as it is not a supported behaviour which most loggers don't handle.

[lostincomputer]

To add to this ticket, loggerFactory.Sink.Scopes is keeping the disposed scopes which I think is wrong.

using (loggerFactory.CreateLogger("Test").BeginScope("Inner Scope"))
{}

loggerFactory.Sink.Scopes; // Still contains "Inner Scope"

[wainwrightmark]

That was intentional - I didn't want to break existing behaviour. The CurrentScopes property should contain only the scopes which haven't yet be disposed. We could rename all this if you don't mind breaking backwards compatibility.

[lostincomputer]

Cool! I didn't know that you already have a PR that addresses these issues. I can't wait for it to get merged.

I don't mind breaking backwards compatibility but take my opinion with a grain of salt because I'm not a maintainer.

[alefranz]

This has been fixed in 0.7.0, as well as adding what @wainwrightmark mentioned (although called Scopes). Thanks @wainwrightmark for the help and please both let me know how it goes.