Script exited with non-zero exit status: 259

[colinbowern]

I'm seeing issue #33 pop up using the pre-release build. I'm getting this sporadically for a PSH script that installs VMware Tools:

==> vmware-windows-iso: Downloading or copying ISO
    vmware-windows-iso: Downloading or copying: file://C:\Users\colinb\Projects\BaseBoxes/C:/Users/colinb/Projects/BaseBoxes/Images/WindowsServer-2012R2.1-amd64.iso
==> vmware-windows-iso: Creating floppy disk...
    vmware-windows-iso: Copying: Keys/CertificateAuthority.crt
    vmware-windows-iso: Copying: Keys/Work/BASEWS2012R21.pfx
    vmware-windows-iso: Copying: Scripts/Enable-WinRM.ps1
    vmware-windows-iso: Copying: Templates/WindowsServer-2012R2.1-Standard/Autounattend.xml
    vmware-windows-iso: Copying: Templates/WindowsServer-2012R2.1-Standard/Sysprep.xml
==> vmware-windows-iso: Creating virtual machine disk
==> vmware-windows-iso: Building and writing VMX file
==> vmware-windows-iso: Starting virtual machine...
==> vmware-windows-iso: Waiting 10s for boot...
==> vmware-windows-iso: Connecting to VM via VNC
==> vmware-windows-iso: Typing the boot command over VNC...
==> vmware-windows-iso: Waiting for WinRM to become available...
==> vmware-windows-iso: Connected to WinRM!
==> vmware-windows-iso: Uploading the 'windows' VMware Tools
==> vmware-windows-iso: Provisioning with Powershell...
==> vmware-windows-iso: Provisioning with shell script: Scripts/Install-VMwareTools.ps1
    vmware-windows-iso: Transcript started, output file is C:\Users\vagrant\AppData\Local\Temp\script.log
    vmware-windows-iso: #< CLIXML
    vmware-windows-iso: Transcript stopped, output file is C:\Users\vagrant\AppData\Local\Temp\script.log
    vmware-windows-iso:
    vmware-windows-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>Mount-DiskImage -ImagePath $Env:Temp\VMwareTools.iso</AV><AI>59606033</AI><Nil /><PI>-1</PI><PC>0</PC><T>Processing</T><SR>-1</SR><SD>0/2+ completed</SD></PR></MS></Obj><Obj S="progress" RefId="1"><TNRef RefId="0" /><MS><I64 N="SourceId">1</I64><PR N="Record"><AV>Mount-DiskImage -ImagePath $Env:Temp\VMwareTools.iso</AV><AI>59606033</AI><Nil /><PI>-1</PI><PC>100</PC><T>Completed</T><SR>0</SR><SD>2/2 completed</SD></PR></MS></Obj><Obj S="progress" RefId="2"><TNRef RefId="0" /><MS><I64 N="SourceId">2</I64><PR N="Record"><AV>Get-DiskImage -ImagePath $Env:Temp\VMwareTools.iso | Get-Volume</AV><AI>496342505</AI><Nil /><PI>-1</PI><PC>100</PC><T>Completed</T><SR>0</SR><SD>1/1 completed</SD></PR></MS></Obj><Obj S="progress" RefId="3"><TNRef RefId="0" /><MS><I64 N="SourceId">3</I64><PR N="Record"><AV>Get-Volume</AV><AI>607711163</AI><Nil /><PI>-1</PI><PC>100</PC><T>Completed</T><SR>0</SR><SD>1/1 completed</SD></PR></MS></Obj><Obj S="progress" RefId="4"><TNRef RefId="0" /><MS><I64 N="SourceId">4</I64><PR N="Record"><AV>Dismount-DiskImage -ImagePath $Env:Temp\VMwareTools.iso</AV><AI>1144664691</AI><Nil /><PI>-1</PI><PC>100</PC><T>Completed</T><SR>0</SR><SD>2/2 completed</SD></PR></MS></Obj></Objs>
==> vmware-windows-iso: Stopping virtual machine...
==> vmware-windows-iso: Deleting output directory...
Build 'vmware-windows-iso' errored: Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]

==> Some builds didn't complete successfully and had errors:
--> vmware-windows-iso: Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]

==> Builds finished but no artifacts were created.

Here is the debug version:

2015/05/29 23:29:51 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:29:51 starting remote command: powershell -executionpolicy bypass -file "%TEMP%\packer-elevated-shell-55684d99-da63-494d-085f-bdda9e8c506d.ps1"
2015/05/29 23:30:02 ui:     vmware-windows-iso: Transcript started, output file is C:\Users\vagrant\AppData\Local\Temp\script.log
    vmware-windows-iso: Transcript started, output file is C:\Users\vagrant\AppData\Local\Temp\script.log
2015/05/29 23:30:08 ui:     vmware-windows-iso: #< CLIXML
    vmware-windows-iso: #< CLIXML
2015/05/29 23:30:59 ui:     vmware-windows-iso: Transcript stopped, output file is C:\Users\vagrant\AppData\Local\Temp\script.log
    vmware-windows-iso: Transcript stopped, output file is C:\Users\vagrant\AppData\Local\Temp\script.log
2015/05/29 23:31:00 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:00 [INFO] RPC endpoint: Communicator ended with: 259
2015/05/29 23:31:00 [INFO] 0 bytes written for 'stderr'
2015/05/29 23:31:00 [INFO] 174 bytes written for 'stdout'
2015/05/29 23:31:00 [INFO] RPC client: Communicator ended with: 259
2015/05/29 23:31:00 [INFO] RPC endpoint: Communicator ended with: 259
2015/05/29 23:31:00 packer-provisioner-powershell.exe: 2015/05/29 23:31:00 [INFO] RPC client: Communicator ended with: 259
2015/05/29 23:31:00 packer-provisioner-powershell.exe: 2015/05/29 23:31:00 [INFO] 0 bytes written for 'stderr'
2015/05/29 23:31:00 packer-provisioner-powershell.exe: 2015/05/29 23:31:00 [INFO] 174 bytes written for 'stdout'
2015/05/29 23:31:00 ui:     vmware-windows-iso:
    vmware-windows-iso:
2015/05/29 23:31:00 ui:     vmware-windows-iso:
2015/05/29 23:31:00 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:00 Executing: C:/Program Files (x86)/VMware/VMware Workstation/vmrun.exe [-T ws list]
    vmware-windows-iso:
2015/05/29 23:31:00 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:00 stdout: Total running VMs: 1
2015/05/29 23:31:00 packer-builder-vmware-windows-iso.exe: C:\Users\colinb\Projects\BaseBoxes\output-vmware-windows-iso\WindowsServer-2012R2.1-Standard.vmx
2015/05/29 23:31:00 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:00 stderr:
2015/05/29 23:31:00 ui: ==> vmware-windows-iso: Stopping virtual machine...
2015/05/29 23:31:00 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:00 Executing: C:/Program Files (x86)/VMware/VMware Workstation==> vmware-windows-iso: Stopping virtual machine...
/vmrun.exe [-T ws stop output-vmware-windows-iso\WindowsServer-2012R2.1-Standard.vmx hard]
2015/05/29 23:31:02 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:02 stdout:
2015/05/29 23:31:02 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:02 stderr:
2015/05/29 23:31:02 packer-builder-vmware-windows-iso.exe: 2015/05/29 23:31:02 Deleting floppy disk: C:\Users\colinb\AppData\Local\Temp\packer715290615
2015/05/29 23:31:02 ui: ==> vmware-windows-iso: Deleting output directory...
==> vmware-windows-iso: Deleting output directory...
2015/05/29 23:31:02 ui error: Build 'vmware-windows-iso' errored: Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]
Build 'vmware-windows-iso' errored: Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]
2015/05/29 23:31:02 Builds completed. Waiting on interrupt barrier...

2015/05/29 23:31:02 machine readable: error-count []string{"1"}
2015/05/29 23:31:02 ui error:
==> Some builds didn't complete successfully and had errors:
==> Some builds didn't complete successfully and had errors:
2015/05/29 23:31:02 machine readable: vmware-windows-iso,error []string{"Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]"}
2015/05/29 23:31:02 ui error: --> vmware-windows-iso: Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]
--> vmware-windows-iso: Script exited with non-zero exit status: 259. Allowed exit codes are: [%!s(int=0)]
2015/05/29 23:31:02 ui:
==> Builds finished but no artifacts were created.

With Packer destroying the artifacts it is difficult to inspect what happened. Packer really needs an option to preserve failed output.

[dylanmei]

While there surely seems to be a problem here, I do have a couple comments:

Is this something that needs to be run via elevated_user/elevated_password? In my experience, the only thing that needs to run like that is installing .NET.

Is the script known to work from a VM? When I'm testing a script, I'll set the shutdown_timeout to a large timeout value, and through the ui run the script manually until it works.

{
  "type": "vmware-windows-ovf",
  "headless": false,
  "shutdown_timeout": "2h",
  "shutdown_command": "shutdown /s /t 7200 /f /d p:4:1 /c \"Packer Shutdown\""
}

[colinbowern]

@dylanmei installing VMware Tools certainly requires elevation

Thanks for the tip on the shutdown timeout - will give it a try. Do you know if that will work even if the script throws up with an error code 259?

[dylanmei]

Elevation is a loaded term. You're already running with admin privileges so you can install stuff, stop and start services, and so on. In the Packer/Vagrant world, it means "run this as a scheduled task so windows thinks I am a real user and not a remote user."

See this excellent article: http://www.hurryupandwait.io/blog/safely-running-windows-automation-operations-that-typically-fail-over-winrm-or-powershell-remoting

[dylanmei]

Regarding your other question - remove your script from the template and run it by hand.

I recommend a two-phase build if you are worried about painful build times. Build one outputs vmx from an iso after applying windows updates. Build two takes the vmx and this is where you would specialize your base vmx by provisioning for Vagrant or for production.

[mefellows]

Is this still an issue @colinbowern?

[kaylynb]

I've been running into this as well. A repro here: kaylynb/packer-windows#53ad

Running on OSX 10.10 w/ packer 0.8.2 and VirtualBox 5.

I'm trying to install updates using the elevated PowerShell provisioner, but it appears to timeout after about 1.5 hours:

    virtualbox-iso: 84/120 [Security Update for Microsoft .NET Framework 4.5.1 and 4.5.2 on Windows 8.1 and Windows Server 2012 R2 x64-based Systems (KB3032663)]
    virtualbox-iso: 85/120 [Security Update for Microsoft .NET Framework 4.5.1 and 4.5.2 on Windows 8.1 and Windows Server 2012 R2 x64-based Systems (KB3023222)]
==> virtualbox-iso: Unregistering and deleting virtual machine...
==> virtualbox-iso: Deleting output directory...
Build 'virtualbox-iso' errored: Script exited with non-zero exit status: 259. Allowed exit codes are: [0]

I don't think it's that specific update, but rather the time, as I've skipped that update, and it still fails. If I install in smaller chunks that take less than an hour each, or use a pre-patched iso (dism+oscdimg) it works fine.

I'll probably try to make a simpler repro (perhaps just an idle wait in the scheduled task) soon(ish).

As a more robust workaround (but doesn't show update in terminal), it's probably best to just do long-running installation tasks with autounattend.xml and set winrm_timeout very high.

[kaylynb]

I created a simpler project that uses the server 2012 eval version and just does a simple wait: kaylynb/packer-windows-psprovisioner-repro. I'm thinking this may actually be some sort of issue with the task scheduler on windows, and maybe not something specifically wrong with packer.

I had time to run it 5 times and it only failed twice:

    virtualbox-iso: Minutes Elapsed: 45
    virtualbox-iso: Minutes Elapsed: 50
    virtualbox-iso: Minutes Elapsed: 55
==> virtualbox-iso: Unregistering and deleting virtual machine...
==> virtualbox-iso: Deleting output directory...
Build 'virtualbox-iso' errored: Script exited with non-zero exit status: 259. Allowed exit codes are: [0]

The timing makes me feel like there is some sort of 1hr timeout happening somewhere, but the task config in elevated.go appears to be setting timeout to 24h, so it doesn't seem like that is the problem.

[spuder]

I also am running into this. Seems to correlate with upgrading packer to 0.11.0 since the same packer configs worked a few weeks ago.

Happened somewhere between 1.5 hours and 2 hours into the build. I suspect it is a built in timeout since it failed at the least complicated step.

==> vmware-iso: Provisioning with Powershell...
==> vmware-iso: Provisioning with shell script: scripts/windows/common/buildtime.ps1
==> vmware-iso: Stopping virtual machine...
==> vmware-iso: Deleting output directory...
Build 'vmware-iso' errored: Script exited with non-zero exit status: 2. Allowed exit codes are: [0]

==> Some builds didn't complete successfully and had errors:
--> vmware-iso: Script exited with non-zero exit status: 2. Allowed exit codes are: [0]

==> Builds finished but no artifacts were created.

[mefellows]

@spuder it's been a while, but is exit status 2 expected in this script? I recall there were some situations where a non-zero exit code was also considered a success and hence valid_exit_codes is supported for the PoSH provisioner.