From 52e899dea436c0782888dce324fff5c14c4cebca Mon Sep 17 00:00:00 2001 From: Francisco-Gamino Date: Wed, 26 Oct 2022 12:12:03 -0700 Subject: [PATCH 1/5] Initialize the first PowerShell instance in worker init --- src/RequestProcessor.cs | 35 +++++++++++++++++----- src/resources/PowerShellWorkerStrings.resx | 3 ++ 2 files changed, 30 insertions(+), 8 deletions(-) diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index c9c10d2f..84d67892 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -95,6 +95,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 +120,26 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request) RemoteSessionNamedPipeServer.CreateCustomNamedPipeServer(pipeName); } + try + { + // Initialize the first PowerShell instance, so that we can populate the worker metadata. + // Previously, this initialization was taking place in the first FunctionLoadRequest. + var rpcLogger = new RpcLogger(_msgStream); + rpcLogger.SetContext(request.RequestId, null); + + _dependencyManager = new DependencyManager(request.WorkerInitRequest.FunctionAppDirectory, logger: rpcLogger); + + _powershellPool.Initialize(_firstPwshInstance); + + 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 +203,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. + // This is the second part of the worker initialization where the PSModulePath is set for the first PowerShell instance. + // The first FunctionLoadRequest 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 @@ -194,13 +216,10 @@ internal StreamingMessage ProcessFunctionLoadRequest(StreamingMessage request) var rpcLogger = new RpcLogger(_msgStream); rpcLogger.SetContext(request.RequestId, null); - _dependencyManager = new DependencyManager(request.FunctionLoadRequest.Metadata.Directory, logger: rpcLogger); var managedDependenciesPath = _dependencyManager.Initialize(request, rpcLogger); SetupAppRootPathAndModulePath(functionLoadRequest, managedDependenciesPath); - _powershellPool.Initialize(_firstPwshInstance); - // Start the download asynchronously if needed. _dependencyManager.StartDependencyInstallationIfNeeded(request, _firstPwshInstance, rpcLogger); diff --git a/src/resources/PowerShellWorkerStrings.resx b/src/resources/PowerShellWorkerStrings.resx index 2d0228d7..07d6e78d 100644 --- a/src/resources/PowerShellWorkerStrings.resx +++ b/src/resources/PowerShellWorkerStrings.resx @@ -352,4 +352,7 @@ Dependency snapshot '{0}' does not contain acceptable module versions. + + Worker init request completed in {0} ms. + \ No newline at end of file From 281218ff40002ed4aa8748fcd260c474a0469491 Mon Sep 17 00:00:00 2001 From: Francisco-Gamino Date: Wed, 26 Oct 2022 12:16:40 -0700 Subject: [PATCH 2/5] Populate language worker metadata --- src/RequestProcessor.cs | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index 84d67892..6ffc7b9f 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -20,6 +20,7 @@ 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 { @@ -131,6 +132,8 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request) _powershellPool.Initialize(_firstPwshInstance); + response.WorkerInitResponse.WorkerMetadata = GetWorkerMetadata(_firstPwshInstance); + rpcLogger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.WorkerInitCompleted, stopwatch.ElapsedMilliseconds)); } catch (Exception e) @@ -538,6 +541,17 @@ private void SetupAppRootPathAndModulePath(FunctionLoadRequest functionLoadReque .InvokeAndClearCommands(); } + private WorkerMetadata GetWorkerMetadata(System.Management.Automation.PowerShell pwsh) + { + var data = new WorkerMetadata(); + data.WorkerBitness = RuntimeInformation.OSArchitecture.ToString(); + data.WorkerVersion = typeof(Worker).Assembly.GetName().Version.ToString(); + data.RuntimeVersion = Utils.GetPowerShellVersion(pwsh); + data.RuntimeName = "powershell"; + + return data; + } + #endregion } } From 5535d8134d6f3dab8b0d2559c6afc8e4e5d1690e Mon Sep 17 00:00:00 2001 From: Francisco-Gamino Date: Tue, 1 Nov 2022 19:26:53 -0700 Subject: [PATCH 3/5] Continue to defer the worker initialization until the first FunctionLoadRequest --- src/RequestProcessor.cs | 13 +++++-------- 1 file changed, 5 insertions(+), 8 deletions(-) diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index 6ffc7b9f..cf5ec219 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -123,15 +123,9 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request) try { - // Initialize the first PowerShell instance, so that we can populate the worker metadata. - // Previously, this initialization was taking place in the first FunctionLoadRequest. var rpcLogger = new RpcLogger(_msgStream); rpcLogger.SetContext(request.RequestId, null); - _dependencyManager = new DependencyManager(request.WorkerInitRequest.FunctionAppDirectory, logger: rpcLogger); - - _powershellPool.Initialize(_firstPwshInstance); - response.WorkerInitResponse.WorkerMetadata = GetWorkerMetadata(_firstPwshInstance); rpcLogger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.WorkerInitCompleted, stopwatch.ElapsedMilliseconds)); @@ -206,8 +200,8 @@ internal StreamingMessage ProcessFunctionLoadRequest(StreamingMessage request) return response; } - // This is the second part of the worker initialization where the PSModulePath is set for the first PowerShell instance. - // The first FunctionLoadRequest contains the information about whether Managed Dependencies is enabled for the function app, + // 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) @@ -219,10 +213,13 @@ internal StreamingMessage ProcessFunctionLoadRequest(StreamingMessage request) var rpcLogger = new RpcLogger(_msgStream); rpcLogger.SetContext(request.RequestId, null); + _dependencyManager = new DependencyManager(request.FunctionLoadRequest.Metadata.Directory, logger: rpcLogger); var managedDependenciesPath = _dependencyManager.Initialize(request, rpcLogger); SetupAppRootPathAndModulePath(functionLoadRequest, managedDependenciesPath); + _powershellPool.Initialize(_firstPwshInstance); + // Start the download asynchronously if needed. _dependencyManager.StartDependencyInstallationIfNeeded(request, _firstPwshInstance, rpcLogger); From 8a265a470ca28182818edcc4d3c99b63b8e2c974 Mon Sep 17 00:00:00 2001 From: Francisco-Gamino Date: Thu, 3 Nov 2022 10:00:46 -0700 Subject: [PATCH 4/5] Address PR comments --- src/RequestProcessor.cs | 10 ++++++---- src/Worker.cs | 14 ++++++++++---- 2 files changed, 16 insertions(+), 8 deletions(-) diff --git a/src/RequestProcessor.cs b/src/RequestProcessor.cs index cf5ec219..b2f177a0 100644 --- a/src/RequestProcessor.cs +++ b/src/RequestProcessor.cs @@ -28,6 +28,7 @@ internal class RequestProcessor 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; @@ -38,11 +39,12 @@ internal class RequestProcessor private Dictionary> _requestHandlers = new Dictionary>(); - 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); @@ -126,7 +128,7 @@ internal StreamingMessage ProcessWorkerInitRequest(StreamingMessage request) var rpcLogger = new RpcLogger(_msgStream); rpcLogger.SetContext(request.RequestId, null); - response.WorkerInitResponse.WorkerMetadata = GetWorkerMetadata(_firstPwshInstance); + response.WorkerInitResponse.WorkerMetadata = GetWorkerMetadata(_pwshVersion); rpcLogger.Log(isUserOnlyLog: false, LogLevel.Trace, string.Format(PowerShellWorkerStrings.WorkerInitCompleted, stopwatch.ElapsedMilliseconds)); } @@ -538,12 +540,12 @@ private void SetupAppRootPathAndModulePath(FunctionLoadRequest functionLoadReque .InvokeAndClearCommands(); } - private WorkerMetadata GetWorkerMetadata(System.Management.Automation.PowerShell pwsh) + private WorkerMetadata GetWorkerMetadata(string pwshVersion) { var data = new WorkerMetadata(); data.WorkerBitness = RuntimeInformation.OSArchitecture.ToString(); data.WorkerVersion = typeof(Worker).Assembly.GetName().Version.ToString(); - data.RuntimeVersion = Utils.GetPowerShellVersion(pwsh); + data.RuntimeVersion = pwshVersion; data.RuntimeName = "powershell"; return data; diff --git a/src/Worker.cs b/src/Worker.cs index 8987086c..2f0f8044 100644 --- a/src/Worker.cs +++ b/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 = 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,11 +76,16 @@ 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); } + + private static string GetPowerShellVersion(System.Management.Automation.PowerShell pwsh) + { + return Utils.GetPowerShellVersion(pwsh); + } } internal class WorkerArguments From ccc58aab7dcf0d4422bc03a709de3ad6f17117be Mon Sep 17 00:00:00 2001 From: Francisco-Gamino Date: Fri, 4 Nov 2022 12:30:50 -0700 Subject: [PATCH 5/5] Address more PR comments --- src/Worker.cs | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/src/Worker.cs b/src/Worker.cs index 2f0f8044..d580e79a 100644 --- a/src/Worker.cs +++ b/src/Worker.cs @@ -40,7 +40,7 @@ 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(); - var pwshVersion = GetPowerShellVersion(firstPowerShellInstance); + var pwshVersion = Utils.GetPowerShellVersion(firstPowerShellInstance); LogPowerShellVersion(pwshVersion); WarmUpPowerShell(firstPowerShellInstance); @@ -81,11 +81,6 @@ private static void LogPowerShellVersion(string pwshVersion) var message = string.Format(PowerShellWorkerStrings.PowerShellVersion, pwshVersion); RpcLogger.WriteSystemLog(LogLevel.Information, message); } - - private static string GetPowerShellVersion(System.Management.Automation.PowerShell pwsh) - { - return Utils.GetPowerShellVersion(pwsh); - } } internal class WorkerArguments