thr3ads.net - openssh unix dev - libssh2 is hanging during a file transfert [Jul 2020]

If this information is useful, please help other people find it:
Share via:

Micka

2020-Jul-07 11:41 UTC

libssh2 is hanging during a file transfert

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, styleJul  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 ?

Brian Candler

2020-Jul-07 11:57 UTC

head link

libssh2 is hanging during a file transfert

My first thought is it could be an MTU problem.

Try running tcpdump at both ends - you should see the same packets (*).? 
If you find one side sends a maximum-sized packet, but the other side 
receives nothing, then that's very likely the issue.

If you don't have access to the far side, then reduce the TCP MSS on 
your side and try again.? (Or at worst, just reduce the MTU on your 
interface).? At least you'll know if that's the problem or not.

Regards,

Brian.

(*) Maybe multiple packets will appear as one packet, if your NIC 
reassembles TCP segments.? Turning off TCP offload on your NIC can 
sometimes be worth trying too.

Micka

2020-Jul-07 13:19 UTC

head link

libssh2 is hanging during a file transfert

I don't see a problem, my MTU is at the default value = 1500,

but when I look at the trace from libssh2,

packet type 4 received,  => SSH_MSG_DEBUG
packet type 91 received,  => SSH_MSG_CHANNEL_OPEN_CONFIRMATION
packet type 93 received, => SSH_MSG_CHANNEL_WINDOW_ADJUST
packet type 99 received, => SSH_MSG_CHANNEL_SUCCESS
packet type 98 received, => SSH_MSG_CHANNEL_REQUEST
packet type 96 received, => SSH_MSG_CHANNEL_EOF
packet type 97 received, => SSH_MSG_CHANNEL_CLOSE ==> why ?


and in the log sshd, I've some strange line :

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

On Tue, Jul 7, 2020 at 1:57 PM Brian Candler <b.candler at pobox.com>
wrote:
> My first thought is it could be an MTU problem.
>
> Try running tcpdump at both ends - you should see the same packets (*).
> If you find one side sends a maximum-sized packet, but the other side
> receives nothing, then that's very likely the issue.
>
> If you don't have access to the far side, then reduce the TCP MSS on
> your side and try again.  (Or at worst, just reduce the MTU on your
> interface).  At least you'll know if that's the problem or not.
>
> Regards,
>
> Brian.
>
> (*) Maybe multiple packets will appear as one packet, if your NIC
> reassembles TCP segments.  Turning off TCP offload on your NIC can
> sometimes be worth trying too.
>
>

Micka

2020-Jul-07 16:04 UTC

head link

libssh2 is hanging during a file transfert

problem corrected with :

chmod 666 /dev/null

On Tue, Jul 7, 2020 at 1:41 PM Micka <mickamusset at gmail.com> wrote:
> 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 ?
>
>
>

Apparently Analagous Threads

Search for more apparently analagous threads

openssh unix dev - Jul 2020 - libssh2 is hanging during a file transfert

libssh2 is hanging during a file transfert

libssh2 is hanging during a file transfert

libssh2 is hanging during a file transfert

libssh2 is hanging during a file transfert

Apparently Analagous Threads