MitchBodmer / serilog-sinks-testcorrelator

A Serilog sink that correlates log events with the code that produced them, enabling unit testing of log output.
MIT License
87 stars 9 forks source link

OutOfMemory Exception when using ILogger Extension Methods #60

Closed ahahn95 closed 4 years ago

ahahn95 commented 4 years ago

When I use extension methods for ILogger, I get the below error message (but not on my serilog tests, it's usually during other tests in my pipeline, which is confusing to me because I would think that tests are self enclosed).

Is this a bug or am I implementing my extension methods incorrectly?

Also, everything seems to work fine without the extension methods.

The error message is

##[error][xUnit.net 00:04:55.36]     Org.Test.PasswordManagement.WhenPasswordReset.ThenCorrect(isInCorporateManagement: True, expectedResult: True) [FAIL]
[xUnit.net 00:04:55.36]       System.InvalidOperationException : Failed to set Database.DefaultConnectionFactory to an instance of the 'System.Data.Entity.Infrastructure.SqlConnectionFactory, EntityFramework' type as specified in the application configuration. See inner exception for details.
[xUnit.net 00:04:55.36]       ---- System.OutOfMemoryException : Exception of type 'System.OutOfMemoryException' was thrown.
[xUnit.net 00:04:55.37]       Stack Trace: ...

My test method is

[Fact]
        public void TestLogWithApplicationId()
        {
           Log.Logger = new LoggerConfiguration().WriteTo.TestCorrelator().CreateLogger();

            using (TestCorrelator.CreateContext())
            {

                Log.Logger.LogWithApplicationIdExtension(
                    LogEventLevel.Information, 
                    4, 
                    "The {organelle} is the powerhouse of the {cell}", 
                    "mitochondria",
                    "cell");

                TestCorrelator.GetLogEventsFromCurrentContext()
                                .Should().ContainSingle()
                                .Which.RenderMessage()
                                .Should().Be("Application ID [4]: The \"mitochondria\" is the powerhouse of the \"cell\"");
            }
        }

My extension method looks like

private static object[] PropertyValuesHelper(int id, params object[] propertyValues)
        {
            var arr = new object[propertyValues.Length + 1];
            arr[0] = id;
            Array.Copy(propertyValues, 0, arr, 1, propertyValues.Length);
            return arr;
        }

        public static void LogWithApplicationIdExtension(this ILogger logger, LogEventLevel severity,
            int id, string template, params object[] propertyValues)
        {
            object[] propertyValuesWithId = PropertyValuesHelper(id, propertyValues);
            logger.Write(severity, "Application ID [{id}]: " + template, propertyValuesWithId);
        }
MitchBodmer commented 4 years ago

How many log events are you emitting? This sink keeps all log events written to the TestCorrelator in memory so that it can give them back to you for asserts. If you're logging a ton of events, or those events have large property payloads, you will run out of memory.

Your extension method adds property payload, so I'd assume that is why you run out of memory.

ahahn95 commented 4 years ago

I'm only logging that one message once. When you say property payload, do you mean the propertyValues arguments that I have? Also, I would think that the TestCorrelator would not be running anymore, since this test has already passed, but as you can see, it's causing unit tests that come like 10 tests later to fail.

MitchBodmer commented 4 years ago

Yep that's what I mean.

You're setting the global static logger to use the TestCorrelator. That means everything that uses that logger will write there. Log.Logger is a global static resource. If you're really just interested in testing the extension method, create a new logger, but don't assign it to Log.Logger.

There is a performance improvement to be made here that I've been putting off for a while just because testing it is a bit difficult. The change would be that log events that aren't emitted within a context are not stored. I'll create an issue to track that enhancement.

ahahn95 commented 4 years ago

Great, thank you a ton for the quick responses!