Page MenuHomePhabricator
Create Task
Maniphest T155798

MediaWiki-Vagrant gives "SSH authentication failed" for no apparent reason
Closed, InvalidPublic
Actions

Description

Vagrant fails to ssh into the box, even though manual connection with the same key and settings works fine.

$ vagrant provision 
==> default: Running provisioner: lsb_check...
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.
$ vagrant status
Current machine states:

default                   running (virtualbox)
...
$ vagrant config --get static_ip
10.11.12.101
$ vagrant ssh-config
Host default
  HostName 127.0.0.1
  User vagrant
  Port 2222
  UserKnownHostsFile /dev/null
  StrictHostKeyChecking no
  PasswordAuthentication no
  IdentityFile "/home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key"
  IdentitiesOnly yes
  LogLevel FATAL
  ForwardAgent yes
  ForwardX11 yes
$ vagrant port
...
    80 (guest) => 10001 (host)
   443 (guest) => 44301 (host)
    22 (guest) => 2222 (host)
  9200 (guest) => 9200 (host)
$ ssh -i /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key -F /dev/null vagrant@10.11.12.101 exit && echo 'yes' || echo 'no'
yes
$ ssh -i /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key -F /dev/null -p 2222 vagrant@127.0.0.1 exit && echo 'yes' || echo 'no'
yes
$ ssh-keygen -lf /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key -E md5
2048 MD5:47:c5:7c:ee:e9:19:df:f7:6e:83:32:8d:10:b8:12:8f no comment (RSA)

Vagrant debug log: P4771; the relevant lines:

...
 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: ["/home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key"]
...
D, [2017-01-19T17:00:43.555225 #23370] DEBUG -- net.ssh.authentication.session[1041dc4]: allowed methods: publickey,password
D, [2017-01-19T17:00:43.555275 #23370] DEBUG -- net.ssh.authentication.methods.none[1040b40]: none failed
D, [2017-01-19T17:00:43.555369 #23370] DEBUG -- net.ssh.authentication.session[1041dc4]: trying publickey
D, [2017-01-19T17:00:43.555607 #23370] DEBUG -- net.ssh.authentication.agent[102cf00]: connecting to ssh-agent
D, [2017-01-19T17:00:43.555695 #23370] DEBUG -- net.ssh.authentication.agent[102cf00]: sending agent request 1 len 48
D, [2017-01-19T17:00:43.556051 #23370] DEBUG -- net.ssh.authentication.agent[102cf00]: received agent packet 2 len 5
D, [2017-01-19T17:00:43.556080 #23370] DEBUG -- net.ssh.authentication.agent[102cf00]: sending agent request 11 len 0
D, [2017-01-19T17:00:43.556616 #23370] DEBUG -- net.ssh.authentication.agent[102cf00]: received agent packet 12 len 794
D, [2017-01-19T17:00:43.556963 #23370] DEBUG -- net.ssh.authentication.methods.publickey[102d34c]: trying publickey (47:c5:7c:ee:e9:19:df:f7:6e:83:32:8d:10:b8:12:8f)
D, [2017-01-19T17:00:43.557064 #23370] DEBUG -- socket[109c3a0]: queueing packet nr 6 type 50 len 348
D, [2017-01-19T17:00:43.557106 #23370] DEBUG -- socket[109c3a0]: sent 372 bytes
D, [2017-01-19T17:00:43.558519 #23370] DEBUG -- socket[109c3a0]: read 68 bytes
D, [2017-01-19T17:00:43.558614 #23370] DEBUG -- socket[109c3a0]: received packet nr 6 type 51 len 44
D, [2017-01-19T17:00:43.558663 #23370] DEBUG -- net.ssh.authentication.session[1041dc4]: allowed methods: publickey,password
E, [2017-01-19T17:00:43.558698 #23370] ERROR -- net.ssh.authentication.session[1041dc4]: all authorization methods failed (tried none, publickey)
...

Related Objects

Event Timeline

Tgr created this task.Jan 20 2017, 1:08 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 20 2017, 1:08 AM
bd808 subscribed.Jan 20 2017, 1:10 AM

Whatever that is, it would be an upstream Vagrant bug. You left vagrant version out of your debugging data.

Tgr added a comment.Jan 20 2017, 1:30 AM

vagrant ssh debug log: P4772; the relevant lines:

DEBUG ssh: Checking key permissions: /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key
 INFO ssh: Invoking SSH: ssh ["vagrant@127.0.0.1", "-p", "2222", "-o", "Compression=yes", "-o", "DSAAuthentication=yes", "-o", "LogLevel=FATAL", "-o", "StrictHostKeyChecking=no", "-o", "UserKnownHostsFile=/dev/null", "-o", "IdentitiesOnly=yes", "-i", "/home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key", "-o", "ForwardX11=yes", "-o", "ForwardX11Trusted=yes", "-o", "ForwardAgent=yes"]
vagrant@127.0.0.1's password:

The command reconstructed from that does indeed fail:

$ ssh vagrant@127.0.0.1 -p 2222 -o Compression=yes -o DSAAuthentication=yes -o LogLevel=FATAL -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o IdentitiesOnly=yes -i /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key -o ForwardX11=yes -o ForwardX11Trusted=yes -o ForwardAgent=yes
vagrant@127.0.0.1's password:

IdentitiesOnly seems to be at fault.

$ ssh -vvv vagrant@127.0.0.1 -p 2222 -o Compression=yes -o DSAAuthentication=yes -o LogLevel=FATAL -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -i /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key -o ForwardX11=yes -o ForwardX11Trusted=yes -o ForwardAgent=yes -o IdentitiesOnly=no
...
debug1: Authentications that can continue: publickey,password
debug1: Trying private key: /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key
debug3: sign_and_send_pubkey: RSA SHA256:qNTRrnRsHeizXcAEvzBDLXMn1/s7AL2J375YsCESoxg
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 52
debug1: Enabling compression at level 6.
debug1: Authentication succeeded (publickey).
...
$ ssh -vvv vagrant@127.0.0.1 -p 2222 -o Compression=yes -o DSAAuthentication=yes -o LogLevel=FATAL -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -i /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key -o ForwardX11=yes -o ForwardX11Trusted=yes -o ForwardAgent=yes -o IdentitiesOnly=yes
...
debug1: Next authentication method: publickey
debug1: Trying private key: /home/tgr/Wikimedia/vagrant/oauth/.vagrant/machines/default/virtualbox/private_key
debug3: sign_and_send_pubkey: RSA SHA256:qNTRrnRsHeizXcAEvzBDLXMn1/s7AL2J375YsCESoxg
debug3: send packet: type 50
debug2: we sent a publickey packet, wait for reply
debug3: receive packet: type 51
debug1: Authentications that can continue: publickey,password
...
Tgr added a comment.Jan 20 2017, 1:38 AM

Running sshd in debug mode on the guest:

$ sudo /usr/sbin/sshd -d -p 1234
debug1: sshd version OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type DSA
debug1: private host key: #1 type 2 DSA
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type ECDSA
debug1: private host key: #2 type 3 ECDSA
debug1: could not open key file '/etc/ssh/ssh_host_ed25519_key': No such file or directory
Could not load host key: /etc/ssh/ssh_host_ed25519_key
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-d'
debug1: rexec_argv[2]='-p'
debug1: rexec_argv[3]='1234'
Set /proc/self/oom_score_adj from 0 to -1000
debug1: Bind to port 1234 on 0.0.0.0.
Server listening on 0.0.0.0 port 1234.
debug1: Bind to port 1234 on ::.
Server listening on :: port 1234.
debug1: Server will not fork when running in debugging mode.
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 10.11.12.1 port 38990 on 10.11.12.101 port 1234
debug1: Client protocol version 2.0; client software version OpenSSH_7.2p2 Ubuntu-4ubuntu2.1
debug1: match: OpenSSH_7.2p2 Ubuntu-4ubuntu2.1 pat OpenSSH* compat 0x04000000
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2
debug1: permanently_set_uid: 104/65534 [preauth]
debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug1: kex: client->server chacha20-poly1305@openssh.com <implicit> zlib@openssh.com [preauth]
debug1: kex: server->client chacha20-poly1305@openssh.com <implicit> zlib@openssh.com [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user vagrant service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug1: PAM: initializing for "vagrant"
debug1: PAM: setting PAM_RHOST to "10.11.12.1"
debug1: PAM: setting PAM_TTY to "ssh"
debug1: userauth-request for user vagrant service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
Authentication refused: bad ownership or modes for file /home/vagrant/.ssh/authorized_keys
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/vagrant/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
Failed publickey for vagrant from 10.11.12.1 port 38990 ssh2: RSA 47:c5:7c:ee:e9:19:df:f7:6e:83:32:8d:10:b8:12:8f
Tgr closed this task as Invalid.Jan 20 2017, 1:43 AM

Authentication refused: bad ownership or modes for file /home/vagrant/.ssh/authorized_keys

The file was mode 664 (probably changed when migrating it to a new laptop); setting to 600 fixed the issue. I am at a complete loss to explain what this has to do with IdentitiesOnly. Some sort of SSH bug? FWIW this is the sshd output with IdentitiesOnly=no:

$ sudo /usr/sbin/sshd -d -p 1234
debug1: sshd version OpenSSH_6.6.1, OpenSSL 1.0.1f 6 Jan 2014
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type RSA
debug1: private host key: #0 type 1 RSA
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type DSA
debug1: private host key: #1 type 2 DSA
debug1: key_parse_private2: missing begin marker
debug1: read PEM private key done: type ECDSA
debug1: private host key: #2 type 3 ECDSA
debug1: could not open key file '/etc/ssh/ssh_host_ed25519_key': No such file or directory
Could not load host key: /etc/ssh/ssh_host_ed25519_key
debug1: rexec_argv[0]='/usr/sbin/sshd'
debug1: rexec_argv[1]='-d'
debug1: rexec_argv[2]='-p'
debug1: rexec_argv[3]='1234'
Set /proc/self/oom_score_adj from 0 to -1000
debug1: Bind to port 1234 on 0.0.0.0.
Server listening on 0.0.0.0 port 1234.
debug1: Bind to port 1234 on ::.
Server listening on :: port 1234.
debug1: Server will not fork when running in debugging mode.
debug1: rexec start in 5 out 5 newsock 5 pipe -1 sock 8
debug1: inetd sockets after dupping: 3, 3
Connection from 10.11.12.1 port 39022 on 10.11.12.101 port 1234
debug1: Client protocol version 2.0; client software version OpenSSH_7.2p2 Ubuntu-4ubuntu2.1
debug1: match: OpenSSH_7.2p2 Ubuntu-4ubuntu2.1 pat OpenSSH* compat 0x04000000
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2
debug1: permanently_set_uid: 104/65534 [preauth]
debug1: list_hostkey_types: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256 [preauth]
debug1: SSH2_MSG_KEXINIT sent [preauth]
debug1: SSH2_MSG_KEXINIT received [preauth]
debug1: kex: client->server chacha20-poly1305@openssh.com <implicit> zlib@openssh.com [preauth]
debug1: kex: server->client chacha20-poly1305@openssh.com <implicit> zlib@openssh.com [preauth]
debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
debug1: SSH2_MSG_NEWKEYS sent [preauth]
debug1: expecting SSH2_MSG_NEWKEYS [preauth]
debug1: SSH2_MSG_NEWKEYS received [preauth]
debug1: KEX done [preauth]
debug1: userauth-request for user vagrant service ssh-connection method none [preauth]
debug1: attempt 0 failures 0 [preauth]
debug1: PAM: initializing for "vagrant"
debug1: PAM: setting PAM_RHOST to "10.11.12.1"
debug1: PAM: setting PAM_TTY to "ssh"
debug1: userauth-request for user vagrant service ssh-connection method publickey [preauth]
debug1: attempt 1 failures 0 [preauth]
debug1: test whether pkalg/pkblob are acceptable [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
Authentication refused: bad ownership or modes for file /home/vagrant/.ssh/authorized_keys
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/vagrant/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
Failed publickey for vagrant from 10.11.12.1 port 39022 ssh2: RSA 43:f4:d5:14:9b:20:0e:e9:b7:2e:86:2f:db:fb:91:67
debug1: userauth-request for user vagrant service ssh-connection method publickey [preauth]
debug1: attempt 2 failures 1 [preauth]
debug1: test whether pkalg/pkblob are acceptable [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/vagrant/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
Failed publickey for vagrant from 10.11.12.1 port 39022 ssh2: RSA 5d:43:88:0d:bc:92:ec:0f:4b:f6:78:78:40:bf:28:0f
debug1: userauth-request for user vagrant service ssh-connection method publickey [preauth]
debug1: attempt 3 failures 2 [preauth]
debug1: test whether pkalg/pkblob are acceptable [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
Authentication refused: bad ownership or modes for file /home/vagrant/.ssh/authorized_keys
debug1: restore_uid: 0/0
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys2
debug1: Could not open authorized keys '/home/vagrant/.ssh/authorized_keys2': No such file or directory
debug1: restore_uid: 0/0
Failed publickey for vagrant from 10.11.12.1 port 39022 ssh2: RSA 49:f5:e6:20:67:23:da:f9:22:cd:e5:bf:19:20:d3:af
debug1: userauth-request for user vagrant service ssh-connection method publickey [preauth]
debug1: attempt 4 failures 3 [preauth]
debug1: temporarily_use_uid: 1000/1000 (e=0/0)
debug1: trying public key file /home/vagrant/.ssh/authorized_keys
debug1: fd 4 clearing O_NONBLOCK
debug1: matching key found: file /home/vagrant/.ssh/authorized_keys, line 2 RSA 47:c5:7c:ee:e9:19:df:f7:6e:83:32:8d:10:b8:12:8f
debug1: restore_uid: 0/0
debug1: ssh_rsa_verify: signature correct
debug1: do_pam_account: called
Accepted publickey for vagrant from 10.11.12.1 port 39022 ssh2: RSA 47:c5:7c:ee:e9:19:df:f7:6e:83:32:8d:10:b8:12:8f
debug1: monitor_child_preauth: vagrant has been authenticated by privileged process
debug1: Enabling compression at level 6. [preauth]
debug1: monitor_read_log: child log fd closed
debug1: PAM: establishing credentials
User child is on pid 4212
debug1: SELinux support disabled
debug1: PAM: establishing credentials
debug1: permanently_set_uid: 1000/1000
debug1: Entering interactive session for SSH2.
debug1: server_init_dispatch_20
debug1: server_input_channel_open: ctype session rchan 0 win 1048576 max 16384
debug1: input_session_request
debug1: channel 0: new [server-session]
debug1: session_new: session 0
debug1: session_open: channel 0
debug1: session_open: session 0: link with channel 0
debug1: server_input_channel_open: confirm session
debug1: server_input_global_request: rtype no-more-sessions@openssh.com want_reply 0
debug1: server_input_channel_req: channel 0 request x11-req reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req x11-req
debug1: channel 1: new [X11 inet listener]
debug1: channel 2: new [X11 inet listener]
debug1: server_input_channel_req: channel 0 request auth-agent-req@openssh.com reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req auth-agent-req@openssh.com
debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
debug1: restore_uid: (unprivileged)
debug1: channel 3: new [auth socket]
debug1: server_input_channel_req: channel 0 request pty-req reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req pty-req
debug1: Allocating pty.
debug1: session_new: session 0
debug1: SELinux support disabled
debug1: session_pty_req: session 0 alloc /dev/pts/1
debug1: server_input_channel_req: channel 0 request env reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req env
debug1: server_input_channel_req: channel 0 request shell reply 1
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req shell
Starting session: shell on pts/1 for vagrant from 10.11.12.1 port 39022
debug1: Setting controlling tty using TIOCSCTTY.
debug1: session_by_tty: session 0 tty /dev/pts/1
debug1: Unable to open session: The name org.freedesktop.ConsoleKit was not provided by any .service files
debug1: Received SIGCHLD.
debug1: session_by_pid: pid 4213
debug1: session_exit_message: session 0 channel 0 pid 4213
debug1: session_exit_message: release channel 0
debug1: session_by_tty: session 0 tty /dev/pts/1
debug1: session_pty_cleanup: session 0 release /dev/pts/1
debug1: unregistering ConsoleKit session (null)
Received disconnect from 10.11.12.1: 11: disconnected by user
debug1: do_cleanup
debug1: temporarily_use_uid: 1000/1000 (e=1000/1000)
debug1: restore_uid: (unprivileged)
debug1: do_cleanup
debug1: PAM: cleanup
debug1: PAM: closing session
debug1: PAM: deleting credentials
bd808 moved this task from Backlog to Done on the MediaWiki-Vagrant board.Jan 23 2017, 4:08 PM
Tgr mentioned this in T158258: Vagrant stops accepting SSH key after provisioning.Feb 15 2017, 11:53 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL