Bug 3486 – improper handling of error conditions on commands involving a data channel

Bug 3486 - improper handling of error conditions on commands involving a data channel

Summary:

improper handling of error conditions on commands involving a data channel

Status:	RESOLVED FIXED

Product:	CoG jglobus
Component:	ftp
Version:	1.2
Platform:	All All

Importance:	P3 blocker
Target Milestone:	---
Assigned To:	Jarek Gawor

URL:
Keywords:

Depends on:
Blocks:
	Show dependency tree / graph

Reported:	2005-06-15 12:05 by Mihael Hategan
Modified:	2005-12-05 17:25 (History)

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note

You need to log in before you can comment on or make changes to this bug.

Description From Mihael Hategan 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...

------------------------------------------------------------------------

------- Comment #1 From Mihael Hategan 2005-06-15 12:08:13 -------

*** Bug 3477 has been marked as a duplicate of this bug. ***

------- Comment #2 From Gregor von Laszewski 2005-06-15 14:57:06 -------

Jay Alameda has been added as the OGCE project ran into the same bug as we did
.

------- Comment #3 From Jarek Gawor 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.

------- Comment #4 From Jarek Gawor 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.

------- Comment #5 From Mihael Hategan 2005-06-22 16:49:30 -------

Works fine here, too.