vagrant
vagrant copied to clipboard
vagrant up stuck
Debug output
==> debian-10: Importing base box 'bento/debian-10'...
==> debian-10: Matching MAC address for NAT networking...
==> debian-10: Setting the name of the VM: debian_debian-10_1670832348597_50011
==> debian-10: Fixed port collision for 22 => 2222. Now on port 2200.
==> debian-10: Clearing any previously set network interfaces...
==> debian-10: Preparing network interfaces based on configuration...
debian-10: Adapter 1: nat
debian-10: Adapter 2: hostonly
==> debian-10: Forwarding ports...
debian-10: 22 (guest) => 2200 (host) (adapter 1)
==> debian-10: Running 'pre-boot' VM customizations...
==> debian-10: Booting VM...
==> debian-10: Waiting for machine to boot. This may take a few minutes...
debian-10: SSH address: 127.0.0.1:2200
debian-10: SSH username: vagrant
debian-10: SSH auth method: private key
Timed out while waiting for the machine to boot. This means that
Vagrant was unable to communicate with the guest machine within
the configured ("config.vm.boot_timeout" value) time period.
If you look above, you should be able to see the error(s) that
Vagrant had when attempting to connect to the machine. These errors
are usually good hints as to what may be wrong.
If you're using a custom box, make sure that networking is properly
working and you're able to connect to the machine. It is a common
problem that networking isn't setup properly in these boxes.
Verify that authentication configurations are also setup properly,
as well.
If the box appears to be booting properly, you may want to increase
the timeout ("config.vm.boot_timeout") value.
Expected behavior
debian10 startup
Actual behavior
It's stuck
Reproduction information
vagrant up
Vagrant version
Vagrant 2.3.4
Host operating system
macos 10.15.7
Guest operating system
bento/debian-10
Steps to reproduce
-
vagrant up
Vagrantfile
Vagrant.configure("2") do |config|
config.vm.define "debian-10"
config.vm.hostname = "debian.local"
config.vm.box = "bento/debian-10"
config.vm.box_check_update = false
config.vm.network "private_network", ip: "192.168.56.170"
config.vm.provider "virtualbox" do |vb|
vb.memory = "4096"
vb.cpus = 4
end
end
I started having this issue recently, although I'm not sure if it is related due to our differing systems. In my case this happens on Windows 11 with an Ubuntu 20.04 guest.
When watching the machine boot via the screen in VirtualBox I can see it stalling on the line xor: measuring software checksum speed
. This happens probably 2 out of 3 times when starting vagrant lately and I haven't figured out why.
In order to get more information about your case, I recommend opening VirtualBox & after you run vagrant up
press the "show" button for the machine to see exactly where yours is stalling out. It will help you troubleshoot if there's more specific detail on what the guest is doing when vagrant times out.
Hi there,
What version of virtualbox are you using? If you could also provide a gist of the output from running vagrant up --debug
that would be helpful as well.
Thanks!
@chrisroberts virtualbox: 7.0.4,154605
INFO ssh: Attempting SSH connection...
INFO ssh: Attempting to connect to SSH...
INFO ssh: - Host: 127.0.0.1
INFO ssh: - Port: 2222
INFO ssh: - Username: vagrant
INFO ssh: - Password? false
INFO ssh: - Key Path: ["/Users/goalidea/.vagrant.d/insecure_private_key"]
DEBUG ssh: - connect_opts: {:auth_methods=>["none", "hostbased", "publickey"], :config=>false, :forward_agent=>false, :send_env=>false, :keys_only=>true, :verify_host_key=>:never, :password=>nil, :port=>2222, :timeout=>15, :user_known_hosts_file=>[], :verbose=>:debug, :logger=>#<Logger:0x00007fd48f580d20 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x00007fd48f580cf8 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x00007fd48f580ca8 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<StringIO:0x00007fd48f580d70>, @binmode=false, @mon_data=#<Monitor:0x00007fd48f580c80>, @mon_data_owner_object_id=153380>>, :keys=>["/Users/goalidea/.vagrant.d/insecure_private_key"], :remote_user=>"vagrant"}
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2022-12-17T09:52:54.231870 #1313] DEBUG -- net.ssh.transport.session[25738]: establishing connection to 127.0.0.1:2222
D, [2022-12-17T09:52:54.232195 #1313] DEBUG -- net.ssh.transport.session[25738]: connection established
I, [2022-12-17T09:52:54.232266 #1313] INFO -- net.ssh.transport.server_version[2574c]: negotiating protocol version
D, [2022-12-17T09:52:54.232281 #1313] DEBUG -- net.ssh.transport.server_version[2574c]: local is `SSH-2.0-Ruby/Net::SSH_7.0.1 x86_64-darwin19'
D, [2022-12-17T09:52:54.255739 #1313] DEBUG -- net.ssh.transport.server_version[2574c]: remote is `SSH-2.0-OpenSSH_7.9p1 Debian-10+deb10u2'
I, [2022-12-17T09:52:54.256043 #1313] INFO -- net.ssh.transport.algorithms[25760]: sending KEXINIT
D, [2022-12-17T09:52:54.256417 #1313] DEBUG -- socket[25774]: queueing packet nr 0 type 20 len 852
D, [2022-12-17T09:52:54.256481 #1313] DEBUG -- socket[25774]: sent 856 bytes
D, [2022-12-17T09:52:54.260056 #1313] DEBUG -- socket[25774]: read 1080 bytes
D, [2022-12-17T09:52:54.260266 #1313] DEBUG -- socket[25774]: received packet nr 0 type 20 len 1076
I, [2022-12-17T09:52:54.260299 #1313] INFO -- net.ssh.transport.algorithms[25760]: got KEXINIT from server
I, [2022-12-17T09:52:54.260385 #1313] INFO -- net.ssh.transport.algorithms[25760]: negotiating algorithms
D, [2022-12-17T09:52:54.260459 #1313] DEBUG -- net.ssh.transport.algorithms[25760]: negotiated:
* kex: ecdh-sha2-nistp521
* host_key: ssh-ed25519
* encryption_server: aes256-ctr
* encryption_client: aes256-ctr
* hmac_client: [email protected]
* hmac_server: [email protected]
* compression_client: none
* compression_server: none
* language_client:
* language_server:
D, [2022-12-17T09:52:54.260477 #1313] DEBUG -- net.ssh.transport.algorithms[25760]: exchanging keys
D, [2022-12-17T09:52:54.264234 #1313] DEBUG -- socket[25774]: queueing packet nr 1 type 30 len 148
D, [2022-12-17T09:52:54.264269 #1313] DEBUG -- socket[25774]: sent 152 bytes
D, [2022-12-17T09:52:54.268486 #1313] DEBUG -- socket[25774]: read 312 bytes
D, [2022-12-17T09:52:54.268604 #1313] DEBUG -- socket[25774]: received packet nr 1 type 31 len 292
D, [2022-12-17T09:52:54.271976 #1313] DEBUG -- socket[25774]: queueing packet nr 2 type 21 len 20
D, [2022-12-17T09:52:54.272034 #1313] DEBUG -- socket[25774]: sent 24 bytes
D, [2022-12-17T09:52:54.272066 #1313] DEBUG -- socket[25774]: received packet nr 2 type 21 len 12
D, [2022-12-17T09:52:54.272398 #1313] DEBUG -- net.ssh.authentication.session[25788]: beginning authentication of `vagrant'
D, [2022-12-17T09:52:54.272560 #1313] DEBUG -- socket[25774]: using encrypt-then-mac
D, [2022-12-17T09:52:54.272651 #1313] DEBUG -- socket[25774]: queueing packet nr 3 type 5 len 32
D, [2022-12-17T09:52:54.272732 #1313] DEBUG -- socket[25774]: sent 100 bytes
D, [2022-12-17T09:52:54.275944 #1313] DEBUG -- socket[25774]: read 100 bytes
D, [2022-12-17T09:52:54.276067 #1313] DEBUG -- socket[25774]: received packet nr 3 type 6 len 32
D, [2022-12-17T09:52:54.276135 #1313] DEBUG -- net.ssh.authentication.session[25788]: trying none
D, [2022-12-17T09:52:54.276216 #1313] DEBUG -- socket[25774]: using encrypt-then-mac
D, [2022-12-17T09:52:54.276271 #1313] DEBUG -- socket[25774]: queueing packet nr 4 type 50 len 48
D, [2022-12-17T09:52:54.276320 #1313] DEBUG -- socket[25774]: sent 116 bytes
D, [2022-12-17T09:52:54.294459 #1313] DEBUG -- socket[25774]: read 100 bytes
D, [2022-12-17T09:52:54.294623 #1313] DEBUG -- socket[25774]: received packet nr 4 type 51 len 32
D, [2022-12-17T09:52:54.294720 #1313] DEBUG -- net.ssh.authentication.session[25788]: allowed methods: publickey,password
D, [2022-12-17T09:52:54.295033 #1313] DEBUG -- net.ssh.authentication.methods.none[2579c]: none failed
D, [2022-12-17T09:52:54.295082 #1313] DEBUG -- net.ssh.authentication.session[25788]: trying publickey
D, [2022-12-17T09:52:54.295501 #1313] DEBUG -- net.ssh.authentication.agent[257b0]: connecting to ssh-agent
D, [2022-12-17T09:52:54.295625 #1313] DEBUG -- net.ssh.authentication.agent[257b0]: sending agent request 1 len 47
D, [2022-12-17T09:52:54.295745 #1313] DEBUG -- net.ssh.authentication.agent[257b0]: received agent packet 5 len 1
D, [2022-12-17T09:52:54.295772 #1313] DEBUG -- net.ssh.authentication.agent[257b0]: sending agent request 11 len 0
D, [2022-12-17T09:52:54.295884 #1313] DEBUG -- net.ssh.authentication.agent[257b0]: received agent packet 12 len 5
D, [2022-12-17T09:52:54.295967 #1313] DEBUG -- net.ssh.authentication.methods.publickey[257d8]: trying publickey (dd:3b:b8:2e:85:04:06:e9:ab:ff:a8:0a:c0:04:6e:d6)
D, [2022-12-17T09:52:54.296012 #1313] DEBUG -- socket[25774]: using encrypt-then-mac
D, [2022-12-17T09:52:54.296047 #1313] DEBUG -- socket[25774]: queueing packet nr 5 type 50 len 352
D, [2022-12-17T09:52:54.296073 #1313] DEBUG -- socket[25774]: sent 420 bytes
D, [2022-12-17T09:52:54.304590 #1313] DEBUG -- socket[25774]: read 372 bytes
D, [2022-12-17T09:52:54.304658 #1313] DEBUG -- socket[25774]: received packet nr 5 type 60 len 304
D, [2022-12-17T09:52:54.306332 #1313] DEBUG -- socket[25774]: using encrypt-then-mac
D, [2022-12-17T09:52:54.306364 #1313] DEBUG -- socket[25774]: queueing packet nr 6 type 50 len 640
D, [2022-12-17T09:52:54.306387 #1313] DEBUG -- socket[25774]: sent 708 bytes
D, [2022-12-17T09:52:54.326985 #1313] DEBUG -- socket[25774]: read 228 bytes
D, [2022-12-17T09:52:54.327057 #1313] DEBUG -- socket[25774]: received packet nr 6 type 53 len 160
I, [2022-12-17T09:52:54.327088 #1313] INFO -- net.ssh.authentication.session[25788]: "System is booting up. Unprivileged users are not permitted to log in yet. Please come back later. For technical details, see pam_nologin(8)."
D, [2022-12-17T09:52:54.330901 #1313] DEBUG -- socket[25774]: read 0 bytes
DEBUG ssh: == Net-SSH connection debug-level log END ==
INFO ssh: SSH not ready: #<Vagrant::Errors::SSHDisconnected: The SSH connection was unexpectedly closed by the remote end. This
usually indicates that SSH within the guest machine was unable to
properly start up. Please boot the VM in GUI mode to check whether
it is booting properly.>
INFO subprocess: Starting process: ["/usr/local/bin/VBoxManage", "showvminfo", "d216ed6b-1720-49b8-98f3-8dd7b9b8cb38", "--machinereadable"]
DEBUG subprocess: Command not in installer, not touching env vars.
INFO subprocess: Command not in installer, restoring original environment...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 32000
DEBUG subprocess: Exit status: 0
DEBUG virtualbox_7_0: Searching for SSH port: 22
DEBUG virtualbox_7_0: read_forward_ports: uuid=d216ed6b-1720-49b8-98f3-8dd7b9b8cb38 active_only=false
INFO subprocess: Starting process: ["/usr/local/bin/VBoxManage", "showvminfo", "d216ed6b-1720-49b8-98f3-8dd7b9b8cb38", "--machinereadable"]
DEBUG subprocess: Command not in installer, not touching env vars.
INFO subprocess: Command not in installer, restoring original environment...
DEBUG subprocess: Selecting on IO
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 32000
DEBUG subprocess: Exit status: 0
DEBUG virtualbox_7_0: - [1, "ssh", 2222, 22, "127.0.0.1"]
DEBUG ssh: Checking key permissions: /Users/goalidea/.vagrant.d/insecure_private_key
INFO ssh: Attempting SSH connection...
INFO ssh: Attempting to connect to SSH...
INFO ssh: - Host: 127.0.0.1
INFO ssh: - Port: 2222
INFO ssh: - Username: vagrant
INFO ssh: - Password? false
INFO ssh: - Key Path: ["/Users/goalidea/.vagrant.d/insecure_private_key"]
DEBUG ssh: - connect_opts: {:auth_methods=>["none", "hostbased", "publickey"], :config=>false, :forward_agent=>false, :send_env=>false, :keys_only=>true, :verify_host_key=>:never, :password=>nil, :port=>2222, :timeout=>15, :user_known_hosts_file=>[], :verbose=>:debug, :logger=>#<Logger:0x00007fd46fa4e200 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x00007fd46fa4e1d8 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x00007fd46fa4e188 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<StringIO:0x00007fd46fa4e250>, @binmode=false, @mon_data=#<Monitor:0x00007fd46fa4e160>, @mon_data_owner_object_id=153580>>, :keys=>["/Users/goalidea/.vagrant.d/insecure_private_key"], :remote_user=>"vagrant"}
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2022-12-17T09:52:54.489707 #1313] DEBUG -- net.ssh.transport.session[25800]: establishing connection to 127.0.0.1:2222
D, [2022-12-17T09:52:54.490096 #1313] DEBUG -- net.ssh.transport.session[25800]: connection established
I, [2022-12-17T09:52:54.490150 #1313] INFO -- net.ssh.transport.server_version[25814]: negotiating protocol version
D, [2022-12-17T09:52:54.490162 #1313] DEBUG -- net.ssh.transport.server_version[25814]: local is `SSH-2.0-Ruby/Net::SSH_7.0.1 x86_64-darwin19'
D, [2022-12-17T09:52:54.500684 #1313] DEBUG -- net.ssh.transport.server_version[25814]: remote is `SSH-2.0-OpenSSH_7.9p1 Debian-10+deb10u2'
I, [2022-12-17T09:52:54.501322 #1313] INFO -- net.ssh.transport.algorithms[25828]: sending KEXINIT
D, [2022-12-17T09:52:54.501635 #1313] DEBUG -- socket[2583c]: queueing packet nr 0 type 20 len 852
D, [2022-12-17T09:52:54.501688 #1313] DEBUG -- socket[2583c]: sent 856 bytes
D, [2022-12-17T09:52:54.507628 #1313] DEBUG -- socket[2583c]: read 1080 bytes
D, [2022-12-17T09:52:54.507817 #1313] DEBUG -- socket[2583c]: received packet nr 0 type 20 len 1076
I, [2022-12-17T09:52:54.507846 #1313] INFO -- net.ssh.transport.algorithms[25828]: got KEXINIT from server
I, [2022-12-17T09:52:54.507935 #1313] INFO -- net.ssh.transport.algorithms[25828]: negotiating algorithms
D, [2022-12-17T09:52:54.508009 #1313] DEBUG -- net.ssh.transport.algorithms[25828]: negotiated:
* kex: ecdh-sha2-nistp521
* host_key: ssh-ed25519
* encryption_server: aes256-ctr
* encryption_client: aes256-ctr
* hmac_client: [email protected]
* hmac_server: [email protected]
* compression_client: none
* compression_server: none
* language_client:
* language_server:
D, [2022-12-17T09:52:54.508030 #1313] DEBUG -- net.ssh.transport.algorithms[25828]: exchanging keys
D, [2022-12-17T09:52:54.510885 #1313] DEBUG -- socket[2583c]: queueing packet nr 1 type 30 len 148
D, [2022-12-17T09:52:54.511021 #1313] DEBUG -- socket[2583c]: sent 152 bytes
D, [2022-12-17T09:52:54.514707 #1313] DEBUG -- socket[2583c]: read 312 bytes
D, [2022-12-17T09:52:54.514865 #1313] DEBUG -- socket[2583c]: received packet nr 1 type 31 len 292
D, [2022-12-17T09:52:54.517865 #1313] DEBUG -- socket[2583c]: queueing packet nr 2 type 21 len 20
D, [2022-12-17T09:52:54.517909 #1313] DEBUG -- socket[2583c]: sent 24 bytes
D, [2022-12-17T09:52:54.517939 #1313] DEBUG -- socket[2583c]: received packet nr 2 type 21 len 12
D, [2022-12-17T09:52:54.518481 #1313] DEBUG -- net.ssh.authentication.session[25850]: beginning authentication of `vagrant'
D, [2022-12-17T09:52:54.518561 #1313] DEBUG -- socket[2583c]: using encrypt-then-mac
D, [2022-12-17T09:52:54.518644 #1313] DEBUG -- socket[2583c]: queueing packet nr 3 type 5 len 32
D, [2022-12-17T09:52:54.518693 #1313] DEBUG -- socket[2583c]: sent 100 bytes
D, [2022-12-17T09:52:54.520423 #1313] DEBUG -- socket[2583c]: read 100 bytes
D, [2022-12-17T09:52:54.520503 #1313] DEBUG -- socket[2583c]: received packet nr 3 type 6 len 32
D, [2022-12-17T09:52:54.520559 #1313] DEBUG -- net.ssh.authentication.session[25850]: trying none
D, [2022-12-17T09:52:54.520622 #1313] DEBUG -- socket[2583c]: using encrypt-then-mac
D, [2022-12-17T09:52:54.520665 #1313] DEBUG -- socket[2583c]: queueing packet nr 4 type 50 len 48
D, [2022-12-17T09:52:54.520698 #1313] DEBUG -- socket[2583c]: sent 116 bytes
D, [2022-12-17T09:52:54.535282 #1313] DEBUG -- socket[2583c]: read 100 bytes
D, [2022-12-17T09:52:54.535791 #1313] DEBUG -- socket[2583c]: received packet nr 4 type 51 len 32
D, [2022-12-17T09:52:54.535899 #1313] DEBUG -- net.ssh.authentication.session[25850]: allowed methods: publickey,password
D, [2022-12-17T09:52:54.535943 #1313] DEBUG -- net.ssh.authentication.methods.none[25864]: none failed
D, [2022-12-17T09:52:54.536015 #1313] DEBUG -- net.ssh.authentication.session[25850]: trying publickey
D, [2022-12-17T09:52:54.536287 #1313] DEBUG -- net.ssh.authentication.agent[25878]: connecting to ssh-agent
D, [2022-12-17T09:52:54.536351 #1313] DEBUG -- net.ssh.authentication.agent[25878]: sending agent request 1 len 47
D, [2022-12-17T09:52:54.536423 #1313] DEBUG -- net.ssh.authentication.agent[25878]: received agent packet 5 len 1
D, [2022-12-17T09:52:54.536439 #1313] DEBUG -- net.ssh.authentication.agent[25878]: sending agent request 11 len 0
D, [2022-12-17T09:52:54.536498 #1313] DEBUG -- net.ssh.authentication.agent[25878]: received agent packet 12 len 5
D, [2022-12-17T09:52:54.536583 #1313] DEBUG -- net.ssh.authentication.methods.publickey[258a0]: trying publickey (dd:3b:b8:2e:85:04:06:e9:ab:ff:a8:0a:c0:04:6e:d6)
D, [2022-12-17T09:52:54.536720 #1313] DEBUG -- socket[2583c]: using encrypt-then-mac
D, [2022-12-17T09:52:54.536760 #1313] DEBUG -- socket[2583c]: queueing packet nr 5 type 50 len 352
D, [2022-12-17T09:52:54.536787 #1313] DEBUG -- socket[2583c]: sent 420 bytes
D, [2022-12-17T09:52:54.544639 #1313] DEBUG -- socket[2583c]: read 372 bytes
D, [2022-12-17T09:52:54.544785 #1313] DEBUG -- socket[2583c]: received packet nr 5 type 60 len 304
D, [2022-12-17T09:52:54.546518 #1313] DEBUG -- socket[2583c]: using encrypt-then-mac
D, [2022-12-17T09:52:54.546563 #1313] DEBUG -- socket[2583c]: queueing packet nr 6 type 50 len 640
D, [2022-12-17T09:52:54.546593 #1313] DEBUG -- socket[2583c]: sent 708 bytes
D, [2022-12-17T09:52:54.565287 #1313] DEBUG -- socket[2583c]: read 228 bytes
D, [2022-12-17T09:52:54.565559 #1313] DEBUG -- socket[2583c]: received packet nr 6 type 53 len 160
I, [2022-12-17T09:52:54.565629 #1313] INFO -- net.ssh.authentication.session[25850]: "System is booting up. Unprivileged users are not permitted to log in yet. Please come back later. For technical details, see pam_nologin(8)."
D, [2022-12-17T09:52:54.567222 #1313] DEBUG -- socket[2583c]: read 0 bytes
From the debug log you have provided, it describes the reason why ssh login is being prevented:
net.ssh.authentication.session[25788]: "System is booting up. Unprivileged users are not permitted to log in yet. Please come back later. For technical details, see pam_nologin(8)."
This may be an issue with the box that was resolved in the last release as testing the bento/debian-10
box locally works without issue and the latest release was just a few days ago. Does the latest version still result in the same behavior?
@chrisroberts i do not known, but my vagrant version is 2.3.4 and it has this bug
Hi @goalidea
Are you still encountering this issue?
@chrisroberts
I have the same issue. Windows 11, Vagrant 2.3.6, VirtualBox 7.0.8, box: bento/ubuntu-20.04
. This happens when the VirtualBox window is not open. So with this .bat script it works fine:
tasklist | find /i "VirtualBox.exe">nul
goto answer%errorlevel%
:answer0
cd %HOMEPATH%\Vagrant
vagrant up
vagrant ssh
vagrant halt
exit
:answer1
cd %ProgramFiles%\Oracle\VirtualBox\
start /min VirtualBox.exe
goto answer0
I think I've found what the problem is. Paravirtualization in VirtualBox with boxes based on Ubuntu 20 and more than 2 cores on VMs. If it set to "Minimal" or "None" and/or only one core and/or other Ubuntu- it works! So you can add to your Vagrantfile this:
Vagrant.configure(2) do |config|
config.vm.provider "virtualbox" do |vb|
vb.customize [
"modifyvm", :id,
"--paravirtprovider", "minimal",
"--cpus", "2"
]
end
end
I think I've found what the problem is. Paravirtualization in VirtualBox with boxes based on Ubuntu 20 and more than 2 cores on VMs. If it set to "Minimal" or "None" and/or only one core and/or other Ubuntu- it works! So you can add to your Vagrantfile this:
Vagrant.configure(2) do |config| config.vm.provider "virtualbox" do |vb| vb.customize [ "modifyvm", :id, "--paravirtprovider", "minimal", "--cpus", "2" ] end end
This fixed it for me. Thanks a lot.