Bug 1056 - ftp client in emode after receiving EODC does not wait for EOD on the same channel
: ftp client in emode after receiving EODC does not wait for EOD on the same ch...
Status: NEW
: CoG jglobus
ftp
: unspecified
: PC Linux
: P2 major
: ---
Assigned To:
:
:
:
:
  Show dependency treegraph
 
Reported: 2003-07-01 12:07 by
Modified: 2007-09-12 16:19 (History)


Attachments


Note

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


Description From 2003-07-01 12:07:39
This is the behavier observed while retrieving from fermilab ftp server. If the
server sends EOD and EODC as a single block then the client handles this correctly.
If the server sends EODC in one block and EOD in the following block, client
never receives that EOD, From the output it is clearly seen that the socket
belonging to the [Thread-4] receives EODC (5) and later does not wait for eny
input on that socket .
Here is the complete output followed by the listing of the code:
[timur@fnisd1 gssgsi]$ java FTPClient true 100
gsiftp://fnisd1.fnal.gov:2813//jon/timur/b-4.5 `pwd`/b-4.100
[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 220 GSI FTP Door ready
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 220 GSI FTP
Door ready
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: AUTH GSSAPI

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 334 ADAT must follow
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 334 ADAT
must follow
[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 235 OK
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 235 OK
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: USER
:globus-mapping:

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 200 User timur logged in
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 200 User
timur logged in
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: PASS dummy

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 200 Already logged in
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 200 Already
logged in
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: TYPE I

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 200 Type set to I
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 200 Type set
to I
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: MODE E

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 200 Will use Extended Block mode
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 200 Will use
Extended Block mode
[main] DEBUG ftp.FTPClient  - setting options: RETR Parallelism=5,5,5;
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: OPTS RETR
Parallelism=5,5,5;

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 200 Parallel streams set
(Parallelism=5,5,5;)
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 200 Parallel
streams set (Parallelism=5,5,5;)
[main] DEBUG extended.GridFTPServerFacade  - parallelism set to 5
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: FEAT

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 211-OK
[main] DEBUG vanilla.Reply  - multiline reply; last line should start with ->211 <-
[main] DEBUG vanilla.Reply  - lenght of line.separator on this OS: 1
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : -> EOF<-
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : -> PARALLEL<-
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : -> SIZE<-
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : -> SBUF<-
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : -> ERET<-
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : -> ESTO<-
[main] DEBUG vanilla.Reply  - read line
[main] DEBUG vanilla.Reply  - line : ->211 End<-
[main] DEBUG vanilla.Reply  - end reached
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 211-OK
 EOF
 PARALLEL
 SIZE
 SBUF
 ERET
 ESTO
211 End
[main] DEBUG ftp.GridFTPClient  - okay, server supports extended, parallel and
striped
[main] DEBUG vanilla.FTPServerFacade  - started passive server at port 35964
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: PORT
131,225,81,191,140,124

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 200 PORT command successful
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 200 PORT
command successful
[main] DEBUG ftp.GridFTPClient  - localServer.store()
[main] DEBUG extended.GridFTPServerFacade  - creating data connection task
[Thread-1] DEBUG dc.TaskThread  - executing task
[Thread-1] DEBUG dc.PassiveConnectTask  - GridFTPPassiveConnectTask server.accept()
[main] DEBUG extended.GridFTPServerFacade  - creating data connection task
[main] DEBUG extended.GridFTPServerFacade  - creating data connection task
[main] DEBUG extended.GridFTPServerFacade  - creating data connection task
[main] DEBUG extended.GridFTPServerFacade  - creating data connection task
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: ERET P 0 100
/jon/timur/b-4.5

[main] DEBUG ftp.FTPClient  - transferRun()
[Thread-2] DEBUG thread.local  - waiting for 1st reply;  maxWait = 100000,
ioDelay = 1000
[Thread-2] DEBUG vanilla.FTPControlChannel  - checking input stream
[Thread-2] DEBUG vanilla.FTPControlChannel  - slept 0
[Thread-3] DEBUG thread.remot  - waiting for 1st reply;  maxWait = 100000,
ioDelay = 1000
[Thread-3] DEBUG vanilla.FTPServerFacade  - waiting for reply in local control
channel
[Thread-3] DEBUG vanilla.FTPServerFacade  - slept 0
[main] DEBUG ftp.FTPClient  - wait for both monitor threads to finish
[Thread-2] DEBUG vanilla.FTPControlChannel  - slept 1000
[Thread-3] DEBUG vanilla.FTPServerFacade  - slept 1000
[Thread-2] DEBUG vanilla.FTPControlChannel  - slept 2000
[Thread-3] DEBUG vanilla.FTPServerFacade  - slept 2000
[Thread-1] DEBUG dc.PassiveConnectTask  - server.accept() returned
[Thread-1] DEBUG dc.SocketBox  - Setting facade's socket
[Thread-1] DEBUG dc.SecureDataChannelFactory  - starting plain data channel
[Thread-1] DEBUG dc.PassiveConnectTask  - starting sink data channel
[Thread-1] DEBUG dc.TaskThread  - finished task
[Thread-1] DEBUG dc.TaskThread  - executing task
[Thread-1] DEBUG dc.PassiveConnectTask  - GridFTPPassiveConnectTask server.accept()
[Thread-1] DEBUG dc.PassiveConnectTask  - server.accept() returned
[Thread-1] DEBUG dc.SocketBox  - Setting facade's socket
[Thread-1] DEBUG dc.SecureDataChannelFactory  - starting plain data channel
[Thread-1] DEBUG dc.PassiveConnectTask  - starting sink data channel
[Thread-4] DEBUG dc.SimpleDataChannel  - TransferSinkThread executing
[Thread-4] DEBUG vanilla.FTPServerFacade  - writing reply
[Thread-4] DEBUG vanilla.FTPServerFacade  - push reply:125 this LocalReply does
not have a message
[Thread-4] DEBUG vanilla.FTPServerFacade  - pushed
[Thread-4] DEBUG vanilla.FTPServerFacade  - wrote reply
[Thread-4] DEBUG dc.SimpleDataChannel  - wrote first reply
[Thread-4] DEBUG dc.EBlockImageDCReader  - 0 100 0
[Thread-4] DEBUG dc.EBlockImageDCReader  - false false
write buffer of length100 offset =0
offset is 0
[Thread-4] DEBUG dc.EBlockImageDCReader  - 64 0 5
[Thread-4] DEBUG dc.EBlockImageDCReader  - true false
[Thread-4] DEBUG dc.EBlockImageDCReader  - expecting EODs: 5
[Thread-4] DEBUG dc.SimpleDataChannel  - finished reading data; transferred 100bytes
[Thread-4] DEBUG dc.SocketBox  - Setting facade's socket to null
[Thread-1] DEBUG dc.TaskThread  - finished task
[Thread-1] DEBUG dc.TaskThread  - executing task
[Thread-1] DEBUG dc.PassiveConnectTask  - GridFTPPassiveConnectTask server.accept()
[Thread-1] DEBUG dc.PassiveConnectTask  - server.accept() returned
[Thread-1] DEBUG dc.SocketBox  - Setting facade's socket
[Thread-1] DEBUG dc.SecureDataChannelFactory  - starting plain data channel
[Thread-1] DEBUG dc.PassiveConnectTask  - starting sink data channel
[Thread-5] DEBUG dc.SimpleDataChannel  - TransferSinkThread executing
[Thread-5] DEBUG dc.EBlockImageDCReader  - 12 0 100
[Thread-5] DEBUG dc.EBlockImageDCReader  - false true
[Thread-5] DEBUG dc.EBlockImageDCReader  - received EOD. Still expecting: 4
write buffer of length0 offset =100
offset is 100
[Thread-5] DEBUG dc.SimpleDataChannel  - finished reading data; transferred 0bytes
[Thread-5] DEBUG dc.SocketBox  - Setting facade's socket to null
[Thread-1] DEBUG dc.TaskThread  - finished task
[Thread-1] DEBUG dc.TaskThread  - executing task
[Thread-1] DEBUG dc.PassiveConnectTask  - GridFTPPassiveConnectTask server.accept()
[Thread-1] DEBUG dc.PassiveConnectTask  - server.accept() returned
[Thread-1] DEBUG dc.SocketBox  - Setting facade's socket
[Thread-1] DEBUG dc.SecureDataChannelFactory  - starting plain data channel
[Thread-1] DEBUG dc.PassiveConnectTask  - starting sink data channel
[Thread-6] DEBUG dc.SimpleDataChannel  - TransferSinkThread executing
[Thread-6] DEBUG dc.EBlockImageDCReader  - 12 0 100
[Thread-6] DEBUG dc.EBlockImageDCReader  - false true
[Thread-6] DEBUG dc.EBlockImageDCReader  - received EOD. Still expecting: 3
write buffer of length0 offset =100
offset is 100
[Thread-6] DEBUG dc.SimpleDataChannel  - finished reading data; transferred 0bytes
[Thread-6] DEBUG dc.SocketBox  - Setting facade's socket to null
[Thread-1] DEBUG dc.TaskThread  - finished task
[Thread-1] DEBUG dc.TaskThread  - executing task
[Thread-1] DEBUG dc.PassiveConnectTask  - GridFTPPassiveConnectTask server.accept()
[Thread-1] DEBUG dc.PassiveConnectTask  - server.accept() returned
[Thread-1] DEBUG dc.SocketBox  - Setting facade's socket
[Thread-1] DEBUG dc.SecureDataChannelFactory  - starting plain data channel
[Thread-1] DEBUG dc.PassiveConnectTask  - starting sink data channel
[Thread-7] DEBUG dc.SimpleDataChannel  - TransferSinkThread executing
[Thread-7] DEBUG dc.EBlockImageDCReader  - 12 0 100
[Thread-7] DEBUG dc.EBlockImageDCReader  - false true
[Thread-7] DEBUG dc.EBlockImageDCReader  - received EOD. Still expecting: 2
write buffer of length0 offset =100
offset is 100
[Thread-7] DEBUG dc.SimpleDataChannel  - finished reading data; transferred 0bytes
[Thread-7] DEBUG dc.SocketBox  - Setting facade's socket to null
[Thread-1] DEBUG dc.TaskThread  - finished task
[Thread-8] DEBUG dc.SimpleDataChannel  - TransferSinkThread executing
[Thread-8] DEBUG dc.EBlockImageDCReader  - 12 0 100
[Thread-8] DEBUG dc.EBlockImageDCReader  - false true
[Thread-8] DEBUG dc.EBlockImageDCReader  - received EOD. Still expecting: 1
write buffer of length0 offset =100
offset is 100
[Thread-8] DEBUG dc.SimpleDataChannel  - finished reading data; transferred 0bytes
[Thread-8] DEBUG dc.SocketBox  - Setting facade's socket to null
[Thread-2] DEBUG thread.local  - reading first reply
[Thread-2] DEBUG vanilla.Reply  - read 1st line
[Thread-2] DEBUG vanilla.Reply  - 1st line: 226 Transfer complete.
[Thread-2] INFO  vanilla.FTPControlChannel  - Control channel received: 226
Transfer complete.
[Thread-2] DEBUG thread.local  - first reply bad: 226 Transfer complete.
[Thread-2] DEBUG thread.local  - category: 2
[Thread-2] DEBUG vanilla.TransferState  - intercepted exception:
org.globus.ftp.exception.ServerException
[Thread-2] DEBUG thread.remot  - abort
[Thread-2] DEBUG thread.local  - thread dying naturally
[Thread-3] DEBUG thread.remot  - thread dying of InterruptedException.
[Thread-3] DEBUG vanilla.TransferState  - intercepted exception:
java.lang.InterruptedException
org.globus.ftp.exception.ServerException: Server refused performing the request.
Custom message:  (error code 1) [Nested exception message:  Custom message:
Unexpected reply: 226 Transfer complete.].  Nested exception is
org.globus.ftp.exception.UnexpectedReplyCodeException:  Custom message:
Unexpected reply: 226 Transfer complete.
        at org.globus.ftp.vanilla.TransferMonitor.run(TransferMonitor.java:169)
[main] INFO  vanilla.FTPControlChannel  - Control channel sending: QUIT

[main] DEBUG vanilla.Reply  - read 1st line
[main] DEBUG vanilla.Reply  - 1st line: 150 Opening BINARY data connection for
/pnfs/fnal.gov/usr/cdfen//jon/timur/b-4.5
[main] INFO  vanilla.FTPControlChannel  - Control channel received: 150 Opening
BINARY data connection for /pnfs/fnal.gov/usr/cdfen//jon/timur/b-4.5
[main] DEBUG vanilla.FTPControlChannel  - ftp socket closed
[main] DEBUG vanilla.FTPServerFacade  - stop master thread
[main] DEBUG vanilla.FTPServerFacade  - wait for master thread to finish
[Thread-1] DEBUG dc.TaskThread  - notify that thread is finishing
[main] DEBUG vanilla.FTPServerFacade  - close data channels
[main] DEBUG vanilla.FTPServerFacade  - close server socket
[main] DEBUG vanilla.FTPServerFacade  - server socket closed
Exception in thread "main" org.globus.ftp.exception.ServerException: Server
refused performing the request. Custom message:  (error code 1) [Nested
exception message:  Custom message: Unexpected reply: 226 Transfer complete.]. 
Nested exception is org.globus.ftp.exception.UnexpectedReplyCodeException: 
Custom message: Unexpected reply: 226 Transfer complete.
        at org.globus.ftp.vanilla.TransferMonitor.run(TransferMonitor.java:169)
[timur@fnisd1 gssgsi]$ Jul 1, 2003 12:04:05 PM
java.util.prefs.FileSystemPreferences syncWorld
WARNING: Couldn't flush user prefs: java.util.prefs.BackingStoreException:
Couldn't get file lock.

[timur@fnisd1 gssgsi]$ cat FTPClient.java

import java.io.* ;
import java.net.URL;
import java.net.URLConnection;
import java.net.HttpURLConnection;
import java.net.ServerSocket;
import java.net.Socket;
import java.net.InetAddress;
import java.util.Hashtable;
import java.util.StringTokenizer;

import org.ietf.jgss.GSSException;
import org.ietf.jgss.GSSContext;
import org.ietf.jgss.GSSCredential;
import org.ietf.jgss.GSSManager;

import org.globus.gsi.GlobusCredential;
import org.globus.gsi.GlobusCredentialException;
import org.globus.gsi.TrustedCertificates;

import org.globus.gsi.gssapi.GlobusGSSManagerImpl;
import org.globus.gsi.gssapi.GlobusGSSCredentialImpl;

import org.globus.gsi.gssapi.net.GssSocket;
import org.globus.gsi.gssapi.net.GssSocketFactory;
import org.globus.gsi.gssapi.net.impl.GSIGssSocket;
import org.globus.gsi.gssapi.auth.AuthorizationException;
import org.globus.gsi.gssapi.auth.Authorization;

import org.gridforum.jgss.ExtendedGSSContext;
import org.gridforum.jgss.ExtendedGSSManager;
import org.gridforum.jgss.ExtendedGSSCredential;

import org.globus.gsi.GSIConstants;
import org.globus.gsi.gssapi.GSSConstants;

import org.globus.ftp.GridFTPClient;
import org.globus.ftp.DataChannelAuthentication;
import org.globus.ftp.Session;
import org.globus.ftp.GridFTPSession;
import org.globus.ftp.RetrieveOptions;
import org.globus.ftp.DataSource;
import org.globus.ftp.DataSink;
import org.globus.ftp.Buffer;
import org.globus.ftp.FileRandomIO;

import org.globus.util.GlobusURL;

import org.globus.gsi.gssapi.GlobusGSSCredentialImpl;
import org.globus.gsi.gssapi.SSLUtil;
import org.globus.gsi.TrustedCertificates;
import org.globus.gsi.GSIConstants;
import org.globus.gsi.gssapi.GlobusGSSManagerImpl;
import org.globus.gsi.GSIConstants;
import org.globus.gsi.gssapi.GSSConstants;
import org.globus.gsi.GlobusCredential;
import org.ietf.jgss.GSSManager;
import org.ietf.jgss.GSSCredential;
import org.ietf.jgss.GSSName;

import org.gridforum.jgss.ExtendedGSSContext;
import org.gridforum.jgss.ExtendedGSSManager;
import org.gridforum.jgss.ExtendedGSSCredential;
import org.globus.gsi.gssapi.net.impl.GSIGssSocket;
import org.globus.gsi.gssapi.net.GssSocket;

import java.io.OutputStream;
import java.io.InputStream;
import java.net.Socket;
import java.net.ServerSocket;

public class FTPClient{

        public static final void main(String[] args) throws Exception
    {
        if(args.length != 4)
        {
            System.out.println("Usage: FTPClient emode length srcurl destfile");
            System.out.println("emode can be true of false");
            System.out.print("if emode is false then the whole file is read");
            System.out.println(" and length is ignored");
            System.out.println("length can be -1, then it is file length");
            return;
        }

        boolean emode = args[0].equalsIgnoreCase("true");
        long length = Long.parseLong(args[1]);
        String srcGsiftpUrl = args[2];
        String destFile = args[3];

        GlobusCredential gcred = GlobusCredential.getDefaultCredential();
        GSSCredential cred = new GlobusGSSCredentialImpl(gcred,
GSSCredential.INITIATE_ONLY);
        RandomAccessFile raf = new RandomAccessFile(destFile,"rw");
        gridFTPRead(emode,length,srcGsiftpUrl,raf,cred);
        System.out.println("done");

        }

      public static void gridFTPRead(boolean emode,
                        long length,
                        String fromGsiftpUrl,
                        final RandomAccessFile diskFile ,
                      GSSCredential deleg_cred)
                      throws Exception
    {

            GlobusURL url =  new GlobusURL(fromGsiftpUrl);
             GridFTPClient client = new GridFTPClient(url.getHost(), url.getPort());
             try
             {
                client.authenticate(deleg_cred); /* use delegated credentials */
                client.setType(GridFTPSession.TYPE_IMAGE);
                if(emode)
                {
                    client.setMode(GridFTPSession.MODE_EBLOCK);
                    client.setOptions(new RetrieveOptions(5));
                }
                else
                {
                    client.setMode(GridFTPSession.MODE_STREAM);
                }
                if (client.isFeatureSupported("DCAU"))
                {
                   
client.setDataChannelAuthentication(DataChannelAuthentication.NONE);
                }
                else
                {
                    client.setLocalNoDataChannelAuthentication();
                }

                DataSink sink = new DataSink()
                {
                    public synchronized void write(Buffer buffer)
                        throws IOException
                    {

                        int read = buffer.getLength();
                        long offset = buffer.getOffset();
                    System.out.println("write buffer of length"+read+" offset
="+offset);
                        System.out.println("offset is "+offset);
                        if (offset < 0)
                        {
                            //throw new IOException("Invalid offset: " + offset);
                        }
                        else
                        {
                            diskFile.seek(offset);
                        }
                        diskFile.write(buffer.getBuffer(), 0, read);
                   }

                    public void close()
                        throws IOException
                    {

                        System.out.println("closing file");
                        diskFile.close();
                    }

                };

                client.setClientWaitParams(1000*100,1000);
                if(emode)
                {
                    if(length == -1)
                    {
                        long size = client.getSize(url.getPath());
                            length = size ;
                    }
                    client.extendedGet(url.getPath(),length,sink,null);
                    System.out.println("extendedGet done");
                }
                else
                {
                    client.get(url.getPath(),sink,null);
                    System.out.println("get done");
                }
                client.close();
             }
             catch(Exception e)
             {
                 e.printStackTrace();
                 try
                 {
                     client.close();
                 }
                 catch(Exception ee)
                 {
                 }
                 try
                 {
                     diskFile.close();
                 }
                 catch(Exception ee)
                 {
                 }
                 throw e;
             }

     }


}
[timur@fnisd1 gssgsi]$
------- Comment #1 From 2003-07-14 09:08:43 -------
I won't be able to look at it before August.
------- Comment #2 From 2004-01-28 02:44:15 -------
I assume this was resolved a while ago?
------- Comment #3 From 2004-01-28 06:28:59 -------
It was not resolved. We had to change our implementation to include both EOD 
and EODC in the same block. But it is a work around on the server side. Client 
still does not implement protocol correctly.
------- Comment #4 From 2004-03-15 19:05:19 -------
I'm lowering the severity of this bug as the reporter has a workaround for this 
problem.
------- Comment #5 From 2007-09-12 16:19:49 -------
Reassigning to current cog developer to close/fix as appropriate.