search

PowerShell / Win32-OpenSSH

Win32 port of OpenSSH
7.42k stars 760 forks source link

ssh server randomly crashing when using sftp. #778

Closed crose-88 closed 4 years ago

crose-88 commented 7 years ago

I'm using the sftpclient in paramiko to connect to the server to put files and list directories etc. I'm finding on both my Windows 7 server and Windows 10 server (machines running the SSH server) that paramiko is reporting the connection has been force closed at random times. It seems to be 50:50 as to if I see the connection force closed, or it connects successfully. When I look on the Windows 7 server, I see a pop up stating that openSSH has crashed and the options to send the crash report to Microsoft. I annoyingly clicked the option in the crash report to automatically send the reports, so I now no longer get the crash pop up when this occurs, so I can't provide any additional information.

I've checked the sftp-server log and it's empty, so no clues there as to what's happening. The fact this happens on multiple machines makes me believe this isn't something specific to a single OS.

Please answer the following "OpenSSH for Windows" version Latestversion: v0.0.16.0

Server OperatingSystem Windows 7 Enterprise Windows 10

For added benefit, the python script which hits this looks similar to below.

import paramiko,

client = paramiko.SSHClient() client.load_system_host_keys() client.set_missing_host_key_policy(paramiko.AutoAddPolicy()) client.connect(ip, username=, password=) sftp_con = client.open_sftp() << Here is where the connection is force closed.

Sorry I can't provide any additional debug then this currently. I'm happy to re-run the test which produces this with any additional debug options set if someone lets me know.

bagajjal commented 7 years ago

Enable the logs in the sshd_config

Subsystem sftp sftp-server.exe -l DEBUG3 LOGLEVEL DEBUG3

While running sftp client, use -vvv flags ( .\sftp.exe -vvv user@IP) so that it dumps the logs onto the console.

Please share sshd.log, sftp-server.log and ssh log file.

I would suggest to do it manually (instead of running the script), since the probability of reproducing this is very high (50:50)..

crose-88 commented 7 years ago

So in an interesting development, if I enable debugging for the sftp-server, I can't reproduce the issue and I tried 10-15 times. As soon as I turn it off I could reproduce it again. Here is the debug output from the client running sftp.exe when the issue happens:

C:\Users\chris.TSNET\Documents\OpenSSH-Win32>.\sftp.exe -vvv ieuser@172.16.10.5 debug3: pipe - r-h:340,io:00BF2450,fd:3 w-h:336,io:00C19CF8,fd:4 debug3: pipe - r-h:348,io:00C32D80,fd:5 w-h:344,io:00C32E00,fd:6 debug3: spawning "C:\Users\chris.TSNET\Documents\OpenSSH-Win32\ssh.exe" "-oForwardX11 no" "-oForwardAgent no" "-oPermitLocalCommand no" "-oClearAllForwardings yes" "-v" "-v" "-v" "-l" "ieuser" "-oProtocol 2" "-s" "--" "172.16.10.5" "sftp" debug3: Register child 00000164 pid 6008, 0 zombies of 0 debug3: close - io:00C32D80, type:2, fd:5, table_index:5 debug3: close - io:00C19CF8, type:2, fd:4, table_index:4 OpenSSH_7.5p1, OpenSSL 1.0.2d 9 Jul 2015 debug2: resolving "172.16.10.5" port 22 debug2: ssh_connect_direct: needpriv 0 debug1: Connecting to 172.16.10.5 [172.16.10.5] port 22. debug3: socket:560, socktype:1, io:00111518, fd:3 debug1: Connection established. debug3: GetFileAttributesExW with last error 2 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_rsa error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_rsa type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_rsa-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_rsa-cert type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_dsa error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_dsa type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_dsa-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_dsa-cert type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ecdsa error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ecdsa type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ecdsa-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ecdsa-cert type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ed25519 error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ed25519 type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ed25519-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ed25519-cert type -1 debug1: Local version string SSH-2.0-OpenSSH_7.5 debug1: Remote protocol version 2.0, remote software version OpenSSH_7.5 debug1: match: OpenSSH_7.5 pat OpenSSH* compat 0x04000000 debug2: fd 3 setting O_NONBLOCK debug1: Authenticating to 172.16.10.5:22 as 'ieuser' debug3: send packet: type 20 debug1: SSH2_MSG_KEXINIT sent debug3: receive packet: type 20 debug1: SSH2_MSG_KEXINIT received debug2: local client KEXINIT proposal 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-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr 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 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 debug2: compression ctos: none debug2: compression stoc: none debug2: languages ctos: debug2: languages stoc: debug2: first_kex_follows 0 debug2: reserved 0 debug2: peer server KEXINIT proposal 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,diffie-hellman-group14-sha1 debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr 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 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 debug2: compression ctos: none debug2: compression stoc: none debug2: languages ctos: debug2: languages stoc: debug2: first_kex_follows 0 debug2: reserved 0 debug1: kex: algorithm: curve25519-sha256 debug1: kex: host key algorithm: ecdsa-sha2-nistp256 debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: compression: none debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: compression: none debug3: send packet: type 30 debug1: expecting SSH2_MSG_KEX_ECDH_REPLY debug3: receive packet: type 31 debug1: Server host key: ecdsa-sha2-nistp256 SHA256:NhHazRv+l+A0kb5AMXktB2pH4K5SYXg6Rhx+DKICJ4E debug3: failed to open file:/dev/tty error:3 debug1: read_passphrase: can't open /dev/tty: No such process The authenticity of host '172.16.10.5 (172.16.10.5)' can't be established. ECDSA key fingerprint is SHA256:NhHazRv+l+A0kb5AMXktB2pH4K5SYXg6Rhx+DKICJ4E. Are you sure you want to continue connecting (yes/no)? Warning: Permanently added '172.16.10.5' (ECDSA) to the list of known hosts. debug3: send packet: type 21 debug2: set_newkeys: mode 1 debug1: rekey after 134217728 blocks debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug3: receive packet: type 21 debug1: SSH2_MSG_NEWKEYS received debug2: set_newkeys: mode 0 debug1: rekey after 134217728 blocks debug3: socket:0, socktype:1, io:00178930, fd:4 debug3: unable to connect to pipe ssh-agent, error: 2 debug3: close - io:00178930, type:2, fd:4, table_index:4 debug1: pubkey_prepare: ssh_get_authentication_socket: No such file or directory debug2: key: C:\Users\chris.TSNET/.ssh/id_rsa (00000000) debug2: key: C:\Users\chris.TSNET/.ssh/id_dsa (00000000) debug2: key: C:\Users\chris.TSNET/.ssh/id_ecdsa (00000000) debug2: key: C:\Users\chris.TSNET/.ssh/id_ed25519 (00000000) debug3: send packet: type 5 debug3: receive packet: type 7 debug1: SSH2_MSG_EXT_INFO received debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521> debug3: receive packet: type 6 debug2: service_accept: ssh-userauth debug1: SSH2_MSG_SERVICE_ACCEPT received debug3: send packet: type 50 debug3: receive packet: type 51 debug1: Authentications that can continue: publickey,password,keyboard-interactive debug3: start over, passed a different list publickey,password,keyboard-interactive debug3: preferred publickey,keyboard-interactive,password debug3: authmethod_lookup publickey debug3: remaining preferred: keyboard-interactive,password debug3: authmethod_is_enabled publickey debug1: Next authentication method: publickey debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_rsa debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_rsa: No such file or directory debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_dsa debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_dsa: No such file or directory debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_ecdsa debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_ecdsa: No such file or directory debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_ed25519 debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_ed25519: No such file or directory debug2: we did not send a packet, disable method debug3: authmethod_lookup keyboard-interactive debug3: remaining preferred: password debug3: authmethod_is_enabled keyboard-interactive debug1: Next authentication method: keyboard-interactive debug2: userauth_kbdint debug3: send packet: type 50 debug2: we sent a keyboard-interactive packet, wait for reply debug3: receive packet: type 51 debug1: Authentications that can continue: publickey,password,keyboard-interactive debug3: userauth_kbdint: disable: no info_req_seen debug2: we did not send a packet, disable method debug3: authmethod_lookup password debug3: remaining preferred: debug3: authmethod_is_enabled password debug1: Next authentication method: password debug3: failed to open file:/dev/tty error:3 debug1: read_passphrase: can't open /dev/tty: No such process ieuser@172.16.10.5's password: debug3: send packet: type 50 debug2: we sent a password packet, wait for reply debug3: receive packet: type 52 debug1: Authentication succeeded (password). Authenticated to 172.16.10.5 ([172.16.10.5]:22). debug2: fd 4 setting O_NONBLOCK debug2: fd 5 setting O_NONBLOCK debug1: channel 0: new [client-session] debug3: ssh_session2_open: channel_new: 0 debug2: channel 0: send open debug3: send packet: type 90 debug1: Requesting no-more-sessions@openssh.com debug3: send packet: type 80 debug1: Entering interactive session. debug1: pledge: network debug3: receive packet: type 80 debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0 debug3: receive packet: type 91 debug2: callback start debug2: fd 3 setting TCP_NODELAY debug2: client_session2_setup: id 0 debug1: Sending subsystem: sftp debug2: channel 0: request subsystem confirm 1 debug3: send packet: type 98 debug2: callback done debug2: channel 0: open confirm rwindow 0 rmax 32768 debug3: recv - from CB ERROR:10054, io:00111518 debug3: send packet: type 1 debug3: send - WSASend() ERROR:10054, io:00111518 Connection reset by 172.16.10.5 port 22 Connection closed

C:\Users\chris.TSNET\Documents\OpenSSH-Win32>

I've attached the logs from the ssh-agent, sshd and sftp-server. They include when I tested this with debug enabled but without the issue occuring incase anything of interest is there. I'll leave debug enabled in the server so if this does reproduce then we'll have the required logging running.

sshlogs.zip

bagajjal commented 7 years ago

Any update?

Few observations.. 1) Looks like ssh-agent is not running.. debug3: unable to connect to pipe ssh-agent, error: 2 debug3: close - io:00178930, type:2, fd:4, table_index:4 debug1: pubkey_prepare: ssh_get_authentication_socket: No such file or directory

2) From sshd.log, change the sshd_config to "PidFile .\sshd.pid". Refer to https://github.com/PowerShell/Win32-OpenSSH/issues/493

error: Couldn't create pid file "./sshd.pid": Permission denied

3) From sshd.log, No domain controller is available for the specified domain or the domain does not exist. error: DsGetDcNameW() failed with error: 1355

4) From the sftp verbose log, Error-10054 means the peer has reset the connection.. debug3: recv - from CB ERROR:10054, io:00111518

crose-88 commented 7 years ago

So I've retested with the fixed pid file and it makes no difference. I've also retested with debug running on the ssh server, but not on the SFTP-server to see what effect that had. I could then see the issue reproducing and in the sshd logs I could see additional debug output. I've attached the sshd log which does cover the issue reproducing to hopefully help with this.

To help with completeness, I'm not running the ssh server on a machine in a domain.

I've confirmed both the agent and server are running, to rule that out from causing this. sshlogs2.zip

bagajjal commented 7 years ago

Couldn't get much information from logs as the connection close triggered from the client side... To make progress we need the client side logs (ssh.exe -vvv user@ip and sftp.exe -vvv user@IP),

1) Can you try using a different SSH client (win23-openssh client or putty) instead of "paramiko". I tried to install "paramiko" but it failed build/temp.linux-x86_64-2.7/_openssl.c:434:30: fatal error: openssl/opensslv.h: No such file or directory compilation terminated. error: command 'x86_64-linux-gnu-gcc' failed with exit status 1

Command "/usr/bin/python -u -c "import setuptools, tokenize;file='/tmp/pip-build-5I8G2O/cryptography/setup.py';f=getattr(tokenize, 'open', open)(file);code=f.read().replace('\r\n', '\n');f.close();exec(c ompile(code, file, 'exec'))" install --record /tmp/pip-kLQvaS-record/install-record.txt --single-version-externally-managed --compile" failed with error code 1 in /tmp/pip-build-5I8G2O/cryptography/

2) I saw couple of SFTP connection being closed because of read socket failures 4552 12:06:13 441 debug3: recv - from CB ERROR:10054, io:00997C98 3544 12:08:09 394 debug3: recv - from CB ERROR:10054, io:006A56E8

3) Looks like this issue is not just specific to SFTP, normal SSH also has this problem 1528 12:06:13 128 debug1: Executing command: C:\Program Files\OpenSSH\ssh-shellhost.exe -nopty cmVnIFFVRVJZICJIS0VZX0xPQ0FMX01BQ0hJTkVcU09GVFdBUkUiIC92IFRlc3Q= 1528 12:06:13 128 debug3: Register child 00000224 pid 3260, 0 zombies of 0 1528 12:06:13 128 debug3: close - io:01268EB0, type:2, fd:7, table_index:7 1528 12:06:13 128 debug3: close - io:01269430, type:2, fd:10, table_index:10 1528 12:06:13 128 debug3: close - io:012690B0, type:2, fd:12, table_index:12 1528 12:06:13 128 debug3: fd 9 is O_NONBLOCK 1528 12:06:13 128 debug3: fd 8 is O_NONBLOCK 1528 12:06:13 128 debug3: fd 11 is O_NONBLOCK 1528 12:06:13 128 debug3: send packet: type 99 1528 12:06:13 222 debug2: channel 1: read<=0 rfd 9 len 0 1528 12:06:13 222 debug2: channel 1: read failed 1528 12:06:13 222 debug2: channel 1: close_read

5340 12:06:11 191 debug1: Executing command: C:\Program Files\OpenSSH\ssh-shellhost.exe -nopty VEFTS0xJU1Q= 5340 12:06:11 191 debug3: Register child 000001FC pid 5716, 0 zombies of 0 5340 12:06:11 191 debug3: close - io:0167B708, type:2, fd:7, table_index:7 5340 12:06:11 191 debug3: close - io:0167BA88, type:2, fd:10, table_index:10 5340 12:06:11 191 debug3: close - io:0167B508, type:2, fd:12, table_index:12 5340 12:06:11 191 debug3: fd 9 is O_NONBLOCK 5340 12:06:11 191 debug3: fd 8 is O_NONBLOCK 5340 12:06:11 191 debug3: fd 11 is O_NONBLOCK 5340 12:06:11 191 debug3: send packet: type 99 5340 12:06:11 566 debug2: channel 1: read<=0 rfd 9 len 0 5340 12:06:11 566 debug2: channel 1: read failed 5340 12:06:11 566 debug2: channel 1: close_read

crose-88 commented 7 years ago

I've reproduced this again with the sftp client bundled in with the server. The client logs when hitting this issue are:

C:\Users\chris.TSNET\Downloads\OpenSSH-Win32\OpenSSH-Win32>sftp.exe -vvv user@172.16.10.7 debug3: pipe - r-h:348,io:013AB1B0,fd:3 w-h:344,io:013AB230,fd:4 debug3: pipe - r-h:356,io:013C42B8,fd:5 w-h:352,io:013C4338,fd:6 debug3: spawning "C:\Users\chris.TSNET\Downloads\OpenSSH-Win32\OpenSSH-Win32\ssh.exe" "-oForwardX11 no" "-oForwardAgent no" "-oPermitLocalCommand no" "-oClearAllForwardings yes" "-v" "-v" "-v" "-l" "user" "-oProtocol 2" "-s" "--" "172.16.10.7" "sftp" debug3: Register child 0000016C pid 8876, 0 zombies of 0 debug3: close - io:013C42B8, type:2, fd:5, table_index:5 debug3: close - io:013AB230, type:2, fd:4, table_index:4 OpenSSH_7.5p1, OpenSSL 1.0.2d 9 Jul 2015 debug2: resolving "172.16.10.7" port 22 debug2: ssh_connect_direct: needpriv 0 debug1: Connecting to 172.16.10.7 [172.16.10.7] port 22. debug3: socket:572, socktype:1, io:0013ED88, fd:3 debug1: Connection established. debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_rsa error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_rsa type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_rsa-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_rsa-cert type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_dsa error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_dsa type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_dsa-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_dsa-cert type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ecdsa error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ecdsa type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ecdsa-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ecdsa-cert type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ed25519 error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ed25519 type -1 debug3: failed to open file:C:\Users\chris.TSNET/.ssh/id_ed25519-cert error:2 debug1: key_load_public: No such file or directory debug1: identity file C:\Users\chris.TSNET/.ssh/id_ed25519-cert type -1 debug1: Local version string SSH-2.0-OpenSSH_7.5 debug1: Remote protocol version 2.0, remote software version OpenSSH_7.5 debug1: match: OpenSSH_7.5 pat OpenSSH* compat 0x04000000 debug2: fd 3 setting O_NONBLOCK debug1: Authenticating to 172.16.10.7:22 as 'user' debug3: hostkeys_foreach: reading file "C:\Users\chris.TSNET/.ssh/known_hosts" debug3: send packet: type 20 debug1: SSH2_MSG_KEXINIT sent debug3: receive packet: type 20 debug1: SSH2_MSG_KEXINIT received debug2: local client KEXINIT proposal 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-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,ext-info-c debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr 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 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 debug2: compression ctos: none debug2: compression stoc: none debug2: languages ctos: debug2: languages stoc: debug2: first_kex_follows 0 debug2: reserved 0 debug2: peer server KEXINIT proposal 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,diffie-hellman-group14-sha1 debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp256,ssh-ed25519 debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr 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 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 debug2: compression ctos: none debug2: compression stoc: none debug2: languages ctos: debug2: languages stoc: debug2: first_kex_follows 0 debug2: reserved 0 debug1: kex: algorithm: curve25519-sha256 debug1: kex: host key algorithm: ecdsa-sha2-nistp256 debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: compression: none debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: compression: none debug3: send packet: type 30 debug1: expecting SSH2_MSG_KEX_ECDH_REPLY debug3: receive packet: type 31 debug1: Server host key: ecdsa-sha2-nistp256 SHA256:+mdkkv4VzYjUTeCooE1jHsMFjqNvlKfePdMxfKE3F+8 debug3: hostkeys_foreach: reading file "C:\Users\chris.TSNET/.ssh/known_hosts" debug3: failed to open file:/dev/tty error:3 debug1: read_passphrase: can't open /dev/tty: No such process The authenticity of host '172.16.10.7 (172.16.10.7)' can't be established. ECDSA key fingerprint is SHA256:+mdkkv4VzYjUTeCooE1jHsMFjqNvlKfePdMxfKE3F+8. Are you sure you want to continue connecting (yes/no)? Warning: Permanently added '172.16.10.7' (ECDSA) to the list of known hosts. debug3: send packet: type 21 debug2: set_newkeys: mode 1 debug1: rekey after 134217728 blocks debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug3: receive packet: type 21 debug1: SSH2_MSG_NEWKEYS received debug2: set_newkeys: mode 0 debug1: rekey after 134217728 blocks debug3: socket:0, socktype:1, io:00143480, fd:4 debug3: unable to connect to pipe ssh-agent, error: 2 debug3: close - io:00143480, type:2, fd:4, table_index:4 debug1: pubkey_prepare: ssh_get_authentication_socket: No such file or directory debug2: key: C:\Users\chris.TSNET/.ssh/id_rsa (00000000) debug2: key: C:\Users\chris.TSNET/.ssh/id_dsa (00000000) debug2: key: C:\Users\chris.TSNET/.ssh/id_ecdsa (00000000) debug2: key: C:\Users\chris.TSNET/.ssh/id_ed25519 (00000000) debug3: send packet: type 5 debug3: receive packet: type 7 debug1: SSH2_MSG_EXT_INFO received debug1: kex_input_ext_info: server-sig-algs=<ssh-ed25519,ssh-rsa,rsa-sha2-256,rsa-sha2-512,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521> debug3: receive packet: type 6 debug2: service_accept: ssh-userauth debug1: SSH2_MSG_SERVICE_ACCEPT received debug3: send packet: type 50 debug3: receive packet: type 51 debug1: Authentications that can continue: publickey,password,keyboard-interactive debug3: start over, passed a different list publickey,password,keyboard-interactive debug3: preferred publickey,keyboard-interactive,password debug3: authmethod_lookup publickey debug3: remaining preferred: keyboard-interactive,password debug3: authmethod_is_enabled publickey debug1: Next authentication method: publickey debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_rsa debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_rsa: No such file or directory debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_dsa debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_dsa: No such file or directory debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_ecdsa debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_ecdsa: No such file or directory debug1: Trying private key: C:\Users\chris.TSNET/.ssh/id_ed25519 debug3: GetFileAttributesExW with last error 2 debug3: no such identity: C:\Users\chris.TSNET/.ssh/id_ed25519: No such file or directory debug2: we did not send a packet, disable method debug3: authmethod_lookup keyboard-interactive debug3: remaining preferred: password debug3: authmethod_is_enabled keyboard-interactive debug1: Next authentication method: keyboard-interactive debug2: userauth_kbdint debug3: send packet: type 50 debug2: we sent a keyboard-interactive packet, wait for reply debug3: receive packet: type 51 debug1: Authentications that can continue: publickey,password,keyboard-interactive debug3: userauth_kbdint: disable: no info_req_seen debug2: we did not send a packet, disable method debug3: authmethod_lookup password debug3: remaining preferred: debug3: authmethod_is_enabled password debug1: Next authentication method: password debug3: failed to open file:/dev/tty error:3 debug1: read_passphrase: can't open /dev/tty: No such process user@172.16.10.7's password: debug3: send packet: type 50 debug2: we sent a password packet, wait for reply debug3: receive packet: type 52 debug1: Authentication succeeded (password). Authenticated to 172.16.10.7 ([172.16.10.7]:22). debug2: fd 4 setting O_NONBLOCK debug2: fd 5 setting O_NONBLOCK debug1: channel 0: new [client-session] debug3: ssh_session2_open: channel_new: 0 debug2: channel 0: send open debug3: send packet: type 90 debug1: Requesting no-more-sessions@openssh.com debug3: send packet: type 80 debug1: Entering interactive session. debug1: pledge: network debug3: receive packet: type 80 debug1: client_input_global_request: rtype hostkeys-00@openssh.com want_reply 0 debug3: receive packet: type 91 debug2: callback start debug2: fd 3 setting TCP_NODELAY debug2: client_session2_setup: id 0 debug1: Sending subsystem: sftp debug2: channel 0: request subsystem confirm 1 debug3: send packet: type 98 debug2: callback done debug2: channel 0: open confirm rwindow 0 rmax 32768 debug3: recv - from CB ERROR:10054, io:0013ED88 debug3: send packet: type 1 debug3: send - WSASend() ERROR:10054, io:0013ED88 Connection reset by 172.16.10.7 port 22 Connection closed

C:\Users\chris.TSNET\Downloads\OpenSSH-Win32\OpenSSH-Win32>

I've attached the sshd.log The end of the ssh-agent log shows the following (I can't confirm timings, as the log times don't match the client time for some reason, perhaps they're for another day)...

5260 12:06:03 488 agent_process_connection pipe:00000178 5260 12:06:03 488 debug3: connection io 00CB04F8 #bytes:0 state:0 5260 12:06:03 519 debug3: connection io 00CB04F8 #bytes:4 state:1 5260 12:06:03 519 debug3: connection io 00CB04F8 #bytes:41 state:2 5260 12:06:03 519 debug1: client type: sshd service 5260 12:06:03 519 debug1: process agent request type 200 5260 12:06:03 566 debug3: connection io 00CB04F8 #bytes:8 state:3 5396 12:06:04 191 agent_process_connection pipe:00000178 5396 12:06:04 191 debug3: connection io 000DF5C8 #bytes:0 state:0 5396 12:06:04 238 debug3: connection io 000DF5C8 #bytes:4 state:1 5396 12:06:04 238 debug3: connection io 000DF5C8 #bytes:41 state:2 5396 12:06:04 238 debug1: client type: sshd service 5396 12:06:04 238 debug1: process agent request type 200 5396 12:06:04 253 debug3: connection io 000DF5C8 #bytes:8 state:3 4188 12:06:09 581 agent_process_connection pipe:00000178 4188 12:06:09 581 debug3: connection io 00CEF498 #bytes:0 state:0 4188 12:06:09 613 debug3: connection io 00CEF498 #bytes:4 state:1 4188 12:06:09 613 debug3: connection io 00CEF498 #bytes:41 state:2 4188 12:06:09 613 debug1: client type: sshd service 4188 12:06:09 613 debug1: process agent request type 200 4188 12:06:09 659 debug3: connection io 00CEF498 #bytes:8 state:3 3488 12:06:10 019 agent_process_connection pipe:00000178 3488 12:06:10 019 debug3: connection io 008FFCA8 #bytes:0 state:0 3488 12:06:10 066 debug3: connection io 008FFCA8 #bytes:4 state:1 3488 12:06:10 066 debug3: connection io 008FFCA8 #bytes:41 state:2 3488 12:06:10 066 debug1: client type: sshd service 3488 12:06:10 066 debug1: process agent request type 200 3488 12:06:10 081 debug3: connection io 008FFCA8 #bytes:8 state:3 2764 12:06:10 503 agent_process_connection pipe:00000178 2764 12:06:10 519 debug3: connection io 00F5F360 #bytes:0 state:0 2764 12:06:10 550 debug3: connection io 00F5F360 #bytes:4 state:1 2764 12:06:10 550 debug3: connection io 00F5F360 #bytes:41 state:2 2764 12:06:10 550 debug1: client type: sshd service 2764 12:06:10 550 debug1: process agent request type 200 2764 12:06:10 566 debug3: connection io 00F5F360 #bytes:8 state:3 1520 12:06:11 831 agent_process_connection pipe:00000178 1520 12:06:11 831 debug3: connection io 0100FB20 #bytes:0 state:0 1520 12:06:11 878 debug3: connection io 0100FB20 #bytes:4 state:1 1520 12:06:11 878 debug3: connection io 0100FB20 #bytes:41 state:2 1520 12:06:11 878 debug1: client type: sshd service 1520 12:06:11 878 debug1: process agent request type 200 1520 12:06:11 894 debug3: connection io 0100FB20 #bytes:8 state:3 1768 12:06:12 503 agent_process_connection pipe:00000178 1768 12:06:12 503 debug3: connection io 00A6F5A8 #bytes:0 state:0 1768 12:06:12 550 debug3: connection io 00A6F5A8 #bytes:4 state:1 1768 12:06:12 550 debug3: connection io 00A6F5A8 #bytes:41 state:2 1768 12:06:12 550 debug1: client type: sshd service 1768 12:06:12 550 debug1: process agent request type 200 1768 12:06:12 566 debug3: connection io 00A6F5A8 #bytes:8 state:3 5260 12:06:13 409 debug1: iocp error: 109 on 00CB04F8 5260 12:06:13 409 debug1: connection 00CB04F8 clean up 1520 12:06:13 409 debug1: iocp error: 109 on 0100FB20 1520 12:06:13 409 debug1: connection 0100FB20 clean up 4188 12:06:13 425 debug1: iocp error: 109 on 00CEF498 4188 12:06:13 425 debug1: connection 00CEF498 clean up 5396 12:06:13 425 debug1: iocp error: 109 on 000DF5C8 5396 12:06:13 425 debug1: connection 000DF5C8 clean up 5260 12:06:13 441 debug1: iocp error: 6 on 00000000 1520 12:06:13 441 debug1: iocp error: 6 on 00000000 1768 12:06:13 441 debug1: iocp error: 109 on 00A6F5A8 1768 12:06:13 441 debug1: connection 00A6F5A8 clean up 4188 12:06:13 456 debug1: iocp error: 6 on 00000000 5396 12:06:13 456 debug1: iocp error: 6 on 00000000 3488 12:06:13 456 debug1: iocp error: 109 on 008FFCA8 3488 12:06:13 456 debug1: connection 008FFCA8 clean up 1768 12:06:13 456 debug1: iocp error: 6 on 00000000 2764 12:06:13 472 debug1: iocp error: 109 on 00F5F360 2764 12:06:13 472 debug1: connection 00F5F360 clean up 3488 12:06:13 488 debug1: iocp error: 6 on 00000000 2764 12:06:13 488 debug1: iocp error: 6 on 00000000 5660 12:06:15 425 agent_process_connection pipe:00000178 5660 12:06:15 425 debug3: connection io 0139F260 #bytes:0 state:0 5660 12:06:15 456 debug3: connection io 0139F260 #bytes:4 state:1 5660 12:06:15 456 debug3: connection io 0139F260 #bytes:41 state:2 5660 12:06:15 456 debug1: client type: sshd service 5660 12:06:15 456 debug1: process agent request type 200 5660 12:06:15 472 debug3: connection io 0139F260 #bytes:8 state:3 4132 12:06:16 097 agent_process_connection pipe:00000178 4132 12:06:16 097 debug3: connection io 001CF5D8 #bytes:0 state:0 4132 12:06:16 144 debug3: connection io 001CF5D8 #bytes:4 state:1 4132 12:06:16 144 debug3: connection io 001CF5D8 #bytes:41 state:2 4132 12:06:16 144 debug1: client type: sshd service 4132 12:06:16 144 debug1: process agent request type 200 4132 12:06:16 159 debug3: connection io 001CF5D8 #bytes:8 state:3 4696 12:06:21 472 agent_process_connection pipe:00000178 4696 12:06:21 472 debug3: connection io 00B0F580 #bytes:0 state:0 4696 12:06:21 519 debug3: connection io 00B0F580 #bytes:4 state:1 4696 12:06:21 519 debug3: connection io 00B0F580 #bytes:41 state:2 4696 12:06:21 519 debug1: client type: sshd service 4696 12:06:21 519 debug1: process agent request type 200 4696 12:06:21 566 debug3: connection io 00B0F580 #bytes:8 state:3 4844 12:06:21 909 agent_process_connection pipe:00000178 4844 12:06:21 909 debug3: connection io 00E5F688 #bytes:0 state:0 4844 12:06:21 956 debug3: connection io 00E5F688 #bytes:4 state:1 4844 12:06:21 956 debug3: connection io 00E5F688 #bytes:41 state:2 4844 12:06:21 956 debug1: client type: sshd service 4844 12:06:21 956 debug1: process agent request type 200 4844 12:06:21 972 debug3: connection io 00E5F688 #bytes:8 state:3 4844 12:06:22 534 debug1: iocp error: 109 on 00E5F688 4844 12:06:22 534 debug1: connection 00E5F688 clean up 4844 12:06:22 550 debug1: iocp error: 6 on 00000000 4108 12:06:22 753 agent_process_connection pipe:00000178 4108 12:06:22 753 debug3: connection io 001C0398 #bytes:0 state:0 4108 12:06:22 800 debug3: connection io 001C0398 #bytes:4 state:1 4108 12:06:22 800 debug3: connection io 001C0398 #bytes:41 state:2 4108 12:06:22 800 debug1: client type: sshd service 4108 12:06:22 800 debug1: process agent request type 200 4108 12:06:22 816 debug3: connection io 001C0398 #bytes:8 state:3 3416 12:06:23 847 agent_process_connection pipe:00000178 3416 12:06:23 847 debug3: connection io 00FDF558 #bytes:0 state:0 3416 12:06:23 894 debug3: connection io 00FDF558 #bytes:4 state:1 3416 12:06:23 894 debug3: connection io 00FDF558 #bytes:41 state:2 3416 12:06:23 894 debug1: client type: sshd service 3416 12:06:23 894 debug1: process agent request type 200 3416 12:06:23 909 debug3: connection io 00FDF558 #bytes:8 state:3 3052 12:06:24 519 agent_process_connection pipe:00000178 3052 12:06:24 519 debug3: connection io 010003B0 #bytes:0 state:0 3052 12:06:24 581 debug3: connection io 010003B0 #bytes:4 state:1 3052 12:06:24 581 debug3: connection io 010003B0 #bytes:41 state:2 3052 12:06:24 581 debug1: client type: sshd service 3052 12:06:24 581 debug1: process agent request type 200 3052 12:06:24 597 debug3: connection io 010003B0 #bytes:8 state:3 3052 12:06:25 441 debug1: iocp error: 109 on 010003B0 3052 12:06:25 441 debug1: connection 010003B0 clean up 4132 12:06:25 456 debug1: iocp error: 109 on 001CF5D8 4132 12:06:25 456 debug1: connection 001CF5D8 clean up 5660 12:06:25 456 debug1: iocp error: 109 on 0139F260 5660 12:06:25 456 debug1: connection 0139F260 clean up 3052 12:06:25 472 debug1: iocp error: 6 on 00000000 4108 12:06:25 472 debug1: iocp error: 109 on 001C0398 4108 12:06:25 472 debug1: connection 001C0398 clean up 3416 12:06:25 472 debug1: iocp error: 109 on 00FDF558 3416 12:06:25 472 debug1: connection 00FDF558 clean up 4132 12:06:25 488 debug1: iocp error: 6 on 00000000 5660 12:06:25 503 debug1: iocp error: 6 on 00000000 4108 12:06:25 503 debug1: iocp error: 6 on 00000000 3416 12:06:25 519 debug1: iocp error: 6 on 00000000 4696 12:06:25 800 debug1: iocp error: 109 on 00B0F580 4696 12:06:25 800 debug1: connection 00B0F580 clean up 4696 12:06:25 816 debug1: iocp error: 6 on 00000000 3804 12:07:59 628 agent_process_connection pipe:00000178 3804 12:07:59 628 debug3: connection io 00F9F968 #bytes:0 state:0 3804 12:07:59 675 debug3: connection io 00F9F968 #bytes:4 state:1 3804 12:07:59 675 debug3: connection io 00F9F968 #bytes:41 state:2 3804 12:07:59 675 debug1: client type: sshd service 3804 12:07:59 675 debug1: process agent request type 200 3804 12:07:59 722 debug3: connection io 00F9F968 #bytes:8 state:3 3048 12:08:00 316 agent_process_connection pipe:00000178 3048 12:08:00 316 debug3: connection io 0009F5D8 #bytes:0 state:0 3048 12:08:00 363 debug3: connection io 0009F5D8 #bytes:4 state:1 3048 12:08:00 363 debug3: connection io 0009F5D8 #bytes:41 state:2 3048 12:08:00 363 debug1: client type: sshd service 3048 12:08:00 363 debug1: process agent request type 200 3048 12:08:00 378 debug3: connection io 0009F5D8 #bytes:8 state:3 4408 12:08:05 675 agent_process_connection pipe:00000178 4408 12:08:05 675 debug3: connection io 0002F610 #bytes:0 state:0 4408 12:08:05 722 debug3: connection io 0002F610 #bytes:4 state:1 4408 12:08:05 722 debug3: connection io 0002F610 #bytes:41 state:2 4408 12:08:05 722 debug1: client type: sshd service 4408 12:08:05 722 debug1: process agent request type 200 4408 12:08:05 769 debug3: connection io 0002F610 #bytes:8 state:3 3936 12:08:06 144 agent_process_connection pipe:00000178 3936 12:08:06 144 debug3: connection io 0197F3E8 #bytes:0 state:0 3936 12:08:06 175 debug3: connection io 0197F3E8 #bytes:4 state:1 3936 12:08:06 175 debug3: connection io 0197F3E8 #bytes:41 state:2 3936 12:08:06 175 debug1: client type: sshd service 3936 12:08:06 175 debug1: process agent request type 200 3936 12:08:06 191 debug3: connection io 0197F3E8 #bytes:8 state:3 4836 12:08:06 581 agent_process_connection pipe:00000178 4836 12:08:06 581 debug3: connection io 00540298 #bytes:0 state:0 4836 12:08:06 644 debug3: connection io 00540298 #bytes:4 state:1 4836 12:08:06 644 debug3: connection io 00540298 #bytes:41 state:2 4836 12:08:06 644 debug1: client type: sshd service 4836 12:08:06 644 debug1: process agent request type 200 4836 12:08:06 659 debug3: connection io 00540298 #bytes:8 state:3 2912 12:08:07 847 agent_process_connection pipe:00000178 2912 12:08:07 847 debug3: connection io 009BF2B8 #bytes:0 state:0 2912 12:08:07 894 debug3: connection io 009BF2B8 #bytes:4 state:1 2912 12:08:07 894 debug3: connection io 009BF2B8 #bytes:41 state:2 2912 12:08:07 894 debug1: client type: sshd service 2912 12:08:07 894 debug1: process agent request type 200 2912 12:08:07 909 debug3: connection io 009BF2B8 #bytes:8 state:3 5956 12:08:08 503 agent_process_connection pipe:00000178 5956 12:08:08 503 debug3: connection io 00EEF308 #bytes:0 state:0 5956 12:08:08 534 debug3: connection io 00EEF308 #bytes:4 state:1 5956 12:08:08 534 debug3: connection io 00EEF308 #bytes:41 state:2 5956 12:08:08 534 debug1: client type: sshd service 5956 12:08:08 534 debug1: process agent request type 200 5956 12:08:08 550 debug3: connection io 00EEF308 #bytes:8 state:3 4836 12:08:09 363 debug1: iocp error: 109 on 00540298 4836 12:08:09 363 debug1: connection 00540298 clean up 3804 12:08:09 378 debug1: iocp error: 109 on 00F9F968 3804 12:08:09 378 debug1: connection 00F9F968 clean up 4408 12:08:09 378 debug1: iocp error: 109 on 0002F610 4408 12:08:09 378 debug1: connection 0002F610 clean up 2912 12:08:09 378 debug1: iocp error: 109 on 009BF2B8 2912 12:08:09 378 debug1: connection 009BF2B8 clean up 4836 12:08:09 394 debug1: iocp error: 6 on 00000000 3804 12:08:09 394 debug1: iocp error: 6 on 00000000 4408 12:08:09 394 debug1: iocp error: 6 on 00000000 2912 12:08:09 409 debug1: iocp error: 6 on 00000000 5956 12:08:09 409 debug1: iocp error: 109 on 00EEF308 5956 12:08:09 409 debug1: connection 00EEF308 clean up 3048 12:08:09 409 debug1: iocp error: 109 on 0009F5D8 3048 12:08:09 409 debug1: connection 0009F5D8 clean up 3936 12:08:09 409 debug1: iocp error: 109 on 0197F3E8 3936 12:08:09 409 debug1: connection 0197F3E8 clean up 5956 12:08:09 409 debug1: iocp error: 6 on 00000000 3048 12:08:09 425 debug1: iocp error: 6 on 00000000 3936 12:08:09 441 debug1: iocp error: 6 on 00000000 3684 12:08:11 644 agent_process_connection pipe:00000178 3684 12:08:11 644 debug3: connection io 0160FA60 #bytes:0 state:0 3684 12:08:11 706 debug3: connection io 0160FA60 #bytes:4 state:1 3684 12:08:11 706 debug3: connection io 0160FA60 #bytes:41 state:2 3684 12:08:11 706 debug1: client type: sshd service 3684 12:08:11 706 debug1: process agent request type 200 3684 12:08:11 722 debug3: connection io 0160FA60 #bytes:8 state:3 3552 12:08:12 331 agent_process_connection pipe:00000178 3552 12:08:12 331 debug3: connection io 000BF558 #bytes:0 state:0 3552 12:08:12 378 debug3: connection io 000BF558 #bytes:4 state:1 3552 12:08:12 378 debug3: connection io 000BF558 #bytes:41 state:2 3552 12:08:12 378 debug1: client type: sshd service 3552 12:08:12 378 debug1: process agent request type 200 3552 12:08:12 394 debug3: connection io 000BF558 #bytes:8 state:3 4708 12:08:17 706 agent_process_connection pipe:00000178 4708 12:08:17 706 debug3: connection io 0080F5D8 #bytes:0 state:0 4708 12:08:17 753 debug3: connection io 0080F5D8 #bytes:4 state:1 4708 12:08:17 753 debug3: connection io 0080F5D8 #bytes:41 state:2 4708 12:08:17 753 debug1: client type: sshd service 4708 12:08:17 753 debug1: process agent request type 200 4708 12:08:17 800 debug3: connection io 0080F5D8 #bytes:8 state:3 1952 12:08:18 159 agent_process_connection pipe:00000178 1952 12:08:18 159 debug3: connection io 000CF610 #bytes:0 state:0 1952 12:08:18 206 debug3: connection io 000CF610 #bytes:4 state:1 1952 12:08:18 206 debug3: connection io 000CF610 #bytes:41 state:2 1952 12:08:18 206 debug1: client type: sshd service 1952 12:08:18 206 debug1: process agent request type 200 1952 12:08:18 223 debug3: connection io 000CF610 #bytes:8 state:3 1952 12:08:18 722 debug1: iocp error: 109 on 000CF610 1952 12:08:18 722 debug1: connection 000CF610 clean up 1952 12:08:18 722 debug1: iocp error: 6 on 00000000 3676 12:08:19 034 agent_process_connection pipe:00000178 3676 12:08:19 034 debug3: connection io 0068F580 #bytes:0 state:0 3676 12:08:19 081 debug3: connection io 0068F580 #bytes:4 state:1 3676 12:08:19 081 debug3: connection io 0068F580 #bytes:41 state:2 3676 12:08:19 081 debug1: client type: sshd service 3676 12:08:19 081 debug1: process agent request type 200 3676 12:08:19 097 debug3: connection io 0068F580 #bytes:8 state:3 1204 12:08:20 269 agent_process_connection pipe:00000178 1204 12:08:20 269 debug3: connection io 005AF5D8 #bytes:0 state:0 1204 12:08:20 331 debug3: connection io 005AF5D8 #bytes:4 state:1 1204 12:08:20 331 debug3: connection io 005AF5D8 #bytes:41 state:2 1204 12:08:20 331 debug1: client type: sshd service 1204 12:08:20 331 debug1: process agent request type 200 1204 12:08:20 347 debug3: connection io 005AF5D8 #bytes:8 state:3 4272 12:08:20 956 agent_process_connection pipe:00000178 4272 12:08:20 956 debug3: connection io 0002F5D8 #bytes:0 state:0 4272 12:08:21 003 debug3: connection io 0002F5D8 #bytes:4 state:1 4272 12:08:21 003 debug3: connection io 0002F5D8 #bytes:41 state:2 4272 12:08:21 003 debug1: client type: sshd service 4272 12:08:21 003 debug1: process agent request type 200 4272 12:08:21 034 debug3: connection io 0002F5D8 #bytes:8 state:3 3684 12:08:21 878 debug1: iocp error: 109 on 0160FA60 3684 12:08:21 878 debug1: connection 0160FA60 clean up 4708 12:08:21 878 debug1: iocp error: 109 on 0080F5D8 4708 12:08:21 878 debug1: connection 0080F5D8 clean up 1204 12:08:21 894 debug1: iocp error: 109 on 005AF5D8 1204 12:08:21 894 debug1: connection 005AF5D8 clean up 3676 12:08:21 894 debug1: iocp error: 109 on 0068F580 3676 12:08:21 894 debug1: connection 0068F580 clean up 3684 12:08:21 909 debug1: iocp error: 6 on 00000000 4272 12:08:21 909 debug1: iocp error: 109 on 0002F5D8 4272 12:08:21 909 debug1: connection 0002F5D8 clean up 3552 12:08:21 925 debug1: iocp error: 109 on 000BF558 3552 12:08:21 925 debug1: connection 000BF558 clean up 1204 12:08:21 925 debug1: iocp error: 6 on 00000000 3676 12:08:21 925 debug1: iocp error: 6 on 00000000 4708 12:08:21 925 debug1: iocp error: 6 on 00000000 4272 12:08:21 941 debug1: iocp error: 6 on 00000000 3552 12:08:21 941 debug1: iocp error: 6 on 00000000

I'm going to re-test this now, with Debug enabled on the SFTP server but not on the SSH server to see if I can reproduce the issue like that.

sshd.zip

crose-88 commented 7 years ago

Ok, everything works fine, I can't reproduce with the SFTP debug enabled.

debug2: fd 3 setting TCP_NODELAY debug2: client_session2_setup: id 0 debug1: Sending subsystem: sftp debug2: channel 0: request subsystem confirm 1 debug3: send packet: type 98 debug2: callback done debug2: channel 0: open confirm rwindow 0 rmax 32768 debug2: channel 0: rcvd adjust 2097152 debug3: receive packet: type 99 debug2: channel_input_status_confirm: type 99 id 0 debug2: subsystem request accepted on channel 0 debug2: Remote version: 3 debug2: Server supports extension "posix-rename@openssh.com" revision 1 debug2: Server supports extension "statvfs@openssh.com" revision 2 debug2: Server supports extension "fstatvfs@openssh.com" revision 2 debug2: Server supports extension "hardlink@openssh.com" revision 1 debug2: Server supports extension "fsync@openssh.com" revision 1 Connected to 172.16.10.7. debug3: Sent message fd 6 T:16 I:1 debug3: SSH_FXP_REALPATH . -> /C:/Users/User size 0 sftp>

I think I've spotted another bug, when the SFTP client is connected, if I exit, then the I see OpenSSH for Windows has stopped responding, and then program crashes.

sftp> exit debug3: close - io:01455A88, type:2, fd:3, table_index:3 debug3: close - io:01455B08, type:2, fd:6, table_index:6 debug2: channel 0: read<=0 rfd 4 len 0 debug2: channel 0: read failed debug2: channel 0: close_read debug3: close - io:001A32D0, type:2, fd:4, table_index:4 debug2: channel 0: input open -> drain debug2: channel 0: ibuf empty debug2: channel 0: send eof debug3: send packet: type 96 debug2: channel 0: input drain -> closed debug3: receive packet: type 96 debug2: channel 0: rcvd eof debug2: channel 0: output open -> drain debug2: channel 0: obuf empty debug2: channel 0: close_write debug3: close - io:00205DC0, type:2, fd:5, table_index:5 debug2: channel 0: output drain -> closed debug3: receive packet: type 98 debug1: client_input_channel_req: channel 0 rtype exit-status reply 0 debug3: receive packet: type 97 debug2: channel 0: rcvd close debug3: channel 0: will not send data after close debug2: channel 0: almost dead debug2: channel 0: gc: notify user debug2: channel 0: gc: user detached debug2: channel 0: send close debug3: send packet: type 97 debug2: channel 0: is dead debug2: channel 0: garbage collecting debug1: channel 0: free: client-session, nchannels 1 debug3: channel 0: status: The following connections are open:

0 client-session (t4 r0 i3/0 o3/0 fd -1/-1 cc -1)

debug3: close - io:002063F8, type:3, fd:6, table_index:6 debug3: send packet: type 1 debug3: fd 0 is not O_NONBLOCK debug3: fd 1 is not O_NONBLOCK Transferred: sent 1844, received 2864 bytes, in -0.3 seconds debug1: Exit status 0 debug3: close - io:001D6D58, type:1, fd:3, table_index:3 debug3: Unregister child at index 0, 0 zombies of 1 << This is what is executed when the program crashes.

C:\Users\chris.TSNET\Downloads\OpenSSH-Win32\OpenSSH-Win32>

diogob commented 6 years ago

Turning on the debug fixed the problem for me as well