Powershell provisioner and #requires directive

Occams commented 4 years ago

Overview of the Issue

Provisioning with powershell provisioner succeeds despite the script being invoked violating a #Requires -Version directive.

https://docs.microsoft.com/en-us/powershell/module/microsoft.powershell.core/about/about_requires?view=powershell-7

Reproduction Steps

Configure a powershell provisioner invoking a script with a #Requires -Version x directive that fails on the to be provisoned target system. Pick a large version number for it to definitely fail on any system. This probably can be reproduced with any requires directive that gets violated during script invocation.

Packer log snippet

2020/05/02 08:13:32 ui: 2020-05-02T08:13:32+02:00: ==> vbox-base-win2012-r2: Provisioning with Powershell... 2020/05/02 08:13:32 ui: 2020-05-02T08:13:32+02:00: ==> vbox-base-win2012-r2: Provisioning with powershell script: scripts/init_provisioning/post-bootstrap.ps1 2020/05/02 08:13:32 packer.exe plugin: Opening scripts/init_provisioning/post-bootstrap.ps1 for reading 2020/05/02 08:13:32 packer.exe plugin: Uploading env vars to c:/Windows/Temp/packer-ps-env-vars-5ead0cbd-97e7-8f63-237a-c34ba075b0e4.ps1 2020/05/02 08:13:32 packer.exe plugin: [INFO] 122 bytes written for 'uploadData' 2020/05/02 08:13:32 packer.exe plugin: Uploading file to 'c:/Windows/Temp/packer-ps-env-vars-5ead0cbd-97e7-8f63-237a-c34ba075b0e4.ps1' 2020/05/02 08:13:32 [INFO] 122 bytes written for 'uploadData' 2020/05/02 08:13:32 packer.exe plugin: Copying file to $env:TEMP\winrmcp-b300f02f-f55c-4e43-6b82-9cb96bb7b655.tmp 2020/05/02 08:13:32 packer.exe plugin: Moving file from $env:TEMP\winrmcp-b300f02f-f55c-4e43-6b82-9cb96bb7b655.tmp to c:\Windows\Temp\packer-ps-env-vars-5ead0cbd-97e7-8f63-237a-c34ba075b0e4.ps1 2020/05/02 08:13:41 packer.exe plugin: Removing temporary file $env:TEMP\winrmcp-b300f02f-f55c-4e43-6b82-9cb96bb7b655.tmp 2020/05/02 08:13:49 packer.exe plugin: [INFO] 1935 bytes written for 'uploadData' 2020/05/02 08:13:49 [INFO] 1935 bytes written for 'uploadData' 2020/05/02 08:13:49 packer.exe plugin: Uploading file to 'C:/Windows/Temp/scripts/post-bootstrap.ps1' 2020/05/02 08:13:49 packer.exe plugin: Copying file to $env:TEMP\winrmcp-9c45e645-e134-4e9d-69d5-0747674cdd84.tmp 2020/05/02 08:13:49 packer.exe plugin: Moving file from $env:TEMP\winrmcp-9c45e645-e134-4e9d-69d5-0747674cdd84.tmp to C:\Windows\Temp\scripts\post-bootstrap.ps1 2020/05/02 08:13:57 packer.exe plugin: Removing temporary file $env:TEMP\winrmcp-9c45e645-e134-4e9d-69d5-0747674cdd84.tmp 2020/05/02 08:14:05 packer.exe plugin: [INFO] starting remote command: powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5ead0cbd-97e7-8f63-237a-c34ba075b0e4.ps1; &'C:/Windows/Temp/scripts/post-bootstrap.ps1'; exit $LastExitCode }" 2020/05/02 08:14:15 packer.exe plugin: [INFO] command 'powershell -executionpolicy bypass "& { if (Test-Path variable:global:ProgressPreference){set-variable -name variable:global:ProgressPreference -value 'SilentlyContinue'};. c:/Windows/Temp/packer-ps-env-vars-5ead0cbd-97e7-8f63-237a-c34ba075b0e4.ps1; &'C:/Windows/Temp/scripts/post-bootstrap.ps1'; exit $LastExitCode }"' exited with code: 0 2020/05/02 08:14:15 packer.exe plugin: [INFO] RPC endpoint: Communicator ended with: 0 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: & : Das Skript "post-bootstrap.ps1" kann nicht ausgeführt werden, da es eine 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: #requires-Anweisung für Windows PowerShell 5.0 enthält. Die für das Skript 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: erforderliche Version von Windows PowerShell stimmt mit der derzeit 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: ausgeführten Windows PowerShell-Version 4.0 nicht überein. 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: In Zeile:1 Zeichen:216 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: + ... a075b0e4.ps1; &'C:/Windows/Temp/scripts/post-bootstrap.ps1'; exit 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: $LastExitCode ... 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: + ~~~~~~~~~~~~ 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: + CategoryInfo : ResourceUnavailable: (post-bootstrap.ps1:String) 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: [], ScriptRequiresException 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: + FullyQualifiedErrorId : ScriptRequiresUnmatchedPSVersion 2020/05/02 08:14:15 ui error: 2020-05-02T08:14:15+02:00: ==> vbox-base-win2012-r2: 2020/05/02 08:14:15 [INFO] 658 bytes written for 'stderr' 2020/05/02 08:14:15 [INFO] 0 bytes written for 'stdout' 2020/05/02 08:14:15 [INFO] RPC client: Communicator ended with: 0 2020/05/02 08:14:15 [INFO] RPC endpoint: Communicator ended with: 0 2020/05/02 08:14:15 packer.exe plugin: [INFO] 658 bytes written for 'stderr' 2020/05/02 08:14:15 packer.exe plugin: [INFO] 0 bytes written for 'stdout' 2020/05/02 08:14:15 packer.exe plugin: [INFO] RPC client: Communicator ended with: 0 2020/05/02 08:14:15 packer.exe plugin: C:/Windows/Temp/scripts/post-bootstrap.ps1 returned with exit code 0

Packer version

1.5.5

Operating system and Environment details

Packer Host: Windows Server 2019 (1809 LTS) Virtualbox guest: Windows Server 2012 R2 (PowerShell v4)

Log Fragments and crash.log files

https://gist.github.com/Occams/099bb951b6a4074a3a4dbd5bea920cf0

nywilken commented 4 years ago

Hi @Occams thanks for reaching out. This looks like it is related to https://github.com/hashicorp/packer/issues/4916. The PR #9040, which is in-progress, may solve this issue if you would like to give it a try. There are test binaries available at https://app.circleci.com/pipelines/github/hashicorp/packer/4704/workflows/ceffa0b5-b673-4f1b-b350-95bdef932600/jobs/46979/artifacts

Occams commented 4 years ago

@nywilken Code compiled to the aforementioned test binaries seems to handle the original issue. Scripts violating a #Requires directive correctly fail provisioning.

However, provisioning scripts that do not invoke any native commands, thus not implicitly setting $LastExitCode, are now failing due to it never being initialized.

2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: Die Variable "$LastExitCode" kann nicht abgerufen werden, weil sie nicht 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: festgelegt wurde. 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: In Zeile:1 Zeichen:392 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: + ... exit 1 }; exit $LastExitCode } 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: + ~~~~~ 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: + CategoryInfo : InvalidOperation: (LastExitCode:String) [], Pare 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: ntContainsErrorRecordException 2020-05-11T10:47:32+02:00: ==> vbox-base-win2012-r2: + FullyQualifiedErrorId : VariableIsUndefined

The failing scripts explicitly include

Set-StrictMode -Version Latest

and

$ErrorActionPreference = "Stop"

There seems to be some leakage of this state to the parent scope of the provisioning wrapper.

nywilken commented 4 years ago

Hi @Occams thanks for testing and reporting back. This is helpful information. I will use this in testing so that I can update the PR to handle such cases. Thanks again!

nywilken commented 4 years ago

This fix for this issue has been reverted, as there were issues with the updated provisioner when executing over Windows SSH. I am reopening for further investigation.

github-actions[bot] commented 2 years ago

This issue has been synced to JIRA for planning.

JIRA ID: HPR-765

burck1 commented 2 years ago

Ran into this today, but rather than #Requires -Version 5.1, our script has #Requires -Modules FooBar (for example). I suspect that all failing #Requires statements would have the the same problem.

==> amazon-ebs: Provisioning with powershell script: /scripts/TestRequires.ps1
==> amazon-ebs: & : The script 'script-63587702-a325-5c53-e815-5b4fbc0b84d0.ps1' cannot be run because the following modules that are
==> amazon-ebs: specified by the "#requires" statements of the script are missing: FooBar.
==> amazon-ebs: At line:1 char:216
==> amazon-ebs: + ... e2bf9.ps1; &'c:/Windows/Temp/script-63587702-a325-5c53-e815-5b4fbc0b8 ...
==> amazon-ebs: +                 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
==> amazon-ebs:     + CategoryInfo          : ResourceUnavailable: (script-63587702...b4fbc0b84d0.ps1:String) [], ScriptRequiresExcept
==> amazon-ebs:    ion
==> amazon-ebs:     + FullyQualifiedErrorId : ScriptRequiresMissingModules
==> amazon-ebs:

Unfortunately, since this caused a silent failure where the logs show an error message but packer continued to execute the scripts, our CI/CD process missed the failure and released a production AMI that caused a service outage :(

Something interesting that we observed; although the powershell provisioner does not seem to recognize the error and thus continues executing the scripts, we do see the error logs colorized red in the output. This means that clearly some part of packer is recognizing that there is an error and thus printing it as red. Does this just mean that something was printed to stderr / the PowerShell Error Stream?. Is there some way to tell the powershell provisioner that it should fail the packer build if there are any logs written to stderr?

burck1 commented 2 years ago

After some testing we came up with this workaround; you must remove your #Requires statements from your scripts and instead check the equivalent requirements with standard PowerShell code.

Instead of `#Requires -Version 8.1` (for example)

$ErrorActionPreference = "Stop"
$minimumRequiredPSVersion = [System.Version]"8.1"
if ($PSVersionTable.PSVersion -lt $minimumRequiredPSVersion) {
    throw "The script cannot be run because it requires PowerShell $($minimumRequiredPSVersion). The current running version of PowerShell is $($PSVersionTable.PSVersion)."
}

Note: Calling throw will raise an exception, terminate the script, and packer will recognize that there was an error and stop execution.

Instead of `#Requires -Modules FooBar, FizzBuzz` (for example)

$ErrorActionPreference = "Stop"
Import-Module -Name "FooBar"
Import-Module -Name "FizzBuzz"

Note: If Import-Module does not find a module with the given name, it will raise an exception, terminate the script, and packer will recognize that there was an error and stop execution.

hashicorp / packer