Timeout on GetReply during UploadFile when using PlainTextEncryption.

[leotohill]

(Edited based on later findings: See the comments for an identification of the cause and proposed solution.)

FTP OS: Windows server 2019 FTP Server: IIS

Computer OS: Windows server 2019

FluentFTP Version: 37.0.3.0

When using the PlainTextEncryption (aka ccc) option, an operation times out on GetReply(). This is reproducable (though sporadically) by simply connecting and then calling GetWorkingDirectory().

See my following comments for logs and ultimate problem identification.

[leotohill]

more findings by using a test like this. The failure is definitely timing-related.

//non standard port, I know. 
var ftp = new FtpClient("localhost", 3409, credentials);
ftp.EncryptionMode = FluentFTP.FtpEncryptionMode.Explicit;
// my validation method approves all, for this test. 
ftp.ValidateCertificate += RemoteCertificateValidation;
ftp.PlainTextEncryption = true;
// reduced timeout for testing purposes, 2s should be plenty
// since I'm testing against localhost. 
ftp.ReadTimeout = 2000;
ftp.Connect();
// if I uncomment the next line, the GetWorkingDirectory will work.
//var size = ftp.GetFileSize("nosuchfile");
var dir = ftp.GetWorkingDirectory();  // times out on socket, usually. 

I've found that anything that slows operations, or perhaps causes a thread interruption, between certain code points A and B makes it work. (exact points A and B are unknown) . So, a race condition is implied. Adding logging to console makes it work, presumably due to the time or thread behavior of those operations. A thread.sleep(1) at the top of ReadStaleData() makes it work.

I enhanced ReadStaleData with some additional diagnostic logging, and also this log provides better information overall than the one that I posted in my OP. Here it is:

# Connect()
Status:   Connecting to ::1:3409
Response: 220 Microsoft FTP Service
Status:   Detected FTP server: WindowsServerIIS
closeStream: True. evenEncrypted: False.
Command:  AUTH TLS
Response: 234 AUTH command ok. Expecting TLS Negotiation.
Status:   FTPS Authentication Successful
Status:   Time to activate encryption: 0h 0m 0s.  Total Seconds: 0.079978.
closeStream: True. evenEncrypted: False.
Command:  USER ftptestuser1
Response: 331 Password required
closeStream: True. evenEncrypted: False.
Command:  PASS ***
Response: 230 User logged in.
closeStream: False. evenEncrypted: True.
closeStream: True. evenEncrypted: False.
Command:  PBSZ 0
Response: 200 PBSZ command successful.
closeStream: True. evenEncrypted: False.
Command:  PROT P
Response: 200 PROT command successful.
closeStream: True. evenEncrypted: False.
Command:  FEAT
Response: 211-Extended features supported:
Response: LANG EN*
Response: UTF8
Response: AUTH TLS;TLS-C;SSL;TLS-P;
Response: PBSZ
Response: PROT C;P;
Response: CCC
Response: HOST
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: 211 END
Status:   Text encoding: System.Text.UTF8Encoding
closeStream: True. evenEncrypted: False.
Command:  OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
closeStream: True. evenEncrypted: False.
Command:  SYST
Response: 215 Windows_NT
closeStream: True. evenEncrypted: False.
Command:  CCC
Response: 200 CCC command successful.
closeStream: False. evenEncrypted: True.
Status:   Listing parser set to: Windows
closeStream: True. evenEncrypted: False.
Status:   There is stale data on the socket, maybe our connection timed out or you did not call GetReply(). Re-connecting...
^Q?+?"??9_)?? ???se data was:  
Status:   Disposing FtpSocketStream...

# Connect()
Status:   Connecting to ::1:3409
Response: 220 Microsoft FTP Service
Status:   Detected FTP server: WindowsServerIIS
closeStream: True. evenEncrypted: False.
Command:  AUTH TLS
Response: 234 AUTH command ok. Expecting TLS Negotiation.
Status:   FTPS Authentication Successful
Status:   Time to activate encryption: 0h 0m 0s.  Total Seconds: 0.0019795.
closeStream: True. evenEncrypted: False.
Command:  USER ftptestuser1
Response: 331 Password required
closeStream: True. evenEncrypted: False.
Command:  PASS ***
Response: 230 User logged in.
closeStream: False. evenEncrypted: True.
closeStream: True. evenEncrypted: False.
Command:  PBSZ 0
Response: 200 PBSZ command successful.
closeStream: True. evenEncrypted: False.
Command:  PROT P
Response: 200 PROT command successful.
closeStream: True. evenEncrypted: False.
Command:  FEAT
Response: 211-Extended features supported:
Response: LANG EN*
Response: UTF8
Response: AUTH TLS;TLS-C;SSL;TLS-P;
Response: PBSZ
Response: PROT C;P;
Response: CCC
Response: HOST
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: 211 END
Status:   Text encoding: System.Text.UTF8Encoding
closeStream: True. evenEncrypted: False.
Command:  OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
closeStream: True. evenEncrypted: False.
Command:  SYST
Response: 215 Windows_NT
closeStream: True. evenEncrypted: False.
Command:  CCC
Response: 200 CCC command successful.
closeStream: False. evenEncrypted: True.
Status:   Listing parser set to: Windows
Command:  PWD
Status:   Disposing FtpSocketStream...

Unhandled Exception: System.TimeoutException: Timed out trying to read data from the socket stream!
   at FluentFTP.FtpSocketStream.Read(Byte[] buffer, Int32 offset, Int32 count) in D:\FluentFTP\FluentFTP\Streams\FtpSocketStream.cs:line 484
   at FluentFTP.FtpSocketStream.ReadLine(Encoding encoding) in D:\FluentFTP\FluentFTP\Streams\FtpSocketStream.cs:line 543
   at FluentFTP.FtpClient.GetReply() in D:\FluentFTP\FluentFTP\Client\FtpClient_Stream.cs:line 245
   at FluentFTP.FtpClient.Execute(String command) in D:\FluentFTP\FluentFTP\Client\FtpClient_Stream.cs:line 85
   at FluentFTP.FtpClient.ReadCurrentWorkingDirectory() in D:\FluentFTP\FluentFTP\Client\FtpClient_FolderManagement.cs:line 733
   at FluentFTP.FtpClient.GetWorkingDirectory() in D:\FluentFTP\FluentFTP\Client\FtpClient_FolderManagement.cs:line 703
   at Test874.Program.Main(String[] args) in D:\FluentFTP\Test874\Program.cs:line 35
Press any key to continue . . .

I'm disappointed and discouraged.

[leotohill]

I've identified the problem and a solution. It involves stale data (an unread server response).

To reiterate, the scenario is simply a connect when using the CCC option, followed by a call to GetWorkingDirectory(), which hangs/times out on the GetReply() call following the sending of the PWD command.

Details:

After sending the CCC command and reading the response from the server, Fluent then calls Close() on FtpSslStream, which issues a TLS "close_notify" to the server, and then closes the ssl stream.

Subsequently, Fluent calls ReadStaleData(), with the intent to consume the server response to the close_notify. See FtpClient.Connect() following the comment "// read stale data (server's reply?)"

This is unreliable and the cause of the problem. ReadStaleData() depends on (m_stream.SocketDataAvailable > 0) which will only be true if the server response has already reached the client. This will not necessarily be the case - the server response may not yet have arrived. So the response to the close_notify goes unread.

The additional call to ReadStaleData() at the top of Execute(command) also fails to read the response to close_notify, for the same reason.

Therefore, the call to GetReply() after the PWD command is issued will attempt to read the response to the close_notify, which is itself still under tls encryption. I don't know why this hangs (blocks waiting for data), rather than just reads an uninterpretable response, but it does.

This is the scenario that results in the hang of GetReply() after the PWD command.

I've tested my theory by modifying FtpSslStream.Close() to read the response, much like GetReply(). This fixed the problem.

TLS specs (I reviewed 1.1 through 1.3) are clear that the server MUST respond to the close_notify message, so this approach seems safe, at least with respect to trying to read the response. If Fluent needs to support non-compliant servers that do not send responses, it should be a configuration option.

With a bit of feedback and guidance I could submit a pull request for this change. I urgently need this library so I hope that this can work out.

Leo

[robinrodricks]

If you can fix it you are very welcome to submit a PR. The issue is quite complex so I don't have any advice at this point. Currently there were issues with the default .NET stream so we have implemented our own secure stream.

[robinrodricks]

It is implemented here -https://github.com/robinrodricks/FluentFTP/blob/master/FluentFTP/Streams/FtpSslStream.cs

[FanDjango]

We have done this in V40-V41. I am closing this and referring you to #873 (also your issue), which also talks about GetReply(...) and ReadStaleData() - these and they way they are used (and where they are used ) has been changed a lot since V37. Since you are the one who can reproduce these things on IIS I would like to work with you in that issues and iron out any remaining things.