serilog-sinks-azure-analytics icon indicating copy to clipboard operation
serilog-sinks-azure-analytics copied to clipboard

Missing Final Logs During Proper Disposal

Open phehr2 opened this issue 2 years ago • 0 comments

Describe the bug A race condition within the BatchProvider Dispose method prevents final logs from being written in some cases. Sometimes the log messages are written successfully, and other times they are not. When they are not written successfully, a SelfLog message is written with the InvalidOperationException message: "The collection argument is empty and has been marked as complete with regards to additions." This message is indicative of the scenario where .Take() is called on a BlockingCollection that is already completed and empty.

To Reproduce Create a .NET background service that logs to a default AzureAnalytics sink. Enable SelfLog logging. Example Program.cs

Start and stop the process and review the SelfLog to identify when the issue occurs. The exception is thrown from this line: https://github.com/saleem-mirza/serilog-sinks-azure-analytics/blob/d71b5ef4e4c59481d4e3c8efcb52912321b98614/src/Serilog.Sinks.AzureAnalytics/Sinks/Batch/BatchProvider.cs#L211 and caught/logged at this line: https://github.com/saleem-mirza/serilog-sinks-azure-analytics/blob/d71b5ef4e4c59481d4e3c8efcb52912321b98614/src/Serilog.Sinks.AzureAnalytics/Sinks/Batch/BatchProvider.cs#L219

I've been able to reproduce more frequently when running the application within an Linux Docker container than I have when running on my Windows desktop in Visual Studio.

Expected behavior During logger disposal, all pending log messages should be written to the Azure Log Analytics Workspace. None should be missed.

Screenshots SelfLog under successful scenario:

2022-11-14 12:26:26 2022-11-14T17:26:26.9434885Z Sending batch of 4 logs
2022-11-14 12:26:28 2022-11-14T17:26:28.0408606Z Transferring log: [OK]
2022-11-14 12:26:30 2022-11-14T17:26:30.7587179Z Halting sink...
2022-11-14 12:26:30 2022-11-14T17:26:30.7589542Z Sending batch of 2 logs
2022-11-14 12:26:30 2022-11-14T17:26:30.8118136Z Transferring log: [OK]
2022-11-14 12:26:30 2022-11-14T17:26:30.8120412Z Sink halted successfully.

SelfLog under unsuccessful scenario:

2022-11-14 12:27:34 2022-11-14T17:27:34.4925474Z Sending batch of 4 logs
2022-11-14 12:27:35 2022-11-14T17:27:35.3973612Z Transferring log: [OK]
2022-11-14 12:27:46 2022-11-14T17:27:46.4924008Z Halting sink...
2022-11-14 12:27:46 2022-11-14T17:27:46.4935898Z The collection argument is empty and has been marked as complete with regards to additions.
2022-11-14 12:27:46 2022-11-14T17:27:46.4936554Z Sink halted successfully.

phehr2 avatar Nov 15 '22 00:11 phehr2