search

net-ssh / net-ssh

Pure Ruby implementation of an SSH (protocol 2) client
http://net-ssh.github.io/net-ssh
MIT License
988 stars 449 forks source link

Pubkey authentication results in SSH::Disconnect from server in Net-SSH 7.2 #920

Closed nathansamson closed 7 months ago

nathansamson commented 1 year ago

Expected behavior

Net-SSH does not connect anymore in net-ssh 7.2 with a certain server (this might very well be a server issue, but it worked in net-ssh 6.2).

I do not control the server or can access their logs. I can help providing debug info from my side if possible...

Actual behavior

Server disconnects

D, [2023-08-09T18:29:29.351860 #68872] DEBUG -- net.ssh.transport.session[97cc]: establishing connection to redacted:8022
D, [2023-08-09T18:29:29.361517 #68872] DEBUG -- net.ssh.transport.session[97cc]: connection established
I, [2023-08-09T18:29:29.361602 #68872]  INFO -- net.ssh.transport.server_version[97e0]: negotiating protocol version
D, [2023-08-09T18:29:29.361617 #68872] DEBUG -- net.ssh.transport.server_version[97e0]: local is `SSH-2.0-Ruby/Net::SSH_7.2.0 x86_64-linux'
D, [2023-08-09T18:29:29.371049 #68872] DEBUG -- net.ssh.transport.server_version[97e0]: remote is `SSH-2.0-JSCAPE'
I, [2023-08-09T18:29:29.371301 #68872]  INFO -- net.ssh.transport.algorithms[97f4]: sending KEXINIT
D, [2023-08-09T18:29:29.371560 #68872] DEBUG -- socket[9808]: queueing packet nr 0 type 20 len 860
D, [2023-08-09T18:29:29.371647 #68872] DEBUG -- socket[9808]: sent 864 bytes
D, [2023-08-09T18:29:29.374154 #68872] DEBUG -- socket[9808]: read 360 bytes
D, [2023-08-09T18:29:29.374238 #68872] DEBUG -- socket[9808]: received packet nr 0 type 20 len 356
I, [2023-08-09T18:29:29.374290 #68872]  INFO -- net.ssh.transport.algorithms[97f4]: got KEXINIT from server
I, [2023-08-09T18:29:29.374360 #68872]  INFO -- net.ssh.transport.algorithms[97f4]: negotiating algorithms
D, [2023-08-09T18:29:29.374553 #68872] DEBUG -- net.ssh.transport.algorithms[97f4]: negotiated:
* kex: diffie-hellman-group-exchange-sha256
* host_key: ssh-rsa
* encryption_server: aes256-ctr
* encryption_client: aes256-ctr
* hmac_client: hmac-sha2-512
* hmac_server: hmac-sha2-512
* compression_client: none
* compression_server: none
* language_client: 
* language_server: 
D, [2023-08-09T18:29:29.374574 #68872] DEBUG -- net.ssh.transport.algorithms[97f4]: exchanging keys
D, [2023-08-09T18:29:29.375686 #68872] DEBUG -- socket[9808]: queueing packet nr 1 type 34 len 20
D, [2023-08-09T18:29:29.375720 #68872] DEBUG -- socket[9808]: sent 24 bytes
D, [2023-08-09T18:29:29.389318 #68872] DEBUG -- socket[9808]: read 1048 bytes
D, [2023-08-09T18:29:29.389560 #68872] DEBUG -- socket[9808]: received packet nr 1 type 31 len 1044
D, [2023-08-09T18:29:29.403200 #68872] DEBUG -- socket[9808]: queueing packet nr 2 type 32 len 1036
D, [2023-08-09T18:29:29.403234 #68872] DEBUG -- socket[9808]: sent 1040 bytes
D, [2023-08-09T18:29:31.682308 #68872] DEBUG -- socket[9808]: received packet nr 2 type 33 len 2108
D, [2023-08-09T18:29:31.774122 #68872] DEBUG -- socket[9808]: queueing packet nr 3 type 21 len 20
D, [2023-08-09T18:29:31.774205 #68872] DEBUG -- socket[9808]: sent 24 bytes
D, [2023-08-09T18:29:31.774239 #68872] DEBUG -- socket[9808]: received packet nr 3 type 21 len 12
D, [2023-08-09T18:29:31.774505 #68872] DEBUG -- net.ssh.authentication.session[981c]: beginning authentication of `REDACTED'
D, [2023-08-09T18:29:31.774635 #68872] DEBUG -- socket[9808]: queueing packet nr 4 type 5 len 28
D, [2023-08-09T18:29:31.774648 #68872] DEBUG -- socket[9808]: sent 96 bytes
D, [2023-08-09T18:29:31.789049 #68872] DEBUG -- socket[9808]: read 96 bytes
D, [2023-08-09T18:29:31.789158 #68872] DEBUG -- socket[9808]: received packet nr 4 type 6 len 28
D, [2023-08-09T18:29:31.789212 #68872] DEBUG -- net.ssh.authentication.session[981c]: trying none
D, [2023-08-09T18:29:31.789280 #68872] DEBUG -- socket[9808]: queueing packet nr 5 type 50 len 60
D, [2023-08-09T18:29:31.789300 #68872] DEBUG -- socket[9808]: sent 128 bytes
D, [2023-08-09T18:29:31.797563 #68872] DEBUG -- socket[9808]: read 96 bytes
D, [2023-08-09T18:29:31.797664 #68872] DEBUG -- socket[9808]: received packet nr 5 type 51 len 28
D, [2023-08-09T18:29:31.797690 #68872] DEBUG -- net.ssh.authentication.session[981c]: allowed methods: publickey
D, [2023-08-09T18:29:31.797713 #68872] DEBUG -- net.ssh.authentication.methods.none[9830]: none failed
D, [2023-08-09T18:29:31.797787 #68872] DEBUG -- net.ssh.authentication.session[981c]: trying publickey
D, [2023-08-09T18:29:31.799085 #68872] DEBUG -- net.ssh.authentication.methods.publickey[9858]: trying publickey (c3:e2:e0:25:29:37:d1:a4:5b:90:47:2e:8c:7e:ac:29) alg rsa-sha2-256
D, [2023-08-09T18:29:31.799162 #68872] DEBUG -- socket[9808]: queueing packet nr 6 type 50 len 364
D, [2023-08-09T18:29:31.799198 #68872] DEBUG -- socket[9808]: sent 432 bytes
D, [2023-08-09T18:29:31.807090 #68872] DEBUG -- socket[9808]: read 384 bytes
D, [2023-08-09T18:29:31.807216 #68872] DEBUG -- socket[9808]: received packet nr 6 type 60 len 316
D, [2023-08-09T18:29:31.808179 #68872] DEBUG -- socket[9808]: queueing packet nr 7 type 50 len 636
D, [2023-08-09T18:29:31.808209 #68872] DEBUG -- socket[9808]: sent 704 bytes
D, [2023-08-09T18:29:31.815777 #68872] DEBUG -- socket[9808]: read 0 bytes
/home/nathan/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/net-ssh-7.2.0/lib/net/ssh/transport/packet_stream.rb:108:in `block in next_packet': connection closed by remote host (Net::SSH::Disconnect)

System configuration

(Same output for same operation on same server with working versions)

D, [2023-08-09T18:30:58.479853 #68993] DEBUG -- net.ssh.transport.session[53e8]: establishing connection to redacted:8022
D, [2023-08-09T18:30:58.489474 #68993] DEBUG -- net.ssh.transport.session[53e8]: connection established
I, [2023-08-09T18:30:58.489550 #68993]  INFO -- net.ssh.transport.server_version[53fc]: negotiating protocol version
D, [2023-08-09T18:30:58.489562 #68993] DEBUG -- net.ssh.transport.server_version[53fc]: local is `SSH-2.0-Ruby/Net::SSH_6.1.0 x86_64-linux'
D, [2023-08-09T18:30:58.498070 #68993] DEBUG -- net.ssh.transport.server_version[53fc]: remote is `SSH-2.0-JSCAPE'
I, [2023-08-09T18:30:58.498226 #68993]  INFO -- net.ssh.transport.algorithms[5410]: sending KEXINIT
D, [2023-08-09T18:30:58.498426 #68993] DEBUG -- socket[5424]: queueing packet nr 0 type 20 len 804
D, [2023-08-09T18:30:58.498489 #68993] DEBUG -- socket[5424]: sent 808 bytes
D, [2023-08-09T18:30:58.498937 #68993] DEBUG -- socket[5424]: read 360 bytes
D, [2023-08-09T18:30:58.499010 #68993] DEBUG -- socket[5424]: received packet nr 0 type 20 len 356
I, [2023-08-09T18:30:58.499066 #68993]  INFO -- net.ssh.transport.algorithms[5410]: got KEXINIT from server
I, [2023-08-09T18:30:58.499116 #68993]  INFO -- net.ssh.transport.algorithms[5410]: negotiating algorithms
D, [2023-08-09T18:30:58.499303 #68993] DEBUG -- net.ssh.transport.algorithms[5410]: negotiated:
* kex: diffie-hellman-group-exchange-sha256
* host_key: ssh-rsa
* encryption_server: aes256-ctr
* encryption_client: aes256-ctr
* hmac_client: hmac-sha2-512
* hmac_server: hmac-sha2-512
* compression_client: none
* compression_server: none
* language_client: 
* language_server: 
D, [2023-08-09T18:30:58.499319 #68993] DEBUG -- net.ssh.transport.algorithms[5410]: exchanging keys
D, [2023-08-09T18:30:58.499444 #68993] DEBUG -- socket[5424]: queueing packet nr 1 type 34 len 20
D, [2023-08-09T18:30:58.499462 #68993] DEBUG -- socket[5424]: sent 24 bytes
D, [2023-08-09T18:30:58.514888 #68993] DEBUG -- socket[5424]: read 1048 bytes
D, [2023-08-09T18:30:58.515199 #68993] DEBUG -- socket[5424]: received packet nr 1 type 31 len 1044
D, [2023-08-09T18:30:58.626258 #68993] DEBUG -- socket[5424]: queueing packet nr 2 type 32 len 1036
D, [2023-08-09T18:30:58.626316 #68993] DEBUG -- socket[5424]: sent 1040 bytes
D, [2023-08-09T18:31:00.991055 #68993] DEBUG -- socket[5424]: read 2112 bytes
D, [2023-08-09T18:31:00.991402 #68993] DEBUG -- socket[5424]: received packet nr 2 type 33 len 2108
D, [2023-08-09T18:31:01.007057 #68993] DEBUG -- socket[5424]: queueing packet nr 3 type 21 len 20
D, [2023-08-09T18:31:01.007105 #68993] DEBUG -- socket[5424]: sent 24 bytes
D, [2023-08-09T18:31:01.007128 #68993] DEBUG -- socket[5424]: read 16 bytes
D, [2023-08-09T18:31:01.007147 #68993] DEBUG -- socket[5424]: received packet nr 3 type 21 len 12
D, [2023-08-09T18:31:01.007286 #68993] DEBUG -- net.ssh.authentication.session[5438]: beginning authentication of `REDACTED'
D, [2023-08-09T18:31:01.007333 #68993] DEBUG -- socket[5424]: queueing packet nr 4 type 5 len 28
D, [2023-08-09T18:31:01.007342 #68993] DEBUG -- socket[5424]: sent 96 bytes
D, [2023-08-09T18:31:01.023201 #68993] DEBUG -- socket[5424]: read 96 bytes
D, [2023-08-09T18:31:01.023333 #68993] DEBUG -- socket[5424]: received packet nr 4 type 6 len 28
D, [2023-08-09T18:31:01.023412 #68993] DEBUG -- net.ssh.authentication.session[5438]: trying none
D, [2023-08-09T18:31:01.023501 #68993] DEBUG -- socket[5424]: queueing packet nr 5 type 50 len 60
D, [2023-08-09T18:31:01.023543 #68993] DEBUG -- socket[5424]: sent 128 bytes
D, [2023-08-09T18:31:01.036142 #68993] DEBUG -- socket[5424]: read 96 bytes
D, [2023-08-09T18:31:01.036290 #68993] DEBUG -- socket[5424]: received packet nr 5 type 51 len 28
D, [2023-08-09T18:31:01.036359 #68993] DEBUG -- net.ssh.authentication.session[5438]: allowed methods: publickey
D, [2023-08-09T18:31:01.036410 #68993] DEBUG -- net.ssh.authentication.methods.none[544c]: none failed
D, [2023-08-09T18:31:01.036515 #68993] DEBUG -- net.ssh.authentication.session[5438]: trying publickey
D, [2023-08-09T18:31:01.036870 #68993] DEBUG -- net.ssh.authentication.methods.publickey[5474]: trying publickey (c3:e2:e0:25:29:37:d1:a4:5b:90:47:2e:8c:7e:ac:29)
D, [2023-08-09T18:31:01.037072 #68993] DEBUG -- socket[5424]: queueing packet nr 6 type 50 len 364
D, [2023-08-09T18:31:01.037157 #68993] DEBUG -- socket[5424]: sent 432 bytes
D, [2023-08-09T18:31:01.047211 #68993] DEBUG -- socket[5424]: read 368 bytes
D, [2023-08-09T18:31:01.047464 #68993] DEBUG -- socket[5424]: received packet nr 6 type 60 len 300
D, [2023-08-09T18:31:01.050065 #68993] DEBUG -- socket[5424]: queueing packet nr 7 type 50 len 636
D, [2023-08-09T18:31:01.050137 #68993] DEBUG -- socket[5424]: sent 704 bytes
D, [2023-08-09T18:31:01.237580 #68993] DEBUG -- socket[5424]: read 80 bytes
D, [2023-08-09T18:31:01.238037 #68993] DEBUG -- socket[5424]: received packet nr 7 type 52 len 12
D, [2023-08-09T18:31:01.238189 #68993] DEBUG -- net.ssh.authentication.methods.publickey[5474]: publickey succeeded (c3:e2:e0:25:29:37:d1:a4:5b:90:47:2e:8c:7e:ac:29)
I, [2023-08-09T18:31:01.238415 #68993]  INFO -- net.ssh.connection.session[5488]: closing remaining channels (0 open)

Example App

Net::SSH.start(
  'redacted',
  "redacted",
  keys: ["./path/redacted"],
  verbose: :debug,
  use_agent: false,
  port: 8022) do |ssh|
  end
zzambers commented 1 year ago

Hello @nathansamson,

I think problem is that server is sending disconnect on RSA+SHA2 attempt (even thought this should not be error). For now, it should be workaroundable with pubkey_algorithms option, see: https://github.com/net-ssh/net-ssh/pull/891

Implementing server-sig-algs extension could possibly make this work out of box. (I have seen some work on this in one net-ssh fork https://github.com/znewsham/net-ssh/pull/1)

For more in depth details about current approach for RSA keys (+ rationale), see my comment here: https://github.com/net-ssh/net-ssh/issues/886#issuecomment-1331126167

mfazekas commented 1 year ago

@zzambers thanks much for the input on this, really useful

nathansamson commented 7 months ago

I forgot to comment but passing pubkey_algorithms: ['ssh-rsa'] fixes this issue.

I think we can close this issue