serilog-contrib / SerilogSinksInMemory

In-memory sink for Serilog to use for testing
MIT License
53 stars 7 forks source link

Random ArgumentException on Should extension method #29

Closed nahuelgq closed 1 year ago

nahuelgq commented 2 years ago

I have a problem when making integration tests using InMemorySink. An ArgumentException raises randomly when we execute "Should()" extension method over InMemorySink.

Error Message:
    System.ArgumentException : Destination array was not long enough. Check the destination index, length, and the array's lower bounds. (Parameter 'destinationArray')
   Stack Trace:
      at System.Array.Copy(Array sourceArray, Int32 sourceIndex, Array destinationArray, Int32 destinationIndex, Int32 length, Boolean reliable)
    at System.Collections.Generic.List`1.CopyTo(T[] array, Int32 arrayIndex)
    at System.Collections.ObjectModel.ReadOnlyCollection`1.CopyTo(T[] array, Int32 index)
    at System.Collections.Generic.List`1..ctor(IEnumerable`1 collection)
    at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source)
    at Serilog.Sinks.InMemory.Assertions.InMemorySinkAssertions.SnapshotOf(InMemorySink instance)
    at Serilog.Sinks.InMemory.Assertions.InMemorySinkAssertions..ctor(InMemorySink instance)
    at Serilog.Sinks.InMemory.Assertions.InMemorySinkAssertionExtensions.Should(InMemorySink instance)
    at api_transferencias_empresas.Test.Unit.MetadataLoggerTestExtensions.VerifyLoggedOnceWithMetadata(InMemorySink logResults, LogEventLevel level, EventId eventId, String message) in /builds/desarrollo/productos-transaccionales/api-transferencias-empresas/Test/api_transferencias_empresas.Test.Unit/MetadataLoggerTestExtensions.cs:line 52

This is how we use it: image

Am I doing something wrong? Thanks you

sandermvanvliet commented 2 years ago

Hm that's an odd one for sure. Could you perhaps tell me if you're sending a lot of messages to the sink or have many tests running at the same time?

It almost feels like the snapshot is started but the collection is somehow changed.

sandermvanvliet commented 2 years ago

Version 0.7.0 contains a fix for this that should make this problem disappear. I hope it works as expected because I found it very hard to come up with a repro case. Let me know how it works for you

nahuelgq commented 2 years ago

Thanks you for the reply! I'll update the package!

Answering to your question, this is the average sink use: It has 11 entries, and here is the resume.

{System.Linq.Enumerable.SelectIListIterator<Serilog.Events.LogEvent, string>} [0]: "Application started. Press Ctrl+C to shut down. - Properties Count 1, Properties content length: 28" [1]: "Hosting environment: {envName} - Properties Count 2, Properties content length: 42" [2]: "Content root path: {contentRoot} - Properties Count 2, Properties content length: 101" [3]: "{HostingRequestStartingLog:l} - Properties Count 17, Properties content length: 441" [4]: "Comenzando invocación - Properties Count 7, Properties content length: 1523" [5]: "Executing endpoint '{EndpointName}' - Properties Count 9, Properties content length: 277" [6]: "Executed endpoint '{EndpointName}' - Properties Count 9, Properties content length: 283" [7]: "Devolviendo respuesta - Properties Count 7, Properties content length: 422" [8]: "Request - Properties Count 8, Properties content length: 1347" [9]: "Response - Properties Count 8, Properties content length: 399" [10]: "{HostingRequestFinishedLog:l} - Properties Count 11, Properties content length: 233"

Ive extracted the info with this query from the inmediate window: logResults.LogEvents.Select(x=>x.MessageTemplate + " - Properties Count " + x.Properties.Count + ", Properties content length: " + string.Join("|", x.Properties.Select(p=>p.Value.ToString())).Length)

On the other hand my tests should run sequentially, but I supose I have some trouble with cleaning state between tests. I couldn't follow your recomendation to dispose the sink between creating the Logger, but I try to do it like this:

using Microsoft.AspNetCore.Hosting;
using Microsoft.AspNetCore.Mvc.Testing;
using Microsoft.Extensions.Configuration;
using Serilog;
using Serilog.Sinks.InMemory;
using System.IO;
using static Serilog.Sinks.InMemory.InMemorySink;

namespace api_transferencias_empresas.Test.Integration
{
    public class TestFixture : WebApplicationFactory<Startup>
    {
        public IConfigurationRoot ConfigurationRoot { get; private set; }

        protected override void ConfigureWebHost(IWebHostBuilder builder)
        {
            ConfigurationRoot = new ConfigurationBuilder()
                .SetBasePath(Directory.GetCurrentDirectory())
                .AddJsonFile("appsettings.json")
                .Build();

            builder.ConfigureAppConfiguration((context, config) =>
            {
                config.SetBasePath(Directory.GetCurrentDirectory()).AddJsonFile("appsettings.json");
            })
            .UseSerilog((context, config) =>
            {
                config.WriteTo.InMemory();
            });
        }

        protected override void Dispose(bool disposing)
        {
            base.Dispose(disposing);
            Instance?.Dispose();
        }
    }
}