search

serilog / serilog-sinks-periodicbatching

Infrastructure for Serilog sinks that process events in batches.
Apache License 2.0
71 stars 29 forks source link

Log.CloseAndFlush() causes PBS write to SelfLog #4

Closed nblumhardt closed 8 years ago

nblumhardt commented 8 years ago

In a short-running .NET Core RC2 console application using the Seq sink, the Log.CloseAndFlush() call functions correctly but causes the following output to be written to SelfLog.

2016-06-20T01:44:46.6165685Z The timer was canceled during invocation: System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at Serilog.Sinks.PeriodicBatching.PortableTimer.<Start>d__6.MoveNext()
colin-young commented 8 years ago

At the point I get into CloseAndFlush SelfLog isn't even available in the base class, at least when I'm debugging the MSSqlServer sink (SelfLog is not available in PBS either when stepping through or running code exercising the MSSqlServer sink). I do get SelfLog messages about failures to update the DB however. My SWAG is that this is some sort of threading issue, since if I do:

var loggerConfiguration = new LoggerConfiguration();
Log.Logger = loggerConfiguration.WriteTo.MSSqlServer(
    connectionString: DatabaseFixture.LogEventsConnectionString,
    tableName: DatabaseFixture.LogTableName,
    autoCreateSqlTable: true,
    batchPostingLimit: 1,
    period: TimeSpan.FromSeconds(10),
    columnOptions: new ColumnOptions())
    .CreateLogger();

var file = File.CreateText("Self.log");
Serilog.Debugging.SelfLog.Enable(TextWriter.Synchronized(file));

// act
const string loggingInformationMessage = "Logging Information message";
Log.Information(loggingInformationMessage);
Thread.Sleep(50);
Log.CloseAndFlush();

the message does make it into the DB log table (I arrived at a delay of 50 experimentally, and I have no idea how robust that is, but I suspect the answer is "not very"). It's almost like the object is being actually disposed before the code in CloseAndFlush gets a chance to execute.

I'm going to attempt to trace through it later using SelfLog.WriteLine("1"), SelfLog.WriteLine("2"), etc. to see if I can get some sense of what's going on.

nblumhardt commented 8 years ago

Expecting this is fixed by #8.