From 881e497b16a744e98c87761858de4f4c3a384d9d Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Fri, 23 Feb 2024 16:00:06 +0100 Subject: [PATCH 1/2] Short circuit WritingTask and await its completion in dispose(async) This to ensure there is no ongoing IO when _streamWriter disposes: ``` Error: System.InvalidOperationException : The stream is currently in use by a previous operation on the stream. Failed Elastic.OpenTelemetry.Tests.TransactionIdProcessorTests.TransactionId_IsAddedToTags [564 ms] Error Message: System.InvalidOperationException : The stream is currently in use by a previous operation on the stream. Stack Trace: at System.IO.StreamWriter.ThrowAsyncIOInProgress() at System.IO.StreamWriter.Dispose(Boolean disposing) at System.IO.TextWriter.Dispose() at Elastic.OpenTelemetry.Diagnostics.LogFileWriter.Dispose() in /home/runner/work/elastic-otel-dotnet/elastic-otel-dotnet/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs:line 297 at Elastic.OpenTelemetry.AgentBuilder.Agent.Dispose() in /home/runner/work/elastic-otel-dotnet/elastic-otel-dotnet/src/Elastic.OpenTelemetry/AgentBuilder.cs:line 270 at Elastic.OpenTelemetry.Tests.TransactionIdProcessorTests.TransactionId_IsAddedToTags() in /home/runner/work/elastic-otel-dotnet/elastic-otel-dotnet/tests/Elastic.OpenTelemetry.Tests/TransactionIdProcessorTests.cs:line 36 at System.RuntimeMethodHandle.InvokeMethod(Object target, Void** arguments, Signature sig, Boolean isConstructor) at System.Reflection.MethodBaseInvoker.InvokeWithNoArgs(Object obj, BindingFlags invokeAttr) ``` this was highlighted on our CI test runs: https://github.com/elastic/elastic-otel-dotnet/actions/runs/8020502607/job/21910481682?pr=39 --- .../Diagnostics/LogFileWriter.cs | 39 ++++++++++--------- 1 file changed, 21 insertions(+), 18 deletions(-) diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs index 96bc153..fceedee 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs @@ -12,6 +12,8 @@ internal sealed class LogFileWriter : IDisposable, IAsyncDisposable { public static readonly bool FileLoggingEnabled = IsFileLoggingEnabled(); + private bool _disposing; + private ManualResetEventSlim _syncDisposeWaitHandle = new(false); private readonly StreamWriter _streamWriter; private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(1024) { @@ -46,13 +48,11 @@ private LogFileWriter() WritingTask = Task.Run(async () => { - while (await _channel.Reader.WaitToReadAsync().ConfigureAwait(false)) - { - while (_channel.Reader.TryRead(out var logLine)) - { - await _streamWriter.WriteLineAsync(logLine).ConfigureAwait(false); - } - } + while (await _channel.Reader.WaitToReadAsync().ConfigureAwait(false) && !_disposing) + while (_channel.Reader.TryRead(out var logLine) && !_disposing) + await _streamWriter.WriteLineAsync(logLine).ConfigureAwait(false); + + _syncDisposeWaitHandle.Set(); }); var builder = StringBuilderCache.Acquire(); @@ -258,9 +258,10 @@ public void WriteLogLine(Activity? activity, int managedThreadId, DateTime dateT } var spin = new SpinWait(); - while (true) + var message = StringBuilderCache.GetStringAndRelease(builder); + while (!_disposing) { - if (_channel.Writer.TryWrite(StringBuilderCache.GetStringAndRelease(builder))) + if (_channel.Writer.TryWrite(message)) break; spin.SpinOnce(); } @@ -288,23 +289,25 @@ private static bool IsFileLoggingEnabled() public void Dispose() { - // We don't wait for the channel to be drained which is probably the correct choice. - // Dispose should be a quick operation with no chance of exceptions. - // We should document methods to wait for the WritingTask, before disposal, if that matters to the - // consumer. - + //tag that we are running a dispose this allows running tasks and spin waits to short circuit + _disposing = true; _channel.Writer.TryComplete(); + + _syncDisposeWaitHandle.Wait(TimeSpan.FromSeconds(1)); + _streamWriter.Dispose(); } public async ValueTask DisposeAsync() { - // We don't wait for the channel to be drained which is probably the correct choice. - // Dispose should be a quick operation with no chance of exceptions. - // We should document methods to await the WritingTask, before disposal, if that matters to the - // consumer. + //tag that we are running a dispose this allows running tasks and spin waits to short circuit + _disposing = true; _channel.Writer.TryComplete(); + + //Writing task will short circuit once _disposing is flipped to true + await WritingTask.ConfigureAwait(false); + await _streamWriter.DisposeAsync().ConfigureAwait(false); } } From 2cef360bf54aa3472172c4634b0cd75ce8cedcf7 Mon Sep 17 00:00:00 2001 From: Martijn Laarman Date: Fri, 23 Feb 2024 16:25:59 +0100 Subject: [PATCH 2/2] _syncDisposeWaitHandle should be readonly --- src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs index fceedee..2cfc5d6 100644 --- a/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs +++ b/src/Elastic.OpenTelemetry/Diagnostics/LogFileWriter.cs @@ -13,7 +13,7 @@ internal sealed class LogFileWriter : IDisposable, IAsyncDisposable public static readonly bool FileLoggingEnabled = IsFileLoggingEnabled(); private bool _disposing; - private ManualResetEventSlim _syncDisposeWaitHandle = new(false); + private readonly ManualResetEventSlim _syncDisposeWaitHandle = new(false); private readonly StreamWriter _streamWriter; private readonly Channel _channel = Channel.CreateBounded(new BoundedChannelOptions(1024) {