Ask a Question

[Exception] Another operation is pending - after having tried to read FtpFile that doesnt exsist.

0 votes
by (140 points)

Hi,

I am struggling with an Error in the Rebex.Ftp nuget package.

I am trying to do the following session:

  1. Connect and Login on the FTP Server using TLS1.2
  2. Try to download a list of files to local files. If a File does not exsist on the FtpServer, the Ftp client should continue to download the next file in the list.
  3. Disconnect from FtpServer

I discovered, that if a File is not Present on the FTPServer, Rebex throws an Exception (Couldn't open the file or directory (550).). That is fine. In my code i swallow the exception, and continue with downloading the next file. When trying to open the next file (Which exsist), I get another Exception (Another operation is pending). I can see in the Log of the FTPServer, that the FTP client doesnt even try and download the next file. The RebexClient throws the exception, and also throws the exception when trying to disconnect.

I have written a small program, that lets you replicate the bug:

       public async Task Run()
    {
        ftpClient = new Ftp();
        ftpClient.Settings.SslAllowedVersions = TlsVersion.TLS11 | TlsVersion.TLS12;
        ftpClient.Settings.SslAcceptAllCertificates = true;

        await ftpClient.ConnectAsync("someftpServer.net", 990, SslMode.Explicit);
        await ftpClient.LoginAsync("SiteUser", "SomePassword");

        // 1st File that is not present on FTP Server
        var fileNotOnFtpServer = "/TestResults10/TestResult1.xls";

        // 2.File is present
        var fileExistsOnFtpServer = "/TestResults10/TestResult2.xls";

        var filesToDownload = new List<string>() { fileNotOnFtpServer, fileExistsOnFtpServer };

        foreach (var file in filesToDownload)
        {
            await DownloadFile(file);
        }

        await ftpClient.DisconnectAsync();
    }

    private async Task DownloadFile(string ftpFilePath)
    {
        var destinationFolder = @"d:\ftpdownload\";
        var destinationFilePath = Path.Combine(destinationFolder, Path.GetFileName(ftpFilePath));

        try
        {
            using (var ftpFileStream = await ftpClient.GetDownloadStreamAsync(ftpFilePath, SeekOrigin.Begin, 0))
            {
                using (var fileStream = File.Create(destinationFilePath))
                {
                    ftpFileStream.CopyTo(fileStream);
                }
            }
            Console.WriteLine($"{ftpFilePath} was transferred");
        }
        catch(Exception ex)
        {
            Console.WriteLine(ex.ToString());
        }
    }

Expected Behaviour
The Ftp client should throw an Exception, when trying to Open a stream to a FTP file that does not exsist. However, you should be able to swallow that Exception, and continue to download another FTP File using a Stream.

Can you please help me here?

Thanks!

Applies to: Rebex FTP/SSL, Rebex SFTP

1 Answer

0 votes
by (148k points)

It should indeed be possible to swallow an "Couldn't open the file or directory (550)" exception and continue with another operation.

The "Another operation is pending" error is supposed to be raised when an Ftp object's method is called while another method is still running, which does not seem to correspond to your code. GetDownloadStreamAsync method is a bit special in this regard, because that operation is only considered finished when the returned Stream has been closed, so perhaps there might be some issue there.

Would it be possible to create a debug log using Ftp object's LogWriter property and either post it here or mail it to support@rebex.net? We are mostly interested in the line showing the "550 Couldn't open the file or directory" error and several commands/responses that preceded that.

Additionally, to help us determine whether this could possibly be a bug in the GetDownloadStreamAsync method, would it be possible to try downloading the file using GetFileAsync?

private async Task DownloadFile(string ftpFilePath)
{
    var destinationFolder = @"d:\ftpdownload\";
    var destinationFilePath = Path.Combine(destinationFolder, Path.GetFileName(ftpFilePath));

    try
    {
        await ftpClient.GetFileAsync(ftpFilePath, destinationFilePath, 0);
        Console.WriteLine($"{ftpFilePath} was transferred");
    }
    catch(Exception ex)
    {
        Console.WriteLine(ex.ToString());
    }
}

Does this fail with "Another operation is pending" as well when the file is not present at the FTP server?

(In the meantime, we will also try reproducing the issue using your code above.)

by (140 points)
This is the log i got from Rebex Client

2022-11-03 11:14:01.413 Opening log file.
2022-11-03 11:14:01.419 INFO FileLogWriter(1)[1] Info: Assembly: Rebex.Common R6.8 for .NET 6.0
2022-11-03 11:14:01.428 INFO FileLogWriter(1)[1] Info: Platform: Windows 10.0.19044 64-bit; CLR: .NET 6.0.10
2022-11-03 11:14:01.428 DEBUG FileLogWriter(1)[1] Info: Culture: da; windows-1252
2022-11-03 11:14:01.579 INFO Ftp(1)[5] Info: Connecting to tc-site-dev.northeurope.cloudapp.azure.com:990 using Ftp.
2022-11-03 11:14:01.580 INFO Ftp(1)[5] Info: Assembly: Rebex.Ftp R6.8 for .NET 6.0
2022-11-03 11:14:01.580 INFO Ftp(1)[5] Info: Platform: Windows 10.0.19044 64-bit; CLR: .NET 6.0.10
2022-11-03 11:14:01.580 DEBUG Ftp(1)[5] Info: Culture: da; windows-1252
2022-11-03 11:14:01.580 INFO Ftp(1)[5] Info: Using proxy none.
2022-11-03 11:14:01.622 DEBUG Ftp(1)[5] Proxy: Resolving 'tc-site-dev.northeurope.cloudapp.azure.com'.
2022-11-03 11:14:01.664 DEBUG Ftp(1)[5] Proxy: Connecting to 40.87.129.115:990 (no proxy).
2022-11-03 11:14:01.705 DEBUG Ftp(1)[5] Proxy: Connection established.
2022-11-03 11:14:01.706 DEBUG Ftp(1)[5] Info: Connection succeeded.
2022-11-03 11:14:01.746 INFO Ftp(1)[5] Response: 220-FileZilla Server 1.5.1
2022-11-03 11:14:01.746 INFO Ftp(1)[5] Response: 220-Please visit https://filezilla-project.org/
2022-11-03 11:14:01.746 INFO Ftp(1)[5] Response: 220 Tricloud FTP Site Server DEV
2022-11-03 11:14:01.753 INFO Ftp(1)[5] Command: AUTH TLS
2022-11-03 11:14:01.919 INFO Ftp(1)[5] Response: 234 Using authentication type TLS.
2022-11-03 11:14:01.920 DEBUG Ftp(1)[5] Info: Upgrading control connection to TLS.
2022-11-03 11:14:01.964 DEBUG Ftp(1)[5] TLS: Using classic TLS core.
2022-11-03 11:14:01.979 DEBUG Ftp(1)[5] TLS: Enabled cipher suites: 0x000F3DF7EBE00640.
2022-11-03 11:14:02.021 DEBUG Ftp(1)[5] TLS: Applicable cipher suites: 0x000F3DF7EBE00640.
2022-11-03 11:14:02.030 DEBUG Ftp(1)[5] TLS: HandshakeMessage:ClientHello was sent.
2022-11-03 11:14:02.098 DEBUG Ftp(1)[5] TLS: HandshakeMessage:ServerHello was received.
2022-11-03 11:14:02.099 INFO Ftp(1)[5] TLS: Negotiating TLS 1.2, RSA with ephemeral ECDH, AES with 128-bit key in GCM mode, AEAD.
2022-11-03 11:14:02.101 DEBUG Ftp(1)[5] TLS: The server supports secure renegotiation.
2022-11-03 11:14:02.102 DEBUG Ftp(1)[5] TLS: Extended master secret is enabled.
2022-11-03 11:14:02.104 DEBUG Ftp(1)[5] TLS: HandshakeMessage:Certificate was received.
2022-11-03 11:14:02.129 DEBUG Ftp(1)[5] TLS: HandshakeMessage:ServerKeyExchange was received.
2022-11-03 11:14:02.129 DEBUG Ftp(1)[5] TLS: HandshakeMessage:ServerHelloDone was received.
2022-11-03 11:14:02.134 DEBUG Ftp(1)[5] TLS: Verifying server certificate ('CN=ftp.powertrain.local').
2022-11-03 11:14:02.135 DEBUG Ftp(1)[5] TLS: Certificate verification result: Accept
2022-11-03 11:14:02.137 DEBUG Ftp(1)[5] TLS: Verifying server key exchange signature.
2022-11-03 11:14:02.166 DEBUG Ftp(1)[5] TLS: Using ephemeral ECDH public key exchange with NIST P-256 curve.
2022-11-03 11:14:02.173 DEBUG Ftp(1)[5] TLS: HandshakeMessage:ClientKeyExchange was sent.
2022-11-03 11:14:02.184 DEBUG Ftp(1)[5] TLS: CipherSpec:ChangeCipherSpec was sent.
2022-11-03 11:14:02.184 DEBUG Ftp(1)[5] TLS: HandshakeMessage:Finished was sent.
2022-11-03 11:14:02.226 DEBUG Ftp(1)[5] TLS: CipherSpec:ChangeCipherSpec was received.
2022-11-03 11:14:02.228 DEBUG Ftp(1)[5] TLS: HandshakeMessage:Finished was received.
2022-11-03 11:14:02.228 INFO Ftp(1)[5] TLS: Connection secured using cipher: TLS 1.2, RSA with ephemeral ECDH, AES with 128-bit key in GCM mode, AEAD.
2022-11-03 11:14:02.228 DEBUG Ftp(1)[5] Info: Control connection upgraded to TLS 1.2.
2022-11-03 11:14:02.238 INFO Ftp(1)[8] Command: USER SiteUser
2022-11-03 11:14:02.276 INFO Ftp(1)[8] Response: 331 Please, specify the password.
2022-11-03 11:14:02.277 INFO Ftp(1)[8] Command: PASS **********
2022-11-03 11:14:02.905 INFO Ftp(1)[8] Response: 230 Login successful.
2022-11-03 11:14:02.906 INFO Ftp(1)[8] Command: FEAT
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response: 211-Features:
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  MDTM
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  REST STREAM
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  SIZE
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  MLST type*;size*;modify*;perm*;
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  MLSD
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  AUTH SSL
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  AUTH TLS
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  PROT
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  PBSZ
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  UTF8
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  TVFS
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  EPSV
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  EPRT
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response:  MFMT
2022-11-03 11:14:03.027 INFO Ftp(1)[8] Response: 211 End
2022-11-03 11:14:03.048 INFO Ftp(1)[8] Command: OPTS UTF8 ON
2022-11-03 11:14:03.116 INFO Ftp(1)[8] Response: 202 UTF8 mode is always enabled. No need to send this command
2022-11-03 11:14:03.124 DEBUG Ftp(1)[3] Info: Starting data transfer.
2022-11-03 11:14:03.125 INFO Ftp(1)[3] Command: PBSZ 0
2022-11-03 11:14:03.165 INFO Ftp(1)[3] Response: 200 PBSZ=0
2022-11-03 11:14:03.165 INFO Ftp(1)[3] Command: PROT P
2022-11-03 11:14:03.204 INFO Ftp(1)[3] Response: 200 Protection level set to P
2022-11-03 11:14:03.209 INFO Ftp(1)[3] Command: TYPE I
2022-11-03 11:14:03.252 INFO Ftp(1)[3] Response: 200 Type set to I
2022-11-03 11:14:03.255 INFO Ftp(1)[3] Command: PASV
2022-11-03 11:14:03.333 INFO Ftp(1)[3] Response: 227 Entering Passive Mode (40,87,129,115,198,103)
2022-11-03 11:14:03.338 DEBUG Ftp(1)[3] Info: Establishing data connection to 40.87.129.115:50791.
2022-11-03 11:14:03.338 DEBUG Ftp(1)[3] Proxy: Connecting to 40.87.129.115:50791 (no proxy).
2022-11-03 11:14:03.379 DEBUG Ftp(1)[3] Proxy: Connection established.
2022-11-03 11:14:03.380 DEBUG Ftp(1)[3] Info: Established data connection from 192.168.1.24:51315.
2022-11-03 11:14:03.381 INFO Ftp(1)[3] Command: RETR /TestResults10/TestResult1.xls
2022-11-03 11:14:03.419 INFO Ftp(1)[3] Response: 550 Couldn't open the file or directory
2022-11-03 11:14:03.446 DEBUG Ftp(1)[3] Info: Error while starting data transfer: Rebex.Net.FtpException: Couldn't open the file or directory (550).
   at Rebex.Net.Ftp.dhwsl(String p0, Boolean p1, vubkh p2, juebh p3, Int64 p4, FtpTransferState p5)
2022-11-03 11:14:03.446 DEBUG Ftp(1)[3] Info: Error while initializing data connection.
2022-11-03 11:14:03.448 ERROR Ftp(1)[3] Info: Rebex.Net.FtpException: Couldn't open the file or directory (550).
   at Rebex.Net.Ftp.dhwsl(String p0, Boolean p1, vubkh p2, juebh p3, Int64 p4, FtpTransferState p5)
   at Rebex.Net.Ftp.hzaeb(String p0, SeekOrigin p1, Int64 p2)
2022-11-03 11:14:05.409 ERROR Ftp(1)[3] Info: Another operation is pending.
2022-11-03 11:14:06.793 ERROR Ftp(1)[3] Info: Another operation is pending.
by (140 points)
Hi Again

If i Replace the DownloadFile method with the following method (Using GetFileAsync), everything works as expected. So I beleive you have a bug in OpenReadAsync method.

 private async Task DownloadFileUsingGetFile(string ftpFilePath)
        {
            var destinationFolder = @"d:\ftpdownload\";
            var destinationFilePath = Path.Combine(destinationFolder,
            Path.GetFileName(ftpFilePath));

            try
            {
                using (var fileStream = File.Create(destinationFilePath))
                {
                    await ftpClient.GetFileAsync(ftpFilePath, fileStream);
                }

                Console.WriteLine($"{ftpFilePath} was transferred");
            }
            catch (Exception ex)
            {
                Console.WriteLine(ex.ToString());
            }
        }
by (148k points)
Thank! I don't see anything out of the ordinary in the log, and certainly nothing that should prevent you from calling another Ftp method. This might indeed be a bug in GetDownloadStreamAsync. We'll look into it now.
by (140 points)
Sounds good - hope you can replicate the Bug.

But which approach is best to use:

 - GetDownloadStreamAsync

Or

- GetFileAsync

And what are their main differences?
by (148k points)
Both these methods map to FTP protocol's RETR command, they only differ in the API: GetDownloadStream returns a readable stream, from which the application is supposed to read data that is being downloaded from the server; GetFile accepts a writable stream, to which it writes all data downloaded from the server. In some scenarios, one approach might be more suitable than the other, and therefore we provide two kinds of methods for file download.

(Note: This only applies to the Ftp object. In Sftp object (part of Rebex SFTP) offers, these methods differ much more, because GetFile uses request pipelining in order to achieve higher throughput, while GetDownloadStream simply maps each Read call to a single SFTP read request.)
by (140 points)
Ok,

Well, we plan on implementing SFTP support also. But right now, we are struggling to get FTPS work, using the GetDownloadStreamAsync method.

But if I understand you correctly, the GetFile approach would be faster in the SFTP scenario?
by (148k points)
We confirm that there is indeed a bug in Ftp.GetDownloadStreamAsync method. It does not affect Ftp.GetDownloadStream, Ftp.GetFile or Ftp.GetFileAsync. We will fix it for the next release that will be published next week. Thanks for bringing this to our attention, and sorry for the inconvenience!
by (148k points)
Yes, GetFile would be faster than GetDownloadStream in SFTP scenario.
by (148k points)
This has been fixed in Rebex FTP/SSL R6.9: https://www.rebex.net/ftp-ssl.net/history.aspx#R6.9
...