InMemorySink doesn't see log entries

[brentarias]

I have a plugin architecture where a half dozen plugins correctly find InMemorySink.Instance containing log entries...as expected. However, I have one plugin that uses the exact same code...but InMemorySink.Instance is empty. The screenshot below shows that the inmemory sink has indeed collected entries, but the static access point doesn't see them.

At the point where I call CreateLogger, I have run the following identity checks:

var assemblies = AppDomain.CurrentDomain.GetAssemblies().Where(x => x.GetName().Name.Contains("Serilog")).Select(x => x.Location);
var inmem = AppDomain.CurrentDomain.GetAssemblies().First(x => x.FullName.Contains("InMemory")).GetHashCode();
var hash = InMemorySink.Instance.GetHashCode();

When I run those same three checks at the location seen in the screenshot below, the results are as follows:

• The assembles var shows the InMemory assembly location is the same in both places.
• The inmem var shows that the hash code of the InMemory assembly is the same in both places.
• The hash var shows that the static InMemorySink.Instance has indeed changed values!

I conclude from this that there is no funny business regarding mismatched DLL's or DLL versions. Instead it seems that internally, InMemory is somehow overwriting its static value. This seems like a bug.

Please help. :)

[sandermvanvliet]

Hi @brentarias!

Internally the InMemorySink uses an AsyncLocal<T> to store its instance. Is the one plugin that doesn’t find the right instance perhaps initialised in an async context?

[brentarias]

I have an update. I found a workaround.

I'm using InMemorySink.Instance within the context of my MSTest automation. All of the MSTest automation routines are declared async. I became suspicious that InMemorySink.Instance might have tied object lifetime to a particular thread. So within my [TestInitialize] MSTest setup, immediately after configuring my dependency injection and logging, I grab and store InMemorySink.Instance into a class property. When all the actual tests run, each then uses that variable...and the problem was solved!

To say this differently, I chose to syphon off the InMemorySink.Instance value before any async/await routines were entered.

[brentarias]

To answer your question, the initialization is enacted within a unit test framework:

        [TestInitialize]
        public async Task Initialize() { // bla, bla, bla, blah }

So yes, I could say it is in an async context. All the test methods are also async. It is within the above method that I have chosen to "pre-capture" the InMemorySink value, before it becomes "corrupt" or lost.

[sandermvanvliet]

Ok that's indeed for MSTest the approach I usually take as well.
Glad you already found it.

[brentarias]

As of now I discovered that if I simply change the signature to remove async from my [TestInitialize] method...the problem goes away! None of my other plugins had async on their [TestInitialize] routine. So now I know why only one plugin was affected.

[sandermvanvliet]

Still good to know, I’ll see if I can do something about that because I imagine more people might bump into this

[brentarias]

All of my plugins have an associated plugin test project. All of those test projects use async test methods. So if you want to reproduce the problem, be sure to have an async test method joined with an async [TestInitialize] method.

[xavierjohn]

My solution was to wait before checking the log.

 await Task.Delay(100); // Giving time for logs to flush.
 var informationMessages = InMemorySink.Instance.Should()
        .HaveMessage("HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms")
        .WithLevel(LogEventLevel.Information)
        .Appearing().Times(2);

[sandermvanvliet]

@xavierjohn that's interesting, it should mean that the logger isn't flushed somehow.

I would imagine that a logger.Dispose() should do the trick too but I'll see if I can replicate that.

[nathan-alden-sr]

The real problem here is that InMemorySink is not thread-safe. Providing a static singleton instance is not really a good decision because it's possible for unit tests (or production code, for that matter) to be run in parallel depending on the library and configuration. This will lead to non-deterministic state inside Instance.

Without improvements to InMemorySink's API, a better way to use it is like this:

InMemorySink inMemorySink = new();
LoggerConfiguration loggerConfiguration = new();

loggerConfiguration.WriteTo.Sink(inMemorySink);

ILogger logger = loggerConfiguration.CreateLogger();

logger.Information("Hello, World!");

inMemorySink.LogEvents.Should().ContainSingle(a => a.MessageTemplate.Text == "Hello, World!");