425 and 421 error after upgrading Windows and FZ server

[JanM]

Hello,

I am a first time poster, but I checked a lot of topics and I think I have some understanding of FTP concepts in general. The case we have at a customer is the following:

Server 2008 R2 with FZS 0.9.41 beta. FTP active is in use.

As Server 2008 R2 is not supported after January 14th, we decided to move to another VM with Windows Server 2019 and FZS 0.9.60_2 beta (latest version). So we transfered the config of the old FZS to the new one. Also we changed the incoming port 21 from the old server to the new one.

This is where the problems started happening. The client of the customer wasn't able to connect to the FTP of our customer at peak moments. A lot of error messages like this one: ftp_put(): Opening data channel for file upload to server (error message from the external FTP client). This error corresponded with errors in FZS logs:

(198209) 26-11-2019 09:40:03 - user (ip)> PASV
(198209) 26-11-2019 09:40:03 - user (ip)> 421 Could not create socket.

I am not sure which FTP Client is being used by the client of our customer.

After reading the Network Configuration Guide, I made the assumption that there was to much load to the FZS server on port 21. So I changed the configuration from Active FTP to Passive FTP. I manually opened 1000 ports (51.000 to 52.000), set FZS to identical custom port range and I entered the external IP in the passive mode field.

First it seemed that this was the solution. But after a few days, a lot of problems where occuring, which don't make sense to me.

A portion of a logfile:

(276679) 2-12-2019 15:30:07 - username (ip)> PASV
(276679) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,200,138)
(276679) 2-12-2019 15:30:07 - username (ip)> STOR 16453858-3.xml
(276679) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/16453858-3.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/16453858-3.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> PASV
(276679) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,201,4)
(276679) 2-12-2019 15:30:07 - username (ip)> STOR 16454009-1.xml
(276679) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454009-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/16454009-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> PASV
(276679) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,199,100)
(276680) 2-12-2019 15:30:07 - username (ip)> PASV
(276680) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,19)
(276679) 2-12-2019 15:30:07 - username (ip)> STOR 16454159-1.xml
(276679) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454159-1.xml"
(276680) 2-12-2019 15:30:07 - username (ip)> STOR 20191202-SQ14SETdub-GLO-16455433-2.pdf
(276680) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/20191202-SQ14SETdub-GLO-16455433-2.pdf"
(276679) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/16454159-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> PASV
(276679) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,199,154)
(276679) 2-12-2019 15:30:07 - username (ip)> STOR 16454122-1.xml
(276679) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454122-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/16454122-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> PASV
(276679) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,199,144)
(276679) 2-12-2019 15:30:07 - username (ip)> STOR 16454115-1.xml
(276679) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454115-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/16454115-1.xml"
(276680) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/20191202-SQ14SETdub-GLO-16455433-2.pdf"
(276679) 2-12-2019 15:30:07 - username (ip)> PASV
(276679) 2-12-2019 15:30:07 - username (ip)> 227 Entering Passive Mode (212,178,90,106,199,97)
(276679) 2-12-2019 15:30:07 - username (ip)> STOR 16454178-1.xml
(276679) 2-12-2019 15:30:07 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454178-1.xml"
(276679) 2-12-2019 15:30:07 - username (ip)> 226 Successfully transferred "/production/16454178-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,200,106)
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16453552-1.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16453552-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/16453552-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,214)
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16452810-5.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16452810-5.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/16452810-5.xml"
(276680) 2-12-2019 15:30:08 - username (ip)> PASV
(276680) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,221)
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,201,142)
(276680) 2-12-2019 15:30:08 - username (ip)> STOR 20191202-A6PBdub-GLO-16455464-1.pdf
(276680) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/20191202-A6PBdub-GLO-16455464-1.pdf"
(276679) 2-12-2019 15:30:08 - username (ip)> STOR belgium/16453262-1.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/belgium/16453262-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/belgium/16453262-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,134)
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16315016-3.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16315016-3.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/16315016-3.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,219)
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16454191-1.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454191-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/16454191-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,201,161)
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16454200-1.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16454200-1.xml"
(276680) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/20191202-A6PBdub-GLO-16455464-1.pdf"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/16454200-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,138)
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16452463-1.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16452463-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> 226 Successfully transferred "/production/16452463-1.xml"
(276679) 2-12-2019 15:30:08 - username (ip)> PASV
(276679) 2-12-2019 15:30:08 - username (ip)> 421 Could not create socket.
(276679) 2-12-2019 15:30:08 - username (ip)> PORT 172,128,11,230,171,0
(276679) 2-12-2019 15:30:08 - username (ip)> 200 Port command successful
(276679) 2-12-2019 15:30:08 - username (ip)> STOR 16444610-1.xml
(276679) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/16444610-1.xml"
(276680) 2-12-2019 15:30:08 - username (ip)> PASV
(276680) 2-12-2019 15:30:08 - username (ip)> 227 Entering Passive Mode (212,178,90,106,201,31)
(276680) 2-12-2019 15:30:08 - username (ip)> STOR 20191202-A6SETdub-GLO-16455527-1.pdf
(276680) 2-12-2019 15:30:08 - username (ip)> 150 Opening data channel for file upload to server of "/production/20191202-A6SETdub-GLO-16455527-1.pdf"
(276680) 2-12-2019 15:30:09 - username (ip)> 226 Successfully transferred "/production/20191202-A6SETdub-GLO-16455527-1.pdf"
(276680) 2-12-2019 15:30:09 - username (ip)> PASV
(276680) 2-12-2019 15:30:09 - username (ip)> 227 Entering Passive Mode (212,178,90,106,202,140)
(276680) 2-12-2019 15:30:09 - username (ip)> STOR 20191202-A6PBdub-GLO-16455464-2.pdf
(276680) 2-12-2019 15:30:09 - username (ip)> 150 Opening data channel for file upload to server of "/production/20191202-A6PBdub-GLO-16455464-2.pdf"
(276680) 2-12-2019 15:30:09 - username (ip)> 226 Successfully transferred "/production/20191202-A6PBdub-GLO-16455464-2.pdf"
(276680) 2-12-2019 15:30:09 - username (ip)> PASV
(276680) 2-12-2019 15:30:09 - username (ip)> 421 Could not create socket.
(276680) 2-12-2019 15:30:10 - username (ip)> PORT 172,128,11,230,238,7
(276680) 2-12-2019 15:30:10 - username (ip)> 200 Port command successful
(276680) 2-12-2019 15:30:10 - username (ip)> STOR 20191202-A6SETdub-GLO-16455568-1.pdf
(276680) 2-12-2019 15:30:10 - username (ip)> 150 Opening data channel for file upload to server of "/production/20191202-A6SETdub-GLO-16455568-1.pdf"
(276682) 2-12-2019 15:30:16 - username (ip)> 425 Can't open data connection for transfer of "/production/20191202-SQ14PBdub-GLO-16455088-3.pdf"
(276684) 2-12-2019 15:30:17 - (not logged in) (ip)> Connected on port 21, sending welcome message...
(276684) 2-12-2019 15:30:17 - (not logged in) (ip)> 220-FileZilla Server 0.9.60 beta
(276684) 2-12-2019 15:30:17 - (not logged in) (ip)> 220-written by Tim Kosse (Tim.Kosse@gmx.de)
(276684) 2-12-2019 15:30:17 - (not logged in) (ip)> 220 Please visit https://filezilla-project.org/
(276684) 2-12-2019 15:30:17 - (not logged in) (ip)> disconnected.
(276679) 2-12-2019 15:30:19 - username (ip)> 425 Can't open data connection for transfer of "/production/16444610-1.xml"
(276680) 2-12-2019 15:30:20 - username (ip)> 425 Can't open data connection for transfer of "/production/20191202-A6SETdub-GLO-16455568-1.pdf"

What could be happening here? Is the FZS overutilized / under to much load? There is a lot of data being transferred to this specific customer, at night the problem doesn't seem to be there, only at peak moments.

Did I make a bad assumption perhaps? Or did I make a configuration error? Any help is appreciated!

For now we changed back to the old server, which seems to be a temporary solution, but we want to be able to use FZS on the new machine of course.

If I forgot to mention anything, please tell me and I will post more information.

[boco]

The client is using Passive mode (mostly successful). At a certain point, you seem to run out of Passive ports (too narrow Passive data port range). How many are configured?

1. Data ports are shared between all FTP users.
2. Any data port, after having been used, gets blocked for 4 minutes. It can't be reused while being in that state.
3. Each port is only used for one transaction.

[JanM]

Thanks for your quick reply!

As I stated in the opening post:

After reading the Network Configuration Guide, I made the assumption that there was to much load to the FZS server on port 21. So I changed the configuration from Active FTP to Passive FTP. I manually opened 1000 ports (51.000 to 52.000), set FZS to identical custom port range and I entered the external IP in the passive mode field.

As for these comments:

2. Any data port, after having been used, gets blocked for 4 minutes. It can't be reused while being in that state.
3. Each port is only used for one transaction.

2: Does this mean that (in my case 1000 opened ports), that we can only accept 250 transactions per minute?
3: Is each file one transaction? Or can there be transactions with multiple files?

Would it be meaningful to ask the client how many files he receives every minute / hour / day?

[botg]

Yes, for each file transfer and directory listing, a separate data connection is opened. As rule of thumb, number of ports should be at least as large as the number of transfers performed in 4 minutes.

[JanM]

Thanks a lot! I will try to figure out how many transactions there are per minute or per hour and I will get back here.

As for this information regarding FTP solutions with lots of transactions, isn't it clever to add or change the network configuration guide? In my case 1000 ports is presumably way to little to make it work, but the configuration guide says:

Valid ports can be from 1 to 65535, however ports less than 1024 are reserved for other protocols. It is best to choose ports >= 50000 for passive mode FTP. Due to the nature of TCP (the underlying transport protocol), a port cannot be reused immediately after each connection. Hence the range of ports should not be too small or transfers of multiple small files can fail. A range of 50 ports should be sufficient in most cases.

[boco]

Well, that was written for home users. For busy servers, try the whole ephemeral range (49152-65535). Not easy to exhaust that one.