FTPException: 425 Data channel timed out due to not meeting

I got the following error when I try to upload a file to server using FTPS implict:

com.enterprisedt.net.ftp.FTPException: 425 Data channel timed out due to not meeting the minimum bandwidth requirement.
at com.enterprisedt.net.ftp.FTPControlSocket.validateReply(FTPControlSocket.java:1223)
at com.enterprisedt.net.ftp.FTPClient.validateTransfer(FTPClient.java:2554)
at com.enterprisedt.net.ftp.FTPClient.a(FTPClient.java:2514)
at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2481)
at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2442)

What is it about?

For the same connection, I'm able to download and list files using get() and dir().

[support2]

Post a debug log file. Do uploads consistently fail? It could be your firewall blocking them.

Hi,

The debug log is in the following:
------------------------------------------------------------------------------------------------------------------------------
DEBUG [CryptixProperties] 24 Nov 2011 13:14:30.796 : Successfully loaded the CryptixEDT properties file
INFO [puretls] 24 Nov 2011 13:14:30.812 : PureTLS debug level=0
DEBUG [SSLFTPClient] 24 Nov 2011 13:14:30.812 : Setting custom validator to com.enterprisedt.net.ftp.ssl.SSLFTPStandardValidator
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:30.827 : Setting remote host
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:30.827 : Setting implicit mode
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:30.827 : Turning off server validation
DEBUG [SSLFTPClient] 24 Nov 2011 13:14:30.827 : Turned server validation off
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:30.827 : Connecting to server ftps.company.com
DEBUG [SSLFTPClient] 24 Nov 2011 13:14:30.827 : Created implicit FTPS client.
DEBUG [SSLFTPClient] 24 Nov 2011 13:14:30.827 : Connecting to ftps.company.com:990
DEBUG [StreamSocketFactory] 24 Nov 2011 13:14:30.827 : Connecting to ftps.company.com:990 via standard socket
INFO [cryptix] 24 Nov 2011 13:14:30.874 : GLOBAL_TRACE=false
INFO [cryptix] 24 Nov 2011 13:14:30.874 : GLOBAL_DEBUG=false
INFO [cryptix] 24 Nov 2011 13:14:30.874 : GLOBAL_DEBUG_SLOW=false
DEBUG [SSLHandshake] 24 Nov 2011 13:14:30.983 : 3 certificates supplied.0 verified certificates.
DEBUG [SSLHandshake] 24 Nov 2011 13:14:30.983 : isVerified=false, acceptUnverified=true
DEBUG [IJCE_Properties] 24 Nov 2011 13:14:30.983 : Successfully loaded the IJCE properties file
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : 220 Microsoft FTP Service
DEBUG [SSLFTPControlSocket] 24 Nov 2011 13:14:31.030 : DISABLE_CONTROL_SSL_CLOSURE=false
DEBUG [SSLFTPControlSocket] 24 Nov 2011 13:14:31.030 : DISABLE_CONTROL_WAIT_ON_CLOSE=false
DEBUG [SSLFTPControlSocket] 24 Nov 2011 13:14:31.030 : ALLOW_BASIC_CONSTRAINTS_IN_NON_CA=false
DEBUG [SSLFTPControlSocket] 24 Nov 2011 13:14:31.030 : SSL handshake completed on control channel
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : ---> PBSZ 0
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : 200 PBSZ command successful.
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : ---> PROT P
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : 200 PROT command successful.
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:31.030 : auth() succeeded
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:31.030 : Logging in with username=comp_ftp
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : ---> USER comp_ftp
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : 331 Password required for comp_ftp.
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:31.030 : ---> PASS ********
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.140 : 230-Welcome to Global ftp/s
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.140 : 230 User logged in.
DEBUG [com.company.ie.processor.TestFtps] 24 Nov 2011 13:14:32.140 : Logged in
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.140 : ---> TYPE A
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.140 : 200 Type set to A.
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.140 : ---> PWD
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.140 : 257 "/" is current directory.
DEBUG [FTPClient] 24 Nov 2011 13:14:32.140 : Attempt #1
DEBUG [SSLFTPControlSocket] 24 Nov 2011 13:14:32.155 : ListenOnAllInterfaces=true
DEBUG [SSLFTPControlSocket] 24 Nov 2011 13:14:32.155 : Creating SSLFTPActiveDataSocket
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.155 : ---> PORT 49,20,30,236,8,72
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.155 : 200 PORT command successful.
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.155 : ---> STOR AOR_ICCMPL.xml.copy
DEBUG [FTPControlSocket] 24 Nov 2011 13:14:32.249 : 125 Data connection already open; Transfer starting.
DEBUG [SSLFTPActiveDataSocket] 24 Nov 2011 13:14:32.249 : Starting SSL handshake on active data socket
DEBUG [SSLFTPActiveDataSocket] 24 Nov 2011 13:14:32.249 : SSL handshake on active data socket complete
DEBUG [SSLFTPActiveDataSocket] 24 Nov 2011 13:14:32.249 : Sending SSL closure alert on data socket
DEBUG [SSLFTPActiveDataSocket] 24 Nov 2011 13:14:32.249 : Waiting for SSL closure response on data socket
WARN [FTPClient] 24 Nov 2011 13:15:32.763 : Caught exception closing data socket : Read timed out
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.FilterInputStream.read(Unknown Source)
at java.io.PushbackInputStream.read(Unknown Source)
at com.enterprisedt.net.puretls.ai.a(SSLuintX.java:109)
at com.enterprisedt.net.puretls.y.a(SSLRecord.java:153)
at com.enterprisedt.net.puretls.z.a(SSLRecordReader.java:68)
at com.enterprisedt.net.puretls.j.a(SSLConn.java:326)
at com.enterprisedt.net.puretls.SSLSocket.waitForClose(SSLSocket.java:305)
at com.enterprisedt.net.ftp.ssl.a.closeChild(SSLFTPActiveDataSocket.java:251)
at com.enterprisedt.net.ftp.ssl.a.close(SSLFTPActiveDataSocket.java:229)
at com.enterprisedt.net.ftp.FTPClient.a(FTPClient.java:2589)
at com.enterprisedt.net.ftp.FTPClient.closeDataSocket(FTPClient.java:2633)
at com.enterprisedt.net.ftp.FTPClient.b(FTPClient.java:2886)
at com.enterprisedt.net.ftp.FTPClient.a(FTPClient.java:2513)
at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2481)
at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2442)
at com.company.ie.processor.TestFtps.putFile(TestFtps.java:134)
at com.company.ie.processor.TestFtps.main(TestFtps.java:96)


java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(Unknown Source)
at java.net.SocketInputStream.read(Unknown Source)
at java.io.FilterInputStream.read(Unknown Source)
at java.io.PushbackInputStream.read(Unknown Source)
at com.enterprisedt.net.puretls.ai.a(SSLuintX.java:109)
at com.enterprisedt.net.puretls.y.a(SSLRecord.java:153)
at com.enterprisedt.net.puretls.z.a(SSLRecordReader.java:68)
at com.enterprisedt.net.puretls.j.a(SSLConn.java:326)
at com.enterprisedt.net.puretls.SSLSocket.waitForClose(SSLSocket.java:305)
at com.enterprisedt.net.ftp.ssl.a.closeChild(SSLFTPActiveDataSocket.java:251)
at com.enterprisedt.net.ftp.ssl.a.close(SSLFTPActiveDataSocket.java:229)
at com.enterprisedt.net.ftp.FTPClient.a(FTPClient.java:2589)
at com.enterprisedt.net.ftp.FTPClient.closeDataSocket(FTPClient.java:2633)
at com.enterprisedt.net.ftp.FTPClient.b(FTPClient.java:2886)
at com.enterprisedt.net.ftp.FTPClient.a(FTPClient.java:2513)
at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2481)
at com.enterprisedt.net.ftp.FTPClient.put(FTPClient.java:2442)
at com.company.ie.processor.TestFtps.putFile(TestFtps.java:134)
at com.company.ie.processor.TestFtps.main(TestFtps.java:96)

DEBUG [FTPClient] 24 Nov 2011 13:15:32.763 : Transferred 3301 bytes to remote host
DEBUG [FTPControlSocket] 24 Nov 2011 13:15:46.013 : 425 Data channel timed out due to not meeting the minimum bandwidth requirement.
INFO [FTPControlSocket] 24 Nov 2011 13:15:46.013 : Expected reply codes = [225,226,250]
ERROR [com.company.ie.processor.TestFtps] 24 Nov 2011 13:15:46.013 : Data channel timed out due to not meeting the minimum bandwidth requirement.

[support2]

This looks like a firewall problem. Contact your network administrator or temporarily turn off your firewall to see if it works.

Confirmed with network team. There's no firewall in between.

After login successfully, with the same connection, get() and list() are working, but put() never worked.

What are the other possible causes for this?

[support2]

Unusual that it would succeed for a get but not a put. Perhaps you could post a successful get log file so we can compare. Also, does Filezilla succeed with a put?

Using Filezilla is ok, both upload and download.

The following is successful log for get(), to be compared with the previous failure log of put():
------------------------------------------------------------------------------------------------------------------------------
DEBUG [CryptixProperties] 5 Dec 2011 13:24:59.509 : Successfully loaded the CryptixEDT properties file
INFO [puretls] 5 Dec 2011 13:24:59.525 : PureTLS debug level=0
DEBUG [SSLFTPClient] 5 Dec 2011 13:24:59.540 : Setting custom validator to com.enterprisedt.net.ftp.ssl.SSLFTPStandardValidator
DEBUG [TestFtps] 5 Dec 2011 13:24:59.540 : Setting remote host
DEBUG [TestFtps] 5 Dec 2011 13:24:59.540 : Setting implicit mode
DEBUG [TestFtps] 5 Dec 2011 13:24:59.540 : Turning off server validation
DEBUG [SSLFTPClient] 5 Dec 2011 13:24:59.540 : Turned server validation off
DEBUG [TestFtps] 5 Dec 2011 13:24:59.540 : Connecting to server ftps.company.com
DEBUG [SSLFTPClient] 5 Dec 2011 13:24:59.540 : Created implicit FTPS client.
DEBUG [SSLFTPClient] 5 Dec 2011 13:24:59.540 : Connecting to ftps.company.com:990
DEBUG [StreamSocketFactory] 5 Dec 2011 13:24:59.540 : Connecting to ftps.company.com:990 via standard socket
INFO [cryptix] 5 Dec 2011 13:24:59.697 : GLOBAL_TRACE=false
INFO [cryptix] 5 Dec 2011 13:24:59.697 : GLOBAL_DEBUG=false
INFO [cryptix] 5 Dec 2011 13:24:59.697 : GLOBAL_DEBUG_SLOW=false
DEBUG [SSLHandshake] 5 Dec 2011 13:24:59.869 : 2 certificates supplied.0 verified certificates.
DEBUG [SSLHandshake] 5 Dec 2011 13:24:59.869 : isVerified=false, acceptUnverified=true
DEBUG [IJCE_Properties] 5 Dec 2011 13:24:59.869 : Successfully loaded the IJCE properties file
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.915 : 220 Microsoft FTP Service
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:24:59.915 : DISABLE_CONTROL_SSL_CLOSURE=false
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:24:59.915 : DISABLE_CONTROL_WAIT_ON_CLOSE=false
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:24:59.915 : ALLOW_BASIC_CONSTRAINTS_IN_NON_CA=false
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:24:59.915 : SSL handshake completed on control channel
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.915 : ---> PBSZ 0
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.931 : 200 PBSZ command successful.
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.931 : ---> PROT P
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.931 : 200 PROT command successful.
DEBUG [TestFtps] 5 Dec 2011 13:24:59.931 : auth() succeeded
DEBUG [TestFtps] 5 Dec 2011 13:24:59.931 : Logging in with username=comp_ftp
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.931 : ---> USER comp_ftp
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.931 : 331 Password required for comp_ftp.
DEBUG [FTPControlSocket] 5 Dec 2011 13:24:59.931 : ---> PASS ********
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.134 : 230-Welcome to Global ftp/s
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.150 : 230 User logged in.
DEBUG [TestFtps] 5 Dec 2011 13:25:01.150 : Logged in
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.150 : ---> TYPE A
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.165 : 200 Type set to A.
DEBUG [TestFtps] 5 Dec 2011 13:25:01.165 : Getting file
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.165 : ---> PWD
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.165 : 257 "/" is current directory.
DEBUG [FTPClient] 5 Dec 2011 13:25:01.165 : Attempt #1
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:25:01.165 : ListenOnAllInterfaces=true
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:25:01.165 : Creating SSLFTPActiveDataSocket
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.165 : ---> PORT 49,20,30,236,13,237
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.165 : 200 PORT command successful.
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.165 : ---> RETR AOR_FCCMPL.xml
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.228 : 125 Data connection already open; Transfer starting.
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.228 : Starting SSL handshake on active data socket
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.228 : SSL handshake on active data socket complete
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.243 : Sending SSL closure alert on data socket
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.243 : Waiting for SSL closure response on data socket
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.243 : Closing active data socket
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.243 : closeChild() succeeded
DEBUG [SSLFTPActiveDataSocket] 5 Dec 2011 13:25:01.243 : close() succeeded
DEBUG [FTPClient] 5 Dec 2011 13:25:01.243 : Transferred 3073 bytes from remote host
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.243 : 226 Transfer complete.
DEBUG [TestFtps] 5 Dec 2011 13:25:01.243 : Successfully transferred in ASCII mode
DEBUG [TestFtps] 5 Dec 2011 13:25:01.243 : Quitting client
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.243 : ---> QUIT
DEBUG [FTPControlSocket] 5 Dec 2011 13:25:01.259 : 221 Goodbye.
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:25:01.259 : Sending SSL closure alert on control socket
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:25:01.259 : Waiting for SSL closure response on control socket
WARN [SSLFTPControlSocket] 5 Dec 2011 13:25:01.259 : Error while awaiting closure confirmation: Short read
DEBUG [SSLFTPControlSocket] 5 Dec 2011 13:25:01.259 : Closing socket on control socket
DEBUG [TestFtps] 5 Dec 2011 13:25:01.259 : Example complete

[support2]

It's not obvious what the problem is. Can you please enable the maximum logging in FZ and post the upload log?

Do you mean the maximum logging in Filezilla?

[support2]

Yup. In the Debug setting, set to level 4 - Debug.

[support2]

[support2]