CoreFTP icon indicating copy to clipboard operation
CoreFTP copied to clipboard

Published 20 hours ago • verified publisher icon sparkeh9

Can not open datastream with EncryptionType == FtpEncryption.Explicit

Open synhaptein opened this issue 7 years ago • 9 comments

When trying to open a datastream with EncryptionType == FtpEncryption.Explicit in basically get stuck in ActivateEncryptionAsync() while calling SslStream.AuthenticateAsClientAsync(..) https://github.com/sparkeh9/CoreFTP/blob/c5d25f6c775c42b92e022f9d4a3eaee93254b183/src/CoreFtp/Infrastructure/Stream/FtpControlStream.cs#L417 and then fail with this stacktrace


System.IO.IOException: Authentication failed because the remote party has closed the transport stream.
   at System.Net.Security.SslState.StartReadFrame(Byte[] buffer, Int32 readBytes, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslState.PartialFrameCallback(AsyncProtocolRequest asyncRequest)
--- End of stack trace from previous location where exception was thrown ---
   at System.Net.Security.SslState.InternalEndProcessAuthentication(LazyAsyncResult lazyResult)
   at System.Net.Security.SslState.EndProcessAuthentication(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoreFtp.Infrastructure.Stream.FtpControlStream.<ActivateEncryptionAsync>d__64.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoreFtp.Infrastructure.Stream.FtpControlStream.<ConnectStreamAsync>d__60.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoreFtp.Infrastructure.Stream.FtpControlStream.<OpenDataStreamAsync>d__58.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoreFtp.FtpClient.<ConnectDataStreamAsync>d__52.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoreFtp.FtpClient.<OpenFileStreamAsync>d__50.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at CoreFtp.FtpClient.<OpenFileWriteStreamAsync>d__39.MoveNext()

      [FtpClient] Sending command: PWD
      Getting Response
      Response expected, but no data exists on the socket
      257 "/" is your current location
      Finished receiving message
      [FtpClient] Opening filestream for /dir/file.ext, STOR
      [FtpClient] Connecting to a data socket
      [FtpClient] Sending command: EPSV
      Getting Response
      Response expected, but no data exists on the socket
      229 Extended Passive mode OK (|||31041|)
      Finished receiving message
      [FtpSocketStream] Opening datastream
      Connecting stream on ftp.server.com:31041
      Connecting
      [nothing, then crash after what I presume is a server-side timeout]

Any idea? Other detail Could not activate encryption for the connection: The remote certificate is invalid according to the validation procedure.so I set IgnoreCertificateErrors = true.

synhaptein avatar Feb 07 '17 21:02 synhaptein

What OS and .NET framework is your dev machine, and what type of environment are you trying to connect to? just so I can try to reproduce it :)

sparkeh9 avatar Feb 08 '17 20:02 sparkeh9

I reproduced it on linux (1.0.3), windows (1.0.3) and osx (1.0.0) on pureftpd

220---------- Welcome to Pure-FTPd [privsep] [TLS] ---------- 211-Extensions supported: EPRT IDLE MDTM SIZE MFMT REST STREAM MLST type*;size*;sizd*;modify*;UNIX.mode*;UNIX.uid*;UNIX.gid*;unique*; MLSD AUTH TLS PBSZ PROT UTF8 TVFS ESTA PASV EPSV SPSV 211 End.

synhaptein avatar Feb 08 '17 20:02 synhaptein

I'm having this same issue.

nine-2-five avatar May 08 '17 05:05 nine-2-five

I'm looking into this issue. The current code works fine for most FTP servers (filezilla for example), but I've run into similar symptoms with ProFTPd running on CentOS.

There seems to be a problem with the TLS handshake for the data connection.

sparkeh9 avatar May 24 '17 09:05 sparkeh9

I have just run into this issue and it seems that with some servers the order of commands are as follows: a. open data socket stream b. send command on control stream c. Activate encryption on data socket stream

Hope this helps

ishchatul avatar Feb 12 '19 19:02 ishchatul

I am having the "remote closed the transport stream" connecting to filezilla server. @ishchatul : Did your abc technique work for CoreFtp?

Adjusted1 avatar Nov 08 '19 22:11 Adjusted1

Another Core compat. ftp library gives me the same error (FluentFTP), maybe .Net Core has an issue here?

Adjusted1 avatar Nov 08 '19 23:11 Adjusted1

Same Problem here, but I use .NET Framework 4.7.2. FileZilla works and gives me the following log:

2019-11-28 09:47:37 7744 1 Status: Resolving address of xername.your-backup.de
2019-11-28 09:47:37 7744 1 Status: Connecting to [1111:111:111:1111::1]:21...
2019-11-28 09:47:37 7744 1 Status: Connection established, waiting for welcome message...
2019-11-28 09:47:37 7744 1 Response: 220 ProFTPD Server (xxxx) [1111:111:111:1111::1]
2019-11-28 09:47:37 7744 1 Command: AUTH TLS
2019-11-28 09:47:37 7744 1 Response: 234 AUTH TLS successful
2019-11-28 09:47:37 7744 1 Status: Initializing TLS...
2019-11-28 09:47:37 7744 1 Status: Verifying certificate...
2019-11-28 09:47:37 7744 1 Status: TLS connection established.
2019-11-28 09:47:37 7744 1 Command: USER xername
2019-11-28 09:47:37 7744 1 Response: 331 Password required for xername
2019-11-28 09:47:37 7744 1 Command: PASS ****************
2019-11-28 09:47:37 7744 1 Response: 230 User xername logged in
2019-11-28 09:47:37 7744 1 Command: SYST
2019-11-28 09:47:37 7744 1 Response: 215 UNIX Type: L8
2019-11-28 09:47:37 7744 1 Command: FEAT
2019-11-28 09:47:37 7744 1 Response: 211-Features:
2019-11-28 09:47:37 7744 1 Response:  AUTH TLS
2019-11-28 09:47:37 7744 1 Response:  CCC
2019-11-28 09:47:37 7744 1 Response:  CLNT
2019-11-28 09:47:37 7744 1 Response:  EPRT
2019-11-28 09:47:37 7744 1 Response:  EPSV
2019-11-28 09:47:37 7744 1 Response:  HOST
2019-11-28 09:47:37 7744 1 Response:  LANG ru-RU.UTF-8;ru-RU;zh-TW.UTF-8;zh-TW;ja-JP.UTF-8;ja-JP;zh-CN.UTF-8;zh-CN;bg-BG.UTF-8;bg-BG;es-ES.UTF-8;es-ES;it-IT.UTF-8;it-IT;ko-KR.UTF-8;ko-KR;en-US.UTF-8;en-US*;fr-FR.UTF-8;fr-FR
2019-11-28 09:47:37 7744 1 Response:  MDTM
2019-11-28 09:47:37 7744 1 Response:  MFF modify;UNIX.group;UNIX.mode;
2019-11-28 09:47:37 7744 1 Response:  MFMT
2019-11-28 09:47:37 7744 1 Response:  MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;
2019-11-28 09:47:37 7744 1 Response:  PBSZ
2019-11-28 09:47:37 7744 1 Response:  PROT
2019-11-28 09:47:37 7744 1 Response:  REST STREAM
2019-11-28 09:47:37 7744 1 Response:  SIZE
2019-11-28 09:47:37 7744 1 Response:  SSCN
2019-11-28 09:47:37 7744 1 Response:  TVFS
2019-11-28 09:47:37 7744 1 Response:  UTF8
2019-11-28 09:47:37 7744 1 Response: 211 End
2019-11-28 09:47:37 7744 1 Command: CLNT FileZilla
2019-11-28 09:47:37 7744 1 Response: 200 OK
2019-11-28 09:47:37 7744 1 Command: OPTS UTF8 ON
2019-11-28 09:47:37 7744 1 Response: 200 UTF8 set to on
2019-11-28 09:47:37 7744 1 Command: PBSZ 0
2019-11-28 09:47:37 7744 1 Response: 200 PBSZ 0 successful
2019-11-28 09:47:37 7744 1 Command: PROT P
2019-11-28 09:47:37 7744 1 Response: 200 Protection set to Private
2019-11-28 09:47:37 7744 1 Status: Logged in
2019-11-28 09:47:37 7744 1 Status: Retrieving directory listing...
2019-11-28 09:47:37 7744 1 Command: PWD
2019-11-28 09:47:37 7744 1 Response: 257 "/" is the current directory
2019-11-28 09:47:37 7744 1 Command: TYPE I
2019-11-28 09:47:37 7744 1 Response: 200 Type set to I
2019-11-28 09:47:37 7744 1 Command: EPSV
2019-11-28 09:47:37 7744 1 Response: 229 Entering Extended Passive Mode (|||58285|)
2019-11-28 09:47:37 7744 1 Command: MLSD
2019-11-28 09:47:37 7744 1 Response: 150 Opening BINARY mode data connection for MLSD
2019-11-28 09:47:37 7744 1 Response: 226 Transfer complete
2019-11-28 09:47:37 7744 1 Status: Directory listing of "/" successful
2019-11-28 09:48:22 7744 2 Status: Resolving address of xername.your-backup.de
2019-11-28 09:48:22 7744 2 Status: Connecting to [1111:111:111:1111::1]:21...
2019-11-28 09:48:22 7744 2 Status: Connection established, waiting for welcome message...
2019-11-28 09:48:22 7744 2 Response: 220 ProFTPD Server (Hetzner Backup) [1111:111:111:1111::1]
2019-11-28 09:48:22 7744 2 Command: AUTH TLS
2019-11-28 09:48:22 7744 2 Response: 234 AUTH TLS successful
2019-11-28 09:48:22 7744 2 Status: Initializing TLS...
2019-11-28 09:48:22 7744 2 Status: Verifying certificate...
2019-11-28 09:48:22 7744 2 Status: TLS connection established.
2019-11-28 09:48:22 7744 2 Command: USER xername
2019-11-28 09:48:22 7744 2 Response: 331 Password required for xername
2019-11-28 09:48:22 7744 2 Command: PASS ****************
2019-11-28 09:48:22 7744 2 Response: 230 User xername logged in
2019-11-28 09:48:22 7744 2 Command: CLNT FileZilla
2019-11-28 09:48:22 7744 2 Response: 200 OK
2019-11-28 09:48:22 7744 2 Command: OPTS UTF8 ON
2019-11-28 09:48:22 7744 2 Response: 200 UTF8 set to on
2019-11-28 09:48:22 7744 2 Command: PBSZ 0
2019-11-28 09:48:22 7744 2 Response: 200 PBSZ 0 successful
2019-11-28 09:48:22 7744 2 Command: PROT P
2019-11-28 09:48:22 7744 2 Response: 200 Protection set to Private
2019-11-28 09:48:22 7744 2 Status: Logged in
2019-11-28 09:48:22 7744 2 Status: Starting upload of xxx.zip
2019-11-28 09:48:22 7744 2 Command: CWD /
2019-11-28 09:48:22 7744 2 Response: 250 CWD command successful
2019-11-28 09:48:22 7744 2 Command: PWD
2019-11-28 09:48:22 7744 2 Response: 257 "/" is the current directory
2019-11-28 09:48:22 7744 2 Command: TYPE I
2019-11-28 09:48:22 7744 2 Response: 200 Type set to I
2019-11-28 09:48:22 7744 2 Command: EPSV
2019-11-28 09:48:22 7744 2 Response: 229 Entering Extended Passive Mode (|||50258|)
2019-11-28 09:48:22 7744 2 Command: STOR xxx.zip
2019-11-28 09:48:22 7744 2 Response: 150 Opening BINARY mode data connection for xxx.zip
2019-11-28 09:48:23 7744 2 Response: 226 Transfer complete
2019-11-28 09:48:23 7744 2 Status: File transfer successful, transferred 16.715.696 bytes in 1 second
2019-11-28 09:48:23 7744 2 Status: Retrieving directory listing of "/"...
2019-11-28 09:48:23 7744 2 Command: EPSV
2019-11-28 09:48:23 7744 2 Response: 229 Entering Extended Passive Mode (|||65093|)
2019-11-28 09:48:23 7744 2 Command: MLSD
2019-11-28 09:48:23 7744 2 Response: 150 Opening BINARY mode data connection for MLSD
2019-11-28 09:48:23 7744 2 Response: 226 Transfer complete
2019-11-28 09:48:23 7744 2 Status: Directory listing of "/" successful
2019-11-28 09:55:18 8144 1 Status: Resolving address of u147290.your-backup.de
2019-11-28 09:55:18 8144 1 Status: Connecting to [2a01:4f8:b19:3000::6]:21...
2019-11-28 09:55:18 8144 1 Status: Connection established, waiting for welcome message...
2019-11-28 09:55:18 8144 1 Response: 220 ProFTPD Server (Hetzner Backup) [2a01:4f8:b19:3000::6]
2019-11-28 09:55:18 8144 1 Command: AUTH TLS
2019-11-28 09:55:18 8144 1 Response: 234 AUTH TLS successful
2019-11-28 09:55:18 8144 1 Status: Initializing TLS...
2019-11-28 09:55:18 8144 1 Status: Verifying certificate...
2019-11-28 09:55:18 8144 1 Status: TLS connection established.
2019-11-28 09:55:18 8144 1 Command: USER u147290
2019-11-28 09:55:18 8144 1 Response: 331 Password required for u147290
2019-11-28 09:55:18 8144 1 Command: PASS ****************
2019-11-28 09:55:18 8144 1 Response: 230 User u147290 logged in
2019-11-28 09:55:18 8144 1 Command: SYST
2019-11-28 09:55:18 8144 1 Response: 215 UNIX Type: L8
2019-11-28 09:55:18 8144 1 Command: FEAT
2019-11-28 09:55:18 8144 1 Response: 211-Features:
2019-11-28 09:55:18 8144 1 Response:  AUTH TLS
2019-11-28 09:55:18 8144 1 Response:  CCC
2019-11-28 09:55:18 8144 1 Response:  CLNT
2019-11-28 09:55:18 8144 1 Response:  EPRT
2019-11-28 09:55:18 8144 1 Response:  EPSV
2019-11-28 09:55:18 8144 1 Response:  HOST
2019-11-28 09:55:18 8144 1 Response:  LANG ru-RU.UTF-8;ru-RU;zh-TW.UTF-8;zh-TW;ja-JP.UTF-8;ja-JP;zh-CN.UTF-8;zh-CN;bg-BG.UTF-8;bg-BG;es-ES.UTF-8;es-ES;it-IT.UTF-8;it-IT;ko-KR.UTF-8;ko-KR;en-US.UTF-8;en-US*;fr-FR.UTF-8;fr-FR
2019-11-28 09:55:18 8144 1 Response:  MDTM
2019-11-28 09:55:18 8144 1 Response:  MFF modify;UNIX.group;UNIX.mode;
2019-11-28 09:55:18 8144 1 Response:  MFMT
2019-11-28 09:55:18 8144 1 Response:  MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX.mode*;UNIX.owner*;UNIX.ownername*;
2019-11-28 09:55:18 8144 1 Response:  PBSZ
2019-11-28 09:55:18 8144 1 Response:  PROT
2019-11-28 09:55:18 8144 1 Response:  REST STREAM
2019-11-28 09:55:18 8144 1 Response:  SIZE
2019-11-28 09:55:18 8144 1 Response:  SSCN
2019-11-28 09:55:18 8144 1 Response:  TVFS
2019-11-28 09:55:18 8144 1 Response:  UTF8
2019-11-28 09:55:18 8144 1 Response: 211 End
2019-11-28 09:55:18 8144 1 Command: CLNT FileZilla
2019-11-28 09:55:18 8144 1 Response: 200 OK
2019-11-28 09:55:18 8144 1 Command: OPTS UTF8 ON
2019-11-28 09:55:18 8144 1 Response: 200 UTF8 set to on
2019-11-28 09:55:18 8144 1 Command: PBSZ 0
2019-11-28 09:55:18 8144 1 Response: 200 PBSZ 0 successful
2019-11-28 09:55:18 8144 1 Command: PROT P
2019-11-28 09:55:18 8144 1 Response: 200 Protection set to Private
2019-11-28 09:55:18 8144 1 Status: Logged in
2019-11-28 09:55:18 8144 1 Status: Retrieving directory listing...
2019-11-28 09:55:18 8144 1 Command: PWD
2019-11-28 09:55:18 8144 1 Response: 257 "/" is the current directory
2019-11-28 09:55:18 8144 1 Command: TYPE I
2019-11-28 09:55:18 8144 1 Response: 200 Type set to I
2019-11-28 09:55:18 8144 1 Command: EPSV
2019-11-28 09:55:18 8144 1 Response: 229 Entering Extended Passive Mode (|||54647|)
2019-11-28 09:55:18 8144 1 Command: MLSD
2019-11-28 09:55:18 8144 1 Response: 150 Opening BINARY mode data connection for MLSD
2019-11-28 09:55:18 8144 1 Response: 226 Transfer complete
2019-11-28 09:55:18 8144 1 Status: Directory listing of "/" successful
2019-11-28 09:55:24 8144 1 Status: Deleting "/xxx.zip"
2019-11-28 09:55:24 8144 1 Command: DELE xxx.zip
2019-11-28 09:55:24 8144 1 Response: 250 DELE command successful

The same connection, same file, same server, same client (Win Server 2012) leads to the following CoreFtp-Log:

Trace: Disconnecting
Debug: Connecting stream on servername.domain.de:21
Debug: Connecting
Debug: Waiting for welcome message
Trace: Getting Response
Debug: 220 ProFTPD Server (xxxx) [::1111:11.11.11.111]
Trace: Finished receiving message
Debug: Encrypting explicitly
Debug: [FtpClient] Sending command: AUTH TLS
Trace: Getting Response
Debug: 234 AUTH TLS successful
Trace: Finished receiving message
Debug: [FtpClient] Sending command: USER xername
Trace: Getting Response
Debug: 331 Password required for xername
Trace: Finished receiving message
Debug: [FtpClient] Sending command: PASS *****
Trace: Getting Response
Debug: 230 User xername logged in
Trace: Finished receiving message
Debug: [FtpClient] Sending command: PBSZ 0
Trace: Getting Response
Debug: 200 PBSZ 0 successful
Trace: Finished receiving message
Debug: [FtpClient] Sending command: PROT P
Trace: Getting Response
Debug: 200 Protection set to Private
Trace: Finished receiving message
Trace: [FtpClient] Determining features
Debug: [FtpClient] Sending command: FEAT
Trace: Getting Response
Debug: 211-Features:
Debug:  AUTH TLS
Debug:  CCC
Debug:  CLNT
Debug:  EPRT
Debug:  EPSV
Debug:  HOST
Debug:  LANG ru-RU.UTF-8;ru-RU;zh-TW.UTF-8;zh-TW;ja-JP.UTF-8;ja-JP;zh-CN.UTF-8;
h-CN;bg-BG.UTF-8;bg-BG;es-ES.UTF-8;es-ES;it-IT.UTF-8;it-IT;ko-KR.UTF-8;ko-KR;en
US.UTF-8;en-US*;fr-FR.UTF-8;fr-FR
Debug:  MDTM
Debug:  MFF modify;UNIX.group;UNIX.mode;
Debug:  MFMT
Debug:  MLST modify*;perm*;size*;type*;unique*;UNIX.group*;UNIX.groupname*;UNIX
mode*;UNIX.owner*;UNIX.ownername*;
Debug:  PBSZ
Debug:  PROT
Debug:  REST STREAM
Debug:  SIZE
Debug:  SSCN
Debug:  TVFS
Debug:  UTF8
Debug: 211 End
Trace: Finished receiving message
Trace: [FtpClient] Determining directory provider
Debug: [FtpClient] Sending command: OPTS UTF8 ON
Trace: Getting Response
Debug: 200 UTF8 set to on
Trace: Finished receiving message
Trace: [FtpClient] Setting transfer mode Binary,
Debug: [FtpClient] Sending command: TYPE I
Trace: Getting Response
Debug: 200 Type set to I
Trace: Finished receiving message
Trace: [FtpClient] changing directory to /
Debug: [FtpClient] Sending command: CWD /
Trace: Getting Response
Debug: 250 CWD command successful
Trace: Finished receiving message
Debug: [FtpClient] Sending command: PWD
Trace: Getting Response
Debug: 257 "/" is the current directory
Trace: Finished receiving message
Debug: [FtpClient] Opening file read stream for /xxx.zip
Debug: [FtpClient] Creating directory structure recursively
Debug: [FtpClient] Opening filestream for /xxx.zip, STOR
Trace: [FtpClient] Connecting to a data socket
Debug: [FtpClient] Sending command: EPSV
Trace: Getting Response
Debug: 229 Entering Extended Passive Mode (|||65246|)
Trace: Finished receiving message
Debug: [FtpSocketStream] Opening datastream
Debug: Connecting stream on servername.domain.de:65246
Debug: Connecting

It hangs at this code in FtpControlStream.cs:

        protected async Task ConnectStreamAsync( string host, int port, CancellationToken token )
        {
            try
            {
                await semaphore.WaitAsync( token );
                Logger?.LogDebug( $"Connecting stream on {host}:{port}" );
                Socket = await ConnectSocketAsync( host, port, token );

                BaseStream = new NetworkStream( Socket );
                LastActivity = DateTime.Now;

                if ( IsDataConnection )
                {
                    if ( Configuration.ShouldEncrypt && Configuration.EncryptionType == FtpEncryption.Explicit )
                    {
                        await ActivateEncryptionAsync();   <---- Hangs here
                    }
                    return;
                }

mirkomaty avatar Nov 28 '19 09:11 mirkomaty

Note the different IPv6 addresses… But this seems to work. The connection for the passive mode data stream is established but CoreFtp can't activate the encryption. Seems to fail during TLS handshake.

If I can do anything to further clarify the situation, please ask.

mirkomaty avatar Nov 28 '19 09:11 mirkomaty