Adding a new logger for tooling console log entries from language workers so that they are always logged as Informational

src/WebJobs.Script/Extensions/ScriptLoggingBuilderExtensions.cs

@@ -6,6 +6,7 @@
 using Microsoft.AspNetCore.Hosting;
 using Microsoft.Azure.WebJobs.Script;
 using Microsoft.Azure.WebJobs.Script.Configuration;
+using Microsoft.Azure.WebJobs.Script.Workers;
 using Microsoft.Extensions.Configuration;
 using Microsoft.Extensions.Hosting;
 
@@ -65,7 +66,10 @@ private static void AddConsoleIfEnabled(ILoggingBuilder builder, bool isDevelopm
 
             if (enableConsole)
             {
-                builder.AddConsole();
+                builder.AddConsole()
+                       // Tooling console json log entries are meant to be used by IDEs / Debuggers.
+                       // Users are not supposed to set the log level for this category via host.JSON logging settings.
+                       .AddFilter(WorkerConstants.FunctionToolingConsoleJsonCategoryName, LogLevel.Information);
             }
         }
     }

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

@@ -38,5 +38,15 @@ public static string RemoveLogPrefix(string msg)
         {
             return Regex.Replace(msg, WorkerConstants.LanguageWorkerConsoleLogPrefix, string.Empty, RegexOptions.IgnoreCase);
         }
+
+        public static bool IsToolingConsoleJsonLogEntry(ConsoleLog consoleLog)
+        {
+            return consoleLog.Message.StartsWith(WorkerConstants.ToolingConsoleJsonLogEntryPrefix, StringComparison.OrdinalIgnoreCase);
+        }
+
+        public static string RemoveToolingConsoleJsonLogPrefix(string msg)
+        {
+            return Regex.Replace(msg, WorkerConstants.ToolingConsoleJsonLogEntryPrefix, string.Empty, RegexOptions.IgnoreCase);
+        }
     }
 }

src/WebJobs.Script/Workers/WorkerConsoleLogService.cs

@@ -13,6 +13,7 @@ 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;
@@ -27,12 +28,14 @@ public WorkerConsoleLogService(ILoggerFactory loggerFactory, IWorkerConsoleLogSo
 
             _source = consoleLogSource ?? throw new ArgumentNullException(nameof(consoleLogSource));
             _logger = loggerFactory.CreateLogger(WorkerConstants.FunctionConsoleLogCategoryName);
+            _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => loggerFactory.CreateLogger(WorkerConstants.FunctionToolingConsoleJsonCategoryName), isThreadSafe: true);
         }
 
-        internal WorkerConsoleLogService(ILogger logger, IWorkerConsoleLogSource consoleLogSource)
+        internal WorkerConsoleLogService(ILogger logger, Lazy<ILogger> toolingConsoleJsonLoggerLazy, 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)
@@ -59,7 +62,16 @@ internal async Task ProcessLogs()
                 while (await source.OutputAvailableAsync(_cts.Token))
                 {
                     var consoleLog = await source.ReceiveAsync();
-                    _logger.Log(consoleLog.Level, consoleLog.Message);
+
+                    if (WorkerProcessUtilities.IsToolingConsoleJsonLogEntry(consoleLog))
+                    {
+                        _toolingConsoleJsonLoggerLazy.Value.Log(consoleLog.Level,
+                            WorkerProcessUtilities.RemoveToolingConsoleJsonLogPrefix(consoleLog.Message));
+                    }
+                    else
+                    {
+                        _logger.Log(consoleLog.Level, consoleLog.Message);
+                    }
                 }
             }
             catch (OperationCanceledException)

src/WebJobs.Script/Workers/WorkerConstants.cs

@@ -35,6 +35,17 @@ public static class WorkerConstants
         public const string LanguageWorkerConsoleLogPrefix = "LanguageWorkerConsoleLog";
         public const string FunctionConsoleLogCategoryName = "Host.Function.Console";
 
+        /// <summary>
+        /// The log category to be used for logging Tooling log entries emitted from language workers.
+        /// </summary>
+        public const string FunctionToolingConsoleJsonCategoryName = "Host.Function.ToolingConsoleJson";
+
+        /// <summary>
+        /// The prefix used by language workers when sending a tooling data log entry via Console.WriteLine.
+        /// Tooling data log entries are meant to be used by IDEs / Debuggers.
+        /// </summary>
+        public const string ToolingConsoleJsonLogEntryPrefix = "azfuncjsonlog:";
+
         // Thresholds
         public const int WorkerRestartErrorIntervalThresholdInMinutes = 30;
 

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

@@ -15,14 +15,22 @@ 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;
 
+        public WorkerConsoleLogServiceTests()
+        {
+            _toolingConsoleTestLogger = new TestLogger("Host.Function.ToolingConsole");
+            _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => _toolingConsoleTestLogger, true);
+        }
+
         [Theory]
         [InlineData(false)]
         [InlineData(true)]
@@ -32,7 +40,7 @@ public async Task WorkerConsoleLogService_ConsoleLogs_LogLevel_Expected(bool use
             _workerConsoleLogSource = new WorkerConsoleLogSource();
             _eventManager = new ScriptEventManager();
             _processRegistry = new EmptyProcessRegistry();
-            _workerConsoleLogService = new WorkerConsoleLogService(_testUserLogger, _workerConsoleLogSource);
+            _workerConsoleLogService = new WorkerConsoleLogService(_testUserLogger, _toolingConsoleJsonLoggerLazy, _workerConsoleLogSource);
             _serviceProviderMock = new Mock<IServiceProvider>(MockBehavior.Strict);
 
             WorkerProcess workerProcess = new TestWorkerProcess(_eventManager, _processRegistry, _testSystemLogger, _workerConsoleLogSource, null, _serviceProviderMock.Object, useStdErrForErrorLogsOnly);
@@ -42,16 +50,19 @@ public async Task WorkerConsoleLogService_ConsoleLogs_LogLevel_Expected(bool use
             workerProcess.ParseErrorMessageAndLog("LanguageWorkerConsoleLog[Test Worker Message No keyword]");
             workerProcess.ParseErrorMessageAndLog("LanguageWorkerConsoleLog[Test Worker Error Message]");
             workerProcess.ParseErrorMessageAndLog("LanguageWorkerConsoleLog[Test Worker Warning Message]");
+            workerProcess.ParseErrorMessageAndLog("azfuncjsonlog:Azure Functions .NET Worker (PID: 4) initialized in debug mode.");
 
             // Act
             _ = _workerConsoleLogService.ProcessLogs().ContinueWith(t => { });
             await _workerConsoleLogService.StopAsync(System.Threading.CancellationToken.None);
             var userLogs = _testUserLogger.GetLogMessages();
             var systemLogs = _testSystemLogger.GetLogMessages();
+            var toolingConsoleLogs = _toolingConsoleTestLogger.GetLogMessages();
 
             // Assert
-            Assert.True(userLogs.Count == 3);
-            Assert.True(systemLogs.Count == 3);
+            Assert.Equal(3, userLogs.Count);
+            Assert.Equal(3, systemLogs.Count);
+            Assert.Equal(1, toolingConsoleLogs.Count);
 
             VerifyLogLevel(userLogs, "Test Error Message", LogLevel.Error);
             VerifyLogLevel(systemLogs, "[Test Worker Error Message]", LogLevel.Error);
@@ -62,19 +73,22 @@ public async Task WorkerConsoleLogService_ConsoleLogs_LogLevel_Expected(bool use
             {
                 VerifyLogLevel(userLogs, "Test Message No keyword", LogLevel.Error);
                 VerifyLogLevel(systemLogs, "[Test Worker Message No keyword]", LogLevel.Error);
+                VerifyLogLevel(toolingConsoleLogs, "Azure Functions .NET Worker (PID: 4) initialized in debug mode.", LogLevel.Error);
             }
             else
             {
                 VerifyLogLevel(userLogs, "Test Message No keyword", LogLevel.Information);
                 VerifyLogLevel(systemLogs, "[Test Worker Message No keyword]", LogLevel.Information);
+                VerifyLogLevel(toolingConsoleLogs, "Azure Functions .NET Worker (PID: 4) initialized in debug mode.", LogLevel.Information);
             }
         }
 
         private static void VerifyLogLevel(IList<LogMessage> allLogs, string msg, LogLevel expectedLevel)
         {
-            var message = allLogs.Where(l => l.FormattedMessage.Contains(msg)).FirstOrDefault();
+            var message = allLogs.FirstOrDefault(l => l.FormattedMessage.Contains(msg));
             Assert.NotNull(message);
             Assert.DoesNotContain(WorkerConstants.LanguageWorkerConsoleLogPrefix, message.FormattedMessage);
+            Assert.DoesNotContain(WorkerConstants.ToolingConsoleJsonLogEntryPrefix, message.FormattedMessage);
             Assert.Equal(expectedLevel, message.Level);
         }
     }