random 425 Can't open data connection

Need help with FileZilla Server? Something does not work as expected? In this forum you may find an answer.

Moderator: Project members

Post Reply
Message
Author
mhanor
500 Syntax error
Posts: 15
Joined: 2007-11-21 09:51

random 425 Can't open data connection

#1 Post by mhanor » 2010-05-14 17:00

Hello.

I'm encountering random "425 Can't open data connection" errors when transferring data between Filezilla Server (host Windows XP SP3 32 bit, fully patched) and some ftp client, using only active ftp sessions:
1) Total Commander (running on the same physical machine&OS, running concurrently with the FTP server)
2) Total Commander (running inside a virtual machine)
3) Midnight Commander (running on another physical machine, using stable Debian Lenny, connected by a gigabit LAN with the first machine) - 1st machine 192.168.0.2, 2nd machine 192.168.0.254

Please note that the "Filezilla server.exe" and "totalcmd.exe" are included in the exception list of the Windows Firewall. I don't have any other firewall/antivirus/antimalware installed. The only AV I've used was KAV, but I've uninstalled it and manually removed any remains (using Autoruns). The FTP server isn't running on the standard port 21.

By "random" I mean it doesn't stop the transfer with 425 when it reaches the same file, by following the same steps to reproduce the issue. The data set I've used for testing is the svn repository of VirtualBox (which contains many files, relatively small in size).

logs:
http://www.sendspace.com/file/a6gk2s
Top
User avatar
botg
Site Admin
Posts: 35565
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: random 425 Can't open data connection

#2 Post by botg » 2010-05-14 22:28

Logs are text, place inline.
Top
mhanor
500 Syntax error
Posts: 15
Joined: 2007-11-21 09:51

Re: random 425 Can't open data connection

#3 Post by mhanor » 2010-05-15 06:18

here's the last part of one of them, I can't just paste them whole, e.g. one of them reached 2MB in size, before the server encountered "425"

if you want, I can put them on pastebin com

(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,195,91
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/LocalConfig.kmk
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,145,221
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/postinst.in
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,155,25
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/preinst.in
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,179,243
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/prerm
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,188,166
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/README
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,199,92
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/rules
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,215,153
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/templates
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,206,92
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> RETR /vbox/debian/VBox.sh
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for file transfer.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> CWD /vbox/doc
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 250 CWD successful. "/vbox/doc" is current directory.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,227,31
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> TYPE A
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Type set to A
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> LIST -la
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for directory list.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 226 Transfer OK
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> CWD /vbox/doc/.svn
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 250 CWD successful. "/vbox/doc/.svn" is current directory.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> PORT 192,168,0,254,208,248
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 200 Port command successful
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> LIST -la
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 150 Opening data channel for directory list.
(000001) 14.05.2010 19:49:29 - x (192.168.0.254)> 425 Can't open data connection.
Top
User avatar
botg
Site Admin
Posts: 35565
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: random 425 Can't open data connection

#4 Post by botg » 2010-05-15 07:07

Most likely the system has just run out of sockets. After having been used, all sockets enter the so-called TIME_WAIT state after which they cannot be reused for 4 minutes.

Try using a broader port range for the transfers.
Top
mhanor
500 Syntax error
Posts: 15
Joined: 2007-11-21 09:51

Re: random 425 Can't open data connection

#5 Post by mhanor » 2010-05-15 09:30

The smaller log has <500 lines, here's a "netstat -an" output, before and after:
The 2MB sized log (31k lines) has outstandingly more TIME_WAIT sockets


Active Connections

Proto Local Address Foreign Address State
TCP 0.0.0.0:445 0.0.0.0:0 LISTENING
TCP 0.0.0.0:60029 0.0.0.0:0 LISTENING
TCP 127.0.0.1:1025 0.0.0.0:0 LISTENING
TCP 127.0.0.1:14147 0.0.0.0:0 LISTENING
TCP 192.168.0.2:1806 68.180.217.19:5050 ESTABLISHED
TCP 192.168.0.2:2221 192.168.0.254:22 ESTABLISHED
TCP 192.168.0.2:2564 174.36.78.243:80 CLOSE_WAIT
TCP 192.168.0.2:2978 64.12.61.3:80 ESTABLISHED
UDP 0.0.0.0:445 *:*
UDP 127.0.0.1:123 *:*
UDP 127.0.0.1:1809 *:*
UDP 127.0.0.1:1810 *:*
UDP 127.0.0.1:44301 *:*
UDP 192.168.0.2:123 *:*
UDP 192.168.0.2:1900 *:*
UDP 192.168.0.2:2098 *:*

*****************************************************************

Active Connections

Proto Local Address Foreign Address State
TCP 0.0.0.0:445 0.0.0.0:0 LISTENING
TCP 0.0.0.0:60029 0.0.0.0:0 LISTENING
TCP 127.0.0.1:1025 0.0.0.0:0 LISTENING
TCP 127.0.0.1:14147 0.0.0.0:0 LISTENING
TCP 192.168.0.2:1806 68.180.217.19:5050 ESTABLISHED
TCP 192.168.0.2:2221 192.168.0.254:22 ESTABLISHED
TCP 192.168.0.2:2564 174.36.78.243:80 CLOSE_WAIT
TCP 192.168.0.2:2978 64.12.61.3:80 ESTABLISHED
TCP 192.168.0.2:60028 192.168.0.254:34173 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:34284 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:35555 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:35556 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:35693 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:36379 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:36516 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:36862 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:37031 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:37341 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:38294 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:38303 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:38718 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:39573 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:39705 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:40618 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:41159 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:41173 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:41289 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:41350 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:41516 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:41810 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:42146 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:42270 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:44564 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:44620 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:44967 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:46040 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:46067 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:46269 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:46287 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:46428 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:47518 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:48294 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:48669 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:48681 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:49165 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:49228 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:49603 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:49798 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:49851 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:50011 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:50319 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:50485 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:51036 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:51075 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:51529 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:52245 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:52815 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:52828 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:53219 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:53292 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:53496 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:53600 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:53713 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:53935 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:54138 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:54615 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:54763 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:55188 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:55193 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:55463 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:55738 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:56306 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:56365 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:56380 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:56451 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:56593 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:56965 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:57510 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:57580 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:58143 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:58488 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:59225 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:60091 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:60246 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:60802 TIME_WAIT
TCP 192.168.0.2:60028 192.168.0.254:60962 TIME_WAIT
TCP 192.168.0.2:60029 192.168.0.254:57021 ESTABLISHED
UDP 0.0.0.0:445 *:*
UDP 127.0.0.1:123 *:*
UDP 127.0.0.1:1809 *:*
UDP 127.0.0.1:1810 *:*
UDP 127.0.0.1:44301 *:*
UDP 192.168.0.2:123 *:*
UDP 192.168.0.2:1900 *:*
UDP 192.168.0.2:2098 *:*


The server behaves like this when the client uses active ftp connections, I have no problems using passive connections. The wiki says "Active mode: Just make sure FileZilla Server is allowed to establish outgoing connections to arbitrary ports"... There's no firewall except Windows Firewall (with the right rule set), no other filtering. The 425 is instant on the server, there's no delay for it, while the client waits for the transfer to be done.
Top
User avatar
boco
Contributor
Posts: 26938
Joined: 2006-05-01 03:28
Location: Germany

Re: random 425 Can't open data connection

#6 Post by boco » 2010-05-15 19:30

Do you see the tremendous number of TIME_WAIT sockets? They are unavailable for ~4 minutes before they are available again. If the range is too narrow, the system can run out of sockets. No further connections will then be possible until some sockets become available again.
No support requests over PM! You will NOT get any reply!!!
FTP connection problems? Please read Network Configuration.
FileZilla connection test: https://filezilla-project.org/conntest.php
FileZilla Pro support: https://customerforum.fileZilla-project.org
Top
User avatar
botg
Site Admin
Posts: 35565
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: random 425 Can't open data connection

#7 Post by botg » 2010-05-15 19:51

What happens if you use a different client, such as for example FileZilla?
Top
mhanor
500 Syntax error
Posts: 15
Joined: 2007-11-21 09:51

Re: random 425 Can't open data connection

#8 Post by mhanor » 2010-05-16 07:48

boco: The inline example above is real, the server encountered 425 very early, there were very few TIME_WAIT sockets in comparison with other times, when the client&server managed to get along together and transfer a few thousands of files, while the number of TIME_WAIT sockets reached a much higher value. That's why I'm questioning the idea that the sockets are depleted, sometimes it fails within seconds.

botg: Yes, it fails too, sooner or later. It also behaves differently than totalcmd and mc, the two clients I use mostly. It just skips the failed files, while mc&tcmd wait at a failed transfer to occur, unaware that the server has just given up.

The stress is on the client side when using the active ftp connection, right (http://slacksite.com/other/ftp.html#active)? After the server fails, I manually connected to the ftp client's data port (using telnet) and it receives the keystrokes as data and it saves it when it asks me if I want to save the incomplete file (content matches with what I wrote). I tested this when the client was running on the same machine with the server and on the 2nd machine. If it was socket depletion, the client should fail opening a new data socket, yes?
Top
User avatar
botg
Site Admin
Posts: 35565
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: random 425 Can't open data connection

#9 Post by botg » 2010-05-16 08:52

The stress is on the client side when using the active ftp connection, right
Yes.
Top
mhanor
500 Syntax error
Posts: 15
Joined: 2007-11-21 09:51

Re: random 425 Can't open data connection

#10 Post by mhanor » 2010-05-18 15:32

I've managed to compile the service component of the server. I've reached to the WindowProc function. When the server is about to fail with 425, the function WindowProc (AsyncSocketEx) receives lParam = 658505744 (every time it's the same value), which means nErrorCode = 10048, WSAEADDRINUSE. It reaches the condition (pSocket->m_lEvent & FD_CONNECT), which is true, so it executes the function pSocket->OnConnect(nErrorCode) and that's the end of it.
Top
User avatar
botg
Site Admin
Posts: 35565
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: random 425 Can't open data connection

#11 Post by botg » 2010-05-18 21:48

Yep, that's due to the TIME_WAIT state.
Top
mhanor
500 Syntax error
Posts: 15
Joined: 2007-11-21 09:51

Re: random 425 Can't open data connection

#12 Post by mhanor » 2010-05-20 17:59

Yes, but that's on the server side. For active FTP connections, the server must behave like a client, so it must connect to remote ports, opened by the FTP client. It uses "one local port to many remote ports" connections.
I've made a network capture to try and understand why Filezilla server fails so soon with MC (4MB in size). I can upload it, if someone wants it.

The Total Commander FTP client opens ports sequentially. Even on my test, where the client and the server were running on the same Windows host, the fail was on the server's part, not on the client's (proof that I could connect&type with telnet on the client's data port). It takes a very long time for the server to encounter a TIME_WAIT socket from the "one local port to many remote", depending on how fast the connections are being made, but it does (remember the 2MB server log). By toying with TCP/IP's Windows driver parameters, MaxUserPort and TcpTimedWaitDelay, I've made the available client port list longer, the problem disappeared on the same test.

But Midnight Commander chooses random ports. This client has no problem opening a port which it opened before in the very near past (again, the telnet test works). But that's why my Filezilla server fails within 10 seconds, after it has managed to transfer less than 700 small files, even with the best values for MaxUserPort and TcpTimedWaitDelay set on the Windows host, running the Filezilla server.

When testing MC and vsftpd on the 2nd machine (Debian), transferring the same data, vsftpd doesn't mind about MC's behaviour. So, is it normal for Filezilla server to fail? Or maybe my reasoning is wrong?
Last edited by mhanor on 2010-05-20 19:39, edited 4 times in total.
Top
User avatar
botg
Site Admin
Posts: 35565
Joined: 2004-02-23 20:49
First name: Tim
Last name: Kosse

Re: random 425 Can't open data connection

#13 Post by botg » 2010-05-20 18:39

Perhaps vsftpd uses SO_REUSEADDR, a somewhat problematic socket option.
Top
Post Reply

Return to “FileZilla Server Support”