openssh bugs - Nov 2006 - [Bug 1263] connection sharing often freezes

http://bugzilla.mindrot.org/show_bug.cgi?id=1263

           Summary: connection sharing often freezes
           Product: Portable OpenSSH
           Version: v4.5p1
          Platform: PPC
        OS/Version: Mac OS X
            Status: NEW
          Severity: major
          Priority: P2
         Component: ssh
        AssignedTo: bitbucket at mindrot.org
        ReportedBy: vincent at vinc17.org


I use connection sharing with Subversion; it was working well in the
past, but for several days (after I updated OpenSSH, in particular),
I've had many problems with it: ssh often freezes. I've tried with two
servers, and I have the same problem with both. For the test, I've used
the following wrapper:

#!/usr/bin/env zsh

source ~/.zshenv
source ~/.zalias
unset DISPLAY

[[ $1 != ay || -e /tmp/ssh-ay.vinc17.org-22-lefevre ]] ||
  (echo "Starting master" >&2; ssh -fMNv ay >&
~/master.log)

echo "executing ssh" >&2
ssh -Cvvv "$@"

Note: I use only the -v option for the master since I can't reproduce
the bug with -vv or -vvv (perhaps I haven't tried hard).

On the remote side (ay, which is a Debian testing/unstable machine with
OpenSSH_4.3p2 Debian-5.1), I have a .ssh/rc file that contains:

case "$OSTYPE" in
  solaris*)  ip="`echo $SSH_CONNECTION | sed 's/ .*//'`";;
  *)         ip="${SSH_CONNECTION%% *}";;
esac

: ${HOST:=`hostname`}
echo "Connected to $HOST (from $ip)" >&2

if read proto cookie && [ -n "$DISPLAY" ]; then
  [ "$HOST" = prunille.vinc17.org ] &&
PATH=${PATH}:/usr/X11R6/bin
  if [ `echo $DISPLAY | cut -c1-10` = 'localhost:' ]; then
    echo add unix:`echo $DISPLAY | cut -c11-` $proto $cookie
  else
    echo add $DISPLAY $proto $cookie
  fi | xauth -q -
fi

I'm going to attach the master.log file and a file containing the two
(identical) commands I've typed from the terminal on my Mac OS X
machine (prunille), and you'll see the point where the second one
freezes.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #1 from vincent at vinc17.org  2006-11-20 12:58 -------
Created an attachment (id=1209)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1209&action=view)
master log




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #2 from vincent at vinc17.org  2006-11-20 12:59 -------
Created an attachment (id=1210)
 --> (http://bugzilla.mindrot.org/attachment.cgi?id=1210&action=view)
typed commands and output




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #3 from djm at mindrot.org  2006-11-20 13:04 -------
Can you replicate this with unpatched openssh-4.5 at each end? Debian
seems to include quite a few patches that may be breaking things.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #4 from vincent at vinc17.org  2006-11-20 13:09 -------
I forgot to say: after the freeze, I can typing Ctrl-\ to interrupt the
svn command (Ctrl-C isn't always sufficient). This makes the master die
after writing the following line to stderr (here, the master.log file):

mm_receive_fd: recvmsg: expected received 1 got 0




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #5 from dtucker at zip.com.au  2006-11-20 13:13 -------
Another thing to watch for: when the connection is in the hung state,
is the "SendQ" column in  the output of netstat corresponding to the
ssh connection non-zero and increasing?  If so that's indicative of a
network problem (probably MTU).




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #6 from dtucker at zip.com.au  2006-11-20 13:15 -------
(In reply to comment #5)
> Another thing to watch for: when the connection is in the hung state,
> is the "SendQ" column in  the output of netstat corresponding to
the
> ssh connection non-zero and increasing?  If so that's indicative of a
> network problem (probably MTU).
Forgot to add: you need to check this on both client and server.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #7 from vincent at vinc17.org  2006-11-20 13:25 -------
The Send-Q column has only 0's on both the client and the server.




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #8 from vincent at vinc17.org  2006-11-20 14:13 -------
(In reply to comment #3)
> Can you replicate this with unpatched openssh-4.5 at each end? Debian
> seems to include quite a few patches that may be breaking things.
I also get a freeze, but I don't get the same debug messages!

prunille:~/wd> svn diff -c 14924 > /dev/null
executing ssh
OpenSSH_4.5p1, OpenSSL 0.9.8d 28 Sep 2006
debug1: Reading configuration data /Users/vinc17/.ssh/config
debug1: /Users/vinc17/.ssh/config line 5: Deprecated option
"FallBackToRsh"
debug1: Applying options for ay
debug1: Applying options for *

When ssh doesn't freeze, the next debug line is:

debug3: Normalising mapped IPv4 in IPv6 address

The master.log still ends with:

debug1: client_input_channel_req: channel 1 rtype exit-status reply 0
debug1: channel 1: free: client-session, nchannels 2
debug1: client_input_channel_req: channel 0 rtype exit-status reply 0
debug1: channel 0: free: client-session, nchannels 1
debug1: fd 26 clearing O_NONBLOCK

and the server debug messages ended with:

debug1: session_by_channel: session 0 channel 0
debug1: session_close_by_channel: channel 0 child 0
debug1: session_close: session 0 pid 0
debug2: channel 0: gc: user detached
debug2: channel 0: is dead
debug2: channel 0: garbage collecting
debug1: channel 0: free: server-session, nchannels 1
debug3: channel 0: status: The following connections are open:
  #0 server-session (t4 r0 i3/0 o3/0 fd 9/9 cfd -1)

debug3: channel 0: close_fds r 9 w 9 e -1 c -1

in the first test, and in a second test:

debug1: server_input_channel_req: channel 0 request exec reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req exec
debug2: fd 9 setting O_NONBLOCK
debug3: fd 9 is O_NONBLOCK
debug2: fd 11 setting O_NONBLOCK
debug2: channel 0: read 413 from efd 11
debug2: channel 0: rwin 131072 elen 413 euse 1
debug2: channel 0: sent ext data 413
debug2: channel 0: read 35 from efd 11
debug2: channel 0: rwin 130659 elen 35 euse 1
debug2: channel 0: sent ext data 35




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #9 from vincent at vinc17.org  2006-11-20 14:24 -------
I've managed to produce a freeze with a master started with -vv (but it
was difficult).

Server debug messages (unpatched v4.5p1):
[...]
debug1: server_input_channel_req: channel 0 request exec reply 0
debug1: session_by_channel: session 0 channel 0
debug1: session_input_channel_req: session 0 req exec
debug2: fd 9 setting O_NONBLOCK
debug3: fd 9 is O_NONBLOCK
debug2: fd 11 setting O_NONBLOCK
debug2: channel 0: read 413 from efd 11
debug2: channel 0: rwin 131072 elen 413 euse 1
debug2: channel 0: sent ext data 413
debug2: channel 0: read 35 from efd 11
debug2: channel 0: rwin 130659 elen 35 euse 1
debug2: channel 0: sent ext data 35

In the terminal (where I typed svn):
[...]
executing ssh
OpenSSH_4.5p1, OpenSSL 0.9.8d 28 Sep 2006
debug1: Reading configuration data /Users/vinc17/.ssh/config
debug1: /Users/vinc17/.ssh/config line 5: Deprecated option
"FallBackToRsh"
debug1: Applying options for ay
debug1: Applying options for *

And the master.log file:
debug1: channel 0: free: client-session, nchannels 1
debug1: fd 26 clearing O_NONBLOCK
debug2: client_process_control: accepted tty 0, subsys 0, cmd svnserve
-t
debug2: client_process_control: got fds stdin 27, stdout 28, stderr 29
debug2: fd 27 setting O_NONBLOCK
debug2: fd 28 setting O_NONBLOCK
debug2: fd 26 setting O_NONBLOCK
debug1: channel 0: new [client-session]
debug2: channel 0: send open
debug2: callback start
debug2: client_session2_setup: id 0
debug1: Sending environment.
debug1: Sending env LC_CTYPE = en_US.ISO8859-1
debug2: channel 0: request env confirm 0
debug1: Sending env LANG = POSIX
debug2: channel 0: request env confirm 0
debug1: Sending env LC_COLLATE = POSIX
debug2: channel 0: request env confirm 0
debug1: Sending command: svnserve -t
debug2: channel 0: request exec confirm 0
debug2: callback done
debug2: channel 0: open confirm rwindow 0 rmax 32768
debug2: channel 0: rcvd adjust 131072
debug2: channel 0: rcvd ext data 413
debug2: channel 0: written 413 to efd 29
debug2: channel 0: rcvd ext data 35
debug2: channel 0: written 35 to efd 29
debug1: fd 30 clearing O_NONBLOCK
debug2: client_process_control: accepted tty 0, subsys 0, cmd svnserve
-t




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.

http://bugzilla.mindrot.org/show_bug.cgi?id=1263





------- Comment #10 from dtucker at zip.com.au  2006-11-20 22:42 -------
On the server when it's hung, can you do "strace -p [pidofsshd]"
(the
unprivileged one) and see what it's waiting on?  The equivalent on the
client would be great if it's available (for both master and slave) but
I don't know what, if any, the equivalent might be on OS X.

Also, I noticed that the descriptors mentioned on the client side are
relatively high.  Are you really running 5-15 sessions concurrently? 
If not there might be a descriptor leak in there somewhere (not sure if
it's contributing to the problem you're seeing though).




------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.