libssh2 is hanging during a file transfert
Micka
mickamusset at gmail.com
Tue Jul 7 21:41:55 AEST 2020
I'm trying to send data to a server with openssh 7.9p1, but it's hanging
somewhere.
the client stop at the line :
Jul 7 11:52:16 TOTO sshd[19553]: debug3: channel 0: will not send data
after close
and after 5 minutes the client closes the connection, why ?
This is the trace of the server openssh : ( DEBUG3 level)
Jul 7 11:52:15 TOTO sshd[31175]: debug3: fd 6 is not O_NONBLOCK
Jul 7 11:52:15 TOTO sshd[31175]: debug1: Forked child 19126.
Jul 7 11:52:15 TOTO sshd[31175]: debug3: send_rexec_state: entering fd = 9
config len 970
Jul 7 11:52:15 TOTO sshd[31175]: debug3: ssh_msg_send: type 0
Jul 7 11:52:15 TOTO sshd[31175]: debug3: send_rexec_state: done
Jul 7 11:52:15 TOTO sshd[19126]: debug3: oom_adjust_restore
Jul 7 11:52:15 TOTO sshd[19126]: debug1: Set /proc/self/oom_score_adj to 0
Jul 7 11:52:15 TOTO sshd[19126]: debug1: rexec start in 6 out 6 newsock 6
pipe 8 sock 9
Jul 7 11:52:15 TOTO sshd[19126]: debug1: inetd sockets after dupping: 5, 5
Jul 7 11:52:15 TOTO sshd[19126]: Connection from 10.91.140.30 port 49822
on 10.91.141.1 port 22
Jul 7 11:52:15 TOTO sshd[19126]: debug1: Client protocol version 2.0;
client software version libssh2_1.9.0_DEV
Jul 7 11:52:15 TOTO sshd[19126]: debug1: no match: libssh2_1.9.0_DEV
Jul 7 11:52:15 TOTO sshd[19126]: debug1: Local version string
SSH-2.0-OpenSSH_7.9
Jul 7 11:52:15 TOTO sshd[19126]: debug2: fd 5 setting O_NONBLOCK
Jul 7 11:52:15 TOTO sshd[19126]: debug3: ssh_sandbox_init: preparing
seccomp filter sandbox
Jul 7 11:52:15 TOTO sshd[19126]: debug2: Network child is on pid 19151
Jul 7 11:52:15 TOTO sshd[19126]: debug3: preauth child monitor started
Jul 7 11:52:15 TOTO sshd[19126]: debug3: privsep user:group 106:65534
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: permanently_set_uid: 106/65534
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: ssh_sandbox_child: setting
PR_SET_NO_NEW_PRIVS [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: ssh_sandbox_child: attaching
seccomp filter program [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: list_hostkey_types:
rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 20 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 20 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: SSH2_MSG_KEXINIT received
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: local server KEXINIT proposal
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: KEX algorithms:
diffie-hellman-group-exchange-sha256 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: host key algorithms:
rsa-sha2-512,rsa-sha2-256,ssh-rsa [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: ciphers ctos:
aes256-ctr,aes192-ctr,aes128-ctr [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: ciphers stoc:
aes256-ctr,aes192-ctr,aes128-ctr [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: MACs ctos:
hmac-sha2-512,hmac-sha2-256 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: MACs stoc:
hmac-sha2-512,hmac-sha2-256 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: compression ctos: none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: compression stoc: none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: languages ctos: [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: languages stoc: [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: first_kex_follows 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: reserved 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: peer client KEXINIT proposal
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: KEX algorithms:
ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,curve25519-sha256,
curve25519-sha256 at libssh.org,diffie-hellman-group14-sha256,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: host key algorithms: ssh-rsa
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: ciphers ctos:
aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc at lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: ciphers stoc:
aes128-ctr,aes192-ctr,aes256-ctr,aes256-cbc,rijndael-cbc at lysator.liu.se,aes192-cbc,aes128-cbc,blowfish-cbc,arcfour128,arcfour,cast128-cbc,3des-cbc
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: MACs ctos:
hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,
hmac-ripemd160 at openssh.com [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: MACs stoc:
hmac-sha2-256,hmac-sha2-512,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-md5-96,hmac-ripemd160,
hmac-ripemd160 at openssh.com [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: compression ctos: none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: compression stoc: none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: languages ctos: [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: languages stoc: [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: first_kex_follows 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: reserved 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: kex: algorithm:
diffie-hellman-group-exchange-sha256 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: kex: host key algorithm: ssh-rsa
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: kex: client->server cipher:
aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: kex: server->client cipher:
aes128-ctr MAC: hmac-sha2-256 compression: none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_REQUEST [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 34 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: SSH2_MSG_KEX_DH_GEX_REQUEST
received [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 0
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_choose_dh: waiting for
MONITOR_ANS_MODULI [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 1 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: monitor_read: checking request 0
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_moduli: got parameters:
2048 4096 8192
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 1
Jul 7 11:52:15 TOTO sshd[19126]: debug2: monitor_read: 0 used once,
disabling now
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_choose_dh: remaining 0
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: SSH2_MSG_KEX_DH_GEX_GROUP sent
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 31 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: bits set: 1978/4096 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: expecting
SSH2_MSG_KEX_DH_GEX_INIT [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 32 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: bits set: 2017/4096 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_sshkey_sign entering [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 6
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: monitor_read: checking request 6
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_sign
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_sign: hostkey proof
signature 0x80311540(271)
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 7
Jul 7 11:52:15 TOTO sshd[19126]: debug2: monitor_read: 6 used once,
disabling now
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_sshkey_sign: waiting for
MONITOR_ANS_SIGN [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 7 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 33 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 21 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: set_newkeys: mode 1 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: rekey after 4294967296 blocks
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: expecting SSH2_MSG_NEWKEYS
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 21 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: SSH2_MSG_NEWKEYS received
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: set_newkeys: mode 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: rekey after 4294967296 blocks
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: KEX done [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 5 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 6 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 50 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: userauth-request for user toto
service ssh-connection method none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: attempt 0 failures 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_getpwnamallow entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 8
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_getpwnamallow: waiting for
MONITOR_ANS_PWNAM [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 9 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: monitor_read: checking request 8
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_pwnamallow
Jul 7 11:52:15 TOTO sshd[19126]: debug2: parse_server_config: config
reprocess config len 970
Jul 7 11:52:15 TOTO sshd[19126]: debug3: auth_shadow_acctexpired: today
18450 sp_expire -1 days left -18451
Jul 7 11:52:15 TOTO sshd[19126]: debug3: account expiration disabled
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_pwnamallow: sending
MONITOR_ANS_PWNAM: 1
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 9
Jul 7 11:52:15 TOTO sshd[19126]: debug2: monitor_read: 8 used once,
disabling now
Jul 7 11:52:15 TOTO sshd[19126]: debug2: input_userauth_request: setting
up authctxt for toto [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_inform_authserv entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 4
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_auth2_read_banner entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 10
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 11 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: monitor_read: checking request 4
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_authserv:
service=ssh-connection, style=
Jul 7 11:52:15 TOTO sshd[19126]: debug2: monitor_read: 4 used once,
disabling now
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: monitor_read: checking request 10
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 11
Jul 7 11:52:15 TOTO sshd[19126]: debug2: monitor_read: 10 used once,
disabling now
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 53 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: userauth_send_banner: sent
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: input_userauth_request: try
method none [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: user_specific_delay: user
specific delay 0.000ms [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: ensure_minimum_time_since:
elapsed 73.257ms, delaying 64.508ms (requested 8.610ms) [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: userauth_finish: failure
partial=0 next methods="publickey" [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: send packet: type 51 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: receive packet: type 50 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: userauth-request for user toto
service ssh-connection method publickey [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: attempt 1 failures 0 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug2: input_userauth_request: try
method publickey [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug1: userauth_pubkey: test pkalg
ssh-rsa pkblob RSA SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_key_allowed entering [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 22
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_key_allowed: waiting for
MONITOR_ANS_KEYALLOWED [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 23 [preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: monitor_read: checking request 22
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_keyallowed entering
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_keyallowed:
key_from_blob: 0x80306160
Jul 7 11:52:15 TOTO sshd[19126]: debug1: temporarily_use_uid: 1001/1001
(e=0/0)
Jul 7 11:52:15 TOTO sshd[19126]: debug1: trying public key file
/home/test.pub
Jul 7 11:52:15 TOTO sshd[19126]: debug1: fd 4 clearing O_NONBLOCK
Jul 7 11:52:15 TOTO sshd[19126]: debug1: /home/test.pub:1: matching key
found: RSA SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4
Jul 7 11:52:15 TOTO sshd[19126]: debug1: /home/test.pub:1: key options:
agent-forwarding port-forwarding pty user-rc x11-forwarding
Jul 7 11:52:15 TOTO sshd[19126]: Accepted key RSA
SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4 found at /home/test.pub:1
Jul 7 11:52:15 TOTO sshd[19126]: debug1: restore_uid: 0/0
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_answer_keyallowed: publickey
authentication test: RSA key is allowed
Jul 7 11:52:15 TOTO sshd[19126]: debug3: mm_request_send entering: type 23
Jul 7 11:52:16 TOTO sshd[19126]: debug3: send packet: type 60 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug2: userauth_pubkey: authenticated 0
pkalg ssh-rsa [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: user_specific_delay: user
specific delay 0.000ms [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: ensure_minimum_time_since:
elapsed 10.037ms, delaying 7.184ms (requested 8.610ms) [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: Postponed publickey for toto from
10.91.140.30 port 49822 ssh2 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: receive packet: type 50 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug1: userauth-request for user toto
service ssh-connection method publickey [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug1: attempt 2 failures 0 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug2: input_userauth_request: try
method publickey [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: userauth_pubkey: have ssh-rsa
signature for RSA SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_key_allowed entering [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_send entering: type 22
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_key_allowed: waiting for
MONITOR_ANS_KEYALLOWED [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 23 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:16 TOTO sshd[19126]: debug3: monitor_read: checking request 22
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_answer_keyallowed entering
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_answer_keyallowed:
key_from_blob: 0x80309fd0
Jul 7 11:52:16 TOTO sshd[19126]: debug1: temporarily_use_uid: 1001/1001
(e=0/0)
Jul 7 11:52:16 TOTO sshd[19126]: debug1: trying public key file
/home/test.pub
Jul 7 11:52:16 TOTO sshd[19126]: debug1: fd 4 clearing O_NONBLOCK
Jul 7 11:52:16 TOTO sshd[19126]: debug1: /home/test.pub:1: matching key
found: RSA SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4
Jul 7 11:52:16 TOTO sshd[19126]: debug1: /home/test.pub:1: key options:
agent-forwarding port-forwarding pty user-rc x11-forwarding
Jul 7 11:52:16 TOTO sshd[19126]: Accepted key RSA
SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4 found at /home/test.pub:1
Jul 7 11:52:16 TOTO sshd[19126]: debug1: restore_uid: 0/0
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_answer_keyallowed: publickey
authentication: RSA key is allowed
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_send entering: type 23
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_sshkey_verify entering
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_send entering: type 24
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_sshkey_verify: waiting for
MONITOR_ANS_KEYVERIFY [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 25 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive entering
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:16 TOTO sshd[19126]: debug3: monitor_read: checking request 24
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_answer_keyverify: publickey
0x80309fd0 signature verified
Jul 7 11:52:16 TOTO sshd[19126]: debug1: auth_activate_options: setting
new authentication options
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_send entering: type 25
Jul 7 11:52:16 TOTO sshd[19126]: Accepted publickey for toto from
10.91.140.30 port 49822 ssh2: RSA
SHA256:fVQ7eL1KeCgpq4/BSsnou/pVnQv8mCouzqfNolAgbp4
Jul 7 11:52:16 TOTO sshd[19126]: debug1: monitor_child_preauth: toto has
been authenticated by privileged process
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_get_keystate: Waiting for new
keys
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive_expect
entering: type 26
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_get_keystate: GOT new keys
Jul 7 11:52:16 TOTO sshd[19126]: debug1: auth_activate_options: setting
new authentication options [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug2: userauth_pubkey: authenticated 1
pkalg ssh-rsa [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: user_specific_delay: user
specific delay 0.000ms [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: ensure_minimum_time_since:
elapsed 12.239ms, delaying 4.982ms (requested 8.610ms) [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: send packet: type 52 [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_request_send entering: type 26
[preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug3: mm_send_keystate: Finished
sending state [preauth]
Jul 7 11:52:16 TOTO sshd[19126]: debug1: monitor_read_log: child log fd
closed
Jul 7 11:52:16 TOTO sshd[19126]: debug3: ssh_sandbox_parent_finish:
finished
Jul 7 11:52:16 TOTO sshd[19126]: User child is on pid 19553
Jul 7 11:52:16 TOTO sshd[19553]: debug1: permanently_set_uid: 1001/1001
Jul 7 11:52:16 TOTO sshd[19553]: debug3: monitor_apply_keystate:
packet_set_state
Jul 7 11:52:16 TOTO sshd[19553]: debug2: set_newkeys: mode 0
Jul 7 11:52:16 TOTO sshd[19553]: debug1: rekey after 4294967296 blocks
Jul 7 11:52:16 TOTO sshd[19553]: debug2: set_newkeys: mode 1
Jul 7 11:52:16 TOTO sshd[19553]: debug1: rekey after 4294967296 blocks
Jul 7 11:52:16 TOTO sshd[19553]: debug1: ssh_packet_set_postauth: called
Jul 7 11:52:16 TOTO sshd[19553]: debug3: ssh_packet_set_state: done
Jul 7 11:52:16 TOTO sshd[19553]: debug3: notify_hostkeys: key 0: ssh-rsa
SHA256:vYlhpVfmXfMCmgD8vuI3qK7ppf3aRj8qhg3hj8OtJCI
Jul 7 11:52:16 TOTO sshd[19553]: debug3: notify_hostkeys: sent 1 hostkeys
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 80
Jul 7 11:52:16 TOTO sshd[19553]: debug1: active: key options:
agent-forwarding port-forwarding pty user-rc x11-forwarding
Jul 7 11:52:16 TOTO sshd[19553]: debug3: sending debug message:
/home/test.pub:1: key options: agent-forwarding port-forwarding pty user-rc
x11-forwarding
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 4
Jul 7 11:52:16 TOTO sshd[19553]: debug3: sending debug message:
/home/test.pub:1: key options: agent-forwarding port-forwarding pty user-rc
x11-forwarding
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 4
Jul 7 11:52:16 TOTO sshd[19553]: debug1: Entering interactive session for
SSH2.
Jul 7 11:52:16 TOTO sshd[19553]: debug2: fd 7 setting O_NONBLOCK
Jul 7 11:52:16 TOTO sshd[19553]: debug2: fd 9 setting O_NONBLOCK
Jul 7 11:52:16 TOTO sshd[19553]: debug1: server_init_dispatch
Jul 7 11:52:16 TOTO sshd[19553]: debug3: receive packet: type 90
Jul 7 11:52:16 TOTO sshd[19553]: debug1: server_input_channel_open: ctype
session rchan 0 win 2097152 max 32768
Jul 7 11:52:16 TOTO sshd[19553]: debug1: input_session_request
Jul 7 11:52:16 TOTO sshd[19553]: debug1: channel 0: new [server-session]
Jul 7 11:52:16 TOTO sshd[19553]: debug2: session_new: allocate (allocated
0 max 10)
Jul 7 11:52:16 TOTO sshd[19553]: debug3: session_unused: session id 0
unused
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_new: session 0
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_open: channel 0
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_open: session 0: link
with channel 0
Jul 7 11:52:16 TOTO sshd[19553]: debug1: server_input_channel_open:
confirm session
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 91
Jul 7 11:52:16 TOTO sshd[19553]: debug3: receive packet: type 98
Jul 7 11:52:16 TOTO sshd[19553]: debug1: server_input_channel_req: channel
0 request subsystem reply 1
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_by_channel: session 0
channel 0
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_input_channel_req:
session 0 req subsystem
Jul 7 11:52:16 TOTO sshd[19553]: debug2: subsystem request for sftp by
user toto
Jul 7 11:52:16 TOTO sshd[19553]: debug1: subsystem: exec()
/usr/lib/openssh/sftp-server -l DEBUG3
Jul 7 11:52:16 TOTO sshd[19553]: Starting session: subsystem 'sftp' for
toto from 10.91.140.30 port 49822 id 0
Jul 7 11:52:16 TOTO sshd[19553]: debug2: fd 5 setting TCP_NODELAY
Jul 7 11:52:16 TOTO sshd[19553]: debug3: ssh_packet_set_tos: set IP_TOS
0x20
Jul 7 11:52:16 TOTO sshd[19553]: debug2: fd 12 setting O_NONBLOCK
Jul 7 11:52:16 TOTO sshd[19553]: debug2: fd 11 setting O_NONBLOCK
Jul 7 11:52:16 TOTO sshd[19553]: debug2: fd 14 setting O_NONBLOCK
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 99
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: read 43 from efd 14
Jul 7 11:52:16 TOTO sshd[19553]: debug3: channel 0: discard efd
Jul 7 11:52:16 TOTO sshd[19553]: debug1: Received SIGCHLD.
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_by_pid: pid 19576
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_exit_message: session 0
channel 0 pid 19576
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: request exit-status
confirm 0
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 98
Jul 7 11:52:16 TOTO sshd[19553]: debug1: session_exit_message: release
channel 0
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: write failed
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: chan_shutdown_write
(i0 o0 sock -1 wfd 11 efd 14 [ignore])
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: send eow
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: output open -> closed
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: read<=0 rfd 12 len 0
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: read failed
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: chan_shutdown_read (i0
o3 sock -1 wfd 12 efd 14 [ignore])
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: input open -> drain
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: read 0 from efd 14
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: closing read-efd 14
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: ibuf empty
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: send eof
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 96
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: input drain -> closed
Jul 7 11:52:16 TOTO sshd[19553]: debug2: channel 0: send close
Jul 7 11:52:16 TOTO sshd[19553]: debug3: send packet: type 97
Jul 7 11:52:16 TOTO sshd[19553]: debug2: notify_done: reading
Jul 7 11:52:16 TOTO sshd[19553]: debug3: channel 0: will not send data
after close
Jul 7 11:57:15 TOTO sshd[19553]: debug3: receive packet: type 1
Jul 7 11:57:15 TOTO sshd[19553]: Received disconnect from 10.91.140.30
port 49822:11: Shutdown
Jul 7 11:57:15 TOTO sshd[19553]: Disconnected from user toto 10.91.140.30
port 49822
Jul 7 11:57:15 TOTO sshd[19553]: debug1: do_cleanup
Jul 7 11:57:15 TOTO sshd[19126]: debug3: mm_request_receive entering
Jul 7 11:57:15 TOTO sshd[19126]: debug1: do_cleanup
and the trace from libssh2:
[libssh2] 3.139411 Transport: Packet type 4 received, length=144
[libssh2] 3.139411 Transport: Debug Packet: /home/test.pub:1: key options:
agent-forwarding port-forwarding pty user-rc x11-forwarding
[libssh2] 3.155011 Transport: Looking for packet of type: 91
[libssh2] 3.155011 Transport: Looking for packet of type: 92
[libssh2] 3.155011 Socket: Recved 64/16384 bytes to 005ECB18+0
=> libssh2_transport_read() raw (64 bytes)
0000: 64 B2 41 29 E9 3E 78 DD 04 3A 7B 8E 30 A8 B5 08 : d.A).>x..:{.0...
0010: E5 0B 49 5A 01 45 91 4C 53 E8 6F D1 E8 15 4D 95 : ..IZ.E.LS.o...M.
0020: DC 21 3F F8 BE C4 7C 42 A4 F6 4E 41 99 4C 23 41 : .!?...|B..NA.L#A
0030: 61 CD CE 38 1E 80 7E AB 06 B9 71 8C 13 54 0B 0E : a..8..~...q..T..
=> libssh2_transport_read() plain (17 bytes)
0000: 5B 00 00 00 00 00 00 00 00 00 00 00 00 00 00 80 : [...............
0010: 00 : .
[libssh2] 3.170611 Transport: Packet type 91 received, length=17
[libssh2] 3.170611 Transport: Looking for packet of type: 91
[libssh2] 3.170611 Conn: Connection Established - ID: 0/0 win: 0/2097152
pack: 32768/32768
[libssh2] 3.170611 Conn: starting request(subsystem) on channel 0/0,
message=sftp
=> libssh2_transport_write plain (23 bytes)
0000: 62 00 00 00 00 00 00 00 09 73 75 62 73 79 73 74 : b........subsyst
0010: 65 6D 01 00 00 00 04 : em.....
=> libssh2_transport_write plain2 (4 bytes)
0000: 73 66 74 70 : sftp
[libssh2] 3.170611 Socket: Sent 80/80 bytes at 005F0B40
=> libssh2_transport_write send() (80 bytes)
0000: 75 10 1C 00 39 49 6D A4 43 3A E1 E7 21 72 4F 85 : u...9Im.C:..!rO.
0010: 66 3A D6 B4 95 6A 6E B1 2B A1 3D F7 A1 1A 5E 28 : f:...jn.+.=...^(
0020: BC B3 10 41 34 7D 1B 71 30 AE 42 FD 7A E5 A7 36 : ...A4}.q0.B.z..6
0030: F7 CA 2D 6C F7 32 08 B5 79 AF 4B C6 5E C9 97 41 : ..-l.2..y.K.^..A
0040: 6B D0 80 6C 3B D4 C4 9A 92 47 AE 50 FE 2A 22 D9 : k..l;....G.P.*".
[libssh2] 3.186211 Transport: Looking for packet of type: 99
[libssh2] 3.186211 Transport: Looking for packet of type: 100
[libssh2] 3.186211 Socket: Recved 112/16384 bytes to 005ECB18+0
=> libssh2_transport_read() raw (112 bytes)
0000: 6D 49 EC 6A E8 A3 E8 39 D5 E7 4F 44 1B 13 B1 D8 : mI.j...9..OD....
0010: D7 1B 99 71 A6 FE 71 6A 6C F3 B8 0C 7B 17 16 36 : ...q..qjl...{..6
0020: BA D9 D7 24 EF DB FB D6 4B C6 41 B2 97 81 7D 19 : ...$....K.A...}.
0030: 52 7A 07 BC EA 9D 49 7F E5 01 1A 14 FA 36 02 A5 : Rz....I......6..
0040: 0F 94 62 5E B2 14 92 34 72 CE 00 DF C1 59 69 10 : ..b^...4r....Yi.
0050: FA 32 22 6E 5C BE F4 91 AC 8A 0B 9F 2A EE 2E 10 : .2"n\.......*...
0060: 70 91 94 6F AC F7 75 C6 C4 D5 F5 28 F3 50 9A B5 : p..o..u....(.P..
=> libssh2_transport_read() plain (9 bytes)
0000: 5D 00 00 00 00 00 20 00 00 : ]..... ..
[libssh2] 3.217411 Transport: Packet type 93 received, length=9
[libssh2] 3.217411 Conn: Window adjust for channel 0/0, adding 2097152
bytes, new window_size=2097152
=> libssh2_transport_read() plain (5 bytes)
0000: 63 00 00 00 00 : c....
[libssh2] 3.217411 Transport: Packet type 99 received, length=5
[libssh2] 3.217411 Transport: Looking for packet of type: 99
[libssh2] 3.217411 Conn: Setting channel 0/0 handle_extended_data mode to 1
[libssh2] 3.217411 SFTP: Sending FXP_INIT packet advertising version 3
support
[libssh2] 3.233011 Conn: Writing 9 bytes on channel 0/0, stream #0
[libssh2] 3.233011 Socket: Recved 176/16384 bytes to 005ECB18+0
=> libssh2_transport_read() raw (176 bytes)
0000: BD EC E4 16 2F 05 A2 AD 03 E1 02 6D BB 99 A4 B7 : ..../......m....
0010: E5 C6 7E CD B1 F8 8E 58 C5 4A 31 F3 F7 D0 34 A0 : ..~....X.J1...4.
0020: AC 7C D9 DB BB DC C0 7E 53 87 DC 62 93 74 D1 21 : .|.....~S..b.t.!
0030: AC 8A 8C 8D F3 71 51 9F 99 4A F8 A7 61 71 F0 4F : .....qQ..J..aq.O
0040: 6E 83 2C 8C DE C1 84 B0 89 70 16 5F 17 DF 8C 63 : n.,......p._...c
0050: 65 C3 AE 19 F2 A4 95 14 52 1B E7 80 57 1B C1 50 : e.......R...W..P
0060: FC E4 85 F6 9A 5B C4 43 73 0A D9 CC D1 C6 41 8E : .....[.Cs.....A.
0070: BB 0E 1D A6 D5 C9 E3 74 E2 5A A1 B1 CF FA 14 AA : .......t.Z......
0080: AC E6 5F 18 16 53 6B D0 B6 4D F0 96 C6 77 55 2B : .._..Sk..M...wU+
0090: 58 6C 60 0F 95 57 CB 31 BB 37 A0 CF EC 29 34 25 : Xl`..W.1.7...)4%
00a0: F1 4A EB DF 95 11 1D 0C 8C 73 F4 8A A3 AC AB 70 : .J.......s.....p
=> libssh2_transport_read() plain (25 bytes)
0000: 62 00 00 00 00 00 00 00 0B 65 78 69 74 2D 73 74 : b........exit-st
0010: 61 74 75 73 00 00 00 00 01 : atus.....
[libssh2] 3.248611 Transport: Packet type 98 received, length=25
[libssh2] 3.248611 Conn: Channel 0 received request type exit-status (wr 0)
[libssh2] 3.264211 Conn: Exit status 1 received for channel 0/0
=> libssh2_transport_read() plain (5 bytes)
0000: 60 00 00 00 00 : `....
[libssh2] 3.264211 Transport: Packet type 96 received, length=5
[libssh2] 3.264211 Conn: EOF received for channel 0/0
=> libssh2_transport_read() plain (5 bytes)
0000: 61 00 00 00 00 : a....
[libssh2] 3.264211 Transport: Packet type 97 received, length=5
[libssh2] 3.279811 Conn: Close received for channel 0/0
[libssh2] 3.279811 Conn: Sending 9 bytes on channel 0/0, stream_id=0
=> libssh2_transport_write plain (9 bytes)
0000: 5E 00 00 00 00 00 00 00 09 : ^........
=> libssh2_transport_write plain2 (9 bytes)
0000: 00 00 00 05 01 00 00 00 03 : .........
[libssh2] 3.279811 Socket: Sent 64/64 bytes at 005F0B40
=> libssh2_transport_write send() (64 bytes)
0000: A4 39 BB 54 DD 45 BA 26 E7 E2 F2 79 7C 2D 9F 1A : .9.T.E.&...y|-..
0010: 29 AF 91 21 71 4A 13 4C CB 7D 4C E5 22 61 FE AF : )..!qJ.L.}L."a..
0020: 14 6E 13 C8 89 2A 43 58 72 60 4B 43 20 FA D5 73 : .n...*CXr`KC ..s
0030: BB 80 95 44 78 D2 0B 1E D5 59 DB E2 E8 7F 09 F8 : ...Dx....Y......
[libssh2] 3.295411 SFTP: Requiring packet 2 id 0
[libssh2] 3.295411 SFTP: recv packet
[libssh2] 3.295411 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 4.309413 SFTP: Requiring packet 2 id 0
[libssh2] 4.309413 SFTP: recv packet
[libssh2] 4.309413 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 5.323415 SFTP: Requiring packet 2 id 0
[libssh2] 5.323415 SFTP: recv packet
[libssh2] 5.323415 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 6.337417 SFTP: Requiring packet 2 id 0
[libssh2] 6.337417 SFTP: recv packet
[libssh2] 6.337417 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 7.351418 SFTP: Requiring packet 2 id 0
[libssh2] 7.351418 SFTP: recv packet
[libssh2] 7.351418 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 8.365420 SFTP: Requiring packet 2 id 0
[libssh2] 8.365420 SFTP: recv packet
[libssh2] 8.365420 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 9.379422 SFTP: Requiring packet 2 id 0
[libssh2] 9.379422 SFTP: recv packet
[libssh2] 9.379422 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
[libssh2] 10.393424 SFTP: Requiring packet 2 id 0
[libssh2] 10.393424 SFTP: recv packet
[libssh2] 10.393424 Conn: channel_read() wants 4 bytes from channel 0/0
stream #0
this where it takes 5 minutes ..... it is repeating ..... until 5 minutes
.... any idea ? why ?
More information about the openssh-unix-dev
mailing list