locked
FtpWebRequest re-sending USER and PASS commands half way through download loop

    Question

  • Well, the title says it all really:

    I'm using FtpWebRequest to download multiple files as follows:

    private string GetFile(Uri uri)
    {
         string un =  Misc.ReadRegKey("ParserFtpUsername");
         string pwd =  Misc.ReadRegKey("ParserFtpPwd");
         string file;

         NetworkCredential cred = new NetworkCredential(un, pwd);
         WebProxy pxy = new WebProxy();
         pxy.UseDefaultCredentials = true;

         FtpWebRequest wr = (FtpWebRequest)WebRequest.Create(uri);
         wr.Credentials = cred;
         wr.Proxy = pxy;
         wr.UseBinary = false;
         wr.Method = WebRequestMethods.Ftp.DownloadFile;

         FtpWebResponse resp = (FtpWebResponse)wr.GetResponse();
            
         Stream respStream = resp.GetResponseStream();
         StreamReader reader =  new StreamReader(respStream);

         file = reader.ReadToEnd();
            
         reader.Close();
         respStream.Close();

         return file;
    }

    ..so I'm calling this chunk of code repeatedly in a loop. However, I've found that around the 10th iteration (not always exactly 10th), the FTP server returns "503 Bad Sequence of Commands". 

    I've now enabled System.Net.trace.log, so that I can see the actual ftp commands that are being sent. I have discovered that for no apparent reason, after the 10th file, the FtpWebRequest re-sends the USER and PASS commands again when they are not required.

    Wondering whether this might be a timeout issue, I've adjusted the wr.Timeout to differing values, and yet the failure still happens at almost exactly the same place regardless.

    Has anyone any ideas of why this is happening? - it's driving me mad!

    Wednesday, March 15, 2006 12:14 PM

Answers

  • Per the RFC it is acceptible for client applications to send the USER command multiple times to change users while keeping the connection alive.  See section 4.1.1.  As mentioned previously in the thread, the FtpWebRequest class supports connection pooling so that the connection can be kept alive.  The pooling does not currently keep track of state as to which user last authenticated on that connection because it can't gaurantee that all code running in the same AppDomain is trusted to use that connection. 

    FtpWebRequest forces the re-authentication of the user for each usage of the connection to avoid accidentally giving access to a site to someone that doesn't know the username/password.  If the server you are connecting to doesn't support the issuing of multple "USER" commands on the same connection, then you can set KeepAlive = false on the request and a new connection will be established for each request.

    As for not sending the "QUIT" command until the end, this is done on purpose as that command signals that the connection is going to be closed.  Admittedly, the REIN command could have been used in this case but is not currently supported as far as I know.  I do not know if the developer considered using REIN or not - it may or may not have been a conscious decision.

     

    Thursday, May 04, 2006 9:12 PM

All replies

  • Could you please send us the log file?
    Friday, March 17, 2006 4:18 PM
  • I ran into this problem too, also when downloading a number of files.  During the operation, the FTP QUIT command was never being issued, so a subsequent attempt to log onto and fetch a file reused the same connection, on which the user was still logged in.  The underlying error was not "503 Bad sequence of commands" but "503 You are already logged in!".

    So you could modify your code to reuse the existing connection to download subsequent files, or add 
         .KeepAlive=False
    to the web request, and it will force the FTP QUIT command to be issued when you close it.

    Friday, April 28, 2006 4:33 PM
  • I've noticed that too with an upload implementation, but i don't get the 503 error.  Maybe because i'm using Serv-U ftp server.  I see in the server log that it is resending the USER / PASS commands.

    My code basically makes an initial connection with .method = PWD and .keepAlive  = true to test the connection.  It then loops through the files to send with .keepAlive = true and then after all the files are sent i do a PWD with the .keepAlive = false to close the connection.

    Here i'll paste the ftp server log with the extral USER / PASS commands highighted in red:

    5] Sat 29Apr06 08:24:18 - (000005) Connected to xxx.xxx.xxx.xxx(Local address xxx.xxx.xxx.xxx)
    Devil Sat 29Apr06 08:24:18 - (000005) 220 Serv-U FTP Server v6.1 for WinSock ready...
    [2] Sat 29Apr06 08:24:18 - (000005) USER lushdog
    Devil Sat 29Apr06 08:24:18 - (000005) 331 User name okay, need password.
    [5] Sat 29Apr06 08:24:18 - (000005) IP-Name: JUKSOFT-C6610E6
    [2] Sat 29Apr06 08:24:18 - (000005) PASS xxxxx
    [5] Sat 29Apr06 08:24:18 - (000005) User LUSHDOG logged in
    Devil Sat 29Apr06 08:24:18 - (000005) 230 User logged in, proceed.
    [2] Sat 29Apr06 08:24:18 - (000005) OPTS utf8 on
    Devil Sat 29Apr06 08:24:18 - (000005) 501 Invalid option.
    [2] Sat 29Apr06 08:24:18 - (000005) PWD
    Devil Sat 29Apr06 08:24:18 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:18 - (000005) CWD /
    Devil Sat 29Apr06 08:24:18 - (000005) 250 Directory changed to /
    [2] Sat 29Apr06 08:24:18 - (000005) PWD
    Devil Sat 29Apr06 08:24:18 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,218)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Alien 1.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\alien 1.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Alien 1.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\alien 1.bmp successfully (243 kB/sec - 11951 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) USER lushdog
    Devil Sat 29Apr06 08:24:18 - (000005) 331 User name okay, need password.
    [2] Sat 29Apr06 08:24:18 - (000005) PASS xxxxx
    [5] Sat 29Apr06 08:24:18 - (000005) User LUSHDOG logged in
    Devil Sat 29Apr06 08:24:18 - (000005) 230 User logged in, proceed.
    [2] Sat 29Apr06 08:24:18 - (000005) OPTS utf8 on
    Devil Sat 29Apr06 08:24:18 - (000005) 501 Invalid option.
    [2] Sat 29Apr06 08:24:18 - (000005) PWD
    Devil Sat 29Apr06 08:24:18 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:18 - (000005) CWD /
    Devil Sat 29Apr06 08:24:18 - (000005) 250 Directory changed to /
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,208)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Alien 2.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\alien 2.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Alien 2.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\alien 2.bmp successfully (418 kB/sec - 10705 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,209)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Balloon.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\balloon.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Balloon.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\balloon.bmp successfully (678 kB/sec - 18064 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,210)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Bear.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\bear.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Bear.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\bear.bmp successfully (625 kB/sec - 14717 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,211)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Beaver.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\beaver.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Beaver.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\beaver.bmp successfully (605 kB/sec - 14238 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) USER lushdog
    Devil Sat 29Apr06 08:24:18 - (000005) 331 User name okay, need password.
    [2] Sat 29Apr06 08:24:18 - (000005) PASS xxxxx
    [5] Sat 29Apr06 08:24:18 - (000005) User LUSHDOG logged in
    Devil Sat 29Apr06 08:24:18 - (000005) 230 User logged in, proceed.
    [2] Sat 29Apr06 08:24:18 - (000005) OPTS utf8 on
    Devil Sat 29Apr06 08:24:18 - (000005) 501 Invalid option.
    [2] Sat 29Apr06 08:24:18 - (000005) PWD
    Devil Sat 29Apr06 08:24:18 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:18 - (000005) CWD /
    Devil Sat 29Apr06 08:24:18 - (000005) 250 Directory changed to /
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,212)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Birthday Cake.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\birthday cake.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Birthday Cake.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\birthday cake.bmp successfully (433 kB/sec - 10638 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,213)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Chocolate Cake.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\chocolate cake.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Chocolate Cake.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\chocolate cake.bmp successfully (787 kB/sec - 19334 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,214)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Da Vinci.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\da vinci.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Da Vinci.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\da vinci.bmp successfully (557 kB/sec - 13108 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,215)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR David.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\david.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for David.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\david.bmp successfully (658 kB/sec - 16844 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:18 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:18 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:18 - (000005) PASV
    Devil Sat 29Apr06 08:24:18 - (000005) 227 Entering Passive Mode (218,147,194,153,7,216)
    [2] Sat 29Apr06 08:24:18 - (000005) STOR Dragon.bmp
    [4] Sat 29Apr06 08:24:18 - (000005) Receiving file e:\matt's folder\dragon.bmp
    Devil Sat 29Apr06 08:24:18 - (000005) 150 Opening BINARY mode data connection for Dragon.bmp.
    [4] Sat 29Apr06 08:24:18 - (000005) Received file e:\matt's folder\dragon.bmp successfully (348 kB/sec - 8545 Bytes)
    Devil Sat 29Apr06 08:24:18 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,217)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Earth.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\earth.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Earth.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\earth.bmp successfully (1055 kB/sec - 24838 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,218)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Fireworks 1.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\fireworks 1.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Fireworks 1.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\fireworks 1.bmp successfully (493 kB/sec - 11602 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,208)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Fireworks 2.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\fireworks 2.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Fireworks 2.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\fireworks 2.bmp successfully (372 kB/sec - 8769 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) USER lushdog
    Devil Sat 29Apr06 08:24:19 - (000005) 331 User name okay, need password.
    [2] Sat 29Apr06 08:24:19 - (000005) PASS xxxxx
    [5] Sat 29Apr06 08:24:19 - (000005) User LUSHDOG logged in
    Devil Sat 29Apr06 08:24:19 - (000005) 230 User logged in, proceed.
    [2] Sat 29Apr06 08:24:19 - (000005) OPTS utf8 on
    Devil Sat 29Apr06 08:24:19 - (000005) 501 Invalid option.
    [2] Sat 29Apr06 08:24:19 - (000005) PWD
    Devil Sat 29Apr06 08:24:19 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:19 - (000005) CWD /
    Devil Sat 29Apr06 08:24:19 - (000005) 250 Directory changed to /
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,209)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Fish.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\fish.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Fish.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\fish.bmp successfully (477 kB/sec - 11245 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,210)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Frog 1.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\frog 1.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Frog 1.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\frog 1.bmp successfully (508 kB/sec - 11973 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,211)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Frog 2.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\frog 2.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Frog 2.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\frog 2.bmp successfully (601 kB/sec - 14781 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,212)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Hand.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\hand.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Hand.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\hand.bmp successfully (593 kB/sec - 13976 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,213)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Hitchcock.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\hitchcock.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Hitchcock.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\hitchcock.bmp successfully (200 kB/sec - 4504 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,214)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Leaf.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\leaf.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Leaf.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\leaf.bmp successfully (464 kB/sec - 10919 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,215)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Monkey 1.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\monkey 1.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Monkey 1.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\monkey 1.bmp successfully (725 kB/sec - 17068 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) USER lushdog
    Devil Sat 29Apr06 08:24:19 - (000005) 331 User name okay, need password.
    [2] Sat 29Apr06 08:24:19 - (000005) PASS xxxxx
    [5] Sat 29Apr06 08:24:19 - (000005) User LUSHDOG logged in
    Devil Sat 29Apr06 08:24:19 - (000005) 230 User logged in, proceed.
    [2] Sat 29Apr06 08:24:19 - (000005) OPTS utf8 on
    Devil Sat 29Apr06 08:24:19 - (000005) 501 Invalid option.
    [2] Sat 29Apr06 08:24:19 - (000005) PWD
    Devil Sat 29Apr06 08:24:19 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:19 - (000005) CWD /
    Devil Sat 29Apr06 08:24:19 - (000005) 250 Directory changed to /
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,216)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Monkey 2.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\monkey 2.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Monkey 2.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\monkey 2.bmp successfully (713 kB/sec - 16798 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,217)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Moon.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\moon.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Moon.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\moon.bmp successfully (479 kB/sec - 10795 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,218)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Owl.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\owl.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Owl.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\owl.bmp successfully (689 kB/sec - 19051 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,208)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Party Hat.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\party hat.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Party Hat.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\party hat.bmp successfully (376 kB/sec - 8465 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,209)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Penguin.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\penguin.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Penguin.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\penguin.bmp successfully (678 kB/sec - 15972 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,210)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Rabbit.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\rabbit.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Rabbit.bmp.
    [4] Sat 29Apr06 08:24:19 - (000005) Received file e:\matt's folder\rabbit.bmp successfully (569 kB/sec - 13992 Bytes)
    Devil Sat 29Apr06 08:24:19 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:19 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:19 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:19 - (000005) PASV
    Devil Sat 29Apr06 08:24:19 - (000005) 227 Entering Passive Mode (218,147,194,153,7,211)
    [2] Sat 29Apr06 08:24:19 - (000005) STOR Rose.bmp
    [4] Sat 29Apr06 08:24:19 - (000005) Receiving file e:\matt's folder\rose.bmp
    Devil Sat 29Apr06 08:24:19 - (000005) 150 Opening BINARY mode data connection for Rose.bmp.
    [4] Sat 29Apr06 08:24:20 - (000005) Received file e:\matt's folder\rose.bmp successfully (747 kB/sec - 17590 Bytes)
    Devil Sat 29Apr06 08:24:20 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:20 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:20 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:20 - (000005) PASV
    Devil Sat 29Apr06 08:24:20 - (000005) 227 Entering Passive Mode (218,147,194,153,7,212)
    [2] Sat 29Apr06 08:24:20 - (000005) STOR Shamrock.bmp
    [4] Sat 29Apr06 08:24:20 - (000005) Receiving file e:\matt's folder\shamrock.bmp
    Devil Sat 29Apr06 08:24:20 - (000005) 150 Opening BINARY mode data connection for Shamrock.bmp.
    [4] Sat 29Apr06 08:24:20 - (000005) Received file e:\matt's folder\shamrock.bmp successfully (633 kB/sec - 14900 Bytes)
    [6] Sat 29Apr06 08:24:20 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:20 - (000005) USER lushdog
    Devil Sat 29Apr06 08:24:20 - (000005) 331 User name okay, need password.
    [2] Sat 29Apr06 08:24:20 - (000005) PASS xxxxx
    [5] Sat 29Apr06 08:24:20 - (000005) User LUSHDOG logged in
    Devil Sat 29Apr06 08:24:20 - (000005) 230 User logged in, proceed.
    [2] Sat 29Apr06 08:24:20 - (000005) OPTS utf8 on
    Devil Sat 29Apr06 08:24:20 - (000005) 501 Invalid option.
    [2] Sat 29Apr06 08:24:20 - (000005) PWD
    Devil Sat 29Apr06 08:24:20 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:20 - (000005) CWD /
    Devil Sat 29Apr06 08:24:20 - (000005) 250 Directory changed to /
    [2] Sat 29Apr06 08:24:20 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:20 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:20 - (000005) PASV
    Devil Sat 29Apr06 08:24:20 - (000005) 227 Entering Passive Mode (218,147,194,153,7,213)
    [2] Sat 29Apr06 08:24:20 - (000005) STOR Sun.bmp
    [4] Sat 29Apr06 08:24:20 - (000005) Receiving file e:\matt's folder\sun.bmp
    Devil Sat 29Apr06 08:24:20 - (000005) 150 Opening BINARY mode data connection for Sun.bmp.
    [4] Sat 29Apr06 08:24:20 - (000005) Received file e:\matt's folder\sun.bmp successfully (281 kB/sec - 6041 Bytes)
    Devil Sat 29Apr06 08:24:20 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:20 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:20 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:20 - (000005) PASV
    Devil Sat 29Apr06 08:24:20 - (000005) 227 Entering Passive Mode (218,147,194,153,7,214)
    [2] Sat 29Apr06 08:24:20 - (000005) STOR Thumbs.db
    [4] Sat 29Apr06 08:24:20 - (000005) Receiving file e:\matt's folder\thumbs.db
    Devil Sat 29Apr06 08:24:20 - (000005) 150 Opening BINARY mode data connection for Thumbs.db.
    [4] Sat 29Apr06 08:24:20 - (000005) Received file e:\matt's folder\thumbs.db successfully (5593 kB/sec - 154624 Bytes)
    Devil Sat 29Apr06 08:24:20 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:20 - (000005) TYPE I
    Devil Sat 29Apr06 08:24:20 - (000005) 200 Type set to I.
    [2] Sat 29Apr06 08:24:20 - (000005) PASV
    Devil Sat 29Apr06 08:24:20 - (000005) 227 Entering Passive Mode (218,147,194,153,7,215)
    [2] Sat 29Apr06 08:24:20 - (000005) STOR Women.bmp
    [4] Sat 29Apr06 08:24:20 - (000005) Receiving file e:\matt's folder\women.bmp
    Devil Sat 29Apr06 08:24:20 - (000005) 150 Opening BINARY mode data connection for Women.bmp.
    [4] Sat 29Apr06 08:24:20 - (000005) Received file e:\matt's folder\women.bmp successfully (365 kB/sec - 9351 Bytes)
    Devil Sat 29Apr06 08:24:20 - (000005) 226 Transfer complete.
    [2] Sat 29Apr06 08:24:20 - (000005) PWD
    Devil Sat 29Apr06 08:24:20 - (000005) 257 "/" is current directory.
    [2] Sat 29Apr06 08:24:20 - (000005) QUIT
    Devil Sat 29Apr06 08:24:20 - (000005) 221 Goodbye!
    [5] Sat 29Apr06 08:24:20 - (000005) Closing connection for user LUSHDOG (00:00:02 connected)

    lushdog

    Friday, April 28, 2006 11:32 PM
  • Well, I don't know this specific app, but I do know FTP.

    Couple of intersesting things in the trace.  The app. is using passive mode FTP, which is telling the client that data port will not be the typical ftp data port as defined in the architecture.  No problem it works great.  But I never once saw a quit on any of the requests until the end.

    Couple that with the fact that all 4XX and 5XX series messages are always a host generated issue.  I believe that what could be happening is that you have reached the maximun number of sessions allowed by the host for a single username/password.  This app. is currently logging on over and over without quiting until the end.  I think that could be the issue.

     

    Monday, May 01, 2006 2:31 AM
  • Thanks JavaMan but you have me confused with the creator of this thread. I am not having any 5xx error messages, he/she is, i just put my log in there to help out :)
    Monday, May 01, 2006 2:48 AM
  • Sorry my friend, I didn't study the thread closely enough, however, your trace does show some possible issues.

    The 501 responses are telling us the server doesn't support that command, it could be removed.

    Also, it still looks like there are multiple logon attempts and sucesses to the host.  I don't believe they are needed, as there were never any quits in between successive logins.

    ciao!

    Monday, May 01, 2006 7:24 AM
  • I'm not sure what the 501 error is coming from but it happens with other ftp clients too so i'm not worried about it.

    The multiple logon attempts are what this thread is all about, myself and the thread author are noticing these in both of our apps.  I'm not sure if you are familiar with the FTPWEBREQUEST class but it is supposed to use the same connection for successive uploads, which it does, but we've noticed the multiple login attemps.  That's why i've provided this trace with the multiple logins highlighted in red so as to help the devs track down the problem.

    lushdog

    Monday, May 01, 2006 9:41 AM
  • Per the RFC it is acceptible for client applications to send the USER command multiple times to change users while keeping the connection alive.  See section 4.1.1.  As mentioned previously in the thread, the FtpWebRequest class supports connection pooling so that the connection can be kept alive.  The pooling does not currently keep track of state as to which user last authenticated on that connection because it can't gaurantee that all code running in the same AppDomain is trusted to use that connection. 

    FtpWebRequest forces the re-authentication of the user for each usage of the connection to avoid accidentally giving access to a site to someone that doesn't know the username/password.  If the server you are connecting to doesn't support the issuing of multple "USER" commands on the same connection, then you can set KeepAlive = false on the request and a new connection will be established for each request.

    As for not sending the "QUIT" command until the end, this is done on purpose as that command signals that the connection is going to be closed.  Admittedly, the REIN command could have been used in this case but is not currently supported as far as I know.  I do not know if the developer considered using REIN or not - it may or may not have been a conscious decision.

     

    Thursday, May 04, 2006 9:12 PM
  • Excellent post JonCole.

    Just for those wondering i DO NOT get the multiple login error with the Serv-U and FileZilla ftp servers.

    lushdog

    Saturday, May 06, 2006 12:36 AM
  • This is an interesting topic. I'm using FtpWebRequest to upload an amount of files and I got the same problem as the original poster after getting to around 10 files being sent in a loop - with exactly the same error message. (FTP 503 Error).

    I found that trapping for the error - alerting the user - and then contiuning anyway seems to work - I haven't so far determined whether or not the file which was being sent when the error occurs does actually get transmitted!

    The suggestion to turn OFF "Keep Alive" does resolve the problem, but it makes the entire process more slow as I assume the connection is being completely closed/reopen for each file.

    If the file which is being processed when the error happens is sent anyway, then trapping for the expected error and  continuing anyway might be a suitable workaround this problem?

     

    Monday, May 22, 2006 8:48 PM
  • I'm using Serv-U Ftp Server for testing my app and i see the multiple USER PASS calls but i do not get the 503 error.  Anyways, if you trap for the error and continue, please check the ftp server's logs to see if there is a disconnect and reconnect after the error. 

    lushdog

    Monday, May 22, 2006 11:14 PM
  • Hi folks,

    Sorry - I thought this thread died a long time ago - thanks for all your replies.  I never got to the bottom of the problem, although the theory of the host not supporting repeated authentication certainly sounds about right.  

    I had already discovered that turning off KeepAlive solved my problem, but the overhead of the FTP connection dropping and re-establishing between each file really slowed things down (unacceptably so, in this application).   So - I cheated   Wrapped the loop in a try..catch, and got the WebRequest to retry up to a maximum of three times if an error response is encountered.  Since then, it's NEVER failed on the 2nd attempt .  I hate this kind of solution - we shouldn't have to do these things, but so often when time's against you, there's no choice.

    shiggsy

    Monday, June 05, 2006 1:40 PM
  • That's too bad shiggsy.  I hope you can do me a favor, i have created another thread about this but i hope you can check to see if it acts the same for you.  If i try to create a directory on a server that already exists i get an exception and the server disconnects and then reconnects for the next file transfer/directory creation.  Could you possibly check this and see if it happens for you too. 

    Create directory1

    Create directory2

     

    Run program twice and check the server's log to see if the second time you ran the program you get disconnects/reconnects.

     

    TIA,

     

    lushdog

    Tuesday, June 06, 2006 9:16 AM
  • I was experiencing this exact same problem.  I found that if I used the same NetworkCredentials object on each request, the problem went away.

    Hope this helps.

    Metro.

    Sunday, June 11, 2006 8:30 PM
  • "I was experiencing this exact same problem."  What problem is it you are talking about.  The multiple USER/PASS commands  problem or the disconnect if directory already exists problem?

     

    TIA,

    lushdog

    Monday, June 12, 2006 1:59 AM
  • Sorry for being vague.  The problem I was experiencing was the first problem described.  The FtpWebRequest object was sending an USER command after it had already logged in when I tried to invoke a Download Method.  The FTP server was responding with a 503 Error (Bad Sequence of Commands).

    I had been creating a NetCredential object for the original file list request and each file download request.  The Ftp server generated the 503 error on the first file download request and consequently, the FtpWebRequest threw a WebException.

    Once I used the same NetCredential object for the file list and download requests, the FtpWebRequest object behaved as expected.  Namely, it didn't send additional USER commands after the first.

    Hope this helps.

    Metro.

     

    Monday, June 12, 2006 3:08 AM
  • Thanks for the awesome feedback (and possible fix). If you have time, could you check into the problem i mentioned?  I'm curious to see if others get the same results i did.

    lushdog

    Monday, June 12, 2006 4:11 AM
  • Hi Metro,

    Thanks for your posting!!!  Your tip has resolved my problem - I was also being hit with the 503 Error (Bad Sequence of Commands) error after around every 10 files or so copied.

    The first solution was to turn OFF "KeepAlive" - this worked, but slowed down the copying process dramatically.

    The second solution was to trap for the 503 Error, deal with it and then carry on - far from ideal!

    However, following your advice, I now use the following line of code BEFORE my loop which copies the files:

    Dim ftpCredentials As New System.Net.NetworkCredential(USERNAME, PASSWORD)

    Then within my loop during the copy I have adjusted the line which sets the credentials to:

    FTPRequest.Credentials = ftpCredentials

    Previously it read:

    FTPRequest.Credentials = New System.Net.NetworkCredential(USERNAME, PASSWORD)

    Thank you again for your suggestion!!!

    Regards,

    David

    Monday, June 12, 2006 8:00 PM
  • Hmm, i wonder if this will help me with my MKD problem. I'll let you know.

    lushdog

    Monday, June 12, 2006 11:12 PM
  • lushdog - I'm afraid I wasn't able to try to reproduce your problem on the same host on which I was having the original problem. It's a 3rd party FTP provider and we do not have permission to create directories - only to download.

    I did however try it on my personal web space FTP service and still could not reproduce the same problem - sorry I know this is not much use, but it does lead me to believe that it might be differences on the server, not the client code, as we all seem to be using more or less the same code.

    As for the new NetworkCredential thing, this has confused me even more!!  Although not shown in the original code I posted, I did go on to define and construct my NetworkCredential (and WebProxy) in the constructor of my FTP class and then just re-use them continually in my loop.  Unfortunately though, this did not help with my problem

    Tuesday, June 20, 2006 10:28 AM
  • Thanks for taking the time to look into it.
    My only problem is that i have the same directory create problem with Serv-U, FileZilla and Quick n' Easy FTP Server!!!

    Interesting stuff, love the FTPWEBREQUEST class though, makes life alot easier.


    lushdog
    Tuesday, June 20, 2006 10:32 AM