search

datalust / serilog-sinks-seq

A Serilog sink that writes events to the Seq structured log server
https://datalust.co/seq
Apache License 2.0
225 stars 50 forks source link

Strange issue which causes the Seq sink to stop working #100

Closed 80dB closed 6 years ago

80dB commented 6 years ago

I'm not entirely sure what changed in the application that could cause this issue. But after starting the app for a few minutes, the Seq logger throws this exception (logged using selflog) :

2018-01-05T21:32:24.5935845Z Exception while emitting periodic batch from Serilog.Sinks.Seq.SeqSink: 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.Seq.SeqSink.<EmitBatchAsync>d__14.MoveNext() --- End of stack trace from previous location where exception was thrown --- at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) at Serilog.Sinks.PeriodicBatching.PeriodicBatchingSink.<OnTick>d__16.MoveNext()

At that point nothing is logged in Seq anymore. It also seems (but not 100% sure) that the sink keeps queueing items but because nothing gets send, the application runs out of memory.

There's also a file sink and that one keeps running just fine (as does the application, until it runs out of memory).

Tested on version 3.4 and the latest preview version.

Looking at the code I don't completely understand what would/could cancel the task. I'll keep searching but if anyone has any idea, that would help 👍

nblumhardt commented 6 years ago

Hi Jerremy- my guess is that there's an HTTP call timing out, most likely client-side (i.e. via HttpClient), but I'm not sure why this would kick in suddenly.

The sink itself should have a size-limited queue to prevent memory exhaustion; it defaults to 100k events, so if the events are very large or the machine small I can imagine it might impact memory substantially.

The other possibility is that some kind of code change has caused multiple Seq sinks to be created; it's possible to do this by creating multiple logging pipelines, or via Serilog.Sinks.Map or similar. Any clues?

Checking the Seq ingestion log in Settings > Diagnostics, and possibly the full diagnostic report (needs Seq 4) or Seq's internal log files (C:\ProgramData\Seq) will show up any server-side issues.

HTH!

80dB commented 6 years ago

After some major debugging we found that we where exhausting the .NET ThreadPool (although I still can't explain why) which caused Tasks to build up (like the Seq HTTP-task).

That said, this issue did eventually cause an out-of-memory exception (which did not occur when Seq logging was turned off). Not entirely able to explain this either, the log messages are not huge, 100k of them could never cause the memory exception.

Anyhow, root cause was not the Seq logger, so closing this.

nblumhardt commented 6 years ago

Thanks for the follow-up, sounds like a tricky failure mode. Glad you tracked it down!