serilog / serilog-sinks-periodicbatching

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

Error: System.Text.EncoderNLS.GetBytes throws System.ArgumentOutOfRangeException: Index and count must refer to a location within the buffer from inside PeriodicBatching sink #54

Closed Aaronontheweb closed 3 years ago

Aaronontheweb commented 3 years ago

Version: Serilog.Sinks.PeriodicBatching 2.2. Serilog 2.8

Troubleshooting some errors from a logfile we were given that appear to originate with some code inside the Serilog sink stack:.

"System.ArgumentOutOfRangeException: Index and count must refer to a location within the buffer.
Parameter name: chars
at System.Text.EncoderNLS.GetBytes(Char[] chars, Int32 charIndex, Int32 charCount, Byte[] bytes, Int32 byteIndex, Boolean flush)
at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder) at System.IO.StreamWriter.Flush()
at Serilog.Debugging.SelfLog.<>cDisplayClass3_0.<Enable>b0(String m) in C:\projects\serilog\src\Serilog\Debugging\SelfLog.cs:line 60
at Serilog.Debugging.SelfLog.WriteLine(String format, Object arg0, Object arg1, Object arg2) in
C:\projects\serilog\src\Serilog\Debugging\SelfLog.cs:line 100 at
Serilog.Sinks.PeriodicBatching.PeriodicBatchingSink.<OnTick>d16.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.PortableTimer.<OnTick>d8.MoveNext() --- End of stack trace from previous location where exception was thrown --- at
System.Runtime.CompilerServices.AsyncMethodBuilderCore.<>c.<ThrowAsync>b__6_1(Object state)
at System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(Object state)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) at
System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() at System.Threading.ThreadPoolWorkQueue.Dispatch()
at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()

Looks to me like the issue is happening here:

https://github.com/serilog/serilog-sinks-periodicbatching/blob/313598fd6c0747489c0fdf3949238dd75e60dae0/src/Serilog.Sinks.PeriodicBatching/Sinks/PeriodicBatching/PeriodicBatchingSink.cs#L237-L240

an Exception gets thrown from inside the PeriodicBatchingSink but the internal error-reporting tool called during SelfLog.WriteLine("Exception while emitting periodic batch from {0}: {1}", this, ex); throws a second, this time unhandled exception to be thrown within the AppDomain.

If I had to guess as to what's happening - unsafe access to a buffer somewhere down the callchain.

Any ideas what we can do to patch this or work-around it? I'd offer to patch the issue myself but I'm not sure where to look.

nblumhardt commented 3 years ago

Hi Aaron!

It looks like whatever is hooked up to SelfLog is not thread-safe. Check out how TextWriter.Synchronized() is used in the last example in:

https://github.com/serilog/serilog/wiki/Debugging-and-Diagnostics#selflog

HTH, let us know how you go :-)

Aaronontheweb commented 3 years ago

Aha - did not know that. But yes, looking deeper at the app code here:

var serilogSelfLog = new StreamWriter(Path.Combine(AppDomain.CurrentDomain.BaseDirectory, SeriLogSelfLog));
Serilog.Debugging.SelfLog.Enable(serilogSelfLog);

I'll see that we make the appropriate changes - thank you!