Only first logging shows unless forcefully disposing

Question

I'm using vs 2017, writing a netcoreapp2.0 library, and testing it with a UnitTest project (XUnit and NUnit give same results).
I've noticed that unless I'm forcefully Disposing of my Serilog logger, only the first line will end up in Seq.

Here are my 2 classes. The library one:

public class Class1
{
    public static Logger _log;

    public Class1(Logger log)
    {
        _log = log;
        _log.Verbose("Class 1 constructor finished");
    }

    public void LogMessage(string s)
    {
        _log.Debug("Got message: {Message}", s);
    }
}

And the Unit test:

public class UnitTest1
{
    public static Logger _log = new LoggerConfiguration()
                                          .WriteTo.Seq("http://localhost:5341", Serilog.Events.LogEventLevel.Verbose)
                                          .MinimumLevel.Verbose()
                                          .CreateLogger();
    [Fact]
    public void Test1()
    {
        _log.Debug("Test 1 logging");
        var c = new Class1(_log);
        c.LogMessage("Logging from test");

        _log.Information("Test finished");

        _log.Dispose(); // Without this, only "Test 1 logging" is logged.
    }
}

Referenced assemblies (from unit test project):

<PackageReference Include="Microsoft.NET.Test.Sdk" Version="15.3.0-preview-20170628-02" />
<PackageReference Include="serilog" Version="2.5.0" />
<PackageReference Include="serilog.sinks.seq" Version="3.3.3" />
<PackageReference Include="xunit" Version="2.2.0" />
<PackageReference Include="xunit.runner.visualstudio" Version="2.2.0" />

Any suggestions?

(Here's a link to a demo project, open with vs 2017 restore the packages and run the test : demo project )

Champion

Answer 1

As per Stephen suggestions, the problem was the life scope of the logger.

Since I'm logging from a unit test class, I feel like disposing of the logger was wrong, but the solution was to change from using a class variable logger to using the static global logger.
That allows me to set it up once on test creation, and dispose of it once after all tests run :

[SetUpFixture]
public class TestsSetup
{
    [OneTimeSetUp]
    public void RunBeforeAnyTests()
    {
        Log.Logger = new LoggerConfiguration().Enrich.WithExceptionDetails()
                                              .WriteTo.Seq("http://localhost:5341")
                                              .MinimumLevel.Verbose()
                                              .CreateLogger();
    }

    [OneTimeTearDown]
    public void RunAfterAnyTests()
    {
        Log.CloseAndFlush();
    }
}

The main confusion I had was that the CloseAndFlush exists on the static one, but not on the ILogger you get when creating one with

Logger _log = new LoggerConfiguration()....

hence why i wasn't able to close and flush my variable one.

Champion

On the variable, you can just call Dispose() - it's the same thing essentially as CloseAndFlush(). HTH! – Picardi

@NicholasBlumhardt It surely does. Cheers mate. Currently for this unit test project the static logger works well the way I've done it, but good to know it can be done with a variable in a very similar way then. – Champion

Answer 2

It looks like you're running into the same problem as described in this blog post. The short of it is that you are responsible for disposing of your logger, which will flush its contents to the appropriate sink.

Kindhearted

True. True. I'll add my answer as well, since I had to do some more work – Champion

Answer 3

I found that results for Log.CloseAndFlush() were intermittent at best when using Serilog to write to Seq, only working when I stepped through in debug mode.

Even if I used IClassFixture and Dispose() to provide a teardown implementation for XUnit only the first message was appearing.

It turns out that the default setting for Serilog is to hold on to the logs for 2 seconds before sending, which means tests finish before logging has completed.

I got a fix from here in the end (although TimeSpan.Zero caused a runtime error for me, so I changed it to TimeSpan.FromMilliseconds(1)):

Log.Logger = new LoggerConfiguration()
    .WriteTo.Seq("http://localhost:5341", 
        period: TimeSpan.FromMilliseconds(1))
    .CreateLogger();

Weimaraner

ah, blast from the past ... have you raised a bug for the TimeSpan.Zero ? I'm sure Nick will have some quick turnover, but i'm assuming they have their reasons to hold the messages (perf probably?) – Champion