Open
Description
Prerequisites
- Write a descriptive title.
- Make sure you are able to repro it on the latest version
- Search the existing issues.
Steps to reproduce
Hello Team,
-This is an OpenSSH service installed in an Azure Windows Server 2016.
- User connects to SFTP using the client MuleSoft, authentication works fine but then tries to upload a file receives the error message: 'Connection reset, and a 0kb file is written'.
- The same issue happens if it is authenticating with Password or PublicKey.
- Using the same user from a source different to AWS works fine and files can be uploaded with no issues.
Any help will be appreciated!
Expected behavior
To be able to authenticate SFTP and upload files.Actual behavior
-When user tries to connect to SFTP and upload a file from AWS, authentication is successful but when tries to upload a file the connection is reset and closed.
-When the same user tries to connect from a source different to AWS, authentication is also successful, and it can upload files.
-We are trying to get any insights of what may cause these error messages, TCP connection seems to be working fine since both sites can communicate, sshd_config does not have any kind of configuration to filter by host.
-This is what we see in the server debug log:
_960 2022-12-05 11:17:51.839 debug3: recv - from CB(2) ERROR:108, io:0000015229982690
960 2022-12-05 11:17:51.839 error: kex_exchange_identification: read: Connection reset_
-From the client side, the error is the below, if we check the folder, there is the file that we were trying to upload with 0kb:
_Connection reset, and a 0kb file is written.Error details
14348 2022-12-05 11:17:50.818 debug3: fd 5 is not O_NONBLOCK
14348 2022-12-05 11:17:50.818 debug3: spawning "C:\\Program Files\\OpenSSH-Win64\\sshd.exe" -R
14348 2022-12-05 11:17:50.823 debug3: send_rexec_state: entering fd = 9 config len 575
14348 2022-12-05 11:17:50.823 debug3: ssh_msg_send: type 0
14348 2022-12-05 11:17:50.823 debug3: send_rexec_state: done
8856 2022-12-05 11:17:50.848 debug1: inetd sockets after dupping: 4, 4
8856 2022-12-05 11:17:50.848 Connection from 10.252.2.69 port 1026 on 10.252.2.38 port 22
8856 2022-12-05 11:17:50.848 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_8.1
8856 2022-12-05 11:17:50.848 debug1: Remote protocol version 2.0, remote software version JSCH-0.1.54
8856 2022-12-05 11:17:50.848 debug1: no match: JSCH-0.1.54
8856 2022-12-05 11:17:50.848 debug2: fd 4 setting O_NONBLOCK
8856 2022-12-05 11:17:50.878 debug3: spawning "C:\\Program Files\\OpenSSH-Win64\\sshd.exe" -y
8856 2022-12-05 11:17:50.883 debug2: Network child is on pid 8932
8856 2022-12-05 11:17:50.883 debug3: send_rexec_state: entering fd = 6 config len 575
8856 2022-12-05 11:17:50.883 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:50.883 debug3: send_rexec_state: done
8856 2022-12-05 11:17:50.883 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:50.883 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:50.883 debug3: preauth child monitor started
8856 2022-12-05 11:17:50.903 debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
8856 2022-12-05 11:17:50.903 debug3: send packet: type 20 [preauth]
8856 2022-12-05 11:17:50.903 debug1: SSH2_MSG_KEXINIT sent [preauth]
8856 2022-12-05 11:17:50.968 debug3: receive packet: type 20 [preauth]
8856 2022-12-05 11:17:50.968 debug1: SSH2_MSG_KEXINIT received [preauth]
8856 2022-12-05 11:17:50.968 debug2: local server KEXINIT proposal [preauth]
8856 2022-12-05 11:17:50.968 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 [preauth]
8856 2022-12-05 11:17:50.968 debug2: host key algorithms: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
8856 2022-12-05 11:17:50.968 debug2: ciphers ctos: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
8856 2022-12-05 11:17:50.968 debug2: ciphers stoc: [email protected],aes128-ctr,aes192-ctr,aes256-ctr,[email protected],[email protected] [preauth]
8856 2022-12-05 11:17:50.968 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 [preauth]
8856 2022-12-05 11:17:50.968 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 [preauth]
8856 2022-12-05 11:17:50.968 debug2: compression ctos: none,[email protected] [preauth]
8856 2022-12-05 11:17:50.968 debug2: compression stoc: none,[email protected] [preauth]
8856 2022-12-05 11:17:50.968 debug2: languages ctos: [preauth]
8856 2022-12-05 11:17:50.968 debug2: languages stoc: [preauth]
8856 2022-12-05 11:17:50.968 debug2: first_kex_follows 0 [preauth]
8856 2022-12-05 11:17:50.968 debug2: reserved 0 [preauth]
8856 2022-12-05 11:17:50.968 debug2: peer client KEXINIT proposal [preauth]
8856 2022-12-05 11:17:50.968 debug2: KEX algorithms: ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group14-sha1,diffie-hellman-group-exchange-sha256,diffie-hellman-group-exchange-sha1,diffie-hellman-group1-sha1 [preauth]
8856 2022-12-05 11:17:50.968 debug2: host key algorithms: ssh-rsa,ssh-dss,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521 [preauth]
8856 2022-12-05 11:17:50.968 debug2: ciphers ctos: aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc [preauth]
8856 2022-12-05 11:17:50.968 debug2: ciphers stoc: aes128-ctr,aes128-cbc,3des-ctr,3des-cbc,blowfish-cbc,aes192-ctr,aes192-cbc,aes256-ctr,aes256-cbc [preauth]
8856 2022-12-05 11:17:50.968 debug2: MACs ctos: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96 [preauth]
8856 2022-12-05 11:17:50.968 debug2: MACs stoc: hmac-md5,hmac-sha1,hmac-sha2-256,hmac-sha1-96,hmac-md5-96 [preauth]
8856 2022-12-05 11:17:50.968 debug2: compression ctos: none [preauth]
8856 2022-12-05 11:17:50.968 debug2: compression stoc: none [preauth]
8856 2022-12-05 11:17:50.968 debug2: languages ctos: [preauth]
8856 2022-12-05 11:17:50.968 debug2: languages stoc: [preauth]
8856 2022-12-05 11:17:50.968 debug2: first_kex_follows 0 [preauth]
8856 2022-12-05 11:17:50.968 debug2: reserved 0 [preauth]
8856 2022-12-05 11:17:50.968 debug1: kex: algorithm: ecdh-sha2-nistp256 [preauth]
8856 2022-12-05 11:17:50.968 debug1: kex: host key algorithm: ssh-rsa [preauth]
8856 2022-12-05 11:17:50.968 debug1: kex: client->server cipher: aes128-ctr MAC: hmac-sha1 compression: none [preauth]
8856 2022-12-05 11:17:50.968 debug1: kex: server->client cipher: aes128-ctr MAC: hmac-sha1 compression: none [preauth]
8856 2022-12-05 11:17:50.968 debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
8856 2022-12-05 11:17:51.053 debug3: receive packet: type 30 [preauth]
8856 2022-12-05 11:17:51.053 debug3: mm_sshkey_sign entering [preauth]
8856 2022-12-05 11:17:51.053 debug3: mm_request_send entering: type 6 [preauth]
8856 2022-12-05 11:17:51.053 debug3: mm_request_receive entering
8856 2022-12-05 11:17:51.053 debug3: monitor_read: checking request 6
8856 2022-12-05 11:17:51.053 debug3: mm_answer_sign
8856 2022-12-05 11:17:51.068 debug3: mm_answer_sign: KEX signature 0000023C2BBF3CD0(399)
8856 2022-12-05 11:17:51.068 debug3: mm_request_send entering: type 7
8856 2022-12-05 11:17:51.068 debug2: monitor_read: 6 used once, disabling now
8856 2022-12-05 11:17:51.068 debug3: mm_sshkey_sign: waiting for MONITOR_ANS_SIGN [preauth]
8856 2022-12-05 11:17:51.068 debug3: mm_request_receive_expect entering: type 7 [preauth]
8856 2022-12-05 11:17:51.068 debug3: mm_request_receive entering [preauth]
8856 2022-12-05 11:17:51.068 debug3: send packet: type 31 [preauth]
8856 2022-12-05 11:17:51.068 debug3: send packet: type 21 [preauth]
8856 2022-12-05 11:17:51.068 debug2: set_newkeys: mode 1 [preauth]
8856 2022-12-05 11:17:51.068 debug1: rekey out after 4294967296 blocks [preauth]
8856 2022-12-05 11:17:51.068 debug1: SSH2_MSG_NEWKEYS sent [preauth]
8856 2022-12-05 11:17:51.068 debug1: expecting SSH2_MSG_NEWKEYS [preauth]
8856 2022-12-05 11:17:51.168 debug3: receive packet: type 21 [preauth]
8856 2022-12-05 11:17:51.168 debug1: SSH2_MSG_NEWKEYS received [preauth]
8856 2022-12-05 11:17:51.168 debug2: set_newkeys: mode 0 [preauth]
8856 2022-12-05 11:17:51.168 debug1: rekey in after 4294967296 blocks [preauth]
8856 2022-12-05 11:17:51.168 debug1: KEX done [preauth]
8856 2022-12-05 11:17:51.168 debug3: receive packet: type 5 [preauth]
8856 2022-12-05 11:17:51.168 debug3: send packet: type 6 [preauth]
8856 2022-12-05 11:17:51.263 debug3: receive packet: type 50 [preauth]
8856 2022-12-05 11:17:51.263 debug1: userauth-request for user dtvSFTP service ssh-connection method none [preauth]
8856 2022-12-05 11:17:51.263 debug1: attempt 0 failures 0 [preauth]
8856 2022-12-05 11:17:51.263 debug3: mm_getpwnamallow entering [preauth]
8856 2022-12-05 11:17:51.263 debug3: mm_request_send entering: type 8 [preauth]
8856 2022-12-05 11:17:51.263 debug3: mm_request_receive entering
8856 2022-12-05 11:17:51.263 debug3: monitor_read: checking request 8
8856 2022-12-05 11:17:51.263 debug3: mm_answer_pwnamallow
8856 2022-12-05 11:17:51.263 debug2: parse_server_config: config reprocess config len 575
8856 2022-12-05 11:17:51.263 debug3: checking match for 'User itservices\\M47029' user dtvsftp host 10.252.2.69 addr 10.252.2.69 laddr 10.252.2.38 lport 22
8856 2022-12-05 11:17:51.263 debug3: match not found
8856 2022-12-05 11:17:51.263 debug3: checking match for 'User dtvSFTP' user dtvsftp host 10.252.2.69 addr 10.252.2.69 laddr 10.252.2.38 lport 22
8856 2022-12-05 11:17:51.263 debug1: user dtvsftp matched 'User dtvSFTP' at line 96
8856 2022-12-05 11:17:51.263 debug3: match found
8856 2022-12-05 11:17:51.263 debug3: reprocess config:97 setting ChrootDirectory E:\\sftp\\DTVInfor
8856 2022-12-05 11:17:51.263 debug3: checking match for 'User compassSFTP' user dtvsftp host 10.252.2.69 addr 10.252.2.69 laddr 10.252.2.38 lport 22
8856 2022-12-05 11:17:51.263 debug3: match not found
8856 2022-12-05 11:17:51.263 debug3: checking match for 'User itservices\\m47030' user dtvsftp host 10.252.2.69 addr 10.252.2.69 laddr 10.252.2.38 lport 22
8856 2022-12-05 11:17:51.263 debug3: match not found
8856 2022-12-05 11:17:51.263 debug3: checking match for 'Group administrators' user dtvsftp host 10.252.2.69 addr 10.252.2.69 laddr 10.252.2.38 lport 22
8856 2022-12-05 11:17:51.263 debug3: LsaLogonUser Succeeded (Impersonation: 0)
8856 2022-12-05 11:17:51.263 debug1: user dtvsftp does not match group list administrators at line 103
8856 2022-12-05 11:17:51.263 debug3: match not found
8856 2022-12-05 11:17:51.263 debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1
8856 2022-12-05 11:17:51.263 debug3: mm_request_send entering: type 9
8856 2022-12-05 11:17:51.263 debug2: monitor_read: 8 used once, disabling now
8856 2022-12-05 11:17:51.263 debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth]
8856 2022-12-05 11:17:51.263 debug3: mm_request_receive_expect entering: type 9 [preauth]
8856 2022-12-05 11:17:51.263 debug3: mm_request_receive entering [preauth]
8856 2022-12-05 11:17:51.268 debug2: input_userauth_request: setting up authctxt for dtvSFTP [preauth]
8856 2022-12-05 11:17:51.268 debug3: mm_inform_authserv entering [preauth]
8856 2022-12-05 11:17:51.268 debug3: mm_request_send entering: type 4 [preauth]
8856 2022-12-05 11:17:51.268 debug3: mm_request_receive entering
8856 2022-12-05 11:17:51.268 debug3: monitor_read: checking request 4
8856 2022-12-05 11:17:51.268 debug3: mm_answer_authserv: service=ssh-connection, style=
8856 2022-12-05 11:17:51.268 debug2: monitor_read: 4 used once, disabling now
8856 2022-12-05 11:17:51.268 debug2: input_userauth_request: try method none [preauth]
8856 2022-12-05 11:17:51.268 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
8856 2022-12-05 11:17:51.268 debug3: ensure_minimum_time_since: elapsed 5.001ms, delaying 3.103ms (requested 8.104ms) [preauth]
8856 2022-12-05 11:17:51.273 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
8856 2022-12-05 11:17:51.273 debug3: send packet: type 51 [preauth]
8856 2022-12-05 11:17:51.367 debug3: receive packet: type 50 [preauth]
8856 2022-12-05 11:17:51.367 debug1: userauth-request for user dtvSFTP service ssh-connection method keyboard-interactive [preauth]
8856 2022-12-05 11:17:51.367 debug1: attempt 1 failures 0 [preauth]
8856 2022-12-05 11:17:51.367 debug2: input_userauth_request: try method keyboard-interactive [preauth]
8856 2022-12-05 11:17:51.367 debug1: keyboard-interactive devs [preauth]
8856 2022-12-05 11:17:51.367 debug1: auth2_challenge: user=dtvSFTP devs= [preauth]
8856 2022-12-05 11:17:51.367 debug1: kbdint_alloc: devices '' [preauth]
8856 2022-12-05 11:17:51.367 debug2: auth2_challenge_start: devices [preauth]
8856 2022-12-05 11:17:51.367 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
8856 2022-12-05 11:17:51.367 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 8.104ms (requested 8.104ms) [preauth]
8856 2022-12-05 11:17:51.377 debug3: userauth_finish: failure partial=0 next methods="publickey,password,keyboard-interactive" [preauth]
8856 2022-12-05 11:17:51.377 debug3: send packet: type 51 [preauth]
8856 2022-12-05 11:17:51.472 debug3: receive packet: type 50 [preauth]
8856 2022-12-05 11:17:51.472 debug1: userauth-request for user dtvSFTP service ssh-connection method password [preauth]
8856 2022-12-05 11:17:51.472 debug1: attempt 2 failures 1 [preauth]
8856 2022-12-05 11:17:51.472 debug2: input_userauth_request: try method password [preauth]
8856 2022-12-05 11:17:51.472 debug3: mm_auth_password entering [preauth]
8856 2022-12-05 11:17:51.472 debug3: mm_request_send entering: type 12 [preauth]
8856 2022-12-05 11:17:51.472 debug3: mm_auth_password: waiting for MONITOR_ANS_AUTHPASSWORD [preauth]
8856 2022-12-05 11:17:51.472 debug3: mm_request_receive_expect entering: type 13 [preauth]
8856 2022-12-05 11:17:51.472 debug3: mm_request_receive entering [preauth]
8856 2022-12-05 11:17:51.472 debug3: mm_request_receive entering
8856 2022-12-05 11:17:51.472 debug3: monitor_read: checking request 12
8856 2022-12-05 11:17:51.472 debug3: mm_answer_authpassword: sending result 1
8856 2022-12-05 11:17:51.472 debug3: mm_request_send entering: type 13
8856 2022-12-05 11:17:51.472 Accepted password for dtvSFTP from 10.252.2.69 port 1026 ssh2
8856 2022-12-05 11:17:51.472 debug1: monitor_child_preauth: dtvSFTP has been authenticated by privileged process
8856 2022-12-05 11:17:51.472 debug3: mm_get_keystate: Waiting for new keys
8856 2022-12-05 11:17:51.472 debug3: mm_request_receive_expect entering: type 26
8856 2022-12-05 11:17:51.472 debug3: mm_request_receive entering
8856 2022-12-05 11:17:51.482 debug3: mm_get_keystate: GOT new keys
8856 2022-12-05 11:17:51.482 debug3: mm_auth_password: user authenticated [preauth]
8856 2022-12-05 11:17:51.482 debug3: user_specific_delay: user specific delay 0.000ms [preauth]
8856 2022-12-05 11:17:51.482 debug3: ensure_minimum_time_since: elapsed 0.000ms, delaying 8.104ms (requested 8.104ms) [preauth]
8856 2022-12-05 11:17:51.482 debug3: send packet: type 52 [preauth]
8856 2022-12-05 11:17:51.482 debug3: mm_request_send entering: type 26 [preauth]
8856 2022-12-05 11:17:51.482 debug3: mm_send_keystate: Finished sending state [preauth]
8856 2022-12-05 11:17:51.482 debug1: monitor_read_log: child log fd closed
8856 2022-12-05 11:17:51.507 debug3: spawning "C:\\Program Files\\OpenSSH-Win64\\sshd.exe" -z
8856 2022-12-05 11:17:51.507 User child is on pid 4428
8856 2022-12-05 11:17:51.507 debug3: send_rexec_state: entering fd = 5 config len 575
8856 2022-12-05 11:17:51.507 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:51.507 debug3: send_rexec_state: done
8856 2022-12-05 11:17:51.507 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:51.507 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:51.507 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:51.507 debug3: ssh_msg_send: type 0
8856 2022-12-05 11:17:51.507 debug3: ssh_msg_send: type 0
960 2022-12-05 11:17:51.839 debug3: recv - from CB(2) ERROR:108, io:0000015229982690
960 2022-12-05 11:17:51.839 error: kex_exchange_identification: read: Connection reset
14348 2022-12-05 11:17:51.849 debug3: fd 5 is not O_NONBLOCK
14348 2022-12-05 11:17:51.849 debug3: spawning "C:\\Program Files\\OpenSSH-Win64\\sshd.exe" -R
14348 2022-12-05 11:17:51.854 debug3: send_rexec_state: entering fd = 8 config len 575
14348 2022-12-05 11:17:51.854 debug3: ssh_msg_send: type 0
14348 2022-12-05 11:17:51.854 debug3: send_rexec_state: done
12244 2022-12-05 11:17:51.879 debug1: inetd sockets after dupping: 4, 4
12244 2022-12-05 11:17:51.879 Connection from 168.63.129.16 port 58456 on 10.252.2.38 port 22
12244 2022-12-05 11:17:51.879 debug1: Local version string SSH-2.0-OpenSSH_for_Windows_8.1Environment data
Name Value
--- ----
PSVersion 5.1.14393.5127
PSEdition Desktop
PSCompatibleVersions {1.0, 2.0, 3.0, 4.0...}
BuildVersion 10.0.14319.42000
CLRVersion 4.0.30319.42000
WSManStackVersion 3.0
PSRemotingProtocolVersion 2.3
SerializationVersion 1.1.0.1Version
SSH-2.0-OpenSSH_for_Windows_8.1
Visuals
No response