Windows builds on VMWare Workstation failing on 1.1.2

[spuder]

Problem

Windows 2012 reboots are not detected properly on packer 1.1.2 with vmware-workstation (linux).
Windows 2012 reboots are detected properly on packer 1.1.2 with vmware-fusion(OsX).

packer 1.0.4 and 1.1.1 work properly on both platforms.

Failures

packer	vmware	os
1.1.2	workstation 12.5.4	ubuntu 16.04

I have reproduced this over 12 times with 100% consistency. I'm using the same packer definition that has been working for months with 1.0.4

Packer does not fail if using 1.0.4/1.1.1 OR if running 1.1.2 with OSX with vmware-fusion

Successes

packer	vmware	os
1.0.4	workstation 12.5.4	ubuntu 16.04
1.1.1	workstation 12.5.4	ubuntu 16.04
1.0.4	vmware-fusion 8	Mac OSX
1.1.2	vmware-fusion 8	Mac OSX

Symptom

This is easy, but very time consuming to reproduce, because it only happens after windows 2012 has completed installing windows updates, and then packer attempts to reboot the machine.

    {
      "script": "scripts/windows/common/stop-windows-updates.ps1",
      "type": "powershell"
    },
    {
      "script": "scripts/windows/common/install-chocolatey.ps1",
      "type": "powershell"
    },
    {
      "type": "powershell",
      "inline": ["choco install pswindowsupdate --verbose -y"]
    },
    {
      "script": "scripts/windows/common/windows-updates.ps1",
      "type": "powershell"
    },
    {
      "type": "windows-restart",
       "pause_before": "1m",
       "restart_timeout": "1h"
    },

Watching the build process, windows always gets stuck shutting down after installing windows updates, and shows error. (Sorry for the picture, the ubuntu build machine doesn't have VNC).

After 5 to 30 minutes, the windows error always clears itself and windows reboots successfully. However packer 1.1.2 never detects that the vm has successfully rebooted, even with a 1 hour timeout.

    vmware-iso: A system shutdown is in progress.(1115)
2017/11/21 14:22:57 ui:     vmware-iso: A system shutdown is in progress.(1115)
2017/11/21 14:22:57 packer-1.1.2: 2017/11/21 14:22:57 Reboot already in progress, waiting...
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 Check if machine is rebooting...
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 [INFO] starting remote command: shutdown.exe -f -r -t 60
2017/11/21 14:23:07 [INFO] 0 bytes written for 'stdout'
2017/11/21 14:23:07 [INFO] 40 bytes written for 'stderr'
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 [INFO] command 'shutdown.exe -f -r -t 60' exited with code: 1115
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 [INFO] RPC endpoint: Communicator ended with: 1115
2017/11/21 14:23:07 [INFO] RPC client: Communicator ended with: 1115
2017/11/21 14:23:07 [INFO] RPC endpoint: Communicator ended with: 1115
2017/11/21 14:23:07 ui:     vmware-iso: A system shutdown is in progress.(1115)
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 [INFO] 0 bytes written for 'stdout'
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 [INFO] 40 bytes written for 'stderr'
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 [INFO] RPC client: Communicator ended with: 1115
    vmware-iso: A system shutdown is in progress.(1115)
2017/11/21 14:23:07 packer-1.1.2: 2017/11/21 14:23:07 Reboot already in progress, waiting...
2017/11/21 14:23:17 packer-1.1.2: 2017/11/21 14:23:17 Check if machine is rebooting...
2017/11/21 14:23:27 [INFO] 0 bytes written for 'stdout'
2017/11/21 14:23:27 [INFO] 0 bytes written for 'stderr'
2017/11/21 14:23:27 packer-1.1.2: 2017/11/21 14:23:27 [INFO] 0 bytes written for 'stderr'
2017/11/21 14:23:27 packer-1.1.2: 2017/11/21 14:23:27 Waiting for machine to reboot with timeout: 5m0s
2017/11/21 14:23:27 packer-1.1.2: 2017/11/21 14:23:27 Waiting for machine to become available...
2017/11/21 14:23:27 packer-1.1.2: 2017/11/21 14:23:27 Checking that communicator is connected with: 'powershell.exe -EncodedCommand ZQBjAGgAbwAgACIAJAB7AGUAbgB2ADoAQwBPAE0AUABVAFQARQBSAE4AQQBNAEUAfQAgAHIAZQBzAHQAYQByAHQAZQBkAC4AIgA='
2017/11/21 14:23:27 packer-1.1.2: 2017/11/21 14:23:27 [INFO] 0 bytes written for 'stdout'
2017/11/21 14:24:02 [INFO] 0 bytes written for 'stdout'
2017/11/21 14:24:02 [INFO] 0 bytes written for 'stderr'
2017/11/21 14:24:02 packer-1.1.2: 2017/11/21 14:24:02 [INFO] 0 bytes written for 'stdout'
2017/11/21 14:24:02 packer-1.1.2: 2017/11/21 14:24:02 [INFO] 0 bytes written for 'stderr'
==> vmware-iso: Timeout waiting for machine to restart.
2017/11/21 14:27:46 ui error: ==> vmware-iso: Timeout waiting for machine to restart.
2017/11/21 14:27:46 [INFO] (telemetry) ending windows-restart
2017/11/21 14:27:46 [INFO] (telemetry) found error: Timeout waiting for machine to restart.
2017/11/21 14:27:46 packer-1.1.2: 2017/11/21 14:27:46 Executing: /usr/bin/vmrun -T ws list
2017/11/21 14:27:46 packer-1.1.2: 2017/11/21 14:27:46 stdout: Total running VMs: 1
2017/11/21 14:27:46 packer-1.1.2: /root/golden-images-vagrant/output-win2012r2-vmware/packer-vmware-iso.vmx
2017/11/21 14:27:46 packer-1.1.2: 2017/11/21 14:27:46 stderr:
2017/11/21 14:27:46 ui: ==> vmware-iso: Stopping virtual machine...
2017/11/21 14:27:46 packer-1.1.2: 2017/11/21 14:27:46 Executing: /usr/bin/vmrun -T ws stop output-win2012r2-vmware/packer-vmware-iso.vmx hard
==> vmware-iso: Stopping virtual machine...
2017/11/21 14:27:48 packer-1.1.2: 2017/11/21 14:27:48 stdout:
2017/11/21 14:27:48 packer-1.1.2: 2017/11/21 14:27:48 stderr:
2017/11/21 14:27:48 packer-1.1.2: 2017/11/21 14:27:48 Deleting floppy disk: /tmp/packer990518872
==> vmware-iso: Deleting output directory...
2017/11/21 14:27:48 ui: ==> vmware-iso: Deleting output directory...
2017/11/21 14:27:49 packer-1.1.2: 2017/11/21 14:27:49 Error removing output dir: remove output-win2012r2-vmware: directory not empty
2017/11/21 14:27:51 [INFO] (telemetry) ending vmware-iso
2017/11/21 14:27:51 [INFO] (telemetry) found error: Timeout waiting for machine to restart.
2017/11/21 14:27:51 ui error: Build 'vmware-iso' errored: Timeout waiting for machine to restart.
2017/11/21 14:27:51 Builds completed. Waiting on interrupt barrier...
2017/11/21 14:27:51 machine readable: error-count []string{"1"}
2017/11/21 14:27:51 ui error:
==> Some builds didn't complete successfully and had errors:
2017/11/21 14:27:51 machine readable: vmware-iso,error []string{"Timeout waiting for machine to restart."}
2017/11/21 14:27:51 ui error: --> vmware-iso: Timeout waiting for machine to restart.
2017/11/21 14:27:51 ui:
==> Builds finished but no artifacts were created.
2017/11/21 14:27:51 [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/21 14:27:51 waiting for all plugin processes to complete...
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 [ERR] Error decoding response stream 39: EOF
2017/11/21 14:27:51 [ERR] Error decoding response stream 36: EOF
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited
2017/11/21 14:27:51 /opt/packer/packer-1.1.2: plugin process exited

Installed 1.15.7 of the vmware VIX api library

vmware-installer -t
Component Name                 Component Long Name                               Component Version
============================== ================================================= ====================
vmware-installer               VMware Installer                                  2.1.0.5087745
vmware-player-setup            VMware Player Setup                               12.5.4.5192485
vmware-vmx                     VMware VMX                                        12.5.4.5192485
vmware-vix-core                VMware VIX Core Library                           1.15.7.5192485
vmware-network-editor          VMware Network Editor                             12.5.4.5192485
vmware-network-editor-ui       VMware Network Editor User Interface              12.5.4.5192485
vmware-tools-netware           VMware Tools for NetWare                          10.1.5.5192485
vmware-tools-linuxPreGlibc25   VMware Tools for legacy Linux                     10.1.5.5192485
vmware-tools-winPreVista       VMware Tools for Windows 2000, XP and Server 2003 10.1.5.5192485
vmware-tools-winPre2k          VMware Tools for Windows 95, 95, Me and NT        10.1.5.5192485
vmware-tools-freebsd           VMware Tools for FreeBSD                          10.1.5.5192485
vmware-tools-windows           VMware Tools for Windows Vista or later           10.1.5.5192485
vmware-tools-solaris           VMware Tools for Solaris                          10.1.5.5192485
vmware-tools-linux             VMware Tools for Linux                            10.1.5.5192485
vmware-usbarbitrator           VMware USB Arbitrator                             15.2.0.5192485
vmware-player-app              VMware Player Application                         12.5.4.5192485
vmware-workstation-server      VMware Workstation Server                         12.5.4.5192485
vmware-ovftool                 VMware OVF Tool component for Linux               4.1.0.3634792
vmware-vprobe                  VMware VProbes component for Linux                12.5.4.5192485
vmware-vix-lib-Workstation1200 VMware VIX Workstation-12.0.0 Library             1.15.7.5192485
vmware-workstation             VMware Workstation                                12.5.4.5192485

Workaround

I've had to roll back to 1.0.4 or 1.1.1 to get windows 2012 images working again.

Theories

These are all the milestones from 1.1.2

1. 1.1.2 improved scripts after restarts in #5272. Perhaps the check command is too specific
2. make restart command work correctly even if user has their own check … #5563 looks suspiciously related

What other information can I provide to help debug this? I want packer 1.1.2 to work with vmware workstation on linux.

[spuder]

I reproduced again and captured a more complete log

https://gist.github.com/spuder/0b745828383ba390521b67ce4bbc7023

The first time packer tries to restart, it writes 0 bytes to stderr and stdout

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

Every time after that it writes
40 bytes to stderr

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)

Also strange is that it only tried to restart the system 4 times. In many of the other times I've reproduced this it has tried to restart dozens of times.

2017/11/22 09:30:56 packer: 2017/11/22 09:30:56 [INFO] starting remo
te command: shutdown.exe -f -r -t 60

Even more strange is that packer did not attempt to restart any more times from 9:31 until 10:30.
It is as if packer is respecting the 1 hour timeout, but it aborts the retries after a few minutes.

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.

[gh2k]

I also have this problem building Server 1709:

[18:50:04][Step 1/3] 2017/11/30 18:48:58 ui: ==> vmware-iso: Restarting Machine
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] starting remote command: shutdown /r /f /t 0 /c "packer restart"
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] command 'shutdown /r /f /t 0 /c "packer restart"' exited with code: 0
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] RPC endpoint: Communicator ended with: 0
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] 0 bytes written for 'stderr'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] 0 bytes written for 'stdout'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] RPC client: Communicator ended with: 0
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] RPC endpoint: Communicator ended with: 0
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] 0 bytes written for 'stdout'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] 0 bytes written for 'stderr'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] RPC client: Communicator ended with: 0
[18:50:05][Step 1/3] 2017/11/30 18:48:58 ui: ==> vmware-iso: Waiting for machine to restart...
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 Check if machine is rebooting...
[18:50:05][Step 1/3] ==> vmware-iso: Waiting for machine to restart...
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] starting remote command: shutdown.exe -f -r -t 60
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] command 'shutdown.exe -f -r -t 60' exited with code: 1115
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] RPC endpoint: Communicator ended with: 1115
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] 0 bytes written for 'stdout'
[18:50:05][Step 1/3]     vmware-iso: A system shutdown is in progress.(1115)
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] 40 bytes written for 'stderr'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] RPC client: Communicator ended with: 1115
[18:50:05][Step 1/3] 2017/11/30 18:48:58 [INFO] RPC endpoint: Communicator ended with: 1115
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] 0 bytes written for 'stdout'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] 40 bytes written for 'stderr'
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 [INFO] RPC client: Communicator ended with: 1115
[18:50:05][Step 1/3] 2017/11/30 18:48:58 ui:     vmware-iso: A system shutdown is in progress.(1115)
[18:50:05][Step 1/3] 2017/11/30 18:48:58 packer: 2017/11/30 18:48:58 Reboot already in progress, waiting...
[18:50:15][Step 1/3] 2017/11/30 18:49:08 packer: 2017/11/30 18:49:08 Check if machine is rebooting...
[18:50:45][Step 1/3] 2017/11/30 18:49:38 [INFO] 0 bytes written for 'stdout'
[18:50:45][Step 1/3] 2017/11/30 18:49:38 [INFO] 0 bytes written for 'stderr'
[18:50:45][Step 1/3] 2017/11/30 18:49:38 packer: 2017/11/30 18:49:38 [INFO] 0 bytes written for 'stdout'
[18:50:45][Step 1/3] 2017/11/30 18:49:38 packer: 2017/11/30 18:49:38 [INFO] 0 bytes written for 'stderr'
[18:50:45][Step 1/3] 2017/11/30 18:49:38 packer: 2017/11/30 18:49:38 Waiting for machine to reboot with timeout: 1h0m0s
[18:50:45][Step 1/3] 2017/11/30 18:49:38 packer: 2017/11/30 18:49:38 Waiting for machine to become available...
[18:50:45][Step 1/3] 2017/11/30 18:49:38 packer: 2017/11/30 18:49:38 Checking that communicator is connected with: 'powershell.exe -EncodedCommand ZQBjAGgAbwAgACIAJAB7AGUAbgB2ADoAQwBPAE0AUABVAFQARQBSAE4AQQBNAEUAfQAgAHIAZQBzAHQAYQByAHQAZQBkAC4AIgA='
[18:50:57][Step 1/3] 2017/11/30 18:49:50 [INFO] 0 bytes written for 'stdout'
[18:50:57][Step 1/3] 2017/11/30 18:49:50 [INFO] 0 bytes written for 'stderr'
[18:50:57][Step 1/3] 2017/11/30 18:49:50 packer: 2017/11/30 18:49:50 [INFO] 0 bytes written for 'stdout'
[18:50:57][Step 1/3] 2017/11/30 18:49:50 packer: 2017/11/30 18:49:50 [INFO] 0 bytes written for 'stderr'
[19:50:05][Step 1/3] ==> vmware-iso: Timeout waiting for machine to restart.
[19:50:05][Step 1/3] 2017/11/30 19:48:58 ui error: ==> vmware-iso: Timeout waiting for machine to restart.
[19:50:05][Step 1/3] 2017/11/30 19:48:58 [INFO] (telemetry) ending windows-restart
[19:50:05][Step 1/3] 2017/11/30 19:48:58 [INFO] (telemetry) found error: Timeout waiting for machine to restart.
[19:50:05][Step 1/3] 2017/11/30 19:48:58 packer: 2017/11/30 19:48:58 Executing: /usr/bin/vmrun -T ws list
[19:50:05][Step 1/3] 2017/11/30 19:48:59 packer: 2017/11/30 19:48:59 stdout: Total running VMs: 1
[19:50:05][Step 1/3] 2017/11/30 19:48:59 packer: /packer/output-vmware-iso/WindowsServer1709Docker.vmx
[19:50:05][Step 1/3] 2017/11/30 19:48:59 packer: 2017/11/30 19:48:59 stderr:
[19:50:05][Step 1/3] 2017/11/30 19:48:59 ui: ==> vmware-iso: Stopping virtual machine...

Apologies for the additional log prefixes... This is from a CI build under TeamCity. Same situation where the 1h timeout expires without any apparent attempt to retry the connection.

The build works just fine on my Linux desktop, which has packer 1.0.4.

[SwampDragons]

@gh2k this failure is also on a linux host?

[gh2k]

Yeah, I'm running Gentoo

[gh2k]

Can confirm that on my workstation 1.1.1 works, and 1.1.2 doesn't. I'm currently running a git bisect between the two versions to figure out what caused the problem as accurately as I can. Might take a while though.

[gh2k]

I would have myself a bunch of time by testing master first. :derp:

Looks like a739623 introduced this problem and it's fixed by c3cb7fe.
So, looks like it will be OK in 1.1.3

Edit: I'm talking rubbish, sorry..

a739623 is the commit that breaks things, but it's not fixed in Master as I suggested. I did something daft when trying to test that.

I managed to get it working in master by pulling provisioner/windows-restart/provisioner.go from a build before the problem commit. e.g. https://github.com/hashicorp/packer/blob/e5c59468/provisioner/windows-restart/provisioner.go - That works.

[SwampDragons]

Thanks for going to all the work of that bisect. I made a PR reverting the change you think is the issue: #5672 While still keeping the code that was the main intent of the original PR associated with the bad commit. Can you try that patch out and let me know if it fixes things?

[gh2k]

Yep, that works fine, @SwampDragons