libssh2 is hanging during a file transfert
Micka
mickamusset at gmail.com
Wed Jul 8 02:04:37 AEST 2020
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 ?
>
>
>
More information about the openssh-unix-dev
mailing list