Another command is currently pending, please try again later

Question

how can this happen ?
the log is here:

DEBUG [FTPClient] 4 May 2008 22:06:48.916 : Class: com.sun.mail.ftp.protocol.FTPClient
Version: 2.0.1
Build timestamp: 9-Jan-2008 14:00:06 EST
Java version: 1.6.0_06
CLASSPATH: /root/workspace/hadoop:/nutch/search/lib/commons-cli-2.0-SNAPSHOT.jar:/nutch/search/lib/commons-codec-1.3.jar:/nutch/search/lib/commons-httpclient-3.0.1.jar:/nutch/search/lib/commons-lang-2.1.jar:/nutch/search/lib/commons-logging-1.0.4.jar:/nutch/search/lib/commons-logging-api-1.0.4.jar:/nutch/search/lib/dsn.jar:/nutch/search/lib/FontBox-0.1.0-dev.jar:/nutch/search/lib/icu4j-3_6.jar:/nutch/search/lib/imap.jar:/nutch/search/lib/jets3t-0.5.0.jar:/nutch/search/lib/jetty-5.1.4.jar:/nutch/search/lib/junit-3.8.1.jar:/nutch/search/lib/log4j-1.2.13.jar:/nutch/search/lib/lucene-core-2.2.0.jar:/nutch/search/lib/lucene-misc-2.2.0.jar:/nutch/search/lib/mail.jar:/nutch/search/lib/PDFBox-0.7.3.jar:/nutch/search/lib/poi-3.0.2-FINAL-20080204.jar:/nutch/search/lib/poi-contrib-3.0.2-FINAL-20080204.jar:/nutch/search/lib/poi-scratchpad-3.0.2-FINAL-20080204.jar:/nutch/search/lib/pop3.jar:/nutch/search/lib/servlet-api.jar:/nutch/search/lib/smtp.jar:/nutch/search/lib/taglibs-i18n.jar:/nutch/search/lib/tika-0.1-dev.jar:/nutch/search/lib/xerces-2_6_2.jar:/nutch/search/lib/xerces-2_6_2-apis.jar:/nutch/search/lib/pmd-ext/jakarta-oro-2.0.8.jar:/nutch/search/lib/pmd-ext/jaxen-1.1-beta-7.jar:/nutch/search/lib/pmd-ext/pmd-3.6.jar:/nutch/search/lib/jetty-ext/ant.jar:/nutch/search/lib/jetty-ext/commons-el.jar:/nutch/search/lib/jetty-ext/jasper-compiler.jar:/nutch/search/lib/jetty-ext/jasper-runtime.jar:/nutch/search/lib/jetty-ext/jsp-api.jar:/nutch/search/test/MailRetrieval.jar:/nutch/search/lib/xmlenc-0.52.jar:/nutch/search/lib/kfs-0.1.jar
OS name: Linux
OS arch: i386
OS version: 2.6.18-53.1.14.el5

DEBUG [FTPClient] 4 May 2008 22:06:48.919 : Connecting to /192.168.140.95:21
DEBUG [SocketUtils] 4 May 2008 22:06:48.923 : Invoking connect with timeout=60000
DEBUG [SocketUtils] 4 May 2008 22:06:48.927 : Connected successfully
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.935 : 220 Serv-U FTP Server v7.0 ready...
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.936 : ---> USER anonymous
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.937 : 331 User name okay, please send complete E-mail address as password.
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.937 : ---> PASS ********
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.939 : 230 User logged in, proceed.
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.945 : ---> CWD /inboxes
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.947 : 250 Directory changed to /inboxes
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.948 : ---> SYST
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.949 : 215 UNIX Type: L8
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.951 : ---> PWD
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.952 : 257 "/inboxes" is current directory.
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.952 : ListenOnAllInterfaces=true
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.953 : ---> PORT 192,168,140,93,208,180
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.954 : 200 PORT Command successful.
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.954 : ---> LIST
DEBUG [FTPControlSocket] 4 May 2008 22:06:48.956 : 150 Opening ASCII mode data connection for /bin/ls.
DEBUG [FTPActiveDataSocket] 4 May 2008 22:06:48.957 : Calling accept()
DEBUG [FTPActiveDataSocket] 4 May 2008 22:06:48.959 : accept() succeeded
DEBUG [FTPControlSocket] 4 May 2008 21:54:08.731 : ---> PWD
DEBUG [FTPControlSocket] 4 May 2008 21:54:08.732 : 426 Data connection closed, listing for /inboxes/haoa aborted.
INFO [FTPControlSocket] 4 May 2008 21:54:08.732 : Expected reply code = [257]
DEBUG [FTPControlSocket] 4 May 2008 21:54:08.732 : ---> QUIT
DEBUG [FTPControlSocket] 4 May 2008 21:54:08.752 : 451 Another command is currently pending, please try again later.
INFO [FTPControlSocket] 4 May 2008 21:54:08.752 : Expected reply codes = [221,226]
java.net.SocketTimeoutException: Read timed out
   at java.net.SocketInputStream.socketRead0(Native Method)
   at java.net.SocketInputStream.read(SocketInputStream.java:129)
   at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264)
   at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306)
   at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158)
   at java.io.InputStreamReader.read(InputStreamReader.java:167)
   at java.io.BufferedReader.fill(BufferedReader.java:136)
   at java.io.BufferedReader.readLine(BufferedReader.java:299)
   at java.io.LineNumberReader.readLine(LineNumberReader.java:182)
   at com.enterprisedt.net.ftp.FTPClient.readLine(FTPClient.java:3210)
   at com.enterprisedt.net.ftp.FTPClient.dir(FTPClient.java:3119)
   at com.enterprisedt.net.ftp.FTPClient.dirDetails(FTPClient.java:3042)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:544)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:528)
   at com.sun.mail.ftp.FTPFolder.forceFetch(FTPFolder.java:507)
   at com.sun.mail.ftp.FTPFolder.open(FTPFolder.java:544)
   at javax.mail.Folder.open(Folder.java:650)

com.enterprisedt.net.ftp.FTPException: Data connection closed, listing for /inboxes/haoa aborted.
   at com.enterprisedt.net.ftp.FTPControlSocket.validateReply(FTPControlSocket.java:1001)
   at com.enterprisedt.net.ftp.FTPClient.pwd(FTPClient.java:3384)
   at com.enterprisedt.net.ftp.FTPClient.dirDetails(FTPClient.java:3031)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:544)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:528)
   
com.enterprisedt.net.ftp.FTPException: Another command is currently pending, please try again later.
   at com.enterprisedt.net.ftp.FTPControlSocket.validateReply(FTPControlSocket.java:978)
   at com.enterprisedt.net.ftp.FTPClient.quit(FTPClient.java:3531)
   at com.sun.mail.ftp.FTPStore.close(FTPStore.java:156)
   at edu.insun.io.NetworkMessage.close(NetworkMessage.java:73)

it works in the first directory , but failed on the second derectory named: /inboxes/haoa

Can any one tell me whether this is just a time-out problem or there is other cause ? [/quote]

Answer 1

every directory in my ftp server has thousands files which size is about 10K.

Answer 2

This looks like a firewall-related problem. Try using passive connection-mode. See here.

Also, have you got any idea why the timestamps in the log are not in sequence? In particular the timestamp of the second PWD command (21:54:08) is ten minutes before the timestamp of the "accept() succeeded" immediately above it.

- Hans

Answer 3

This looks like a firewall-related problem. Try using passive connection-mode. See here.

Also, have you got any idea why the timestamps in the log are not in sequence? In particular the timestamp of the second PWD command (21:54:08) is ten minutes before the timestamp of the "accept() succeeded" immediately above it.

- Hans

Sorry, it's my mistake. I run my application twice and merge the two part of log in one, the first time's log is the second half, when I see other post, They also have the system enviroment properties, so I run it again and add it as the first half.

I am sure it is not firewall-related problem. And it is passive connection-mode. I do this just follow the Filezilla FTP client. The ftp server is configured by myself, the system has no firewall at all. I found a strange problem : when ls the current directory, the log 's output is right, but the replycode is error, and so throw a FTPException ? I will log it to a file and post it to help you analysis.

Answer 4

ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group        2170 Apr 22 23:27 4D61696C313230383837373938393033312D313838363334.Repository.FileStreamStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         705 Apr 22 23:36 4D61696C313230383837383530333230332D313838363739.Repository.FileObjectStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group        3612 Apr 22 23:36 4D61696C313230383837383530333230332D313838363739.Repository.FileStreamStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         710 Apr 22 23:37 4D61696C313230383837383631383135362D313838363838.Repository.FileObjectStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         921 Apr 22 23:37 4D61696C313230383837383631383135362D313838363838.Repository.FileStreamStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         709 Apr 22 23:37 4D61696C313230383837383632303936382D313838363930.Repository.FileObjectStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group        1883 Apr 22 23:37 4D61696C313230383837383632303936382D313838363930.Repository.FileStreamStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         711 Apr 22 23:53 4D61696C313230383837393331373736352D313838373236.Repository.FileObjectStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group        4040 Apr 22 23:53 4D61696C313230383837393331373736352D313838373236.Repository.FileStreamStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         709 Apr 22 23:53 4D61696C313230383837393433393730332D313838373339.Repository.FileObjectStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         982 Apr 22 23:53 4D61696C313230383837393433393730332D313838373339.Repository.FileStreamStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group         709 Apr 23 00:03 4D61696C313230383837393930373635362D313838373736.Repository.FileObjectStore
ALL [FTPClient] 5 May 2008 11:02:44.671 : -rw-rw-rw-   1 user     group        1510 Apr 23 00:03 4D61696C313230383837393930373635362D313838373736.Repository.FileStreamStore
DEBUG [FTPActiveDataSocket] 5 May 2008 11:02:44.671 : closeChild() succeeded
DEBUG [FTPActiveDataSocket] 5 May 2008 11:02:44.671 : close() succeeded
DEBUG [FTPControlSocket] 5 May 2008 11:02:44.671 : 150 Opening ASCII mode data connection for /bin/ls.
INFO [FTPControlSocket] 5 May 2008 11:02:44.671 : Expected reply codes = [226,250]
com.enterprisedt.net.ftp.FTPException: Opening ASCII mode data connection for /bin/ls.
   at com.enterprisedt.net.ftp.FTPControlSocket.validateReply(FTPControlSocket.java:978)
   at com.enterprisedt.net.ftp.FTPClient.dir(FTPClient.java:3139)
   at com.enterprisedt.net.ftp.FTPClient.dirDetails(FTPClient.java:3042)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:544)
   at com.enterprisedt.net.ftp.FileTransferClient.directoryList(FileTransferClient.java:528)
   at com.sun.mail.ftp.FTPFolder.forceFetch(FTPFolder.java:507)
   at com.sun.mail.ftp.FTPFolder.open(FTPFolder.java:544)DEBUG [FTPControlSocket] 5 May 2008 11:02:44.671 : ---> QUIT
DEBUG [FTPControlSocket] 5 May 2008 11:02:44.671 : 226 Transfer complete. 1,656,561 bytes transferred. 415.76 KB/sec.

   at javax.mail.Folder.open(Folder.java:650)
   at com.sun.mail.ftp.FTPMessageTest.main(FTPMessageTest.java:57)

ls operation is successful, but the reply code is out of expected ?

Answer 5

DEBUG [FTPClient] 5 May 2008 16:39:00.218 : Class: com.enterprisedt.net.ftp.FTPClient
Version: 2.0.1
Build timestamp: 9-Jan-2008 14:00:06 EST
Java version: 1.6.0
CLASSPATH: D:\ToolsLib\lucene\hadoop-0.15.0\src\src;D:\ToolsLib\lucene\hadoop-0.15.0\lib\jetty-ext\commons-el.jar;......
OS name: Windows XP
OS arch: x86
OS version: 5.1

DEBUG [FTPClient] 5 May 2008 16:39:00.218 : Connecting to /192.168.140.95:21
DEBUG [SocketUtils] 5 May 2008 16:39:00.218 : Invoking connect with timeout=120000
DEBUG [SocketUtils] 5 May 2008 16:39:00.218 : Connected successfully
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.249 : 220 Serv-U FTP Server v7.0 ready...
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.249 : ---> USER anonymous
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.265 : 331 User name okay, please send complete E-mail address as password.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.265 : ---> PASS ********
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.265 : 230 User logged in, proceed.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.280 : ---> CWD /inboxes
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.280 : 250 Directory changed to /inboxes
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.280 : ---> SYST
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.280 : 215 UNIX Type: L8
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.296 : ---> PWD
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.296 : 257 "/inboxes" is current directory.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.296 : ListenOnAllInterfaces=true
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.296 : ---> PORT 192,168,140,5,13,4
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.296 : 200 PORT Command successful.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.296 : ---> LIST
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.311 : 150 Opening ASCII mode data connection for /bin/ls.
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:00.311 : Calling accept()
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:00.311 : accept() succeeded
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:00.311 : closeChild() succeeded
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:00.311 : close() succeeded
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.436 : 226 Transfer complete. 2,008 bytes transferred. 122.56 KB/sec.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.452 : ---> CWD /inboxes/cuirun
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.452 : 250 Directory changed to /inboxes/cuirun
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.452 : ---> PWD
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.452 : 257 "/inboxes/cuirun" is current directory.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.468 : ListenOnAllInterfaces=true
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.468 : ---> PORT 192,168,140,5,13,6
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.468 : 200 PORT Command successful.
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.468 : ---> LIST
DEBUG [FTPControlSocket] 5 May 2008 16:39:00.468 : 150 Opening ASCII mode data connection for /bin/ls.
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:00.468 : Calling accept()
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:00.483 : accept() succeeded
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:03.968 : closeChild() succeeded
DEBUG [FTPActiveDataSocket] 5 May 2008 16:39:03.968 : close() succeeded
DEBUG [FTPControlSocket] 5 May 2008 16:39:03.983 : 226 Transfer complete. 1,665,749 bytes transferred. 462.66 KB/sec.
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.530 : ---> TYPE I
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.530 : 200 Type set to I.
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.530 : ---> PASV
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.530 : 227 Entering Passive Mode (192,168,140,95,5,201)
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.530 : Substituting server supplied IP (192.168.140.95) with remote host IP (192.168.140.95)
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.530 : ---> RETR 4D61696C313230383236383433363739362D343535.Repository.FileStreamStore
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.546 : 150 Opening BINARY mode data connection for 4D61696C313230383236383433363739362D343535.Repository.FileStreamStore (4150 Bytes).
DEBUG [FTPClient] 5 May 2008 16:39:04.546 : Transferred 4150 bytes from remote host
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.655 : 226 Transfer complete. 4,150 bytes transferred. 4.05 KB/sec.
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : ---> TYPE I
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : 200 Type set to I.
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : ---> PASV
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : 227 Entering Passive Mode (192,168,140,95,5,202)
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : Substituting server supplied IP (192.168.140.95) with remote host IP (192.168.140.95)
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : ---> RETR 4D61696C313230383236383433383339302D343632.Repository.FileStreamStore
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.671 : 150 Opening BINARY mode data connection for 4D61696C313230383236383433383339302D343632.Repository.FileStreamStore (2616 Bytes).
DEBUG [FTPClient] 5 May 2008 16:39:04.686 : Transferred 2616 bytes from remote host
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.858 : 226 Transfer complete. 2,616 bytes transferred. 2.55 KB/sec.
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.858 : ---> TYPE I
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.874 : 200 Type set to I.
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.874 : ---> PASV
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.874 : 227 Entering Passive Mode (192,168,140,95,5,203)
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.874 : Substituting server supplied IP (192.168.140.95) with remote host IP (192.168.140.95)
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.874 : ---> RETR 4D61696C313230383236383434313039332D343737.Repository.FileStreamStore
DEBUG [FTPControlSocket] 5 May 2008 16:39:04.890 : 150 Opening BINARY mode data connection for 4D61696C313230383236383434313039332D343737.Repository.FileStreamStore (2357 Bytes).
DEBUG [FTPClient] 5 May 2008 16:39:04.890 : Transferred 2357 bytes from remote host
DEBUG [FTPControlSocket] 5 May 2008 16:39:05.61 : 226 Transfer complete. 2,357 bytes transferred. 2.30 KB/sec.
DEBUG [FTPControlSocket] 5 May 2008 16:39:05.61 : ---> TYPE I
DEBUG [FTPControlSocket] 5 May 2008 16:39:05.61 : 200 Type set to I.
DEBUG [FTPControlSocket] 5 May 2008 16:39:05.61 : ---> PASV
DEBUG [FTPControlSocket] 5 May 2008 16:39:05.77 : 227 Entering Passive Mode (192,168,140,95,5,204)
DEBUG [FTPControlSocket] 5 May 2008 16:39:05.77 : Substituting server supplied IP (192.168.140.95) with remote host IP (192.168.140.95)
...............omited (same as the above)

DEBUG [FTPControlSocket] 5 May 2008 16:39:48.999 : 200 Type set to I.
DEBUG [FTPControlSocket] 5 May 2008 16:39:48.999 : ---> CWD /inboxes/haoa
DEBUG [FTPControlSocket] 5 May 2008 16:39:48.999 : 227 Entering Passive Mode (192,168,140,95,6,161)
DEBUG [FTPControlSocket] 5 May 2008 16:39:48.999 : ---> PWD
DEBUG [FTPControlSocket] 5 May 2008 16:39:48.999 : 250 Directory changed to /inboxes/haoa
DEBUG [FTPControlSocket] 5 M

Answer 6

There is a CWD & PWD being called during the transfer:

---> CWD /inboxes/haoa 
227 Entering Passive Mode (192,168,140,95,6,161)
---> PWD 
250 Directory changed to /inboxes/haoa
---> PORT 192,168,140,5,13,203 
257 "/inboxes/haoa" is current directory. 

That isn't good - all your commands are getting out of sequence.