Packer VirtualBox builds failing under macOS High Sierra 10.13.2

[geerlingguy]

So, super strange thing: I can't build this box—or any of my other Debian/Ubuntu boxes, for that matter—on my work laptop, running macOS 10.13.2. So far I've only debugged on that laptop, running both VirtualBox 5.2.4 and VirtualBox 5.1.30, along with both Packer 1.0.3, and 1.1.3.

For some reason, Packer itself is really slow no matter the version, so I'm wondering if there's something on the system hindering the build.

The boot_command was highly suspect (Ubuntu's always done weird things with it anyways...), because for some reason in one case the installer would drop to a blank screen (nothing on it), and then eventually it would drop back to language selection.

In other cases (playing with the <esc><wait><f6><wait> etc game in the beginning of the boot_command), I would get a popup for 'exit to the console installer' over and over again. Very odd behavior.

So using PACKER_LOG=1 packer build --only=virtualbox-iso ubuntu1604.json, I found that just using the following boot_command:

  "builders": [
    {
      "type": "virtualbox-iso",
      "boot_command": [
        "<enter>"
      ],
      ...

I would get the following output in the console on my host:

2017/12/24 22:59:49 ui: ==> virtualbox-iso: Typing the boot command...
==> virtualbox-iso: Typing the boot command...
2017/12/24 22:59:49 packer: 2017/12/24 22:59:49 Special code '<enter>' found, replacing with: [1c 9c]
2017/12/24 22:59:49 packer: 2017/12/24 22:59:49 Executing VBoxManage: []string{"controlvm", "packer-ubuntu-16.04-amd64", "keyboardputscancode", "1c"}
2017/12/24 22:59:52 packer: 2017/12/24 22:59:52 stdout:
2017/12/24 22:59:52 packer: 2017/12/24 22:59:52 stderr:
2017/12/24 22:59:52 packer: 2017/12/24 22:59:52 Executing VBoxManage: []string{"controlvm", "packer-ubuntu-16.04-amd64", "keyboardputscancode", "9c"}
2017/12/24 22:59:55 packer: 2017/12/24 22:59:55 stdout:
2017/12/24 22:59:55 packer: 2017/12/24 22:59:55 stderr:
2017/12/24 22:59:55 packer: 2017/12/24 22:59:55 [INFO] Waiting for SSH, up to timeout: 2h46m40s
2017/12/24 22:59:55 ui: ==> virtualbox-iso: Waiting for SSH to become available...
==> virtualbox-iso: Waiting for SSH to become available...

...but when switching off headless mode (so I could see the GUI), here's what I saw:

[geerlingguy]

So super strange thing, too...

1c 9c is the keydown + keyup for the enter key... and if I run the following commands myself after going back to the installer main menu in the running vm:

VBoxManage controlvm packer-ubuntu-16.04-amd64 keyboardputscancode 1c
VBoxManage controlvm packer-ubuntu-16.04-amd64 keyboardputscancode 9c

Then it proceeds with installation and gets ready for the preseed file... so something's going funny with the interpretation of the keycodes, but only when they come from Packer. Maybe my terminal environment is jacking up the text somehow??

[geerlingguy]

I'm dropping my own .bash_profile customizations in a new shell, and will see if this makes any difference. Could there be some other text encoding going on between Packer and the shell?

[geerlingguy]

Don't know if this is related in any way, but hashicorp/packer#2855.

I'm switching way back to Packer 0.12.2, which I know has worked on this particular computer in the past, and will see if there's any positive difference. Next test will be running the exact same config on my personal laptop (same config, same OS, different hardware).

And if that doesn't work, I'll try it on Fedora. If that doesn't work, Windows... gotta find somewhere this works.

[geerlingguy]

Also, right when the commands are passed, while watching Apple's Console app, I see the message:

VirtualBoxVM (LaunchServices)
LSExceptions shared instance invalidated for timeout.

And a second before that some messages like:

IOHIDDeviceClass::start: elementCount=16 reportHandlerCount=4
IOHIDDeviceClass::buildElements: type=0 *buffer=7f91cb881030 *count=16 size=1536
IOHIDDeviceClass::buildElements: type=1 *buffer=7f91cc4334c0 *count=4 size=384
IOHIDDeviceClass::start: elementCount=16 reportHandlerCount=4
IOHIDDeviceClass::buildElements: type=0 *buffer=7f91cb882a30 *count=16 size=1536
IOHIDDeviceClass::buildElements: type=1 *buffer=7f91cc42d410 *count=4 size=384

And interestingly, a few of these:

Month 13 is out of bounds

Then a little later,

process VirtualBoxVM[98010] caught waking the CPU 45002 times over ~123 seconds, averaging 363 wakes / second and violating a limit of 45000 wakes over 300 seconds.

[geerlingguy]

Trying Packer 1.1.3 with Virtualbox latest dev build 5.2.97 (119762 - from https://www.virtualbox.org/wiki/Testbuilds)

[geerlingguy]

Hmm, found this in the VirtualBox log (in the VM folder, in my case ~/VirtualBox VMs/[vm name]/Logs/VBox.log):

00:00:11.806103 VMMDev: Guest Log: BIOS: KBD: unsupported int 16h function 03
00:00:11.806513 VMMDev: Guest Log: BIOS: AX=0305 BX=0000 CX=0000 DX=0000

Found https://www.virtualbox.org/ticket/8058, but it doesn't seem necessarily related... checking all the created VM settings seems to indicate things are set up correctly.

Edit—here is the entire log for the moment when Packer sends across its VBoxManage commands:

00:00:26.162049 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0
00:00:26.162147 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=720x400, Sending to async-handler
00:00:26.162250 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=720x400
00:00:26.162275 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=720x400
00:00:26.162299 GUI: UIFrameBufferPrivate::performResize: Size=720x400, Directly using source bitmap content
00:00:26.183826 VMMDev: Guest Log: BIOS: KBD: unsupported int 16h function 03
00:00:26.184427 VMMDev: Guest Log: BIOS: AX=0305 BX=0000 CX=0000 DX=0000 
00:00:26.301884 Display::handleDisplayResize: uScreenId=0 pvVRAM=000000010cc0a000 w=800 h=600 bpp=16 cbLine=0x640 flags=0x0
00:00:26.302015 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=800x600, Sending to async-handler
00:00:26.302100 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=800x600
00:00:26.302116 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=800x600
00:00:26.302140 GUI: UIFrameBufferPrivate::performResize: Size=800x600, Directly using source bitmap content
00:00:26.394941 GIM: KVM: VCPU  0: Enabled system-time struct. at 0x000000003f261000 - u32TscScale=0xa5294a52 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x12000b7243 uVirtNanoTS=0x5ce774fab
00:00:26.395039 TM: Switching TSC mode from 'Dynamic' to 'RealTscOffset'
00:00:26.438018 GIM: KVM: Enabled wall-clock struct. at 0x0000000002104128 - u32Sec=1514181053 u32Nano=936691000 uVersion=2
00:00:26.438398 PIT: mode=2 count=0x12a5 (4773) - 249.98 Hz (ch=0)
00:00:26.500581 APIC0: Switched mode to x2APIC
00:00:26.603602 PIT: mode=0 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:26.857651 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=1 CmdIf0=0xc4 (-1 usec ago) CmdIf1=0xa0 (-1 usec ago)
00:00:26.857807 PIIX3 ATA: Ctl#0: finished processing RESET
00:00:26.860482 PIIX3 ATA: Ctl#1: RESET, DevSel=0 AIOIf=0 CmdIf0=0x00 (-1 usec ago) CmdIf1=0x00 (-1 usec ago)
00:00:26.860603 PIIX3 ATA: Ctl#1: finished processing RESET

And here is the same log, for when I execute the command myself:

00:00:35.032836 Display::handleDisplayResize: uScreenId=0 pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0 flags=0x0
00:00:35.032923 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=720x400, Sending to async-handler
00:00:35.033020 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=720x400
00:00:35.033056 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=720x400
00:00:35.033091 GUI: UIFrameBufferPrivate::performResize: Size=720x400, Directly using source bitmap content
00:00:35.067493 VMMDev: Guest Log: BIOS: KBD: unsupported int 16h function 03
00:00:35.067925 VMMDev: Guest Log: BIOS: AX=0305 BX=0000 CX=0000 DX=0000 
00:00:35.162004 Display::handleDisplayResize: uScreenId=0 pvVRAM=000000010e131000 w=800 h=600 bpp=16 cbLine=0x640 flags=0x0
00:00:35.162091 GUI: UIFrameBufferPrivate::NotifyChange: Screen=0, Origin=0x0, Size=800x600, Sending to async-handler
00:00:35.162175 GUI: UIMachineView::sltHandleNotifyChange: Screen=0, Size=800x600
00:00:35.162199 GUI: UIFrameBufferPrivate::handleNotifyChange: Size=800x600
00:00:35.162227 GUI: UIFrameBufferPrivate::performResize: Size=800x600, Directly using source bitmap content
00:00:35.251607 GIM: KVM: VCPU  0: Enabled system-time struct. at 0x000000003f261000 - u32TscScale=0xa5294a52 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x1869942fdd uVirtNanoTS=0x7dffed70b
00:00:35.251654 TM: Switching TSC mode from 'Dynamic' to 'RealTscOffset'
00:00:35.286199 GIM: KVM: Enabled wall-clock struct. at 0x0000000002104128 - u32Sec=1514181305 u32Nano=661552000 uVersion=2
00:00:35.286358 PIT: mode=2 count=0x12a5 (4773) - 249.98 Hz (ch=0)
00:00:35.349480 APIC0: Switched mode to x2APIC
00:00:35.454856 PIT: mode=0 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:00:35.709018 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=1 CmdIf0=0xc4 (-1 usec ago) CmdIf1=0xa0 (-1 usec ago)
00:00:35.709123 PIIX3 ATA: Ctl#0: finished processing RESET
00:00:35.711001 PIIX3 ATA: Ctl#1: RESET, DevSel=0 AIOIf=0 CmdIf0=0x00 (-1 usec ago) CmdIf1=0x00 (-1 usec ago)
00:00:35.711090 PIIX3 ATA: Ctl#1: finished processing RESET

Diff:

-Display::handleDisplayResize: uScreenId=0 pvVRAM=000000010e131000 w=800 h=600 bpp=16 cbLine=0x640 flags=0x0
+Display::handleDisplayResize: uScreenId=0 pvVRAM=000000010cc0a000 w=800 h=600 bpp=16 cbLine=0x640 flags=0x0
...
-GIM: KVM: VCPU  0: Enabled system-time struct. at 0x000000003f261000 - u32TscScale=0xa5294a52 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x1869942fdd uVirtNanoTS=0x7dffed70b
+GIM: KVM: VCPU  0: Enabled system-time struct. at 0x000000003f261000 - u32TscScale=0xa5294a52 i8TscShift=-1 uVersion=2 fFlags=0x1 uTsc=0x12000b7243 uVirtNanoTS=0x5ce774fab
...
-GIM: KVM: Enabled wall-clock struct. at 0x0000000002104128 - u32Sec=1514181305 u32Nano=661552000 uVersion=2
+GIM: KVM: Enabled wall-clock struct. at 0x0000000002104128 - u32Sec=1514181053 u32Nano=936691000 uVersion=2

Nothing interesting there; though running both 1c and 9c resulted in the exact same on-screen behavior as I noticed when Packer ran it. I'm going to try just 1c (return key down, without the up) and see if it's any different.

[geerlingguy]

Strange, if I just hit 1c... but not 9c, then the install starts going—but I think that's because it keeps hitting enter on the 'install ubuntu' screen then every dialog that comes afterwards.

Okay, changing the game a bit and will try on another computer.

[geerlingguy]

Welp.

Ran it on my personal laptop. Same exact versions of everything... and no issues whatsoever.

I wonder if the work laptop has some sort of networking or other kind of proxying system installed that's screwing with commands and VirtualBox? Maybe some cache somewhere?

Well, since I can't reproduce this issue on another computer, I'm probably going to wipe my work laptop and reinstall. Probably faster to do that (~3-4 hours, all automated) than debug exactly where this error is coming from.

[aspyatkin]

Hello, did you manage to resolve this problem?
I am facing the same problem - can't build Ubuntu 16.04 images with recent versions of Packer (1.1.3), Virtualbox (5.2.4), macOS 10.13.2. For some reason it just quits console mode installation and shows the same "Select language" window as in the screenshot above. Tried different boot commands from several packer template repositories, with no luck at all. I clearly remember I was able to build an image using Virtualbox 5.1.24 and Packer 1.0.3 (template).

Also noticed packer slowness. Might it be due to meltdown and spectre patches or something like that?