logging improvements in GrpcWorkerChannel (Azure#9570)

src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.Log.cs

@@ -0,0 +1,37 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the MIT License. See License.txt in the project root for license information.
+
+using System;
+using Microsoft.Extensions.Logging;
+using static Microsoft.Azure.WebJobs.Script.Grpc.Messages.StreamingMessage;
+
+namespace Microsoft.Azure.WebJobs.Script.Grpc
+{
+    internal partial class GrpcWorkerChannel
+    {
+        // EventId range is 800-899
+        private static class Logger
+        {
+            private static readonly Action<ILogger, string, ContentOneofCase, Exception> _channelReceivedMessage = LoggerMessage.Define<string, ContentOneofCase>(
+                LogLevel.Debug,
+                new EventId(820, nameof(ChannelReceivedMessage)),
+                "[channel] received {workerId}: {msgType}");
+
+            private static readonly Action<ILogger, string, Exception> _invocationResponseReceived = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                new EventId(821, nameof(InvocationResponseReceived)),
+                "InvocationResponse received for invocation: '{invocationId}'");
+
+            private static readonly Action<ILogger, string, Exception> _ignoringRpcLog = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                new EventId(822, nameof(IgnoringRpcLog)),
+                "Ignoring RpcLog from invocation '{invocationId}' because there is no matching ScriptInvocationContext.");
+
+            internal static void ChannelReceivedMessage(ILogger logger, string workerId, ContentOneofCase msgType) => _channelReceivedMessage(logger, workerId, msgType, null);
+
+            internal static void InvocationResponseReceived(ILogger logger, string invocationId) => _invocationResponseReceived(logger, invocationId, null);
+
+            internal static void IgnoringRpcLog(ILogger logger, string invocationId) => _ignoringRpcLog(logger, invocationId, null);
+        }
+    }
+}

src/WebJobs.Script.Grpc/Channel/GrpcWorkerChannel.cs

@@ -40,7 +40,7 @@
 
 namespace Microsoft.Azure.WebJobs.Script.Grpc
 {
-    internal class GrpcWorkerChannel : IRpcWorkerChannel, IDisposable
+    internal partial class GrpcWorkerChannel : IRpcWorkerChannel, IDisposable
     {
         private readonly IScriptEventManager _eventManager;
         private readonly RpcWorkerConfig _workerConfig;
@@ -247,9 +247,9 @@ private async Task ProcessInbound()
                 {
                     while (_inbound.TryRead(out var msg))
                     {
-                        if (debug)
+                        if (debug && msg.MessageType != MsgType.RpcLog)
                         {
-                            _workerChannelLogger.LogDebug("[channel] received {0}: {1}", msg.WorkerId, msg.MessageType);
+                            Logger.ChannelReceivedMessage(_workerChannelLogger, msg.WorkerId, msg.MessageType);
                         }
                         ThreadPool.QueueUserWorkItem(_processInbound, msg);
                     }
@@ -960,7 +960,7 @@ private IList<string> GetOutputMaps(IList<ParameterBinding> bindings)
 
         internal async Task InvokeResponse(InvocationResponse invokeResponse)
         {
-            _workerChannelLogger.LogDebug("InvocationResponse received for invocation: '{invocationId}'", invokeResponse.InvocationId);
+            Logger.InvocationResponseReceived(_workerChannelLogger, invokeResponse.InvocationId);
 
             // Check if the worker supports logging user-code-thrown exceptions to app insights
             bool capabilityEnabled = !string.IsNullOrEmpty(_workerCapabilities.GetCapabilityState(RpcWorkerConstants.EnableUserCodeException));
@@ -986,25 +986,24 @@ internal async Task InvokeResponse(InvocationResponse invokeResponse)
                             }
                         }
 
-                        StringBuilder logBuilder = new StringBuilder();
-                        bool usedSharedMemory = false;
+                        StringBuilder sharedMemoryLogBuilder = null;
 
                         foreach (ParameterBinding binding in invokeResponse.OutputData)
                         {
                             switch (binding.RpcDataCase)
                             {
                                 case ParameterBindingType.RpcSharedMemory:
-                                    logBuilder.AppendFormat("{0}:{1},", binding.Name, binding.RpcSharedMemory.Count);
-                                    usedSharedMemory = true;
+                                    sharedMemoryLogBuilder ??= new StringBuilder();
+                                    sharedMemoryLogBuilder.AppendFormat("{0}:{1},", binding.Name, binding.RpcSharedMemory.Count);
                                     break;
                                 default:
                                     break;
                             }
                         }
 
-                        if (usedSharedMemory)
+                        if (sharedMemoryLogBuilder != null)
                         {
-                            _workerChannelLogger.LogDebug("Shared memory usage for response of invocation '{invocationId}' is {SharedMemoryUsage}", invokeResponse.InvocationId, logBuilder.ToString());
+                            _workerChannelLogger.LogDebug("Shared memory usage for response of invocation '{invocationId}' is {SharedMemoryUsage}", invokeResponse.InvocationId, sharedMemoryLogBuilder);
                         }
 
                         IDictionary<string, object> bindingsDictionary = await invokeResponse.OutputData
@@ -1117,6 +1116,10 @@ internal void Log(GrpcEvent msg)
                     }
                 }, (context, rpcLog, _isWorkerApplicationInsightsLoggingEnabled));
             }
+            else
+            {
+                Logger.IgnoringRpcLog(_workerChannelLogger, rpcLog.InvocationId);
+            }
         }
 
         internal void SystemLog(GrpcEvent msg)