preventing placeholder hosts from draining worker console logs

release_notes.md

@@ -9,5 +9,6 @@
   - Includes fixes from 2.16.0
 - Migrated Scale Metrics to use `Azure.Data.Tables` SDK (#10276)
   - Added support for Identity-based connections
-- Skip validation of `FUNCTIONS_WORKER_RUNTIME` with funciton metadata in placeholder mode. (#10459)
-- Sanitize exception logs (#10443)
+- Skip validation of `FUNCTIONS_WORKER_RUNTIME` with function metadata in placeholder mode. (#10459)
+- Sanitize exception logs (#10443)
+- Improving console log handling during specialization (#10345)

src/WebJobs.Script/Workers/Http/HttpWorkerProcess.cs

@@ -6,6 +6,7 @@
 using Microsoft.Azure.WebJobs.Script.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 
 namespace Microsoft.Azure.WebJobs.Script.Workers.Http
 {
@@ -30,8 +31,10 @@ internal HttpWorkerProcess(string workerId,
                                        IEnvironment environment,
                                        IMetricsLogger metricsLogger,
                                        IServiceProvider serviceProvider,
+                                       IOptionsMonitor<ScriptApplicationHostOptions> scriptApplicationHostOptions,
                                        ILoggerFactory loggerFactory)
-            : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, loggerFactory, environment, httpWorkerOptions.Description.UseStdErrorStreamForErrorsOnly)
+            : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, loggerFactory, environment,
+                  scriptApplicationHostOptions, httpWorkerOptions.Description.UseStdErrorStreamForErrorsOnly)
         {
             _processFactory = processFactory;
             _eventManager = eventManager;

src/WebJobs.Script/Workers/Http/HttpWorkerProcessFactory.cs

@@ -5,6 +5,7 @@
 using Microsoft.Azure.WebJobs.Script.Diagnostics;
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 
 namespace Microsoft.Azure.WebJobs.Script.Workers.Http
 {
@@ -18,6 +19,7 @@ internal class HttpWorkerProcessFactory : IHttpWorkerProcessFactory
         private readonly IEnvironment _environment;
         private readonly IMetricsLogger _metricsLogger;
         private readonly IServiceProvider _serviceProvider;
+        private readonly IOptionsMonitor<ScriptApplicationHostOptions> _scriptApplicationHostOptions;
 
         public HttpWorkerProcessFactory(IScriptEventManager eventManager,
                                        ILoggerFactory loggerFactory,
@@ -26,7 +28,8 @@ public HttpWorkerProcessFactory(IScriptEventManager eventManager,
                                        IWorkerConsoleLogSource consoleLogSource,
                                        IEnvironment environment,
                                        IMetricsLogger metricsLogger,
-                                       IServiceProvider serviceProvider)
+                                       IServiceProvider serviceProvider,
+                                       IOptionsMonitor<ScriptApplicationHostOptions> scriptApplicationHostOptions)
         {
             _loggerFactory = loggerFactory ?? throw new ArgumentNullException(nameof(loggerFactory));
             _eventManager = eventManager ?? throw new ArgumentNullException(nameof(eventManager));
@@ -36,12 +39,14 @@ public HttpWorkerProcessFactory(IScriptEventManager eventManager,
             _metricsLogger = metricsLogger ?? throw new ArgumentNullException(nameof(metricsLogger));
             _environment = environment;
             _serviceProvider = serviceProvider;
+            _scriptApplicationHostOptions = scriptApplicationHostOptions;
         }
 
         public IWorkerProcess Create(string workerId, string scriptRootPath, HttpWorkerOptions httpWorkerOptions)
         {
             ILogger workerProcessLogger = _loggerFactory.CreateLogger($"Worker.HttpWorkerProcess.{workerId}");
-            return new HttpWorkerProcess(workerId, scriptRootPath, httpWorkerOptions, _eventManager, _workerProcessFactory, _processRegistry, workerProcessLogger, _consoleLogSource, _environment, _metricsLogger, _serviceProvider, _loggerFactory);
+            return new HttpWorkerProcess(workerId, scriptRootPath, httpWorkerOptions, _eventManager, _workerProcessFactory, _processRegistry, workerProcessLogger,
+                _consoleLogSource, _environment, _metricsLogger, _serviceProvider, _scriptApplicationHostOptions, _loggerFactory);
         }
     }
 }

src/WebJobs.Script/Workers/ProcessManagement/WorkerProcess.cs

@@ -14,6 +14,7 @@
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Extensions.DependencyInjection;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 using Mono.Unix;
 
 namespace Microsoft.Azure.WebJobs.Script.Workers
@@ -30,13 +31,15 @@ internal abstract class WorkerProcess : IWorkerProcess, IDisposable
         private readonly IDisposable _eventSubscription;
         private readonly Lazy<ILogger> _toolingConsoleJsonLoggerLazy;
         private readonly IEnvironment _environment;
+        private readonly IOptionsMonitor<ScriptApplicationHostOptions> _scriptApplicationHostOptions;
 
         private bool _useStdErrorStreamForErrorsOnly;
         private Queue<string> _processStdErrDataQueue = new Queue<string>(3);
         private IHostProcessMonitor _processMonitor;
         private object _syncLock = new object();
 
-        internal WorkerProcess(IScriptEventManager eventManager, IProcessRegistry processRegistry, ILogger workerProcessLogger, IWorkerConsoleLogSource consoleLogSource, IMetricsLogger metricsLogger, IServiceProvider serviceProvider, ILoggerFactory loggerFactory, IEnvironment environment, bool useStdErrStreamForErrorsOnly = false)
+        internal WorkerProcess(IScriptEventManager eventManager, IProcessRegistry processRegistry, ILogger workerProcessLogger, IWorkerConsoleLogSource consoleLogSource, IMetricsLogger metricsLogger,
+            IServiceProvider serviceProvider, ILoggerFactory loggerFactory, IEnvironment environment, IOptionsMonitor<ScriptApplicationHostOptions> scriptApplicationHostOptions, bool useStdErrStreamForErrorsOnly = false)
         {
             _processRegistry = processRegistry;
             _workerProcessLogger = workerProcessLogger;
@@ -46,6 +49,7 @@ internal WorkerProcess(IScriptEventManager eventManager, IProcessRegistry proces
             _useStdErrorStreamForErrorsOnly = useStdErrStreamForErrorsOnly;
             _serviceProvider = serviceProvider;
             _environment = environment;
+            _scriptApplicationHostOptions = scriptApplicationHostOptions;
             _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => loggerFactory.CreateLogger(WorkerConstants.ToolingConsoleLogCategoryName), isThreadSafe: true);
 
             // We subscribe to host start events so we can handle the restart that occurs
@@ -218,7 +222,13 @@ internal void BuildAndLogConsoleLog(string msg, LogLevel level)
             }
             else
             {
-                _consoleLogSource?.Log(consoleLog);
+                // These are 'user' console logs and should be forwarded to the ScriptHost, unless
+                // we're in placeholder mode. In that case, we ignore the logs so they are not captured
+                // by the specialized host when it starts.
+                if (!_scriptApplicationHostOptions.CurrentValue.IsStandbyConfiguration)
+                {
+                    _consoleLogSource?.Log(consoleLog);
+                }
             }
         }
 

src/WebJobs.Script/Workers/Rpc/RpcWorkerProcess.cs

@@ -39,8 +39,10 @@ internal RpcWorkerProcess(string runtime,
                                        IServiceProvider serviceProvider,
                                        IOptions<FunctionsHostingConfigOptions> hostingConfigOptions,
                                        IEnvironment environment,
+                                       IOptionsMonitor<ScriptApplicationHostOptions> scriptApplicationHostOptions,
                                        ILoggerFactory loggerFactory)
-            : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, loggerFactory, environment, rpcWorkerConfig.Description.UseStdErrorStreamForErrorsOnly)
+            : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, loggerFactory, environment,
+                  scriptApplicationHostOptions, rpcWorkerConfig.Description.UseStdErrorStreamForErrorsOnly)
         {
             _runtime = runtime;
             _processFactory = processFactory;

src/WebJobs.Script/Workers/Rpc/RpcWorkerProcessFactory.cs

@@ -22,6 +22,7 @@ internal class RpcWorkerProcessFactory : IRpcWorkerProcessFactory
         private readonly IServiceProvider _serviceProvider;
         private readonly IOptions<FunctionsHostingConfigOptions> _hostingConfigOptions;
         private readonly IEnvironment _environment;
+        private readonly IOptionsMonitor<ScriptApplicationHostOptions> _scriptApplicationHostOptions;
 
         public RpcWorkerProcessFactory(IRpcServer rpcServer,
                                        IScriptEventManager eventManager,
@@ -32,7 +33,8 @@ public RpcWorkerProcessFactory(IRpcServer rpcServer,
                                        IMetricsLogger metricsLogger,
                                        IServiceProvider serviceProvider,
                                        IOptions<FunctionsHostingConfigOptions> hostingConfigOptions,
-                                       IEnvironment environment)
+                                       IEnvironment environment,
+                                       IOptionsMonitor<ScriptApplicationHostOptions> scriptApplicationHostOptions)
         {
             _loggerFactory = loggerFactory;
             _eventManager = eventManager;
@@ -44,12 +46,14 @@ public RpcWorkerProcessFactory(IRpcServer rpcServer,
             _serviceProvider = serviceProvider;
             _hostingConfigOptions = hostingConfigOptions;
             _environment = environment;
+            _scriptApplicationHostOptions = scriptApplicationHostOptions;
         }
 
         public IWorkerProcess Create(string workerId, string runtime, string scriptRootPath, RpcWorkerConfig workerConfig)
         {
             ILogger workerProcessLogger = _loggerFactory.CreateLogger($"Worker.rpcWorkerProcess.{runtime}.{workerId}");
-            return new RpcWorkerProcess(runtime, workerId, scriptRootPath, _rpcServer.Uri, workerConfig, _eventManager, _workerProcessFactory, _processRegistry, workerProcessLogger, _consoleLogSource, _metricsLogger, _serviceProvider, _hostingConfigOptions, _environment, _loggerFactory);
+            return new RpcWorkerProcess(runtime, workerId, scriptRootPath, _rpcServer.Uri, workerConfig, _eventManager, _workerProcessFactory, _processRegistry,
+                workerProcessLogger, _consoleLogSource, _metricsLogger, _serviceProvider, _hostingConfigOptions, _environment, _scriptApplicationHostOptions, _loggerFactory);
         }
     }
 }

src/WebJobs.Script/Workers/WorkerConsoleLogService.cs

@@ -7,18 +7,21 @@
 using System.Threading.Tasks.Dataflow;
 using Microsoft.Extensions.Hosting;
 using Microsoft.Extensions.Logging;
+using Microsoft.Extensions.Options;
 
 namespace Microsoft.Azure.WebJobs.Script.Workers
 {
     internal class WorkerConsoleLogService : IHostedService, IDisposable
     {
         private readonly ILogger _logger;
+        private readonly ScriptApplicationHostOptions _options;
         private readonly IWorkerConsoleLogSource _source;
         private readonly CancellationTokenSource _cts = new CancellationTokenSource();
         private Task _processingTask;
         private bool _disposed = false;
 
-        public WorkerConsoleLogService(ILoggerFactory loggerFactory, IWorkerConsoleLogSource consoleLogSource)
+        public WorkerConsoleLogService(ILoggerFactory loggerFactory, IWorkerConsoleLogSource consoleLogSource,
+            IOptions<ScriptApplicationHostOptions> options)
         {
             if (loggerFactory == null)
             {
@@ -27,6 +30,7 @@ public WorkerConsoleLogService(ILoggerFactory loggerFactory, IWorkerConsoleLogSo
 
             _source = consoleLogSource ?? throw new ArgumentNullException(nameof(consoleLogSource));
             _logger = loggerFactory.CreateLogger(WorkerConstants.ConsoleLogCategoryName);
+            _options = options.Value;
         }
 
         internal WorkerConsoleLogService(ILogger logger, IWorkerConsoleLogSource consoleLogSource)
@@ -37,7 +41,12 @@ internal WorkerConsoleLogService(ILogger logger, IWorkerConsoleLogSource console
 
         public Task StartAsync(CancellationToken cancellationToken)
         {
-            _processingTask = ProcessLogs();
+            // Don't start processing logs if this is a standby configuration. This can lead
+            // to placeholder loggers capturing user logs during specialization.
+            if (!_options.IsStandbyConfiguration)
+            {
+                _processingTask = ProcessLogs();
+            }
             return Task.CompletedTask;
         }
 

test/DotNetIsolated60/Program.cs

@@ -1,6 +1,7 @@
-using Microsoft.Azure.Functions.Worker;
 using Microsoft.Extensions.Hosting;
 
+Console.WriteLine("Console Out from worker on startup.");
+
 //Debugger.Launch();
 
 // Tests can set an env var that will swap this to use the proxy

test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/SpecializationE2ETests.cs

@@ -27,6 +27,7 @@
 using Microsoft.Azure.WebJobs.Script.Description;
 using Microsoft.Azure.WebJobs.Script.Grpc;
 using Microsoft.Azure.WebJobs.Script.WebHost;
+using Microsoft.Azure.WebJobs.Script.Workers;
 using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.DependencyInjection;
@@ -55,6 +56,8 @@ public class SpecializationE2ETests
         private static readonly string _dotnetIsolatedUnsuppportedPath = Path.GetFullPath(@"..\..\DotNetIsolatedUnsupportedWorker\debug");
         private static readonly string _dotnetIsolatedEmptyScriptRoot = Path.GetFullPath(@"..\..\..\..\EmptyScriptRoot");
 
+        private static Action<IServiceCollection> _customizeScriptHostServices;
+
         private const string _specializedScriptRoot = @"TestScripts\CSharp";
 
         private readonly TestEnvironment _environment;
@@ -76,6 +79,9 @@ public SpecializationE2ETests(ITestOutputHelper testOutputHelper)
             _loggerProvider = new TestLoggerProvider();
 
             _testOutputHelper = testOutputHelper;
+
+            // allow each test to override this
+            _customizeScriptHostServices = null;
         }
 
         [Fact]
@@ -1034,6 +1040,57 @@ await TestHelpers.Await(() =>
             Assert.Empty(completedLogs.Where(p => p.Level == LogLevel.Error));
         }
 
+        [Fact]
+        public async Task Specialization_Writes_WorkerStartupLogs()
+        {
+            // Create a test logger per-host so we can ensure logs go to the correct one when specializing
+            var perScriptHostLoggers = new List<(bool IsPlaceholderMode, TestLoggerProvider Logger)>();
+            _customizeScriptHostServices = s =>
+            {
+                var isPlaceholderMode = _environment.GetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode);
+                var testLoggerProvider = new TestLoggerProvider();
+                perScriptHostLoggers.Add(new(isPlaceholderMode == "1", testLoggerProvider));
+
+                s.AddSingleton<ILoggerProvider>(testLoggerProvider);
+            };
+
+            var builder = InitializeDotNetIsolatedPlaceholderBuilder(_dotnetIsolated60Path, "HttpRequestDataFunction", "QueueFunction");
+            var storageValue = TestHelpers.GetTestConfiguration().GetWebJobsConnectionString("AzureWebJobsStorage");
+
+            using var testServer = new TestServer(builder);
+
+            var client = testServer.CreateClient();
+            var response = await client.GetAsync("api/warmup");
+            response.EnsureSuccessStatusCode();
+
+            var webChannelManager = testServer.Services.GetService<IWebHostRpcWorkerChannelManager>();
+            var placeholderChannel = await webChannelManager.GetChannels("dotnet-isolated").Single().Value.Task;
+            var process = placeholderChannel.WorkerProcess as WorkerProcess;
+            process.BuildAndLogConsoleLog("Fake console out from placeholder", LogLevel.Information);
+
+            _environment.SetEnvironmentVariable("AzureWebJobsStorage", storageValue);
+            _environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsiteContainerReady, "1");
+            _environment.SetEnvironmentVariable(EnvironmentSettingNames.AzureWebsitePlaceholderMode, "0");
+
+            response = await client.GetAsync("api/HttpRequestDataFunction");
+            response.EnsureSuccessStatusCode();
+
+            var placeholderLogger = perScriptHostLoggers.Single(p => p.IsPlaceholderMode).Logger;
+            var userLogger = perScriptHostLoggers.Single(p => !p.IsPlaceholderMode).Logger;
+
+            string logs = placeholderLogger.GetLog();
+
+            Assert.Null(placeholderLogger.GetAllLogMessages().SingleOrDefault(p => p.Category == "Host.Function.Console"));
+            var placeholderMessages = placeholderLogger.GetAllLogMessages().Select(p => p.FormattedMessage);
+            Assert.DoesNotContain("Console Out from worker on startup.", placeholderMessages);
+            Assert.DoesNotContain("Fake console out from placeholder", placeholderMessages); // placeholder 'user' console logs should never be logged
+
+            Assert.Single(userLogger.GetAllLogMessages().Select(p => p.Category), "Host.Function.Console");
+            var userMessages = userLogger.GetAllLogMessages().Select(p => p.FormattedMessage);
+            Assert.Contains("Console Out from worker on startup.", userMessages);
+            Assert.DoesNotContain("Fake console out from placeholder", userMessages); // this log should be 'lost' and never written
+        }
+
         private async Task DotNetIsolatedPlaceholderMiss(string scriptRootPath, Action additionalSpecializedSetup = null)
         {
             var builder = InitializeDotNetIsolatedPlaceholderBuilder(scriptRootPath, "HttpRequestDataFunction");
@@ -1153,6 +1210,8 @@ private IWebHostBuilder CreateStandbyHostBuilder(params string[] functions)
                             o.Functions = functions;
                         }
                     });
+
+                    _customizeScriptHostServices?.Invoke(s);
                 });
 
             return builder;

test/WebJobs.Script.Tests.Shared/TestOptionsMonitor.cs

@@ -12,6 +12,11 @@ namespace Microsoft.Azure.WebJobs.Script.Tests
         private readonly Func<T> _optionsFactory;
         private Action<T, string> _listener;
 
+        public TestOptionsMonitor()
+            : this(() => new T())
+        {
+        }
+
         public TestOptionsMonitor(T options)
             : this(() => options ?? new T())
         {