Packer: PowerShell provisioner silently ignores some types of errors

[sandersaares]

Packer v1.0.0 on Windows 10 Enterprise 15063.296.

Building a Windows Server 2016 Standard image on Hyper-V.

The following provisioner contains invalid PowerShell commands. I would expect the build to fail. However, these errors are silently ignored.

    {
      "type": "powershell",
      "inline": "this is not a valid powershell command"
    }

Debug log snippet:

2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 [DEBUG] connecting to remote shell using WinRM
2017/05/23 09:47:38 ui: ==> hyperv-iso: Connected to WinRM!
==> hyperv-iso: Connected to WinRM!
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Running the provision hook
==> hyperv-iso: Provisioning with Powershell...
2017/05/23 09:47:38 ui: ==> hyperv-iso: Provisioning with Powershell...
==> hyperv-iso: Provisioning with shell script: C:\Users\saares\AppData\Local\Temp\packer-powershell-provisioner887540923
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Found command: this is not a valid powershell command
2017/05/23 09:47:38 ui: ==> hyperv-iso: Provisioning with shell script: C:\Users\saares\AppData\Local\Temp\packer-powershell-provisioner887540923
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Opening C:\Users\saares\AppData\Local\Temp\packer-powershell-provisioner887540923 for reading
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Building command line for: if (Test-Path variable:global:ProgressPreference){$ProgressPreference='SilentlyContinue'};$env:PACKER_BUILDER_TYPE="hyperv-iso"; $env:PACKER_BUILD_NAME="hyperv-iso"; &'c:/Windows/Temp/script.ps1';exit $LastExitCode
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 [INFO] 39 bytes written for 'uploadData'
2017/05/23 09:47:38 [INFO] 39 bytes written for 'uploadData'
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Uploading file to 'c:/Windows/Temp/script.ps1'
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Copying file to $env:TEMP\winrmcp-848ef57a-37f2-474c-60ab-df80537f7458.tmp
2017/05/23 09:47:38 packer.exe: 2017/05/23 09:47:38 Moving file from $env:TEMP\winrmcp-848ef57a-37f2-474c-60ab-df80537f7458.tmp to c:\Windows\Temp\script.ps1
2017/05/23 09:47:41 packer.exe: #< CLIXML
2017/05/23 09:47:41 packer.exe: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj></Objs>2017/05/23 09:47:41 Removing temporary file $env:TEMP\winrmcp-848ef57a-37f2-474c-60ab-df80537f7458.tmp
2017/05/23 09:47:43 packer.exe: 2017/05/23 09:47:43 [INFO] starting remote command: powershell -executionpolicy bypass -encodedCommand aQBmACAAKABUAGUAcwB0AC0AUABhAHQAaAAgAHYAYQByAGkAYQBiAGwAZQA6AGcAbABvAGIAYQBsADoAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAKQB7ACQAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAPQAnAFMAaQBsAGUAbgB0AGwAeQBDAG8AbgB0AGkAbgB1AGUAJwB9ADsAJABlAG4AdgA6AFAAQQBDAEsARQBSAF8AQgBVAEkATABEAEUAUgBfAFQAWQBQAEUAPQAiAGgAeQBwAGUAcgB2AC0AaQBzAG8AIgA7ACAAJABlAG4AdgA6AFAAQQBDAEsARQBSAF8AQgBVAEkATABEAF8ATgBBAE0ARQA9ACIAaAB5AHAAZQByAHYALQBpAHMAbwAiADsAIAAmACcAYwA6AC8AVwBpAG4AZABvAHcAcwAvAFQAZQBtAHAALwBzAGMAcgBpAHAAdAAuAHAAcwAxACcAOwBlAHgAaQB0ACAAJABMAGEAcwB0AEUAeABpAHQAQwBvAGQAZQA=
2017/05/23 09:47:46 ui:     hyperv-iso: #< CLIXML
    hyperv-iso: #< CLIXML
2017/05/23 09:47:48 packer.exe: 2017/05/23 09:47:48 [INFO] command 'powershell -executionpolicy bypass -encodedCommand aQBmACAAKABUAGUAcwB0AC0AUABhAHQAaAAgAHYAYQByAGkAYQBiAGwAZQA6AGcAbABvAGIAYQBsADoAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAKQB7ACQAUAByAG8AZwByAGUAcwBzAFAAcgBlAGYAZQByAGUAbgBjAGUAPQAnAFMAaQBsAGUAbgB0AGwAeQBDAG8AbgB0AGkAbgB1AGUAJwB9ADsAJABlAG4AdgA6AFAAQQBDAEsARQBSAF8AQgBVAEkATABEAEUAUgBfAFQAWQBQAEUAPQAiAGgAeQBwAGUAcgB2AC0AaQBzAG8AIgA7ACAAJABlAG4AdgA6AFAAQQBDAEsARQBSAF8AQgBVAEkATABEAF8ATgBBAE0ARQA9ACIAaAB5AHAAZQByAHYALQBpAHMAbwAiADsAIAAmACcAYwA6AC8AVwBpAG4AZABvAHcAcwAvAFQAZQBtAHAALwBzAGMAcgBpAHAAdAAuAHAAcwAxACcAOwBlAHgAaQB0ACAAJABMAGEAcwB0AEUAeABpAHQAQwBvAGQAZQA=' exited with code: 0
2017/05/23 09:47:48 packer.exe: 2017/05/23 09:47:48 [INFO] RPC endpoint: Communicator ended with: 0
2017/05/23 09:47:48 [INFO] 1082 bytes written for 'stderr'
    hyperv-iso: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj><S S="Error">this : The term 'this' is not recognized as the name of a cmdlet, function, script file, or operable program. Check _x000D__x000A_</S><S S="Error">the spelling of the name, or if a path was included, verify that the path is correct and try again._x000D__x000A_</S><S S="Error">At C:\Windows\Temp\script.ps1:1 char:1_x000D__x000A_</S><S S="Error">+ this is not a valid powershell command_x000D__x000A_</S><S S="Error">+ ~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : ObjectNotFound: (this:String) [], CommandNotFoundException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : CommandNotFoundException_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S></Objs>
2017/05/23 09:47:48 [INFO] 0 bytes written for 'stdout'
2017/05/23 09:47:48 [INFO] RPC client: Communicator ended with: 0
2017/05/23 09:47:48 [INFO] RPC endpoint: Communicator ended with: 0
2017/05/23 09:47:48 packer.exe: 2017/05/23 09:47:48 [INFO] 1082 bytes written for 'stderr'
2017/05/23 09:47:48 packer.exe: 2017/05/23 09:47:48 [INFO] 0 bytes written for 'stdout'
2017/05/23 09:47:48 packer.exe: 2017/05/23 09:47:48 [INFO] RPC client: Communicator ended with: 0
2017/05/23 09:47:48 ui:     hyperv-iso: <Objs Version="1.1.0.1" xmlns="http://schemas.microsoft.com/powershell/2004/04"><Obj S="progress" RefId="0"><TN RefId="0"><T>System.Management.Automation.PSCustomObject</T><T>System.Object</T></TN><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Preparing modules for first use.</AV><AI>0</AI><Nil /><PI>-1</PI><PC>-1</PC><T>Completed</T><SR>-1</SR><SD> </SD></PR></MS></Obj><S S="Error">this : The term 'this' is not recognized as the name of a cmdlet, function, script file, or operable program. Check _x000D__x000A_</S><S S="Error">the spelling of the name, or if a path was included, verify that the path is correct and try again._x000D__x000A_</S><S S="Error">At C:\Windows\Temp\script.ps1:1 char:1_x000D__x000A_</S><S S="Error">+ this is not a valid powershell command_x000D__x000A_</S><S S="Error">+ ~~~~_x000D__x000A_</S><S S="Error">    + CategoryInfo          : ObjectNotFound: (this:String) [], CommandNotFoundException_x000D__x000A_</S><S S="Error">    + FullyQualifiedErrorId : CommandNotFoundException_x000D__x000A_</S><S S="Error"> _x000D__x000A_</S></Objs>

You can see some errors printed there but Packer just continues as if all was fine.

[sandersaares]

This seems to be due to the fact that while an error is written, $LastExitCode is not set. The powershell provisioner uses $LastExitCode as its own exit code, so there we are - Packer thinks all went well.

A workaround is to prefix the command in the template with $ErrorActionPreference="Stop", which causes the whole PowerShell execution to stop on first error (including the parent script, which would otherwise exit with $LastExitCode).

From the usage of $LastExitCode in the default content for the autogenerated parent script, I infer that the intent is to fail the provisioner if something in the script fails. Therefore it seems like it might be valid to also include $ErrorActionPreference="Stop" in the default parent script.

[luke-vidler]

Thanks for the explanation, has helped me. Seeing this when I try to use the PowerShell Inline provisioner with the Azure-arm builder thats building a Windows 2012r2 .vhd image.

[sandonov]

I've been pulling my hair out with this. Thank you for the solution!

[mwhooker]

It looks like the powershell execute command has been subject to entropy. I see the docs still call it out as powershell "& { {{.Vars}}{{.Path}}; exit $LastExitCode}", which I think is what it used to be.

I'll see if I can work out the correct command to run. Currently it's if (Test-Path variable:global:ProgressPreference){$ProgressPreference='SilentlyContinue'};{{.Vars}}&'{{.Path}}';exit $LastExitCode

[matt-richardson]

The fun part of it is that $LastExitCode is only set based on external programs called from powershell, not based on any errors.

I looked through the code base for Octopus Deploy (which does a _lot_ of powershell script running) and we do:

var command = "powershell -NonInteractive -NoProfile -NoLogo -ExecutionPolicy Unrestricted -Command \"$ErrorActionPreference = 'Stop'; . {{. '" + scriptFile + "' " + args + "; if ((test-path variable:global:lastexitcode)) {{ exit $LastExitCode }}}}\"";

Hope that helps.

[mwhooker]

that looks useful, thanks!

[taliesins]

I have been working out the kinks for how to remotely run powershell without encoding issues and returning expected results. I think it is almost ready to be pulled into Packer.

https://github.com/taliesins/terraform/blob/HyperVProvider/builtin/providers/hyperv/powershell/template.go

[SwampDragons]

@taliesins think this'll be ready for this milestone? (Scheduled for Sept 27)

[SwampDragons]

Pushing this to the next milestone, since I haven't heard from @taliesins and I assume that means he's got other stuff going on.

[SwampDragons]

I think we should probably conclude that @taliesins is too busy with other things to get this across the finish line; unscheduling for now.

[lavahot]

@taliesins Can we get this issue resolved? Weren't to you close to a fix already?

[gvcgael]

I still encounter this problem with packer 1.4.0. A script with a syntax error doesn't abort the build.

[puetzk]

I also just hit this, with another twist that the error itself was the powershell provisioner seeming not copying the script?

==> openstack: Using winrm communicator to connect: 10.141.130.30
==> openstack: Waiting for WinRM to become available...
==> openstack: #< CLIXML
openstack: WinRM connected.
==> openstack: System.Management.Automation.PSCustomObjectSystem.Object1Preparing modules for first use.0-1-1Completed-1 2Preparing modules for first use.0-1-1Completed-1
==> openstack: Connected to WinRM!
==> openstack: Provisioning with Powershell...
==> openstack: Provisioning with powershell script: ../common/install-python.ps1
==> openstack: & : The term 'c:/Windows/Temp/script-5da72be0-bc01-7db9-53da-45767cb4574a.ps1' is not recognized as the name of a
==> openstack: cmdlet, function, script file, or operable program. Check the spelling of the name, or if a path was included, verify
==> openstack: that the path is correct and try again.
==> openstack: At line:1 char:216
==> openstack: + ... 43fe7.ps1; &'c:/Windows/Temp/script-5da72be0-bc01-7db9-53da-45767cb45 ...
==> openstack: + ~~~~~~~~~~~~~
==> openstack: + CategoryInfo : ObjectNotFound: (c:/Windows/Temp...5767cb4574a.ps1:String) [], CommandNotFoundException
==> openstack: + FullyQualifiedErrorId : CommandNotFoundException
==> openstack:
==> openstack: Provisioning with Powershell...
==> openstack: Provisioning with powershell script: ../conan/scripts/install-conan.ps1

So not only did the error not stop the build, it also seems to be that the file which was missing is the script packer supposedly just uploaded (maybe that failed too, and that error was also silently ignored)?

[puetzk]

On a subsequent run (no changes to the template or source image) it worked fine, so it was apparently some transient hiccup, and there's nothing more in the log (the next provisioner script actually failed because it uses python, which hadn't been installed because the script got skipped by this error, and that failure did abort the build).

[nywilken]

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.