Getting Disconnected from server after many MLST commands

[filip]

Hello,
i am experiencing a weird issue:

I am using WinSCP.net and trying to upload many files to ftp server.
Process involves a lot of commands trying to find out if file or directory exists. And of course many commands for uploading a file.
After specific number of these commands I get error (usually MLST command for finding if directory exists) : Lost connection. Disconnected from server.

I've been trying to find a cause for this, but no luck. After many hours of testing I narrowed simulation to sending only one command (in filezilla log it is MLST) in a loop, so it looks like this in filezilla server log:

Code: Select all

(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:07 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:07 - fz (37.46.209.14)> 550 File or directory not found.

In this case after exactly after 728 commands, i get the error. If I dont change the path, the number of commands is always the same.
If I change the path so it is longer the number of successful commands lowers down.
If i check for directory which exists, log looks like this:

Code: Select all

(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> MLST /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> 250-Listing /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)>  type=dir;modify=20210805172843; /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> 250 End
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> MLST /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> 250-Listing /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)>  type=dir;modify=20210805172843; /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> 250 End
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> MLST /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> 250-Listing /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)>  type=dir;modify=20210805172843; /backup2
(004704)11.08.2021 17:08:51 - fz (37.46.209.14)> 250 End

And number of these commands before error is exactly 393 (each time i run that).
So it seems to me, that it depends on amount of message data.

But why it is disconnecting anyway?
I tried two different Filezilla Servers (on different locations) and is the same problem on both. Version is 0.9.60.
When I try different FTP server (some linux one at NAS) it works without problem, thats why I assume it is server problem and not client.

Any idea whats wrong?

Thanks,
Filip

[botg]

Are you using FTP over TLS or is it an insecure plaintext connection? What does it actually say in the server log when the client disconnects?

[filip]

yes, it is FTP over TLS.
it says nothing, there is just result of last successful command, so it looks like this:

Code: Select all

(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:06 - fz (37.46.209.14)> 550 File or directory not found.
(004702)11.08.2021 17:03:07 - fz (37.46.209.14)> MLST /backup3/test long path/one more long path/test123345
(004702)11.08.2021 17:03:07 - fz (37.46.209.14)> 550 File or directory not found.

nothing more..
and it doesnt show disconnected immediately after i get error on client, just several seconds later...

[botg]

What happens if you disable Windows Firewall for a test? It is known to sabotage FTP.

[filip]

Well I just tried and it works with windows firewall disabled
But why does it work with other ftp server?
What can I do? Disabling and enabling firewall every time is not a good solution..

[filip]

Interesting thing is that deciding is whether firewall is turned on while logging on to site.
If firewall is off during login and I enable firewall later, it goes on without error.
So it looks like it starting the sabotage only during login process

[botg]

You could use a proper firewall instead of Windows Firewall. Some hardware firewall running Linux would be ideal.

[filip]

Well yes, but I cant tell all all potential users to turn off Windows Firewall
Any other suggestions?
I will try to ask WinSCP developer as well in meantime.

[botg]

Sure you can tell users to turn of Windows Firewall. Whether users follow this advise is a different story though.

Unfortunately, since Windows firewall is well known to have bugs affecting FTP, nothing can be done other than to use a different firewall.

[filip]

Hello,
one more thing question:
I analyzed client logs for both cases and noticed these diferences:

FileZilla server:

Code: Select all

< 2021-10-05 17:08:24.185 227 Entering Passive Mode (217,16,185,200,226,47)
> 2021-10-05 17:08:24.185 MLSD
. 2021-10-05 17:08:24.185 Connecting to 217.16.185.200:57903 ...
. 2021-10-05 17:08:24.204 Session ID reused
. 2021-10-05 17:08:24.204 Using TLSv1.2, cipher TLSv1.2: ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA, ECDHE-RSA-AES256-GCM-SHA384 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AESGCM(256) Mac=AEAD
. 2021-10-05 17:08:24.204 TLS connection established
< 2021-10-05 17:08:24.205 150 Opening data channel for directory listing of "/"
. 2021-10-05 17:08:24.215 Data connection closed
< 2021-10-05 17:08:24.216 226 Successfully transferred "/"

Other (linux) ftp server:

Code: Select all

< 2021-10-04 19:50:55.696 227 Entering Passive Mode (xxx).
> 2021-10-04 19:50:55.696 MLSD
. 2021-10-04 19:50:55.696 Connecting to xxx ...
< 2021-10-04 19:50:55.723 150 Opening ASCII mode data connection for MLSD
. 2021-10-04 19:50:55.728 Session ID reused
. 2021-10-04 19:50:55.729 Using TLSv1.2, cipher TLSv1.2: ECDHE-RSA-AES128-GCM-SHA256, 2048 bit RSA, ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 Kx=ECDH     Au=RSA  Enc=AESGCM(128) Mac=AEAD
. 2021-10-04 19:50:55.729 TLS connection established
. 2021-10-04 19:50:55.752 Data connection closed
< 2021-10-04 19:50:55.752 226 Transfer complete

Two things:
1. FileZilla does:

Code: Select all

150 Opening data channel for directory listing of "/"

vs other server

Code: Select all

150 Opening ASCII mode data connection for MLSD

2. FileZilla does TLS first and Opening data channel after vs working servers do it otherway around.

Any thoughts?

Thanks,
Filip

[botg]

No, that cannot even be done the other way around.

[filip]

Do you see the logs?

And what about opening mode for listing?