Avoid creating RpcLogger instances unnecessarily by adding static method 'WriteSystemLog' to RpcLogger (#170)

Author: daxian-dbw

src/Logging/RpcLogger.cs

@@ -59,22 +59,34 @@ public void Log(LogLevel logLevel, string message, Exception exception = null, b
             }
             else
             {
-                // For system logs, we log to stdio with a prefix of LanguageWorkerConsoleLog.
-                // These are picked up by the Functions Host
-                _systemLogMsg.Append(SystemLogPrefix).AppendLine("System Log: {");
-                if (!string.IsNullOrEmpty(_requestId))
-                {
-                    _systemLogMsg.AppendLine($"  Request-Id: {_requestId}");
-                }
-                if (!string.IsNullOrEmpty(_invocationId))
-                {
-                    _systemLogMsg.AppendLine($"  Invocation-Id: {_invocationId}");
-                }
-                _systemLogMsg.AppendLine($"  Log-Message: {message}").AppendLine("}");
+                WriteSystemLog(message, _systemLogMsg, _requestId, _invocationId);
+            }
+        }
 
-                Console.WriteLine(_systemLogMsg.ToString());
-                _systemLogMsg.Clear();
+        private static void WriteSystemLog(string message, StringBuilder stringBuilder, string requestId, string invocationId)
+        {
+            stringBuilder = stringBuilder ?? new StringBuilder();
+
+            // For system logs, we log to stdio with a prefix of LanguageWorkerConsoleLog.
+            // These are picked up by the Functions Host
+            stringBuilder.Append(SystemLogPrefix).AppendLine("System Log: {");
+            if (!string.IsNullOrEmpty(requestId))
+            {
+                stringBuilder.AppendLine($"  Request-Id: {requestId}");
             }
+            if (!string.IsNullOrEmpty(invocationId))
+            {
+                stringBuilder.AppendLine($"  Invocation-Id: {invocationId}");
+            }
+            stringBuilder.AppendLine($"  Log-Message: {message}").AppendLine("}");
+
+            Console.WriteLine(stringBuilder.ToString());
+            stringBuilder.Clear();
+        }
+
+        internal static void WriteSystemLog(string message)
+        {
+            WriteSystemLog(message, stringBuilder: null, requestId: null, invocationId: null);
         }
     }
 }

src/PowerShell/PowerShellManager.cs

@@ -92,7 +92,7 @@ internal void InvokeProfile(string profilePath)
             Exception exception = null;
             if (profilePath == null)
             {
-                _logger.Log(LogLevel.Trace, string.Format(PowerShellWorkerStrings.FileNotFound, "profile.ps1", FunctionLoader.FunctionAppRootPath));
+                RpcLogger.WriteSystemLog(string.Format(PowerShellWorkerStrings.FileNotFound, "profile.ps1", FunctionLoader.FunctionAppRootPath));
                 return;
             }
 

src/PowerShell/PowerShellManagerPool.cs

@@ -31,6 +31,8 @@ internal class PowerShellManagerPool
         internal PowerShellManagerPool(MessagingStream msgStream)
         {
             string upperBound = Environment.GetEnvironmentVariable("PSWorkerInProcConcurrencyUpperBound");
+            RpcLogger.WriteSystemLog(string.Format(PowerShellWorkerStrings.LogConcurrencyUpperBound, upperBound));
+
             if (string.IsNullOrEmpty(upperBound) || !int.TryParse(upperBound, out _upperBound))
             {
                 _upperBound = 1;
@@ -81,6 +83,8 @@ internal PowerShellManager CheckoutIdleWorker(StreamingMessage request, AzFuncti
                     var logger = new RpcLogger(_msgStream);
                     logger.SetContext(requestId, invocationId);
                     psManager = new PowerShellManager(logger);
+
+                    RpcLogger.WriteSystemLog(string.Format(PowerShellWorkerStrings.LogNewPowerShellManagerCreated, _poolSize));
                 }
                 else
                 {

src/RequestProcessor.cs

@@ -21,7 +21,6 @@ namespace  Microsoft.Azure.Functions.PowerShellWorker
     internal class RequestProcessor
     {
         private readonly FunctionLoader _functionLoader;
-        private readonly RpcLogger _logger;
         private readonly MessagingStream _msgStream;
         private readonly PowerShellManagerPool _powershellPool;
         private readonly DependencyManager _dependencyManager;
@@ -39,7 +38,6 @@ internal class RequestProcessor
         internal RequestProcessor(MessagingStream msgStream)
         {
             _msgStream = msgStream;
-            _logger = new RpcLogger(_msgStream);
             _powershellPool = new PowerShellManagerPool(msgStream);
             _functionLoader = new FunctionLoader();
             _dependencyManager = new DependencyManager();
@@ -83,7 +81,7 @@ internal async Task ProcessRequestLoop()
                 }
                 else
                 {
-                    _logger.Log(LogLevel.Error, string.Format(PowerShellWorkerStrings.UnsupportedMessage, request.ContentCase));
+                    RpcLogger.WriteSystemLog(string.Format(PowerShellWorkerStrings.UnsupportedMessage, request.ContentCase));
                     continue;
                 }
 
@@ -107,7 +105,7 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request)
             string pipeName = Environment.GetEnvironmentVariable("PSWorkerCustomPipeName");
             if (!string.IsNullOrEmpty(pipeName))
             {
-                _logger.Log(LogLevel.Information, string.Format(PowerShellWorkerStrings.SpecifiedCustomPipeName, pipeName));
+                RpcLogger.WriteSystemLog(string.Format(PowerShellWorkerStrings.SpecifiedCustomPipeName, pipeName));
                 RemoteSessionNamedPipeServer.CreateCustomNamedPipeServer(pipeName);
             }
 

src/resources/PowerShellWorkerStrings.resx

@@ -205,4 +205,10 @@
   <data name="FailToClenupModuleDestinationPath" xml:space="preserve">
     <value>Failed to clean up module destination path '{0}'</value>
   </data>
+  <data name="LogConcurrencyUpperBound" xml:space="preserve">
+    <value>The enforced concurrency level (pool size limit) is '{0}'.</value>
+  </data>
+  <data name="LogNewPowerShellManagerCreated" xml:space="preserve">
+    <value>A new PowerShell manager instance is added to the pool. Current pool size '{0}'.</value>
+  </data>
 </root>

test/Unit/PowerShell/PowerShellManagerTests.cs

@@ -177,17 +177,6 @@ public void ProfileShouldWork()
             Assert.Equal("Information: INFORMATION: Hello PROFILE", _testLogger.FullLog[0]);
         }
 
-        [Fact]
-        public void ProfileDoesNotExist()
-        {
-            //initialize fresh log
-            _testLogger.FullLog.Clear();
-            _testManager.InvokeProfile(null);
-
-            Assert.Single(_testLogger.FullLog);
-            Assert.Matches("Trace: No 'profile.ps1' is found at the FunctionApp root folder: ", _testLogger.FullLog[0]);
-        }
-
         [Fact]
         public void ProfileWithTerminatingError()
         {