Deferred Log Dispatcher (#10530)

RohitRanjanMS · web-flow · commit 2d36bbe8b1b1 · 2024-10-22T14:31:58.000-07:00
* Deferred Log Dispatcher
diff --git a/release_notes.md b/release_notes.md
@@ -8,6 +8,7 @@
 - Improving console log handling during specialization (#10345)
 - Update Node.js Worker Version to [3.10.1](https://github.com/Azure/azure-functions-nodejs-worker/releases/tag/v3.10.1)
 - Remove packages `Microsoft.Azure.Cosmos.Table` and `Microsoft.Azure.DocumentDB.Core` (#10503)
+- Buffering startup logs and forwarding to ApplicationInsights/OpenTelemetry after logger providers are added to the logging system (#10530)
 - Implement host configuration property to allow configuration of the metadata provider timeout period (#10526)
   - The value can be set via `metadataProviderTimeout` in host.json and defaults to "00:00:30" (30 seconds).
   - For logic apps, unless configured via the host.json, the timeout is disabled by default.
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogEntry.cs
@@ -0,0 +1,24 @@
+﻿// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Generic;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
+{
+    public struct DeferredLogEntry
+    {
+        public LogLevel LogLevel { get; set; }
+
+        public string Category { get; set; }
+
+        public string Message { get; set; }
+
+        public Exception Exception { get; set; }
+
+        public EventId EventId { get; set; }
+
+        public List<object> ScopeStorage { get; set; }
+    }
+}
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLogger.cs
@@ -0,0 +1,80 @@
+﻿// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Generic;
+using System.Threading.Channels;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
+{
+    /// <summary>
+    /// A logger that defers log entries to a channel.
+    /// </summary>
+    public class DeferredLogger : ILogger
+    {
+        private readonly Channel<DeferredLogEntry> _channel;
+        private readonly string _categoryName;
+        private readonly IExternalScopeProvider _scopeProvider;
+        private readonly IEnvironment _environment;
+
+        // Cached placeholder mode flag
+        private bool _isPlaceholderModeDisabled = false;
+
+        public DeferredLogger(Channel<DeferredLogEntry> channel, string categoryName, IExternalScopeProvider scopeProvider, IEnvironment environment)
+        {
+            _channel = channel;
+            _categoryName = categoryName;
+            _scopeProvider = scopeProvider;
+            _environment = environment;
+        }
+
+        public IDisposable BeginScope<TState>(TState state) => _scopeProvider.Push(state);
+
+        // Restrict logging to errors only for now, as we are seeing a lot of unnecessary logs.
+        // https://github.com/Azure/azure-functions-host/issues/10556
+        public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Error;
+
+        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
+        {
+            // Skip logging if it's not enabled or placeholder mode is enabled
+            if (!IsEnabled(logLevel))
+            {
+                return;
+            }
+
+            // Only check IsPlaceholderModeEnabled if it hasn't been disabled
+            if (!_isPlaceholderModeDisabled && _environment.IsPlaceholderModeEnabled())
+            {
+                return;
+            }
+
+            // Cache the fact that placeholder mode is disabled
+            _isPlaceholderModeDisabled = true;
+
+            string formattedMessage = formatter?.Invoke(state, exception);
+            if (string.IsNullOrEmpty(formattedMessage))
+            {
+                return;
+            }
+
+            var log = new DeferredLogEntry
+            {
+                LogLevel = logLevel,
+                Category = _categoryName,
+                Message = formattedMessage,
+                Exception = exception,
+                EventId = eventId
+            };
+
+            // Persist the scope state so it can be reapplied in the original order when forwarding logs to the logging provider.
+            _scopeProvider.ForEachScope((scope, state) =>
+            {
+                state.ScopeStorage ??= new List<object>();
+                state.ScopeStorage.Add(scope);
+            }, log);
+
+            _channel.Writer.TryWrite(log);
+        }
+    }
+}
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/DeferredLoggerProvider.cs
@@ -0,0 +1,124 @@
+﻿// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using System.Collections.Generic;
+using System.Threading.Channels;
+using System.Threading.Tasks;
+using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Logging.Abstractions;
+
+namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
+{
+    public sealed class DeferredLoggerProvider : ILoggerProvider, ISupportExternalScope
+    {
+        private readonly Channel<DeferredLogEntry> _channel = Channel.CreateBounded<DeferredLogEntry>(new BoundedChannelOptions(150)
+        {
+            FullMode = BoundedChannelFullMode.DropOldest,
+            // Avoids locks and interlocked operations when reading from the channel.
+            SingleReader = true,
+            SingleWriter = false
+        });
+
+        private readonly TimeSpan _deferredLogDelay = TimeSpan.FromSeconds(10);
+        private readonly IEnvironment _environment;
+        private IExternalScopeProvider _scopeProvider;
+        private bool _isEnabled = true;
+
+        public DeferredLoggerProvider(IEnvironment environment)
+        {
+            _environment = environment;
+        }
+
+        public int Count => _channel.Reader.Count;
+
+        public ILogger CreateLogger(string categoryName)
+        {
+            return _isEnabled ? new DeferredLogger(_channel, categoryName, _scopeProvider, _environment) : NullLogger.Instance;
+        }
+
+        public void ProcessBufferedLogs(IReadOnlyCollection<ILoggerProvider> forwardingProviders, bool runImmediately = false)
+        {
+            // Forward all buffered logs to the new provider
+            Task.Run(async () =>
+            {
+                if (!runImmediately)
+                {
+                    // Wait for 10 seconds, this will increase the probability of these logs appearing in live metrics.
+                    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
+                        while (_channel.Reader.TryRead(out _))
+                        {
+                            // Drain the channel
+                        }
+                    }
+
+                    await foreach (var log in _channel.Reader.ReadAllAsync())
+                    {
+                        foreach (var forwardingProvider in forwardingProviders)
+                        {
+                            var logger = forwardingProvider.CreateLogger(log.Category);
+                            List<IDisposable> scopes = null;
+
+                            try
+                            {
+                                // Create a scope for each object in ScopeObject
+                                if (log.ScopeStorage?.Count > 0)
+                                {
+                                    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--)
+                                    {
+                                        scopes[i].Dispose();
+                                    }
+                                }
+                            }
+                        }
+                    }
+                }
+                catch (Exception ex)
+                {
+                    if (ex.IsFatal())
+                    {
+                        throw;
+                    }
+                }
+            });
+        }
+
+        public void SetScopeProvider(IExternalScopeProvider scopeProvider)
+        {
+            _scopeProvider = scopeProvider;
+        }
+
+        public void Dispose()
+        {
+            _isEnabled = false;
+            _channel.Writer.TryComplete();
+        }
+    }
+}
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLogger.cs
@@ -3,15 +3,12 @@
 
 using System;
 using System.Collections.Generic;
-using Microsoft.AspNetCore.Http;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Host.Executors.Internal;
 using Microsoft.Azure.WebJobs.Host.Indexers;
-using Microsoft.Azure.WebJobs.Host.Listeners;
 using Microsoft.Azure.WebJobs.Logging;
 using Microsoft.Azure.WebJobs.Script.Configuration;
 using Microsoft.Azure.WebJobs.Script.Eventing;
-using Microsoft.Azure.WebJobs.Script.Extensions;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
@@ -31,7 +28,7 @@ public class SystemLogger : ILogger
         private readonly IExternalScopeProvider _scopeProvider;
         private AppServiceOptions _appServiceOptions;
 
-        public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator eventGenerator, IEnvironment environment,  IDebugStateProvider debugStateProvider,
+        public SystemLogger(string hostInstanceId, string categoryName, IEventGenerator eventGenerator, IEnvironment environment, IDebugStateProvider debugStateProvider,
            IScriptEventManager eventManager, IExternalScopeProvider scopeProvider, IOptionsMonitor<AppServiceOptions> appServiceOptionsMonitor)
         {
             _environment = environment;
@@ -181,7 +178,6 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
                 formattedMessage = Sanitizer.Sanitize(formattedMessage);
                 innerExceptionMessage = innerExceptionMessage ?? string.Empty;
             }
-
             _eventGenerator.LogFunctionTraceEvent(logLevel, subscriptionId, appName, functionName, eventName, source, details, summary, innerExceptionType, innerExceptionMessage, invocationId, _hostInstanceId, activityId, runtimeSiteName, slotName, DateTime.UtcNow);
         }
     }
diff --git a/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs b/src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs
@@ -61,4 +61,4 @@ public void SetScopeProvider(IExternalScopeProvider scopeProvider)
             _scopeProvider = scopeProvider;
         }
     }
-}
+}
diff --git a/src/WebJobs.Script.WebHost/Program.cs b/src/WebJobs.Script.WebHost/Program.cs
@@ -88,6 +88,8 @@ public static IWebHostBuilder CreateWebHostBuilder(string[] args = null)
 
                     loggingBuilder.AddDefaultWebJobsFilters();
                     loggingBuilder.AddWebJobsSystem<WebHostSystemLoggerProvider>();
+                    loggingBuilder.Services.AddSingleton<DeferredLoggerProvider>();
+                    loggingBuilder.Services.AddSingleton<ILoggerProvider>(s => s.GetRequiredService<DeferredLoggerProvider>());
                 })
                 .UseStartup<Startup>();
         }
diff --git a/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs b/src/WebJobs.Script.WebHost/WebJobsScriptHostService.cs
@@ -2,6 +2,7 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Generic;
 using System.Collections.ObjectModel;
 using System.IO;
 using System.Linq;
@@ -14,12 +15,14 @@
 using Microsoft.ApplicationInsights.Extensibility.Implementation.ApplicationId;
 using Microsoft.Azure.WebJobs.Host;
 using Microsoft.Azure.WebJobs.Logging;
+using Microsoft.Azure.WebJobs.Logging.ApplicationInsights;
 using Microsoft.Azure.WebJobs.Script.Config;
 using Microsoft.Azure.WebJobs.Script.Configuration;
 using Microsoft.Azure.WebJobs.Script.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Azure.WebJobs.Script.Metrics;
 using Microsoft.Azure.WebJobs.Script.Scale;
+using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.Extensions;
 using Microsoft.Azure.WebJobs.Script.Workers;
 using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
@@ -348,6 +351,16 @@ 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);
+                }
+
                 var scriptHost = (ScriptHost)ActiveHost.Services.GetService<ScriptHost>();
                 if (scriptHost != null)
                 {
diff --git a/src/WebJobs.Script/WebJobs.Script.csproj b/src/WebJobs.Script/WebJobs.Script.csproj
@@ -93,6 +93,7 @@
     <PackageReference Include="System.Text.Encodings.Web" Version="8.0.0" />
     <PackageReference Include="System.Text.Json" Version="8.0.5" />
     <PackageReference Include="System.Text.RegularExpressions" Version="4.3.1" />
+    <PackageReference Include="System.Threading.Channels" Version="8.0.0" />
   </ItemGroup>
 
   <ItemGroup>
diff --git a/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs b/test/WebJobs.Script.Tests/Eventing/DeferredLoggerProviderTests.cs

Original file line number	Diff line number	Diff line change
`@@ -61,4 +61,4 @@ public void SetScopeProvider(IExternalScopeProvider scopeProvider)`
`61`	`61`	`_scopeProvider = scopeProvider;`
`62`	`62`	`}`
`63`	`63`	`}`
`64`		`-}`
	`64`	`+}`
Original file line number	Diff line number	Diff line change
`@@ -88,6 +88,8 @@ public static IWebHostBuilder CreateWebHostBuilder(string[] args = null)`
`88`	`88`
`89`	`89`	`loggingBuilder.AddDefaultWebJobsFilters();`
`90`	`90`	`loggingBuilder.AddWebJobsSystem<WebHostSystemLoggerProvider>();`
	`91`	`+ loggingBuilder.Services.AddSingleton<DeferredLoggerProvider>();`
	`92`	`+ loggingBuilder.Services.AddSingleton<ILoggerProvider>(s => s.GetRequiredService<DeferredLoggerProvider>());`
`91`	`93`	`})`
`92`	`94`	`.UseStartup<Startup>();`
`93`	`95`	`}`