Quoting gilles.lami@kuehne-nagel.com:
Can you post the result of a "sshd -ddd" (so on the server) after a ssh
connection ?
The following is the output from secure with sshd running as LOGLEVEL DEBUG3;
[root@web01 log]# tail -f --lines=0 secure
May 10 14:02:23 web01 sshd[30110]: debug3: fd 4 is not O_NONBLOCK
May 10 14:02:23 web01 sshd[30121]: debug1: rexec start in 4 out 4
newsock 4 pipe 6 sock 7
May 10 14:02:23 web01 sshd[30110]: debug1: Forked child 30121.
May 10 14:02:23 web01 sshd[30110]: debug3: send_rexec_state: entering
fd = 7 config len 410
May 10 14:02:23 web01 sshd[30110]: debug3: ssh_msg_send: type 0
May 10 14:02:23 web01 sshd[30110]: debug3: send_rexec_state: done
May 10 14:02:23 web01 sshd[30121]: debug1: inetd sockets after dupping: 3, 3
May 10 14:02:23 web01 sshd[30121]: Connection from ::ffff:10.127.5.103
port 4860
May 10 14:02:23 web01 sshd[30121]: debug1: Client protocol version
2.0; client software version OpenSSH_4.5
May 10 14:02:23 web01 sshd[30121]: debug1: match: OpenSSH_4.5 pat OpenSSH*
May 10 14:02:23 web01 sshd[30121]: debug1: Enabling compatibility mode
for protocol 2.0
May 10 14:02:23 web01 sshd[30121]: debug1: Local version string
SSH-2.0-OpenSSH_3.9p1
May 10 14:02:23 web01 sshd[30121]: debug2: fd 3 setting O_NONBLOCK
May 10 14:02:23 web01 sshd[30121]: debug2: Network child is on pid 30122
May 10 14:02:23 web01 sshd[30121]: debug3: preauth child monitor started
May 10 14:02:23 web01 sshd[30122]: debug3: privsep user:group 74:74
May 10 14:02:23 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:23 web01 sshd[30122]: debug1: permanently_set_uid: 74/74
May 10 14:02:23 web01 sshd[30122]: debug1: list_hostkey_types: ssh-rsa,ssh-dss
May 10 14:02:23 web01 sshd[30122]: debug1: SSH2_MSG_KEXINIT sent
May 10 14:02:23 web01 sshd[30122]: debug1: SSH2_MSG_KEXINIT received
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit: none,zlib
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit: none,zlib
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
first_kex_follows 0
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit: reserved 0
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit: ssh-rsa,ssh-dss
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
aes128-cbc,3des-cbc,blowfish-cbc,cast128-cbc,arcfour128,arcfour256,arcfour,aes192-cbc,aes256-cbc,rijndael-cbc@lysator.liu.se,aes128-ctr,aes192-ctr,aes256-ctr
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
hmac-md5,hmac-sha1,hmac-ripemd160,hmac-ripemd160@openssh.com,hmac-sha1-96,hmac-md5-96
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
none,zlib@openssh.com,zlib
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
none,zlib@openssh.com,zlib
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit:
first_kex_follows 0
May 10 14:02:24 web01 sshd[30122]: debug2: kex_parse_kexinit: reserved 0
May 10 14:02:24 web01 sshd[30122]: debug2: mac_init: found hmac-md5
May 10 14:02:24 web01 sshd[30122]: debug1: kex: client->server
aes128-cbc hmac-md5 none
May 10 14:02:24 web01 sshd[30122]: debug2: mac_init: found hmac-md5
May 10 14:02:24 web01 sshd[30122]: debug1: kex: server->client
aes128-cbc hmac-md5 none
May 10 14:02:24 web01 sshd[30122]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST
received
May 10 14:02:24 web01 sshd[30122]: debug3: mm_request_send entering: type 0
May 10 14:02:24 web01 sshd[30122]: debug3: mm_choose_dh: waiting for
MONITOR_ANS_MODULI
May 10 14:02:24 web01 sshd[30122]: debug3: mm_request_receive_expect
entering: type 1
May 10 14:02:24 web01 sshd[30121]: debug3: monitor_read: checking request 0
May 10 14:02:24 web01 sshd[30122]: debug3: mm_request_receive entering
May 10 14:02:24 web01 sshd[30121]: debug3: mm_answer_moduli: got
parameters: 1024 1024 8192
May 10 14:02:24 web01 sshd[30121]: debug3: mm_request_send entering: type 1
May 10 14:02:24 web01 sshd[30121]: debug2: monitor_read: 0 used once,
disabling now
May 10 14:02:24 web01 sshd[30122]: debug3: mm_choose_dh: remaining 0
May 10 14:02:24 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:24 web01 sshd[30122]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
May 10 14:02:24 web01 sshd[30122]: debug2: dh_gen_key: priv key bits
set: 142/256
May 10 14:02:24 web01 sshd[30122]: debug2: bits set: 529/1024
May 10 14:02:24 web01 sshd[30122]: debug1: expecting SSH2_MSG_KEX_DH_GEX_INIT
May 10 14:02:24 web01 sshd[30122]: debug2: bits set: 503/1024
May 10 14:02:24 web01 sshd[30122]: debug3: mm_key_sign entering
May 10 14:02:24 web01 sshd[30122]: debug3: mm_request_send entering: type 5
May 10 14:02:24 web01 sshd[30122]: debug3: mm_key_sign: waiting for
MONITOR_ANS_SIGN
May 10 14:02:24 web01 sshd[30121]: debug3: monitor_read: checking request 5
May 10 14:02:24 web01 sshd[30122]: debug3: mm_request_receive_expect
entering: type 6
May 10 14:02:24 web01 sshd[30121]: debug3: mm_answer_sign
May 10 14:02:24 web01 sshd[30122]: debug3: mm_request_receive entering
May 10 14:02:24 web01 sshd[30121]: debug3: mm_answer_sign: signature
0x89a9660(143)
May 10 14:02:24 web01 sshd[30121]: debug3: mm_request_send entering: type 6
May 10 14:02:24 web01 sshd[30121]: debug2: monitor_read: 5 used once,
disabling now
May 10 14:02:24 web01 sshd[30122]: debug1: SSH2_MSG_KEX_DH_GEX_REPLY sent
May 10 14:02:24 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:24 web01 sshd[30122]: debug2: kex_derive_keys
May 10 14:02:24 web01 sshd[30122]: debug2: set_newkeys: mode 1
May 10 14:02:24 web01 sshd[30122]: debug1: SSH2_MSG_NEWKEYS sent
May 10 14:02:24 web01 sshd[30122]: debug1: expecting SSH2_MSG_NEWKEYS
May 10 14:02:25 web01 sshd[30122]: debug2: set_newkeys: mode 0
May 10 14:02:25 web01 sshd[30122]: debug1: SSH2_MSG_NEWKEYS received
May 10 14:02:25 web01 sshd[30122]: debug1: KEX done
May 10 14:02:25 web01 sshd[30122]: debug1: userauth-request for user
txxxxxx service ssh-connection method none
May 10 14:02:25 web01 sshd[30122]: debug1: attempt 0 failures 0
May 10 14:02:25 web01 sshd[30122]: debug3: mm_getpwnamallow entering
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_send entering: type 7
May 10 14:02:25 web01 sshd[30122]: debug3: mm_getpwnamallow: waiting
for MONITOR_ANS_PWNAM
May 10 14:02:25 web01 sshd[30121]: debug3: monitor_read: checking request 7
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_receive_expect
entering: type 8
May 10 14:02:25 web01 sshd[30121]: debug3: mm_answer_pwnamallow
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30121]: debug3: mm_answer_pwnamallow:
sending MONITOR_ANS_PWNAM: 1
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_send entering: type 8
May 10 14:02:25 web01 sshd[30121]: debug2: monitor_read: 7 used once,
disabling now
May 10 14:02:25 web01 sshd[30122]: debug2: input_userauth_request:
setting up authctxt for txxxxxx
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30122]: debug3: mm_start_pam entering
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_send entering: type 46
May 10 14:02:25 web01 sshd[30122]: debug3: mm_inform_authserv entering
May 10 14:02:25 web01 sshd[30121]: debug3: monitor_read: checking request 46
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_send entering: type 3
May 10 14:02:25 web01 sshd[30121]: debug1: PAM: initializing for "txxxxxx"
May 10 14:02:25 web01 sshd[30122]: debug3: mm_inform_authrole entering
May 10 14:02:25 web01 sshd[30121]: debug3: Normalising mapped IPv4 in
IPv6 address
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_send entering: type 4
May 10 14:02:25 web01 sshd[30121]: debug3: Trying to reverse map
address 10.127.5.103.
May 10 14:02:25 web01 sshd[30122]: debug2: input_userauth_request: try
method none
May 10 14:02:25 web01 sshd[30121]: debug1: PAM: setting PAM_RHOST to
"10.127.5.103"
May 10 14:02:25 web01 sshd[30122]: debug3: mm_auth2_read_banner entering
May 10 14:02:25 web01 sshd[30121]: debug1: PAM: setting PAM_TTY to "ssh"
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_send entering: type 9
May 10 14:02:25 web01 sshd[30121]: debug2: monitor_read: 46 used once,
disabling now
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_receive_expect
entering: type 10
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30122]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30121]: debug3: monitor_read: checking request 3
May 10 14:02:25 web01 sshd[30121]: debug3: mm_answer_authserv:
service=ssh-connection, style=
May 10 14:02:25 web01 sshd[30121]: debug2: monitor_read: 3 used once,
disabling now
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30121]: debug3: monitor_read: checking request 4
May 10 14:02:25 web01 sshd[30121]: debug3: mm_answer_authrole: role=
May 10 14:02:25 web01 sshd[30121]: debug2: monitor_read: 4 used once,
disabling now
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30121]: debug3: monitor_read: checking request 9
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_send entering: type 10
May 10 14:02:25 web01 sshd[30121]: debug2: monitor_read: 9 used once,
disabling now
May 10 14:02:25 web01 sshd[30122]: debug1: userauth_banner: sent
May 10 14:02:25 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:25 web01 sshd[30122]: Failed none for txxxxxx from
::ffff:10.127.5.103 port 4860 ssh2
May 10 14:02:28 web01 sshd[30122]: debug1: userauth-request for user
txxxxxx service ssh-connection method password
May 10 14:02:28 web01 sshd[30122]: debug1: attempt 1 failures 1
May 10 14:02:28 web01 sshd[30122]: debug2: input_userauth_request: try
method password
May 10 14:02:28 web01 sshd[30122]: debug3: mm_auth_password entering
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_send entering: type 11
May 10 14:02:28 web01 sshd[30122]: debug3: mm_auth_password: waiting
for MONITOR_ANS_AUTHPASSWORD
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_receive_expect
entering: type 12
May 10 14:02:28 web01 sshd[30121]: debug3: monitor_read: checking request 11
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_receive entering
May 10 14:02:28 web01 sshd[30121]: debug3: PAM: sshpam_passwd_conv
called with 1 messages
May 10 14:02:28 web01 sshd[30121]: debug1: PAM: password
authentication accepted for txxxxxx
May 10 14:02:28 web01 sshd[30121]: debug3: mm_answer_authpassword:
sending result 1
May 10 14:02:28 web01 sshd[30121]: debug3: mm_request_send entering: type 12
May 10 14:02:28 web01 sshd[30121]: debug3: mm_request_receive_expect
entering: type 47
May 10 14:02:28 web01 sshd[30122]: debug3: mm_auth_password: user
authenticated
May 10 14:02:28 web01 sshd[30122]: debug3: mm_do_pam_account entering
May 10 14:02:28 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_send entering: type 47
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_receive_expect
entering: type 48
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_receive entering
May 10 14:02:28 web01 sshd[30121]: debug3: PAM: do_pam_account
pam_acct_mgmt = 0
May 10 14:02:28 web01 sshd[30121]: debug3: mm_request_send entering: type 48
May 10 14:02:28 web01 sshd[30121]: Accepted password for txxxxxx from
::ffff:10.127.5.103 port 4860 ssh2
May 10 14:02:28 web01 sshd[30122]: debug3: mm_do_pam_account returning 1
May 10 14:02:28 web01 sshd[30122]: Accepted password for txxxxxx from
::ffff:10.127.5.103 port 4860 ssh2
May 10 14:02:28 web01 sshd[30121]: debug1: monitor_child_preauth:
txxxxxx has been authenticated by privileged process
May 10 14:02:28 web01 sshd[30121]: debug3: mm_get_keystate: Waiting
for new keys
May 10 14:02:28 web01 sshd[30122]: debug3: mm_send_keystate: Sending
new keys: 0x89a1300 0x89a1938
May 10 14:02:28 web01 sshd[30121]: debug3: mm_request_receive_expect
entering: type 25
May 10 14:02:28 web01 sshd[30122]: debug3: mm_newkeys_to_blob:
converting 0x89a1300
May 10 14:02:28 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:28 web01 sshd[30122]: debug3: mm_newkeys_to_blob:
converting 0x89a1938
May 10 14:02:28 web01 sshd[30122]: debug3: mm_send_keystate: New keys
have been sent
May 10 14:02:28 web01 sshd[30122]: debug3: mm_send_keystate: Sending
compression state
May 10 14:02:28 web01 sshd[30122]: debug3: mm_request_send entering: type 25
May 10 14:02:28 web01 sshd[30122]: debug3: mm_send_keystate: Finished
sending state
May 10 14:02:28 web01 sshd[30121]: debug3: mm_newkeys_from_blob:
0x8a18ca0(118)
May 10 14:02:28 web01 sshd[30121]: debug2: mac_init: found hmac-md5
May 10 14:02:28 web01 sshd[30121]: debug3: mm_get_keystate: Waiting
for second key
May 10 14:02:28 web01 sshd[30121]: debug3: mm_newkeys_from_blob:
0x8a18ca0(118)
May 10 14:02:28 web01 sshd[30121]: debug2: mac_init: found hmac-md5
May 10 14:02:28 web01 sshd[30121]: debug3: mm_get_keystate: Getting
compression state
May 10 14:02:28 web01 sshd[30121]: debug3: mm_get_keystate: Getting
Network I/O buffers
May 10 14:02:28 web01 sshd[30121]: debug3: mm_share_sync: Share sync
May 10 14:02:28 web01 sshd[30121]: debug3: mm_share_sync: Share sync end
May 10 14:02:29 web01 sshd[30121]: debug2: User child is on pid 30124
May 10 14:02:29 web01 sshd[30121]: debug3: mm_request_receive entering
May 10 14:02:34 web01 sshd[30121]: debug1: do_cleanup
May 10 14:02:34 web01 sshd[30121]: debug1: PAM: cleanup
May 10 14:02:34 web01 sshd[30121]: debug3: PAM: sshpam_thread_cleanup entering
[root@web01 log]#
----------------------------------------------------------------
This message was sent using IMP, the Internet Messaging Program.
