Azure / azure-functions-powershell-worker

PowerShell language worker for Azure Functions.
MIT License
205 stars 53 forks source link

$env:PSModulePath set incorrectly for second instance when PSWorkerInProcConcurrencyUpperBound > 1 #645

Open kwill-MSFT opened 3 years ago

kwill-MSFT commented 3 years ago

Repro steps

  1. Create new Functions project
  2. Add 2 TimerTrigger functions, both with "schedule": "*/1 * * * * *"
  3. Add Start-Sleep -Seconds 5 into the code for both timer functions. This ensures they both try to execute simultaneously.
  4. In local.settings.json, set "PSWorkerInProcConcurrencyUpperBound": "2"
  5. Include the Az modules in requirements.psd1
  6. Add code to profile.ps1 which imports an Az module. The following is what I used to narrow down the problem:
    Write-Information "Running profile.ps1"
    Write-Information "PSModulePath = $($env:PSModulePath)"
    Get-Module Az.Resources -ListAvailable | fl Name, Path
    Import-Module Az.Resources
    Get-AzLocation | Out-Null
    Write-Information "Done in profile.ps1"

Result:

For detailed output, run func with --verbose flag.
[2021-06-16T01:24:00.034Z] Executing 'Functions.TimerTrigger2' (Reason='Timer fired at 2021-06-15T20:24:00.0138898-05:00', Id=fc897759-bc62-4fb5-974c-cf0a5e882d20)
[2021-06-16T01:24:00.034Z] Executing 'Functions.TimerTrigger1' (Reason='Timer fired at 2021-06-15T20:24:00.0138896-05:00', Id=927dca38-8e2a-4bc4-9ed7-255174224d05)
[2021-06-16T01:24:00.698Z] Worker process started and initialized.
[2021-06-16T01:24:01.234Z] INFORMATION: Running profile.ps1
[2021-06-16T01:24:01.239Z] INFORMATION: PSModulePath = C:\Users\xxx\AppData\Local\AzureFunctions\FunctionsPSWorkerInProcConcurrencyUpperBoundIssue\ManagedDependencies\210616004428282.r;C:\Temp\Projects\FunctionsPSWorkerInProcConcurrencyUpperBoundIssue\Modules;C:\Users\xxx\AppData\Roaming\npm\node_modules\azure-functions-core-tools\bin\workers\powershell\7\Modules
[2021-06-16T01:24:01.360Z] OUTPUT: 
[2021-06-16T01:24:01.385Z] OUTPUT: Name : Az.Resources
[2021-06-16T01:24:01.388Z] OUTPUT: Path : C:\Users\xxx\AppData\Local\AzureFunctions\FunctionsPSWorkerInProcConcurrencyUpperBoundIssue\ManagedDependencies\210616004428282.r\Az.Resources\4.2.0\Az.Resources.psd1
[2021-06-16T01:24:01.389Z] OUTPUT: 
[2021-06-16T01:24:01.391Z] OUTPUT: 
[2021-06-16T01:24:04.746Z] Host lock lease acquired by instance ID '0000000000000000000000004BCB02C4'.
[2021-06-16T01:24:08.376Z] INFORMATION: Done in profile.ps1
[2021-06-16T01:24:08.473Z] INFORMATION: Running profile.ps1
[2021-06-16T01:24:08.477Z] INFORMATION: PSModulePath = C:\Users\xxx\Documents\PowerShell\Modules;C:\Program Files\PowerShell\Modules;c:\users\xxx\appdata\roaming\npm\node_modules\azure-functions-core-tools\bin\workers\powershell\7\runtimes\win\lib\netcoreapp3.1\Modules;C:\Users\xxx\AppData\Local\AzureFunctions\FunctionsPSWorkerInProcConcurrencyUpperBoundIssue\ManagedDependencies\210616004428282.r;C:\Temp\Projects\FunctionsPSWorkerInProcConcurrencyUpperBoundIssue\Modules;C:\Users\xxx\AppData\Roaming\npm\node_modules\azure-functions-core-tools\bin\workers\powershell\7\Modules
[2021-06-16T01:24:08.534Z] OUTPUT: 
[2021-06-16T01:24:08.537Z] OUTPUT: Name : Az.Resources
[2021-06-16T01:24:08.539Z] OUTPUT: Path : C:\Users\xxx\Documents\PowerShell\Modules\Az.Resources\3.4.1\Az.Resources.psd1
[2021-06-16T01:24:08.541Z] OUTPUT: 
[2021-06-16T01:24:08.542Z] OUTPUT: Name : Az.Resources
[2021-06-16T01:24:08.543Z] OUTPUT: Path : C:\Users\xxx\AppData\Local\AzureFunctions\FunctionsPSWorkerInProcConcurrencyUpperBoundIssue\ManagedDependencies\210616004428282.r\Az.Resources\4.2.0\Az.Resources.psd1
[2021-06-16T01:24:08.545Z] OUTPUT: 
[2021-06-16T01:24:08.547Z] OUTPUT: 
[2021-06-16T01:24:08.872Z] ERROR: Assembly with same name is already loaded
[2021-06-16T01:24:08.874Z] 
[2021-06-16T01:24:08.875Z] Exception             : 
[2021-06-16T01:24:08.877Z]     Type       : System.IO.FileLoadException
[2021-06-16T01:24:08.879Z]     Message    : Assembly with same name is already loaded

The first time profile.ps1 executes, PSModulePath is correct and only shows a single Az.Resources module available.

The second time profile.ps1 executes, PSModulePath includes 'C:\Users\xxx\Documents\PowerShell\Modules' and results in 2 available Az.Resources modules available. This then results in the FileLoadException.

This can be worked around by manually setting the $env:PSModulePath in profile.ps1 prior to the Import-Module line.

AnatoliB commented 3 years ago

Thank you @kwill-MSFT.

A few more details:

Workarounds: