Sporadic reproducible GetListing, Download and other failures: IOException on control connection

[FanDjango]

This has been reported quite a few times.

What does the failure look like?

Typically, it manifests as an IOException. Depending on the API call being performed, this exception can cause

• a GetListing result to be empty while the exeption is ignored
• other commands to fail with an IOException.

If you look closely at the IOException, you might see:
an attempt was made to access a socket in a way forbidden by its access permissions

When does it happen?

It happens on an control connection (only if encrypted) when you have issued many API calls (that execute commands and get the response).

Reported by (ignore the incorrect title):

@omanThYp #104 (comment)
@oleksabor #104 (comment)

#752 could such a case, but sadly there is no log

See also #723 : one of the "strange" ways this problem can show up.

A newer issue of this kind: #1130

[FanDjango]

This is the original post of @oleksabor, many thanks to him for this effort:

Original post from #104

I did a test (like stress test) that connects to the FTPs server and download files.
Here is the source code of the test project

The test is executed in a loop, about 170 iterations.

One iteration is to

• check folder exists (FTPS fails if GetListing is executed for missing folder)
• get folder listing
• download each file

170 iterations, 3 folders, 2 files in each folder.

I've tried the FileZilla ftp server (both 1.1.0-beta1 and 1.0.1) and IIS Ftps server - errors are the same with slightly variations.

IIS ftps

I've used the https://medium.com/@sithum/create-ftps-server-on-windows-server-iis-in-5-minutes-sithum-devops-7a09823d91a4 guide to set up ftps with IIS

The problem is that I'm getting error each 25 time - GetListing returns nothing for 183085 (however there are files)

I can run test project three times in a row and three times it produces the same errors

• 25th iteration could not get 183085 folder content.
• Then error An existing connection was forcibly closed by the remote host is thrown for GetListing and 680605 folder on 49th iteration.
• then DirectoryExists check throws the same connection closed for notexists directory.
• and then file download fails /183085/Mzc3w_4nTee1.jpg

The same (approximately) errors are thrown each time I'm running this test FluentFtpMT

• ftp trace output for IIS fluentFtp.txt
• test client app log for IIS fluentFtpApp.txt
• test client app log with 500ms pauses between FTP calls for IIS fluentFtpAppPaused500.txt

FileZilla

I've just installed FileZilla server and added a test user

with the FileZilla server

• each 57th iteration fails to GetListing on dir failed to get dir 680605
• each 86th iteration fails to download file failed to get file /183085/WdZ6redPXm7j.jpg
• 114th iteration fails to GetListing of 680605 directory
• 143th iteration fails to download file failed to get file /183085/WdZ6redPXm7j.jpg

There are less errors on FileZilla with 500ms pauses between each ftp call but

• iterating 80

  2021-10-28 17:09:16,903 [1] WARN - no folder listing result on path:680605

• iterating 109

2021-10-28 17:11:54,444 [1] WARN - no folder listing result on path:183085

• iterating 137

  2021-10-28 17:14:25,551 [1] WARN - no folder listing result on path:220924

here are logs

• client application log filezillaClient.txt
• fluentFtp trace filezillaFluent.txt
• server log FilezillaServer.txt

I did those tests on my Windows 10 OS version 20H2 OS build 19042, 1288)

test project uses the .Net Framework 4.8 and FluentFtp 35.0.5

Connection is FTPS w/ Explicit mode

I've tried to add some Thread.Sleep between ftp calls (it may done using the Websettings.Wait = true) but errors are still here

[FanDjango]

I then wrote, in #104

@oleksabor Using your exact github code and connecting to a very high performace proftpd server of my own, I can reproduce the issue.

I am getting the same errors ( your sln is using FluentFTP V35).

After upgrading to FluentFTP V42 and making the few neccessary ->V40 migration changes, the problem STILL can be reproduced.

So now we can start to search for the problem.

[FanDjango]

Some first results of testing, using @oleksabor initial approach as a basis. I forked his GitHub test sln.

The goal was to find out a little bit more about the real problem and to remove conjecture.

1. I have modified the test program to only do the following (up to 500 times):

CWD /home/testuser
PWD

These commands do not use a data connection. No data connection (SSL) needs to be created and disposed. They only exercise the control connection.

These commands are iterated up to 500 times with no waits in between.

They always fail in the same way on the 474th iteration, on all of my available client systems.

2. The test suite will run all 500 iterations without failure if encryption is turned off.

3. The test suite encounters the problem or multiple problems if encryption is turned on.

4. Disabling stream buffering does not help.

5. Disabling or enabling socket polling does not have any effect on the problem occurrence(s).

6. .NET 6.0 or .NET Framework 4.8 targets both exhibit the same problem(s).

7. Any problems occur after the same amount of iterations - deterministic and not random. Independent of host system.

8. The errors occur in GetReply...ReadLine --> FtpSocketStream.ReadLine --> Read. I put a try/catch into FtpSocketStream.Read: The errors themselves are always, (note: also in the original Getlisting/Download szenario) "an attempt was made to access a socket in a way forbidden by its access permissions", an IOException, after which the socket is no longer connected, which is reacted to in different ways when they percolate upwards, depending on the function that you called. In a GetListing(), in a Download..., depending on the code that catches this exception, the further behaviour difffers. The control connection is closed though, which can cause a reconnect attempt, thus causing confusion if you don`t see that happening, or you can get "empty directories". Standardizing this behaviour could be a todo-item.

9. It looks like continuous reading from the SSL control connection stream in a huge amount of single byte READ operations is somehow exhausting some resource inside the implementation of SslStream.

[FanDjango]

I have further reduced the tests to

Command:  NOOP
Status:   Waiting for response to: NOOP
Response: 200 NOOP command successful

I can do 1057 of these commands and then I get the above described failure.

Choosing a "longer" command (i.e. more bytes) does not change the number of commands before the exception occurs.

So I my environment I can cycle about 1057 commands/responses and then I get an IOException.

[FanDjango]

Conversely, if I do

Command:  PASV
Response: 227 Entering Passive Mode (192,168,1,109,132,201).
Command:  MLSD /home/mike
Response: 150 Opening BINARY mode data connection for MLSD
....listing deleted....
Response: 226 Transfer complete

Guess how many? 289.
Looks like we must count the response lines, not the commands.

[robinrodricks]

Made a small change to only honor SslSessionLength if the FTP connection is using FTPS (IsEncrypted).

If that was not your intention, I can change the behavior, let me know.

[FanDjango]

This is now released as V42.1.0