Incorrect retry actions after transfer connection drops because server reports too long file size #1045

Waynezhi · 2022-11-15T18:07:47Z

FTP Server OS: Apache FtpServer

Client Computer OS: Ubuntu (amazon linux 2)

FluentFTP Version: 42.0

Framework: .NET 6

It is working very few time under Ubuntu, but under Windows I got a file with double or 3x size.

Logs :


# AutoConnect()

# AutoDetect(True, False)

# ConnectAsync()
Status:   FluentFTP 42.0.0.0
Status:   Connecting to *.*.*.*:21
Status:   Waiting for a response
Response: 220 Service ready for new user.
Command:  AUTH TLS
Status:   Waiting for response to: AUTH TLS
Response: 431 Service is unavailable.
Command:  USER ****
Status:   Waiting for response to: USER ****
Response: 331 User name okay, need password for ****.
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed.
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extensions supported
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: LANG en;zh-tw;ja;is
Response: MLST Size;Modify;Type;Perm
Response: AUTH SSL
Response: AUTH TLS
Response: MODE Z
Response: UTF8
Response: TVFS
Response: MD5
Response: MMD5
Response: MFMT
Response: 211 End
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer
Status:   Listing parser set to: Machine

# GetFileSize("****.txt.gz", -1)
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 213 85049263

# GetModifiedTime("****.txt.gz")
Command:  MDTM ****.txt.gz
Status:   Waiting for response to: MDTM ****.txt.gz
Response: 213 20221115094042.667
Downloading file to:

# DownloadFile("/tmp/tmp9CCdaq.tmp", "****.txt.gz", Resume, Retry)

# GetFileSize("****.txt.gz", -1)
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 213 85049263

# OpenRead("****.txt.gz", Binary, 0, 85049263)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStreamAsync(PASV, "RETR ****.txt.gz", 0)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (*,*,*,*,181,29)
Status:   Connecting to *.*.*.*:46365
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.

Status:   Disposing FtpSocketStream...

# OpenRead("****.txt.gz", Binary, 74993893, 0)

# GetFileSize("****.txt.gz", -1)
Status:   Socket has stale data - prior to command execution
Status:   The stale data was:
Stale:    226 Transfer complete.
Status:   Closing stream because of stale data
Status:   Disposing FtpSocketStream...

# ConnectAsync()
Status:   FluentFTP 42.0.0.0
Status:   Connecting to *.*.*.*:21
Status:   Waiting for a response
Response: 220 Service ready for new user.
Command:  USER ****
Status:   Waiting for response to: USER ****
Response: 331 User name okay, need password for ****.
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed.
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extensions supported
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: LANG en;zh-tw;ja;is
Response: MLST Size;Modify;Type;Perm
Response: AUTH SSL
Response: AUTH TLS
Response: MODE Z
Response: UTF8
Response: TVFS
Response: MD5
Response: MMD5
Response: MFMT
Response: 211 End
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer
Status:   Listing parser set to: Machine
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 213 85049263
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStreamAsync(PASV, "RETR ****.txt.gz", 74993893)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (*,*,*,*,181,11)
Status:   Connecting to *.*.*.*:46347
Command:  REST 74993893
Status:   Waiting for response to: REST 74993893
Response: 350 Restarting at 74993893. Send STORE or RETRIEVE to initiate transfer.
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.

Status:   Disposing FtpSocketStream...

# OpenRead("****.txt.gz", Binary, 149987786, 0)

# GetFileSize("****.txt.gz", -1)
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 226 Transfer complete.

# OpenPassiveDataStreamAsync(PASV, "RETR ****.txt.gz", 149987786)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 213 85049263
Status:   Disposing FtpSocketStream...

# Dispose()
Status:   Disposing FtpClient object...
Status:   Disposing FtpSocketStream...
Unhandled exception. FluentFTP.FtpException: Error while downloading the file from the server. See InnerException for more info.
 ---> FluentFTP.FtpException: Malformed PASV response: 85049263
   at FluentFTP.Client.BaseClient.BaseFtpClient.GetPassivePort(FtpDataConnectionType type, FtpReply reply, String& host, Int32& port)
   at FluentFTP.AsyncFtpClient.OpenPassiveDataStreamAsync(FtpDataConnectionType type, String command, Int64 restart, CancellationToken token)
   at FluentFTP.AsyncFtpClient.OpenDataStreamAsync(String command, Int64 restart, CancellationToken token)
   at FluentFTP.AsyncFtpClient.OpenRead(String path, FtpDataType type, Int64 restart, Int64 fileLen, CancellationToken token)
   at FluentFTP.AsyncFtpClient.ResumeDownloadAsync(String remotePath, Stream downStream, Int64 offset, IOException ex, CancellationToken token)
   at FluentFTP.AsyncFtpClient.DownloadFileInternalAsync(String localPath, String remotePath, Stream outStream, Int64 restartPosition, IProgress`1 progress, CancellationToken token, FtpProgress metaProgress, Int64 knownFileSize, Boolean isAppend)
   --- End of inner exception stack trace ---
   at FluentFTP.AsyncFtpClient.DownloadFileInternalAsync(String localPath, String remotePath, Stream outStream, Int64 restartPosition, IProgress`1 progress, CancellationToken token, FtpProgress metaProgress, Int64 knownFileSize, Boolean isAppend)
   at FluentFTP.AsyncFtpClient.DownloadFileToFileAsync(String localPath, String remotePath, FtpLocalExists existsMode, FtpVerify verifyOptions, IProgress`1 progress, CancellationToken token, FtpProgress metaProgress)
   at FluentFTP.AsyncFtpClient.DownloadFile(String localPath, String remotePath, FtpLocalExists existsMode, FtpVerify verifyOptions, IProgress`1 progress, CancellationToken token)

The text was updated successfully, but these errors were encountered:

FanDjango · 2022-11-15T18:49:40Z

I can tell you what is happening:

# OpenPassiveDataStreamAsync(PASV, "RETR ****.txt.gz", 0)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (*,*,*,*,181,29)
Status:   Connecting to *.*.*.*:46365
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.

Status:   Disposing FtpSocketStream...

# OpenRead("****.txt.gz", Binary, 74993893, 0)

# GetFileSize("****.txt.gz", -1)
Status:   Socket has stale data - prior to command execution
Status:   The stale data was:
Stale:    226 Transfer complete.
Status:   Closing stream because of stale data
Status:   Disposing FtpSocketStream...

# ConnectAsync()
Status:   FluentFTP 42.0.0.0
Status:   Connecting to *.*.*.*:21

This is the first transfer attempt. It fails, then detects stale data which causes a re-connect, the subsequent retry again fails, then reads stale data which came too late to be identified as being stale "226 Transfer complete" and from that point onwards a number of subsequent things go wrong.

But why does the first download simply stop/die?

Here are some ideas:

lets have a look at the server logs, if possible.
for debugging this problem, don't code resume, don't use retry, it just clouds up the issue.
if it possible for you, try sync instead of async to see if that isolates the problem

Could you post the source code - what is the client config?

Once we find out more, lets change the title of this issue, as it is misleading.

Waynezhi · 2022-11-15T21:35:20Z

Sorry, no access to server logs, I changed download call without resume, and tried with sync call with FtpClient, nothing changed, I was wondering why the first try failed too, the server disconnected the client every x seconds ?

here is the code snippet:

using (var ftpClient = new AsyncFtpClient(ftpHost, credentials))
{
  ftpClient.Config.LogToConsole = true;
  await ftpClient.Connect();

  var progress = new Progress<FtpProgress>(p =>
  {  
	Console.WriteLine("{0} transferred", p.TransferredBytes);
  );

  var path = Path.GetTempFileName();
  await ftpClient.DownloadFile(path, ftpPath, progress: progress, existsMode: FtpLocalExists.Overwrite);

  await ftpClient.Disconnect();
}

and the logs:

# ConnectAsync()
Status:   FluentFTP 42.0.0.0
Status:   Connecting to *.*.*.*:21
Status:   Waiting for a response
Response: 220 Service ready for new user.
Command:  USER ****
Status:   Waiting for response to: USER ****
Response: 331 User name okay, need password for ****.
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed.
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extensions supported
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: LANG en;zh-tw;ja;is
Response: MLST Size;Modify;Type;Perm
Response: AUTH SSL
Response: AUTH TLS
Response: MODE Z
Response: UTF8
Response: TVFS
Response: MD5
Response: MMD5
Response: MFMT
Response: 211 End
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer
Status:   Listing parser set to: Machine

# DownloadFile("/tmp/tmpA0SYRR.tmp", "****.txt.gz", Overwrite, None)

# GetFileSize("****.txt.gz", -1)
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 213 85049263

# OpenRead("****.txt.gz", Binary, 0, 85049263)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStreamAsync(AutoPassive, "RETR ****.txt.gz", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||46068|)
Status:   Connecting to *.*.*.*:46068
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.
69.0 MB transferred
Status:   Disposing FtpSocketStream...

# OpenRead("****.txt.gz", Binary, 74993893, 0)

# GetFileSize("****.txt.gz", -1)
Status:   Socket has stale data - prior to command execution
Status:   The stale data was:
Stale:    226 Transfer complete.
Status:   Closing stream because of stale data
Status:   Disposing FtpSocketStream...

# ConnectAsync()
Status:   FluentFTP 42.0.0.0
Status:   Connecting to *.*.*.*:21
Status:   Waiting for a response
Response: 220 Service ready for new user.
Command:  USER ****
Status:   Waiting for response to: USER ****
Response: 331 User name okay, need password for ****.
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed.
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extensions supported
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: LANG en;zh-tw;ja;is
Response: MLST Size;Modify;Type;Perm
Response: AUTH SSL
Response: AUTH TLS
Response: MODE Z
Response: UTF8
Response: TVFS
Response: MD5
Response: MMD5
Response: MFMT
Response: 211 End
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer
Status:   Listing parser set to: Machine
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 213 85049263
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStreamAsync(AutoPassive, "RETR ****.txt.gz", 74993893)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||46088|)
Status:   Connecting to *.*.*.*:46088
Command:  REST 74993893
Status:   Waiting for response to: REST 74993893
Response: 350 Restarting at 74993893. Send STORE or RETRIEVE to initiate transfer.
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.
138.0 MB transferred
142.1 MB transferred
Status:   Disposing FtpSocketStream...

# OpenRead("****.txt.gz", Binary, 149987786, 0)

# GetFileSize("****.txt.gz", -1)
Status:   Testing connectivity using Socket.Poll()...
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 226 Transfer complete.

# OpenPassiveDataStreamAsync(AutoPassive, "RETR ****.txt.gz", 149987786)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 213 85049263
Status:   Disposing FtpSocketStream...

# Dispose()
Status:   Disposing FtpClient object...
Status:   Disposing FtpSocketStream...
Unhandled exception. FluentFTP.FtpException: Error while downloading the file from the server. See InnerException for more info.
 ---> FluentFTP.FtpException: Failed to get the EPSV port from: 85049263
   at FluentFTP.Client.BaseClient.BaseFtpClient.GetEnhancedPassivePort(FtpReply reply, String& host, Int32& port)
   at FluentFTP.AsyncFtpClient.OpenPassiveDataStreamAsync(FtpDataConnectionType type, String command, Int64 restart, CancellationToken token)
   at FluentFTP.AsyncFtpClient.OpenDataStreamAsync(String command, Int64 restart, CancellationToken token)
   at FluentFTP.AsyncFtpClient.OpenRead(String path, FtpDataType type, Int64 restart, Int64 fileLen, CancellationToken token)
   at FluentFTP.AsyncFtpClient.ResumeDownloadAsync(String remotePath, Stream downStream, Int64 offset, IOException ex, CancellationToken token)
   at FluentFTP.AsyncFtpClient.DownloadFileInternalAsync(String localPath, String remotePath, Stream outStream, Int64 restartPosition, IProgress`1 progress, CancellationToken token, FtpProgress metaProgress, Int64 knownFileSize, Boolean isAppend)
   --- End of inner exception stack trace ---
   at FluentFTP.AsyncFtpClient.DownloadFileInternalAsync(String localPath, String remotePath, Stream outStream, Int64 restartPosition, IProgress`1 progress, CancellationToken token, FtpProgress metaProgress, Int64 knownFileSize, Boolean isAppend)
   at FluentFTP.AsyncFtpClient.DownloadFileToFileAsync(String localPath, String remotePath, FtpLocalExists existsMode, FtpVerify verifyOptions, IProgress`1 progress, CancellationToken token, FtpProgress metaProgress)
   at FluentFTP.AsyncFtpClient.DownloadFile(String localPath, String remotePath, FtpLocalExists existsMode, FtpVerify verifyOptions, IProgress`1 progress, CancellationToken token)

FanDjango · 2022-11-15T22:18:54Z

Ok, I will try your code.

Waynezhi · 2022-11-16T08:52:37Z

another strange thing is the SIZE command returned 85049263, but we got more from the server, first disconnecting after 79MB, second one after 140 MB.

under Windows, it is different after 142.1 MB transferred Status: Disposing FtpSocketStream..., here is the logs:

# OpenRead("****.txt.gz", Binary, 149987786, 0)

# GetFileSize("****.txt.gz")
Status:   Socket has stale data - prior to command execution
Status:   The stale data was:
Stale:    226 Transfer complete.
Status:   Closing stream because of stale data
Status:   Disposing FtpSocketStream...

# Connect()
Status:   FluentFTP 42.0.0.0
Status:   Connecting to *.*.*.*:21
Status:   Waiting for a response
Response: 220 Service ready for new user.
Command:  USER ****
Status:   Waiting for response to: USER ****
Response: 331 User name okay, need password for ****.
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed.
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extensions supported
Response: SIZE
Response: MDTM
Response: REST STREAM
Response: LANG en;zh-tw;ja;is
Response: MLST Size;Modify;Type;Perm
Response: AUTH SSL
Response: AUTH TLS
Response: MODE Z
Response: UTF8
Response: TVFS
Response: MD5
Response: MMD5
Response: MFMT
Response: 211 End
Status:   Text encoding: System.Text.UTF8Encoding+UTF8EncodingSealed
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer
Status:   Listing parser set to: Machine
Command:  SIZE ****.txt.gz
Status:   Waiting for response to: SIZE ****.txt.gz
Response: 213 85049263
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStream(PASV, "RETR ****.txt.gz", 149987786)
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (35,245,8,99,165,187)
Status:   Connecting to *.*.*.*:42427
Command:  REST 149987786
Status:   Waiting for response to: REST 149987786
Response: 350 Restarting at 149987786. Send STORE or RETRIEVE to initiate transfer.
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.
Status:   Downloaded 149987786 bytes
Status:   Disposing FtpSocketStream...
Status:   Waiting for response to: *DOWNLOAD*
Response: 551 Data transfer failed.
Status:   Failed to download file.
Command:  QUIT
Status:   Waiting for response to: QUIT
Response: 221 Goodbye.
Status:   Disposing FtpSocketStream...

# Dispose()
Status:   Disposing FtpClient object...
Status:   Disposing FtpSocketStream...

FanDjango · 2022-11-16T12:55:14Z

another strange thing is the SIZE command returned 85049263, but we got more from the server, first disconnecting after 79MB, second one after 140 MB.

In my opinion there is a bug in the logic that continues the download after a failure.

So two problems exist:

Why does it fail ?
Why does the (retries) mechanism use wrong offsets etc.

Let's concentrate on number 1 for a moment:

You cannot get the server log. Ok.

You want to transfer about 85MB. How long a time passes until the first fail?

It is this part that interests me:

# OpenRead("****.txt.gz", Binary, 0, 85049263)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStreamAsync(AutoPassive, "RETR ****.txt.gz", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||46068|)
Status:   Connecting to *.*.*.*:46068
Command:  RETR ****.txt.gz
Status:   Waiting for response to: RETR ****.txt.gz
Response: 150 Getting data connection.
69.0 MB transferred
Status:   Disposing FtpSocketStream...

What time passes from 150 Getting data connection. to the Status: Disposing FtpSocketStream?

Can you Wireshark trace the transfer?

#2: The retry mechanism - which is using a reconnect and then a wrong size/offset. We will be investigating that.

Waynezhi · 2022-11-16T13:38:55Z

the duration depends on the network, it was taking about 1 minute to have 70 MB transferred and then transfer complete, I tried with other files in the same ftp server, only success with a file of 3.5 MB, but downloaded almost double size (6.4 MB).

FanDjango · 2022-11-16T19:55:36Z

It will take some time to try to simulate this. Please stand by.

FanDjango · 2022-11-17T11:07:23Z

Ok, using your code snippet - I am transfering a big file. If the transfer runs well, it finishes ok:

1073676288 transferred
1073741824 transferred
Status:   Downloaded 1073741824 bytes
Status:   Disposing FtpSocketStream...
1073741824 transferred
Status:   Waiting for response to: *DOWNLOAD*
Status:   Testing connectivity using Socket.Poll()...
Response: 226 Transfer complete
Command:  QUIT
Status:   Waiting for response to: QUIT
Response: 221 Goodbye.
Status:   Disposing FtpSocketStream...

# Dispose()
Status:   Disposing FtpClient object...
Status:   Disposing FtpSocketStream...
Finished

If I artificially "fail" the transfer in the middle, the resume logic takes over and tries to continue the download. I have not tested that yet to see if it would work.

Looking at your logs, I am surprised that the resume logic immediately encounters "stale data", a 226 Transfer complete message sitting there.

 OpenRead("****.txt.gz", Binary, 149987786, 0)

# GetFileSize("****.txt.gz")
Status:   Socket has stale data - prior to command execution
Status:   The stale data was:
Stale:    226 Transfer complete.
Status:   Closing stream because of stale data
Status:   Disposing FtpSocketStream...
...
...
...

For the moment, please disregard anything that comes after that first failure, those are just consequential errors.

The server drops the data connection some time in the middle, but also sends 226 Transfer complete? That's interesting.

Are you able to test something if I create a special branch with some debugging code for you?

Waynezhi · 2022-11-17T14:21:22Z

Sure I can do some tests with you.

Today I create a another code with old simple FtpWebRequest, strangely it is working, I checked the downloaded file size which is not the one returned by ftp server (76039496 instead of 85049263), here is the code, hope to help you

string fileName = Path.GetTempFileName();

var requestFileDownload = (FtpWebRequest)WebRequest.Create(ftpUrl);
requestFileDownload.Credentials = credentials;
requestFileDownload.Method = WebRequestMethods.Ftp.DownloadFile;
var responseFileDownload = (FtpWebResponse)requestFileDownload.GetResponse();
var responseStream = responseFileDownload.GetResponseStream();

Console.WriteLine("Writing to {0}", fileName);
var fileStream = new FileStream(fileName, FileMode.Create, FileAccess.ReadWrite, FileShare.ReadWrite, bufferSize: 4096, useAsync: true);

int Length = 4096; // size of file 4MB Max only
var buffer = new Byte[Length];
int bytesRead = await responseStream.ReadAsync(buffer, 0, Length);
int fileLen = 0, lastTransferred = 0;
while (bytesRead > 0)
{
    fileLen += bytesRead;
    await fileStream.WriteAsync(buffer, 0, bytesRead);
    if (fileLen > lastTransferred + 1024 * 1024 * 10)
    {
        lastTransferred = fileLen;
        Console.WriteLine("{0} transferred", lastTransferred);
    }
    //bytesRead = responseStream.Read(buffer, 0, Length);
    bytesRead = await responseStream.ReadAsync(buffer, 0, Length); // Read file using await keyword 
}
Console.WriteLine("{0} transferred totally", fileLen);

responseStream.Close();
fileStream.Close();

logs extracted from Wireshark:

Response: 220 Service ready for new user.
Request: USER ****
Response: 331 User name okay, need password for ****.
Request: PASS ****
Response: 230 User logged in, proceed.
Request: OPTS utf8 on
Response: 200 Command OPTS okay.
Request: PWD
Response: 257 /" is current directory."
Request: TYPE I
Response: 200 Command TYPE okay.
Request: PASV
Response: 227 Entering Passive Mode (*,*,*,*,165,212)
Request: RETR ****.txt.gz
Response: 150 Getting data connection.
Response: 226 Transfer complete.
Request: QUIT
Response: 221 Goodbye.

FanDjango · 2022-11-17T15:11:06Z

Is that Wireshark extract from the FtpWebRequest or from FluentFtp?

Waynezhi · 2022-11-17T15:12:01Z

from FtpWebRequest, means that I got smaller size file than the server.

FanDjango · 2022-11-17T15:12:55Z

I would be happy for the FluentFTP Wireshark trace :-)

Waynezhi · 2022-11-21T17:26:02Z

hello, should I give you some additional information or not ? @FanDjango

FanDjango · 2022-11-21T18:02:12Z

I would be happy for the FluentFTP Wireshark trace :-)

Hi, thank you. Yes. Can you take a wireshark trace of the Fluentftp failure?

Waynezhi · 2022-11-21T20:33:17Z

I would be happy for the FluentFTP Wireshark trace :-)

Hi, thank you. Yes. Can you take a wireshark trace of the Fluentftp failure?

Response: 220 Service ready for new user.
Request: AUTH TLS
Response: 431 Service is unavailable.
Request: USER ****
Response: 331 User name okay, need password for ****.
Request: PASS ****
Response: 230 User logged in, proceed.
Request: FEAT
Response: 211-Extensions supported
Request: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Request: SYST
Response: 215 UNIX Type: Apache FtpServer
Request: SIZE ****.txt.gz
Response: 213 86204746
Request: TYPE I
Response: 200 Command TYPE okay.
Request: PASV
Response: 227 Entering Passive Mode (*,*,*,*,164,183)
Request: RETR ****.txt.gz
Response: 150 Getting data connection.
Response: 226 Transfer complete.
Response: 220 Service ready for new user.
Request: USER ****
Response: 331 User name okay, need password for ****.
Request: PASS ****
Response: 230 User logged in, proceed.
Request: FEAT
Response: 211-Extensions supported
Request: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Request: SYST
Response: 215 UNIX Type: Apache FtpServer
Request: SIZE ****.txt.gz
Response: 213 86204746
Request: TYPE I
Response: 200 Command TYPE okay.
Request: PASV
Response: 227 Entering Passive Mode (*,*,*,*,164,233)
Request: REST 75986889
Response: 350 Restarting at 75986889. Send STORE or RETRIEVE to initiate transfer.
Request: RETR ****.txt.gz
Response: 150 Getting data connection.
Response: 226 Transfer complete.
Response: 220 Service ready for new user.
Request: USER ****
Response: 331 User name okay, need password for ****.
Request: PASS ****
Response: 230 User logged in, proceed.
Request: FEAT
Response: 211-Extensions supported
Request: OPTS UTF8 ON
Response: 200 Command OPTS okay.
Request: SYST
Response: 215 UNIX Type: Apache FtpServer
Request: SIZE ****.txt.gz
Response: 213 86204746
Request: TYPE I
Response: 200 Command TYPE okay.
Request: PASV
Response: 227 Entering Passive Mode (*,*,*,*,165,30)
Request: REST 151973778
Response: 350 Restarting at 151973778. Send STORE or RETRIEVE to initiate transfer.
Request: RETR ****.txt.gz
Response: 150 Getting data connection.
Response: 551 Data transfer failed.
Request: QUIT
Response: 221 Goodbye.

FanDjango · 2022-11-21T20:44:40Z

I need to see all TCP Packets in this sequence, no editing:

Request: PASV
Response: 227 Entering Passive Mode (*,*,*,*,164,183)
Request: RETR ****.txt.gz
Response: 150 Getting data connection
<--- inside this regeion ------>
Response: 226 Transfer complete.
Response: 220 Service ready for new user.

FanDjango · 2022-11-23T19:09:58Z

I am sorry, I cannot help you. That is not what I expect when I would like to see a wireshark trace. Maybe you can find some way to debug exactly what is happening and why the connection is dropping.

Perhaps investigate NOOP and also perhaps look at polling?

Waynezhi · 2022-11-23T19:47:59Z

I don’t understand, I just do a filtering to the ftp IP address in wireshark trace, do you have a example of what is supposed to be like ?

FanDjango · 2022-11-23T21:15:43Z

Something like this:

Waynezhi · 2022-11-23T21:46:02Z

During debug, I got an error: it seems that we can not trust the returned size, since we got the EOF before the fileLen reached, and the resume job will download from the beginning, again and again.

Unexpected EOF for remote file 46428_3410024_mp.txt.gz [16028030/18009511 bytes read]

FanDjango · 2022-11-24T11:10:09Z

Also maybe the FTP server has a bug when he is serving a .gz file? Try using a different ending in the name?

Somehow we are getting closer to the reason for the problem, you need to try some things.

Waynezhi · 2022-11-24T11:14:00Z

I set to mode S, but nothing changed

ftpClient.Connect();
ftpClient.Execute("MODE S");

Command:  MODE S
Status:   Waiting for response to: MODE S
Response: 200 Command MODE okay.

there are only .gz files on the server

FanDjango · 2022-11-24T11:15:52Z

Can you execute a STAT command after the connect and see what is the current mode after connect?

FanDjango · 2022-11-24T11:17:45Z

Did I understand correctly: you cannot access the server, like to do a ls -l command?

Waynezhi · 2022-11-24T11:25:58Z

Can you execute a STAT command after the connect and see what is the current mode after connect?

STAT returned the server type and ip address like

Command:  STAT
Status:   Waiting for response to: STAT
Response: 211-Apache FtpServer
Response: Connected to ...
...

Did I understand correctly: you cannot access the server, like to do a ls -l command?

I can only access by ftp protocol

Waynezhi · 2022-11-24T11:29:29Z

If the server returned 226 Transfer complete means file has been transferred completely, no need to check about the size ? otherwise, an error code should be returned

FanDjango · 2022-11-24T11:35:18Z

That would be one possible solution. Also I am thinking about "readToEnd" as an option. I will work on it, how long are you still available at this time?

Waynezhi · 2022-11-24T11:36:20Z

more than 4hours

FanDjango · 2022-11-24T11:43:01Z

Ok, ready for the next test, please use the same link.

Waynezhi · 2022-11-24T11:45:10Z

Ok, ready for the next test, please use the same link.

I did not see your commits in the branch, last commit was 1h ago ?

FanDjango · 2022-11-24T11:46:11Z

oops. ok, pushed.

Waynezhi · 2022-11-24T11:49:23Z

# DownloadFile("C:\Users\chnzw\AppData\Local\Temp\tmpF654.tmp", "46428_3410024_mp.txt.gz", Overwrite, None)

# GetFileSize("46428_3410024_mp.txt.gz")
Command:  SIZE 46428_3410024_mp.txt.gz
Status:   Waiting for response to: SIZE 46428_3410024_mp.txt.gz
Response: 213 17782043

# OpenRead("46428_3410024_mp.txt.gz", Binary, 0, 17782043)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStream(AutoPassive, "RETR 46428_3410024_mp.txt.gz", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||42244|)
Status:   Connecting to IP #1= ***:42244
Command:  RETR 46428_3410024_mp.txt.gz
Status:   Waiting for response to: RETR 46428_3410024_mp.txt.gz
Response: 150 Getting data connection.
2,6 MB transferred
5,1 MB transferred
7,7 MB transferred
10,3 MB transferred
12,8 MB transferred
Status:   IOException coming: False 15823243 17782043 0
Status:   IOException: Unexpected EOF for remote file 46428_3410024_mp.txt.gz [15823243/17782043 bytes read], attempting resume
Status:   Waiting for response to: *IOException*
Status:   Testing connectivity using Socket.Poll()...
Response: 226 Transfer complete.
Status:   Downloaded 15823243 bytes
Status:   Disposing FtpSocketStream(data connection)
15,1 MB transferred
Status:   Waiting for response to: *DOWNLOAD*
Status:   Disposing FtpSocketStream(data connection)
Status:   IOException for file C:\Users\chnzw\AppData\Local\Temp\tmpF654.tmp : Unable to read data from the transport connection: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond..
Status:   Failed to download file.
Status:   Testing connectivity using Socket.Poll()...
Command:  QUIT
Status:   Waiting for response to: QUIT
Response: 221 Goodbye.
Status:   Disposing FtpSocketStream(control connection)

# Dispose()
Status:   Disposing FtpClient object...
Status:   Disposing FtpSocketStream(control connection)

FanDjango · 2022-11-24T11:50:30Z

Ok, small problem, I must solve.

FanDjango · 2022-11-24T11:55:50Z

Next try, please.

Waynezhi · 2022-11-24T12:02:27Z

working now, get correct file size, big thanks @FanDjango !

# DownloadFile("C:\Users\chnzw\AppData\Local\Temp\tmp24B7.tmp", "46428_3410024_mp.txt.gz", Overwrite, None)

# GetFileSize("46428_3410024_mp.txt.gz")
Command:  SIZE 46428_3410024_mp.txt.gz
Status:   Waiting for response to: SIZE 46428_3410024_mp.txt.gz
Response: 213 17782043

# OpenRead("46428_3410024_mp.txt.gz", Binary, 0, 17782043)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay.

# OpenPassiveDataStream(AutoPassive, "RETR 46428_3410024_mp.txt.gz", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||42184|)
Status:   Connecting to IP #1= ***:42184
Command:  RETR 46428_3410024_mp.txt.gz
Status:   Waiting for response to: RETR 46428_3410024_mp.txt.gz
Response: 150 Getting data connection.
2,6 MB transferred
5,1 MB transferred
7,7 MB transferred
10,3 MB transferred
12,8 MB transferred
Status:   IOException coming: False 15823243 17782043 0
Status:   IOException: Unexpected EOF for remote file 46428_3410024_mp.txt.gz [15823243/17782043 bytes read], attempting resume
Status:   Waiting for response to: *IOException*
Status:   Testing connectivity using Socket.Poll()...
Response: 226 Transfer complete.
Status:   Downloaded 15823243 bytes
Status:   Disposing FtpSocketStream(data connection)
15,1 MB transferred
Command:  QUIT
Status:   Waiting for response to: QUIT
Response: 221 Goodbye.
Status:   Disposing FtpSocketStream(control connection)

# Dispose()
Status:   Disposing FtpClient object...
Status:   Disposing FtpSocketStream(control connection)

FanDjango · 2022-11-24T12:03:51Z

Oooof. I will make a PR as an official fix for this strange problem and it will be in the next release.

FanDjango · 2022-11-24T22:37:01Z

Currently I am inverstigating whether this fix should be generic (for all servers) or only for the Apache FTP server.

I have implemented an Apache FTP server and I cannot reproduce this problem. I must assume that the server in this issue might be very old code?

Waynezhi · 2022-11-28T15:20:27Z

Sorry, no information about the server.
But if the server said Transfer complete, that should be reliable.

FanDjango · 2022-11-28T18:06:28Z

It also said SIZE 12345 and that was not reliable, so don't make any assumptions about what else it might be saying.

FanDjango · 2022-12-01T18:26:11Z

Released as V42.1.0

FanDjango added bug work in progress labels Nov 16, 2022

FanDjango changed the title ~~Received FluentFTP.FtpException: Malformed PASV response when downloading~~ Incorrect retry after transfer connection drops Nov 16, 2022

FanDjango changed the title ~~Incorrect retry after transfer connection drops~~ Incorrect retry actions after transfer connection drops Nov 16, 2022

FanDjango changed the title ~~Incorrect retry actions after transfer connection drops~~ Incorrect retry actions after transfer connection drops for unknown reason Nov 16, 2022

FanDjango added the response requested label Nov 18, 2022

FanDjango removed work in progress response requested labels Nov 22, 2022

FanDjango added possible bug and removed bug labels Nov 23, 2022

FanDjango added enhancement work in progress and removed possible bug labels Nov 24, 2022

FanDjango changed the title ~~Incorrect retry actions after transfer connection drops for unknown reason~~ Incorrect retry actions after transfer connection drops because server reports too long file size Nov 24, 2022

FanDjango added apache-ftp-server and removed work in progress labels Nov 24, 2022

FanDjango added the work in progress label Nov 28, 2022

FanDjango added fixed and removed work in progress labels Nov 28, 2022

FanDjango closed this as completed Nov 28, 2022

Incorrect retry actions after transfer connection drops because server reports too long file size #1045

Incorrect retry actions after transfer connection drops because server reports too long file size #1045

Comments

Waynezhi commented Nov 15, 2022

FanDjango commented Nov 15, 2022 • edited Loading

Waynezhi commented Nov 15, 2022 • edited Loading

FanDjango commented Nov 15, 2022

Waynezhi commented Nov 16, 2022 • edited Loading

FanDjango commented Nov 16, 2022

Waynezhi commented Nov 16, 2022 • edited Loading

FanDjango commented Nov 16, 2022

FanDjango commented Nov 17, 2022

Waynezhi commented Nov 17, 2022 • edited Loading

FanDjango commented Nov 17, 2022

Waynezhi commented Nov 17, 2022 • edited Loading

FanDjango commented Nov 17, 2022

Waynezhi commented Nov 21, 2022

FanDjango commented Nov 21, 2022

Waynezhi commented Nov 21, 2022

FanDjango commented Nov 21, 2022

FanDjango commented Nov 23, 2022

Waynezhi commented Nov 23, 2022

FanDjango commented Nov 23, 2022

Waynezhi commented Nov 23, 2022 • edited Loading

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 24, 2022 • edited Loading

FanDjango commented Nov 24, 2022

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 24, 2022 • edited Loading

Waynezhi commented Nov 24, 2022 • edited Loading

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 24, 2022 • edited Loading

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 24, 2022

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 24, 2022

FanDjango commented Nov 24, 2022

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 24, 2022

FanDjango commented Nov 24, 2022

FanDjango commented Nov 24, 2022

Waynezhi commented Nov 28, 2022

FanDjango commented Nov 28, 2022

FanDjango commented Dec 1, 2022

FanDjango commented Nov 15, 2022 •

edited

Loading

Waynezhi commented Nov 15, 2022 •

edited

Loading

Waynezhi commented Nov 16, 2022 •

edited

Loading

Waynezhi commented Nov 16, 2022 •

edited

Loading

Waynezhi commented Nov 17, 2022 •

edited

Loading

Waynezhi commented Nov 17, 2022 •

edited

Loading

Waynezhi commented Nov 23, 2022 •

edited

Loading

Waynezhi commented Nov 24, 2022 •

edited

Loading

Waynezhi commented Nov 24, 2022 •

edited

Loading

Waynezhi commented Nov 24, 2022 •

edited

Loading

Waynezhi commented Nov 24, 2022 •

edited

Loading