Extending deferred logger to forward logs to AppInsights from webhost. (#10771)

* Extending deferred logger to forward logs to AppInsights from webhost.
* Added a feature flag to control the behavior.

Author: RohitRanjanMS

release_notes.md

@@ -14,6 +14,7 @@
 - Fix modification of ISO strings during the parsing of function metadata bindings.
   - This fixes the listener errors related to the CosmosDB trigger's `StartFromTime` parameter. (#10735)
 - Updated `WebJobs.Script` to target .NET 8 (instead of .NET Standard 2.1)
+- Extending Log Forwarding to AppInsights and OTel for Enhanced Troubleshooting
 - Allow for binding names to use snake case (#10764). Examples include `_`, `binding_name`, and `_binding`.
 - Add support for the release channel setting `WEBSITE_PlatformReleaseChannel` and use this value in extension bundles resolution.
 - Update PowerShell 7.4 worker to [4.0.4134](https://github.com/Azure/azure-functions-powershell-worker/releases/tag/v4.0.4134)

src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs

@@ -68,7 +68,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
             };
 
             // Persist the scope state so it can be reapplied in the original order when forwarding logs to the logging provider.
-            _scopeProvider.ForEachScope((scope, state) =>
+            _scopeProvider?.ForEachScope((scope, state) =>
             {
                 state.ScopeStorage ??= new List<object>();
                 state.ScopeStorage.Add(scope);

src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs

@@ -48,54 +48,61 @@ public void ProcessBufferedLogs(IReadOnlyCollection<ILoggerProvider> forwardingP
                     await Task.Delay(_deferredLogDelay);
                 }
 
-                // Disable the channel and let the consumer know that there won't be any more logs.
-                _isEnabled = false;
-                _channel.Writer.TryComplete();
-
                 try
                 {
                     if (forwardingProviders is null || forwardingProviders.Count == 0)
                     {
-                        // No providers, just drain the messages without logging
+                        // No providers, just drain the messages without logging and disable the channel.
+                        _isEnabled = false;
+                        _channel.Writer.TryComplete();
                         while (_channel.Reader.TryRead(out _))
                         {
                             // Drain the channel
                         }
+                        return;
                     }
 
-                    await foreach (var log in _channel.Reader.ReadAllAsync())
+                    while (await _channel.Reader.WaitToReadAsync())
                     {
-                        foreach (var forwardingProvider in forwardingProviders)
+                        while (_channel.Reader.TryRead(out var log))
                         {
-                            var logger = forwardingProvider.CreateLogger(log.Category);
-                            List<IDisposable> scopes = null;
-
-                            try
+                            foreach (var forwardingProvider in forwardingProviders)
                             {
-                                // Create a scope for each object in ScopeObject
+                                var logger = forwardingProvider.CreateLogger(log.Category);
+                                List<IDisposable> scopes = null;
+
                                 if (log.ScopeStorage?.Count > 0)
                                 {
-                                    scopes ??= new List<IDisposable>();
-                                    foreach (var scope in log.ScopeStorage)
+                                    try
                                     {
-                                        // Create and store each scope
-                                        scopes.Add(logger.BeginScope(scope));
-                                    }
-                                }
+                                        // Create a scope for each object in ScopeObject
+                                        scopes ??= new List<IDisposable>();
+                                        foreach (var scope in log.ScopeStorage)
+                                        {
+                                            // Create and store each scope
+                                            scopes.Add(logger.BeginScope(scope));
+                                        }
 
-                                // Log the message
-                                logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message);
-                            }
-                            finally
-                            {
-                                if (scopes is not null)
-                                {
-                                    // Dispose all scopes in reverse order to properly unwind them
-                                    for (int i = scopes.Count - 1; i >= 0; i--)
+                                        // Log the message
+                                        logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message);
+                                    }
+                                    finally
                                     {
-                                        scopes[i].Dispose();
+                                        if (scopes is not null)
+                                        {
+                                            // Dispose all scopes in reverse order to properly unwind them
+                                            for (int i = scopes.Count - 1; i >= 0; i--)
+                                            {
+                                                scopes[i].Dispose();
+                                            }
+                                        }
                                     }
                                 }
+                                else
+                                {
+                                    // No scopes, avoid try-finally block
+                                    logger.Log(log.LogLevel, log.EventId, log.Exception, log.Message);
+                                }
                             }
                         }
                     }

src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs

@@ -351,14 +351,17 @@ private async Task UnsynchronizedStartHostAsync(ScriptHostStartupOperation activ
 
                 ActiveHost = localHost;
 
-                // Forward initial startup logs to AppInsights/OpenTelemetry.
-                // These are not tracked by the AppInsights and OpenTelemetry logger provider as these are added in the script host.
-                var loggerProviders = ActiveHost.Services.GetServices<ILoggerProvider>();
-                var deferredLogProvider = ActiveHost.Services.GetService<DeferredLoggerProvider>();
-                if (deferredLogProvider is not null)
-                {
-                    var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider or OpenTelemetryLoggerProvider).ToArray();
-                    deferredLogProvider.ProcessBufferedLogs(selectedProviders);
+                if (!FeatureFlags.IsEnabled(ScriptConstants.FeatureFlagDisableWebHostLogForwarding, _environment))
+                {
+                    // Forward logs to AppInsights/OpenTelemetry.
+                    // These are not tracked by the AppInsights and OpenTelemetry logger provider as these are added in the script host.
+                    var loggerProviders = ActiveHost.Services.GetServices<ILoggerProvider>();
+                    var deferredLogProvider = ActiveHost.Services.GetService<DeferredLoggerProvider>();
+                    if (deferredLogProvider is not null)
+                    {
+                        var selectedProviders = loggerProviders.Where(provider => provider is ApplicationInsightsLoggerProvider or OpenTelemetryLoggerProvider).ToArray();
+                        deferredLogProvider.ProcessBufferedLogs(selectedProviders);
+                    }
                 }
 
                 var scriptHost = (ScriptHost)ActiveHost.Services.GetService<ScriptHost>();

src/WebJobs.Script/ScriptConstants.cs

@@ -130,6 +130,7 @@ public static class ScriptConstants
         public const string FeatureFlagRelaxedAssemblyUnification = "RelaxedAssemblyUnification";
         public const string FeatureFlagEnableDiagnosticEventLogging = "EnableDiagnosticEventLogging";
         public const string FeatureFlagDisableDiagnosticEventLogging = "DisableDiagnosticEventLogging";
+        public const string FeatureFlagDisableWebHostLogForwarding = "DisableWebHostLogForwarding";
         public const string FeatureFlagDisableMergedWebHostScriptHostConfiguration = "DisableMergedConfiguration";
         public const string FeatureFlagEnableWorkerIndexing = "EnableWorkerIndexing";
         public const string FeatureFlagEnableDebugTracing = "EnableDebugTracing";

test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs

@@ -6,7 +6,10 @@
 using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Logging.Abstractions;
+using Microsoft.Extensions.Options;
+using Microsoft.WebJobs.Script.Tests;
 using Moq;
+using OpenTelemetry.Logs;
 using Xunit;
 
 namespace Microsoft.Azure.WebJobs.Script.Tests.Eventing
@@ -139,5 +142,39 @@ public void ProcessBufferedLogs_ThrowsNoExceptionsWhenChannelIsEmpty()
             // Act & Assert (no exceptions should be thrown)
             provider.ProcessBufferedLogs(new[] { mockLoggerProvider.Object }, true);
         }
+
+        [Fact]
+        public async Task Dispose_DoNotDisablesProviderAndCompletesChannel()
+        {
+            var testEnvironment = new TestEnvironment();
+            testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "0");
+
+            // Arrange
+            var provider = new DeferredLoggerProvider(testEnvironment);
+            var logger = provider.CreateLogger("TestCategory");
+            logger.LogError("Error Log");
+
+            // Create an instance of IOptionsMonitor<OpenTelemetryLoggerOptions>
+            var optionsMonitor = Mock.Of<IOptionsMonitor<OpenTelemetryLoggerOptions>>();
+
+            // Pass the optionsMonitor to the OpenTelemetryLoggerProvider constructor
+            //OpenTelemetryLoggerProvider openTelemetryLoggerProvider = new(optionsMonitor);
+            TestLoggerProvider testLoggerProvider = new TestLoggerProvider();
+            testLoggerProvider.SetScopeProvider(new LoggerExternalScopeProvider());
+
+            // Act
+            provider.ProcessBufferedLogs(new List<ILoggerProvider>() { testLoggerProvider }, true); // Process immediately
+
+            // Wait a short period to ensure the channel is completed
+            await Task.Delay(100);
+            Assert.Equal(0, provider.Count); // Ensure channel is drained
+
+            // Assert that the log was forwarded to the testLoggerProvider
+            Assert.Equal(1, testLoggerProvider.GetAllLogMessages().Count);
+            Assert.Equal(Assert.Single(testLoggerProvider.GetAllLogMessages()).FormattedMessage, "Error Log");
+
+            // Ensure that the LoggerProvider is not disabled and still returns DeferredLogger
+            Assert.True(provider.CreateLogger("TestCategory") is DeferredLogger);
+        }
     }
 }