UPDATE2: SSH problem to Solaris 10 : Resource temporarily unavailable]
2007-12-25 6:48:00
(thanks to Crist Clark for suggesting a truss on the client end. Not the
problem but gave me a lead).
So, I truss-ed the client ssh call and managed to identify the exact
incoming packet that caused the ssh connection to fail. From that I
snooped both ends of the conversation and with a snoop -x on the exact
packet causing the problem, I diff'ed it and.....
server sending
0080 66 9b a3 ed 66 1f 22 6a 09 0b e5 64 4a 2b b4 20 f...f."j...dJ+.
0090 93 71 b7 8f c3 e6 84 8a 09 58 21 99 3f 59 08 4c .q.......X!.?Y.L
00a0 a5 ee 12 05 2f 97 7d 01 f0 66 6f 03 f6 57 3b 19 ..../.}..fo..W;.
^^
client receiving
0080 66 9b a3 ed 66 1f 22 6a 09 0b e5 64 4a 2b b4 20 f...f."j...dJ+.
0090 93 71 b7 8f c3 e6 84 0a 09 58 21 99 3f 59 08 4c .q.......X!.?Y.L
00a0 a5 ee 12 05 2f 97 7d 01 f0 66 6f 03 f6 57 3b 19 ..../.}..fo..W;.
^^
on line 0090 column 8 !! We are getting a corruption/modification of the
packet.
This is repeatable on 3 servers all connected to the same switch, and
occcurs at exactly the same stage in the SSH handshaking every time.
So I've a last got some proof to take to the network team.
Chris.
---------------------------- Original Message ----------------------------
Subject: UPDATE: SSH problem to Solaris 10 : Resource temporarily
unavailable
From: "Chris.Boler at Home.t" <chris.tech at relob.co.uk>
Date: Tue, January 23, 2007 9:42 am
To: codeprof at codeprof.com
--------------------------------------------------------------------------
So, the problem gets a bit stranger. Thanks for the responses so far but
it doesn't appear to be an install problem, a resource issue, or a duplex
issue, and we're not using zones.
We have a backup vlan connection as well and when I ssh over this vlan it
is fine !. So the problem seems to be specific to the bge1 interface
(these are all V240s where we are having this problem). I have run a snoop
on both ends and there doesn't seem to be any packet loss, but we do get
re-transmissions:
1 0.00000 hostA -> hostB TCP D=22 S=36061 Syn Seq=2902458693 Len=0
Win=49640 Options=<mss 1460,nop,nop,sackOK>
2 0.00023 hostB -> hostA TCP D=36061 S=22 Syn Ack=2902458694
Seq=3528546784 Len=0 Win=49640 Options=<mss 1460,nop,n
op,sackOK>
3 0.00026 hostA -> hostB TCP D=22 S=36061 Ack=3528546785
Seq=2902458694 Len=0 Win=49640
4 0.00355 hostB -> hostA TCP D=36061 S=22 Push Ack=2902458694
Seq=3528546785 Len=20 Win=49640
5 0.00033 hostA -> hostB TCP D=22 S=36061 Ack=3528546805
Seq=2902458694 Len=0 Win=49640
6 0.00010 hostA -> hostB TCP D=22 S=36061 Push Ack=3528546805
Seq=2902458694 Len=20 Win=49640
7 0.00005 hostB -> hostA TCP D=36061 S=22 Ack=2902458714
Seq=3528546805 Len=0 Win=49640
8 0.00045 hostA -> hostB TCP D=22 S=36061 Push Ack=3528546805
Seq=2902458714 Len=368 Win=49640
9 0.00003 hostB -> hostA TCP D=36061 S=22 Ack=2902459082
Seq=3528546805 Len=0 Win=49640
10 0.00926 hostB -> hostA TCP D=36061 S=22 Push Ack=2902459082
Seq=3528546805 Len=384 Win=49640
11 0.00032 hostA -> hostB TCP D=22 S=36061 Ack=3528547189
Seq=2902459082 Len=0 Win=49256
12 0.00011 hostA -> hostB TCP D=22 S=36061 Push Ack=3528547189
Seq=2902459082 Len=24 Win=49256
13 0.00912 hostB -> hostA TCP D=36061 S=22 Push Ack=2902459106
Seq=3528547189 Len=56 Win=49640
14 0.04617 hostA -> hostB TCP D=22 S=36061 Ack=3528547245
Seq=2902459106 Len=0 Win=49256
15 0.00010 hostB -> hostA TCP D=36061 S=22 Push Ack=2902459106
Seq=3528547245 Len=488 Win=49640
16 0.00039 hostA -> hostB TCP D=22 S=36061 Fin Ack=3528547245
Seq=2902459106 Len=0 Win=49640
17 0.00002 hostB -> hostA TCP D=36061 S=22 Ack=2902459107
Seq=3528547733 Len=0 Win=49640
18 0.04383 hostB -> hostA TCP D=36061 S=22 Fin Ack=2902459107
Seq=3528547733 Len=0 Win=49640
19 0.00033 hostA -> hostB TCP D=22 S=36061 Ack=3528547245
Seq=2902459107 Len=0 Win=49640
20 4.78489 hostB -> hostA TCP D=36061 S=22 Fin Push Ack=2902459107
Seq=3528547245 Len=488 Win=49640
21 9.66132 hostB -> hostA TCP D=36061 S=22 Fin Push Ack=2902459107
Seq=3528547245 Len=488 Win=49640
22 19.33082 hostB -> hostA TCP D=36061 S=22 Fin Push Ack=2902459107
Seq=3528547245 Len=488 Win=49640
23 38.64960 hostB -> hostA TCP D=36061 S=22 Fin Push Ack=2902459107
Seq=3528547245 Len=488 Win=49640
24 60.01086 hostB -> hostA TCP D=36061 S=22 Fin Push Ack=2902459107
Seq=3528547245 Len=488 Win=49640
25 60.00995 hostB -> hostA TCP D=36061 S=22 Fin Push Ack=2902459107
Seq=3528547245 Len=488 Win=49640
I'm very confused...
Chris.
---------------------------- Original Message ----------------------------
Subject: SSH problem to Solaris 10 : Resource temporarily unavailable
From: "Chris.Boler at Home.t" <chris.tech at relob.co.uk>
Date: Mon, January 22, 2007 4:01 pm
To: codeprof at codeprof.com
--------------------------------------------------------------------------
We have a strange problem SSH'ing to some new Solaris 10 installs,
from similar Solaris 10 builds, the SSH client hangs, and from existing
Solaris 9 servers we get the following:
$ ssh 10.70.56.12
Read from socket failed: Resource temporarily unavailable
Everything else seems to work, I've even re-enabled telnet and that's fine.
With debug enabled, I get the following on the client end:
$ ssh -vvv 10.70.56.12
Sun_SSH_1.1, SSH protocols 1.5/2.0, OpenSSL 0x0090700f
debug1: Reading configuration data /etc/ssh/ssh_config
debug1: Rhosts Authentication disabled, originating port will not be trusted.
debug1: ssh_connect: needpriv 0
debug1: Connecting to 10.70.56.12 [10.70.56.12] port 22.
debug1: Connection established.
debug1: identity file /export/home/chrisb/.ssh/identity type -1
debug1: identity file /export/home/chrisb/.ssh/id_rsa type -1
debug1: identity file /export/home/chrisb/.ssh/id_dsa type -1
debug1: Remote protocol version 2.0, remote software version Sun_SSH_1.1
debug1: no match: Sun_SSH_1.1
debug1: Enabling compatibility mode for protocol 2.0
debug1: Local version string SSH-2.0-Sun_SSH_1.1
debug1: SSH2_MSG_KEXINIT sent
debug3: kex_reset_dispatch -- should we dispatch_set(KEXINIT) here? 0 && !0
debug1: SSH2_MSG_KEXINIT received
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit:
aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc
debug2: kex_parse_kexinit:
aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: en-US
debug2: kex_parse_kexinit: en-US
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1
debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
debug2: kex_parse_kexinit:
aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc
debug2: kex_parse_kexinit:
aes128-ctr,aes128-cbc,arcfour,3des-cbc,blowfish-cbc
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: hmac-md5,hmac-sha1,hmac-sha1-96,hmac-md5-96
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: none,zlib
debug2: kex_parse_kexinit: i-default,en-US
debug2: kex_parse_kexinit: i-default,en-US
debug2: kex_parse_kexinit: first_kex_follows 0
debug2: kex_parse_kexinit: reserved 0
debug2: mac_init: found hmac-md5
debug1: kex: server->client aes128-ctr hmac-md5 none
debug2: mac_init: found hmac-md5
debug1: kex: client->server aes128-ctr hmac-md5 none
debug1: Peer sent proposed langtags, ctos: i-default,en-US
debug1: Peer sent proposed langtags, stoc: i-default,en-US
debug1: We proposed langtags, ctos: en-US
debug1: We proposed langtags, stoc: en-US
debug1: Negotiated lang: en-US
debug1: SSH2_MSG_KEX_DH_GEX_REQUEST sent
debug1: expecting SSH2_MSG_KEX_DH_GEX_GROUP
debug1: Remote: Negotiated main locale: en_US.UTF-8
Read from socket failed: Resource temporarily unavailable
debug1: Calling cleanup 0x47d2c(0x0)
and the following on the Solaris 10 server end:
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.info] Connection from
10.70.56.16 port 48589
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: Client
protocol version 2.0; client software version Sun_SSH_1.1
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: no
match: Sun_SSH_1.1
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
Enabling compatibility mode for protocol 2.0
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: Local
version string SSH-2.0-Sun_SSH_1.1
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
list_hostkey_types: ssh-rsa,ssh-dss
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
SSH2_MSG_KEXINIT sent
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
SSH2_MSG_KEXINIT received
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: kex:
client->server aes128-ctr hmac-md5 none
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: kex:
server->client aes128-ctr hmac-md5 none
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: Peer
sent proposed langtags, ctos: en-US
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: Peer
sent proposed langtags, stoc: en-US
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: We
proposed langtags, ctos: i-default,en-US
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: We
proposed langtags, stoc: i-default,en-US
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
Negotiated main locale: en_US.UTF-8
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
Negotiated messages locale: en_US.UTF-8
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
SSH2_MSG_KEX_DH_GEX_REQUEST received
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
SSH2_MSG_KEX_DH_GEX_GROUP sent
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
dh_gen_key: priv key bits set: 132/256
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1: bits
set: 1605/3191
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
expecting SSH2_MSG_KEX_DH_GEX_INIT
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.info] Connection
closed by 10.70.56.16
Jan 22 10:59:55 batfink sshd[25368]: [ID 800047 auth.debug] debug1:
Calling cleanup 0x4584c(0x0)
Any clues ?.
--
Chris Boler
--
--
Comments
Got something to say?
You must be logged in to post a comment.
