search

net-ssh / net-ssh

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

net-ssh freezes / hangs when using proxycommand #170

Closed madsheep closed 8 years ago

madsheep commented 10 years ago

for some servers we see the following issue:

This works perfectly: 

>ssh user@server hostname
=> server

with following ssh config and proxycommand 

Host server
  User user
  ProxyCommand ssh -A proxy_server nc %h %p
  ForwardAgent yes

but doing similar thing with net/ssh will hang forever: 

require 'net/ssh'
require 'net/ssh/proxy/command'

proxy = Net::SSH::Proxy::Command.new('ssh proxy_user@proxy_server nc %h %p')
Net::SSH.start(host, user, :proxy => proxy) do |ssh|
    puts ssh.exec!'hostname'
end

it outputs out the hostname of the server but it never exits the loop. I can see in the server logs that the session was established with no problems.

Digging in net/ssh codebase with pry brought me as far as:

https://github.com/net-ssh/net-ssh/blob/master/lib/net/ssh/transport/session.rb#L113

I can see that it's hanging on the close call of the IO socket. Following my 'gut feeling' I've modified the proxy command: 

proxy = Net::SSH::Proxy::Command.new('ssh proxy_user@proxy_server nc -q 1 %h %p')

which seems to have fixed the issue, but I'm not sure if this is a 'legit' fix: 

man nc | grep "\-q"
     -q seconds   after  EOF on stdin, wait the specified number of sec‐
                    onds and then quit. If seconds is negative, wait  for‐
                    ever.

I'm not even sure if this issue belongs to net/ssh but what I'm sure of it's not documented well - so far I've found only one person to mention this on SO:

http://stackoverflow.com/questions/19400903/ruby-net-ssh-wirth-proxy-command-causes-freeze/24488242#24488242

delano commented 10 years ago

Thanks for the detailed report.

saulcosta commented 8 years ago

What is the status of this issue?

mfazekas commented 8 years ago

Nothing, is this still an issue with latest relases?

saulcosta commented 8 years ago

From what I can tell, I'm running into the same issue on version 3.0.2. I can SSH into the server fine via command line, but Net::SSH hangs on close:

D, [2016-02-06T11:59:27.883374 #2366] DEBUG -- net.ssh.transport.session[3e4ea00]: establishing connection to <REDACTED HOSTNAME>:22
D, [2016-02-06T11:59:28.997308 #2366] DEBUG -- net.ssh.transport.session[3e4ea00]: connection established
I, [2016-02-06T11:59:28.997459 #2366]  INFO -- net.ssh.transport.server_version[3e4d574]: negotiating protocol version
D, [2016-02-06T11:59:29.006561 #2366] DEBUG -- net.ssh.transport.server_version[3e4d574]: remote is `SSH-2.0-OpenSSH_6.0p1 Debian-4+deb7u2'
D, [2016-02-06T11:59:29.006667 #2366] DEBUG -- net.ssh.transport.server_version[3e4d574]: local is `SSH-2.0-Ruby/Net::SSH_3.0.1 x86_64-linux'
D, [2016-02-06T11:59:29.091923 #2366] DEBUG -- io[3e4db14]: read 960 bytes
D, [2016-02-06T11:59:29.092065 #2366] DEBUG -- io[3e4db14]: received packet nr 0 type 20 len 956
I, [2016-02-06T11:59:29.092158 #2366]  INFO -- net.ssh.transport.algorithms[3e4bf80]: got KEXINIT from server
I, [2016-02-06T11:59:29.092298 #2366]  INFO -- net.ssh.transport.algorithms[3e4bf80]: sending KEXINIT
D, [2016-02-06T11:59:29.092499 #2366] DEBUG -- io[3e4db14]: queueing packet nr 0 type 20 len 1684
D, [2016-02-06T11:59:29.092563 #2366] DEBUG -- io[3e4db14]: sent 1688 bytes
I, [2016-02-06T11:59:29.092604 #2366]  INFO -- net.ssh.transport.algorithms[3e4bf80]: negotiating algorithms
D, [2016-02-06T11:59:29.092753 #2366] DEBUG -- net.ssh.transport.algorithms[3e4bf80]: negotiated:
* kex: diffie-hellman-group-exchange-sha1
* host_key: ssh-rsa
* encryption_server: aes128-cbc
* encryption_client: aes128-cbc
* hmac_client: hmac-sha1
* hmac_server: hmac-sha1
* compression_client: none
* compression_server: none
* language_client: 
* language_server: 
D, [2016-02-06T11:59:29.092830 #2366] DEBUG -- net.ssh.transport.algorithms[3e4bf80]: exchanging keys
D, [2016-02-06T11:59:29.093036 #2366] DEBUG -- io[3e4db14]: queueing packet nr 1 type 34 len 20
D, [2016-02-06T11:59:29.093090 #2366] DEBUG -- io[3e4db14]: sent 24 bytes
D, [2016-02-06T11:59:29.176534 #2366] DEBUG -- io[3e4db14]: read 152 bytes
D, [2016-02-06T11:59:29.176679 #2366] DEBUG -- io[3e4db14]: received packet nr 1 type 31 len 148
D, [2016-02-06T11:59:29.179071 #2366] DEBUG -- io[3e4db14]: queueing packet nr 2 type 32 len 140
D, [2016-02-06T11:59:29.179157 #2366] DEBUG -- io[3e4db14]: sent 144 bytes
D, [2016-02-06T11:59:29.263446 #2366] DEBUG -- io[3e4db14]: read 720 bytes
D, [2016-02-06T11:59:29.263621 #2366] DEBUG -- io[3e4db14]: received packet nr 2 type 33 len 700
D, [2016-02-06T11:59:29.265978 #2366] DEBUG -- io[3e4db14]: queueing packet nr 3 type 21 len 20
D, [2016-02-06T11:59:29.266070 #2366] DEBUG -- io[3e4db14]: sent 24 bytes
D, [2016-02-06T11:59:29.266177 #2366] DEBUG -- io[3e4db14]: received packet nr 3 type 21 len 12
D, [2016-02-06T11:59:29.266587 #2366] DEBUG -- net.ssh.authentication.session[23776f0]: beginning authentication of `root'
D, [2016-02-06T11:59:29.266754 #2366] DEBUG -- io[3e4db14]: queueing packet nr 4 type 5 len 28
D, [2016-02-06T11:59:29.266831 #2366] DEBUG -- io[3e4db14]: sent 52 bytes
D, [2016-02-06T11:59:29.387399 #2366] DEBUG -- io[3e4db14]: read 52 bytes
D, [2016-02-06T11:59:29.387564 #2366] DEBUG -- io[3e4db14]: received packet nr 4 type 6 len 28
D, [2016-02-06T11:59:29.387747 #2366] DEBUG -- net.ssh.authentication.session[23776f0]: trying none
D, [2016-02-06T11:59:29.387935 #2366] DEBUG -- io[3e4db14]: queueing packet nr 5 type 50 len 44
D, [2016-02-06T11:59:29.388030 #2366] DEBUG -- io[3e4db14]: sent 68 bytes
D, [2016-02-06T11:59:29.474574 #2366] DEBUG -- io[3e4db14]: read 68 bytes
D, [2016-02-06T11:59:29.474741 #2366] DEBUG -- io[3e4db14]: received packet nr 5 type 51 len 44
D, [2016-02-06T11:59:29.474906 #2366] DEBUG -- net.ssh.authentication.session[23776f0]: allowed methods: publickey,password
D, [2016-02-06T11:59:29.475023 #2366] DEBUG -- net.ssh.authentication.methods.none[2371a34]: none failed
D, [2016-02-06T11:59:29.475139 #2366] DEBUG -- net.ssh.authentication.session[23776f0]: trying publickey
D, [2016-02-06T11:59:29.475451 #2366] DEBUG -- net.ssh.authentication.agent[23683a8]: connecting to ssh-agent
D, [2016-02-06T11:59:29.475641 #2366] DEBUG -- net.ssh.authentication.agent[23683a8]: sending agent request 1 len 44
D, [2016-02-06T11:59:29.475844 #2366] DEBUG -- net.ssh.authentication.agent[23683a8]: received agent packet 2 len 5
D, [2016-02-06T11:59:29.475959 #2366] DEBUG -- net.ssh.authentication.agent[23683a8]: sending agent request 11 len 0
D, [2016-02-06T11:59:29.476159 #2366] DEBUG -- net.ssh.authentication.agent[23683a8]: received agent packet 12 len 316
D, [2016-02-06T11:59:29.476556 #2366] DEBUG -- net.ssh.authentication.methods.publickey[2368c90]: trying publickey (b5:94:82:9f:ec:e6:a5:0c:e1:03:67:f5:8c:43:da:eb)
D, [2016-02-06T11:59:29.476749 #2366] DEBUG -- io[3e4db14]: queueing packet nr 6 type 50 len 348
D, [2016-02-06T11:59:29.476846 #2366] DEBUG -- io[3e4db14]: sent 372 bytes
D, [2016-02-06T11:59:29.559110 #2366] DEBUG -- io[3e4db14]: read 68 bytes
D, [2016-02-06T11:59:29.559309 #2366] DEBUG -- io[3e4db14]: received packet nr 6 type 51 len 44
D, [2016-02-06T11:59:29.559448 #2366] DEBUG -- net.ssh.authentication.session[23776f0]: allowed methods: publickey,password
D, [2016-02-06T11:59:29.559609 #2366] DEBUG -- net.ssh.authentication.methods.publickey[2368c90]: trying publickey (d0:1e:94:ec:26:2c:4e:6c:32:da:bd:6b:76:4f:d7:45)
D, [2016-02-06T11:59:29.559775 #2366] DEBUG -- io[3e4db14]: queueing packet nr 7 type 50 len 348
D, [2016-02-06T11:59:29.559851 #2366] DEBUG -- io[3e4db14]: sent 372 bytes
D, [2016-02-06T11:59:29.643395 #2366] DEBUG -- io[3e4db14]: read 324 bytes
D, [2016-02-06T11:59:29.643568 #2366] DEBUG -- io[3e4db14]: received packet nr 7 type 60 len 300
D, [2016-02-06T11:59:29.647823 #2366] DEBUG -- io[3e4db14]: queueing packet nr 8 type 50 len 620
D, [2016-02-06T11:59:29.647914 #2366] DEBUG -- io[3e4db14]: sent 644 bytes
D, [2016-02-06T11:59:29.730460 #2366] DEBUG -- io[3e4db14]: read 36 bytes
D, [2016-02-06T11:59:29.730619 #2366] DEBUG -- io[3e4db14]: received packet nr 8 type 52 len 12
D, [2016-02-06T11:59:29.730713 #2366] DEBUG -- net.ssh.authentication.methods.publickey[2368c90]: publickey succeeded (d0:1e:94:ec:26:2c:4e:6c:32:da:bd:6b:76:4f:d7:45)
D, [2016-02-06T11:59:29.731005 #2366] DEBUG -- io[3e4db14]: queueing packet nr 9 type 90 len 44
D, [2016-02-06T11:59:29.731176 #2366] DEBUG -- io[3e4db14]: sent 68 bytes
D, [2016-02-06T11:59:29.813156 #2366] DEBUG -- io[3e4db14]: read 52 bytes
D, [2016-02-06T11:59:29.813340 #2366] DEBUG -- io[3e4db14]: received packet nr 9 type 91 len 28
I, [2016-02-06T11:59:29.813536 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_open_confirmation: 0 0 0 32768
I, [2016-02-06T11:59:29.813947 #2366]  INFO -- net.ssh.connection.channel[234004c]: sending channel request "env"
D, [2016-02-06T11:59:29.814131 #2366] DEBUG -- io[3e4db14]: queueing packet nr 10 type 98 len 44
I, [2016-02-06T11:59:29.814485 #2366]  INFO -- net.ssh.connection.channel[234004c]: sending channel request "exec"
D, [2016-02-06T11:59:29.814708 #2366] DEBUG -- io[3e4db14]: queueing packet nr 11 type 98 len 60
D, [2016-02-06T11:59:29.814849 #2366] DEBUG -- io[3e4db14]: sent 152 bytes
D, [2016-02-06T11:59:29.897555 #2366] DEBUG -- io[3e4db14]: read 88 bytes
D, [2016-02-06T11:59:29.897730 #2366] DEBUG -- io[3e4db14]: received packet nr 10 type 93 len 28
I, [2016-02-06T11:59:29.897833 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_window_adjust: 0 +2097152
D, [2016-02-06T11:59:29.897995 #2366] DEBUG -- io[3e4db14]: received packet nr 11 type 99 len 12
I, [2016-02-06T11:59:29.898085 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_success: 0
D, [2016-02-06T11:59:29.899104 #2366] DEBUG -- io[3e4db14]: read 68 bytes
D, [2016-02-06T11:59:29.899263 #2366] DEBUG -- io[3e4db14]: read 140 bytes
D, [2016-02-06T11:59:29.899468 #2366] DEBUG -- io[3e4db14]: received packet nr 12 type 94 len 44
I, [2016-02-06T11:59:29.899579 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_data: 0 17b
D, [2016-02-06T11:59:29.899718 #2366] DEBUG -- io[3e4db14]: received packet nr 13 type 98 len 44
I, [2016-02-06T11:59:29.899868 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_request: 0 exit-status false
D, [2016-02-06T11:59:29.900005 #2366] DEBUG -- io[3e4db14]: received packet nr 14 type 96 len 12
I, [2016-02-06T11:59:29.900091 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_eof: 0
D, [2016-02-06T11:59:29.900233 #2366] DEBUG -- io[3e4db14]: received packet nr 15 type 97 len 12
I, [2016-02-06T11:59:29.900318 #2366]  INFO -- net.ssh.connection.session[23401b4]: channel_close: 0
D, [2016-02-06T11:59:29.900452 #2366] DEBUG -- io[3e4db14]: queueing packet nr 12 type 97 len 28
[
    [0] "Command run here\n",
    [1] "",
    [2] 0
]
I, [2016-02-06T11:59:29.900987 #2366]  INFO -- net.ssh.connection.session[23401b4]: closing remaining channels (0 open)

<HANGS HERE>
mfazekas commented 8 years ago

What is the exact command you're using? It has best chance of fixing if we can figure out a way to reproduce. Optimal is an unit/integration test.

mfazekas commented 8 years ago

I've tried this:

require 'net/ssh'
require 'net/ssh/proxy/command'
proxy = Net::SSH::Proxy::Command.new("ssh #{ENV["USER"]}@127.0.0.1 nc %h %p")
Net::SSH.start('localhost', ENV["USER"], :proxy => proxy) do |ssh|
    puts ssh.exec!'hostname'
end

it did not hang for me on 3.1.0beta2

we'd also need stacktrace on the hangup pressing ctrl+C should show the sacktrace

mfazekas commented 8 years ago

will be reopened if we have new details