Hang waiting for ssh to become available

[derks]

Seems like the plugin is unable to detect that SSH is available... it always hangs. Manually SSHing works fine (outside of vagrant):

Vagrant: 2.1.5
Packet Plugin: 0.1.6

$ vagrant up --provider packet node0
[fog][DEPRECATION] Unable to load Fog::Packet::Compute
[fog][DEPRECATION] The format Fog::Compute::Packet is deprecated
Bringing machine 'node0' up with 'packet' provider...
==> node0: Warning! The Packet provider doesn't support any of the Vagrant
==> node0: high-level network configurations (`config.vm.network`). They
==> node0: will be silently ignored.
==> node0: Launching an instance with the following settings...
==> node0:  -- Project: XXXXXXXXXXXXXXX
==> node0:  -- Facility: ewr1
==> node0:  -- OS: ubuntu_16_04
==> node0:  -- Machine: t1.small.x86
==> node0: Waiting for instance to become "ready"...
==> node0: Waiting for SSH to become available...

[derks]

The following is the debug log for the above example:

DEBUG ssh: Checking whether SSH is ready...
 INFO machine: Calling action: read_ssh_info on provider Packet (75359b3a-9832-4604-add8-46d9d0c4f526)
 INFO interface: Machine: action ["read_ssh_info", "start", {:target=>:node0}]
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: machine_action_read_ssh_info #<Vagrant::Action::Builder:0x00000001019a0720>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::ConfigValidate:0x0000000104043490>
 INFO warden: Calling IN action: #<VagrantPlugins::Packet::Action::ConnectPacket:0x0000000104043440>
 INFO connect_packet: Connecting to Packet...
 INFO warden: Calling IN action: #<VagrantPlugins::Packet::Action::ReadSSHInfo:0x00000001023be9c8>
 INFO warden: Calling OUT action: #<VagrantPlugins::Packet::Action::ReadSSHInfo:0x00000001023be9c8>
 INFO warden: Calling OUT action: #<VagrantPlugins::Packet::Action::ConnectPacket:0x0000000104043440>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x0000000104043490>
 INFO interface: Machine: action ["read_ssh_info", "end", {:target=>:node0}]
DEBUG ssh: Checking key permissions: /Users/derks/.vagrant.d/insecure_private_key
 INFO ssh: Attempting SSH connection...
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 75359b3a.packethost.net
 INFO ssh:   - Port: 22
 INFO ssh:   - Username: root
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/derks/.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=>22, :timeout=>15, :user_known_hosts_file=>[], :verbose=>:debug, :encryption=>["aes128-cbc", "3des-cbc", "blowfish-cbc", "cast128-cbc", "aes192-cbc", "aes256-cbc", "rijndael-cbc@lysator.liu.se", "idea-cbc", "arcfour128", "arcfour256", "arcfour", "aes128-ctr", "aes192-ctr", "aes256-ctr", "cast128-ctr", "blowfish-ctr", "3des-ctr", "none"], :logger=>#<Logger:0x0000000101926e70 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x0000000101926e20 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x0000000101926d30 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<StringIO:0x0000000101926ee8>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x0000000101926ad8>>>, :keys=>["/Users/derks/.vagrant.d/insecure_private_key"]}
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2018-10-01T10:45:56.195162 #84944] DEBUG -- net.ssh.transport.session[80c91910]: establishing connection to 75359b3a.packethost.net:22
D, [2018-10-01T10:45:56.270802 #84944] DEBUG -- net.ssh.transport.session[80c91910]: connection established
I, [2018-10-01T10:45:56.270965 #84944]  INFO -- net.ssh.transport.server_version[80c910dc]: negotiating protocol version
D, [2018-10-01T10:45:56.271012 #84944] DEBUG -- net.ssh.transport.server_version[80c910dc]: local is `SSH-2.0-Ruby/Net::SSH_5.0.2 x86_64-darwin13'
D, [2018-10-01T10:45:56.357668 #84944] DEBUG -- net.ssh.transport.server_version[80c910dc]: remote is `SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.4'
I, [2018-10-01T10:45:56.358195 #84944]  INFO -- net.ssh.transport.algorithms[80c8de8c]: sending KEXINIT
D, [2018-10-01T10:45:56.358575 #84944] DEBUG -- socket[80c91668]: queueing packet nr 0 type 20 len 1156
D, [2018-10-01T10:45:56.358721 #84944] DEBUG -- socket[80c91668]: sent 1160 bytes
D, [2018-10-01T10:45:56.422744 #84944] DEBUG -- socket[80c91668]: read 960 bytes
D, [2018-10-01T10:45:56.422897 #84944] DEBUG -- socket[80c91668]: received packet nr 0 type 20 len 956
I, [2018-10-01T10:45:56.422985 #84944]  INFO -- net.ssh.transport.algorithms[80c8de8c]: got KEXINIT from server
I, [2018-10-01T10:45:56.423166 #84944]  INFO -- net.ssh.transport.algorithms[80c8de8c]: negotiating algorithms
D, [2018-10-01T10:45:56.423357 #84944] DEBUG -- net.ssh.transport.algorithms[80c8de8c]: negotiated:
* kex: diffie-hellman-group14-sha1
* host_key: ssh-rsa
* encryption_server: aes128-ctr
* encryption_client: aes128-ctr
* hmac_client: hmac-sha1
* hmac_server: hmac-sha1
* compression_client: none
* compression_server: none
* language_client:
* language_server:
D, [2018-10-01T10:45:56.423391 #84944] DEBUG -- net.ssh.transport.algorithms[80c8de8c]: exchanging keys
D, [2018-10-01T10:45:56.434019 #84944] DEBUG -- socket[80c91668]: queueing packet nr 1 type 30 len 268
D, [2018-10-01T10:45:56.434114 #84944] DEBUG -- socket[80c91668]: sent 272 bytes
D, [2018-10-01T10:45:56.534323 #84944] DEBUG -- socket[80c91668]: read 848 bytes
D, [2018-10-01T10:45:56.534594 #84944] DEBUG -- socket[80c91668]: received packet nr 1 type 31 len 828
D, [2018-10-01T10:45:56.536127 #84944] DEBUG -- socket[80c91668]: queueing packet nr 2 type 21 len 20
D, [2018-10-01T10:45:56.536295 #84944] DEBUG -- socket[80c91668]: sent 24 bytes
D, [2018-10-01T10:45:56.536439 #84944] DEBUG -- socket[80c91668]: received packet nr 2 type 21 len 12
D, [2018-10-01T10:45:56.537175 #84944] DEBUG -- net.ssh.authentication.session[811290a4]: beginning authentication of `root'
D, [2018-10-01T10:45:56.537357 #84944] DEBUG -- socket[80c91668]: queueing packet nr 3 type 5 len 28
D, [2018-10-01T10:45:56.537437 #84944] DEBUG -- socket[80c91668]: sent 52 bytes
D, [2018-10-01T10:45:56.714386 #84944] DEBUG -- socket[80c91668]: read 52 bytes
D, [2018-10-01T10:45:56.714760 #84944] DEBUG -- socket[80c91668]: received packet nr 3 type 6 len 28
D, [2018-10-01T10:45:56.714971 #84944] DEBUG -- net.ssh.authentication.session[811290a4]: trying none
D, [2018-10-01T10:45:56.715270 #84944] DEBUG -- socket[80c91668]: queueing packet nr 4 type 50 len 44
D, [2018-10-01T10:45:56.715407 #84944] DEBUG -- socket[80c91668]: sent 68 bytes
D, [2018-10-01T10:45:56.786270 #84944] DEBUG -- socket[80c91668]: read 52 bytes
D, [2018-10-01T10:45:56.786670 #84944] DEBUG -- socket[80c91668]: received packet nr 4 type 51 len 28
D, [2018-10-01T10:45:56.786857 #84944] DEBUG -- net.ssh.authentication.session[811290a4]: allowed methods: publickey
D, [2018-10-01T10:45:56.786978 #84944] DEBUG -- net.ssh.authentication.methods.none[81121408]: none failed
D, [2018-10-01T10:45:56.787081 #84944] DEBUG -- net.ssh.authentication.session[811290a4]: trying publickey
D, [2018-10-01T10:45:56.787682 #84944] DEBUG -- net.ssh.authentication.agent[80c36f60]: connecting to ssh-agent
D, [2018-10-01T10:45:56.787920 #84944] DEBUG -- net.ssh.authentication.agent[80c36f60]: sending agent request 1 len 47
D, [2018-10-01T10:45:56.788181 #84944] DEBUG -- net.ssh.authentication.agent[80c36f60]: received agent packet 5 len 1
D, [2018-10-01T10:45:56.788262 #84944] DEBUG -- net.ssh.authentication.agent[80c36f60]: sending agent request 11 len 0
D, [2018-10-01T10:45:56.788443 #84944] DEBUG -- net.ssh.authentication.agent[80c36f60]: received agent packet 12 len 5
D, [2018-10-01T10:45:56.788800 #84944] DEBUG -- net.ssh.authentication.methods.publickey[80c37f78]: trying publickey (dd:3b:b8:2e:85:04:06:e9:ab:ff:a8:0a:c0:04:6e:d6)
D, [2018-10-01T10:45:56.789165 #84944] DEBUG -- socket[80c91668]: queueing packet nr 5 type 50 len 348
D, [2018-10-01T10:45:56.789289 #84944] DEBUG -- socket[80c91668]: sent 372 bytes
D, [2018-10-01T10:45:56.872834 #84944] DEBUG -- socket[80c91668]: read 52 bytes
D, [2018-10-01T10:45:56.873212 #84944] DEBUG -- socket[80c91668]: received packet nr 5 type 51 len 28
D, [2018-10-01T10:45:56.873409 #84944] DEBUG -- net.ssh.authentication.session[811290a4]: allowed methods: publickey
E, [2018-10-01T10:45:56.873508 #84944] ERROR -- net.ssh.authentication.session[811290a4]: all authorization methods failed (tried none, publickey)

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO ssh: SSH not up: #<Vagrant::Errors::SSHAuthenticationFailed: SSH authentication failed! This is typically caused by the public/private
keypair for the SSH user not being properly set on the guest VM. Please
verify that the guest VM is setup with the proper public key, and that
the private key path for Vagrant is setup properly as well.>

I will verify the SSH configuration settings on Packet, and Local.

[derks]

OK, I did find that I was not configuring the ssh key path correctly, however am still unable to connect:

DEBUG ssh: Checking whether SSH is ready...
 INFO machine: Calling action: read_ssh_info on provider Packet (9b2537b2-c90e-423d-9944-a5f1f8fc30bd)
 INFO interface: Machine: action ["read_ssh_info", "start", {:target=>:node0}]
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: machine_action_read_ssh_info #<Vagrant::Action::Builder:0x0000000101aac1c8>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::ConfigValidate:0x0000000101aa38e8>
 INFO warden: Calling IN action: #<VagrantPlugins::Packet::Action::ConnectPacket:0x0000000101aa38c0>
 INFO connect_packet: Connecting to Packet...
 INFO warden: Calling IN action: #<VagrantPlugins::Packet::Action::ReadSSHInfo:0x0000000101a7b190>
 INFO warden: Calling OUT action: #<VagrantPlugins::Packet::Action::ReadSSHInfo:0x0000000101a7b190>
 INFO warden: Calling OUT action: #<VagrantPlugins::Packet::Action::ConnectPacket:0x0000000101aa38c0>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x0000000101aa38e8>
 INFO interface: Machine: action ["read_ssh_info", "end", {:target=>:node0}]
DEBUG ssh: Checking key permissions: /Users/derks/.ssh/id_rsa
 INFO ssh: Attempting SSH connection...
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 9b2537b2.packethost.net
 INFO ssh:   - Port: 22
 INFO ssh:   - Username: root
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/derks/.ssh/id_rsa"]
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=>22, :timeout=>15, :user_known_hosts_file=>[], :verbose=>:debug, :encryption=>["aes128-cbc", "3des-cbc", "blowfish-cbc", "cast128-cbc", "aes192-cbc", "aes256-cbc", "rijndael-cbc@lysator.liu.se", "idea-cbc", "arcfour128", "arcfour256", "arcfour", "aes128-ctr", "aes192-ctr", "aes256-ctr", "cast128-ctr", "blowfish-ctr", "3des-ctr", "none"], :logger=>#<Logger:0x000000010096df38 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x000000010096dee8 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x000000010096ddd0 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<StringIO:0x000000010096dfd8>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x000000010096dd08>>>, :keys=>["/Users/derks/.ssh/id_rsa"]}
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2018-10-01T11:33:58.564452 #92875] DEBUG -- net.ssh.transport.session[8122e620]: establishing connection to 9b2537b2.packethost.net:22

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO retryable: Retryable exception raised: #<Errno::EHOSTUNREACH: No route to host - connect(2) for [2604:1380:1:1a00::1]:22>
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 9b2537b2.packethost.net
 INFO ssh:   - Port: 22
 INFO ssh:   - Username: root
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/derks/.ssh/id_rsa"]
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=>22, :timeout=>15, :user_known_hosts_file=>[], :verbose=>:debug, :encryption=>["aes128-cbc", "3des-cbc", "blowfish-cbc", "cast128-cbc", "aes192-cbc", "aes256-cbc", "rijndael-cbc@lysator.liu.se", "idea-cbc", "arcfour128", "arcfour256", "arcfour", "aes128-ctr", "aes192-ctr", "aes256-ctr", "cast128-ctr", "blowfish-ctr", "3des-ctr", "none"], :logger=>#<Logger:0x00000001029faaa8 @level=0, @progname=nil, @default_formatter=#<Logger::Formatter:0x00000001029fa8c8 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x00000001029fa800 @shift_period_suffix=nil, @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<StringIO:0x00000001029fac38>, @mon_owner=nil, @mon_count=0, @mon_mutex=#<Thread::Mutex:0x00000001029fa698>>>, :keys=>["/Users/derks/.ssh/id_rsa"]}

It would appear that the host address we are attempting to connect to is incorrect:

 INFO retryable: Retryable exception raised: #<Errno::EHOSTUNREACH: No route to host - connect(2) for [2604:1380:1:1a00::1]:22>

[derks]

This seems likely to be an issue with Packet... I am now running vagrant+packet OK... so closing this out for now.