vagrant up hangs #884

Closed
gibo opened this Issue Apr 15, 2012 · 4 comments

Projects

None yet

5 participants

@gibo
gibo commented Apr 15, 2012

I'm running a fresh install of OSX 10.7.3 on a Intel Core 2 Duo.
Virtual Box 4.1.12
Ruby 1.9.3
Latest version of Vagrant

I've added lucid32 and then ran vagrant up, at this point, I get the message 'Waiting for VM to boot. This may take a few minutes' and vagrant seems to hang.

Virtual Box says the machine is running.

Below is the Vagrant log (Sorry I can't give anymore info!).

INFO global: Vagrant version: 1.0.2
INFO vagrant: vagrant invoked: ["up"]
INFO environment: Environment initialized (#Vagrant::Environment:0x007fdb5388c300)
INFO environment: - cwd: /Users/gibo/workspace
INFO environment: Home path: /Users/gibo/.vagrant.d
INFO plugin: Searching and loading any available plugins...
INFO plugin: Loaded 0 plugins.
INFO environment: Loading configuration...
INFO cli: CLI: [] "up" []
INFO datastore: Created: /Users/gibo/workspace/.vagrant
INFO virtualbox_base: VBoxManage path: VBoxManage
INFO subprocess: Starting process: ["VBoxManage", "--version"]
INFO virtualbox: Using VirtualBox driver: Vagrant::Driver::VirtualBox_4_1
INFO virtualbox_base: VBoxManage path: VBoxManage
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de"]
INFO vm: Loading guest: linux
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO up: Booting: default
INFO interface: info: VM already created. Booting if it's not already running...
[default] VM already created. Booting if it's not already running...
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO hosts: Host class: Vagrant::Hosts::BSD
INFO runner: Running action: start
INFO warden: Calling action: #Vagrant::Action::General::CheckVirtualbox:0x007fdb5390c708
INFO subprocess: Starting process: ["VBoxManage", "list", "hostonlyifs"]
INFO warden: Calling action: #Vagrant::Action::General::Validate:0x007fdb5390c6b8
INFO warden: Calling action: #Vagrant::Action::VM::CheckAccessible:0x007fdb5390c690
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO warden: Calling action: #Vagrant::Action::VM::CleanMachineFolder:0x007fdb5390c5f0
INFO subprocess: Starting process: ["VBoxManage", "list", "systemproperties"]
INFO warden: Calling action: #Vagrant::Action::VM::ClearForwardedPorts:0x007fdb5390c578
INFO interface: info: Clearing any previously set forwarded ports...
[default] Clearing any previously set forwarded ports...
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "modifyvm", "de0d3366-4f87-4398-b266-1fe54eb737de", "--natpf1", "delete", "ssh"]
INFO warden: Calling action: #Vagrant::Action::Env::Set:0x007fdb5390c528
INFO warden: Calling action: #Vagrant::Action::VM::CheckPortCollisions:0x007fdb5390c4d8
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "list", "vms"]
INFO warden: Calling action: #Vagrant::Action::VM::ForwardPorts:0x007fdb5390c460
INFO interface: info: Forwarding ports...
[default] Forwarding ports...
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO interface: info: -- 22 => 2222 (adapter 1)
[default] -- 22 => 2222 (adapter 1)
INFO subprocess: Starting process: ["VBoxManage", "modifyvm", "de0d3366-4f87-4398-b266-1fe54eb737de", "--natpf1", "ssh,tcp,,2222,,22"]
INFO warden: Calling action: #Vagrant::Action::VM::Provision:0x007fdb5390c438
INFO warden: Calling action: #Vagrant::Action::VM::PruneNFSExports:0x007fdb539bace0
INFO subprocess: Starting process: ["VBoxManage", "list", "vms"]
INFO warden: Calling action: #Vagrant::Action::VM::NFS:0x007fdb539baba0
INFO warden: Calling action: #Vagrant::Action::VM::ClearSharedFolders:0x007fdb54024860
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "sharedfolder", "remove", "de0d3366-4f87-4398-b266-1fe54eb737de", "--name", "v-root"]
INFO warden: Calling action: #Vagrant::Action::VM::ShareFolders:0x007fdb54024838
INFO interface: info: Creating shared folders metadata...
[default] Creating shared folders metadata...
INFO subprocess: Starting process: ["VBoxManage", "sharedfolder", "add", "de0d3366-4f87-4398-b266-1fe54eb737de", "--name", "v-root", "--hostpath", "/Users/gibo/workspace"]
INFO warden: Calling action: #Vagrant::Action::VM::HostName:0x007fdb54055a50
INFO warden: Calling action: #Vagrant::Action::VM::ClearNetworkInterfaces:0x007fdb54055a28
INFO interface: info: Clearing any previously set network interfaces...
[default] Clearing any previously set network interfaces...
INFO subprocess: Starting process: ["VBoxManage", "modifyvm", "de0d3366-4f87-4398-b266-1fe54eb737de", "--nic2", "none", "--nic3", "none", "--nic4", "none", "--nic5", "none", "--nic6", "none", "--nic7", "none", "--nic8", "none"]
INFO warden: Calling action: #Vagrant::Action::VM::Network:0x007fdb54055a00
INFO warden: Calling action: #Vagrant::Action::VM::SaneDefaults:0x007fdb540874d8
INFO subprocess: Starting process: ["VBoxManage", "storagectl", "de0d3366-4f87-4398-b266-1fe54eb737de", "--name", "SATA Controller", "--hostiocache", "on"]
INFO sanedefaults: Enabling the Host I/O cache on the SATA controller... (exit status = 0)
INFO subprocess: Starting process: ["VBoxManage", "modifyvm", "de0d3366-4f87-4398-b266-1fe54eb737de", "--natdnsproxy1", "on"]
INFO sanedefaults: Enable the NAT DNS proxy on adapter 1... (exit status = 0)
INFO warden: Calling action: #Vagrant::Action::VM::Customize:0x007fdb53b48698
INFO warden: Calling action: #Vagrant::Action::VM::Boot:0x007fdb53b485d0
INFO interface: info: Booting VM...
[default] Booting VM...
INFO subprocess: Starting process: ["VBoxManage", "startvm", "de0d3366-4f87-4398-b266-1fe54eb737de", "--type", "headless"]
INFO interface: info: Waiting for VM to boot. This can take a few minutes.
[default] Waiting for VM to boot. This can take a few minutes.
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "de0d3366-4f87-4398-b266-1fe54eb737de", "--machinereadable"]
INFO ssh: Connecting to SSH: 127.0.0.1:2222

@frankscholten

I am having a similar problem with Vagrant 1.0.2, Ubuntu 11.10, Ruby 1.7.8 and Virtualbox 4.1.2_Ubuntu

@mikkin
mikkin commented May 3, 2012

Same problem with vagrant 1.0.1 and vbox 4.1.10. Managed to capture some debug logs if it helps:

DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 32000
DEBUG subprocess: Exit status: 0
DEBUG virtualbox_4_1: - [1, "ssh", 2222, 22]
DEBUG ssh: Checking key permissions: /Users/ogodson/Development/vagrant-dev-environment/manifests/files/home/vagrant/.ssh/id_rsa
DEBUG ssh: Checking key permissions: /Users/ogodson/Development/vagrant-dev-environment/manifests/files/home/vagrant/.ssh/id_rsa
INFO ssh: Connecting to SSH: 127.0.0.1:2222
INFO ssh: SSH not up: #<Timeout::Error: execution expired>
DEBUG ssh: Checking whether SSH is ready...
DEBUG virtualbox_4_1: Searching for SSH port: 22
DEBUG virtualbox_4_1: read_forward_ports: uuid=c2f71fb2-b9b6-4e66-8ed9-1e1f448ba943 active_only=false
INFO subprocess: Starting process: ["VBoxManage", "showvminfo", "c2f71fb2-b9b6-4e66-8ed9-1e1f448ba943", "--machinereadable"]
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stdout: name="vagrant-dev-environment_1331834330"
ostype="Ubuntu_64"
UUID="c2f71fb2-b9b6-4e66-8ed9-1e1f448ba943"
CfgFile="/Users/ogodson/VirtualBox VMs/vagrant-dev-environment_1331834330/vagrant-dev-environment_1331834330.vbox"
SnapFldr="/Users/ogodson/VirtualBox VMs/vagrant-dev-environment_1331834330/Snapshots"
LogFldr="/Users/ogodson/VirtualBox VMs/vagrant-dev-environment_1331834330/Logs"
hardwareuuid="c2f71fb2-b9b6-4e66-8ed9-1e1f448ba943"
memory=2048
pagefusion="off"
vram=8
cpuexecutioncap=100
hpet="off"
chipset="piix3"
firmware="BIOS"
cpus=1
synthcpu="off"
bootmenu="messageandmenu"
boot1="disk"
boot2="dvd"
boot3="none"
boot4="none"
acpi="on"
ioapic="on"
pae="on"
biossystemtimeoffset=0
rtcuseutc="off"
hwvirtex="on"
hwvirtexexcl="off"
nestedpaging="on"
largepages="on"
vtxvpid="on"
VMState="running"
VMStateChangeTime="2012-04-28T00:21:33.172000000"
monitorcount=1
accelerate3d="off"
accelerate2dvideo="off"
teleporterenabled="off"
teleporterport=0
teleporteraddress=""
teleporterpassword=""
storagecontrollername0="IDE Controller"
storagecontrollertype0="PIIX4"
storagecontrollerinstance0="0"
storagecontrollermaxportcount0="2"
storagecontrollerportcount0="2"
storagecontrollerbootable0="on"
storagecontrollername1="SATA Controller"
storagecontrollertype1="IntelAhci"
storagecontrollerinstance1="0"
storagecontrollermaxportcount1="30"
storagecontrollerportcount1="30"
storagecontrollerbootable1="on"
"IDE Controller-0-0"="none"
"IDE Controller-0-1"="none"
"IDE Controller-1-0"="emptydrive"
"IDE Controller-IsEjected"="off"
"IDE Controller-1-1"="none"
"SATA Controller-0-0"="/Users/ogodson/VirtualBox VMs/vagrant-dev-environment_1331834330/box-disk1.vmdk"
"SATA Controller-ImageUUID-0-0"="ce02845f-c877-4312-8256-a8782d30125d"
"SATA Controller-1-0"="none"
"SATA Controller-2-0"="none"
"SATA Controller-3-0"="none"
"SATA Controller-4-0"="none"
"SATA Controller-5-0"="none"
"SATA Controller-6-0"="none"
"SATA Controller-7-0"="none"
"SATA Controller-8-0"="none"
"SATA Controller-9-0"="none"
"SATA Controller-10-0"="none"
"SATA Controller-11-0"="none"
"SATA Controller-12-0"="none"
"SATA Controller-13-0"="none"
"SATA Controller-14-0"="none"
"SATA Controller-15-0"="none"
"SATA Controller-16-0"="none"
"SATA Controller-17-0"="none"
"SATA Controller-18-0"="none"
"SATA Controller-19-0"="none"
"SATA Controller-20-0"="none"
"SATA Controller-21-0"="none"
"SATA Controller-22-0"="none"
"SATA Controller-23-0"="none"
"SATA Controller-24-0"="none"
"SATA Controller-25-0"="none"
"SATA Controller-26-0"="none"
"SATA Controller-27-0"="none"
"SATA Controller-28-0"="none"
"SATA Controller-29-0"="none"
natnet1="nat"
macaddress1="080027D0C990"
cableconnected1="on"
nic1="nat"
mtu="0"
sockSnd="64"
sockRcv="64"
tcpWndSnd="64"
tcpWndRcv="64"
Forwarding(0)="ssh,tcp,,2222,,22"
hostonlyadapter2="vboxnet0"
macaddress2="08002790945F"
cableconnected2="on"
nic2="hostonly"
nic3="none"
nic4="none"
nic5="none"
nic6="none"
nic7="none"
nic8="none"
hidpointing="ps2mouse"
hidkeyboard="ps2kbd"
uart1="off"
uart2="off"
audio="none"
clipboard="bidirectional"
VideoMode="720,400,0"
vrde="off"
usb="off"
SharedFolderNameMachineMapping1="v-root"
SharedFolderPathMachineMapping1="/Users/ogodson/Development/vagrant-dev-environment"
SharedFolderNameMachineMapping2="manifests"
SharedFolderPathMachineMapping2="/Users/ogodson/Development/vagrant-dev-environment/manifests"
VRDEActiveConnection="off"
VRDEClients=0
GuestMemoryBalloon=0
GuestOSType="Linux26_64"
GuestAdditionsRunLevel=2
GuestAdditionsVersion="4.1.10r76795"
GuestAdditionsFacility_VirtualBox Base Driver=50,1335572517108
GuestAdditionsFacility_VirtualBox System Service=50,1335572533003
GuestAdditionsFacility_Seamless Mode=0,1335572517108
GuestAdditionsFacility_Graphics Mode=0,1335572517107

@mitchellh
Owner

This looks like #391 rearing its ugly head again. :( #391

@mitchellh mitchellh closed this May 5, 2012
@willdurand
Contributor

@mitchellh I guess this is not related to #391.

I experienced the same issue and it was a controller issue.

Host: VirtualBox 4.0 on a Debian stable (squeeze 32), vagrant 1.0.5
Box: Ubuntu Lucid32

To be more precise, I tried to boot the image using VirtualBox GUI. I used the vmdk file and created a new machine. Nothing was related to vagrant here. So I configured all the stuff and started the machine.

It failed and an initramfs prompt has been displayed. Most of the time, this appears because no disk can be found.

That's why I tried to change the disk controller, I removed the SATA controller and attached the disk to the IDE controller. With this configuration, I was able to boot the image, and to log in. \o/

I made a change in the odf file of the box (.vagrant.d/boxes/lucid32/box.odf) to change the configuration. I attached the disk to the IDE controller instead of the SATA controller (by changing the parent attribute number).

Back to vagrant, I was able to boot the VM.

As you can't really tell people to edit the odf file themselves, and because this box works in some cases, I think we can state 2 things:

  • boxes are not fully portable;
  • tools you use to create a box can affect its behavior.

I noticed you used Mac OSX and VirtualBox 4.2 to create the lucid32 box. That could be the cause.

A solution could be to use the config.vm.customize configuration parameter to automatically fix this SATA/IDE issue. Read how here: https://groups.google.com/forum/?fromgroups#!topic/vagrant-up/PV2dDVv1h8U.

Thank you.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment