robinrodricks / FluentFTP

An FTP and FTPS client for .NET & .NET Standard, optimized for speed. Provides extensive FTP commands, File uploads/downloads, SSL/TLS connections, Automatic directory listing parsing, File hashing/checksums, File permissions/CHMOD, FTP proxies, FXP support, UTF-8 support, Async/await support, Powershell support and more. Written entirely in C#.
MIT License
3.13k stars 655 forks source link

download file fail with 51.1.0 works in 48.0.0 #1670

Open lukechenw opened 2 weeks ago

lukechenw commented 2 weeks ago

FTP Server OS: Unix

FTP Server Type: Apache FtpServer

Client Computer OS: Windows

FluentFTP Version: 51.1.0

Framework: .NET 4

download file fail using the DownloadFile method. Same code works with version 49.0.1 Found after upgrading FluentFTP from 48.0.0 to 51.1.0

using (var ftp = new AsyncFtpClient(host, user, pass))
{
    await ftp.Connect(m_cts.Token);

    // define the progress tracking callback
    var progress = new Progress<FtpProgress>(p =>
    {
        if (m_cts.IsCancellationRequested)
        {
            return;
        }

        SetMessage(string.Format("{0}MB({1})", p.TransferredBytes / 1024 / 1024, p.TransferSpeedToString()));
    });

    // download a file and ensure the local directory is created
    var status = await ftp.DownloadFile(localPath, remotePath, FtpLocalExists.Overwrite, FtpVerify.Retry, progress, m_cts.Token);
    if (status == FtpStatus.Success)
    {
        m_cts?.Cancel();

        var destFileName = Path.Combine(IMGPath, Path.GetFileName(localPath));
        if (File.Exists(destFileName))
            File.Delete(destFileName);

        File.Move(localPath, destFileName);
    }
    else
    {
        SetMessage("download fail", true);
    }
}

Logs : Logs for 48.0.0:

2024-10-24 14:58:28.1806 | >         Connect(False) 
2024-10-24 14:58:28.1956 | Connecting to IP #1= ***:21 
2024-10-24 14:58:28.2332 | Response: 220 Service ready for new user. [739182.291d] 
2024-10-24 14:58:28.2422 | Command:  USER *** 
2024-10-24 14:58:28.2632 | Response: 331 User name okay, need password for ***. [17ms] 
2024-10-24 14:58:28.2632 | Command:  PASS *** 
2024-10-24 14:58:28.2772 | Response: 230 User logged in, proceed. [11ms] 
2024-10-24 14:58:28.2772 | Command:  FEAT 
2024-10-24 14:58:28.3172 | Response: 211 End [36ms] 
2024-10-24 14:58:28.3172 | Text encoding: System.Text.UTF8Encoding 
2024-10-24 14:58:28.3172 | Command:  OPTS UTF8 ON 
2024-10-24 14:58:28.3172 | Response: 200 Command OPTS okay. [3ms] 
2024-10-24 14:58:28.3172 | Command:  SYST 
2024-10-24 14:58:28.3332 | Response: 215 UNIX Type: Apache FtpServer [5ms] 
2024-10-24 14:58:28.3332 | Detected FTP server: Apache 
2024-10-24 14:58:28.3332 | Command:  PWD 
2024-10-24 14:58:28.3332 | Response: 257 "/" is current directory. [6ms] 
2024-10-24 14:58:30.3334 | >         DownloadFile("IMGDown\aaa.img.gz", "PRD80000000000000002587611", Overwrite, Retry) 
2024-10-24 14:58:30.3334 | >         GetFileSize("PRD80000000000000002587611", -1) 
2024-10-24 14:58:30.3334 | Command:  SIZE PRD80000000000000002587611 
2024-10-24 14:58:30.3444 | Response: 213 184 [1ms] 
2024-10-24 14:58:30.3444 | >         OpenRead("PRD80000000000000002587611", Binary, 0, 184) 
2024-10-24 14:58:30.3444 | Command:  TYPE I 
2024-10-24 14:58:30.3444 | Response: 200 Command TYPE okay. [5ms] 
2024-10-24 14:58:30.3444 | >         OpenDataStreamAsync("RETR PRD80000000000000002587611", 0) 
2024-10-24 14:58:30.3444 | >         OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0) 
2024-10-24 14:58:30.3444 | Command:  EPSV 
2024-10-24 14:58:30.3674 | Response: 229 Entering Passive Mode (|||59370|) [7ms] 
2024-10-24 14:58:30.3674 | Connecting to IP #1= ***:59370 
2024-10-24 14:58:30.3674 | Command:  RETR PRD80000000000000002587611 
2024-10-24 14:58:30.3794 | Response: 150 File status okay; about to open data connection. [9ms] 
2024-10-24 14:58:43.6421 | Download cancellation requested 
2024-10-24 14:58:43.6651 | >         Dispose() 

Logs for 51.1.0 :

2024-10-24 14:51:31.4857 | >         Connect(False) 
2024-10-24 14:51:31.5517 | Response: 220 Service ready for new user. [739182.286d] 
2024-10-24 14:51:31.5517 | Command:  USER *** 
2024-10-24 14:51:31.5747 | Response: 331 User name okay, need password for ***. [12ms] 
2024-10-24 14:51:31.5747 | Command:  PASS *** 
2024-10-24 14:51:31.5827 | Response: 230 User logged in, proceed. [5ms] 
2024-10-24 14:51:31.5827 | Command:  FEAT 
2024-10-24 14:51:31.6187 | Response: 211 End [32ms] 
2024-10-24 14:51:31.6187 | Text encoding: System.Text.UTF8Encoding 
2024-10-24 14:51:31.6187 | Command:  OPTS UTF8 ON 
2024-10-24 14:51:31.6267 | Response: 200 Command OPTS okay. [3ms] 
2024-10-24 14:51:31.6267 | Command:  SYST 
2024-10-24 14:51:31.6267 | Response: 215 UNIX Type: Apache FtpServer [6ms] 
2024-10-24 14:51:31.6267 | Detected FTP server: Apache 
2024-10-24 14:51:31.6267 | Command:  PWD 
2024-10-24 14:51:31.6267 | Response: 257 "/" is current directory. [4ms] 
2024-10-24 14:51:35.3446 | >         DownloadFile("IMGDown\aaa.img.gz", "PRD80000000000000002587611", Overwrite, Retry) 
2024-10-24 14:51:35.3506 | >         GetFileSize("PRD80000000000000002587611", -1) 
2024-10-24 14:51:35.3506 | Command:  SIZE PRD80000000000000002587611 
2024-10-24 14:51:35.3506 | Response: 213 184 [1ms] 
2024-10-24 14:51:35.3506 | >         OpenRead("PRD80000000000000002587611", Binary, 0, 184, False) 
2024-10-24 14:51:35.3506 | Command:  TYPE I 
2024-10-24 14:51:35.3636 | Response: 200 Command TYPE okay. [3ms] 
2024-10-24 14:51:35.3636 | >         OpenDataStreamAsync("RETR PRD80000000000000002587611", 0) 
2024-10-24 14:51:35.3636 | >         OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0) 
2024-10-24 14:51:35.3636 | Command:  EPSV 
2024-10-24 14:51:35.3636 | Response: 229 Entering Passive Mode (|||13656|) [5ms] 
2024-10-24 14:51:35.3786 | Command:  RETR PRD80000000000000002587611 
2024-10-24 14:51:35.3786 | Response: 150 File status okay; about to open data connection. [9ms] 
2024-10-24 14:51:35.6132 | Response: 426 Data connection error. [234ms] 
2024-10-24 14:51:35.6132 | Failed to download file. 
2024-10-24 14:51:35.6132 | Retrying to download file. 
2024-10-24 14:51:35.6132 | >         GetFileSize("PRD80000000000000002587611", -1) 
2024-10-24 14:51:35.6132 | Command:  SIZE PRD80000000000000002587611 
2024-10-24 14:51:35.6132 | Response: 213 184 [1ms] 
2024-10-24 14:51:35.6132 | >         OpenRead("PRD80000000000000002587611", Binary, 0, 184, False) 
2024-10-24 14:51:35.6132 | >         OpenDataStreamAsync("RETR PRD80000000000000002587611", 0) 
2024-10-24 14:51:35.6132 | >         OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0) 
2024-10-24 14:51:35.6132 | Command:  EPSV 
2024-10-24 14:51:35.6132 | Response: 229 Entering Passive Mode (|||12799|) [6ms] 
2024-10-24 14:51:35.6132 | Command:  RETR PRD80000000000000002587611 
2024-10-24 14:51:35.6272 | Response: 150 File status okay; about to open data connection. [8ms] 
2024-10-24 14:51:35.7102 | Response: 426 Data connection error. [82ms] 
2024-10-24 14:51:35.7102 | Failed to download file. 
2024-10-24 14:51:35.7102 | Retrying to download file. 
2024-10-24 14:51:35.7102 | >         GetFileSize("PRD80000000000000002587611", -1) 
2024-10-24 14:51:35.7102 | Command:  SIZE PRD80000000000000002587611 
2024-10-24 14:51:35.7102 | Response: 213 184 [3ms] 
2024-10-24 14:51:35.7102 | >         OpenRead("PRD80000000000000002587611", Binary, 0, 184, False) 
2024-10-24 14:51:35.7102 | >         OpenDataStreamAsync("RETR PRD80000000000000002587611", 0) 
2024-10-24 14:51:35.7102 | >         OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0) 
2024-10-24 14:51:35.7102 | Command:  EPSV 
2024-10-24 14:51:35.7102 | Response: 229 Entering Passive Mode (|||49423|) [6ms] 
2024-10-24 14:51:35.7222 | Command:  RETR PRD80000000000000002587611 
2024-10-24 14:51:35.7222 | Response: 150 File status okay; about to open data connection. [8ms] 
2024-10-24 14:51:35.8442 | Response: 426 Data connection error. [120ms] 
2024-10-24 14:51:35.8442 | Failed to download file. 
2024-10-24 14:51:35.8462 | >         Dispose() 
2024-10-24 14:51:35.8462 | >         DisposeAsync() 
2024-10-24 14:51:35.8462 | >         Disconnect() 
2024-10-24 14:51:35.8462 | Command:  QUIT 
2024-10-24 14:51:35.8462 | Response: 221 Goodbye. [4ms] >
FanDjango commented 2 weeks ago

Change both logs to include log messages with "VERBOSE" severity, please.

lukechenw commented 1 week ago

Logs for 48.0.0:

# Connect(False)
Status:   FluentFTP 48.0.0.0(.NET Framework 4.6.2)
Status:   Connecting to IP #1= ***:21
Status:   Waiting for a response
Response: 220 Service ready for new user. [739183.082d]
Command:  USER ***
Status:   Waiting for response to: USER ***
Response: 331 User name okay, need password for ***. [11ms]
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed. [5ms]
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 [35ms]
Status:   Text encoding: System.Text.UTF8Encoding
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay. [5ms]
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer [7ms]
Status:   Detected FTP server: Apache
Status:   Listing parser set to: Machine
Command:  PWD
Status:   Waiting for response to: PWD
Response: 257 "/" is current directory. [7ms]

# DownloadFile("IMGDown\aaa.img.gz", "PRD80000000000000002587611", Overwrite, Retry)

# GetFileSize("PRD80000000000000002587611", -1)
Command:  SIZE PRD80000000000000002587611
Status:   Waiting for response to: SIZE PRD80000000000000002587611
Response: 213 184 [2ms]

# OpenRead("PRD80000000000000002587611", Binary, 0, 184)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay. [5ms]

# OpenDataStreamAsync("RETR PRD80000000000000002587611", 0)

# OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||11404|) [8ms]
Status:   Connecting to IP #1= ***:11404
Command:  RETR PRD80000000000000002587611
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 150 File status okay; about to open data connection. [12ms]
“demo.exe”(CLR v4.0.30319: demo.exe): 已加载“Anonymously Hosted DynamicMethods Assembly”。
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Download cancellation requested
引发的异常:“System.Threading.Tasks.TaskCanceledException”(位于 mscorlib.dll 中)

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

Logs for 51.1.0 :

# Connect(False)
Status:   FluentFTP 51.1.0.0(.NET Framework 4.6.2) AsyncFtpClient
Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(control) IP #1 = ***:21
Status:   Waiting for a response
Response: 220 Service ready for new user. [739183.083d]
Command:  USER ***
Status:   Waiting for response to: USER ***
Response: 331 User name okay, need password for ***. [11ms]
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230 User logged in, proceed. [4ms]
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 [32ms]
Status:   Text encoding: System.Text.UTF8Encoding
Command:  OPTS UTF8 ON
Status:   Waiting for response to: OPTS UTF8 ON
Response: 200 Command OPTS okay. [4ms]
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX Type: Apache FtpServer [6ms]
Status:   Detected FTP server: Apache
Status:   Active ServerHandler is: Apache
Status:   Listing parser set to: Machine
Command:  PWD
Status:   Waiting for response to: PWD
Response: 257 "/" is current directory. [5ms]

# DownloadFile("IMGDown\aaa.img.gz", "PRD80000000000000002587611", Overwrite, Retry)

# GetFileSize("PRD80000000000000002587611", -1)
Command:  SIZE PRD80000000000000002587611
Status:   Waiting for response to: SIZE PRD80000000000000002587611
Response: 213 184 [2ms]

# OpenRead("PRD80000000000000002587611", Binary, 0, 184, False)
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command TYPE okay. [4ms]

# OpenDataStreamAsync("RETR PRD80000000000000002587611", 0)

# OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||46341|) [7ms]
Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:46341
Command:  RETR PRD80000000000000002587611
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 150 File status okay; about to open data connection. [9ms]
“demo.exe”(CLR v4.0.30319: demo.exe): 已加载“Anonymously Hosted DynamicMethods Assembly”。
Status:   Downloaded 184 bytes, 30ms, 5.9 KB/s
Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 426 Data connection error. [77ms]
Status:   Failed to download file.
Status:   Retrying to download file.

# GetFileSize("PRD80000000000000002587611", -1)
Command:  SIZE PRD80000000000000002587611
Status:   Waiting for response to: SIZE PRD80000000000000002587611
Response: 213 184 [2ms]

# OpenRead("PRD80000000000000002587611", Binary, 0, 184, False)

# OpenDataStreamAsync("RETR PRD80000000000000002587611", 0)

# OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||26841|) [7ms]
Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:26841
Command:  RETR PRD80000000000000002587611
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 150 File status okay; about to open data connection. [8ms]
Status:   Downloaded 184 bytes, 33ms, 4.9 KB/s
Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 426 Data connection error. [54ms]
Status:   Failed to download file.
Status:   Retrying to download file.

# GetFileSize("PRD80000000000000002587611", -1)
Command:  SIZE PRD80000000000000002587611
Status:   Waiting for response to: SIZE PRD80000000000000002587611
Response: 213 184 [1ms]

# OpenRead("PRD80000000000000002587611", Binary, 0, 184, False)

# OpenDataStreamAsync("RETR PRD80000000000000002587611", 0)

# OpenPassiveDataStreamAsync(AutoPassive, "RETR PRD80000000000000002587611", 0)
Command:  EPSV
Status:   Waiting for response to: EPSV
Response: 229 Entering Passive Mode (|||16553|) [8ms]
Status:   Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:16553
Command:  RETR PRD80000000000000002587611
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 150 File status okay; about to open data connection. [10ms]
Status:   Downloaded 184 bytes, 33ms, 4.9 KB/s
Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)
Status:   Waiting for response to: RETR PRD80000000000000002587611
Response: 426 Data connection error. [58ms]
Status:   Failed to download file.

# Dispose()

# DisposeAsync()
Status:   Disposing(async) AsyncFtpClient

# Disconnect()
Command:  QUIT
Status:   Waiting for response to: QUIT
Response: 221 Goodbye. [2ms]
Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(control)
Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(control) (redundant)
FanDjango commented 1 week ago

Thank you for posting a verbose log (which we always request), but why on earth did you then remove the time stamps? So I needed to go back and forth between the first log and the verbose one, what a drag, man.

Response: 150 File status okay; about to open data connection. [12ms]
“demo.exe”(CLR v4.0.30319: demo.exe): 已加载“Anonymously Hosted DynamicMethods Assembly”。
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Download cancellation requested
引发的异常:“System.Threading.Tasks.TaskCanceledException”(位于 mscorlib.dll 中)

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

In this one, who is doing a cancel???

I don`t see that "it works". The file might have been downloaded ok, but the result is not right. The new version is somewhat better in that it tells you the "426 Data connection error". The file once again probably is present (downloaded) but now at least the response from the server is being looked at.

426 Data connection error
It is considered a transient negative reply as it is considered to be a temporary condition.
It is usually sent when the data connection is unexpectedly closed before the completion
of a data transfer.
In this case, the client is encouraged to restart the FTP transaction and try again.
# GetFileSize("PRD80000000000000002587611", -1)
Command:  SIZE PRD80000000000000002587611
Status:   Waiting for response to: SIZE PRD80000000000000002587611
Response: 213 184 [2ms]

The size is 184.

Status:   Downloaded 184 bytes, 33ms, 4.9 KB/s
Status:   Disposing(async) AsyncFtpClient.FtpSocketStream(data)

We downloaded 184 and closed the connection. So phoooey.

Response: 426 Data connection error. [58ms]

Looks like the server prefers to close the connection himself and calls that a failure.

The only reason that "worked" previously is because in the old version, for some reasons, such a negative response was not reported and not acted upon. Unclean and now fixed. Sadly that means this download is thus classified as failed.

We would rather need to concentrate what the Apache file server would prefer: Should we wait for him to close the connection when the download is finished? Ignore any error messages?

I realize that it worked before. But your log doesn't really show that. It shows cancellations, exceptions etc. I see no download success message. Of course the file might be present on the disk, but how safe is the assumption that all is ok. This apache server problem had been hiding behind the old versions code until it surfaced now.

lukechenw commented 1 week ago

I cancelled the download because the file was too large(>100G)

Response: 150 File status okay; about to open data connection. [12ms]
“demo.exe”(CLR v4.0.30319: demo.exe): 已加载“Anonymously Hosted DynamicMethods Assembly”。
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Closing/Disposing FtpSocketStream(data connection)
Status:   Download cancellation requested
引发的异常:“System.Threading.Tasks.TaskCanceledException”(位于 mscorlib.dll 中)

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

On the FTP server, PRD80000000000000002587611 is a connection file ( size is 184byte ), The actual files are stored on another FTP server, and the file size >100G.

# GetFileSize("PRD80000000000000002587611", -1)
Command:  SIZE PRD80000000000000002587611
Status:   Waiting for response to: SIZE PRD80000000000000002587611
Response: 213 184 [2ms]
FanDjango commented 1 week ago

So the result of the SIZE command is a lie!

This FluentFTP version handles these things correctly. So it stops after 184 bytes. I explained that previously.

One way to handle this quickly is to provide a custom server handler and to provide

ServerHandler.AlwaysReadToEnd(...)

Perhaps, we should introduce a new download FileExists option to allow saying "AlwaysReadToEnd".