<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.0 TRANSITIONAL//EN">
<HTML>
<HEAD>
<META HTTP-EQUIV="Content-Type" CONTENT="text/html; CHARSET=UTF-8">
<META NAME="GENERATOR" CONTENT="GtkHTML/1.0.1">
</HEAD>
<BODY>
<BR>
Hello,
<BR>
<BR>
When running scp (from openssh-3.4p1) on our linux systems we are experiencing hangs after authentication. According to the debug messages, authentication succeeds but the file itself is not transferred. Openssh is built using OpenSSL 0.9.6d.
<BR>
<BR>
The command
<BR>
<BR>
scp foo 192.168.1.111:/tmp
<BR>
<BR>
will hang until the connection times out.
<BR>
<BR>
Below are the client and server side logs. An strace of the client and server sides (using -f to follow the child process) shows that both are stuck in select() with NULL timeout. So they will both wait forever until they receive some input.
<BR>
<BR>
Using ssh to log in interactively works fine.
<BR>
<BR>
The problem is shown below using password authentication, but it also happens using RSA authentication.
<BR>
<BR>
We have a system with identical hardware and the same ssh installation
<BR>
(Openssh-3.4p1 + OpenSSL 0.9.6d) that does shows the problem only sporadically. On the system that generated the logs below, scp always fails.
<BR>
<BR>
The one peculiarity of our system is that /var is on a separate partition which is reformatted on boot. A skeleton /var filesystem is copied into the new /var. This is because these systems are designed for
<BR>
unattended kiosks, where the only service intervention is to cycle the power. I have no idea if this is relevant or not, but it is a peculiarity.
<BR>
<BR>
Our linux kernel is 2.4.17 and the glibc is 2.2.5. The system is built from a Linux from Scratch "distribution".
<BR>
<BR>
I would appreciate knowing if anyone has seen something like this before and how it might be worked around.
<BR>
<BR>
Thanks!
<BR>
<BR>
Best Wishes,
<BR>
<BR>
Greg Wright
<BR>
<BR>
<BR>
<BR>
The portion of the client strace log that shows the trouble is below. (I can provide the rest if it helps.)
<BR>
<BR>
<BR>
[pid 1438] close(4) = 0
<BR>
[pid 1438] dup(0) = 4
<BR>
[pid 1438] dup(1) = 5
<BR>
[pid 1438] dup(2) = 6
<BR>
[pid 1438] ioctl(4, TCGETS, 0xbffff604) = -1 EINVAL (Invalid argument)
<BR>
[pid 1438] fcntl(4, F_GETFL) = 0 (flags O_RDONLY)
<BR>
[pid 1438] fcntl(4, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
<BR>
[pid 1438] ioctl(5, TCGETS, 0xbffff604) = -1 EINVAL (Invalid argument)
<BR>
[pid 1438] fcntl(5, F_GETFL) = 0x1 (flags O_WRONLY)
<BR>
[pid 1438] fcntl(5, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
<BR>
[pid 1438] ioctl(6, TCGETS, {B38400 opost isig icanon echo ...}) = 0
<BR>
[pid 1438] gettimeofday({1027615805, 895450}, NULL) = 0
<BR>
[pid 1438] rt_sigaction(SIGINT, {0x80538a4, [], SA_RESTART|0x4000000}, {SIG_DFL}, 8) = 0
<BR>
[pid 1438] rt_sigaction(SIGQUIT, {0x80538a4, [], SA_RESTART|0x4000000}, {SIG_DFL}, 8) = 0
<BR>
[pid 1438] rt_sigaction(SIGTERM, {0x80538a4, [], SA_RESTART|0x4000000}, {SIG_DFL}, 8) = 0
<BR>
[pid 1438] select(7, [3], [3], NULL, NULL) = 1 (out [3])
<BR>
[pid 1438] write(3, "\234\231\277\177\16\315\317\207m\306\3522F\203<\275w\326"..., 64) = 64
<BR>
[pid 1438] select(7, [3], [], NULL, NULL) = 1 (in [3])
<BR>
[pid 1438] read(3, "\353\246&.\207\10\276\333K\203\325\267N\207\247\266\212"..., 8192) = 48
<BR>
[pid 1438] getsockname(3, {sin_family=AF_INET, sin_port=htons(2019), sin_addr=inet_addr("192.168.1.5")}}, [16]) = 0
<BR>
[pid 1438] setsockopt(3, SOL_IP, IP_TOS, [8], 4) = 0
<BR>
[pid 1438] select(7, [3], [3], NULL, NULL) = 1 (out [3])
<BR>
[pid 1438] write(3, "\v{fu\371\332O\370\376O\6)\226\362\303\32I\216\32Z\t\303"..., 64) = 64
<BR>
[pid 1438] select(7, [3], [], NULL, NULL
<BR>
<BR>
<BR>
...and there it stops.
<BR>
<BR>
<BR>
The client side log:
<BR>
<BR>
h> scp -v foo 192.168.1.111:/tmp
<BR>
Executing: program /usr/bin/ssh host 192.168.1.111, user (unspecified), command scp -v -t /tmp
<BR>
OpenSSH_3.4p1, SSH protocols 1.5/2.0, OpenSSL 0x0090604f
<BR>
debug1: Reading configuration data /etc/ssh/ssh_config
<BR>
debug1: Rhosts Authentication disabled, originating port will not be trusted.
<BR>
debug1: ssh_connect: needpriv 0
<BR>
debug1: Connecting to 192.168.1.111 [192.168.1.111] port 22.
<BR>
debug1: Connection established.
<BR>
debug1: identity file /root/.ssh/identity type 0
<BR>
debug1: identity file /root/.ssh/id_rsa type 1
<BR>
debug1: identity file /root/.ssh/id_dsa type 2
<BR>
debug1: Remote protocol version 1.99, remote software version OpenSSH_3.4p1
<BR>
debug1: match: OpenSSH_3.4p1 pat OpenSSH*
<BR>
Enabling compatibility mode for protocol 2.0
<BR>
debug1: Local version string SSH-2.0-OpenSSH_3.4p1
<BR>
debug1: SSH2_MSG_KEXINIT sent
<BR>
debug1: SSH2_MSG_KEXINIT received
<BR>
debug1: kex: server->client aes128-cbc hmac-md5 none
<BR>
debug1: kex: client->server aes128-cbc hmac-md5 none
<BR>
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST sent
<BR>
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
<BR>
debug1: dh_gen_key: priv key bits set: 116/256
<BR>
debug1: bits set: 1561/3191
<BR>
debug1: SSH2_MSG_KEX_DH_GEX_INIT sent
<BR>
debug1: expecting SSH2_MSG_KEX_DH_GEX_REPLY
<BR>
debug1: Host '192.168.1.111' is known and matches the RSA host key.
<BR>
debug1: Found key in /root/.ssh/known_hosts:41
<BR>
debug1: bits set: 1556/3191
<BR>
debug1: ssh_rsa_verify: signature correct
<BR>
debug1: kex_derive_keys
<BR>
debug1: newkeys: mode 1
<BR>
debug1: SSH2_MSG_NEWKEYS sent
<BR>
debug1: waiting for SSH2_MSG_NEWKEYS
<BR>
debug1: newkeys: mode 0
<BR>
debug1: SSH2_MSG_NEWKEYS received
<BR>
debug1: done: ssh_kex2.
<BR>
debug1: send SSH2_MSG_SERVICE_REQUEST
<BR>
debug1: service_accept: ssh-userauth
<BR>
debug1: got SSH2_MSG_SERVICE_ACCEPT
<BR>
debug1: authentications that can continue: publickey,password,keyboard-interactive
<BR>
debug1: next auth method to try is publickey
<BR>
debug1: userauth_pubkey_agent: testing agent key /root/.ssh/id_rsa
<BR>
debug1: authentications that can continue: publickey,password,keyboard-interactive
<BR>
debug1: userauth_pubkey_agent: testing agent key /root/.ssh/id_dsa
<BR>
debug1: authentications that can continue: publickey,password,keyboard-interactive
<BR>
debug1: try pubkey: /root/.ssh/id_rsa
<BR>
debug1: authentications that can continue: publickey,password,keyboard-interactive
<BR>
debug1: try pubkey: /root/.ssh/id_dsa
<BR>
debug1: authentications that can continue: publickey,password,keyboard-interactive
<BR>
debug1: next auth method to try is keyboard-interactive
<BR>
debug1: authentications that can continue: publickey,password,keyboard-interactive
<BR>
debug1: next auth method to try is password
<BR>
root@192.168.1.111's password:
<BR>
debug1: ssh-userauth2 successful: method password
<BR>
debug1: fd 4 setting O_NONBLOCK
<BR>
debug1: fd 5 setting O_NONBLOCK
<BR>
debug1: channel 0: new [client-session]
<BR>
debug1: send channel open 0
<BR>
debug1: Entering interactive session.
<BR>
debug1: ssh_session2_setup: id 0
<BR>
debug1: Sending command: scp -v -t /tmp
<BR>
debug1: channel request 0: exec
<BR>
debug1: channel 0: open confirm rwindow 0 rmax 32768
<BR>
<BR>
<BR>
The server side log:
<BR>
<BR>
debug1: sshd version OpenSSH_3.4p1
<BR>
debug1: private host key: #0 type 0 RSA1
<BR>
debug1: read PEM private key done: type RSA
<BR>
debug1: private host key: #1 type 1 RSA
<BR>
debug1: read PEM private key done: type DSA
<BR>
debug1: private host key: #2 type 2 DSA
<BR>
socket: Address family not supported by protocol
<BR>
debug1: Bind to port 22 on 0.0.0.0.
<BR>
Server listening on 0.0.0.0 port 22.
<BR>
Generating 768 bit RSA key.
<BR>
RSA key generation complete.
<BR>
debug1: Server will not fork when running in debugging mode.
<BR>
Connection from 192.168.1.5 port 1743
<BR>
debug1: Client protocol version 2.0; client software version OpenSSH_3.4p1
<BR>
debug1: match: OpenSSH_3.4p1 pat OpenSSH*
<BR>
Enabling compatibility mode for protocol 2.0
<BR>
debug1: Local version string SSH-1.99-OpenSSH_3.4p1
<BR>
debug1: list_hostkey_types: ssh-rsa,ssh-dss
<BR>
debug1: SSH2_MSG_KEXINIT sent
<BR>
debug1: SSH2_MSG_KEXINIT received
<BR>
debug1: kex: client->server aes128-cbc hmac-md5 none
<BR>
debug1: kex: server->client aes128-cbc hmac-md5 none
<BR>
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST received
<BR>
debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
<BR>
debug1: dh_gen_key: priv key bits set: 121/256
<BR>
debug1: bits set: 1598/3191
<BR>
debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
<BR>
debug1: bits set: 1618/3191
<BR>
debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
<BR>
debug1: kex_derive_keys
<BR>
debug1: newkeys: mode 1
<BR>
debug1: SSH2_MSG_NEWKEYS sent
<BR>
debug1: waiting for SSH2_MSG_NEWKEYS
<BR>
debug1: newkeys: mode 0
<BR>
debug1: SSH2_MSG_NEWKEYS received
<BR>
debug1: KEX done
<BR>
debug1: userauth-request for user root service ssh-connection method none
<BR>
debug1: attempt 0 failures 0
<BR>
Failed none for root from 192.168.1.5 port 1743 ssh2
<BR>
Failed none for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: userauth-request for user root service ssh-connection method publickey
<BR>
debug1: attempt 1 failures 1
<BR>
debug1: test whether pkalg/pkblob are acceptable
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys
<BR>
debug1: restore_uid
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys2
<BR>
debug1: restore_uid
<BR>
Failed publickey for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: userauth-request for user root service ssh-connection method publickey
<BR>
debug1: attempt 2 failures 2
<BR>
debug1: test whether pkalg/pkblob are acceptable
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys
<BR>
debug1: restore_uid
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys2
<BR>
debug1: restore_uid
<BR>
Failed publickey for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: userauth-request for user root service ssh-connection method publickey
<BR>
debug1: attempt 3 failures 3
<BR>
debug1: test whether pkalg/pkblob are acceptable
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys
<BR>
debug1: restore_uid
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys2
<BR>
debug1: restore_uid
<BR>
Failed publickey for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: userauth-request for user root service ssh-connection method publickey
<BR>
debug1: attempt 4 failures 4
<BR>
debug1: test whether pkalg/pkblob are acceptable
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys
<BR>
debug1: restore_uid
<BR>
debug1: temporarily_use_uid: 0/0 (e=0)
<BR>
debug1: trying public key file /root/.ssh/authorized_keys2
<BR>
debug1: restore_uid
<BR>
Failed publickey for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: userauth-request for user root service ssh-connection method keyboard-interactive
<BR>
debug1: attempt 5 failures 5
<BR>
debug1: keyboard-interactive devs
<BR>
debug1: auth2_challenge: user=root devs=
<BR>
debug1: kbdint_alloc: devices ''
<BR>
Failed keyboard-interactive for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: userauth-request for user root service ssh-connection method password
<BR>
debug1: attempt 6 failures 6
<BR>
Accepted password for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: monitor_child_preauth: root has been authenticated by privileged processAccepted password for root from 192.168.1.5 port 1743 ssh2
<BR>
debug1: newkeys: mode 0
<BR>
debug1: newkeys: mode 1
<BR>
debug1: Entering interactive session for SSH2.
<BR>
debug1: fd 3 setting O_NONBLOCK
<BR>
debug1: fd 7 setting O_NONBLOCK
<BR>
debug1: server_init_dispatch_20
<BR>
debug1: server_input_channel_open: ctype session rchan 0 win 131072 max 32768
<BR>
debug1: input_session_request
<BR>
debug1: channel 0: new [server-session]
<BR>
debug1: session_new: init
<BR>
debug1: session_new: session 0
<BR>
debug1: session_open: channel 0
<BR>
debug1: session_open: session 0: link with channel 0
<BR>
debug1: server_input_channel_open: confirm session
<BR>
Read error from remote host: Connection timed out
<BR>
debug1: Calling cleanup 0x8060534(0x0)
<BR>
debug1: channel_free: channel 0: server-session, nchannels 1
<BR>
debug1: Calling cleanup 0x806c570(0x0)
<BR>
<BR>
<TABLE CELLSPACING="0" CELLPADDING="0" WIDTH="100%">
<TR>
<TD>
<PRE>--
Gregory Wright
Chief Technical Officer
PacketStorm Communications, Inc.
20 Meridian Road
Eatontown, New Jersey 07724
1 732 544-2434 ext. 206
1 732 544-2437 [fax]
gwright@packetstorm.com</PRE>
</TD>
</TR>
</TABLE>
<TABLE CELLSPACING="0" CELLPADDING="0" WIDTH="100%">
<TR>
<TD>
<PRE>--
Gregory Wright
Chief Technical Officer
PacketStorm Communications, Inc.
20 Meridian Road
Eatontown, New Jersey 07724
1 732 544-2434 ext. 206
1 732 544-2437 [fax]
gwright@packetstorm.com
</PRE>
</TD>
</TR>
</TABLE>
</BODY>
</HTML>