NOOP should be counted and waited correctly

[Adhara3]

Hi,

I am reusing the same connection to download multiple files. I have NOOP enabled because I sometimes experience timeouts.

Look at this log

01-13 14:44:02.060 INFO  144 FtpLogger Response: 227 Entering Passive Mode (172,30,14,136,173,237) 
01-13 14:44:02.062 INFO  144 FtpLogger Status:   Connecting to 172.30.14.136:44525 
01-13 14:44:02.067 INFO  144 FtpLogger Command:  RETR 20211215_16.35.27-WD.log 
01-13 14:44:02.124 INFO  144 FtpLogger Response: 125 Transfer starting BINARY mode for 20211215_16.35.27-WD.log. 
01-13 14:44:03.580 DEBUG 144 FtpLogger Command:  NOOP 
01-13 14:44:03.585 DEBUG 144 FtpLogger Status:   Disposing FtpSocketStream... 
01-13 14:44:03.592 INFO  144 FtpLogger Response: 226 Transfer complete. 
01-13 14:44:03.596 INFO  144 FtpLogger File Verification: PASS 
01-13 14:44:03.598 DEBUG 144 FtpLogger >         DownloadFile("C:\temp\logs\20210428_13.42.14-PO.log", "20210428_13.42.14-PO.log", Overwrite, OnlyChecksum) 
01-13 14:44:03.607 DEBUG 144 FtpLogger >         GetFileSize("20210428_13.42.14-PO.log") 
01-13 14:44:03.613 DEBUG 144 FtpLogger >         OpenRead("20210428_13.42.14-PO.log", Binary, 0, -1) 
01-13 14:44:03.625 DEBUG 144 FtpLogger >         OpenPassiveDataStream(PASV, "RETR 20210428_13.42.14-PO.log", 0) 
01-13 14:44:03.636 INFO  144 FtpLogger Command:  PASV 
01-13 14:44:03.700 INFO  144 FtpLogger Response: 200 NOOP command successful. 
01-13 14:44:03.899 DEBUG 144 FtpLogger >         DownloadFile("C:\temp\logs\20211011_13.47.08-PO.log", "20211011_13.47.08-PO.log", Overwrite, OnlyChecksum) 
01-13 14:44:03.914 DEBUG 144 FtpLogger >         GetFileSize("20211011_13.47.08-PO.log") 
01-13 14:44:03.931 DEBUG 144 FtpLogger >         OpenRead("20211011_13.47.08-PO.log", Binary, 0, -1) 

As you can see the NOOP response arrived very late and was probably treated as the response to the PASV command.

I see the following issues here.

1. When NOOP is enabled we currently keep track of them by a boolean which means that if we send 3 of them, we lose that info. It's probably better to count the number of expected NOOP
2. When looking for stale data we use the AvailableData on the socket, which does not wait, so like in this scenario no data was actually available even if we knew that a NOOP response should arrive. So I would not use the check stale data function here
3. I do not understand why the PASV listener is accepting the NOOP response. I mean, ok it's a success reply but then the PASV regex parsing should fail, but it doesn't.

Any thought?

Thanks
A

[FanDjango]

@Adhara3

I am reusing the same connection to download multiple files. I have NOOP disabled because I have encountered the problems you have described (Stale Data problems). Since I do not need the NOOPs up to now I have not delved deeper in to the subject you describe, but I certainly agree with your analysis.

[Adhara3]

@FanDjango

i first tried not to use them but I experienced some disconnections, so in a way they helped me improve. I will try to provide a PR with some proposals.

Cheers
A

[FanDjango]

Why even track the NOOP responses? Why not just send them out into the void. If any 200 NOOP command successful should arrive, just ignore them, they have served their purpose.

Tracking them would tell us something is wrong if the responses don't come, but then we would at the same time have a lot of other indicators something is hanging. So...

I could imagine just discarding the 200 NOOP command successful responses, keeping the context focused on the actual commands being responded to. It's sort of like OUT-OF-BAND data, put it somewhere else, in this case: wastebasket.

Your thoughts?

[FanDjango]

So, I have been doing some fairly extensive testing on this and up to now I have not been able to reproduce the same problem as described above, where a NOOP response is wrongly considered a response to a different command.

Even with a major stress test, NoopInterval set to only 100, it works. You just get massive amounts of stale data 200 NOOP command successful after the 226 Transfer complete. See the log number 1 below.

But using NOOPs does have serious caveats because:

Once I use encryption (see log number 2, below), things go very wrong: When the download finishes, the stale data (which is very probably 200 NOOP command successful, many of them) can't be decrypted. And for some reason encryption (actually decryption) is no longer possible on this connection, for any commands after the download.

Program:

FtpSess.Config.ValidateAnyCertificate = true;

FtpSess.Config.DataConnectionType = FtpDataConnectionType.AutoPassive;

FtpSess.Config.NoopInterval = 100;

FtpSess.Config.DownloadDataType = FtpDataType.Binary;

FtpSess.AutoConnect();

FtpStatus status1 = FTP_Sess.DownloadFile("D:\\temp\\test1.bin", "/home/mike/test1", FtpLocalExists.Overwrite, FtpVerify.None, progress);
FtpStatus status2 = FTP_Sess.DownloadFile("D:\\temp\\test2.bin", "/home/mike/test2", FtpLocalExists.Overwrite, FtpVerify.None, progress);

...

Log #1 (no encryption active):

>         DownloadFile("D:\temp\test.bin", "/home/mike/test1", Overwrite, None)
>         GetFileSize("/home/mike/test1")
Command:  SIZE /home/mike/test1
Response: 550 SIZE not allowed in ASCII mode
Command:  TYPE I
Response: 200 Type set to I
Command:  SIZE /home/mike/test1
Response: 213 104857600
>         OpenRead("/home/mike/test1", Binary, 0, 104857600)
>         OpenPassiveDataStream(AutoPassive, "RETR /home/mike/test1", 0)
Command:  EPSV
Response: 229 Entering Extended Passive Mode (|||52540|)
Status:   Connecting to ***:52540
Command:  RETR /home/mike/test1
Response: 150 Opening BINARY mode data connection for /home/mike/test1 (104857600 bytes)
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Status:   Disposing FtpSocketStream...
Response: 226 Transfer complete
Status:   There is stale data on the socket, maybe our connection timed out or you did not call GetReply(). Re-connecting...
Status:   The stale data was: 200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
>         DownloadFile("D:\temp\test.bin", "/home/mike/test2", Overwrite, None)
>         GetFileSize("/home/mike/test2")
Command:  SIZE /home/mike/test2
Response: 213 104857600
>         OpenRead("/home/mike/test2", Binary, 0, 104857600)
>         OpenPassiveDataStream(AutoPassive, "RETR /home/mike/test2", 0)
Command:  EPSV
Response: 229 Entering Extended Passive Mode (|||53652|)
Status:   Connecting to ***:53652
Command:  RETR /home/mike/test2
Response: 150 Opening BINARY mode data connection for /home/mike/test2 (104857600 bytes)
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Status:   Disposing FtpSocketStream...
Response: 226 Transfer complete
Status:   There is stale data on the socket, maybe our connection timed out or you did not call GetReply(). Re-connecting...
Status:   The stale data was: 200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
200 NOOP command successful
Command:  QUIT
Response: 221 Goodbye.
Status:   Disposing FtpSocketStream...

Log #2 (encryption active):

>         DownloadFile("D:\temp\test.bin", "/home/mike/test1", Overwrite, None)
>         GetFileSize("/home/mike/test1")
Command:  SIZE /home/mike/test1
Response: 550 SIZE not allowed in ASCII mode
Command:  TYPE I
Response: 200 Type set to I
Command:  SIZE /home/mike/test1
Response: 213 104857600
>         OpenRead("/home/mike/test1", Binary, 0, 104857600)
>         OpenPassiveDataStream(AutoPassive, "RETR /home/mike/test1", 0)
Command:  EPSV
Response: 229 Entering Extended Passive Mode (|||21372|)
Status:   Connecting to ***:21372
Command:  RETR /home/mike/test1
Response: 150 Opening BINARY mode data connection for /home/mike/test1 (104857600 bytes)
Status:   FTPS Authentication Successful
Status:   Time to activate encryption: 0h 0m 0s.  Total Seconds: 0,0039964.
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Status:   Disposing FtpSocketStream...
Response: 226 Transfer complete
Status:   There is stale data on the socket, maybe our connection timed out or you did not call GetReply(). Re-connecting...
Status:   The stale data was: ↨♥♥ 5$????        ???H?)?;↕g♦?l?fE?↑^,?7?|?∟?.<{<\?       y?[]b☺?↨♥♥ 5$????       ?BBFTW??@???f4?=?Fd'?a???j??☼5r????y[+?x?{5►?↨♥♥ 5$???? ?
6▲↨♥♥ 5$????    ?"↓?R?~⌂?T?jSxc?A???◄Z???W??u;♫a?gj?l?S????↨♥♥ 5$????   ?♫????'-X??M???i??◄-b?♣P=?[?X ??7⌂?♣b#??↨♥♥ 5$????      ???♫◄?.??↓??|?♀?BV+?W☼?'?s?~[◄;?P-??Q?)??⌂\♂??↨♥♥ 5$????        ???:¶??T?☻%?B??Dx?☼?↓↨f?↨☺J►☺??8¶???S<}???↨♥♥ 5$tr?5g?i?\b???)3?2Xh?mCEPW?_?UH?7?∟????w??↨♥♥ 5$????     ?♣#S)w↕?F♂"??????;R,??¶???☻???`??5????↨♥♥ 5$????        ?ib?∟?mtd?3S??t{%+?*^A
?? §::?:►yf"?/☼[m:D'    ?◄↨♥♥ 5$????    ?♠???◄t$♂?)☻j??‼#?Ym????Z3??P2??⌂?? ?.??{↨♥♥ 5$????     ??♫??p??????}1??\F???)?
        ?v???Di?wj??+?{?☼yE↨♥♥ 5$????   ?hh??‼??>?.??p??=M???o??}??n>0?7←♠ ?`y?E??@m1↨♥♥ 5$???? ??%⌂ *Cl8?5???qp◄??s?↓??O????:s;?l?Y2P2☼?♫6r↨♥♥ 5$????  ??u→r???a:?j??G9?♂4☺[V☺▲↔d?t?j?!??xgt??aId?Q
>         DownloadFile("D:\temp\test.bin", "/home/mike/test2", Overwrite, None)
>         GetFileSize("/home/mike/test2")
Command:  SIZE /home/mike/test2
Status:   IOException for file D:\temp\test.bin : Fehler bei Entschlüsselungsvorgang, siehe interne Ausnahme.
Status:   Failed to download file.
Command:  QUIT
Warning:  FtpClient.Disconnect(): Exception caught and discarded while closing control connection: System.IO.IOException: Fehler bei Entschlüsselungsvorgang, siehe interne Ausnahme. ---> System.ComponentModel.Win32Exception: Die angegebenen Daten konnten nicht entschlüsselt werden
   --- Ende der internen Ausnahmestapelüberwachung ---
   bei System.Net.Security._SslStream.EndRead(IAsyncResult asyncResult)
   bei System.Net.Security.SslStream.EndRead(IAsyncResult asyncResult)
   bei FluentFTP.FtpSocketStream.Read(Byte[] buffer, Int32 offset, Int32 count)
   bei FluentFTP.FtpSocketStream.ReadLine(Encoding encoding)
   bei FluentFTP.Client.BaseClient.BaseFtpClient.GetReplyInternal(String command)
   bei FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.ExecuteInternal(String command)
   bei FluentFTP.FtpClient.Execute(String command)
   bei FluentFTP.FtpClient.Disconnect()
Status:   Disposing FtpSocketStream...
Finished```

[FanDjango]

Two things:

1. We are not alone. This essay on NOOP handling makes for very interesting reading.
2. I have been getting improvements in the behaviour of ReadStaleData: By not reading the available bytes directly off the socket, but instead picking the bytes off the stream, the ssl decryption is not thrown out of its context. Some other (new) errors then ensue out of that and I will do some more digging.

[FanDjango]

I have added some more debug logging in some places. See the listing further below.

1. If using encryption, NOOP will work if FTP_Sess.Config.SslBuffering = FtpsBuffering.Off

2. Even then, any encrypted data shown as stale data in ReadStaleData(...) will show up as gobbledigook. Not a real problem.

3. If buffering is turned on, all sorts of errors appear when you try to make NOOP handling better by consuming the NOOPs, either in GetReply(...) or in ReadStaleData(...).

4. The most frustrating thing debugging this, is the huge try { block in DownloadFileInternal(...) which catches an I/O Exception which actually occurs in FtpSocketStream.cs in the Write(...) method.

5. There is a very big probability that NOOPs and their responses work differently on diverse servers. Thus trying to find a unified way to handle NOOPs is a big requirement. Otherwise GetReply(...) and ReadStaleData(...) need to be given a home in the ServerHandler universe.

Currently I think the only way to make NOOPs work when the SSL stream is buffered, is to have two streams on the same socket. One for writing, one for reading.

Note: The following (log of encrypted transfer, no buffering) contains extensive debugging messages not included in the normal code, and I have implemented a new GetReply and ReadStaleData:

>         DownloadFile("D:\temp\test2.bin", "/home/mike/test2", Overwrite, None)
>         GetFileSize("/home/mike/test2")
Status:   Checking for stale data: prior to command execution
Command:  SIZE /home/mike/test2
Status:   Waiting for response to: SIZE /home/mike/test2
Response: 213 1073741824
>         OpenRead("/home/mike/test2", Binary, 0, 1073741824)
>         OpenPassiveDataStream(PASV, "RETR /home/mike/test2", 0)
Status:   Checking for stale data: prior to command execution
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (192,168,1,110,179,139).
Status:   Connecting to ***:45963
Status:   Checking for stale data: prior to command execution
Command:  RETR /home/mike/test2
Status:   Waiting for response to: RETR /home/mike/test2
Response: 150 Opening BINARY mode data connection for /home/mike/test2 (1073741824 bytes)
Status:   FTPS Authentication Successful
Status:   Time to activate encryption: 0h 0m 0s.  Total Seconds: 0,0049979.
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Command:  NOOP
Status:   Disposing FtpSocketStream...
Status:   Waiting for a response
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Status:   exhausted: 200 NOOP: data transfer in progress
Response: 226 Transfer complete
Status:   Checking for stale data: after download
Status:   Checking for stale data: prior to command execution
Command:  QUIT
Status:   Waiting for response to: QUIT
Response: 221 Goodbye.
Status:   Disposing FtpSocketStream...

[FanDjango]

As a first step I have created PR #966. It will force disable SSL Buffering if a user explicitely wants NOOPs to be sent out.

If and when NOOPs are made to work with SSL Buffering with no problems, this can be undone.

[FanDjango]

We are not there yet by a long way... with my new versions of ReadStaleData(...) and GetReply(...) that I have not released to as a PR yet.

Server: proftpd

Current status:

.NET Framework 4.7

Encryption OFF, .NET Framework 4.7: works
NOOP Sequence Behavior: 200,200,200,200,200,200,200,200,200,200,200,200,226
(200 = 200 NOOP command successful)

Encryption ON, .NET Framework 4.7: works because SSL Buffering is turned off, but with current master: sometimes fails.
NOOP Sequence Behavior: 200,200,200,200,200,200,200,200,200,200,200,200,226
(200 = 200 NOOP: data transfer in progress)

Note the difference in the response text plain vs. encrypt

.NET 6

Encryption OFF, .NET 6: works
NOOP Sequence Behavior: 226,200,200,200,200,200,200,200,200,200,200,200,200
(200 = 200 NOOP command successful)

Encryption ON, .NET 6, does not work even though SSL Buffering is turned off, symptoms similar to buffering is on
NOOP Sequence Behavior: 200 and then failure because the server is not sending all NOOP responses right away.
(200 = 200 NOOP command successful)

Currently if you need to reliably use NOOPs, you need to either turn off encryption for best results or try .NET Framework, which will sometimes glitch with the current master. Also, your experience will vary depending on the server type and its configuration.

I will concentrate on the new GetReply(...) and ReadStaleData(...) for the moment, but this will take a while.

[FanDjango]

It is also worthwhile to read the following: Keep Alive Techniques

I have found FTP clients that disallow configuring NOOPs when the connection is encrypted as well as servers, that allow you to block keep-alives (such as NOOP). It seems that many are having probems concerning this and there is a bit of chaos in how it is being addressed.

So your mileage may vary when you try to keep your connection alive on a long running FTP.