packer 0.12.1 VirtualBox builder uses wrong WinRM port.

[StefanScherer]

Building a Windows Server 2016 guest with the VirtualBox builder does not work with Packer 0.12.1 using WinRM. It seems that packer tries the wrong port instead of its calculated port mapping.

• Packer version from packer version
  0.12.1

• Host platform
  MacOS Sierra 10.12.2

• VirtualBox version 5.1.12

• Debug log output from PACKER_LOG=1 packer build template.json.

Just the relevant part retrieving port 2683 for the port mapping and then trying to connect to 127.0.0.1:5985 WinRM port:

016/12/21 21:12:54 packer: 2016/12/21 21:12:54 Looking for available communicator (SSH, WinRM, etc) port between 2222 and 4444
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 Trying port: 2683
2016/12/21 21:12:54 ui: ==> virtualbox-iso: Creating forwarded port mapping for communicator (SSH, WinRM, etc) (host port 2683)
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 Executing VBoxManage: []string{"modifyvm", "WindowsServer2016Docker", "--natpf1", "packercomm,tcp,127.0.0.1,2683,,5985"}
==> virtualbox-iso: Creating forwarded port mapping for communicator (SSH, WinRM, etc) (host port 2683)
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 stdout:
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 stderr:
2016/12/21 21:12:54 ui: ==> virtualbox-iso: Executing custom VBoxManage commands...
==> virtualbox-iso: Executing custom VBoxManage commands...
2016/12/21 21:12:54 ui:     virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --memory 2048
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 Executing VBoxManage: []string{"modifyvm", "WindowsServer2016Docker", "--memory", "2048"}
    virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --memory 2048
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 stdout:
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 stderr:
2016/12/21 21:12:54 ui:     virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --cpus 2
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 Executing VBoxManage: []string{"modifyvm", "WindowsServer2016Docker", "--cpus", "2"}
    virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --cpus 2
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 stdout:
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 stderr:
2016/12/21 21:12:54 ui: ==> virtualbox-iso: Starting the virtual machine...
2016/12/21 21:12:54 packer: 2016/12/21 21:12:54 Executing VBoxManage: []string{"startvm", "WindowsServer2016Docker", "--type", "gui"}
==> virtualbox-iso: Starting the virtual machine...
2016/12/21 21:12:55 packer: 2016/12/21 21:12:55 stdout: Waiting for VM "WindowsServer2016Docker" to power on...
2016/12/21 21:12:55 packer: VM "WindowsServer2016Docker" has been successfully started.
2016/12/21 21:12:55 packer: 2016/12/21 21:12:55 stderr:
2016/12/21 21:12:55 ui: ==> virtualbox-iso: Waiting 2m0s for boot...
==> virtualbox-iso: Waiting 2m0s for boot...
==> virtualbox-iso: Typing the boot command...
2016/12/21 21:14:55 ui: ==> virtualbox-iso: Typing the boot command...
2016/12/21 21:14:55 packer: 2016/12/21 21:14:55 Waiting for WinRM, up to timeout: 6h0m0s
2016/12/21 21:14:55 ui: ==> virtualbox-iso: Waiting for WinRM to become available...
==> virtualbox-iso: Waiting for WinRM to become available...
2016/12/21 21:15:00 packer: 2016/12/21 21:15:00 [INFO] Attempting WinRM connection...
2016/12/21 21:15:00 packer: 2016/12/21 21:15:00 [DEBUG] connecting to remote shell using WinRM
2016/12/21 21:15:30 packer: 2016/12/21 21:15:30 [ERROR] connection error: unknown error Post http://127.0.0.1:5985/wsman: EOF
2016/12/21 21:15:30 packer: 2016/12/21 21:15:30 [ERROR] WinRM connection err: unknown error Post http://127.0.0.1:5985/wsman: EOF
2016/12/21 21:15:35 packer: 2016/12/21 21:15:35 [INFO] Attempting WinRM connection...
2016/12/21 21:15:35 packer: 2016/12/21 21:15:35 [DEBUG] connecting to remote shell using WinRM
2016/12/21 21:16:05 packer: 2016/12/21 21:16:05 [ERROR] connection error: unknown error Post http://127.0.0.1:5985/wsman: EOF
2016/12/21 21:16:05 packer: 2016/12/21 21:16:05 [ERROR] WinRM connection err: unknown error Post http://127.0.0.1:5985/wsman: EOF

• The simplest example template and scripts needed to reproduce the bug.

git clone https://github.com/StefanScherer/packer-windows
cd packer-windows
packer build --only virtualbox-iso windows_2016_docker.json

It's just a normal Windows guest template which worked with older versions of packer.

Here is also a screenshot of a previsous build where I tried the WinRM port manually with the go winrm cli:

I tried to peek into the source base and found at least builder/virtualbox/common/step_forward_ssh.go which saves the port in sshHostPort which probably should be read at some other point to set the WinRM port correctly.

	// Save the port we're using so that future steps can use it
	state.Put("sshHostPort", sshHostPort)

[rickard-von-essen]

I agree with your description, but according to the change log we have no changes close to this area in 0.12.1. Can you verify that it works correctly with 0.12.0?

[damphyr]

I can verify that it works with 0.10.x but fails on 0.12.x trying to build a VirtualBox Vagrant basebox with Win7 and Win10.

[StefanScherer]

I'll try. My packer virtualbox build just has "entered" my other running VMware Fusion Vagrant VM which had port 5985 mapped to the host :-)

[StefanScherer]

It seems to work with 0.12.0. This log looks promising, guest is not ready for WinRM, but packer tries the correct port:

2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 Looking for available communicator (SSH, WinRM, etc) port between 2222 and 4444
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 Trying port: 3386
2016/12/21 22:57:48 ui: ==> virtualbox-iso: Creating forwarded port mapping for communicator (SSH, WinRM, etc) (host port 3386)
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 Executing VBoxManage: []string{"modifyvm", "WindowsServer2016Docker", "--natpf1", "packercomm,tcp,127.0.0.1,3386,,5985"}
==> virtualbox-iso: Creating forwarded port mapping for communicator (SSH, WinRM, etc) (host port 3386)
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 stdout:
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 stderr:
2016/12/21 22:57:48 ui: ==> virtualbox-iso: Executing custom VBoxManage commands...
==> virtualbox-iso: Executing custom VBoxManage commands...
2016/12/21 22:57:48 ui:     virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --memory 2048
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 Executing VBoxManage: []string{"modifyvm", "WindowsServer2016Docker", "--memory", "2048"}
    virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --memory 2048
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 stdout:
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 stderr:
2016/12/21 22:57:48 ui:     virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --cpus 2
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 Executing VBoxManage: []string{"modifyvm", "WindowsServer2016Docker", "--cpus", "2"}
    virtualbox-iso: Executing: modifyvm WindowsServer2016Docker --cpus 2
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 stdout:
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 stderr:
2016/12/21 22:57:48 ui: ==> virtualbox-iso: Starting the virtual machine...
==> virtualbox-iso: Starting the virtual machine...
2016/12/21 22:57:48 packer: 2016/12/21 22:57:48 Executing VBoxManage: []string{"startvm", "WindowsServer2016Docker", "--type", "gui"}
2016/12/21 22:57:50 packer: 2016/12/21 22:57:50 stdout: Waiting for VM "WindowsServer2016Docker" to power on...
2016/12/21 22:57:50 packer: VM "WindowsServer2016Docker" has been successfully started.
2016/12/21 22:57:50 packer: 2016/12/21 22:57:50 stderr:
2016/12/21 22:57:50 ui: ==> virtualbox-iso: Waiting 2m0s for boot...
==> virtualbox-iso: Waiting 2m0s for boot...
==> virtualbox-iso: Typing the boot command...
2016/12/21 22:59:50 ui: ==> virtualbox-iso: Typing the boot command...
2016/12/21 22:59:50 packer: 2016/12/21 22:59:50 Waiting for WinRM, up to timeout: 6h0m0s
2016/12/21 22:59:50 ui: ==> virtualbox-iso: Waiting for WinRM to become available...
==> virtualbox-iso: Waiting for WinRM to become available...
2016/12/21 22:59:55 packer: 2016/12/21 22:59:55 [INFO] Attempting WinRM connection...
2016/12/21 22:59:55 packer: 2016/12/21 22:59:55 [DEBUG] connecting to remote shell using WinRM
2016/12/21 23:01:10 packer: 2016/12/21 23:01:10 [ERROR] connection error: unknown error Post http://127.0.0.1:3386/wsman: EOF
2016/12/21 23:01:10 packer: 2016/12/21 23:01:10 [ERROR] WinRM connection err: unknown error Post http://127.0.0.1:3386/wsman: EOF
2016/12/21 23:01:15 packer: 2016/12/21 23:01:15 [INFO] Attempting WinRM connection...
2016/12/21 23:01:15 packer: 2016/12/21 23:01:15 [DEBUG] connecting to remote shell using WinRM

[DanHam]

This bug appears to have been introduced by PR #2576. This changed the way the WinRM port was set in helper/communicator/step_connect.go which unfortunately broke things for the Virtualbox iso builder. The ovf builder should also be affected in the same way.

I've tested a fix that should align the Virtualbox builders with the new way of doing things introduced by PR #2576 and issued a PR - #4321

[StefanScherer]

Thanks for the help

[rickard-von-essen]

@DanHam Great!