search

packer-community / packer-windows-plugins

A suite of Packer plugins for provisioning Windows machines
113 stars 20 forks source link

Script exited with non-zero exit status: 259 #58

Open colinbowern opened 9 years ago

colinbowern commented 9 years ago

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 commented 9 years ago

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 commented 9 years ago

@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 commented 9 years ago

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 commented 9 years ago

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 commented 9 years ago

Is this still an issue @colinbowern?

kaylynb commented 9 years ago

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 commented 9 years ago

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 commented 8 years ago

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 commented 8 years ago

@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.