fetching IsToolingConsoleJsonLogEntry earlier to break the debugging …

…deadlock (#9486)

* fetching IsToolingConsoleJsonLogEntry earlier to break the debugging deadlock

* PR fixes

* Fixing unit test failure

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

@@ -31,8 +31,9 @@ internal HttpWorkerProcess(string workerId,
                                        IWorkerConsoleLogSource consoleLogSource,
                                        IEnvironment environment,
                                        IMetricsLogger metricsLogger,
-                                       IServiceProvider serviceProvider)
-            : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, httpWorkerOptions.Description.UseStdErrorStreamForErrorsOnly)
+                                       IServiceProvider serviceProvider,
+                                       ILoggerFactory loggerFactory)
+            : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, loggerFactory, httpWorkerOptions.Description.UseStdErrorStreamForErrorsOnly)
         {
             _processFactory = processFactory;
             _eventManager = eventManager;

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

@@ -41,7 +41,7 @@ public HttpWorkerProcessFactory(IScriptEventManager eventManager,
         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);
+            return new HttpWorkerProcess(workerId, scriptRootPath, httpWorkerOptions, _eventManager, _workerProcessFactory, _processRegistry, workerProcessLogger, _consoleLogSource, _environment, _metricsLogger, _serviceProvider, _loggerFactory);
         }
     }
 }

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

@@ -26,13 +26,14 @@ internal abstract class WorkerProcess : IWorkerProcess, IDisposable
         private readonly int processExitTimeoutInMilliseconds = 1000;
         private readonly IServiceProvider _serviceProvider;
         private readonly IDisposable _eventSubscription;
+        private readonly Lazy<ILogger> _toolingConsoleJsonLoggerLazy;
 
         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, bool useStdErrStreamForErrorsOnly = false)
+        internal WorkerProcess(IScriptEventManager eventManager, IProcessRegistry processRegistry, ILogger workerProcessLogger, IWorkerConsoleLogSource consoleLogSource, IMetricsLogger metricsLogger, IServiceProvider serviceProvider, ILoggerFactory loggerFactory, bool useStdErrStreamForErrorsOnly = false)
         {
             _processRegistry = processRegistry;
             _workerProcessLogger = workerProcessLogger;
@@ -41,6 +42,7 @@ internal WorkerProcess(IScriptEventManager eventManager, IProcessRegistry proces
             _metricsLogger = metricsLogger;
             _useStdErrorStreamForErrorsOnly = useStdErrStreamForErrorsOnly;
             _serviceProvider = serviceProvider;
+            _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => loggerFactory.CreateLogger(WorkerConstants.ToolingConsoleLogCategoryName), isThreadSafe: true);
 
             // We subscribe to host start events so we can handle the restart that occurs
             // on host specialization.
@@ -193,10 +195,16 @@ internal void BuildAndLogConsoleLog(string msg, LogLevel level)
                 Message = msg,
                 Level = level
             };
+
             if (WorkerProcessUtilities.IsConsoleLog(msg))
             {
                 _workerProcessLogger?.Log(level, WorkerProcessUtilities.RemoveLogPrefix(msg));
             }
+            else if (WorkerProcessUtilities.IsToolingConsoleJsonLogEntry(msg))
+            {
+                // log with the message prefix as coretools expects it.
+                _toolingConsoleJsonLoggerLazy.Value.Log(level, msg);
+            }
             else
             {
                 _consoleLogSource?.Log(consoleLog);

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

@@ -39,9 +39,9 @@ public static string RemoveLogPrefix(string msg)
             return Regex.Replace(msg, WorkerConstants.LanguageWorkerConsoleLogPrefix, string.Empty, RegexOptions.IgnoreCase);
         }
 
-        public static bool IsToolingConsoleJsonLogEntry(ConsoleLog consoleLog)
+        public static bool IsToolingConsoleJsonLogEntry(string msg)
         {
-            return consoleLog.Message.StartsWith(WorkerConstants.ToolingConsoleLogPrefix, StringComparison.OrdinalIgnoreCase);
+            return msg.StartsWith(WorkerConstants.ToolingConsoleLogPrefix, StringComparison.OrdinalIgnoreCase);
         }
     }
 }

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

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

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

@@ -49,7 +49,7 @@ public RpcWorkerProcessFactory(IRpcServer rpcServer,
         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);
+            return new RpcWorkerProcess(runtime, workerId, scriptRootPath, _rpcServer.Uri, workerConfig, _eventManager, _workerProcessFactory, _processRegistry, workerProcessLogger, _consoleLogSource, _metricsLogger, _serviceProvider, _hostingConfigOptions, _environment, _loggerFactory);
         }
     }
 }

src/WebJobs.Script/Workers/WorkerConsoleLogService.cs

@@ -13,7 +13,6 @@ namespace Microsoft.Azure.WebJobs.Script.Workers
     internal class WorkerConsoleLogService : IHostedService, IDisposable
     {
         private readonly ILogger _logger;
-        private readonly Lazy<ILogger> _toolingConsoleJsonLoggerLazy;
         private readonly IWorkerConsoleLogSource _source;
         private readonly CancellationTokenSource _cts = new CancellationTokenSource();
         private Task _processingTask;
@@ -28,14 +27,12 @@ public WorkerConsoleLogService(ILoggerFactory loggerFactory, IWorkerConsoleLogSo
 
             _source = consoleLogSource ?? throw new ArgumentNullException(nameof(consoleLogSource));
             _logger = loggerFactory.CreateLogger(WorkerConstants.ConsoleLogCategoryName);
-            _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => loggerFactory.CreateLogger(WorkerConstants.ToolingConsoleLogCategoryName), isThreadSafe: true);
         }
 
-        internal WorkerConsoleLogService(ILogger logger, Lazy<ILogger> toolingConsoleJsonLoggerLazy, IWorkerConsoleLogSource consoleLogSource)
+        internal WorkerConsoleLogService(ILogger logger, IWorkerConsoleLogSource consoleLogSource)
         {
             _source = consoleLogSource ?? throw new ArgumentNullException(nameof(consoleLogSource));
             _logger = logger ?? throw new ArgumentNullException(nameof(logger));
-            _toolingConsoleJsonLoggerLazy = toolingConsoleJsonLoggerLazy ?? throw new ArgumentNullException(nameof(toolingConsoleJsonLoggerLazy));
         }
 
         public Task StartAsync(CancellationToken cancellationToken)
@@ -62,16 +59,7 @@ internal async Task ProcessLogs()
                 while (await source.OutputAvailableAsync(_cts.Token))
                 {
                     var consoleLog = await source.ReceiveAsync();
-
-                    if (WorkerProcessUtilities.IsToolingConsoleJsonLogEntry(consoleLog))
-                    {
-                        // log with the message prefix as coretools expects it.
-                        _toolingConsoleJsonLoggerLazy.Value.Log(consoleLog.Level, consoleLog.Message);
-                    }
-                    else
-                    {
-                        _logger.Log(consoleLog.Level, consoleLog.Message);
-                    }
+                    _logger.Log(consoleLog.Level, consoleLog.Message);
                 }
             }
             catch (OperationCanceledException)

test/WebJobs.Script.Tests/Workers/Http/HttpWorkerProcessTests.cs

@@ -35,7 +35,7 @@ public HttpWorkerProcessTests()
                 Arguments = new WorkerProcessArguments() { ExecutablePath = "test" },
                 Description = new HttpWorkerDescription()
                 {
-                   WorkingDirectory = @"c:\testDir"
+                    WorkingDirectory = @"c:\testDir"
                 }
             };
             _settingsManager = ScriptSettingsManager.Instance;
@@ -54,7 +54,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);
+                HttpWorkerProcess httpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, new TestEnvironment(), new TestMetricsLogger(), _serviceProviderMock.Object, new LoggerFactory());
                 Process childProcess = httpWorkerProcess.CreateWorkerProcess();
                 Assert.NotNull(childProcess.StartInfo.EnvironmentVariables);
                 Assert.Equal(childProcess.StartInfo.EnvironmentVariables[HttpWorkerConstants.PortEnvVarName], _workerPort.ToString());
@@ -70,7 +70,7 @@ public void CreateWorkerProcess_LinuxConsumption_AssingnsExecutePermissions_invo
         {
             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);
+            var mockHttpWorkerProcess = new HttpWorkerProcess(_testWorkerId, _rootScriptPath, _httpWorkerOptions, _mockEventManager.Object, _defaultWorkerProcessFactory, _processRegistry, _testLogger, _languageWorkerConsoleLogSource.Object, testEnvironment, new TestMetricsLogger(), _serviceProviderMock.Object, new LoggerFactory());
             mockHttpWorkerProcess.CreateWorkerProcess();
             // Verify method invocation
             var testLogs = _testLogger.GetLogMessages();

test/WebJobs.Script.Tests/Workers/Rpc/RpcWorkerProcessTests.cs

@@ -9,6 +9,7 @@
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Azure.WebJobs.Script.Workers;
 using Microsoft.Azure.WebJobs.Script.Workers.Rpc;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Moq;
 using Xunit;
@@ -57,7 +58,8 @@ public RpcWorkerProcessTests()
                 new TestMetricsLogger(),
                 serviceProviderMock.Object,
                 _functionsHostingConfigOptions,
-                testEnv);
+                testEnv,
+                new LoggerFactory());
         }
 
         [Fact]

test/WebJobs.Script.Tests/Workers/TestWorkerProcess.cs

@@ -12,8 +12,8 @@ namespace Microsoft.Azure.WebJobs.Script.Tests.Workers
 {
     internal class TestWorkerProcess : WorkerProcess
     {
-        internal TestWorkerProcess(IScriptEventManager eventManager, IProcessRegistry processRegistry, ILogger workerProcessLogger, IWorkerConsoleLogSource consoleLogSource, IMetricsLogger metricsLogger, IServiceProvider serviceProvider, bool useStdErrStreamForErrorsOnly = false)
-        : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, useStdErrStreamForErrorsOnly)
+        internal TestWorkerProcess(IScriptEventManager eventManager, IProcessRegistry processRegistry, ILogger workerProcessLogger, IWorkerConsoleLogSource consoleLogSource, IMetricsLogger metricsLogger, IServiceProvider serviceProvider, ILoggerFactory loggerFactory, bool useStdErrStreamForErrorsOnly = false)
+        : base(eventManager, processRegistry, workerProcessLogger, consoleLogSource, metricsLogger, serviceProvider, loggerFactory, useStdErrStreamForErrorsOnly)
         {
         }
 

test/WebJobs.Script.Tests/Workers/WorkerConsoleLogServiceTests.cs

@@ -5,30 +5,35 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Threading.Tasks;
+using Castle.Core.Logging;
 using Microsoft.Azure.WebJobs.Script.Eventing;
 using Microsoft.Azure.WebJobs.Script.Workers;
 using Microsoft.Extensions.Logging;
+using Microsoft.WebJobs.Script.Tests;
 using Moq;
 using Xunit;
 
 namespace Microsoft.Azure.WebJobs.Script.Tests.Workers
 {
     public class WorkerConsoleLogServiceTests
     {
-        private TestLogger _toolingConsoleTestLogger;
         private IScriptEventManager _eventManager;
         private IProcessRegistry _processRegistry;
         private TestLogger _testUserLogger = new TestLogger("Host.Function.Console");
         private TestLogger _testSystemLogger = new TestLogger("Worker.rpcWorkerProcess");
-        private Lazy<ILogger> _toolingConsoleJsonLoggerLazy;
         private WorkerConsoleLogService _workerConsoleLogService;
         private WorkerConsoleLogSource _workerConsoleLogSource;
         private Mock<IServiceProvider> _serviceProviderMock;
+        private static Microsoft.Extensions.Logging.ILogger _testLogger;
+        private static TestLoggerProvider _testLoggerProvider;
+        private static LoggerFactory _testLoggerFactory;
 
         public WorkerConsoleLogServiceTests()
         {
-            _toolingConsoleTestLogger = new TestLogger("Host.Function.ToolingConsoleLog");
-            _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => _toolingConsoleTestLogger, true);
+            _testLoggerProvider = new TestLoggerProvider();
+            _testLoggerFactory = new LoggerFactory();
+            _testLoggerFactory.AddProvider(_testLoggerProvider);
+            _testLogger = _testLoggerProvider.CreateLogger(WorkerConstants.ToolingConsoleLogCategoryName);
         }
 
         [Theory]
@@ -40,10 +45,10 @@ public async Task WorkerConsoleLogService_ConsoleLogs_LogLevel_Expected(bool use
             _workerConsoleLogSource = new WorkerConsoleLogSource();
             _eventManager = new ScriptEventManager();
             _processRegistry = new EmptyProcessRegistry();
-            _workerConsoleLogService = new WorkerConsoleLogService(_testUserLogger, _toolingConsoleJsonLoggerLazy, _workerConsoleLogSource);
+            _workerConsoleLogService = new WorkerConsoleLogService(_testUserLogger, _workerConsoleLogSource);
             _serviceProviderMock = new Mock<IServiceProvider>(MockBehavior.Strict);
 
-            WorkerProcess workerProcess = new TestWorkerProcess(_eventManager, _processRegistry, _testSystemLogger, _workerConsoleLogSource, null, _serviceProviderMock.Object, useStdErrForErrorLogsOnly);
+            WorkerProcess workerProcess = new TestWorkerProcess(_eventManager, _processRegistry, _testSystemLogger, _workerConsoleLogSource, null, _serviceProviderMock.Object, _testLoggerFactory, useStdErrForErrorLogsOnly);
             workerProcess.ParseErrorMessageAndLog("Test Message No keyword");
             workerProcess.ParseErrorMessageAndLog("Test Error Message");
             workerProcess.ParseErrorMessageAndLog("Test Warning Message");
@@ -57,7 +62,7 @@ public async Task WorkerConsoleLogService_ConsoleLogs_LogLevel_Expected(bool use
             await _workerConsoleLogService.StopAsync(System.Threading.CancellationToken.None);
             var userLogs = _testUserLogger.GetLogMessages();
             var systemLogs = _testSystemLogger.GetLogMessages();
-            var toolingConsoleLogs = _toolingConsoleTestLogger.GetLogMessages();
+            var toolingConsoleLogs = _testLoggerProvider.GetAllLogMessages();
 
             // Assert
             Assert.Equal(3, userLogs.Count);