Failed to get EPSV port intermmittent but repeatable failure

[leotohill]

FTP OS: Windows server 2019 FTP Server: IIS

Computer OS: Windows server 2019

FluentFTP Version: ? 37.0.3.0

A simple test sometimes fails, indicating that the EPSV command did not return the expected response. Which is true, see the logs. But why? Also, the test does not fail when I debug my app, OR when I set FtpTrace.LogToFile. Weird, right? It will not fail when I capture a trace using a tracelistener. Server and client are the same machine. Also, sHould I be concerned about log messages that say " There is stale data on the socket, maybe our connection timed out or you did not call GetReply(). Re-connecting..."

Relevent code, where I'm calling my own wrapper of FtpClient, which does OpenRead, OpenWRite, and OpenAppend.

`

       using (var outStream = client.OpenWrite(TEST_FILENAME))
        {
            WriteToStreamInChunks(content, outStream, Encoding.UTF8, byteBuffer);
            outStream.Flush();  
            outStream.Close(); 
        }
        // read back the file just written and check its content
        using (var inStream = client.OpenRead(TEST_FILENAME))
        {
            var bytes = inStream.Read(byteBuffer, 0, BUF_SIZE);
            var newContent = Encoding.UTF8.GetString(byteBuffer, 0, bytes);
            Assert.AreEqual(content, newContent, "Did not read back what we wrote.");
        }

`

Logs :

# Connect()
Status:   Connecting to 127.0.0.1:3409
Response: 220 Microsoft FTP Service
Status:   Detected FTP server: WindowsServerIIS
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.0009949.
Command:  USER WSAMZN-N0JLNNJ9\FtpTestUser1
Response: 331 Password required
Command:  PASS ***
Response: 230 User logged in.
Command:  PBSZ 0
Response: 200 PBSZ command successful.
Command:  PROT P
Response: 200 PROT command successful.
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
Command:  OPTS UTF8 ON
Response: 200 OPTS UTF8 command successful - UTF8 encoding now ON.
Command:  SYST
Response: 215 Windows_NT
Status:   Listing parser set to: Windows
Command:  SIZE ftptest1.txt
Response: 213 58
Command:  TYPE I
Response: 200 Type set to I.

# OpenPassiveDataStream(AutoPassive, "APPE ftptest1.txt", 0)
Command:  EPSV
Response: 229 Entering Extended Passive Mode (|||56127|)
Status:   Connecting to 127.0.0.1:56127
Command:  APPE ftptest1.txt
Response: 125 Data connection already open; Transfer starting.
Status:   FTPS Authentication Successful
Status:   Time to activate encryption: 0h 0m 0s.  Total Seconds: 0.0009834.
Status:   Disposing FtpSocketStream...
Status:   Disposing FtpSocketStream...

# OpenRead("ftptest1.txt", Binary, 0, 0)

# GetFileSize("ftptest1.txt")
Command:  SIZE ftptest1.txt
Response: 226 Transfer complete.

# OpenPassiveDataStream(AutoPassive, "RETR ftptest1.txt", 0)
Command:  EPSV
Response: 213 116

# Dispose()
Status:   Disposing FtpClient object...
Status:   There is stale data on the socket, maybe our connection timed out or you did not call GetReply(). Re-connecting...
Status:   Disposing FtpSocketStream...
Status:   Not sending QUIT because the connection has already been closed.
Status:   Disposing FtpSocketStream...
Status:   Disposing FtpSocketStream...

[leotohill]

aha! What the trace is reporting as the response to the EPSV command is actually the response to my file write. Response "213 116" is IIS FTP saying "File Status, length 116 bytes" which is the length of the file I just wrote. So, hmm, I guess that after closing my write stream I need to do a GetReply()? What's the general rule for using GetReply()? I know that if I call it at the wrong time it will hang/timeout. Don't want that.
It's also unclear why attaching a debugger or logging to a file prevents this problem.

[leotohill]

And now I see in FtpClient.UploadFileInternal() your use of GetReply() (and NOOP, which I'll need to consider). I'd love to use the higher level API but I'm converting from another library and I need to stick to the patterns used there.

[leotohill]

I wonder if it would make sense for Fluent to read and discard any channel replies BEFORE issuing any command? Yeah, there would be unprocessed replies, but that might be ok, and interpreting a previous command's reply as the the current command's reply is never ok.

[robinrodricks]

I wonder if it would make sense for Fluent to read and discard any channel replies BEFORE issuing any command? Yeah, there would be unprocessed replies, but that might be ok, and interpreting a previous command's reply as the the current command's reply is never ok.

Possibly, its a good idea.

[robinrodricks]

We are already reading stale data on the socket. This should work... https://github.com/robinrodricks/FluentFTP/blob/master/FluentFTP/Client/FtpClient_Stream.cs#L51

[leotohill]

Yeah, but the ReadStaleData approach suffers from the same race condition as I encountered with the CCC command: yes, it will read stale data if that data has already arrived at the socket, but it may not have arrived yet. It is not a blocking read: it does not wait for data to arrive. Which explains my failure to repro the problem when debugging: the different timing in a debugging scenario gave different results. I don't see any reliable solution other than doing a blocking read (i.e., GetReply) in every case where a reply is expected. This would be the responsibility of the application code (the code that is using FluentFtp). The attempt to address the problem with ReadStaleData only makes it fail unpredictably.

[FanDjango]

I would like to know the status of this issue.

Reason:

From FluentFTP V41 onwards, there have been extensive modifications to GetReply() and stale data checking (previous to commands). It has a non-blocking and a blocking mode, and the new ReadStaleData() now handles encrypted stale data correctly.

The high level API makes use of these changes, which effectively solve the problem you describe further up.

But since you are using lower level functions, you might need to call the new GetReply() function yourself in some cases, and use the new parameters introduced to pick up dragging "pseudo" stale data.

So your statement

I don't see any reliable solution other than doing a blocking read (i.e., GetReply) in every case where a reply is expected.

is absolutely correct. If you use the low level functions, you need to replicate what our API functions also do: They make use of GetReply( ... ) to pick up expected data, to pick up an unknown amount of NOOP replies or to pick up data that only might arrive.

Please indicate if you would like to work more on this.

[FanDjango]

Also, can we integrate #874 into this issue here? Because I feel that any further work on how GetReply() and ReadStaleData() work and might need to be enhanced for IIS being "a bit sluggish" can be done in here.

[robinrodricks]

@leotohill I agree with @FanDjango , we should use GetReply() and it will sort out your issues.

I'm closing this as there is no bug here.