Populate language worker metadata in init response (#884)

* Populate language worker metadata

* Continue to defer the worker initialization until the first FunctionLoadRequest

Author: Francisco-Gamino

src/RequestProcessor.cs

@@ -20,13 +20,15 @@ namespace Microsoft.Azure.Functions.PowerShellWorker
 {
     using System.Diagnostics;
     using LogLevel = Microsoft.Azure.WebJobs.Script.Grpc.Messages.RpcLog.Types.Level;
+    using System.Runtime.InteropServices;
 
     internal class RequestProcessor
     {
         private readonly MessagingStream _msgStream;
         private readonly System.Management.Automation.PowerShell _firstPwshInstance;
         private readonly PowerShellManagerPool _powershellPool;
         private DependencyManager _dependencyManager;
+        private string _pwshVersion;
 
         // Holds the exception if an issue is encountered while processing the function app dependencies.
         private Exception _initTerminatingError;
@@ -37,11 +39,12 @@ internal class RequestProcessor
         private Dictionary<StreamingMessage.ContentOneofCase, Func<StreamingMessage, StreamingMessage>> _requestHandlers =
             new Dictionary<StreamingMessage.ContentOneofCase, Func<StreamingMessage, StreamingMessage>>();
 
-        internal RequestProcessor(MessagingStream msgStream, System.Management.Automation.PowerShell firstPwshInstance)
+        internal RequestProcessor(MessagingStream msgStream, System.Management.Automation.PowerShell firstPwshInstance, string pwshVersion)
         {
             _msgStream = msgStream;
             _firstPwshInstance = firstPwshInstance;
             _powershellPool = new PowerShellManagerPool(() => new RpcLogger(msgStream));
+            _pwshVersion = pwshVersion;
 
             // Host sends capabilities/init data to worker
             _requestHandlers.Add(StreamingMessage.ContentOneofCase.WorkerInitRequest, ProcessWorkerInitRequest);
@@ -95,6 +98,9 @@ internal async Task ProcessRequestLoop()
 
         internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request)
         {
+            var stopwatch = new Stopwatch();
+            stopwatch.Start();
+
             var workerInitRequest = request.WorkerInitRequest;
             Environment.SetEnvironmentVariable("AZUREPS_HOST_ENVIRONMENT", $"AzureFunctions/{workerInitRequest.HostVersion}");
             Environment.SetEnvironmentVariable("POWERSHELL_DISTRIBUTION_CHANNEL", $"Azure-Functions:{workerInitRequest.HostVersion}");
@@ -117,6 +123,22 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request)
                 RemoteSessionNamedPipeServer.CreateCustomNamedPipeServer(pipeName);
             }
 
+            try
+            {
+                var rpcLogger = new RpcLogger(_msgStream);
+                rpcLogger.SetContext(request.RequestId, null);
+
+                response.WorkerInitResponse.WorkerMetadata = GetWorkerMetadata(_pwshVersion);
+
+                rpcLogger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.WorkerInitCompleted, stopwatch.ElapsedMilliseconds));
+            }
+            catch (Exception e)
+            {
+                status.Status = StatusResult.Types.Status.Failure;
+                status.Exception = e.ToRpcException();
+                return response;
+            }
+
             return response;
         }
 
@@ -180,11 +202,10 @@ internal StreamingMessage ProcessFunctionLoadRequest(StreamingMessage request)
                 return response;
             }
 
-            // Ideally, the initialization should happen when processing 'WorkerInitRequest', however, the 'WorkerInitRequest'
-            // message doesn't provide information about the FunctionApp. That information is not available until the first
-            // 'FunctionLoadRequest' comes in. Therefore, we run initialization here.
-            // Also, we receive a FunctionLoadRequest when a proxy is configured. Proxies don't have the Metadata.Directory set
-            // which would cause initialization issues with the PSModulePath. Since they don't have that set, we skip over them.
+            // Ideally, the initialization should happen when processing 'WorkerInitRequest'. However, we defer the initialization
+            // until the first 'FunctionLoadRequest' which contains the information about whether Managed Dependencies is enabled for the function app,
+            // and if it is, we add the Managed Dependencies path to the PSModulePath.
+            // Also, we receive a FunctionLoadRequest when a proxy is configured. This is just a no-op on the worker size, so we skip over them.
             if (!_isFunctionAppInitialized && !functionLoadRequest.Metadata.IsProxy)
             {
                 try
@@ -519,6 +540,17 @@ private void SetupAppRootPathAndModulePath(FunctionLoadRequest functionLoadReque
                 .InvokeAndClearCommands();
         }
 
+        private WorkerMetadata GetWorkerMetadata(string pwshVersion)
+        {
+            var data = new WorkerMetadata();
+            data.WorkerBitness = RuntimeInformation.OSArchitecture.ToString();
+            data.WorkerVersion = typeof(Worker).Assembly.GetName().Version.ToString();
+            data.RuntimeVersion = pwshVersion;
+            data.RuntimeName = "powershell";
+
+            return data;
+        }
+
         #endregion
     }
 }

src/Worker.cs

@@ -40,11 +40,12 @@ public async static Task Main(string[] args)
             // This PowerShell instance is shared by the first PowerShellManager instance created in the pool,
             // and the dependency manager (used to download dependent modules if needed).
             var firstPowerShellInstance = Utils.NewPwshInstance();
-            LogPowerShellVersion(firstPowerShellInstance);
+            var pwshVersion = Utils.GetPowerShellVersion(firstPowerShellInstance);
+            LogPowerShellVersion(pwshVersion);
             WarmUpPowerShell(firstPowerShellInstance);
 
             var msgStream = new MessagingStream(arguments.Host, arguments.Port);
-            var requestProcessor = new RequestProcessor(msgStream, firstPowerShellInstance);
+            var requestProcessor = new RequestProcessor(msgStream, firstPowerShellInstance, pwshVersion);
 
             // Send StartStream message
             var startedMessage = new StreamingMessage()
@@ -75,9 +76,9 @@ private static void WarmUpPowerShell(System.Management.Automation.PowerShell fir
                 .InvokeAndClearCommands();
         }
 
-        private static void LogPowerShellVersion(System.Management.Automation.PowerShell pwsh)
+        private static void LogPowerShellVersion(string pwshVersion)
         {
-            var message = string.Format(PowerShellWorkerStrings.PowerShellVersion, Utils.GetPowerShellVersion(pwsh));
+            var message = string.Format(PowerShellWorkerStrings.PowerShellVersion, pwshVersion);
             RpcLogger.WriteSystemLog(LogLevel.Information, message);
         }
     }

src/resources/PowerShellWorkerStrings.resx

@@ -352,4 +352,7 @@
   <data name="DependencySnapshotDoesNotContainAcceptableModuleVersions" xml:space="preserve">
     <value>Dependency snapshot '{0}' does not contain acceptable module versions.</value>
   </data>
+  <data name="WorkerInitCompleted" xml:space="preserve">
+    <value>Worker init request completed in {0} ms.</value>
+  </data>
 </root>