Timed out trying to read data from the socket stream

[MaxRubbel]

FTP Server OS: Uknown

FTP Server Type: drftpd / Unkown

Client Computer OS: Windows / Debian

FluentFTP Version: 50.0.1

Framework: .NET 8

Hello, I have the problem that the Asyc client times out. As soon as it fetches the list of names from the FTP. I can't explain why and I can't intercept it either. The program closes / crashes completely afterwards.

If I do the same code with the FTP client that is not Async, everything works fine.

Thanks for any help!

Logs :

[22:25:46 ERR] Error with FTP server: *** System.TimeoutException: Timed out trying to read data from the socket stream! at FluentFTP.FtpSocketStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token) at FluentFTP.FtpDataStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token) at FluentFTP.FtpSocketStream.ReadLineAsync(Encoding encoding, CancellationToken token) at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token) at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token) at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token) at FTPDownloader.FtpClientAsync.GetNames(String remotePath, CancellationToken cancellationToken) at FTPDownloader.Watcher.Execute(String host, Int32 port, FtpConfiguration configuration, CancellationToken cancellationToken)

`[22:25:12 INF] Start

# Connect(False)
Status:   FluentFTP 50.0.1.0(.NET 6.0) AsyncFtpClient
Status:   Connecting to IP #1= ***:***
Status:   Waiting for a response
Response: 220 DrFTPD+ 2.0 (+STABLE+) $Revision: 1949 $ http://drftpd.org [739033,851d]
Command:  AUTH TLS
Status:   Waiting for response to: AUTH TLS
Response: 234 AUTH TLS successful [11ms]
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 256) [150ms]
Command:  USER ***
Status:   Waiting for response to: USER ***
Response: 331 Password required for ***. [23ms]
Command:  PASS ***
Status:   Waiting for response to: PASS ***
Response: 230-
Response: 230-         Welcome to the future of FXP:ing
Response: 230-      ___      _____________  ___
Response: 230-     / _ \____/ __/_  __/ _ \/ _ \
Response: 230-    / // / __/ _/  / / / ___/ // /
Response: 230-   /____/_/ /_/   /_/ /_/  /____/
Response: 230-                   DistRibuted FTP Daemon
Response: 230-                        http://drftpd.org
Response: 230 *** logged in successfully. [13ms]
Command:  PBSZ 0
Status:   Waiting for response to: PBSZ 0
Response: 200 Command okay [20ms]
Command:  PROT P
Status:   Waiting for response to: PROT P
Response: 200 Command okay [19ms]
Command:  FEAT
Status:   Waiting for response to: FEAT
Response: 211-Extensions supported:
Response: PRET
Response: AUTH SSL
Response: PBSZ
Response: CPSV
Response: SSCN
Response: MLST type*,x.crc32*,size*,modify*,unix.owner*,unix.group*,x.slaves*,x.xfertime*
Response: CLNT
Response: NOOP
Response: 211 End [16ms]
Status:   Text encoding: System.Text.ASCIIEncoding+ASCIIEncodingSealed
Command:  SYST
Status:   Waiting for response to: SYST
Response: 215 UNIX system type. [12ms]
Status:   Active ServerHandler is: None
Status:   Listing parser set to: Machine
Command:  PWD
Status:   Waiting for response to: PWD
Response: 257 "/" is current directory [12ms]

# DirectoryExists("TEST1/TEST2")
Command:  CWD TEST1/TEST2
Status:   Waiting for response to: CWD TEST1/TEST2
Response: 250 Directory changed to /TEST1/TEST2 [862ms]
Command:  PWD
Status:   Waiting for response to: PWD
Response: 257 "/TEST1/TEST2" is current directory [19ms]
Command:  CWD /
Status:   Waiting for response to: CWD /
Response: 250 Directory changed to / [12ms]

# GetNameListing("TEST1/TEST2")
Command:  TYPE I
Status:   Waiting for response to: TYPE I
Response: 200 Command okay [50ms]

# OpenDataStreamAsync("NLST /TEST1/TEST2", 0)

# OpenPassiveDataStreamAsync(PASV, "NLST /TEST1/TEST2", 0)
Command:  PRET NLST /TEST1/TEST2
Status:   Waiting for response to: PRET NLST /TEST1/TEST2
Response: 200 OK, will use master for upcoming transfer [12ms]
Command:  PASV
Status:   Waiting for response to: PASV
Response: 227 Entering Passive Mode (194,127,172,166,178,9). [17ms]
Status:   Connecting to IP #1= ***:***
Command:  NLST /TEST1/TEST2
Status:   Waiting for response to: NLST /TEST1/TEST2
Response: 150 File status okay; about to open data connection. [12ms]
Warning:  SSL Buffering disabled because of .NET 5.0 and later
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 256) [66ms]
+---------------------------------------+
Status:   Disposing(async) FtpSocketStream(data connection of AsyncFtpClient)

# CloseDataStream()
Status:   Testing connectivity using Socket.Poll()...

# CloseDataStream()
Status:   Waiting for response to: NLST /TEST1/TEST2
Status:   Waiting for response to: NLST /TEST1/TEST2
Response: 226- [Ul: 264.4GB] [Dl: 1.5PB] [Average speed: 199.0GB]
Response: 226-      [Credits: -16.1TB] [Ratio: 1:0.0]
Response: 226 Closing data connection [32,671s]
[22:25:46 ERR] Error with FTP server: ***
System.TimeoutException: Timed out trying to read data from the socket stream!
   at FluentFTP.FtpSocketStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token)
   at FluentFTP.FtpDataStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token)
   at FluentFTP.FtpSocketStream.ReadLineAsync(Encoding encoding, CancellationToken token)
   at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token)
   at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token)
   at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token)
   at FTPDownloader.FtpClientAsync.GetNames(String remotePath, CancellationToken cancellationToken)
   at FTPDownloader.Watcher.Execute(String host, Int32 port, FtpConfiguration configuration, CancellationToken cancellationToken)

# Disconnect()
Status:   Disposing(async) FtpSocketStream(control connection of AsyncFtpClient)
Status:   AsyncFtpClient incorrectly called Close(sync)
Status:   Disposing(sync) FtpSocketStream(control connection of AsyncFtpClient)
Status:   Not sending QUIT because the connection has already been closed.

# DisposeAsync()
Status:   Disposing(async) AsyncFtpClient

# Connect(False)
Status:   FluentFTP 50.0.1.0(.NET 6.0) AsyncFtpClient
Unhandled exception. System.TimeoutException: Timed out trying to read data from the socket stream!
   at FluentFTP.FtpSocketStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token)
   at FluentFTP.FtpSocketStream.ReadLineAsync(Encoding encoding, CancellationToken token)
   at FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.GetReplyInternal(CancellationToken token, String command, Boolean exhaustNoop, Int32 timeOut, Boolean useSema)
   at FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.GetReplyInternal(CancellationToken token, String command)
   at FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.CloseDataStreamInternal(FtpDataStream stream, CancellationToken token)
   at FluentFTP.Client.BaseClient.BaseFtpClient.FluentFTP.IInternalFtpClient.CloseDataStreamInternal(FtpDataStream stream, CancellationToken token)
   at FluentFTP.FtpDataStream.CloseAsync(CancellationToken token)
   at FluentFTP.FtpSocketStream.<>c__DisplayClass77_0.<<ReadAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.<>c.<ThrowAsync>b__128_1(Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
Status:   Connecting to IP #1= ***:***
Status:   Waiting for a response
Response: 220 DrFTPD 3.2.0 https://github.com/drftpd-ng/drftpd3  [739033,852d]
Command:  AUTH TLS
Status:   Waiting for response to: AUTH TLS
Response: 234 AUTH TLS successful [44ms]
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, 44550, 255) [2,683s]
Command:  USER ***
Status:   Waiting for response to: USER ***`

[FanDjango]

Might be useful to see the async code of yours. Also a log of the successful sync operation to be able to compare the behaviour.

[MaxRubbel]

Function that calls it: IEnumerable<string> dirs; try { dirs = await ftpClient.GetNames(path, cancellationToken); } catch (FtpAuthenticationException) { _logger.LogError("Du bist beim Host {HOST} momentan gesperrt.", host); return; } catch (Exception ex) { _logger.LogError(ex, "Error with FTP server: {Host}", host); return; }

Connect function: public FtpClientAsync(string host, int port, string username, string password) { Host = host; _client = new AsyncFtpClient(host, username, password, port); _client.Config.RetryAttempts = 5; _client.Config.EncryptionMode = FtpEncryptionMode.Explicit; _client.Config.DataConnectionEncryption = true; _client.Config.ValidateAnyCertificate = true; _client.Config.DataConnectionType = FtpDataConnectionType.PASV; _client.Config.DownloadDataType = FtpDataType.Binary; _client.Config.SocketKeepAlive = true; _client.Config.StaleDataCheck = true; _client.Config.ConnectTimeout = 30000; _client.Config.ReadTimeout = 30000; _client.Config.DataConnectionConnectTimeout = 30000; _client.Config.DataConnectionReadTimeout = 30000; _client.Config.TransferChunkSize = 131072; _client.Config.LocalFileBufferSize = 8192; _client.Config.LogUserName = false; _client.Config.LogPassword = false; _client.Config.LogHost = false; _client.Config.LogToConsole = true; }

Function that executes the actual list command: public async Task<IEnumerable<string>> GetNames(string remotePath, CancellationToken cancellationToken) { string[]? ftpNames = await _client.GetNameListing(remotePath, cancellationToken); return ftpNames .Where(item => Path.GetFileName(item)[0] is not ('(' or '[' or '_' or '#')) .Where(item => !item.Equals("Sample", StringComparison.OrdinalIgnoreCase)); }

[FanDjango]

Looks to me that somewhere in your async code, it is continuing and disposing the client while some other process is still waiting for data or a response.

You will want to debug this yourself. The "code snippets" you decided to divulge do not provide a lot of motivation on my side to even polish my crystal ball.

[MaxRubbel]

Sorry, I am still quite new.

Complete function which executes the code

private async Task Execute(string host, int port, FtpConfiguration configuration, CancellationToken cancellationToken = default)
    {
        if (!configuration.Enabled) return;
        _logger.LogDebug("Lookup Dirs from {Host}, Date: {DATE}, File Date {DATE2}", host, DateTime.Now.ToLocalTime(), _configuration.General.Date);

        using FtpClientAsync ftpClient = new(host, port, configuration.User, configuration.Password);

        if (!await Utils.ConnectFtp(ftpClient, _logger, host, cancellationToken))
            return;

        if (!ftpClient.IsConnected)
        {
            _logger.LogError("Failed to connect to FTP server: {Host}", host);
            return;
        }

        foreach (string path in configuration.Paths)
        {
            await using AsyncServiceScope scope = _provider.CreateAsyncScope();
            ReleaseRepository releaseRepository = scope.ServiceProvider.GetRequiredService<ReleaseRepository>();
            CacheRepository cacheRepository = scope.ServiceProvider.GetRequiredService<CacheRepository>();

            _logger.LogDebug("Schaut auf Verzeichniss {DIR} beim Host {HOST}", path, host);

            if (!await Utils.ConnectFtp(ftpClient, _logger, host, cancellationToken))
                return;

            if (!await ftpClient.DirectoryExists(path, cancellationToken))
            {
                _logger.LogError("Verzeichniss {DIR} beim Host {HOST} gibt es nicht", path, host);
                return;
            }

            IEnumerable<string> dirs;
            try
            {
                dirs = await ftpClient.GetNames(path, cancellationToken);
            }
            catch (FtpAuthenticationException)
            {
                _logger.LogError("Du bist beim Host {HOST} momentan gesperrt.", host);
                return;
            }
            catch (Exception ex)
            {
                _logger.LogError(ex, "Error with FTP server: {Host}", host);
                return;
            }

            IEnumerable<Release> releases = await releaseRepository.ListAsync(cancellationToken);
            IEnumerable<Cache> caches = await cacheRepository.ListAsync(cancellationToken);

            foreach (string dirFull in dirs)
            {
                string dirName = Path.GetFileName(dirFull);
                string dirFullPath = $"/{path}/{dirName}";
                if (releases.Any(item => (item.Name == dirName && item.Host == host) || (item.Name == dirName && item.Host != host && item.Error is 0 or 5))) continue;
                if (caches.Any(item => item.Name == dirName && item.Host == host)) continue;

                _logger.LogTrace("Release found {RELEASE}", dirFullPath);

                DateTimeOffset dirModifiedTime;
                FtpListItem dir;
                try
                {
                    dir = await ftpClient.GetDirInfo(dirFullPath, cancellationToken);
                    if (dir.Modified.ToLocalTime() < _configuration.General.Date)
                    {
                        Cache cache = new() { Name = dirName, Host = host, Modified = dir.Modified.ToLocalTime() };
                        await cacheRepository.CreateAsync(cache, cancellationToken);
                        continue;
                    }

                    dirModifiedTime = dir.Modified.ToLocalTime();
                }
                catch (Exception)
                {
                    dirModifiedTime = DateTimeOffset.Now.ToLocalTime();
                }

                Release release = new()
                {
                    Name = dirName,
                    Host = host,
                    RemotePath = dirFullPath,
                    Modified = dirModifiedTime,
                    AddDate = DateTimeOffset.Now.ToLocalTime()
                };
                await releaseRepository.CreateAsync(release, cancellationToken);
                _logger.LogDebug("Release added {RELEASE}", dirName);
            }
        }
    }

FtpClient Class

public class FtpClientAsync : IDisposable
{
    private readonly AsyncFtpClient _client;

    public FtpClientAsync(string host, int port, string username, string password)
    {
        Host = host;
        _client = new AsyncFtpClient(host, username, password, port);
        _client.Config.RetryAttempts = 5;
        _client.Config.EncryptionMode = FtpEncryptionMode.Explicit;
        _client.Config.DataConnectionEncryption = true;
        _client.Config.ValidateAnyCertificate = true;
        _client.Config.DataConnectionType = FtpDataConnectionType.PASV;
        _client.Config.DownloadDataType = FtpDataType.Binary;
        _client.Config.SocketKeepAlive = true;
        _client.Config.StaleDataCheck = true;
        _client.Config.ConnectTimeout = 30000;
        _client.Config.ReadTimeout = 30000;
        _client.Config.DataConnectionConnectTimeout = 30000;
        _client.Config.DataConnectionReadTimeout = 30000;
        _client.Config.TransferChunkSize = 131072;
        _client.Config.LocalFileBufferSize = 8192;
    }

    public bool IsConnected => _client.IsConnected;
    public string Host { get; }

    public async void Dispose()
    {
        try
        {
            if (_client.IsConnected)
                await Disconnect();
            if (!_client.IsDisposed)
                await _client.DisposeAsync();
        }
        catch (Exception)
        {
            // ignored
        }
    }

    public async Task Connect(CancellationToken cancellationToken)
    {
        await _client.Connect(cancellationToken);
    }

    public async Task<bool> DirectoryExists(string directoryPath, CancellationToken cancellationToken)
    {
        return await _client.DirectoryExists(directoryPath, cancellationToken);
    }

    public async Task DownloadDirectory(string remotePath, string localPath, CancellationToken cancellationToken)
    {
        await _client.DownloadDirectory(localPath, remotePath, token: cancellationToken, existsMode: FtpLocalExists.Overwrite);
    }

    public async Task<FtpListItem[]> GetDirectories(string remotePath)
    {
        FtpListItem[]? directorys = await _client.GetListing(remotePath, FtpListOption.ForceList | FtpListOption.Modify);
        return directorys
            .Where(item => item.Type == FtpObjectType.Directory)
            .Where(item => item.Name[0] is not ('(' or '[' or '_' or '#'))
            .Where(item => !item.Name.Equals("Sample", StringComparison.OrdinalIgnoreCase))
            .ToArray();
    }

    public async Task<IEnumerable<string>> GetNames(string remotePath, CancellationToken cancellationToken)
    {
        string[]? ftpNames = await _client.GetNameListing(remotePath, cancellationToken);
        return ftpNames
            .Where(item => Path.GetFileName(item)[0] is not ('(' or '[' or '_' or '#'))
            .Where(item => !item.Equals("Sample", StringComparison.OrdinalIgnoreCase));
    }

    public async Task<FtpListItem> GetDirInfo(string remotePath, CancellationToken cancellationToken)
    {
        return await _client.GetObjectInfo(remotePath, true, cancellationToken);
    }

    private async Task Disconnect(CancellationToken cancellationToken = default)
    {
        await _client.Disconnect(cancellationToken);
    }
}

Function to Connect Client

public static async Task<bool> ConnectFtp(FtpClientAsync ftpClientAsync, ILogger logger, String host, CancellationToken cancellationToken)
        {
            if (ftpClientAsync.IsConnected) return true;
            try
            {
                await ftpClientAsync.Connect(cancellationToken);
            }
            catch (FtpAuthenticationException)
            {
                logger.LogError("Du bist beim Host {HOST} momentan gesperrt.", host);
                return false;
            }
            catch (Exception ex)
            {
                logger.LogError(ex, "Failed to connect to FTP server: {Host}", host);
                return false;
            }

            return true;
        }

[FanDjango]

Where does the second (i.e. not the first one in the log)

# Connect(False)
Status:   FluentFTP 50.0.1.0(.NET 6.0) AsyncFtpClient

come from?

[MaxRubbel]

The program executes an FTP and when this is finished it starts the next FTP server immediately

[FanDjango]

Ok. Somewhere in you async code, one of the tasks is not awaited on and while this is running to completion, your other code already progresses onwards. Only you can find it - are you developing this in VS? Perhaps you can step through or use breakpoints, add some more logger output of your own.

[FanDjango]

The program executes an FTP and when this is finished it starts the next FTP server immediately

Do the testing by reducing complexity and dividing into parts. I.e., let the program execute only one FTP, not multiple ones. Does that one end correctly?

[MaxRubbel]

Okay, thanks for the feedback!

The problem is that the error only occurs sporadically, it is difficult to debug or test.

But if you say it's me and something is not awaiting then I'll search again and see.

Many thanks in any case!

[FanDjango]

The problem is that the error only occurs sporadically

You never said that yet.

You said in the beginning:

As soon as it fetches the list of names from the FTP. I can't explain why and I can't intercept it either. The program closes / crashes completely afterwards.

Especially this part of the log tells me there are more than one thread or process or whatever competing - typically this happens when (just an example) you forget to "await", the calling code simply continues and runs simultaneously to the async called routine.

Command:  NLST /TEST1/TEST2
Status:   Waiting for response to: NLST /TEST1/TEST2
Response: 150 File status okay; about to open data connection. [12ms]
Warning:  SSL Buffering disabled because of .NET 5.0 and later
Status:   FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, 44550, 256) [66ms]
+---------------------------------------+
Status:   Disposing(async) FtpSocketStream(data connection of AsyncFtpClient)

# CloseDataStream()
Status:   Testing connectivity using Socket.Poll()...

# CloseDataStream()
Status:   Waiting for response to: NLST /TEST1/TEST2
Status:   Waiting for response to: NLST /TEST1/TEST2
Response: 226- [Ul: 264.4GB] [Dl: 1.5PB] [Average speed: 199.0GB]
Response: 226-      [Credits: -16.1TB] [Ratio: 1:0.0]
Response: 226 Closing data connection [32,671s]

It is is sporadic, that is very strange though - it is possible that some timing issue is also at play here.

But if you say it's me

Not really, I'm saying where and what I would look for first, and how to simplify and divide the code so that you can determine better, what is happening. Maybe add a lot more logging. Maybe add task/thread id's to the logging, dunno.

[J0nathan550]

Same issue here! With ProFTPD. Whenever I try to download files (`download_directory') after an 50 mb of retriving specific file the downloading stops at certain point giving me the bad internet speed and after waiting a little it gives the exception (timeout exception) with no way of handle.

[MaxRubbel]

Hello,

I have now done some research and have run the client in non-async mode for test purposes and also get a "Time Out" error in some repeated situations.

If I interpret this correctly, the client crashes at NLST /TEST1 because the folder is empty. I also don't get an "extra" exception that the folder is empty or something, I haven't found one either.

If something is missing again or you need more information, please let me know. Thank you for any help!

Console Log:

System.InvalidOperationException: The FtpSocketStream object is not connected.
   at FluentFTP.FtpSocketStream.ActivateEncryption(String targetHost, X509CertificateCollection clientCerts, SslProtocols sslProtocols)
   at FluentFTP.FtpClient.OpenPassiveDataStream(FtpDataConnectionType type, String command, Int64 restart)
   at FluentFTP.FtpClient.OpenDataStream(String command, Int64 restart)
   at FluentFTP.FtpClient.GetNameListing(String path)
   at FTPDownloader.FtpClient.GetNames(String remotePath)
   at FTPDownloader.Workers.Watcher.HandleDirectory(FtpClient ftpClient, String host, String dirPath, String configPath, CancellationToken cancellationToken)

FTP Log:

2024-06-12 18:29:48.328 +02:00 [DBG] +---------------------------------------+
2024-06-12 18:29:49.117 +02:00 [INF] >         DirectoryExists("CHARTS")
2024-06-12 18:29:49.117 +02:00 [INF] Command:  CWD TEST1
2024-06-12 18:29:49.117 +02:00 [DBG] Waiting for response to: CWD TEST1
2024-06-12 18:29:49.154 +02:00 [INF] Response: 250 CWD command successful. [36ms]
2024-06-12 18:29:49.154 +02:00 [INF] Command:  PWD
2024-06-12 18:29:49.154 +02:00 [DBG] Waiting for response to: PWD
2024-06-12 18:29:49.191 +02:00 [INF] Response: 257 "/TEST1" is current directory. [37ms]
2024-06-12 18:29:49.191 +02:00 [INF] Command:  CWD /
2024-06-12 18:29:49.191 +02:00 [DBG] Waiting for response to: CWD /
2024-06-12 18:29:49.228 +02:00 [INF] Response: 250 CWD command successful. [36ms]
2024-06-12 18:29:49.228 +02:00 [INF] >         GetNameListing("TEST1")
2024-06-12 18:29:49.228 +02:00 [INF] >         OpenDataStream("NLST /TEST1", 0)
2024-06-12 18:29:49.228 +02:00 [INF] >         OpenPassiveDataStream(PASV, "NLST /TEST1", 0)
2024-06-12 18:29:49.228 +02:00 [INF] Command:  PASV
2024-06-12 18:29:49.228 +02:00 [DBG] Waiting for response to: PASV
2024-06-12 18:29:49.265 +02:00 [INF] Response: 227 Entering Passive Mode (89,149,202,10,201,77) [36ms]
2024-06-12 18:29:49.265 +02:00 [INF] Connecting to IP #1= ***:1234
2024-06-12 18:29:49.272 +02:00 [INF] Command:  NLST /TEST1
2024-06-12 18:29:49.272 +02:00 [DBG] Waiting for response to: NLST /TEST1
2024-06-12 18:29:49.309 +02:00 [INF] Response: 550 No files found. [36ms]
2024-06-12 18:29:49.309 +02:00 [DBG] Disposing(sync) FtpSocketStream(data connection of FtpClient)
2024-06-12 18:29:49.309 +02:00 [INF] >         CloseDataStream()
2024-06-12 18:29:49.313 +02:00 [INF] >         DirectoryExists("TEST2")
2024-06-12 18:29:49.313 +02:00 [INF] Command:  CWD TEST2

Code:

public IEnumerable<string> GetNames(string remotePath)
    {
        if (!_client.IsConnected)
        {
            _logger.LogInformation("FTP Reconnect - GetNames");
            Connect();
        }
        string[]? ftpNames = _client.GetNameListing(remotePath);
        return ftpNames
            .Where(item => Path.GetFileName(item)[0] is not ('(' or '[' or '_' or '#'))
            .Where(item => !item.Equals("Super", StringComparison.OrdinalIgnoreCase));
    }

[FanDjango]

I am going to try somehow to reproduce that part you logged, but I am afraid this may take some time. Please stand by.

[MaxRubbel]

For perhaps easier testing, here are all the settings on the client.

public FtpClient(string host, int port, string username, string password, ILogger<FtpClient> logger)
    {
        _logger = logger;
        Host = host;
        _client = new FluentFTP.FtpClient(host, username, password, port);
        _client.Config.RetryAttempts = 10;
        _client.Config.EncryptionMode = FtpEncryptionMode.Explicit;
        _client.Config.DataConnectionEncryption = true;
        _client.Config.ValidateAnyCertificate = true;
        _client.Config.DataConnectionType = FtpDataConnectionType.PASV;
        _client.Config.FXPDataType = FtpDataType.Binary;
        _client.Config.DownloadDataType = FtpDataType.Binary;
        _client.Config.SocketKeepAlive = true;
        _client.Config.StaleDataCheck = true;
        _client.Config.ConnectTimeout = 30000;
        _client.Config.ReadTimeout = 30000;
        _client.Config.DataConnectionConnectTimeout = 30000;
        _client.Config.DataConnectionReadTimeout = 30000;
        _client.Config.TransferChunkSize = 131072;
        _client.Config.LocalFileBufferSize = 8192;
        _client.Config.LogUserName = false;
        _client.Config.LogPassword = false;
        _client.Config.LogHost = false;
        _client.Config.LogToConsole = true;
    }

[FanDjango]

Ok. First, one question:

2024-06-12 18:29:48.328 +02:00 [DBG] +---------------------------------------+ 2024-06-12 18:29:49.117 +02:00 [INF] > DirectoryExists("CHARTS") 2024-06-12 18:29:49.117 +02:00 [INF] Command: CWD TEST1 2024-06-12 18:29:49.117 +02:00 [DBG] Waiting for response to: CWD TEST1 2024-06-12 18:29:49.154 +02:00 [INF] Response: 250 CWD command successful. [36ms]

Have you redacted this? Because I suppose then it would be `DirectoryExists("TEST1"), right? You just forgot to edit that?

Now, look at our code for GetNameListing(...):

            catch (FtpCommandException ftpEx) {
                // Some FTP servers throw 450 or 550 for empty folders. Absorb these.
                if (ftpEx.CompletionCode == null ||
                    (!ftpEx.CompletionCode.StartsWith("450") && !ftpEx.CompletionCode.StartsWith("550"))) {
                    throw ftpEx;
                }

Sadly, I do not have a server available which handles empty name-lists like this. Yours does. So I cannot really reproduce this well.

I do have another question first:

I have no way to see from where the exception is coming from. Yes, I know it is in at FluentFTP.FtpSocketStream.ActivateEncryption(...), but since your log just continues onwards I don't have any way to see how we got to there. If you could output the exception and the log in the same stream, I could see exactly where this happens.

What I need you to do:

Run this code ONCE ONLY for a directory that is empty and DO NOT continue after that.

public IEnumerable<string> GetNames(string remotePath)
    {
        if (!_client.IsConnected)
        {
            _logger.LogInformation("FTP Reconnect - GetNames");
            Connect();
        }
        string[]? ftpNames = _client.GetNameListing(remotePath);
        return ftpNames
            .Where(item => Path.GetFileName(item)[0] is not ('(' or '[' or '_' or '#'))
            .Where(item => !item.Equals("Super", StringComparison.OrdinalIgnoreCase));
    }

Perhaps do that in VS in a separate console application and let's look at the output, where any exceptions will be in sequence with the rest of the log messages.

[MaxRubbel]

Ok. First, one question:

2024-06-12 18:29:48.328 +02:00 [DBG] +---------------------------------------+ 2024-06-12 18:29:49.117 +02:00 [INF] > DirectoryExists("CHARTS") 2024-06-12 18:29:49.117 +02:00 [INF] Command: CWD TEST1 2024-06-12 18:29:49.117 +02:00 [DBG] Waiting for response to: CWD TEST1 2024-06-12 18:29:49.154 +02:00 [INF] Response: 250 CWD command successful. [36ms]

Have you redacted this? Because I suppose then it would be `DirectoryExists("TEST1"), right? You just forgot to edit that?

Yes, I must have forgotten to replace that. I replaced it with TEST1 to make it easier to understand.

Here are the logs, I hope I have done everything the way you want it.

2024-06-13 17:35:18.400 +02:00 [Information] [FTPDownloader.Workers.Watcher] Starte Watcher
2024-06-13 17:35:18.401 +02:00 [Debug] [FTPDownloader.Workers.Watcher] Lookup Dirs from "HOST", Date: 06/13/2024 17:35:18, File Date 03/07/2024 00:00:00
2024-06-13 17:35:18.402 +02:00 [Information] [FTPDownloader.FtpClient] >         Connect(False)
2024-06-13 17:35:18.403 +02:00 [Debug] [FTPDownloader.FtpClient] FluentFTP 50.0.1.0(.NET 6.0) FtpClient
2024-06-13 17:35:19.013 +02:00 [Information] [FTPDownloader.FtpClient] Connecting to IP #1= ***:1234
2024-06-13 17:35:19.033 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for a response
2024-06-13 17:35:19.582 +02:00 [Information] [FTPDownloader.FtpClient] Response: 220 DrFTPD 3.2.0 https://github.com/drftpd-ng/drftpd3  [739049.65d]
2024-06-13 17:35:19.583 +02:00 [Information] [FTPDownloader.FtpClient] Command:  AUTH TLS
2024-06-13 17:35:19.583 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: AUTH TLS
2024-06-13 17:35:19.620 +02:00 [Information] [FTPDownloader.FtpClient] Response: 234 AUTH TLS successful [36ms]
2024-06-13 17:35:19.664 +02:00 [Information] [FTPDownloader.FtpClient] FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, DiffieHellman, 0) [44ms]
2024-06-13 17:35:19.665 +02:00 [Information] [FTPDownloader.FtpClient] Command:  USER ***
2024-06-13 17:35:19.665 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: USER ***
2024-06-13 17:35:19.722 +02:00 [Information] [FTPDownloader.FtpClient] Response: 331 Password required for ***. [56ms]
2024-06-13 17:35:19.722 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PASS ***
2024-06-13 17:35:19.722 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PASS ***
2024-06-13 17:35:19.821 +02:00 [Debug] [FTPDownloader.FtpClient] Response: 230-                                _____
Response: 230- ______________________________|__   |____ ________________________________
Response: 230- \     _      /   _     /  _     /   |    |    _     /  _     /    _      /
Response: 230-  \    \     /    /    /   /____/.   |    |    /    /   /____/.    /_____/
Response: 230-   \________/____/    /______    |___|____|___/    /______    |____|
Response: 230- .-=----------- /____/ ---- |____| --------- /____/ ---- |____| -------=-.
Response: 230- `-=-------------------------------------------------------------------=-'
Response: 230-       `-----( Type 'site onel MESSAGE' to enter your message )-----'
2024-06-13 17:35:19.821 +02:00 [Information] [FTPDownloader.FtpClient] Response: 230 User *** logged in. [98ms]
2024-06-13 17:35:19.821 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PBSZ 0
2024-06-13 17:35:19.821 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PBSZ 0
2024-06-13 17:35:19.857 +02:00 [Information] [FTPDownloader.FtpClient] Response: 200 PBSZ 0 successful [36ms]
2024-06-13 17:35:19.858 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PROT P
2024-06-13 17:35:19.858 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PROT P
2024-06-13 17:35:19.894 +02:00 [Information] [FTPDownloader.FtpClient] Response: 200 Protection set to Private [36ms]
2024-06-13 17:35:19.894 +02:00 [Information] [FTPDownloader.FtpClient] Command:  FEAT
2024-06-13 17:35:19.894 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: FEAT
2024-06-13 17:35:19.992 +02:00 [Debug] [FTPDownloader.FtpClient] Response: 211- Extensions supported:
Response: AUTH TLS
Response: AUTH SSL
Response: PBSZ
Response: PROT
Response: CPSV
Response: SSCN
Response: MDTM
Response: SIZE
Response: REST STREAM
Response: SYST
Response: EPRT
Response: EPSV
Response: CEPR
2024-06-13 17:35:19.992 +02:00 [Information] [FTPDownloader.FtpClient] Response: 211 End [98ms]
2024-06-13 17:35:19.992 +02:00 [Information] [FTPDownloader.FtpClient] Text encoding: System.Text.ASCIIEncoding+ASCIIEncodingSealed
2024-06-13 17:35:19.992 +02:00 [Information] [FTPDownloader.FtpClient] Command:  SYST
2024-06-13 17:35:19.992 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: SYST
2024-06-13 17:35:20.029 +02:00 [Information] [FTPDownloader.FtpClient] Response: 215 UNIX Type: L8 [36ms]
2024-06-13 17:35:20.029 +02:00 [Debug] [FTPDownloader.FtpClient] Active ServerHandler is: None
2024-06-13 17:35:20.029 +02:00 [Debug] [FTPDownloader.FtpClient] Listing parser set to: Unix
2024-06-13 17:35:20.029 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PWD
2024-06-13 17:35:20.029 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PWD
2024-06-13 17:35:20.065 +02:00 [Information] [FTPDownloader.FtpClient] Response: 257 "/" is current directory. [36ms]
2024-06-13 17:35:20.067 +02:00 [Debug] [FTPDownloader.Workers.Watcher] Schaut auf Verzeichniss "TEST1" beim Host "HOST"
2024-06-13 17:35:20.067 +02:00 [Information] [FTPDownloader.FtpClient] >         DirectoryExists("TEST1")
2024-06-13 17:35:20.067 +02:00 [Information] [FTPDownloader.FtpClient] Command:  CWD TEST1
2024-06-13 17:35:20.068 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: CWD TEST1
2024-06-13 17:35:20.172 +02:00 [Debug] [FTPDownloader.FtpClient] Response: 250- --NEWS--
Response: 250-
Response: 250- New Feature:  Login with (!)Username to kill ghost connections.
Response: 250- New Feature:  Login with (/)Username to disable use_dir_size.
Response: 250-
Response: 250- --=- Type SITE HELP for a nice list of SITE commands -=--
Response: 250-
2024-06-13 17:35:20.172 +02:00 [Information] [FTPDownloader.FtpClient] Response: 250 CWD command successful. [104ms]
2024-06-13 17:35:20.172 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PWD
2024-06-13 17:35:20.172 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PWD
2024-06-13 17:35:20.208 +02:00 [Information] [FTPDownloader.FtpClient] Response: 257 "/TEST1" is current directory. [36ms]
2024-06-13 17:35:20.208 +02:00 [Information] [FTPDownloader.FtpClient] Command:  CWD /
2024-06-13 17:35:20.209 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: CWD /
2024-06-13 17:35:20.245 +02:00 [Information] [FTPDownloader.FtpClient] Response: 250 CWD command successful. [36ms]
2024-06-13 17:35:20.246 +02:00 [Information] [FTPDownloader.FtpClient] >         GetNameListing("TEST1")
2024-06-13 17:35:20.246 +02:00 [Information] [FTPDownloader.FtpClient] Command:  TYPE I
2024-06-13 17:35:20.246 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: TYPE I
2024-06-13 17:35:20.283 +02:00 [Information] [FTPDownloader.FtpClient] Response: 200 Type set to I. [36ms]
2024-06-13 17:35:20.283 +02:00 [Information] [FTPDownloader.FtpClient] >         OpenDataStream("NLST /TEST1", 0)
2024-06-13 17:35:20.283 +02:00 [Information] [FTPDownloader.FtpClient] >         OpenPassiveDataStream(PASV, "NLST /TEST1", 0)
2024-06-13 17:35:20.283 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PASV
2024-06-13 17:35:20.283 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PASV
2024-06-13 17:35:20.321 +02:00 [Information] [FTPDownloader.FtpClient] Response: 227 Entering Passive Mode (89,149,202,10,185,213) [37ms]
2024-06-13 17:35:20.321 +02:00 [Information] [FTPDownloader.FtpClient] Connecting to IP #1= ***:47573
2024-06-13 17:35:20.329 +02:00 [Information] [FTPDownloader.FtpClient] Command:  NLST /TEST1
2024-06-13 17:35:20.329 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: NLST /TEST1
2024-06-13 17:35:20.368 +02:00 [Information] [FTPDownloader.FtpClient] Response: 550 No files found. [38ms]
2024-06-13 17:35:20.368 +02:00 [Debug] [FTPDownloader.FtpClient] Disposing(sync) FtpSocketStream(data connection of FtpClient)
2024-06-13 17:35:20.368 +02:00 [Information] [FTPDownloader.FtpClient] >         CloseDataStream()
2024-06-13 17:35:20.368 +02:00 [Error] [FTPDownloader.Workers.Watcher] Error with FTP server: "HOST"
System.InvalidOperationException: The FtpSocketStream object is not connected.
   at FluentFTP.FtpSocketStream.ActivateEncryption(String targetHost, X509CertificateCollection clientCerts, SslProtocols sslProtocols)
   at FluentFTP.FtpClient.OpenPassiveDataStream(FtpDataConnectionType type, String command, Int64 restart)
   at FluentFTP.FtpClient.OpenDataStream(String command, Int64 restart)
   at FluentFTP.FtpClient.GetNameListing(String path)
   at FTPDownloader.FtpClient.GetNames(String remotePath)
   at FTPDownloader.Workers.Watcher.HandleDirectory(FtpClient ftpClient, String host, String dirPath, String configPath, CancellationToken cancellationToken)
2024-06-13 17:35:20.373 +02:00 [Information] [FTPDownloader.FtpClient] >         Disconnect()
2024-06-13 17:35:20.373 +02:00 [Information] [FTPDownloader.FtpClient] Command:  QUIT
2024-06-13 17:35:20.373 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: QUIT
2024-06-13 17:35:20.415 +02:00 [Debug] [FTPDownloader.FtpClient] Response: 221- Goodbye
2024-06-13 17:35:20.415 +02:00 [Information] [FTPDownloader.FtpClient] Response: 221  [41ms]
2024-06-13 17:35:20.415 +02:00 [Debug] [FTPDownloader.FtpClient] Disposing(sync) FtpSocketStream(control connection of FtpClient)
2024-06-13 17:35:20.415 +02:00 [Information] [FTPDownloader.FtpClient] >         Dispose()
2024-06-13 17:35:20.415 +02:00 [Debug] [FTPDownloader.FtpClient] Disposing(sync) FtpClient
2024-06-13 17:35:20.415 +02:00 [Information] [FTPDownloader.Workers.Watcher] Watcher Wartet 5 Minuten bis zur nächsten Ausführung
2024-06-13 17:35:22.761 +02:00 [Error] [FTPDownloader.Workers.Watcher] An unknown error occured.
System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at FTPDownloader.Workers.Watcher.<>c__DisplayClass8_0.<<ExecuteAsync>b__0>d.MoveNext()
2024-06-13 17:35:22.762 +02:00 [Debug] [FTPDownloader.Workers.Watcher] Close Watcher

[FanDjango]

Exactly what was needed. Great!

[FanDjango]

I have located the problem and made a fix. It is in a dangerous place, so it needs some careful testing - you are the ideal person to do that.

You need to get this branch on my fork: "https://github.com/FanDjango/FluentFTP/tree/I1582".

Please use that to build the above used program and run it again to see if there is correct behaviour. Please show the log, only the part beginning with "Command: NLST /TEST1" up to the end is needed.

[MaxRubbel]

So I just tested it with the branch you said, I didn't get an error.

I'll ask another question, could this also be the problem in the Async Client?

Thank you for your efforts!

2024-06-14 18:03:16.600 +02:00 [Information] [FTPDownloader.FtpClient] Response: 250 CWD command successful. [100ms]
2024-06-14 18:03:16.600 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PWD
2024-06-14 18:03:16.600 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PWD
2024-06-14 18:03:16.636 +02:00 [Information] [FTPDownloader.FtpClient] Response: 257 "/TEST1" is current directory. [35ms]
2024-06-14 18:03:16.636 +02:00 [Information] [FTPDownloader.FtpClient] Command:  CWD /
2024-06-14 18:03:16.636 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: CWD /
2024-06-14 18:03:16.673 +02:00 [Information] [FTPDownloader.FtpClient] Response: 250 CWD command successful. [36ms]
2024-06-14 18:03:16.673 +02:00 [Information] [FTPDownloader.FtpClient] >         GetNameListing("TEST1")
2024-06-14 18:03:16.673 +02:00 [Information] [FTPDownloader.FtpClient] Command:  TYPE I
2024-06-14 18:03:16.673 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: TYPE I
2024-06-14 18:03:16.709 +02:00 [Information] [FTPDownloader.FtpClient] Response: 200 Type set to I. [35ms]
2024-06-14 18:03:16.709 +02:00 [Information] [FTPDownloader.FtpClient] >         OpenDataStream("NLST /TEST1", 0)
2024-06-14 18:03:16.710 +02:00 [Information] [FTPDownloader.FtpClient] >         OpenPassiveDataStream(PASV, "NLST /TEST1", 0)
2024-06-14 18:03:16.710 +02:00 [Information] [FTPDownloader.FtpClient] Command:  PASV
2024-06-14 18:03:16.710 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: PASV
2024-06-14 18:03:16.746 +02:00 [Information] [FTPDownloader.FtpClient] Response: 227 Entering Passive Mode (89,149,202,10,208,127) [36ms]
2024-06-14 18:03:16.746 +02:00 [Debug] [FTPDownloader.FtpClient] Connecting(sync) FtpClient.FtpSocketStream(data) IP #1 = ***:1234
2024-06-14 18:03:16.754 +02:00 [Information] [FTPDownloader.FtpClient] Command:  NLST /TEST1
2024-06-14 18:03:16.754 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: NLST /TEST1
2024-06-14 18:03:16.790 +02:00 [Information] [FTPDownloader.FtpClient] Response: 550 No files found. [35ms]
2024-06-14 18:03:16.790 +02:00 [Debug] [FTPDownloader.FtpClient] Disposing(sync) FtpClient.FtpSocketStream(data)
2024-06-14 18:03:16.790 +02:00 [Information] [FTPDownloader.FtpClient] >         CloseDataStream()
2024-06-14 18:03:16.791 +02:00 [Debug] [FTPDownloader.FtpClient] +---------------------------------------+
2024-06-14 18:03:16.791 +02:00 [Debug] [FTPDownloader.FtpClient] +---------------------------------------+
2024-06-14 18:03:17.772 +02:00 [Information] [FTPDownloader.FtpClient] >         Disconnect()
2024-06-14 18:03:17.772 +02:00 [Information] [FTPDownloader.FtpClient] Command:  QUIT
2024-06-14 18:03:17.772 +02:00 [Debug] [FTPDownloader.FtpClient] Waiting for response to: QUIT
2024-06-14 18:03:17.810 +02:00 [Debug] [FTPDownloader.FtpClient] Response: 221- Goodbye
2024-06-14 18:03:17.810 +02:00 [Information] [FTPDownloader.FtpClient] Response: 221  [37ms]
2024-06-14 18:03:17.810 +02:00 [Debug] [FTPDownloader.FtpClient] Disposing(sync) FtpClient.FtpSocketStream(control)
2024-06-14 18:03:17.810 +02:00 [Information] [FTPDownloader.FtpClient] >         Dispose()
2024-06-14 18:03:17.810 +02:00 [Debug] [FTPDownloader.FtpClient] Disposing(sync) FtpClient

[FanDjango]

So I just tested it with the branch you said, I didn't get an error.

That's great. Thanks for testing.

could this also be the problem in the Async Client?

Certainly, yes. Perhaps. But let's go slowly, step by step.

Let's call the problem I worked on "The NLST 550 problem", ok?

I fixed it for SYNC only and you tested it. Let me now also fix it for the ASYNC client, adding that to the branch you tested, I'll tell you when that is ready.

And then you can begin to use that for async and we will go on from there and see what happens, ok? Perhaps it will be ok, perhaps there will be more things to look at. But we are making progress and your logs are now such that I can understand the problems better.

[MaxRubbel]

All right, let's do it that way!

Thank you!

[FanDjango]

Ok, the special branch that I made for you now also has a fix for ASYNC also. You could now see what happens and I am curious to see a log.

[MaxRubbel]

So the program is now running, unfortunately this only happens sporadically with Async Client, not always. That's why I can't give you anything right now. I will let you know if the error occurs again.

[FanDjango]

That's perfectly ok. Wait for it.

[MaxRubbel]

Hello,

it has been running for 2 days now. Absolutely no problems, in my experience it crashed a long time ago with the old version.

[FanDjango]

So, the actual problem was:

Whenever you directly or indirectly cause a NLST command to be issued AND the directory to be listed is empty, this special server answers with a 550... error message. This is not the only way to "send nothing". Others do it differently. There is code in FluentFTP to handle either such was, but the "550..." code was broken or never functional.

I will now undertake to get this fix validated, further testing etc., then I will merge it. At some point in time it will then be released into the next NuGet release.

[FanDjango]

@J0nathan550 If this does not address the problem you mentioned, please open up a separate issue, ok?

[J0nathan550]

@J0nathan550 If this does not address the problem you mentioned, please open up a separate issue, ok?

Oh, I'm simply waiting the fixes. I had similar issues. But I just switched to 49.0.2 and my issue was resolved.

[MaxRubbel]

Hello, it's me again. There has been a crash after all. But this time apparently because it did not get a connection. My timeout settings are as follows:

_client.Config.ConnectTimeout = 30000;
_client.Config.ReadTimeout = 30000;
_client.Config.DataConnectionConnectTimeout = 30000;
 _client.Config.DataConnectionReadTimeout = 30000;

Which makes me wonder why it crashes completely.

FTP LOG:

2024-06-23 09:22:53.322 +02:00 [Information] [FTP] >         DirectoryExists("TEST/TEST1")
2024-06-23 09:22:53.322 +02:00 [Information] [FTP] Command:  CWD TEST/TEST1
2024-06-23 09:22:53.322 +02:00 [Debug] [FTP] Waiting for response to: CWD TEST/TEST1
2024-06-23 09:22:56.075 +02:00 [Information] [FTP] Response: 250 Directory changed to /TEST/TEST1 [2.753s]
2024-06-23 09:22:56.075 +02:00 [Information] [FTP] Command:  PWD
2024-06-23 09:22:56.075 +02:00 [Debug] [FTP] Waiting for response to: PWD
2024-06-23 09:22:56.095 +02:00 [Information] [FTP] Response: 257 "/TEST/TEST1" is current directory [19ms]
2024-06-23 09:22:56.095 +02:00 [Information] [FTP] Command:  CWD /
2024-06-23 09:22:56.095 +02:00 [Debug] [FTP] Waiting for response to: CWD /
2024-06-23 09:22:56.114 +02:00 [Information] [FTP] Response: 250 Directory changed to / [19ms]
2024-06-23 09:22:56.114 +02:00 [Information] [FTP] >         GetNameListing("TEST/TEST1")
2024-06-23 09:22:56.114 +02:00 [Information] [FTP] >         OpenDataStreamAsync("NLST /TEST/TEST1", 0)
2024-06-23 09:22:56.114 +02:00 [Information] [FTP] >         OpenPassiveDataStreamAsync(PASV, "NLST /TEST/TEST1", 0)
2024-06-23 09:22:56.114 +02:00 [Information] [FTP] Command:  PRET NLST /TEST/TEST1
2024-06-23 09:22:56.114 +02:00 [Debug] [FTP] Waiting for response to: PRET NLST /TEST/TEST1
2024-06-23 09:22:56.122 +02:00 [Information] [FTP] Response: 200 OK, will use master for upcoming transfer [7ms]
2024-06-23 09:22:56.122 +02:00 [Information] [FTP] Command:  PASV
2024-06-23 09:22:56.122 +02:00 [Debug] [FTP] Waiting for response to: PASV
2024-06-23 09:22:56.129 +02:00 [Information] [FTP] Response: 227 Entering Passive Mode (***,***,***,***,169,47). [7ms]
2024-06-23 09:22:56.129 +02:00 [Debug] [FTP] Connecting(async) AsyncFtpClient.FtpSocketStream(data) IP #1 = ***:43311
2024-06-23 09:22:56.136 +02:00 [Information] [FTP] Command:  NLST /TEST/TEST1
2024-06-23 09:22:56.136 +02:00 [Debug] [FTP] Waiting for response to: NLST /TEST/TEST1
2024-06-23 09:22:56.144 +02:00 [Information] [FTP] Response: 150 File status okay; about to open data connection. [7ms]
2024-06-23 09:22:56.161 +02:00 [Information] [FTP] FTPS authentication successful, lib = .NET SslStream, cipher suite = Tls12 (Aes256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, DiffieHellman, 0) [17ms]
2024-06-23 09:22:56.161 +02:00 [Debug] [FTP] +---------------------------------------+
2024-06-23 09:23:26.161 +02:00 [Debug] [FTP] Disposing(async) AsyncFtpClient.FtpSocketStream(data)
2024-06-23 09:23:26.161 +02:00 [Information] [FTP] >         CloseDataStream()
2024-06-23 09:23:26.161 +02:00 [Debug] [FTP] Testing connectivity using Socket.Poll()...
2024-06-23 09:23:26.168 +02:00 [Information] [FTP] >         CloseDataStream()
2024-06-23 09:23:26.168 +02:00 [Debug] [FTP] Waiting for response to: NLST /TEST/TEST1
2024-06-23 09:23:26.662 +02:00 [Debug] [FTP] Waiting for response to: NLST /TEST/TEST1
2024-06-23 09:23:28.299 +02:00 [Debug] [FTP] Response: 226- [Ul: 264.4GB] [Dl: 1.6PB] [Average speed: 200.3GB]
Response: 226-      [Credits: -16.6TB] [Ratio: 1:0.0]
2024-06-23 09:23:28.299 +02:00 [Information] [FTP] Response: 226 Closing data connection [32.162s]
2024-06-23 09:23:28.328 +02:00 [Error] [FTP] Error with FTP server: "HOST" on Path "TEST/TEST1"
System.TimeoutException: Timed out trying to read data from the socket stream!
   at FluentFTP.FtpSocketStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token)
   at FluentFTP.FtpDataStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken token)
   at FluentFTP.FtpSocketStream.ReadLineAsync(Encoding encoding, CancellationToken token)
   at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token)
   at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token)
   at FluentFTP.AsyncFtpClient.GetNameListing(String path, CancellationToken token)
   at FTPDownloader.FtpClientAsync.GetNames(String remotePath, CancellationToken cancellationToken)
   at FTPDownloader.Workers.Watcher.HandleDirectory(FtpClientAsync ftpClientAsync, String host, String dirPath, String configPath, ILogger testLogger, CancellationToken cancellationToken)

[FanDjango]

This is good - so there is still a bug in the code for empty NLSTs. I will try to find out how this special case can happen, some timing issue somewhere, perhaps. Must study the code and your log some more. Could you check if that directory is actually empty (or was empty)? Is this still the same server as always in the other cases above? Has anything else changed other than using Async instead of Sync?

I know it takes a long time to catch, but could you run again but turn off the polling? Testing connectivity using Socket.Poll()... This would make the possible causes much less.

[FanDjango]

2024-06-23 09:22:56.161 +---------------------------------------+
2024-06-23 09:23:26.161 Disposing(async) AsyncFtpClient.FtpSocketStream(data)
2024-06-23 09:23:26.161 >         CloseDataStream()
2024-06-23 09:23:26.161 Testing connectivity using Socket.Poll()...
2024-06-23 09:23:26.168 >         CloseDataStream()
2024-06-23 09:23:26.168 Waiting for response to: NLST /TEST/TEST1
2024-06-23 09:23:26.662 Waiting for response to: NLST /TEST/TEST1
2024-06-23 09:23:28.299 Response: 226- [Ul: 264.4GB] [Dl: 1.6PB] [Average speed: 200.3GB]
Response: 226-      [Credits: -16.6TB] [Ratio: 1:0.0]
2024-06-23 09:23:28.299 Response: 226 Closing data connection [32.162s]

Looks to me like:

1. No data came for the name list
2. Thirty seconds later it timed out and closed the data connection
3. At the same time per random a socket poll noticed there is no connection and also tries to close the data connection
4. SO now we have 2 close operations running and BOTH of them wait to see a response of the control connection
5. One of these gets the success message 226, the other times out.

Note: This is probably a problem exacerbated by async operation.

Quick solution: Stop using the polling, set the pollinterval to zero.

@robinrodricks FluentFTP BUG: Double close due to inferior implementation of polling. Need a semaphore here. Or a polling demon, similar to the NOOP daemon. OR Check in IsConnected() before polling, whether it has been called by CloseDataStream. This would be a quick and reasonably clean workaround. OR (method of choice) In CloseDataStream, disable and then re-enable polling.

[FanDjango]

@MaxRubbel The test branch I made for you, has got changed as per the previous post.

https://github.com/FanDjango/FluentFTP/tree/I1582

Please test with this one. Do not turn off polling, ignore my request from yesterday. I think I have understood what was going wrong and so don't change anything on your side, just use the new code I uploaded.

[MaxRubbel]

All right, I've installed it and will report back.

I also wanted to say that I did not change the async code to the sync code except that now everything is awaited and the client is just async.

[MaxRubbel]

Hello,

nothing has happened since then, it has been running continuously. But like last time, it can still come unexpectedly.

Thank you very much!

[FanDjango]

Thanks for the update. Let's watch another week, ok?

[MaxRubbel]

Absolutely no problem, of course!