authenticationsshcapistranocapistrano3sshkit

Capistrano can't deploy to new Ubuntu server because SSHKit / Net::SSH can't authenticate


I'm trying to set up a staging/testing server for a new version of an application I'm working on. So I have set it up so that my local account can authenticate into the deployment server without having to type in a password:

$ ssh tester@app-staging.acme.com
Welcome to Ubuntu 16.04 LTS (GNU/Linux 4.4.0-28-generic x86_64)

 * Documentation:  https://help.ubuntu.com
 * Management:     https://landscape.canonical.com
 * Support:        https://ubuntu.com/advantage

0 packages can be updated.
0 updates are security updates.

Last login: Thu Jul  7 15:53:38 2016 from 10.10.12.50
tester@app-staging:~$ logout

Now I try to get in with Capistrano, but it just rejects me straight away:

$ cap staging deploy:check

$ cap staging deploy:check
(Backtrace restricted to imported tasks)
cap aborted!
Net::SSH::AuthenticationFailed: Authentication failed for user tester@app-staging.acme.com

Tasks: TOP => rbenv:validate
(See full trace by running task with --trace)

Investigation so far:

Now I'm kind of out of ideas for how to diagnose this.

I can't tell whether there is any Capistrano equivalent to ssh -v in order to get more information about what it's trying to do.

Clearly my SSH connection is fine, but Capistrano isn't using the right settings to connect, so maybe I have the syntax wrong or something equally obvious. To that end, here are the files I currently have:

Capfile:

require 'capistrano/setup'
require 'capistrano/deploy'
require 'capistrano/rbenv'
require 'capistrano/bundler'
require 'capistrano/rails/assets'
require 'capistrano/rails/migrations'
require 'capistrano/nginx'

Dir.glob("lib/capistrano/tasks/*.rake").each { |r| import r }

config/deploy.rb:

lock '3.5.0'

set :application, 'app'

set :scm, :svn
set :repo_url, 'https://svn.acme.com/app/trunk'

set :ssh_options, {
  auth_methods: ['publickey'],
  keys: ['~/.ssh/id_ed25519'],
}

config/deploy/staging.rb:

set :rails_env, 'staging'

server 'all-staging.acme.com', user: 'tester', port: 22,
       roles: %w{web app db}

set :deploy_to, '/var/www/app/staging'

Chasing the problem into sshkit:

I noticed that capistrano uses sshkit to do the actual SSH work, so I wrote a test program for that.

#!/usr/bin/env ruby

require 'sshkit'
require 'sshkit/dsl'

include SSHKit::DSL

SSHKit.config.output_verbosity = Logger::DEBUG

on 'tester@app-staging.acme.com' do
  puts capture(:ls, '-l')
end

This exhibits the same issue, where it asks for the password despite supposedly defaulting to use the same key. Although setting the verbosity to DEBUG hasn't really added any useful diagnostics to go work.

Chasing the problem into Net::SSH:

When installing gems for sshkit, I noticed that it was using yet another SSH library, net-ssh, to do the actual SSH work, so I tried making a new test program which just used that.

$ cat test 
#!/usr/bin/env ruby

require 'net/ssh'

Net::SSH.start('portal-staging.syd.nuix.com', 'tester', verbose: :debug) do |ssh|
  output = ssh.exec!("ls -l")
  puts output
end

This time, the debug output is useful:

$ ./test 
D, [2016-07-08T10:52:56.725877 #56100] DEBUG -- net.ssh.transport.session[3fe8c6916074]: establishing connection to app-staging.acme.com:22
D, [2016-07-08T10:52:56.727988 #56100] DEBUG -- net.ssh.transport.session[3fe8c6916074]: connection established
I, [2016-07-08T10:52:56.728056 #56100]  INFO -- net.ssh.transport.server_version[3fe8c6913414]: negotiating protocol version
D, [2016-07-08T10:52:56.728080 #56100] DEBUG -- net.ssh.transport.server_version[3fe8c6913414]: local is `SSH-2.0-Ruby/Net::SSH_3.1.1 x86_64-darwin13.0'
D, [2016-07-08T10:52:56.749127 #56100] DEBUG -- net.ssh.transport.server_version[3fe8c6913414]: remote is `SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu1'
D, [2016-07-08T10:52:56.750086 #56100] DEBUG -- socket[3fe8c6913ae0]: read 976 bytes
D, [2016-07-08T10:52:56.750166 #56100] DEBUG -- socket[3fe8c6913ae0]: received packet nr 0 type 20 len 972
I, [2016-07-08T10:52:56.750219 #56100]  INFO -- net.ssh.transport.algorithms[3fe8c690fddc]: got KEXINIT from server
I, [2016-07-08T10:52:56.750326 #56100]  INFO -- net.ssh.transport.algorithms[3fe8c690fddc]: sending KEXINIT
D, [2016-07-08T10:52:56.750437 #56100] DEBUG -- socket[3fe8c6913ae0]: queueing packet nr 0 type 20 len 1684
D, [2016-07-08T10:52:56.750504 #56100] DEBUG -- socket[3fe8c6913ae0]: sent 1688 bytes
I, [2016-07-08T10:52:56.750531 #56100]  INFO -- net.ssh.transport.algorithms[3fe8c690fddc]: negotiating algorithms
D, [2016-07-08T10:52:56.750628 #56100] DEBUG -- net.ssh.transport.algorithms[3fe8c690fddc]: negotiated:
* kex: diffie-hellman-group14-sha1
* host_key: ecdsa-sha2-nistp256
* 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, [2016-07-08T10:52:56.750654 #56100] DEBUG -- net.ssh.transport.algorithms[3fe8c690fddc]: exchanging keys
D, [2016-07-08T10:52:56.752145 #56100] DEBUG -- socket[3fe8c6913ae0]: queueing packet nr 1 type 30 len 268
D, [2016-07-08T10:52:56.752209 #56100] DEBUG -- socket[3fe8c6913ae0]: sent 272 bytes
D, [2016-07-08T10:52:56.753413 #56100] DEBUG -- socket[3fe8c6913ae0]: read 504 bytes
D, [2016-07-08T10:52:56.753475 #56100] DEBUG -- socket[3fe8c6913ae0]: received packet nr 1 type 31 len 484
D, [2016-07-08T10:52:56.754718 #56100] DEBUG -- socket[3fe8c6913ae0]: queueing packet nr 2 type 21 len 20
D, [2016-07-08T10:52:56.754785 #56100] DEBUG -- socket[3fe8c6913ae0]: sent 24 bytes
D, [2016-07-08T10:52:56.754829 #56100] DEBUG -- socket[3fe8c6913ae0]: received packet nr 2 type 21 len 12
D, [2016-07-08T10:52:56.755084 #56100] DEBUG -- net.ssh.authentication.session[3fe8c68d21bc]: beginning authentication of `tester'
D, [2016-07-08T10:52:56.755183 #56100] DEBUG -- socket[3fe8c6913ae0]: queueing packet nr 3 type 5 len 28
D, [2016-07-08T10:52:56.755222 #56100] DEBUG -- socket[3fe8c6913ae0]: sent 52 bytes
D, [2016-07-08T10:52:56.793167 #56100] DEBUG -- socket[3fe8c6913ae0]: read 52 bytes
D, [2016-07-08T10:52:56.793356 #56100] DEBUG -- socket[3fe8c6913ae0]: received packet nr 3 type 6 len 28
D, [2016-07-08T10:52:56.793467 #56100] DEBUG -- net.ssh.authentication.session[3fe8c68d21bc]: trying none
D, [2016-07-08T10:52:56.793589 #56100] DEBUG -- socket[3fe8c6913ae0]: queueing packet nr 4 type 50 len 44
D, [2016-07-08T10:52:56.793640 #56100] DEBUG -- socket[3fe8c6913ae0]: sent 68 bytes
D, [2016-07-08T10:52:56.795136 #56100] DEBUG -- socket[3fe8c6913ae0]: read 68 bytes
D, [2016-07-08T10:52:56.795258 #56100] DEBUG -- socket[3fe8c6913ae0]: received packet nr 4 type 51 len 44
D, [2016-07-08T10:52:56.795319 #56100] DEBUG -- net.ssh.authentication.session[3fe8c68d21bc]: allowed methods: publickey,password
D, [2016-07-08T10:52:56.795361 #56100] DEBUG -- net.ssh.authentication.methods.none[3fe8c68cb18c]: none failed
D, [2016-07-08T10:52:56.795404 #56100] DEBUG -- net.ssh.authentication.session[3fe8c68d21bc]: trying publickey
E, [2016-07-08T10:52:56.795652 #56100] ERROR -- net.ssh.authentication.key_manager[3fe8c68cbad8]: could not load public key file `/Users/tester/.ssh/id_ed25519.pub': Net::SSH::Exception (public key at /Users/tester/.ssh/id_ed25519.pub is not valid)
D, [2016-07-08T10:52:56.795787 #56100] DEBUG -- net.ssh.authentication.agent[3fe8c68c2dfc]: connecting to ssh-agent
D, [2016-07-08T10:52:56.795868 #56100] DEBUG -- net.ssh.authentication.agent[3fe8c68c2dfc]: sending agent request 1 len 49
D, [2016-07-08T10:52:56.795972 #56100] DEBUG -- net.ssh.authentication.agent[3fe8c68c2dfc]: received agent packet 2 len 5
D, [2016-07-08T10:52:56.796016 #56100] DEBUG -- net.ssh.authentication.agent[3fe8c68c2dfc]: sending agent request 11 len 0
D, [2016-07-08T10:52:56.796136 #56100] DEBUG -- net.ssh.authentication.agent[3fe8c68c2dfc]: received agent packet 12 len 550
E, [2016-07-08T10:52:56.796241 #56100] ERROR -- net.ssh.authentication.agent[3fe8c68c2dfc]: ignoring unimplemented key:unsupported key type `ssh-ed25519' tester@bucket.local
D, [2016-07-08T10:52:56.796414 #56100] DEBUG -- net.ssh.authentication.methods.publickey[3fe8c68c3e64]: trying publickey (4b:98:3b:de:13:27:69:2e:75:84:58:0b:4b:43:70:2f)
D, [2016-07-08T10:52:56.796677 #56100] DEBUG -- socket[3fe8c6913ae0]: queueing packet nr 5 type 50 len 508
D, [2016-07-08T10:52:56.796729 #56100] DEBUG -- socket[3fe8c6913ae0]: sent 532 bytes
D, [2016-07-08T10:52:56.797367 #56100] DEBUG -- socket[3fe8c6913ae0]: read 68 bytes
D, [2016-07-08T10:52:56.797440 #56100] DEBUG -- socket[3fe8c6913ae0]: received packet nr 5 type 51 len 44
D, [2016-07-08T10:52:56.797513 #56100] DEBUG -- net.ssh.authentication.session[3fe8c68d21bc]: allowed methods: publickey,password
D, [2016-07-08T10:52:56.797546 #56100] DEBUG -- net.ssh.authentication.session[3fe8c68d21bc]: trying password
[at this point I interrupt the process]

So it kind of seems like it only tries one of my keys, deeming it invalid, and logs that it's unsupported a few lines down. There is another key in my .ssh directory which seemingly isn't even getting tried.


Solution

  • It looks like ed25519 keys are supported by Net SSH 4.0.0alpha1-4.

    https://github.com/net-ssh/net-ssh/issues/214

    You probably can use RSA keys, upgrade to net-ssh 4.0.0alpha4, or possibly use SSH Agent to get around this.