3486 2005-06-15 12:05 improper handling of error conditions on commands involving a data channel 2005-12-05 17:25:08 1 1 1 Unclassified CoG jglobus ftp 1.2 All All RESOLVED FIXED P3 blocker --- 1 hategan@mcs.anl.gov gawor@mcs.anl.gov allcock@mcs.anl.gov childers@mcs.anl.gov gregor@mcs.anl.gov jalameda@ncsa.uiuc.edu madduri@mcs.anl.gov hategan@mcs.anl.gov 2005-06-15 12:05:49 The following scenarios do not work as expected: 1. = Java code = cl.setPassiveMode(true); //foo does not exist try{cl.mlsd("foo");}catch(Exception e) {} cl.setPassiveMode(true); cl.mlsd(); ------------------------------------------------------------------------ = Client log = DEBUG [FTPControlChannel] - opening control channel to plussed : 5000 DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 220 GridFTP Server plussed.mcs.anl.gov 2.0 (gcc32dbg, 1114447190-1) ready. DEBUG [FTPControlChannel] - Control channel received: 220 GridFTP Server plussed.mcs.anl.gov 2.0 (gcc32dbg, 1114447190-1) ready. DEBUG [FTPControlChannel] - Control channel sending: AUTH GSSAPI DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 334 Using authentication type; ADAT must follow. DEBUG [FTPControlChannel] - Control channel received: 334 Using authentication type; ADAT must follow. DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 235 GSSAPI Authentication successful. DEBUG [FTPControlChannel] - Control channel received: 235 GSSAPI Authentication successful. DEBUG [FTPControlChannel] - Control channel sending: USER :globus-mapping: DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 331 Password required for :globus-mapping:. DEBUG [FTPControlChannel] - Control channel received: 331 Password required for :globus-mapping:. DEBUG [FTPControlChannel] - Control channel sending: PASS dummy DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 230 User hategan logged in. DEBUG [FTPControlChannel] - Control channel received: 230 User hategan logged in. DEBUG [FTPControlChannel] - Control channel sending: PASV DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 227 Entering Passive Mode (140,221,36,13,237,207) DEBUG [FTPControlChannel] - Control channel received: 227 Entering Passive Mode (140,221,36,13,237,207) DEBUG [GridFTPServerFacade] - hostport: 140.221.36.13 60879 DEBUG [TransferThreadManager] - adding new empty socketBox to the socket pool DEBUG [SocketPool] - adding a free socket DEBUG [TransferThreadManager] - connecting active socket 0; total cached sockets = 1 DEBUG [TaskThread] - executing task: org.globus.ftp.dc.GridFTPActiveConnectTask@af993e DEBUG [GridFTPActiveConnectTask] - connecting new socket to: 140.221.36.13 60879 DEBUG [GridFTPClient] - sessions match DEBUG [FTPControlChannel] - Control channel sending: MLSD foo DEBUG [TransferThreadManager] - checking out a socket; total cached sockets = 1; free = 1; busy = 0 DEBUG [FTPClient] - transferRun() DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPControlChannel] - checking input stream DEBUG [FTPControlChannel] - slept 0 DEBUG [FTPClient] - wait for both monitor threads to finish DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPServerFacade$LocalControlChannel] - waiting for reply in local control channel DEBUG [FTPServerFacade$LocalControlChannel] - slept 0 DEBUG [GridFTPActiveConnectTask] - authenticating DEBUG [GridFTPServerFacade] - Creating secure socket DEBUG [FTPServerFacade$LocalControlChannel] - slept 200 DEBUG [TransferMonitor] - reading first reply DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 500-Command failed. : System error in stat: No such file or directory DEBUG [Reply] - multiline reply; last line should start with ->500 <- DEBUG [Reply] - lenght of line.separator on this OS: 1 DEBUG [Reply] - read line DEBUG [Reply] - line : ->500-A system call failed: No such file or directory<- DEBUG [Reply] - read line DEBUG [Reply] - line : ->500 End.<- DEBUG [Reply] - end reached DEBUG [FTPControlChannel] - Control channel received: 500-Command failed. : System error in stat: No such file or directory 500-A system call failed: No such file or directory 500 End. DEBUG [TransferMonitor] - first reply bad: 500-Command failed. : System error in stat: No such file or directory 500-A system call failed: No such file or directory 500 End. DEBUG [TransferMonitor] - category: 5 DEBUG [TransferState] - intercepted exception: org.globus.ftp.exception.ServerException DEBUG [TransferMonitor] - abort DEBUG [TransferMonitor] - thread dying naturally DEBUG [FTPControlChannel] - Control channel sending: PASV DEBUG [Reply] - read 1st line DEBUG [TransferMonitor] - thread dying of InterruptedException. DEBUG [TransferState] - intercepted exception: java.lang.InterruptedException DEBUG [FTPServerFacade$LocalControlChannel] - writing reply DEBUG [FTPServerFacade$LocalControlChannel] - push reply:451 active connection to server failed java.net.SocketException: Connection reset java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:168) at org.globus.gsi.gssapi.SSLUtil.read(SSLUtil.java:37) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readToken(GSIGssInputStream.java:64) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readHandshakeToken(GSIGssInputStream.java:54) at org.globus.gsi.gssapi.net.impl.GSIGssSocket.readToken(GSIGssSocket.java:60) at org.globus.gsi.gssapi.net.GssSocket.authenticateClient(GssSocket.java:110) at org.globus.gsi.gssapi.net.GssSocket.startHandshake(GssSocket.java:140) at org.globus.gsi.gssapi.net.GssSocket.getOutputStream(GssSocket.java:160) at org.globus.ftp.extended.GridFTPServerFacade.authenticate(GridFTPServerFacade.java:542) at org.globus.ftp.dc.GridFTPActiveConnectTask.execute(GridFTPActiveConnectTask.java:72) at org.globus.ftp.dc.TaskThread.run(TaskThread.java:64) at java.lang.Thread.run(Thread.java:534) DEBUG [FTPServerFacade$LocalControlChannel] - wrote reply DEBUG [TaskThread] - finished task: org.globus.ftp.dc.GridFTPActiveConnectTask@af993e DEBUG [TaskThread] - executing task: org.globus.ftp.dc.ActiveStartTransferTask@da4b71 DEBUG [Reply] - 1st line: 227 Entering Passive Mode (140,221,36,13,237,208) DEBUG [FTPControlChannel] - Control channel received: 227 Entering Passive Mode (140,221,36,13,237,208) DEBUG [GridFTPServerFacade] - hostport: 140.221.36.13 60880 DEBUG [TransferThreadManager] - adding new empty socketBox to the socket pool DEBUG [SocketPool] - adding a free socket DEBUG [TransferThreadManager] - connecting active socket 0; total cached sockets = 1 DEBUG [GridFTPClient] - sessions match DEBUG [FTPControlChannel] - Control channel sending: MLSD DEBUG [FTPServerFacade$LocalControlChannel] - writing reply DEBUG [TransferThreadManager] - checking out a socket; total cached sockets = 1; free = 1; busy = 0 DEBUG [FTPServerFacade$LocalControlChannel] - push reply:451 startTransfer() failed java.lang.IllegalArgumentException: socket is null java.lang.IllegalArgumentException: socket is null at org.globus.ftp.dc.ActiveStartTransferTask.execute(ActiveStartTransferTask.java:95) at org.globus.ftp.dc.TaskThread.run(TaskThread.java:64) at java.lang.Thread.run(Thread.java:534) DEBUG [FTPClient] - transferRun() DEBUG [FTPServerFacade$LocalControlChannel] - wrote reply DEBUG [TaskThread] - finished task: org.globus.ftp.dc.ActiveStartTransferTask@da4b71 DEBUG [TaskThread] - executing task: org.globus.ftp.dc.GridFTPActiveConnectTask@2c1e6b DEBUG [GridFTPActiveConnectTask] - connecting new socket to: 140.221.36.13 60880 DEBUG [GridFTPActiveConnectTask] - authenticating DEBUG [GridFTPServerFacade] - Creating secure socket DEBUG [FTPClient] - wait for both monitor threads to finish DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPControlChannel] - checking input stream DEBUG [FTPControlChannel] - slept 0 DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPServerFacade$LocalControlChannel] - waiting for reply in local control channel DEBUG [FTPServerFacade$LocalControlChannel] - local control channel ready org.globus.ftp.exception.ServerException: Server refused performing the request. Custom message: (error code 1) [Nested exception message: Custom message: Unexpected reply: 451 active connection to server failed java.net.SocketException: Connection reset java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:168) at org.globus.gsi.gssapi.SSLUtil.read(SSLUtil.java:37) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readToken(GSIGssInputStream.java:64) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readHandshakeToken(GSIGssInputStream.java:54) at org.globus.gsi.gssapi.net.impl.GSIGssSocket.readToken(GSIGssSocket.java:60) at org.globus.gsi.gssapi.net.GssSocket.authenticateClient(GssSocket.java:110) at org.globus.gsi.gssapi.net.GssSocket.startHandshake(GssSocket.java:140) at org.globus.gsi.gssapi.net.GssSocket.getOutputStream(GssSocket.java:160) at org.globus.ftp.extended.GridFTPServerFacade.authenticate(GridFTPServerFacade.java:542) at org.globus.ftp.dc.GridFTPActiveConnectTask.execute(GridFTPActiveConnectTask.java:72) at org.globus.ftp.dc.TaskThread.run(TaskThread.java:64) at java.lang.Thread.run(Thread.java:534) ]. Nested exception is org.globus.ftp.exception.UnexpectedReplyCodeException: Custom message: Unexpected reply: 451 active connection to server failed java.net.SocketException: Connection reset java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:168) at org.globus.gsi.gssapi.SSLUtil.read(SSLUtil.java:37) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readToken(GSIGssInputStream.java:64) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readHandshakeToken(GSIGssInputStream.java:54) at org.globus.gsi.gssapi.net.impl.GSIGssSocket.readToken(GSIGssSocket.java:60) at org.globus.gsi.gssapi.net.GssSocket.authenticateClient(GssSocket.java:110) at org.globus.gsi.gssapi.net.GssSocket.startHandshake(GssSocket.java:140) at org.globus.gsi.gssapi.net.GssSocket.getOutputStream(GssSocket.java:160) at org.globus.ftp.extended.GridFTPServerFacade.authenticate(GridFTPServerFacade.java:542) at org.globus.ftp.dc.GridFTPActiveConnectTask.execute(GridFTPActiveConnectTask.java:72) at org.globus.ftp.dc.TaskThread.run(TaskThread.java:64) at java.lang.Thread.run(Thread.java:534) at org.globus.ftp.vanilla.TransferMonitor.run(TransferMonitor.java:174) DEBUG [TransferMonitor] - reading first reply DEBUG [FTPServerFacade$LocalControlChannel] - pop reply DEBUG [TransferMonitor] - first reply bad: 451 active connection to server failed java.net.SocketException: Connection reset java.net.SocketException: Connection reset at java.net.SocketInputStream.read(SocketInputStream.java:168) at org.globus.gsi.gssapi.SSLUtil.read(SSLUtil.java:37) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readToken(GSIGssInputStream.java:64) at org.globus.gsi.gssapi.net.impl.GSIGssInputStream.readHandshakeToken(GSIGssInputStream.java:54) at org.globus.gsi.gssapi.net.impl.GSIGssSocket.readToken(GSIGssSocket.java:60) at org.globus.gsi.gssapi.net.GssSocket.authenticateClient(GssSocket.java:110) at org.globus.gsi.gssapi.net.GssSocket.startHandshake(GssSocket.java:140) at org.globus.gsi.gssapi.net.GssSocket.getOutputStream(GssSocket.java:160) at org.globus.ftp.extended.GridFTPServerFacade.authenticate(GridFTPServerFacade.java:542) at org.globus.ftp.dc.GridFTPActiveConnectTask.execute(GridFTPActiveConnectTask.java:72) at org.globus.ftp.dc.TaskThread.run(TaskThread.java:64) at java.lang.Thread.run(Thread.java:534) DEBUG [TransferMonitor] - category: 4 DEBUG [TransferState] - intercepted exception: org.globus.ftp.exception.ServerException Done DEBUG [TransferMonitor] - abort DEBUG [TransferMonitor] - thread dying of InterruptedException. DEBUG [TransferState] - intercepted exception: java.lang.InterruptedException DEBUG [TransferMonitor] - thread dying naturally ------------------------------------------------------------------------ = Server log = [21998] Sat Jun 11 19:35:01 2005 :: Server started in daemon mode. [21998] Sat Jun 11 19:35:09 2005 :: New connection from: vpnclient18121.mcs.anl.gov:35545 [21998] Sat Jun 11 19:35:14 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: USER :globus-mapping: [21998] Sat Jun 11 19:35:14 2005 :: vpnclient18121.mcs.anl.gov:35545: [SERVER]: 331 Password required for :globus-mapping:. [21998] Sat Jun 11 19:35:14 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: PASS dummy [21998] Sat Jun 11 19:35:14 2005 :: User hategan successfully authorized [21998] Sat Jun 11 19:35:14 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: PASS dummy [21998] Sat Jun 11 19:35:14 2005 :: vpnclient18121.mcs.anl.gov:35545: [SERVER]: 230 User hategan logged in. [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: PASV [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [SERVER]: 227 Entering Passive Mode (140,221,36,13,237,207) [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: MLSD foo [21998] Sat Jun 11 19:35:15 2005 :: Finished transferring "/home/hategan/foo". [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [SERVER]: 500-Command failed. : System error in stat: No such file or directory 500-A system call failed: No such file or directory 500 End. [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: PASV [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [SERVER]: 227 Entering Passive Mode (140,221,36,13,237,208) [21998] Sat Jun 11 19:35:15 2005 :: vpnclient18121.mcs.anl.gov:35545: [CLIENT]: MLSD [21998] Sat Jun 11 19:35:16 2005 :: Requesting abort... [21998] Sat Jun 11 19:35:16 2005 :: Starting to transfer "/home/hategan". [21998] Sat Jun 11 19:35:16 2005 :: Finished transferring "/home/hategan". [21998] Sat Jun 11 19:35:16 2005 :: vpnclient18121.mcs.anl.gov:35545: [SERVER]: 421 Server terminated [21998] Sat Jun 11 19:35:16 2005 :: Closed connection from vpnclient18121.mcs.anl.gov:35545 [21998] Sat Jun 11 19:38:48 2005 :: Server is shutting down... 2. = Java code = cl.setPassiveMode(false); try{cl.mlsd("foo");}catch(Exception e) {} cl.setPassiveMode(true); cl.put(new File("/home/mike/wiki.css"), "wiki.css", false); ------------------------------------------------------------------------ = Client log = DEBUG [FTPControlChannel] - opening control channel to plussed : 5000 DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 220 GridFTP Server plussed.mcs.anl.gov 2.0 (gcc32dbg, 1114447190-1) ready. DEBUG [FTPControlChannel] - Control channel received: 220 GridFTP Server plussed.mcs.anl.gov 2.0 (gcc32dbg, 1114447190-1) ready. DEBUG [FTPControlChannel] - Control channel sending: AUTH GSSAPI DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 334 Using authentication type; ADAT must follow. DEBUG [FTPControlChannel] - Control channel received: 334 Using authentication type; ADAT must follow. DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 235 GSSAPI Authentication successful. DEBUG [FTPControlChannel] - Control channel received: 235 GSSAPI Authentication successful. DEBUG [FTPControlChannel] - Control channel sending: USER :globus-mapping: DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 331 Password required for :globus-mapping:. DEBUG [FTPControlChannel] - Control channel received: 331 Password required for :globus-mapping:. DEBUG [FTPControlChannel] - Control channel sending: PASS dummy DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 230 User hategan logged in. DEBUG [FTPControlChannel] - Control channel received: 230 User hategan logged in. DEBUG [FTPServerFacade] - started passive server at port 50000 DEBUG [FTPControlChannel] - Control channel sending: PORT 140,221,18,121,195,80 DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 200 PORT Command successful. DEBUG [FTPControlChannel] - Control channel received: 200 PORT Command successful. DEBUG [GridFTPClient] - sessions match DEBUG [FTPControlChannel] - Control channel sending: MLSD foo DEBUG [FTPClient] - transferRun() DEBUG [TaskThread] - executing task: org.globus.ftp.dc.GridFTPPassiveConnectTask@1f6226 DEBUG [GridFTPPassiveConnectTask] - server.accept() DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPControlChannel] - checking input stream DEBUG [FTPControlChannel] - slept 0 DEBUG [FTPClient] - wait for both monitor threads to finish DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPServerFacade$LocalControlChannel] - waiting for reply in local control channel DEBUG [FTPServerFacade$LocalControlChannel] - slept 0 DEBUG [TransferMonitor] - reading first reply DEBUG [Reply] - read 1st line DEBUG [Reply] - 1st line: 500-Command failed. : System error in stat: No such file or directory DEBUG [Reply] - multiline reply; last line should start with ->500 <- DEBUG [Reply] - lenght of line.separator on this OS: 1 DEBUG [Reply] - read line DEBUG [Reply] - line : ->500-A system call failed: No such file or directory<- DEBUG [Reply] - read line DEBUG [Reply] - line : ->500 End.<- DEBUG [Reply] - end reached DEBUG [FTPServerFacade$LocalControlChannel] - slept 200 DEBUG [FTPControlChannel] - Control channel received: 500-Command failed. : System error in stat: No such file or directory 500-A system call failed: No such file or directory 500 End. DEBUG [TransferMonitor] - first reply bad: 500-Command failed. : System error in stat: No such file or directory 500-A system call failed: No such file or directory 500 End. DEBUG [TransferMonitor] - category: 5 DEBUG [TransferState] - intercepted exception: org.globus.ftp.exception.ServerException DEBUG [TransferMonitor] - abort DEBUG [TransferMonitor] - thread dying naturally DEBUG [FTPControlChannel] - Control channel sending: PASV DEBUG [Reply] - read 1st line DEBUG [TransferMonitor] - thread dying of InterruptedException. DEBUG [TransferState] - intercepted exception: java.lang.InterruptedException DEBUG [Reply] - 1st line: 227 Entering Passive Mode (140,221,36,13,238,24) DEBUG [FTPControlChannel] - Control channel received: 227 Entering Passive Mode (140,221,36,13,238,24) DEBUG [GridFTPServerFacade] - hostport: 140.221.36.13 60952 DEBUG [TransferThreadManager] - adding new empty socketBox to the socket pool DEBUG [SocketPool] - adding a free socket DEBUG [TransferThreadManager] - connecting active socket 0; total cached sockets = 1 DEBUG [FTPClient] - sessions match DEBUG [GridFTPServerFacade] - starting outgoing transfer without mode E DEBUG [TransferThreadManager] - checking out a socket; total cached sockets = 1; free = 1; busy = 0 DEBUG [FTPControlChannel] - Control channel sending: STOR wiki.css DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPControlChannel] - checking input stream DEBUG [FTPControlChannel] - slept 0 DEBUG [FTPClient] - wait for both transfer to start DEBUG [TransferMonitor] - waiting for 1st reply; maxWait = 12000, ioDelay = 200 DEBUG [FTPServerFacade$LocalControlChannel] - waiting for reply in local control channel DEBUG [FTPServerFacade$LocalControlChannel] - slept 0 DEBUG [FTPControlChannel] - slept 200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 200 DEBUG [FTPControlChannel] - slept 400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 400 DEBUG [FTPControlChannel] - slept 600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 600 DEBUG [FTPControlChannel] - slept 800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 800 DEBUG [FTPControlChannel] - slept 1000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 1000 DEBUG [FTPControlChannel] - slept 1200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 1200 DEBUG [FTPControlChannel] - slept 1400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 1400 DEBUG [FTPControlChannel] - slept 1600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 1600 DEBUG [FTPControlChannel] - slept 1800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 1800 DEBUG [FTPControlChannel] - slept 2000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 2000 DEBUG [FTPControlChannel] - slept 2200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 2200 DEBUG [FTPControlChannel] - slept 2400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 2400 DEBUG [FTPControlChannel] - slept 2600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 2600 DEBUG [FTPControlChannel] - slept 2800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 2800 DEBUG [FTPControlChannel] - slept 3000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 3000 DEBUG [FTPControlChannel] - slept 3200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 3200 DEBUG [FTPControlChannel] - slept 3400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 3400 DEBUG [FTPControlChannel] - slept 3600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 3600 DEBUG [FTPControlChannel] - slept 3800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 3800 DEBUG [FTPControlChannel] - slept 4000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 4000 DEBUG [FTPControlChannel] - slept 4200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 4200 DEBUG [FTPControlChannel] - slept 4400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 4400 DEBUG [FTPControlChannel] - slept 4600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 4600 DEBUG [FTPControlChannel] - slept 4800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 4800 DEBUG [FTPControlChannel] - slept 5000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 5000 DEBUG [FTPControlChannel] - slept 5200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 5200 DEBUG [FTPControlChannel] - slept 5400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 5400 DEBUG [FTPControlChannel] - slept 5600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 5600 DEBUG [FTPControlChannel] - slept 5800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 5800 DEBUG [FTPControlChannel] - slept 6000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 6000 DEBUG [FTPControlChannel] - slept 6200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 6200 DEBUG [FTPControlChannel] - slept 6400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 6400 DEBUG [FTPControlChannel] - slept 6600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 6600 DEBUG [FTPControlChannel] - slept 6800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 6800 DEBUG [FTPControlChannel] - slept 7000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 7000 DEBUG [FTPControlChannel] - slept 7200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 7200 DEBUG [FTPControlChannel] - slept 7400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 7400 DEBUG [FTPControlChannel] - slept 7600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 7600 DEBUG [FTPControlChannel] - slept 7800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 7800 DEBUG [FTPControlChannel] - slept 8000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 8000 DEBUG [FTPControlChannel] - slept 8200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 8200 DEBUG [FTPControlChannel] - slept 8400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 8400 DEBUG [FTPControlChannel] - slept 8600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 8600 DEBUG [FTPControlChannel] - slept 8800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 8800 DEBUG [FTPControlChannel] - slept 9000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 9000 DEBUG [FTPControlChannel] - slept 9200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 9200 DEBUG [FTPControlChannel] - slept 9400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 9400 DEBUG [FTPControlChannel] - slept 9600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 9600 DEBUG [FTPControlChannel] - slept 9800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 9800 DEBUG [FTPControlChannel] - slept 10000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 10000 DEBUG [FTPControlChannel] - slept 10200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 10200 DEBUG [FTPControlChannel] - slept 10400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 10400 DEBUG [FTPControlChannel] - slept 10600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 10600 DEBUG [FTPControlChannel] - slept 10800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 10800 DEBUG [FTPControlChannel] - slept 11000 DEBUG [FTPServerFacade$LocalControlChannel] - slept 11000 DEBUG [FTPControlChannel] - slept 11200 DEBUG [FTPServerFacade$LocalControlChannel] - slept 11200 DEBUG [FTPControlChannel] - slept 11400 DEBUG [FTPServerFacade$LocalControlChannel] - slept 11400 DEBUG [FTPControlChannel] - slept 11600 DEBUG [FTPServerFacade$LocalControlChannel] - slept 11600 DEBUG [FTPControlChannel] - slept 11800 DEBUG [FTPServerFacade$LocalControlChannel] - slept 11800 DEBUG [FTPControlChannel] - timeout DEBUG [TransferMonitor] - thread dying of timeout DEBUG [TransferState] - intercepted exception: org.globus.ftp.exception.ServerException DEBUG [TransferMonitor] - abort DEBUG [TransferMonitor] - thread dying of InterruptedException. DEBUG [TransferState] - intercepted exception: java.lang.InterruptedException Done org.globus.ftp.exception.ServerException: Reply wait timeout. (error code 4) at org.globus.ftp.vanilla.FTPControlChannel.waitFor(FTPControlChannel.java:213) at org.globus.ftp.vanilla.TransferMonitor.run(TransferMonitor.java:108) ------------------------------------------------------------------------ = Server log = [22084] Sat Jun 11 19:52:30 2005 :: Server started in daemon mode. [22084] Sat Jun 11 19:52:34 2005 :: New connection from: vpnclient18121.mcs.anl.gov:35569 [22084] Sat Jun 11 19:52:39 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: USER :globus-mapping: [22084] Sat Jun 11 19:52:39 2005 :: vpnclient18121.mcs.anl.gov:35569: [SERVER]: 331 Password required for :globus-mapping:. [22084] Sat Jun 11 19:52:39 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: PASS dummy [22084] Sat Jun 11 19:52:39 2005 :: User hategan successfully authorized [22084] Sat Jun 11 19:52:39 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: PASS dummy [22084] Sat Jun 11 19:52:39 2005 :: vpnclient18121.mcs.anl.gov:35569: [SERVER]: 230 User hategan logged in. [22084] Sat Jun 11 19:52:40 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: PORT 140,221,18,121,195,80 [22084] Sat Jun 11 19:52:40 2005 :: vpnclient18121.mcs.anl.gov:35569: [SERVER]: 200 PORT Command successful. [22084] Sat Jun 11 19:52:40 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: MLSD foo [22084] Sat Jun 11 19:52:40 2005 :: Finished transferring "/home/hategan/foo". [22084] Sat Jun 11 19:52:40 2005 :: vpnclient18121.mcs.anl.gov:35569: [SERVER]: 500-Command failed. : System error in stat: No such file or directory 500-A system call failed: No such file or directory 500 End. [22084] Sat Jun 11 19:52:40 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: PASV [22084] Sat Jun 11 19:52:40 2005 :: vpnclient18121.mcs.anl.gov:35569: [SERVER]: 227 Entering Passive Mode (140,221,36,13,238,24) [22084] Sat Jun 11 19:52:41 2005 :: vpnclient18121.mcs.anl.gov:35569: [CLIENT]: STOR wiki.css [22084] Sat Jun 11 19:52:53 2005 :: Requesting abort... [22084] Sat Jun 11 19:52:53 2005 :: Starting to transfer "/home/hategan/wiki.css". [22084] Sat Jun 11 19:52:53 2005 :: Finished transferring "/home/hategan/wiki.css". [22084] Sat Jun 11 19:52:53 2005 :: vpnclient18121.mcs.anl.gov:35569: [SERVER]: 421 Server terminated [22084] Sat Jun 11 19:52:53 2005 :: Closed connection from vpnclient18121.mcs.anl.gov:35569 [22084] Sat Jun 11 19:53:40 2005 :: Server is shutting down... ------------------------------------------------------------------------ hategan@mcs.anl.gov 2005-06-15 12:08:13 *** Bug 3477 has been marked as a duplicate of this bug. *** gregor@mcs.anl.gov 2005-06-15 14:57:06 Jay Alameda has been added as the OGCE project ran into the same bug as we did . gawor@mcs.anl.gov 2005-06-20 22:27:03 Committed some fixes today (based on Mihael's patches). Both test cases seem to pass for me. Please verify and let me know. I'll add botch test cases to regular ftp tests. gawor@mcs.anl.gov 2005-06-21 15:13:58 Committed another fix (related to the second case) and also committed three separate tests to test these conditions. Please use the latest code to retest and let me know. hategan@mcs.anl.gov 2005-06-22 16:49:30 Works fine here, too.