packer-1.1.2 bug

log.md

PACKER_LOG=1 /opt/packer/1.1.2/packe
r build --only=vmware-iso -var 'headless=true' windows-2012.json
...<redacted text>

Here it is finishing up several hours of windows updates

2017/11/22 09:24:27 ui:     vmware-iso: 4 Installed  KB3178539 356 K
B Security Update for Windows Server 2012 R2 (KB...
    vmware-iso: 4 Installed  KB3178539 356 KB Security Update for Wi
ndows Server 2012 R2 (KB...
2017/11/22 09:24:55 ui:     vmware-iso: 4 Installed  KB3179574  29 M
B Update for Windows Server 2012 R2 (KB3179574)
    vmware-iso: 4 Installed  KB3179574  29 MB Update for Windows Ser
ver 2012 R2 (KB3179574)
2017/11/22 09:25:01 ui:     vmware-iso: 4 Installed  KB3173424  10 M
B Update for Windows Server 2012 R2 (KB3173424)
    vmware-iso: 4 Installed  KB3173424  10 MB Update for Windows Ser
ver 2012 R2 (KB3173424)
2017/11/22 09:26:54 ui:     vmware-iso: 4 Installed  KB3186539  68 M
B Microsoft .NET Framework 4.7 for Windows 8.1 a...
    vmware-iso: 4 Installed  KB3186539  68 MB Microsoft .NET Framewo
rk 4.7 for Windows 8.1 a...
2017/11/22 09:27:25 ui:     vmware-iso: 4 Installed  KB4033428   3 M
B Update for Windows Server 2012 R2 (KB4033428)
    vmware-iso: 4 Installed  KB4033428   3 MB Update for Windows Ser
ver 2012 R2 (KB4033428)
    vmware-iso: 4 Installed  KB4048958 293 MB 2017-11 Security Month
ly Quality Rollup for Wi...
2017/11/22 09:28:55 ui:     vmware-iso: 4 Installed  KB4048958 293 M
B 2017-11 Security Monthly Quality Rollup for Wi...
2017/11/22 09:29:25 ui:     vmware-iso: 4 Installed  KB890830   37 M
B Windows Malicious Software Removal Tool for Wi...
    vmware-iso: 4 Installed  KB890830   37 MB Windows Malicious Soft
ware Removal Tool for Wi...
2017/11/22 09:29:25 ui:     vmware-iso: Reboot is required, but do i
t manually.
    vmware-iso: Reboot is required, but do it manually.
2017/11/22 09:29:25 ui:     vmware-iso:
2017/11/22 09:29:25 packer: 2017/11/22 09:29:25 [INFO] command 'powe
rshell -executionpolicy bypass "& { if (Test-Path variable:global:Pr
ogressPreference){$ProgressPreference='SilentlyContinue'};$env:PACKE
R_BUILDER_TYPE=\"vmware-iso\"; $env:PACKER_BUILD_NAME=\"vmware-iso\"
; &'c:/Windows/Temp/script-5a159201-c7de-645c-a081-f45f3b1c9db3.ps1'
;exit $LastExitCode }"' exited with code: 0
    vmware-iso:
2017/11/22 09:29:25 packer: 2017/11/22 09:29:25 [INFO] RPC endpoint:
 Communicator ended with: 0
2017/11/22 09:29:25 ui:     vmware-iso:
    vmware-iso:
2017/11/22 09:29:25 ui:     vmware-iso: Ended Windows Update Install
ation
    vmware-iso: Ended Windows Update Installation
2017/11/22 09:29:25 [INFO] 26119 bytes written for 'stdout'
2017/11/22 09:29:25 [INFO] 0 bytes written for 'stderr'
2017/11/22 09:29:25 [INFO] RPC client: Communicator ended with: 0
2017/11/22 09:29:25 [INFO] RPC endpoint: Communicator ended with: 0
2017/11/22 09:29:25 packer: 2017/11/22 09:29:25 [INFO] 26119 bytes w
ritten for 'stdout'
2017/11/22 09:29:25 packer: 2017/11/22 09:29:25 [INFO] 0 bytes writt
en for 'stderr'
2017/11/22 09:29:25 packer: 2017/11/22 09:29:25 [INFO] RPC client: C
ommunicator ended with: 0
2017/11/22 09:29:25 [INFO] (telemetry) ending powershell
2017/11/22 09:29:25 [INFO] (telemetry) Starting provisioner windows-
restart
2017/11/22 09:29:25 ui: ==> vmware-iso: Pausing 1m0s before the next
 provisioner...
==> vmware-iso: Pausing 1m0s before the next provisioner...
2017/11/22 09:30:25 ui: ==> vmware-iso: Restarting Machine
==> vmware-iso: Restarting Machine
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] starting remo
te command: shutdown /r /f /t 0 /c "packer restart"
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] command 'shut
down /r /f /t 0 /c "packer restart"' exited with code: 0
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] RPC endpoint:
 Communicator ended with: 0
2017/11/22 09:30:25 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:30:25 [INFO] 0 bytes written for 'stderr'
2017/11/22 09:30:25 [INFO] RPC client: Communicator ended with: 0
2017/11/22 09:30:25 [INFO] RPC endpoint: Communicator ended with: 0
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] 0 bytes writt
en for 'stderr'
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] RPC client: C
ommunicator ended with: 0
2017/11/22 09:30:25 ui: ==> vmware-iso: Waiting for machine to resta
rt...
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 Check if machine is
rebooting...
==> vmware-iso: Waiting for machine to restart...
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] starting remo
te command: shutdown.exe -f -r -t 60
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] command 'shut
down.exe -f -r -t 60' exited with code: 1115
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] RPC endpoint:
 Communicator ended with: 1115
2017/11/22 09:30:25 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:30:25 [INFO] 40 bytes written for 'stderr'
2017/11/22 09:30:25 [INFO] RPC client: Communicator ended with: 1115
2017/11/22 09:30:25 [INFO] RPC endpoint: Communicator ended with: 11
15
2017/11/22 09:30:25 ui:     vmware-iso: A system shutdown is in prog
ress.(1115)
    vmware-iso: A system shutdown is in progress.(1115)
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] 40 bytes writ
ten for 'stderr'
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 [INFO] RPC client: C
ommunicator ended with: 1115
2017/11/22 09:30:25 packer: 2017/11/22 09:30:25 Reboot already in pr
ogress, waiting...
2017/11/22 09:30:35 packer: 2017/11/22 09:30:35 Check if machine is
2017/11/22 09:30:35 packer: 2017/11/22 09:30:35 [INFO] starting remo
te command: shutdown.exe -f -r -t 60
2017/11/22 09:30:36 packer: 2017/11/22 09:30:36 [INFO] command 'shut
down.exe -f -r -t 60' exited with code: 1115
2017/11/22 09:30:36 packer: 2017/11/22 09:30:36 [INFO] RPC endpoint:
 Communicator ended with: 1115
2017/11/22 09:30:36 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:30:36 [INFO] 40 bytes written for 'stderr'
2017/11/22 09:30:36 [INFO] RPC client: Communicator ended with: 1115
2017/11/22 09:30:36 [INFO] RPC endpoint: Communicator ended with: 11
15
2017/11/22 09:30:36 ui:     vmware-iso: A system shutdown is in prog
ress.(1115)
    vmware-iso: A system shutdown is in progress.(1115)
2017/11/22 09:30:36 packer: 2017/11/22 09:30:36 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:30:36 packer: 2017/11/22 09:30:36 [INFO] 40 bytes writ
ten for 'stderr'
2017/11/22 09:30:36 packer: 2017/11/22 09:30:36 [INFO] RPC client: C
ommunicator ended with: 1115
2017/11/22 09:30:36 packer: 2017/11/22 09:30:36 Reboot already in pr
ogress, waiting...
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 Check if machine is
rebooting...
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 [INFO] starting remo
te command: shutdown.exe -f -r -t 60
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 [INFO] command 'shut
down.exe -f -r -t 60' exited with code: 1115
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 [INFO] RPC endpoint:
 Communicator ended with: 1115
2017/11/22 09:30:46 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:30:46 [INFO] 40 bytes written for 'stderr'
2017/11/22 09:30:46 [INFO] RPC client: Communicator ended with: 1115
2017/11/22 09:30:46 [INFO] RPC endpoint: Communicator ended with: 11
15
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 [INFO] 40 bytes writ
ten for 'stderr'
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 [INFO] RPC client: C
ommunicator ended with: 1115
    vmware-iso: A system shutdown is in progress.(1115)
2017/11/22 09:30:46 ui:     vmware-iso: A system shutdown is in prog
ress.(1115)
2017/11/22 09:30:46 packer: 2017/11/22 09:30:46 Reboot already in pr
ogress, waiting...
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 Check if machine is
rebooting...
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] starting remo
te command: shutdown.exe -f -r -t 60
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] command 'shut
down.exe -f -r -t 60' exited with code: 1115
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] RPC endpoint:
2017/11/22 09:30:56 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:30:56 [INFO] 40 bytes written for 'stderr'
2017/11/22 09:30:56 [INFO] RPC client: Communicator ended with: 1115
2017/11/22 09:30:56 [INFO] RPC endpoint: Communicator ended with: 11
15
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] 40 bytes writ
ten for 'stderr'
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] RPC client: C
ommunicator ended with: 1115
    vmware-iso: A system shutdown is in progress.(1115)
2017/11/22 09:30:56 ui:     vmware-iso: A system shutdown is in prog
ress.(1115)
2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 Reboot already in pr
ogress, waiting...
2017/11/22 09:31:06 packer: 2017/11/22 09:31:06 Check if machine is
rebooting...
2017/11/22 09:31:16 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:31:16 [INFO] 0 bytes written for 'stderr'
2017/11/22 09:31:16 packer: 2017/11/22 09:31:16 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:31:16 packer: 2017/11/22 09:31:16 Waiting for machine
to reboot with timeout: 1h0m0s
2017/11/22 09:31:16 packer: 2017/11/22 09:31:16 Waiting for machine
to become available...
2017/11/22 09:31:16 packer: 2017/11/22 09:31:16 Checking that commun
icator is connected with: 'powershell.exe -EncodedCommand ZQBjAGgAbw
AgACIAJAB7AGUAbgB2ADoAQwBPAE0AUABVAFQARQBSAE4AQQBNAEUAfQAgAHIAZQBzAH
QAYQByAHQAZQBkAC4AIgA='
2017/11/22 09:31:16 packer: 2017/11/22 09:31:16 [INFO] 0 bytes writt
en for 'stderr'
2017/11/22 09:31:51 [INFO] 0 bytes written for 'stdout'
2017/11/22 09:31:51 [INFO] 0 bytes written for 'stderr'
2017/11/22 09:31:51 packer: 2017/11/22 09:31:51 [INFO] 0 bytes writt
en for 'stdout'
2017/11/22 09:31:51 packer: 2017/11/22 09:31:51 [INFO] 0 bytes writt
en for 'stderr'
2017/11/22 10:30:25 ui error: ==> vmware-iso: Timeout waiting for ma
chine to restart.
==> vmware-iso: Timeout waiting for machine to restart.
2017/11/22 10:30:25 [INFO] (telemetry) ending windows-restart
2017/11/22 10:30:25 [INFO] (telemetry) found error: Timeout waiting
for machine to restart.
2017/11/22 10:30:25 packer: 2017/11/22 10:30:25 Executing: /usr/bin/
vmrun -T ws list
2017/11/22 10:30:26 packer: 2017/11/22 10:30:26 stdout: Total runnin
g VMs: 1
2017/11/22 10:30:26 packer: /root/1.1.2/output-win2012r2-vmware/pack
er-vmware-iso.vmx
2017/11/22 10:30:26 packer: 2017/11/22 10:30:26 stderr:
2017/11/22 10:30:26 ui: ==> vmware-iso: Stopping virtual machine...
==> vmware-iso: Stopping virtual machine...
2017/11/22 10:30:26 packer: 2017/11/22 10:30:26 Executing: /usr/bin/
vmrun -T ws stop output-win2012r2-vmware/packer-vmware-iso.vmx hard
2017/11/22 10:30:27 packer: 2017/11/22 10:30:27 stdout:
2017/11/22 10:30:27 packer: 2017/11/22 10:30:27 stderr:
2017/11/22 10:30:27 packer: 2017/11/22 10:30:27 Deleting floppy disk
: /tmp/packer194523569
2017/11/22 10:30:27 ui: ==> vmware-iso: Deleting output directory...
==> vmware-iso: Deleting output directory...
2017/11/22 10:30:28 [INFO] (telemetry) ending vmware-iso
2017/11/22 10:30:28 [INFO] (telemetry) found error: Timeout waiting
for machine to restart.
2017/11/22 10:30:28 ui error: Build 'vmware-iso' errored: Timeout wa
iting for machine to restart.
2017/11/22 10:30:28 Builds completed. Waiting on interrupt barrier..
.
2017/11/22 10:30:28 machine readable: error-count []string{"1"}
2017/11/22 10:30:28 ui error:
==> Some builds didn't complete successfully and had errors:
2017/11/22 10:30:28 machine readable: vmware-iso,error []string{"Tim
eout waiting for machine to restart."}
2017/11/22 10:30:28 ui error: --> vmware-iso: Timeout waiting for ma
chine to restart.
2017/11/22 10:30:28 ui:
==> Builds finished but no artifacts were created.
2017/11/22 10:30:28 [INFO] (telemetry) Finalizing.
Build 'vmware-iso' errored: Timeout waiting for machine to restart.

==> Some builds didn't complete successfully and had errors:
--> vmware-iso: Timeout waiting for machine to restart.

==> Builds finished but no artifacts were created.
2017/11/22 10:30:29 waiting for all plugin processes to complete...
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 [ERR] Error decoding response stream 47: EOF
2017/11/22 10:30:29 [ERR] Error decoding response stream 50: EOF
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited
2017/11/22 10:30:29 /opt/packer/1.1.2/packer: plugin process exited