Possible bug found in SSHD and tunneling(Based on question number 43605)

[Bhavani Shankar]

I've run into a very strange phenomenom that I'm hoping someone can help me with. I've debugged it from all angles and everything points back to ubuntu and sshd (or a library it depends on). Here's the scenario:

At my office, I am sshing to my home machine using putty and setting up a dynamic socks proxy on port 8080. When I point my firefox 3 (or firefox 2, or ie 7, I tried them all) to the localhost:8080 and surf the web (specifically lifehacker.com due to it's massive number of external links), the web pages renders through once. Then if I do a shift-refresh, it starts to load again, then hangs. My putty ssh session is hung also. I can however fire up a second putty session into my home machine and it responds fine. My home linux machine can also still go out on the internet, surf from the console (vnc) etc just fine.

So.. after trying out all the browsers, I thought, well, maybe it's my router.. (whr-g125 running dd-wrt 2.4sp1). So .. I made my router itself open via ssh to the internet, and tunneled (ssh'd) in directly to my router. The socks proxy using Firefox worked just fine, refreshing over and over without incident.

So now I thought "It must be the sshd on ubuntu". So I downloaded the latest Openssh Portable 5.1p1 and compiled it from source. Fired up a new putty session to tunnel, refreshed the browser, same hang.. browser quits pulling up website, putty session hung.

So finally, I fired up a brand new Fedora 9 instance in my ubuntu server (using vbox), told my router to redirect to it's sshd, and connected from my work machine directly to Fedora 9 VM. Lo and behold, it worked just fine refreshing lifehacker.com over and over.

So .. the $64,000 question is what library or networking code does ssh compile against that could be causing the ssh channels via socks to not free up (or get overloaded)? I have attached a snipped of the sshd running in debug mode to glean some insight (the final entry is the last time returned before hang). The only difference I can see from the ubuntu sshd logs vs the fedora sshd logs is fedora seems to instantly free up the 'nchannels' as soon as the browser has finished loading the page. I did not see that same behavior from the ubuntu sshd dump (stuck upwards of 33 nchannels).

Thanks!

-----snip from tail end of log before hang-----
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 14: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 15: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 16: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 17: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 18: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 19: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 20: connected Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 277 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 22: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 278 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 23: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 279 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 24: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 280 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 25: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 281 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 26: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 282 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 27: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 283 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 28: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 284 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 29: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 285 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 30: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 286 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target tags.lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 31: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 287 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target lifehacker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 32: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 288 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:47 trinity sshd[28749]: debug1: channel 33: new [direct-tcpip] Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:47 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 289 win 16384 max 16384 Aug 29 17:50:47 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 34: new [direct-tcpip] Aug 29 17:50:48 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:48 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 290 win 16384 max 16384 Aug 29 17:50:48 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 35: new [direct-tcpip] Aug 29 17:50:48 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 4: free:
direct-tcpip, nchannels 37
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 5: free:
direct-tcpip, nchannels 36
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 6: free:
direct-tcpip, nchannels 35
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 11: free:
direct-tcpip, nchannels 34
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 45: free:
direct-tcpip, nchannels 33
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 21: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 22: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 23: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 24: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 25: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 26: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 27: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 28: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 29: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 30: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 31: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 32: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 33: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 34: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 35: connected Aug 29 17:50:48 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 259 win 16384 max 16384 Aug 29 17:50:48 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 4: new [direct-tcpip] Aug 29 17:50:48 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 7: free:
direct-tcpip, nchannels 33
Aug 29 17:50:48 trinity sshd[28749]: debug1: channel 8: free:
direct-tcpip, nchannels 32
Aug 29 17:50:48 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 260 win 16384 max 16384 Aug 29 17:50:48 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:49 trinity sshd[28749]: debug1: channel 5: new [direct-tcpip] Aug 29 17:50:49 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:49 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 261 win 16384 max 16384 Aug 29 17:50:49 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:49 trinity sshd[28749]: debug1: channel 6: new [direct-tcpip] Aug 29 17:50:49 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip
Aug 29 17:50:49 trinity sshd[28749]: debug1: channel 2: free:
direct-tcpip, nchannels 33
Aug 29 17:50:49 trinity sshd[28749]: debug1: channel 19: free:
direct-tcpip, nchannels 32
Aug 29 17:50:49 trinity sshd[28749]: debug1: server_input_channel_open:
ctype direct-tcpip rchan 266 win 16384 max 16384 Aug 29 17:50:49 trinity sshd[28749]: debug1: server_request_direct_tcpip:
originator 0.0.0.0 port 0, target cache.gawker.com port 80 Aug 29 17:50:49 trinity sshd[28749]: debug1: channel 2: new [direct-tcpip] Aug 29 17:50:49 trinity sshd[28749]: debug1: server_input_channel_open:
confirm direct-tcpip

[Bhavani Shankar (bhavi)]

question owner gave more info about the bug (refer below)

http://osdir.com/ml/network.openssh.general/2006-11/msg00047.html

debug2: channel 9: read<=0 rfd 19 len 0
debug2: channel 9: read failed
debug2: channel 9: close_read
debug2: channel 9: input open -> drain
debug2: channel 3: read<=0 rfd 13 len 0
debug2: channel 3: read failed
debug2: channel 3: close_read
debug2: channel 3: input open -> drain
debug2: channel 6: read<=0 rfd 16 len 0
debug2: channel 6: read failed
debug2: channel 6: close_read
debug2: channel 6: input open -> drain
debug2: channel 2: read<=0 rfd 12 len 0
debug2: channel 2: read failed
debug2: channel 2: close_read
debug2: channel 2: input open -> drain
debug2: channel 4: read<=0 rfd 14 len 0
debug2: channel 4: read failed
debug2: channel 4: close_read
debug2: channel 4: input open -> drain
debug2: channel 13: read<=0 rfd 23 len 0
debug2: channel 13: read failed
debug2: channel 13: close_read
debug2: channel 13: input open -> drain
debug2: channel 14: read<=0 rfd 24 len 0
debug2: channel 14: read failed
debug2: channel 14: close_read
debug2: channel 14: input open -> drain
debug2: channel 8: read<=0 rfd 18 len 0
debug2: channel 8: read failed
debug2: channel 8: close_read
debug2: channel 8: input open -> drain

So confirming.

[Marko Kevac (mkevac)]

Same here with Karmic.

I am creating ssh tunnel (port forwarding) to my home machine.

11 concurrent connections work, more than 11 freezes tunnel completely.

If creating tunnel to same machine from another machine with OpenSUSE, everything is fine.

[Tom Moore (mooret01)]

BTW - I may have found the smoking gun to this. It seems if I tell the browser NOT to perform remote DNS lookups through the tunnel, the sessions do not hang. So I'm not sure if it's something to do with the way ubuntu/sshd handles DNS lookups through a socks proxy?

[Tom Moore (tmoore01)]

FYI.. this is probably related to SSHD and not ubuntu. This happens on archlinux as well, and may have something to do with DNS lookups that are forwarded through the SSH proxy. Changing "AddressFamily inet" in sshd_config may help, as that prevents the dns from doing ipv6 lookups.

[Ken Sharp (kennybobs)]

tldr; Can you give this a more sensible title?