improving behavior by ignoring 'user' console logs completely when in…

… placeholder mode
Azure · Sep 10, 2024 · e93345c · e93345c
1 parent 7ea373e
commit e93345c
Show file tree

Hide file tree

Showing 9 changed files with 60 additions and 16 deletions.
diff --git a/src/WebJobs.Script/Workers/Http/HttpWorkerProcess.cs b/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;

diff --git a/src/WebJobs.Script/Workers/Http/HttpWorkerProcessFactory.cs b/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);
         }
     }
 }
diff --git a/src/WebJobs.Script/Workers/ProcessManagement/WorkerProcess.cs b/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);
+                }
             }
         }
 

diff --git a/src/WebJobs.Script/Workers/Rpc/RpcWorkerProcess.cs b/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;

diff --git a/src/WebJobs.Script/Workers/Rpc/RpcWorkerProcessFactory.cs b/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);
         }
     }
 }
diff --git a/test/WebJobs.Script.Tests.Integration/WebHostEndToEnd/SpecializationE2ETests.cs b/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;
@@ -1062,6 +1063,11 @@ public async Task Specialization_Writes_WorkerStartupLogs()
             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");
@@ -1072,11 +1078,17 @@ public async Task Specialization_Writes_WorkerStartupLogs()
             var placeholderLogger = perScriptHostLoggers.Single(p => p.IsPlaceholderMode).Logger;
             var userLogger = perScriptHostLoggers.Single(p => !p.IsPlaceholderMode).Logger;
 
-            Assert.DoesNotContain("Host.Function.Console", placeholderLogger.GetAllLogMessages().Select(p => p.Category));
-            Assert.DoesNotContain("Console Out from worker on startup.", placeholderLogger.GetAllLogMessages().Select(p => p.FormattedMessage));
+            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.Contains("Host.Function.Console", userLogger.GetAllLogMessages().Select(p => p.Category));
-            Assert.Contains("Console Out from worker on startup.", userLogger.GetAllLogMessages().Select(p => p.FormattedMessage));
+            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)

diff --git a/test/WebJobs.Script.Tests.Shared/TestOptionsMonitor.cs b/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())
         {

diff --git a/test/WebJobs.Script.Tests/Workers/Http/HttpWorkerProcessTests.cs b/test/WebJobs.Script.Tests/Workers/Http/HttpWorkerProcessTests.cs
@@ -30,6 +30,7 @@ public class HttpWorkerProcessTests
         private readonly TestLogger _testLogger = new TestLogger("test");
         private readonly HttpWorkerOptions _httpWorkerOptions;
         private readonly Mock<IServiceProvider> _serviceProviderMock;
+        private readonly TestOptionsMonitor<ScriptApplicationHostOptions> _scriptApplicationHostOptions = new();
 
         public HttpWorkerProcessTests()
         {
@@ -58,7 +59,7 @@ public void CreateWorkerProcess_VerifyEnvVars(string processEnvValue)
                 {
                     Assert.Equal(Environment.GetEnvironmentVariable(HttpWorkerConstants.PortEnvVarName), processEnvValue);
                 }
-                HttpWorkerProcess httpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, new TestEnvironment(), new TestMetricsLogger(), _serviceProviderMock.Object, new LoggerFactory());
+                HttpWorkerProcess httpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, new TestEnvironment(), new TestMetricsLogger(), _serviceProviderMock.Object, _scriptApplicationHostOptions, new LoggerFactory());
                 Process childProcess = httpWorkerProcess.CreateWorkerProcess();
                 Assert.NotNull(childProcess.StartInfo.EnvironmentVariables);
                 Assert.Equal(childProcess.StartInfo.EnvironmentVariables[HttpWorkerConstants.PortEnvVarName], _workerPort.ToString());
@@ -77,7 +78,7 @@ public async Task StartProcess_LinuxConsumption_TriesToAssignExecutePermissions_
                 File.Create(_executablePath).Dispose();
                 TestEnvironment testEnvironment = new TestEnvironment();
                 testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.ContainerName, "TestContainer");
-                var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, new LoggerFactory());
+                var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, _scriptApplicationHostOptions, new LoggerFactory());
 
                 try
                 {
@@ -104,7 +105,7 @@ public async Task StartProcess_LinuxConsumption_TriesToAssignExecutePermissions_
             File.Delete(_executablePath);
             TestEnvironment testEnvironment = new TestEnvironment();
             testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.ContainerName, "TestContainer");
-            var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, new LoggerFactory());
+            var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, _scriptApplicationHostOptions, new LoggerFactory());
 
             try
             {
@@ -132,7 +133,7 @@ public async Task StartProcess_VerifySanitizedCredentialLogging(string input, bo
                 File.Create(_executablePath).Dispose();
                 TestEnvironment testEnvironment = new TestEnvironment();
                 testEnvironment.SetEnvironmentVariable(EnvironmentSettingNames.ContainerName, "TestContainer");
-                var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, new LoggerFactory());
+                var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, _scriptApplicationHostOptions, new LoggerFactory());
 
                 try
                 {

diff --git a/test/WebJobs.Script.Tests/Workers/Rpc/RpcWorkerProcessTests.cs b/test/WebJobs.Script.Tests/Workers/Rpc/RpcWorkerProcessTests.cs
@@ -44,6 +44,7 @@ public RpcWorkerProcessTests()
             serviceProviderMock.Setup(p => p.GetService(typeof(IScriptHostManager))).Returns(scriptHostManagerMock.Object);
 
             _functionsHostingConfigOptions = Options.Create(new FunctionsHostingConfigOptions());
+            var scriptApplicationHostOptions = new TestOptionsMonitor<ScriptApplicationHostOptions>();
 
             _rpcWorkerProcess = new RpcWorkerProcess("node",
                 "testworkerId",
@@ -59,6 +60,7 @@ public RpcWorkerProcessTests()
                 serviceProviderMock.Object,
                 _functionsHostingConfigOptions,
                 testEnv,
+                scriptApplicationHostOptions,
                 new LoggerFactory());
         }