PowerShell / PowerShell/Win32-OpenSSH
The connection is too slow and always timeout
Nobody has claimed this yet.
- Dominant language
- No language data
- Stars
- 8.3k
- Forks
- 819
- PR merge metrics
- No merged PRs in 30d
Description
"OpenSSH for Windows" version
8.6.0.0
Server OperatingSystem
Window7 64bit
Client OperatingSystem
Windows Embedded Standard
What is failing
I use SSHD as the service, the connection would task more than 5 minutes via putty or SSH client directly, it always timeout until I modify the time out from 2 minutes to 10 minutes. I highlight the steps that takes long time as below(always some performance in many attempts).
Any suggestion would thanks a lot.


Below is the full log(I hid my personal information).
5128 2021-11-17 00:26:50.692 Connection from xxx.xxx.xxx.xx port 62587 on 192.168.111.102 port 22
5128 2021-11-17 00:26:50.692 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_8.6
5128 2021-11-17 00:26:50.692 debug1: Remote protocol version 2.0, remote software version PuTTY_Release_0.75
5128 2021-11-17 00:26:50.692 debug1: compat_banner: no match: PuTTY_Release_0.75
5128 2021-11-17 00:26:50.692 debug2: fd 4 setting O_NONBLOCK
5128 2021-11-17 00:26:50.693 debug3: unable to load module api-ms-win-security-lsapolicy-l1-1-0.dll at run time, error: 126
5128 2021-11-17 00:26:50.693 debug3: unable to load module api-ms-win-security-lsapolicy-l1-1-0.dll at run time, error: 126
5128 2021-11-17 00:26:50.693 debug3: unable to load module api-ms-win-security-lsapolicy-l1-1-0.dll at run time, error: 126
5128 2021-11-17 00:26:50.732 debug3: unable to load module api-ms-win-security-lsapolicy-l1-1-0.dll at run time, error: 126
5128 2021-11-17 00:26:50.742 debug3: unable to load module api-ms-win-security-lsapolicy-l1-1-0.dll at run time, error: 126
5128 2021-11-17 00:26:50.743 debug3: spawning "C:\Program Files\OpenSSH\sshd.exe" -y as user
5128 2021-11-17 00:26:50.743 debug2: Network child is on pid 5960
5128 2021-11-17 00:26:50.743 debug3: send_rexec_state: enxxxxing fd = 6 config len 339
5128 2021-11-17 00:26:50.743 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:26:50.743 debug3: send_rexec_state: done
5128 2021-11-17 00:26:50.743 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:26:50.743 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:26:50.744 debug3: preauth child monitor started
5128 2021-11-17 00:29:00.179 debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
5128 2021-11-17 00:29:00.179 debug3: send packet: type 20 [preauth]
5128 2021-11-17 00:29:00.179 debug1: SSH2_MSG_KEXINIT sent [preauth]
5128 2021-11-17 00:29:00.179 debug3: receive packet: type 20 [preauth]
5128 2021-11-17 00:29:00.179 debug1: SSH2_MSG_KEXINIT received [preauth]
5128 2021-11-17 00:29:00.179 debug2: local server KEXINIT proposal [preauth]
5128 2021-11-17 00:29:00.179 debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group14-sha256 [preauth]
5128 2021-11-17 00:29:00.179 debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
5128 2021-11-17 00:29:00.179 debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
5128 2021-11-17 00:29:00.179 debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth]
5128 2021-11-17 00:29:00.179 debug2: compression ctos: none,zlib@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: compression stoc: none,zlib@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: languages ctos: [preauth]
5128 2021-11-17 00:29:00.179 debug2: languages stoc: [preauth]
5128 2021-11-17 00:29:00.179 debug2: first_kex_follows 0 [preauth]
5128 2021-11-17 00:29:00.179 debug2: reserved 0 [preauth]
5128 2021-11-17 00:29:00.179 debug2: peer client KEXINIT proposal [preauth]
5128 2021-11-17 00:29:00.179 debug2: KEX algorithms: gss-gex-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group14-sha1-toWM5Slw5Ew8Mqkay+al2g==,gss-group1-sha1-toWM5Slw5Ew8Mqkay+al2g==,curve448-sha512,curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,rsa2048-sha256,rsa1024-sha1,diffie-hellman-group1-sha1,ext-info-c [preauth]
5128 2021-11-17 00:29:00.179 debug2: host key algorithms: ssh-ed25519,ssh-ed448,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss,null [preauth]
5128 2021-11-17 00:29:00.179 debug2: ciphers ctos: aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,chacha20-poly1305@openssh.com,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128 [preauth]
5128 2021-11-17 00:29:00.179 debug2: ciphers stoc: aes256-ctr,aes256-cbc,rijndael-cbc@lysator.liu.se,aes192-ctr,aes192-cbc,aes128-ctr,aes128-cbc,chacha20-poly1305@openssh.com,3des-ctr,3des-cbc,blowfish-ctr,blowfish-cbc,arcfour256,arcfour128 [preauth]
5128 2021-11-17 00:29:00.179 debug2: MACs ctos: hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-sha2-256-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-etm@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: MACs stoc: hmac-sha2-256,hmac-sha1,hmac-sha1-96,hmac-md5,hmac-sha2-256-etm@openssh.com,hmac-sha1-etm@openssh.com,hmac-sha1-96-etm@openssh.com,hmac-md5-etm@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: compression ctos: none,zlib,zlib@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: compression stoc: none,zlib,zlib@openssh.com [preauth]
5128 2021-11-17 00:29:00.179 debug2: languages ctos: [preauth]
5128 2021-11-17 00:29:00.179 debug2: languages stoc: [preauth]
5128 2021-11-17 00:29:00.179 debug2: first_kex_follows 0 [preauth]
5128 2021-11-17 00:29:00.179 debug2: reserved 0 [preauth]
5128 2021-11-17 00:29:00.179 debug1: kex: algorithm: curve25519-sha256 [preauth]
5128 2021-11-17 00:29:00.179 debug1: kex: host key algorithm: ssh-ed25519 [preauth]
5128 2021-11-17 00:29:00.179 debug1: kex: client->server cipher: aes256-ctr MAC: hmac-sha2-256 compression: none [preauth]
5128 2021-11-17 00:29:00.179 debug1: kex: server->client cipher: aes256-ctr MAC: hmac-sha2-256 compression: none [preauth]
5128 2021-11-17 00:29:00.179 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
5128 2021-11-17 00:29:00.530 debug3: receive packet: type 30 [preauth]
5128 2021-11-17 00:29:00.530 debug1: SSH2_MSG_KEX_ECDH_INIT received [preauth]
5128 2021-11-17 00:29:00.534 debug3: mm_sshkey_sign: enxxxxing [preauth]
5128 2021-11-17 00:29:00.534 debug3: mm_request_send: enxxxxing, type 6 [preauth]
5128 2021-11-17 00:29:00.534 debug3: mm_request_receive: enxxxxing
5128 2021-11-17 00:29:00.534 debug3: monitor_read: checking request 6
5128 2021-11-17 00:29:00.534 debug3: mm_answer_sign: enxxxxing
5128 2021-11-17 00:29:00.535 debug3: mm_answer_sign: KEX signature 0000000000419000(83)
5128 2021-11-17 00:29:00.535 debug3: mm_request_send: enxxxxing, type 7
5128 2021-11-17 00:29:00.535 debug2: monitor_read: 6 used once, disabling now
5128 2021-11-17 00:29:00.535 debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
5128 2021-11-17 00:29:00.535 debug3: mm_request_receive_expect: enxxxxing, type 7 [preauth]
5128 2021-11-17 00:29:00.535 debug3: mm_request_receive: enxxxxing [preauth]
5128 2021-11-17 00:29:00.535 debug3: send packet: type 31 [preauth]
5128 2021-11-17 00:29:00.535 debug3: send packet: type 21 [preauth]
5128 2021-11-17 00:29:00.535 debug2: set_newkeys: mode 1 [preauth]
5128 2021-11-17 00:29:00.535 debug1: rekey out afxxxx 4294967296 blocks [preauth]
5128 2021-11-17 00:29:00.535 debug1: SSH2_MSG_NEWKEYS sent [preauth]
5128 2021-11-17 00:29:00.535 debug1: Sending SSH2_MSG_EXT_INFO [preauth]
5128 2021-11-17 00:29:00.535 debug3: send packet: type 7 [preauth]
5128 2021-11-17 00:29:00.535 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
5128 2021-11-17 00:29:09.711 debug3: receive packet: type 21 [preauth]
5128 2021-11-17 00:29:09.711 debug1: SSH2_MSG_NEWKEYS received [preauth]
5128 2021-11-17 00:29:09.711 debug2: set_newkeys: mode 0 [preauth]
5128 2021-11-17 00:29:09.711 debug1: rekey in afxxxx 4294967296 blocks [preauth]
5128 2021-11-17 00:29:09.711 debug1: KEX done [preauth]
5128 2021-11-17 00:29:09.711 debug3: receive packet: type 5 [preauth]
5128 2021-11-17 00:29:09.711 debug3: send packet: type 6 [preauth]
5128 2021-11-17 00:29:27.457 debug3: receive packet: type 50 [preauth]
5128 2021-11-17 00:29:27.457 debug1: userauth-request for user xxxx\\xxxx service ssh-connection method none [preauth]
5128 2021-11-17 00:29:27.457 debug1: attempt 0 failures 0 [preauth]
5128 2021-11-17 00:29:27.457 debug3: mm_getpwnamallow: enxxxxing [preauth]
5128 2021-11-17 00:29:27.457 debug3: mm_request_send: enxxxxing, type 8 [preauth]
5128 2021-11-17 00:29:27.457 debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
5128 2021-11-17 00:29:27.457 debug3: mm_request_receive_expect: enxxxxing, type 9 [preauth]
5128 2021-11-17 00:29:27.457 debug3: mm_request_receive: enxxxxing [preauth]
5128 2021-11-17 00:29:27.457 debug3: mm_request_receive: enxxxxing
5128 2021-11-17 00:29:27.457 debug3: monitor_read: checking request 8
5128 2021-11-17 00:29:27.457 debug3: mm_answer_pwnamallow: enxxxxing
5128 2021-11-17 00:29:27.458 debug2: parse_server_config_depth: config reprocess config len 339
5128 2021-11-17 00:29:27.458 debug3: checking match for 'Group administrators' user xxxx\xxxx host 132.223.130.14 addr 132.223.130.14 laddr 192.168.111.102 lport 22
5128 2021-11-17 00:29:27.474 debug3: lookup_principal_name: Successfully discovered explicit principal name: 'xxxx\xxxx'=>'xxxx@xxxx.xxxxadyne.com'
5128 2021-11-17 00:29:27.482 debug3: LsaLogonUser Succeeded (Impersonation: 0)
5128 2021-11-17 00:29:27.482 debug1: user xxxx\xxxx matched group list administrators at line 87
5128 2021-11-17 00:29:27.482 debug3: match found
5128 2021-11-17 00:29:27.482 debug3: reprocess config:88 setting AuthorizedKeysFile PROGRAMDATA/ssh/administrators_authorized_keys
5128 2021-11-17 00:29:27.483 debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
5128 2021-11-17 00:29:27.483 debug3: mm_request_send: enxxxxing, type 9
5128 2021-11-17 00:29:27.483 debug2: monitor_read: 8 used once, disabling now
5128 2021-11-17 00:29:27.484 debug2: input_userauth_request: setting up authctxt for xxxx\\xxxx [preauth]
5128 2021-11-17 00:29:27.484 debug3: mm_inform_authserv: enxxxxing [preauth]
5128 2021-11-17 00:29:27.484 debug3: mm_request_send: enxxxxing, type 4 [preauth]
5128 2021-11-17 00:29:27.484 debug2: input_userauth_request: try method none [preauth]
5128 2021-11-17 00:29:27.484 debug3: mm_request_receive: enxxxxing
5128 2021-11-17 00:29:27.484 debug3: monitor_read: checking request 4
5128 2021-11-17 00:29:27.484 debug3: mm_answer_authserv: service=ssh-connection, style=
5128 2021-11-17 00:29:27.484 debug2: monitor_read: 4 used once, disabling now
5128 2021-11-17 00:29:27.484 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
5128 2021-11-17 00:29:27.484 debug3: ensure_minimum_time_since: elapsed 27.002ms, delaying 23.382ms (requested 6.298ms) [preauth]
5128 2021-11-17 00:29:27.508 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-inxxxxactive" [preauth]
5128 2021-11-17 00:29:27.508 debug3: send packet: type 51 [preauth]
5128 2021-11-17 00:29:27.852 debug3: receive packet: type 50 [preauth]
5128 2021-11-17 00:29:27.852 debug1: userauth-request for user xxxx\\xxxx service ssh-connection method keyboard-inxxxxactive [preauth]
5128 2021-11-17 00:29:27.852 debug1: attempt 1 failures 0 [preauth]
5128 2021-11-17 00:29:27.852 debug2: input_userauth_request: try method keyboard-inxxxxactive [preauth]
5128 2021-11-17 00:29:27.852 debug1: keyboard-inxxxxactive devs [preauth]
5128 2021-11-17 00:29:27.852 debug1: auth2_challenge: user=xxxx\\xxxx devs= [preauth]
5128 2021-11-17 00:29:27.852 debug1: kbdint_alloc: devices '' [preauth]
5128 2021-11-17 00:29:27.852 debug2: auth2_challenge_start: devices [preauth]
5128 2021-11-17 00:29:27.852 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
5128 2021-11-17 00:29:27.852 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 6.298ms (requested 6.298ms) [preauth]
5128 2021-11-17 00:29:27.859 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-inxxxxactive" [preauth]
5128 2021-11-17 00:29:27.859 debug3: send packet: type 51 [preauth]
5128 2021-11-17 00:29:32.977 debug3: receive packet: type 2 [preauth]
5128 2021-11-17 00:29:32.977 debug3: Received SSH2_MSG_IGNORE [preauth]
5128 2021-11-17 00:29:32.977 debug3: receive packet: type 50 [preauth]
5128 2021-11-17 00:29:32.977 debug1: userauth-request for user xxxx\\xxxx service ssh-connection method password [preauth]
5128 2021-11-17 00:29:32.977 debug1: attempt 2 failures 1 [preauth]
5128 2021-11-17 00:29:32.977 debug2: input_userauth_request: try method password [preauth]
5128 2021-11-17 00:29:32.977 debug3: mm_auth_password: enxxxxing [preauth]
5128 2021-11-17 00:29:32.977 debug3: mm_request_send: enxxxxing, type 12 [preauth]
5128 2021-11-17 00:29:32.977 debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
5128 2021-11-17 00:29:32.977 debug3: mm_request_receive_expect: enxxxxing, type 13 [preauth]
5128 2021-11-17 00:29:32.977 debug3: mm_request_receive: enxxxxing [preauth]
5128 2021-11-17 00:29:32.977 debug3: mm_request_receive: enxxxxing
5128 2021-11-17 00:29:32.977 debug3: monitor_read: checking request 12
5128 2021-11-17 00:29:32.983 debug3: lookup_principal_name: Successfully discovered explicit principal name: 'xxxx\xxxx'=>'xxxx@xxxx.xxxxadyne.com'
5128 2021-11-17 00:29:33.001 debug3: mm_answer_authpassword: sending result 1
5128 2021-11-17 00:29:33.001 debug3: mm_answer_authpassword: sending result 1
5128 2021-11-17 00:29:33.001 debug3: mm_request_send: enxxxxing, type 13
5128 2021-11-17 00:29:33.001 Accepted password for xxxx\xxxx from xxx.xxx.xxx.xxx port 62587 ssh2
5128 2021-11-17 00:29:33.001 debug1: monitor_child_preauth: user xxxx\xxxx authenticated by privileged process
5128 2021-11-17 00:29:33.001 debug3: mm_get_keystate: Waiting for new keys
5128 2021-11-17 00:29:33.001 debug3: mm_request_receive_expect: enxxxxing, type 26
5128 2021-11-17 00:29:33.001 debug3: mm_request_receive: enxxxxing
5128 2021-11-17 00:29:33.003 debug3: mm_get_keystate: GOT new keys
5128 2021-11-17 00:29:33.003 debug3: mm_auth_password: user authenticated [preauth]
5128 2021-11-17 00:29:33.003 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
5128 2021-11-17 00:29:33.003 debug3: ensure_minimum_time_since: elapsed 24.001ms, delaying 1.191ms (requested 6.298ms) [preauth]
5128 2021-11-17 00:29:33.003 debug3: send packet: type 52 [preauth]
5128 2021-11-17 00:29:33.003 debug3: mm_request_send: enxxxxing, type 26 [preauth]
5128 2021-11-17 00:29:33.003 debug3: mm_send_keystate: Finished sending state [preauth]
5128 2021-11-17 00:29:33.003 debug1: monitor_read_log: child log fd closed
5128 2021-11-17 00:29:33.019 debug3: spawning "C:\Program Files\OpenSSH\sshd.exe" -z as user
5128 2021-11-17 00:29:33.019 User child is on pid 3836
5128 2021-11-17 00:29:33.019 debug3: send_rexec_state: enxxxxing fd = 5 config len 339
5128 2021-11-17 00:29:33.019 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:29:33.019 debug3: send_rexec_state: done
5128 2021-11-17 00:29:33.019 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:29:33.019 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:29:33.019 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:29:33.019 debug3: ssh_msg_send: type 0
5128 2021-11-17 00:29:33.019 debug3: ssh_msg_send: type 0
3836 2021-11-17 00:31:59.772 debug3: recv_idexch_state: enxxxxing fd = 3
3836 2021-11-17 00:31:59.772 debug3: ssh_msg_recv enxxxxing
3836 2021-11-17 00:31:59.772 debug3: recv_idexch_state: done
3836 2021-11-17 00:31:59.772 debug2: fd 4 setting O_NONBLOCK
3836 2021-11-17 00:31:59.772 debug3: recv_autxctx_state: enxxxxing fd = 3
3836 2021-11-17 00:31:59.772 debug3: ssh_msg_recv enxxxxing
3836 2021-11-17 00:31:59.772 debug3: recv_autxctx_state: done
3836 2021-11-17 00:31:59.773 debug2: parse_server_config_depth: config reprocess config len 339
3836 2021-11-17 00:31:59.773 debug3: checking match for 'Group administrators' user xxxx\xxxx host xxx.xxx.xxx.xxx addr xxx.xxx.xxx.xxx laddr 192.168.111.102 lport 22
3836 2021-11-17 00:31:59.774 debug3: get_user_token - i am running as xxxx\xxxx, returning process token
3836 2021-11-17 00:31:59.774 debug1: user xxxx\xxxx matched group list administrators at line 87
3836 2021-11-17 00:31:59.774 debug3: match found
3836 2021-11-17 00:31:59.774 debug3: reprocess config:88 setting AuthorizedKeysFile PROGRAMDATA/ssh/administrators_authorized_keys
3836 2021-11-17 00:31:59.775 debug3: monitor_recv_keystate: enxxxxing
3836 2021-11-17 00:31:59.775 debug3: ssh_msg_recv enxxxxing
3836 2021-11-17 00:31:59.775 debug3: monitor_recv_keystate: done
3836 2021-11-17 00:31:59.775 debug3: monitor_apply_keystate: packet_set_state
3836 2021-11-17 00:31:59.775 debug2: set_newkeys: mode 0
3836 2021-11-17 00:31:59.775 debug1: rekey in afxxxx 4294967296 blocks
3836 2021-11-17 00:31:59.775 debug2: set_newkeys: mode 1
3836 2021-11-17 00:31:59.775 debug1: rekey out afxxxx 4294967296 blocks
3836 2021-11-17 00:31:59.775 debug1: ssh_packet_set_postauth: called
3836 2021-11-17 00:31:59.775 debug3: ssh_packet_set_state: done
3836 2021-11-17 00:31:59.775 debug3: monitor_recv_authopt: enxxxxing
3836 2021-11-17 00:31:59.775 debug3: ssh_msg_recv enxxxxing
3836 2021-11-17 00:31:59.775 debug3: monitor_recv_authopt: done
3836 2021-11-17 00:31:59.775 debug3: notify_hostkeys: key 0: ssh-rsa SHA256:MjZYhMhcVlQhE3BT4ZZQeNigfFpehvVy5VeRC3ja6FI
3836 2021-11-17 00:31:59.775 debug3: notify_hostkeys: key 1: ecdsa-sha2-nistp256 SHA256:X6Qt8evE0joCL2uKKMz65hjPz2USWDJF52NXDQCAHIU
3836 2021-11-17 00:31:59.775 debug3: notify_hostkeys: key 2: ssh-ed25519 SHA256:mfq+4X6/4+qI4ncXwWbVkILsSFn/7ohixE7ndnqB4AY
3836 2021-11-17 00:31:59.775 debug3: notify_hostkeys: sent 3 hostkeys
3836 2021-11-17 00:31:59.775 debug3: send packet: type 80
3836 2021-11-17 00:31:59.775 debug1: active: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
3836 2021-11-17 00:31:59.775 debug1: Enxxxxing inxxxxactive session for SSH2.
3836 2021-11-17 00:31:59.775 debug2: fd 7 setting O_NONBLOCK
3836 2021-11-17 00:31:59.775 debug2: fd 8 setting O_NONBLOCK
3836 2021-11-17 00:31:59.775 debug1: server_init_dispatch
3836 2021-11-17 00:31:59.776 debug3: receive packet: type 90
3836 2021-11-17 00:31:59.776 debug1: server_input_channel_open: ctype session rchan 256 win 16384 max 16384
3836 2021-11-17 00:31:59.776 debug1: input_session_request
3836 2021-11-17 00:31:59.776 debug1: channel 0: new [server-session]
3836 2021-11-17 00:31:59.776 debug2: session_new: allocate (allocated 0 max 10)
3836 2021-11-17 00:31:59.776 debug3: session_unused: session id 0 unused
3836 2021-11-17 00:31:59.776 debug1: session_new: session 0
3836 2021-11-17 00:31:59.776 debug1: session_open: channel 0
3836 2021-11-17 00:31:59.776 debug1: session_open: session 0: link with channel 0
3836 2021-11-17 00:31:59.776 debug1: server_input_channel_open: confirm session
3836 2021-11-17 00:31:59.776 debug3: send packet: type 91
3836 2021-11-17 00:32:00.506 debug3: receive packet: type 98
3836 2021-11-17 00:32:00.506 debug1: server_input_channel_req: channel 0 request pty-req reply 1
3836 2021-11-17 00:32:00.506 debug1: session_by_channel: session 0 channel 0
3836 2021-11-17 00:32:00.506 debug1: session_input_channel_req: session 0 req pty-req
3836 2021-11-17 00:32:00.506 debug1: Allocating pty.
3836 2021-11-17 00:32:00.506 debug3: fd 9 is not O_NONBLOCK
3836 2021-11-17 00:32:00.506 debug3: fd 10 is not O_NONBLOCK
3836 2021-11-17 00:32:00.506 debug1: session_pty_req: session 0 alloc windows-pty
3836 2021-11-17 00:32:00.506 debug1: Ignoring unsupported tty mode opcode 3 (0x3)
3836 2021-11-17 00:32:00.506 debug1: Ignoring unsupported tty mode opcode 42 (0x2a)
3836 2021-11-17 00:32:00.506 debug3: send packet: type 99
3836 2021-11-17 00:32:00.506 debug3: receive packet: type 98
3836 2021-11-17 00:32:00.506 debug1: server_input_channel_req: channel 0 request shell reply 1
3836 2021-11-17 00:32:00.506 debug1: session_by_channel: session 0 channel 0
3836 2021-11-17 00:32:00.506 debug1: session_input_channel_req: session 0 req shell
3836 2021-11-17 00:32:00.506 Starting session: shell on windows-pty for xxxx\xxxx from xxx.xxx.xxx.xxx port 62587 id 0
3836 2021-11-17 00:32:00.507 debug2: fd 11 setting O_NONBLOCK
3836 2021-11-17 00:32:00.507 debug2: fd 12 setting O_NONBLOCK
3836 2021-11-17 00:32:00.507 debug2: fd 13 setting O_NONBLOCK
3836 2021-11-17 00:32:00.507 debug2: fd 14 setting O_NONBLOCK
3836 2021-11-17 00:32:00.507 debug2: fd 15 setting O_NONBLOCK
3836 2021-11-17 00:32:00.507 debug2: fd 16 setting O_NONBLOCK
3836 2021-11-17 00:32:00.507 debug3: shell: "c:\windows\system32\cmd.exe"
3836 2021-11-17 00:32:00.507 debug3: shell_option: /c
3836 2021-11-17 00:32:00.507 debug3: couldn't find CreatePseudoConsole() in kernel32.dll dll
3836 2021-11-17 00:32:00.507 debug3: This windows OS doesn't support conpty
3836 2021-11-17 00:32:00.507 debug3: pty commandline: "C:\Program Files\OpenSSH\ssh-shellhost.exe" ---pty "c:\windows\system32\cmd.exe"
3836 2021-11-17 00:32:00.508 debug2: fd 4 setting TCP_NODELAY
3836 2021-11-17 00:32:00.508 debug2: channel 0: rfd 13 isatty
3836 2021-11-17 00:32:00.508 debug3: fd 13 is O_NONBLOCK
3836 2021-11-17 00:32:00.509 debug3: fd 12 is O_NONBLOCK
3836 2021-11-17 00:32:00.509 debug3: send packet: type 99
3836 2021-11-17 00:42:36.411 Connection closed by xxx.xxx.xxx.xxx port 62587
3836 2021-11-17 00:42:36.411 debug1: channel 0: free: server-session, nchannels 1
3836 2021-11-17 00:42:36.411 debug3: channel 0: status: The following connections are open:\r\n #0 server-session (t4 r256 i0/0 o0/0 e[closed]/0 fd 13/12/-1 sock -1 cc -1)\r\n
3836 2021-11-17 00:42:36.411 Close session: user xxxx\xxxx from xxx.xxx.xxx.xxx port 62587 id 0
3836 2021-11-17 00:42:36.411 debug3: session_unused: session id 0 unused
3836 2021-11-17 00:42:36.411 debug1: do_cleanup
3836 2021-11-17 00:42:36.411 Transferred: sent 3952, received 2016 bytes
3836 2021-11-17 00:42:36.411 Closing connection to xxx.xxx.xxx.xxx port 62587
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Start by comparing the supplied OpenSSH_for_Windows_8.6 and sshd debug log timestamps, especially the delays before KEXINIT and user authentication. Reproduce with the listed Windows 7 and Windows Embedded Standard environments and PuTTY or another SSH client. Done would require isolating the cause of the multi-minute delay and documenting or fixing the affected connection path.
Written by the indexing model from the issue text.
Assessment
- Domain
- networking, operating-systems
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Needs clarification
- Newbie friendliness
- 25/100