[internal-logging] remove flush to disk after write (#4275)

src/OpenTelemetry.AutoInstrumentation.AspNetCoreBootstrapper/BootstrapperHostingStartup.cs

@@ -15,7 +15,8 @@ namespace OpenTelemetry.AutoInstrumentation.AspNetCoreBootstrapper;
 /// </summary>
 internal class BootstrapperHostingStartup : IHostingStartup
 {
-    private static readonly IOtelLogger Logger = OtelLogging.GetLogger("AspNetCoreBootstrapper");
+    private const string BootstrapperLoggerSuffix = "AspNetCoreBootstrapper";
+    private static readonly IOtelLogger Logger = OtelLogging.GetLogger(BootstrapperLoggerSuffix);
 
     private readonly LogSettings _logSettings;
 
@@ -33,29 +34,36 @@ internal class BootstrapperHostingStartup : IHostingStartup
     /// <param name="builder">The <see cref="IWebHostBuilder"/>.</param>
     public void Configure(IWebHostBuilder builder)
     {
-        if (!_logSettings.LogsEnabled)
-        {
-            Logger.Information("BootstrapperHostingStartup loaded, but OpenTelemetry Logs disabled. Skipping.");
-            return;
-        }
-
-        if (!_logSettings.EnabledInstrumentations.Contains(LogInstrumentation.ILogger))
-        {
-            Logger.Information($"BootstrapperHostingStartup loaded, but {nameof(LogInstrumentation.ILogger)} instrumentation is disabled. Skipping.");
-            return;
-        }
-
         try
         {
-            builder.ConfigureLogging(logging => logging.AddOpenTelemetryLogsFromStartup());
+            if (!_logSettings.LogsEnabled)
+            {
+                Logger.Information("BootstrapperHostingStartup loaded, but OpenTelemetry Logs disabled. Skipping.");
+                return;
+            }
 
-            var applicationName = GetApplicationName();
-            Logger.Information($"BootstrapperHostingStartup loaded for application with name {applicationName}.");
+            if (!_logSettings.EnabledInstrumentations.Contains(LogInstrumentation.ILogger))
+            {
+                Logger.Information($"BootstrapperHostingStartup loaded, but {nameof(LogInstrumentation.ILogger)} instrumentation is disabled. Skipping.");
+                return;
+            }
+
+            try
+            {
+                builder.ConfigureLogging(logging => logging.AddOpenTelemetryLogsFromStartup());
+
+                var applicationName = GetApplicationName();
+                Logger.Information($"BootstrapperHostingStartup loaded for application with name {applicationName}.");
+            }
+            catch (Exception ex)
+            {
+                Logger.Error($"Error in BootstrapperHostingStartup: {ex}");
+                throw;
+            }
         }
-        catch (Exception ex)
+        finally
         {
-            Logger.Error($"Error in BootstrapperHostingStartup: {ex}");
-            throw;
+            OtelLogging.CloseLogger(BootstrapperLoggerSuffix, Logger);
         }
     }
 

src/OpenTelemetry.AutoInstrumentation.Loader/Loader.cs

@@ -11,9 +11,11 @@ namespace OpenTelemetry.AutoInstrumentation.Loader;
 /// </summary>
 internal partial class Loader
 {
+    private const string LoaderLoggerSuffix = "Loader";
     private static readonly string ManagedProfilerDirectory;
+    private static readonly IOtelLogger Logger = OtelLogging.GetLogger(LoaderLoggerSuffix);
 
-    private static readonly IOtelLogger Logger = OtelLogging.GetLogger("Loader");
+    private static int _isExiting;
 
     /// <summary>
     /// Initializes static members of the <see cref="Loader"/> class.
@@ -33,6 +35,29 @@ internal partial class Loader
         }
 
         TryLoadManagedAssembly();
+
+        // AssemblyResolve_ManagedProfilerDependencies logs only if Debug enabled.
+        // If Debug is not enabled, logger won't be needed anymore.
+        if (Logger.IsEnabled(LogLevel.Debug))
+        {
+            // Register shutdown on exit
+            AppDomain.CurrentDomain.ProcessExit += OnExit;
+        }
+        else
+        {
+            OtelLogging.CloseLogger(LoaderLoggerSuffix, Logger);
+        }
+    }
+
+    private static void OnExit(object? sender, EventArgs e)
+    {
+        if (Interlocked.Exchange(ref _isExiting, value: 1) != 0)
+        {
+            // OnExit() was already called before
+            return;
+        }
+
+        OtelLogging.CloseLogger(LoaderLoggerSuffix, Logger);
     }
 
     private static void TryLoadManagedAssembly()

src/OpenTelemetry.AutoInstrumentation.Loader/OpenTelemetry.AutoInstrumentation.Loader.csproj

@@ -22,6 +22,9 @@
   <Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\RollingFileSink.cs">
     <Link>Logging\RollingFileSink.cs</Link>
   </Compile>
+  <Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\PeriodicFlushToDiskSink.cs">
+    <Link>Logging\PeriodicFlushToDiskSink.cs</Link>
+  </Compile>
   <Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\RollingInterval.cs">
     <Link>Logging\RollingInterval.cs</Link>
   </Compile>

src/OpenTelemetry.AutoInstrumentation.StartupHook/OpenTelemetry.AutoInstrumentation.StartupHook.csproj

@@ -25,6 +25,9 @@
     <Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\RollingFileSink.cs">
       <Link>Logging\RollingFileSink.cs</Link>
     </Compile>
+    <Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\PeriodicFlushToDiskSink.cs">
+      <Link>Logging\PeriodicFlushToDiskSink.cs</Link>
+    </Compile>
     <Compile Include="..\OpenTelemetry.AutoInstrumentation\Logging\RollingInterval.cs">
       <Link>Logging\RollingInterval.cs</Link>
     </Compile>

src/OpenTelemetry.AutoInstrumentation.StartupHook/StartupHook.cs

@@ -11,7 +11,8 @@ using OpenTelemetry.AutoInstrumentation.RulesEngine;
 /// </summary>
 internal class StartupHook
 {
-    private static readonly IOtelLogger Logger = OtelLogging.GetLogger("StartupHook");
+    private const string StartuphookLoggerSuffix = "StartupHook";
+    private static readonly IOtelLogger Logger = OtelLogging.GetLogger(StartuphookLoggerSuffix);
 
     // This property must be initialized before any rule is evaluated since it may be used during rule evaluation.
     internal static string? LoaderAssemblyLocation { get; set; }
@@ -31,7 +32,8 @@ internal class StartupHook
             var ruleEngine = new RuleEngine();
             if (!ruleEngine.ValidateRules())
             {
-                throw new Exception("Rule Engine Failure: One or more rules failed validation. Automatic Instrumentation won't be loaded.");
+                throw new Exception(
+                    "Rule Engine Failure: One or more rules failed validation. Automatic Instrumentation won't be loaded.");
             }
 
             Logger.Information("Initialization.");
@@ -61,6 +63,10 @@ internal class StartupHook
                 throw;
             }
         }
+        finally
+        {
+            OtelLogging.CloseLogger(StartuphookLoggerSuffix, Logger);
+        }
     }
 
     private static string GetLoaderAssemblyLocation()

src/OpenTelemetry.AutoInstrumentation/Instrumentation.cs

@@ -99,6 +99,10 @@ internal static class Instrumentation
             _pluginManager = new PluginManager(GeneralSettings.Value);
             _pluginManager.Initializing();
 
+            // Register to shutdown events
+            AppDomain.CurrentDomain.ProcessExit += OnExit;
+            AppDomain.CurrentDomain.DomainUnload += OnExit;
+
 #if NET
             var profilerEnabled = GeneralSettings.Value.ProfilerEnabled;
 
@@ -120,10 +124,6 @@ internal static class Instrumentation
 
             if (TracerSettings.Value.TracesEnabled || MetricSettings.Value.MetricsEnabled)
             {
-                // Register to shutdown events
-                AppDomain.CurrentDomain.ProcessExit += OnExit;
-                AppDomain.CurrentDomain.DomainUnload += OnExit;
-
                 if (GeneralSettings.Value.FlushOnUnhandledException)
                 {
                     AppDomain.CurrentDomain.UnhandledException += OnUnhandledException;
@@ -459,6 +459,10 @@ internal static class Instrumentation
                 // with the exception.
             }
         }
+        finally
+        {
+            OtelLogging.CloseLogger("Managed", Logger);
+        }
     }
 
     private static void OnUnhandledException(object sender, UnhandledExceptionEventArgs args)
@@ -471,17 +475,9 @@ internal static class Instrumentation
                 OnExit(sender, args);
             }
         }
-        catch (Exception ex)
+        catch (Exception)
         {
-            try
-            {
-                Logger.Error(ex, "An exception occurred while processing an unhandled exception.");
-            }
-            catch
-            {
-                // If we encounter an error while logging there is nothing else we can do
-                // with the exception.
-            }
+            // Logger was already shutdown.
         }
     }
 }

src/OpenTelemetry.AutoInstrumentation/Logging/FileSink.cs

@@ -61,7 +61,7 @@ internal sealed class FileSink : IDisposable
                 return false;
             }
             _output.Write(message);
-            FlushToDisk();
+            _output.Flush();
             return true;
         }
     }
@@ -76,7 +76,10 @@ internal sealed class FileSink : IDisposable
 
     public void FlushToDisk()
     {
-        _output.Flush();
-        _underlyingStream.Flush(true);
+        lock (_syncRoot)
+        {
+            _output.Flush();
+            _underlyingStream.Flush(flushToDisk: true);
+        }
     }
 }

src/OpenTelemetry.AutoInstrumentation/Logging/IOtelLogger.cs

@@ -3,7 +3,7 @@
 
 namespace OpenTelemetry.AutoInstrumentation.Logging;
 
-internal interface IOtelLogger : IDisposable
+internal interface IOtelLogger
 {
     LogLevel Level { get; }
 
@@ -88,4 +88,6 @@ internal interface IOtelLogger : IDisposable
     void Error<T0, T1, T2>(Exception exception, string messageTemplate, T0 property0, T1 property1, T2 property2, bool writeToEventLog = true);
 
     void Error(Exception exception, string messageTemplate, object[] args, bool writeToEventLog = true);
+
+    void Close();
 }

src/OpenTelemetry.AutoInstrumentation/Logging/InternalLogger.cs

@@ -7,7 +7,7 @@ internal class InternalLogger : IOtelLogger
 {
     private static readonly object[] NoPropertyValues = Array.Empty<object>();
 
-    private readonly ISink _sink;
+    private ISink _sink;
 
     internal InternalLogger(ISink sink, LogLevel logLevel)
     {
@@ -142,9 +142,13 @@ internal class InternalLogger : IOtelLogger
     public void Error(Exception exception, string messageTemplate, object[] args, bool writeToEventLog)
         => Write(LogLevel.Error, exception, messageTemplate, args, writeToEventLog);
 
-    public void Dispose()
+    public void Close()
     {
-        if (_sink is IDisposable disposableSink)
+        // Replace with Noop sink, so that attempts to write after logger is closed
+        // don't try to write to disposed sink.
+
+        var oldSink = Interlocked.Exchange(ref _sink, NoopSink.Instance);
+        if (oldSink is IDisposable disposableSink)
         {
             disposableSink.Dispose();
         }

src/OpenTelemetry.AutoInstrumentation/Logging/NoopLogger.cs

@@ -181,7 +181,7 @@ internal class NoopLogger : IOtelLogger
     {
     }
 
-    public void Dispose()
+    public void Close()
     {
     }
 }

src/OpenTelemetry.AutoInstrumentation/Logging/NoopSink.cs

@@ -8,6 +8,12 @@ namespace OpenTelemetry.AutoInstrumentation.Logging;
 /// </summary>
 internal class NoopSink : ISink
 {
+    public static readonly NoopSink Instance = new();
+
+    private NoopSink()
+    {
+    }
+
     public void Write(string message)
     {
     }

src/OpenTelemetry.AutoInstrumentation/Logging/OtelLogging.cs

@@ -43,11 +43,29 @@ internal static class OtelLogging
         return OtelLoggers.GetOrAdd(suffix, CreateLogger);
     }
 
+    public static void CloseLogger(string suffix, IOtelLogger otelLogger)
+    {
+        try
+        {
+            // Update logger associated with the key, so that future calls to GetLogger
+            // return NoopLogger.
+            if (OtelLoggers.TryUpdate(suffix, NoopLogger.Instance, otelLogger))
+            {
+                otelLogger.Close();
+            }
+        }
+        catch (Exception)
+        {
+            // intentionally empty
+        }
+    }
+
     // Helper method for testing
     internal static void Reset()
     {
         _configuredLogLevel = GetConfiguredLogLevel();
         _configuredLogSink = GetConfiguredLogSink();
+        OtelLoggers.Clear();
     }
 
     internal static LogLevel? GetConfiguredLogLevel()
@@ -138,7 +156,7 @@ internal static class OtelLogging
         // Uses ISink? here, sink creation can fail so we specify default fallback at the end.
         var sink = _configuredLogSink switch
         {
-            LogSink.NoOp => new NoopSink(),
+            LogSink.NoOp => NoopSink.Instance,
             LogSink.Console => new ConsoleSink(suffix),
             LogSink.File => CreateFileSink(suffix),
             // default to null, then default value is specified only at the end.
@@ -147,7 +165,7 @@ internal static class OtelLogging
 
         return sink ??
             // Default to NoopSink
-            new NoopSink();
+            NoopSink.Instance;
     }
 
     private static ISink? CreateFileSink(string suffix)
@@ -160,13 +178,14 @@ internal static class OtelLogging
                 var fileName = GetLogFileName(suffix);
                 var logPath = Path.Combine(logDirectory, fileName);
 
-                return new RollingFileSink(
+                var rollingFileSink = new RollingFileSink(
                     path: logPath,
                     fileSizeLimitBytes: FileSizeLimitBytes,
                     retainedFileCountLimit: 10,
                     rollingInterval: RollingInterval.Day,
                     rollOnFileSizeLimit: true,
                     retainedFileTimeLimit: null);
+                return new PeriodicFlushToDiskSink(rollingFileSink, TimeSpan.FromSeconds(5));
             }
         }
         catch (Exception)

src/OpenTelemetry.AutoInstrumentation/Logging/PeriodicFlushToDiskSink.cs

@@ -0,0 +1,77 @@
+//------------------------------------------------------------------------------
+// <auto-generated />
+// This comment is here to prevent StyleCop from analyzing a file originally from Serilog.
+//------------------------------------------------------------------------------
+
+// Copyright 2013-2019 Serilog Contributors
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Modified by OpenTelemetry Authors.
+
+namespace OpenTelemetry.AutoInstrumentation.Logging;
+
+/// <summary>
+/// A sink wrapper that periodically flushes the wrapped sink to disk.
+/// </summary>
+internal sealed class PeriodicFlushToDiskSink : ISink, IDisposable
+{
+    readonly ISink _sink;
+    readonly Timer _timer;
+    int _flushRequired;
+
+    /// <summary>
+    /// Construct a <see cref="PeriodicFlushToDiskSink"/> that wraps
+    /// <paramref name="sink"/> and flushes it at the specified <paramref name="flushInterval"/>.
+    /// </summary>
+    /// <param name="sink">The sink to wrap.</param>
+    /// <param name="flushInterval">The interval at which to flush the underlying sink.</param>
+    /// <exception cref="ArgumentNullException">When <paramref name="sink"/> is <code>null</code></exception>
+    public PeriodicFlushToDiskSink(RollingFileSink sink, TimeSpan flushInterval)
+    {
+        _sink = sink ?? throw new ArgumentNullException(nameof(sink));
+
+        _timer = new Timer(_ => FlushToDisk(sink), null, flushInterval, flushInterval);
+    }
+
+    /// <inheritdoc />
+    public void Write(string message)
+    {
+        _sink.Write(message);
+        Interlocked.Exchange(ref _flushRequired, 1);
+    }
+
+    /// <inheritdoc />
+    public void Dispose()
+    {
+        _timer.Dispose();
+        (_sink as IDisposable)?.Dispose();
+    }
+
+    void FlushToDisk(RollingFileSink flushable)
+    {
+        try
+        {
+            if (Interlocked.CompareExchange(ref _flushRequired, 0, 1) == 1)
+            {
+                // May throw ObjectDisposedException, since we're not trying to synchronize
+                // anything here in the wrapper.
+                flushable.FlushToDisk();
+            }
+        }
+        catch (Exception)
+        {
+            // Ignore
+        }
+    }
+}

test/OpenTelemetry.AutoInstrumentation.StartupHook.Tests/TestLogger.cs

@@ -181,7 +181,7 @@ internal class TestLogger : IOtelLogger
     {
     }
 
-    public void Dispose()
+    public void Close()
     {
     }
 

test/OpenTelemetry.AutoInstrumentation.Tests/OtelLoggingTests.cs

@@ -125,7 +125,7 @@ public class OtelLoggingTests : IDisposable
             var logLine = "== Test Log Here ==";
 
             logger.Debug(logLine, false);
-            logger.Dispose(); // Dispose the logger to release the file
+            logger.Close(); // Shutdown the logger to release the file
 
             var files = tempLogsDirectory.GetFiles();
 
@@ -178,6 +178,109 @@ public class OtelLoggingTests : IDisposable
         }
     }
 
+    [Fact]
+    public void AfterLoggerIsClosed_ConsecutiveLogCallsWithTheSameLoggerAreNotWrittenToConfiguredSink()
+    {
+        Environment.SetEnvironmentVariable("OTEL_LOG_LEVEL", "debug");
+        Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "console");
+
+        var currentWritter = Console.Out;
+
+        using var ms = new MemoryStream();
+        using var tw = new StreamWriter(ms);
+
+        Console.SetOut(tw);
+
+        try
+        {
+            // Reset internal state
+            OtelLogging.Reset();
+
+            var loggerSuffix = "ConsoleUnitTests";
+            var logger = OtelLogging.GetLogger(loggerSuffix);
+
+            var expectedLogContent = "== Test Log Here ==";
+            LogAndFlush(logger, expectedLogContent, tw);
+
+            using var streamReader = new StreamReader(ms);
+
+            var content = ReadWrittenContent(ms, streamReader);
+            Assert.Contains(expectedLogContent, content);
+
+            // Reset
+            ms.SetLength(0);
+
+            OtelLogging.CloseLogger(loggerSuffix, logger);
+
+            LogAndFlush(logger, expectedLogContent, tw);
+
+            content = ReadWrittenContent(ms, streamReader);
+            Assert.Empty(content);
+        }
+        finally
+        {
+            Console.SetOut(currentWritter);
+        }
+    }
+
+    [Fact]
+    public void AfterLoggerIsClosed_ConsecutiveCallsToGetLoggerReturnNoopLogger()
+    {
+        Environment.SetEnvironmentVariable("OTEL_LOG_LEVEL", "debug");
+        Environment.SetEnvironmentVariable("OTEL_DOTNET_AUTO_LOGGER", "console");
+
+        var currentWritter = Console.Out;
+
+        using var ms = new MemoryStream();
+        using var tw = new StreamWriter(ms);
+
+        Console.SetOut(tw);
+
+        try
+        {
+            // Reset internal state
+            OtelLogging.Reset();
+
+            var loggerSuffix = "ConsoleUnitTests";
+            var logger = OtelLogging.GetLogger(loggerSuffix);
+
+            var expectedLogContent = "== Test Log Here ==";
+            LogAndFlush(logger, expectedLogContent, tw);
+
+            using var streamReader = new StreamReader(ms);
+
+            var content = ReadWrittenContent(ms, streamReader);
+            Assert.Contains(expectedLogContent, content);
+
+            // Reset
+            ms.SetLength(0);
+
+            OtelLogging.CloseLogger(loggerSuffix, logger);
+
+            logger = OtelLogging.GetLogger(loggerSuffix);
+            LogAndFlush(logger, expectedLogContent, tw);
+
+            content = ReadWrittenContent(ms, streamReader);
+            Assert.Empty(content);
+        }
+        finally
+        {
+            Console.SetOut(currentWritter);
+        }
+    }
+
+    private static void LogAndFlush(IOtelLogger logger, string logLine, StreamWriter? tw)
+    {
+        logger.Debug(logLine, false);
+        tw?.Flush(); // Forces rows to be written
+    }
+
+    private static string ReadWrittenContent(MemoryStream ms, StreamReader streamReader)
+    {
+        ms.Position = 0; // reset reading position
+        return streamReader.ReadToEnd();
+    }
+
     private static void UnsetLoggingEnvVars()
     {
         Environment.SetEnvironmentVariable("OTEL_LOG_LEVEL", null);