PowerShell / PowerShell/Win32-OpenSSH

The connection is too slow and always timeout

Open
#1,858 6 comments 0 reactions 0 assignees View on GitHub

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.

image

image

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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.