Hanging ssh sessions with openssh-5.1p1 and Solaris 8 & 10

Did you figure anything out on this? I have the exact same issue
since moving to openssh 5.1p1 on Solaris 10. At first I thought it
was this old ssh.com v3.2 client (before they changed to tectia) that
we've been using, but the trial SecureCRT 6.1 client doesn't exhibit
this issue on a large paste.

Re: Hanging ssh sessions with openssh-5.1p1 and Solaris 8 & 10

I was trying to reply to the original thread
[url]http://groups.google.com/group/mailing.unix.openssh-dev/browse_frm/thread/e1fde329c7e2610f/83815469c90068e2?lnk=gst&q=Hanging+ssh+sessions+#83815469c90068e2[/url]

The issue is that on large copy & paste into the ssh client will cause
the connection to hang showing no output. The original thread above
claims this occurs with pasting >= 1024 characters but I haven't
actually counted them. Debug mode for the sshd process does not
output any additional info. On clients in which I could run a debug,
the problem does not occur, such as a openssh 5.1p1 command line
client. I can reproduce this issue using puTTy consistently. The
trial version of SecureCRT 6.1 can paste in large amounts of data
without causing the hang.

Re: Hanging ssh sessions with openssh-5.1p1 and Solaris 8 & 10

Installed snapshot for the test
# ssh -v
OpenSSH_5.1p1-snap20081105, OpenSSL 0.9.8i 15 Sep 2008

Here is the sshd log with my "Notes" added:
Nov 5 13:56:01 someserv sshd[960]: [ID 800047 local7.debug] debug1:
fd 6 clearing O_NONBLOCK
Nov 5 13:56:01 someserv sshd[960]: [ID 800047 local7.debug] debug1:
Forked child 1094.
Nov 5 13:56:01 someserv sshd[960]: [ID 800047 local7.debug] debug3:
send_rexec_state: entering fd = 11 config len 214
Nov 5 13:56:01 someserv sshd[960]: [ID 800047 local7.debug] debug3:
ssh_msg_send: type 0
Nov 5 13:56:01 someserv sshd[960]: [ID 800047 local7.debug] debug3:
send_rexec_state: done
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
rexec start in 6 out 6 newsock 6 pipe 8 sock 11
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
inetd sockets after dupping: 5, 5
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.info]
Connection from 10.10.18.23 port 2266
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
Client protocol version 1.99; client software version 3.2.9 SSH Secure
Shell for
Windows
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
no match: 3.2.9 SSH Secure Shell for Windows
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
Enabling compatibility mode for protocol 2.0
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
Local version string SSH-2.0-OpenSSH_5.1
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
fd 5 setting O_NONBLOCK
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
Network child is on pid 1095
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
preauth child monitor started
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
monitor_read: checking request 4
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_sign
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_sign: signature 7f718(55)
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_send entering: type 5
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
monitor_read: 4 used once, disabling now
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
monitor_read: checking request 6
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_pwnamallow
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
Trying to reverse map address 10.10.18.23.
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
parse_server_config: config reprocess config len 214
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
auth_shadow_acctexpired: today 14188 sp_expire -1 days left -14189
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
account expiration disabled
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_send entering: type 7
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
monitor_read: 6 used once, disabling now
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
monitor_read: checking request 3
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_authserv: service=ssh-connection, style=
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
monitor_read: 3 used once, disabling now
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
monitor_read: checking request 10
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_authpassword: sending result 0
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_send entering: type 11
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.info] Failed
none for sshuser from 10.10.18.23 port 2266 ssh2
Nov 5 13:56:01 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
monitor_read: checking request 10
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
auth_shadow_pwexpired: today 14188 sp_lstchg 13934 sp_max -1
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
password expiration disabled
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_authpassword: sending result 1
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_send entering: type 11
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.info] Accepted
password for sshuser from 10.10.18.23 port 2266 ssh2
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
monitor_child_preauth: sshuser has been authenticated by privileged
process
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_get_keystate: Waiting for new keys
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive_expect entering: type 24
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_newkeys_from_blob: 89648(118)
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
mac_setup: found hmac-md5
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_get_keystate: Waiting for second key
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_newkeys_from_blob: 89648(118)
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
mac_setup: found hmac-md5
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_get_keystate: Getting compression state
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_get_keystate: Getting Network I/O buffers
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_share_sync: Share sync
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_share_sync: Share sync end
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.info] User
child is on pid 1096
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
permanently_set_uid: 100/1
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
set_newkeys: mode 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
set_newkeys: mode 1
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
Entering interactive session for SSH2.
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
fd 4 setting O_NONBLOCK
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
fd 6 setting O_NONBLOCK
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
server_init_dispatch_20
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
Received SSH2_MSG_IGNORE
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
server_input_channel_open: ctype session rchan 0 win 10000 max 512
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
input_session_request
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
channel 0: new [server-session]
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
session_new: allocate (allocated 0 max 10)
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
session_unused: session id 0 unused
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_new: session 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_open: channel 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_open: session 0: link with channel 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
server_input_channel_open: confirm session
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
Received SSH2_MSG_IGNORE
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
server_input_channel_req: channel 0 request pty-req reply 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_by_channel: session 0 channel 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_input_channel_req: session 0 req pty-req
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
Allocating pty.
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
mm_request_send entering: type 25
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
mm_pty_allocate: waiting for MONITOR_ANS_PTY
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
monitor_read: checking request 25
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
mm_request_receive_expect entering: type 26
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_pty entering
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug2:
session_new: allocate (allocated 0 max 10)
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
session_unused: session id 0 unused
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug1:
session_new: session 0
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_send entering: type 26
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_answer_pty: tty /dev/pts/2 ptyfd 4
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_pty_req: session 0 alloc /dev/pts/2
Nov 5 13:56:02 someserv sshd[1094]: [ID 800047 local7.debug] debug3:
mm_request_receive entering
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
Received SSH2_MSG_IGNORE
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
server_input_channel_req: channel 0 request shell reply 1
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_by_channel: session 0 channel 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_input_channel_req: session 0 req shell
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
fd 5 setting TCP_NODELAY
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
channel 0: rfd 10 isatty
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug2:
fd 10 setting O_NONBLOCK
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
fd 8 is O_NONBLOCK
Nov 5 13:56:02 someserv sshd[1098]: [ID 800047 local7.debug] debug1:
Setting controlling tty using TIOCSCTTY.
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
Received SSH2_MSG_IGNORE
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
server_input_channel_req: channel 0 request window-change reply 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_by_channel: session 0 channel 0
Nov 5 13:56:02 someserv sshd[1096]: [ID 800047 local7.debug] debug1:
session_input_channel_req: session 0 req window-change
Nov 5 13:56:02 someserv sshd[1098]: [ID 800047 local7.debug] debug3:
channel 0: close_fds r -1 w -1 e -1 c -1
Note: ogin complete at this point
Note: then I paste a large buffer
Nov 5 13:56:27 someserv sshd[1096]: [ID 800047 local7.debug] debug3:
Received SSH2_MSG_IGNORE
Note: client is hung, no new output shown on client side, only one log
msg appeared, shown above