You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@commons.apache.org by "Sebb (JIRA)" <ji...@apache.org> on 2011/03/22 04:08:06 UTC
[jira] [Updated] (NET-249) FtpClient hangs 20 minutes in
FTPClient.completePendingCommand from retrieveFile or listFiles
[ https://issues.apache.org/jira/browse/NET-249?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Sebb updated NET-249:
---------------------
Description:
I have a Ftp Client with several connections in multi-thread that connects to a remote Ftp Server to list files and download new ones.
After 3 minutes of runtime, I get a 20-minute timeout for all running Ftp connections.
Here are the logs for 1 thread :
{noformat}
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,224,172)
20090114 142216 (Command Sent Message): LIST /Dir1/Dir2/Dir3
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /bin/ls.
20090114 142216 (Reply Received Message): 226 Transfer complete.
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,138,240)
20090114 142216 (Command Sent Message): RETR /Dir1/Dir2/Dir3/File1
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /Dir1/Dir2/Dir3/File1 (12364 bytes).
*** 20 minutes without any message ***
20090114 144216 (Reply Received Message): 426 Data connection: Interrupted system call.
20090114 144216 (Command Sent Message): PASV
20090114 144216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,109,169)
20090114 144216 (Command Sent Message): RETR /Dir1/Dir2/Dir3/File1
20090114 144216 (Reply Received Message): 150 Opening BINARY mode data connection for /Dir1/Dir2/Dir3/File2 (12387 bytes).
20090114 144216 (Reply Received Message): 226 Transfer complete.
{noformat}
Here are the logs for another thread :
{noformat}
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,174,233)
20090114 142216 (Command Sent Message): RETR /DirA/DirB/DirC/FileA
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /DirA/DirB/DirC/FileA (14209 bytes).
20090114 142216 (Reply Received Message): 226 Transfer complete.
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,202,81)
20090114 142216 (Command Sent Message): LIST /DirA/DirB/DirD
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /bin/ls.
*** 20 minutes without any message ***
20090114 144216 (Reply Received Message): 426 Data connection: Interrupted system call.
20090114 144216 (Command Sent Message): PASV
20090114 144216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,11,16)
20090114 144216 (Command Sent Message): RETR /DirA/DirB/DirD/FileB
20090114 144216 (Reply Received Message): 150 Opening BINARY mode data connection for /DirA/DirB/DirD/FileB (14145 bytes).
{noformat}
So it happens during LIST or during RETR command.
The issue is always reproducible when connecting to this Ftp server.
What is the meaning of the error message "426 Data connection: Interrupted system call." ?
Here are the stack-traces where the FtpClient is blocked during 20 minutes.
For 1st connection :
{noformat}
Stack 30 - Wed Jan 14 14:40:00 CET 2009
"FTPMediationTask" prio=3 tid=0x00aac800 nid=0x156 runnable [0x6877e000..0x6877fb70]
java.lang.Thread.State: RUNNABLE
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)
- locked <0x8fc23880> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0x8fc23880> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:294)
at org.apache.commons.net.ftp.FTP.getReply(FTP.java:619)
at org.apache.commons.net.ftp.FTPClient.completePendingCommand(FTPClient.java:1244)
at org.apache.commons.net.ftp.FTPClient.initiateListParsing(FTPClient.java:2309)
at org.apache.commons.net.ftp.FTPClient.initiateListParsing(FTPClient.java:2269)
at org.apache.commons.net.ftp.FTPClient.listFiles(FTPClient.java:2046)
[...]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
{noformat}
And for the second connection :
{noformat}
Stack 27 - Wed Jan 14 14:37:00 CET 2009
"FTPMediationTask" prio=3 tid=0x0140b800 nid=0xe7 runnable [0x6967e000..0x6967f8f0]
java.lang.Thread.State: RUNNABLE
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)
- locked <0x7ea6cd20> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0x7ea6cd20> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:294)
at org.apache.commons.net.ftp.FTP.getReply(FTP.java:619)
at org.apache.commons.net.ftp.FTPClient.completePendingCommand(FTPClient.java:1244)
at org.apache.commons.net.ftp.FTPClient.retrieveFile(FTPClient.java:1301)
[...]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
{noformat}
The issue originally happened on commons-net 1.4, but I have upgraded to 2.0, and the issue is still there.
Here is the normal configuration :
Client1 connects to FtpServer to download files -> No issue
Client2 connects to FtpServer to download files -> 20-min timeout issue
(Client1 and Client2 are 2 different servers)
But when I try : Client2 connects to Client1 (instead of FtpServer) to download files -> No issue
Please help me find out a workaround or tell me if this is a bug in commons-net, or on remote FtpServer (but this would be strange, because Client1 has no issue)
Thanks in advance
was:
I have a Ftp Client with several connections in multi-thread that connects to a remote Ftp Server to list files and download new ones.
After 3 minutes of runtime, I get a 20-minute timeout for all running Ftp connections.
Here are the logs for 1 thread :
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,224,172)
20090114 142216 (Command Sent Message): LIST /Dir1/Dir2/Dir3
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /bin/ls.
20090114 142216 (Reply Received Message): 226 Transfer complete.
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,138,240)
20090114 142216 (Command Sent Message): RETR /Dir1/Dir2/Dir3/File1
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /Dir1/Dir2/Dir3/File1 (12364 bytes).
*** 20 minutes without any message ***
20090114 144216 (Reply Received Message): 426 Data connection: Interrupted system call.
20090114 144216 (Command Sent Message): PASV
20090114 144216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,109,169)
20090114 144216 (Command Sent Message): RETR /Dir1/Dir2/Dir3/File1
20090114 144216 (Reply Received Message): 150 Opening BINARY mode data connection for /Dir1/Dir2/Dir3/File2 (12387 bytes).
20090114 144216 (Reply Received Message): 226 Transfer complete.
Here are the logs for another thread :
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,174,233)
20090114 142216 (Command Sent Message): RETR /DirA/DirB/DirC/FileA
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /DirA/DirB/DirC/FileA (14209 bytes).
20090114 142216 (Reply Received Message): 226 Transfer complete.
20090114 142216 (Command Sent Message): PASV
20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,202,81)
20090114 142216 (Command Sent Message): LIST /DirA/DirB/DirD
20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /bin/ls.
*** 20 minutes without any message ***
20090114 144216 (Reply Received Message): 426 Data connection: Interrupted system call.
20090114 144216 (Command Sent Message): PASV
20090114 144216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,11,16)
20090114 144216 (Command Sent Message): RETR /DirA/DirB/DirD/FileB
20090114 144216 (Reply Received Message): 150 Opening BINARY mode data connection for /DirA/DirB/DirD/FileB (14145 bytes).
So it happens during LIST or during RETR command.
The issue is always reproducible when connecting to this Ftp server.
What is the meaning of the error message "426 Data connection: Interrupted system call." ?
Here are the stack-traces where the FtpClient is blocked during 20 minutes.
For 1st connection :
Stack 30 - Wed Jan 14 14:40:00 CET 2009
"FTPMediationTask" prio=3 tid=0x00aac800 nid=0x156 runnable [0x6877e000..0x6877fb70]
java.lang.Thread.State: RUNNABLE
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)
- locked <0x8fc23880> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0x8fc23880> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:294)
at org.apache.commons.net.ftp.FTP.getReply(FTP.java:619)
at org.apache.commons.net.ftp.FTPClient.completePendingCommand(FTPClient.java:1244)
at org.apache.commons.net.ftp.FTPClient.initiateListParsing(FTPClient.java:2309)
at org.apache.commons.net.ftp.FTPClient.initiateListParsing(FTPClient.java:2269)
at org.apache.commons.net.ftp.FTPClient.listFiles(FTPClient.java:2046)
[...]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
And for the second connection :
Stack 27 - Wed Jan 14 14:37:00 CET 2009
"FTPMediationTask" prio=3 tid=0x0140b800 nid=0xe7 runnable [0x6967e000..0x6967f8f0]
java.lang.Thread.State: RUNNABLE
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)
- locked <0x7ea6cd20> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0x7ea6cd20> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:294)
at org.apache.commons.net.ftp.FTP.getReply(FTP.java:619)
at org.apache.commons.net.ftp.FTPClient.completePendingCommand(FTPClient.java:1244)
at org.apache.commons.net.ftp.FTPClient.retrieveFile(FTPClient.java:1301)
[...]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619)
The issue originally happened on commons-net 1.4, but I have upgraded to 2.0, and the issue is still there.
Here is the normal configuration :
Client1 connects to FtpServer to download files -> No issue
Client2 connects to FtpServer to download files -> 20-min timeout issue
(Client1 and Client2 are 2 different servers)
But when I try : Client2 connects to Client1 (instead of FtpServer) to download files -> No issue
Please help me find out a workaround or tell me if this is a bug in commons-net, or on remote FtpServer (but this would be strange, because Client1 has no issue)
Thanks in advance
Fix formatting
> FtpClient hangs 20 minutes in FTPClient.completePendingCommand from retrieveFile or listFiles
> ---------------------------------------------------------------------------------------------
>
> Key: NET-249
> URL: https://issues.apache.org/jira/browse/NET-249
> Project: Commons Net
> Issue Type: Bug
> Components: FTP
> Affects Versions: 1.4, 2.0
> Environment: Client and Server running on Solaris 9
> Reporter: David Tavoularis
>
> I have a Ftp Client with several connections in multi-thread that connects to a remote Ftp Server to list files and download new ones.
> After 3 minutes of runtime, I get a 20-minute timeout for all running Ftp connections.
> Here are the logs for 1 thread :
> {noformat}
> 20090114 142216 (Command Sent Message): PASV
> 20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,224,172)
> 20090114 142216 (Command Sent Message): LIST /Dir1/Dir2/Dir3
> 20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /bin/ls.
> 20090114 142216 (Reply Received Message): 226 Transfer complete.
> 20090114 142216 (Command Sent Message): PASV
> 20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,138,240)
> 20090114 142216 (Command Sent Message): RETR /Dir1/Dir2/Dir3/File1
> 20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /Dir1/Dir2/Dir3/File1 (12364 bytes).
> *** 20 minutes without any message ***
> 20090114 144216 (Reply Received Message): 426 Data connection: Interrupted system call.
> 20090114 144216 (Command Sent Message): PASV
> 20090114 144216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,109,169)
> 20090114 144216 (Command Sent Message): RETR /Dir1/Dir2/Dir3/File1
> 20090114 144216 (Reply Received Message): 150 Opening BINARY mode data connection for /Dir1/Dir2/Dir3/File2 (12387 bytes).
> 20090114 144216 (Reply Received Message): 226 Transfer complete.
> {noformat}
> Here are the logs for another thread :
> {noformat}
> 20090114 142216 (Command Sent Message): PASV
> 20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,174,233)
> 20090114 142216 (Command Sent Message): RETR /DirA/DirB/DirC/FileA
> 20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /DirA/DirB/DirC/FileA (14209 bytes).
> 20090114 142216 (Reply Received Message): 226 Transfer complete.
> 20090114 142216 (Command Sent Message): PASV
> 20090114 142216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,202,81)
> 20090114 142216 (Command Sent Message): LIST /DirA/DirB/DirD
> 20090114 142216 (Reply Received Message): 150 Opening BINARY mode data connection for /bin/ls.
> *** 20 minutes without any message ***
> 20090114 144216 (Reply Received Message): 426 Data connection: Interrupted system call.
> 20090114 144216 (Command Sent Message): PASV
> 20090114 144216 (Reply Received Message): 227 Entering Passive Mode (10,250,10,116,11,16)
> 20090114 144216 (Command Sent Message): RETR /DirA/DirB/DirD/FileB
> 20090114 144216 (Reply Received Message): 150 Opening BINARY mode data connection for /DirA/DirB/DirD/FileB (14145 bytes).
> {noformat}
> So it happens during LIST or during RETR command.
> The issue is always reproducible when connecting to this Ftp server.
> What is the meaning of the error message "426 Data connection: Interrupted system call." ?
> Here are the stack-traces where the FtpClient is blocked during 20 minutes.
> For 1st connection :
> {noformat}
> Stack 30 - Wed Jan 14 14:40:00 CET 2009
> "FTPMediationTask" prio=3 tid=0x00aac800 nid=0x156 runnable [0x6877e000..0x6877fb70]
> java.lang.Thread.State: RUNNABLE
> 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)
> - locked <0x8fc23880> (a java.io.InputStreamReader)
> at java.io.InputStreamReader.read(InputStreamReader.java:167)
> at java.io.BufferedReader.fill(BufferedReader.java:136)
> at java.io.BufferedReader.readLine(BufferedReader.java:299)
> - locked <0x8fc23880> (a java.io.InputStreamReader)
> at java.io.BufferedReader.readLine(BufferedReader.java:362)
> at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:294)
> at org.apache.commons.net.ftp.FTP.getReply(FTP.java:619)
> at org.apache.commons.net.ftp.FTPClient.completePendingCommand(FTPClient.java:1244)
> at org.apache.commons.net.ftp.FTPClient.initiateListParsing(FTPClient.java:2309)
> at org.apache.commons.net.ftp.FTPClient.initiateListParsing(FTPClient.java:2269)
> at org.apache.commons.net.ftp.FTPClient.listFiles(FTPClient.java:2046)
> [...]
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
> at java.lang.Thread.run(Thread.java:619)
> {noformat}
> And for the second connection :
> {noformat}
> Stack 27 - Wed Jan 14 14:37:00 CET 2009
> "FTPMediationTask" prio=3 tid=0x0140b800 nid=0xe7 runnable [0x6967e000..0x6967f8f0]
> java.lang.Thread.State: RUNNABLE
> 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)
> - locked <0x7ea6cd20> (a java.io.InputStreamReader)
> at java.io.InputStreamReader.read(InputStreamReader.java:167)
> at java.io.BufferedReader.fill(BufferedReader.java:136)
> at java.io.BufferedReader.readLine(BufferedReader.java:299)
> - locked <0x7ea6cd20> (a java.io.InputStreamReader)
> at java.io.BufferedReader.readLine(BufferedReader.java:362)
> at org.apache.commons.net.ftp.FTP.__getReply(FTP.java:294)
> at org.apache.commons.net.ftp.FTP.getReply(FTP.java:619)
> at org.apache.commons.net.ftp.FTPClient.completePendingCommand(FTPClient.java:1244)
> at org.apache.commons.net.ftp.FTPClient.retrieveFile(FTPClient.java:1301)
> [...]
> at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
> at java.lang.Thread.run(Thread.java:619)
> {noformat}
> The issue originally happened on commons-net 1.4, but I have upgraded to 2.0, and the issue is still there.
> Here is the normal configuration :
> Client1 connects to FtpServer to download files -> No issue
> Client2 connects to FtpServer to download files -> 20-min timeout issue
> (Client1 and Client2 are 2 different servers)
> But when I try : Client2 connects to Client1 (instead of FtpServer) to download files -> No issue
> Please help me find out a workaround or tell me if this is a bug in commons-net, or on remote FtpServer (but this would be strange, because Client1 has no issue)
> Thanks in advance
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira