Adding a new logger for tooling console log entries from language wor…

…kers so that they are always logged as Informational (#8435)

* Adding a new logger for console json log entries emitted from worker via standard output (Console.WriteLine) with Information level as the logging level so that the logging level set for Host is not affecting these log entries as they are being used by debuggers/IDEs

* Tiny clean up on tests

* Adding a null check on constructor.

* Renamed the constant for logger category name to remove the "Function" prefix.

src/WebJobs.Script.WebHost/Diagnostics/SystemLoggerProvider.cs

@@ -49,7 +49,7 @@ public ILogger CreateLogger(string categoryName)
 
         private bool IsUserLogCategory(string categoryName)
         {
-            return LogCategories.IsFunctionUserCategory(categoryName) || categoryName.Equals(WorkerConstants.FunctionConsoleLogCategoryName, StringComparison.OrdinalIgnoreCase);
+            return LogCategories.IsFunctionUserCategory(categoryName) || categoryName.Equals(WorkerConstants.ConsoleLogCategoryName, StringComparison.OrdinalIgnoreCase);
         }
 
         public void Dispose()

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.ToolingConsoleLogCategoryName, 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.ToolingConsoleLogPrefix, StringComparison.OrdinalIgnoreCase);
+        }
+
+        public static string RemoveToolingConsoleJsonLogPrefix(string msg)
+        {
+            return Regex.Replace(msg, WorkerConstants.ToolingConsoleLogPrefix, 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;
@@ -26,13 +27,15 @@ public WorkerConsoleLogService(ILoggerFactory loggerFactory, IWorkerConsoleLogSo
             }
 
             _source = consoleLogSource ?? throw new ArgumentNullException(nameof(consoleLogSource));
-            _logger = loggerFactory.CreateLogger(WorkerConstants.FunctionConsoleLogCategoryName);
+            _logger = loggerFactory.CreateLogger(WorkerConstants.ConsoleLogCategoryName);
+            _toolingConsoleJsonLoggerLazy = new Lazy<ILogger>(() => loggerFactory.CreateLogger(WorkerConstants.ToolingConsoleLogCategoryName), 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

@@ -33,7 +33,18 @@ public static class WorkerConstants
 
         // Logs
         public const string LanguageWorkerConsoleLogPrefix = "LanguageWorkerConsoleLog";
-        public const string FunctionConsoleLogCategoryName = "Host.Function.Console";
+        public const string ConsoleLogCategoryName = "Host.Function.Console";
+
+        /// <summary>
+        /// The log category to be used for logging Tooling log entries emitted from language workers.
+        /// </summary>
+        public const string ToolingConsoleLogCategoryName = "Host.Function.ToolingConsoleLog";
+
+        /// <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 ToolingConsoleLogPrefix = "azfuncjsonlog:";
 
         // Thresholds
         public const int WorkerRestartErrorIntervalThresholdInMinutes = 30;

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

@@ -124,7 +124,7 @@ await TestHelpers.Await(() =>
             IEnumerable<FunctionTraceEvent> allLogs = Fixture.EventGenerator.GetFunctionTraceEvents();
             Assert.False(allLogs.Any(l => l.Summary.Contains("From ")));
             Assert.False(allLogs.Any(l => l.Source.EndsWith(".User")));
-            Assert.False(allLogs.Any(l => l.Source == WorkerConstants.FunctionConsoleLogCategoryName));
+            Assert.False(allLogs.Any(l => l.Source == WorkerConstants.ConsoleLogCategoryName));
             Assert.NotEmpty(allLogs);
         }
 

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

@@ -192,7 +192,7 @@ public async Task Scenario_Logging()
             await TestHelpers.Await(() =>
             {
                 userLogs = Fixture.Host.GetScriptHostLogMessages(userCategory).Select(p => p.FormattedMessage).ToList();
-                consoleLog = Fixture.Host.GetScriptHostLogMessages(WorkerConstants.FunctionConsoleLogCategoryName).Select(p => p.FormattedMessage).SingleOrDefault();
+                consoleLog = Fixture.Host.GetScriptHostLogMessages(WorkerConstants.ConsoleLogCategoryName).Select(p => p.FormattedMessage).SingleOrDefault();
                 return userLogs.Count == 11 && consoleLog != null;
             }, userMessageCallback: Fixture.Host.GetLog);
 
@@ -232,7 +232,7 @@ await TestHelpers.Await(() =>
             Assert.False(allLogs.Any(l => l.Summary.Contains("loglevel")));
             Assert.False(allLogs.Any(l => l.Summary.Contains("after done")));
             Assert.False(allLogs.Any(l => l.Source.EndsWith(".User")));
-            Assert.False(allLogs.Any(l => l.Source == WorkerConstants.FunctionConsoleLogCategoryName));
+            Assert.False(allLogs.Any(l => l.Source == WorkerConstants.ConsoleLogCategoryName));
             Assert.NotEmpty(allLogs);
         }
 

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.ToolingConsoleLog");
+            _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.ToolingConsoleLogPrefix, message.FormattedMessage);
             Assert.Equal(expectedLevel, message.Level);
         }
     }