Skip to content

ssh server randomly crashing when using sftp. #778

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
crose-88 opened this issue Jun 20, 2017 · 8 comments
Closed

ssh server randomly crashing when using sftp. #778

crose-88 opened this issue Jun 20, 2017 · 8 comments

Comments

@crose-88
Copy link

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
Copy link
Collaborator

bagajjal commented Jun 20, 2017

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
Copy link
Author

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 [email protected]
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,[email protected],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: [email protected],[email protected],[email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],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,[email protected],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: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],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: [email protected] MAC: compression: none
debug1: kex: client->server cipher: [email protected] 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
[email protected]'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 [email protected]
debug3: send packet: type 80
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 80
debug1: client_input_global_request: rtype [email protected] 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
Copy link
Collaborator

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 create sshd.pid under logs folder by default #493

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

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

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

@crose-88
Copy link
Author

crose-88 commented Jul 6, 2017

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
Copy link
Collaborator

bagajjal commented Jul 6, 2017

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/

  1. 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

  2. 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
Copy link
Author

crose-88 commented Jul 7, 2017

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 [email protected]
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,[email protected],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: [email protected],[email protected],[email protected],[email protected],[email protected],ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa
debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],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,[email protected],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: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr
debug2: MACs ctos: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],hmac-sha2-256,hmac-sha2-512,hmac-sha1
debug2: MACs stoc: [email protected],[email protected],[email protected],[email protected],[email protected],[email protected],[email protected],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: [email protected] MAC: compression: none
debug1: kex: client->server cipher: [email protected] 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
[email protected]'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 [email protected]
debug3: send packet: type 80
debug1: Entering interactive session.
debug1: pledge: network
debug3: receive packet: type 80
debug1: client_input_global_request: rtype [email protected] 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
Copy link
Author

crose-88 commented Jul 7, 2017

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 "[email protected]" revision 1
debug2: Server supports extension "[email protected]" revision 2
debug2: Server supports extension "[email protected]" revision 2
debug2: Server supports extension "[email protected]" revision 1
debug2: Server supports extension "[email protected]" 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
Copy link

diogob commented Jan 9, 2018

Turning on the debug fixed the problem for me as well

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants