search

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.14k stars 656 forks source link

Downloading files of size 3GB by using DownloadFile freeze after first file is downloaded. #1642

Closed dblda closed 2 months ago

dblda commented 2 months ago

FTP Server OS: Windows

FTP Server Type: FubarDev.FtpServer as Windows service

Client Computer OS: Windows

FluentFTP Version: 51

Framework: 6

Trying to download many files but each time when a first file is downloaded all the process freeze. Please can you help to solve this problem? I Was trying different configuration. Files are 3gb big. File is downloaded to destination path but for some reasons client.DownloadFile do not finish execution.

Logs : Here you have logs:

2024-09-08 07:40:00.6590  DEBUG   Starting download File number 1 of 418 with name: fileparttodownload.z01 from path.
2024-09-08 07:40:00.6590  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         GetListing(null, Auto)
2024-09-08 07:40:00.6769  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  TYPE I
2024-09-08 07:40:00.6769  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: TYPE I
2024-09-08 07:40:00.6769  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 200 Binary transfer mode active. [<1ms]
2024-09-08 07:40:00.6769  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         OpenDataStreamAsync("MLSD /", 0)
2024-09-08 07:40:00.6769  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         OpenPassiveDataStreamAsync(PASV, "MLSD /", 0)
2024-09-08 07:40:00.6904  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  PASV
2024-09-08 07:40:00.6904  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: PASV
2024-09-08 07:40:00.6904  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 227 Entering Passive Mode (***,***,***,***,244,182). [1ms]
2024-09-08 07:40:00.6904  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  PASV advertised a non-routable IPAD. Using original connect dnsname/IPAD
2024-09-08 07:40:00.6904  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:62646
2024-09-08 07:40:00.6904  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  MLSD /
2024-09-08 07:40:00.6904  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: MLSD /
2024-09-08 07:40:00.6904  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 150 Opening data connection. [<1ms]
2024-09-08 07:40:00.6904  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  +---------------------------------------+
2024-09-08 07:40:00.7048  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Listing:  perm=cmpel;type=cdir;modify=20240907193916.303;create=20240524134553.802; .
2024-09-08 07:40:00.7048  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Listing:  perm=cmpfel;type=dir;modify=20240908053530.931;create=20240906183000.144; 36
2024-09-08 07:40:00.7048  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Listing:  perm=cmpfel;type=dir;modify=20240907161116.802;create=20240824161000.040; VM
2024-09-08 07:40:00.7048  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  -----------------------------------------
2024-09-08 07:40:00.7048  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Disposing(async) AsyncFtpClient.FtpSocketStream(data)
2024-09-08 07:40:00.7048  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         CloseDataStream()
2024-09-08 07:40:00.7048  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: MLSD /
2024-09-08 07:40:00.7429  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 226 Closing data connection. [44ms]
2024-09-08 07:40:00.7429  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Disposing(async) AsyncFtpClient.FtpSocketStream(data) (redundant)
2024-09-08 07:40:00.7522  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         FileExists("/36/fileparttodownload.z01")
2024-09-08 07:40:00.7522  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  SIZE /36/fileparttodownload.z01
2024-09-08 07:40:00.7522  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: SIZE /36/fileparttodownload.z01
2024-09-08 07:40:00.7522  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 213 3221225472 [1ms]
2024-09-08 07:40:00.7522  DEBUG  File exist on Ftp Server downloading...
2024-09-08 07:40:00.7522  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         DownloadFile("D:\fileparttodownload.z01", "/36/fileparttodownload.z01", Overwrite, None)
2024-09-08 07:40:00.7793  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         GetFileSize("/36/fileparttodownload.z01", -1)
2024-09-08 07:40:00.7793  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  SIZE /36/fileparttodownload.z01
2024-09-08 07:40:00.7793  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: SIZE /36/fileparttodownload.z01
2024-09-08 07:40:00.7793  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 213 3221225472 [<1ms]
2024-09-08 07:40:00.7862  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         OpenRead("/36/fileparttodownload.z01", Binary, 0, 3221225472, False)
2024-09-08 07:40:00.7862  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         OpenDataStreamAsync("RETR /36/fileparttodownload.z01", 0)
2024-09-08 07:40:00.7862  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  >         OpenPassiveDataStreamAsync(PASV, "RETR /36/fileparttodownload.z01", 0)
2024-09-08 07:40:00.7862  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  PASV
2024-09-08 07:40:00.7862  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: PASV
2024-09-08 07:40:00.7862  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 227 Entering Passive Mode (***,***,***,***,244,183). [<1ms]
2024-09-08 07:40:00.7862  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  PASV advertised a non-routable IPAD. Using original connect dnsname/IPAD
2024-09-08 07:40:00.7862  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:62647
2024-09-08 07:40:00.7862  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Command:  RETR /36/fileparttodownload.z01
2024-09-08 07:40:00.7862  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: RETR /36/fileparttodownload.z01
2024-09-08 07:40:00.8054  INFO  FTP FluentFTP.Logging.FtpLogAdapter.Log  Response: 150 Opening connection for data transfer. [11ms]
2024-09-08 07:40:00.8054  DEBUG   Download progress: 0.006103515625 ETA: 00:00:38.8211568
2024-09-08 07:40:00.8054  DEBUG   Download progress: 0.002034505208333333 ETA: 00:00:54.2332134
2024-09-08 07:40:00.8054  DEBUG   Download progress: 0.008138020833333332 ETA: 00:00:31.6451685
2024-09-08 07:40:00.8054  DEBUG   Download progress: 0.004069010416666666 ETA: 00:00:49.7717474
2024-09-08 07:40:03.5213  DEBUG   Download progress: 10.001081476608913 ETA: 00:00:24.4116113
2024-09-08 07:40:03.5213  DEBUG   Download progress: 10.00153472026189 ETA: 00:00:24.4110246
2024-09-08 07:40:03.5213  DEBUG   Download progress: 10.002803802490234 ETA: 00:00:24.4112830
2024-09-08 07:40:06.2360  DEBUG   Download progress: 20.00087474783262 ETA: 00:00:21.7085319
2024-09-08 07:40:06.2360  DEBUG   Download progress: 20.0012826671203 ETA: 00:00:21.7084036
2024-09-08 07:40:08.9508  DEBUG   Download progress: 30.001212408145268 ETA: 00:00:18.9974508
2024-09-08 07:40:11.6656  DEBUG   Download progress: 40.00163686772187 ETA: 00:00:16.2844853
2024-09-08 07:40:11.6656  DEBUG   Download progress: 40.00122894843419 ETA: 00:00:16.2847127
2024-09-08 07:40:14.3799  DEBUG   Download progress: 50.00015397866567 ETA: 00:00:13.5713225
2024-09-08 07:40:14.3799  DEBUG   Download progress: 50.00137773652872 ETA: 00:00:13.5710065
2024-09-08 07:40:17.0946  DEBUG   Download progress: 60.00007204711437 ETA: 00:00:10.8573780
2024-09-08 07:40:19.8095  DEBUG   Download progress: 70.00072101751962 ETA: 00:00:08.1430087
2024-09-08 07:40:19.8095  DEBUG   Download progress: 70.00194477538267 ETA: 00:00:08.1426864
2024-09-08 07:40:22.5241  DEBUG   Download progress: 80.00019478301206 ETA: 00:00:05.4288214
2024-09-08 07:40:25.2390  DEBUG   Download progress: 90.00011297563711 ETA: 00:00:02.7144572
2024-09-08 07:40:25.2390  DEBUG   Download progress: 90.00079284111658 ETA: 00:00:02.7142562
2024-09-08 07:40:25.2390  DEBUG   Download progress: 90.00169932842255 ETA: 00:00:02.7140040
2024-09-08 07:40:27.9535  DEBUG   Download progress: 100 ETA: 00:00:00
2024-09-08 07:40:27.9535  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Downloaded 3221225472 bytes, 27.144s, 113.2 MB/s
2024-09-08 07:40:28.0627  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Disposing(async) AsyncFtpClient.FtpSocketStream(data)
2024-09-08 07:40:28.0641  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Waiting for response to: RETR /36/fileparttodownload.z01
2024-09-08 07:45:28.0954  DEBUG  FTP FluentFTP.Logging.FtpLogAdapter.Log  Disposing(async) AsyncFtpClient.FtpSocketStream(data) (redundant)

And this is my code:

using (var client = new AsyncFtpClient(applicationSettings.FtpServerHost, user, pass))
{
    var timeOut = 300000;
    client.Port = (int)applicationSettings.FtpServerPort;
    client.Config.EncryptionMode = FtpEncryptionMode.Implicit;
    client.Config.ConnectTimeout = timeOut;
    client.Config.ReadTimeout = timeOut;
    client.Config.DataConnectionConnectTimeout = timeOut;
    client.Config.DataConnectionReadTimeout = timeOut;
    client.Config.DataConnectionType = FtpDataConnectionType.EPSV;
    client.Config.SocketKeepAlive = true;
    client.Config.NoopInterval = 15000;

    client.Config.LogToConsole = true;

    // create NLog logger
    var nlogLogger = new NLogLoggerProvider();
    // wrap with MELA ILogger
    var logger = nlogLogger.CreateLogger("FTP");
    // wrap with FtpLogAdapter
    client.Logger = new FtpLogAdapter(logger);
    // connect to the server and automatically detect working FTP settings
    await client.AutoConnect();

    int x = 0;
    _logger.Debug($"Numer of file to download: {files.Count}");
    var path = Path.Combine(applicationSettings.Base, applicationSettings.Segment1);
    var pathDestination = _configuration.GetSection("Destination").Value;
    foreach (var file in files)
    {
        ++x;
        lastLoggedPercentage = -1;
        _logger.Debug($"Staring download file {x} of {files.Count} ");

        var filePath = file.Path.Replace(path, string.Empty);
        var fileDescPath = $@"{pathDestination}{filePath}";

        _logger.Debug($"Starting download File number {x} with name: {file.Path}");
        // check if a file exists
        var list = await client.GetListing();
        if (await client.FileExists(filePath))
        {

            // Callback method that accepts a FtpProgress object

            _logger.Debug($"File exist on Ftp Server downloading...");
            var status = await client.DownloadFile(fileDescPath, filePath, FtpLocalExists.Overwrite, FtpVerify.None, progress, token);
            _logger.Debug($"Status of file download {files.Count} ");
            if (status == FtpStatus.Success)
            {
                file.Downloaded = true;
                await _repo.SaveAsync();
                var resultMessage = $"File with name: {file.Path} was downloaded to directory: {fileDescPath}";
            }
        }
        else
        {
            _logger.Error($"File {file.Path} doesn't exist.");
        }

    }
}

        static int lastLoggedPercentage = -1; // To track the last logged 10% boundary
        Progress<FtpProgress> progress = new Progress<FtpProgress>(x => {

            // When progress in unknown, -1 will be sent

            if (x.Progress < 0)
            {
                _logger.Debug("Progress is unknown");
            }
            else
            {
                // Calculate current percentage rounded down to the nearest 10
                int currentPercentage = (int)(x.Progress / 10) * 10;

                // Log only if the current percentage is different from the last logged percentage
                if (currentPercentage != lastLoggedPercentage)
                {
                    _logger.Debug($"Download progress: {x.Progress} ETA: {x.ETA}");
                    lastLoggedPercentage = currentPercentage;
                }

            }
        });
FanDjango commented 2 months ago

My first idea would be to keep the control connection open by using NOOPs. Sadly, your log ends too early, I would have liked to see the way it continues concerning the control connection and final disposal.

FanDjango commented 2 months ago

Sadly, your log ends too early, I would have liked to see the way it continues concerning the control connection and final disposal.

Always people don't provide the complete sequence, also the initial connection etc. Always somehow redacted logs.

To be honest, either you are capable enough to debug this yourself, or you cannot decide what to delete from the log and instead should include a complete one.

And then, no response to a support reaction. So it cannot be that urgent, also.

dblda commented 2 months ago

Hi, I add all log. I checked what happened after several hours during that day and nothing was changed. I mean no additional logs appeared until I start trying to terminate the proces with client in terminal. So client freezes just after file is physically downloaded.

After all, an initial connection is attached.

I was thinking about using NOOPs, as you suggested but still didn’t figure it out how to do that.

FanDjango commented 2 months ago

Ok, so it is just hanging? No timeout after some time? Nothing?

For NOOP, you need 

            client.Config.Noop = true;
            client.Config.NoopInterval = 15000;
            client.Config.NoopTestConnectivity = false;
dblda commented 2 months ago

Yes, was just hanging. It started to work continuously. the solution was to add Noop configuration and remove all other timeouts previously configured. Thanks you for your help.

FanDjango commented 2 months ago

Do you want to investigate why the process was hanging? Or satisfied and we close this?