Rodolfo
Rodolfo

Reputation: 51

Incomplete file download on Android emulator

I'm facing a very strange problem. I've a simple Xamarin test app that downloads a single zip file (around 1.5MB) from our public FTP Server (Cerberus). The downloaded file is always missing a small random number of bytes. The app runs on the Android emulator installed from Visual Studio 2019 (it's a clean installation on Win10 and VS2019; on the machine resides also Android Studio Giraffe), and uses the Rebex library. I've tried with Rebex.Net v5.5, v6.0 and v6.2, and also running Android 7,9 and 11 on different emulator devices with the very same result. If I run the same app on a real device (or I compile the same code for Windows, Net Framework 4.8) the problem disappear. Obviously there are no exceptions, and enabling the verbose log of the Rebex library I can see each data packet (ranging randomly from 1440 to 65536 bytes) correctly received. This is the piece of code from the Android app (the same code without modification runs on Windows) that downloads the file:

using Rebex.Net;
    
private void ConnectSync()
    {
        tbLocalSize.Text = "";
        tbRemoteSize.Text = "";

        Ftp ftp = new Ftp();

        try
        {
            ftp.Connect("ftp.siafield.it");
        }
        catch (Exception connEx)
        {
            return;
        }

        try
        {
            ftp.Login("my-username", "my-password");
            ftp.ChangeDirectory("my-test-dir");
            ftp.ChangeDirectory("tx");

            string fDest = Path.Combine(_baseDir, "sede011.000");
            long remSize = ftp.GetFileLength("sede011.000");

            ftp.Download("sede011.000", _baseDir, Rebex.IO.TraversalMode.NonRecursive, Rebex.IO.TransferMethod.Copy, Rebex.IO.ActionOnExistingFiles.OverwriteAll);

            FileInfo fi = new FileInfo(fDest);

            tbRemoteSize.Text = remSize.ToString();
            tbLocalSize.Text = fi.Length.ToString();
        }
        catch (Exception loginEx)
        {
            return;
        }
        finally
        {
            ftp.Disconnect();
        }
    }

This is an excerpt from the log (verbose log from the Rebex library) of the real app, where I try to download the same file from the same server (I've skipped most of the packet lines between the start and the end of the download):

20230927 09:54:49:062 - DownloadFile, download del file remoto sede011.000 in /storage/emulated/0/Android/obb/it.sia.siatecmobile/rx/sede011.000, 1474169 bytes
20230927 09:54:49:066 - 20230927 09:54:49.066 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Sent data over control connection: , offset=0, length=18
20230927 09:54:49:067 - 20230927 09:54:49.067 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Command, message=SIZE sede011.000
20230927 09:54:49:091 - 20230927 09:54:49.090 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received data over control connection: , offset=0, length=13
20230927 09:54:49:091 - 20230927 09:54:49.091 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Response, message=213 1474169
20230927 09:54:49:093 - 20230927 09:54:49.092 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Starting data transfer.
20230927 09:54:49:093 - 20230927 09:54:49.093 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Sent data over control connection: , offset=0, length=6
20230927 09:54:49:094 - 20230927 09:54:49.094 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Command, message=PASV
20230927 09:54:49:123 - 20230927 09:54:49.123 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received data over control connection: , offset=0, length=48
20230927 09:54:49:124 - 20230927 09:54:49.124 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Response, message=227 Entering Passive Mode (5,249,135,22,47,67)
20230927 09:54:49:124 - 20230927 09:54:49.124 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Establishing data connection to 5.249.135.22:12099.
20230927 09:54:49:125 - 20230927 09:54:49.125 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Proxy, message=Connecting to 5.249.135.22:12099 (no proxy).
20230927 09:54:49:155 - 20230927 09:54:49.155 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Proxy, message=Connection established.
20230927 09:54:49:155 - 20230927 09:54:49.155 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Established data connection from 192.168.232.2:50896.
20230927 09:54:49:156 - 20230927 09:54:49.156 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Sent data over control connection: , offset=0, length=18
20230927 09:54:49:156 - 20230927 09:54:49.156 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Command, message=RETR sede011.000
20230927 09:54:49:173 - 20230927 09:54:49.173 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received data over control connection: , offset=0, length=29
20230927 09:54:49:174 - 20230927 09:54:49.173 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Response, message=150 Opening data connection
20230927 09:54:49:174 - 20230927 09:54:49.174 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Data transfer started.
20230927 09:54:49:175 - 20230927 09:54:49.174 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:50:343 - 20230927 09:54:50.342 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 1440 bytes of data through data connection.
20230927 09:54:50:344 - 20230927 09:54:50.344 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:50:345 - 20230927 09:54:50.344 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 46080 bytes of data through data connection.
20230927 09:54:50:345 - 20230927 09:54:50.345 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:50:346 - 20230927 09:54:50.346 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 45672 bytes of data through data connection.
20230927 09:54:50:347 - 20230927 09:54:50.347 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:50:401 - 20230927 09:54:50.400 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 5760 bytes of data through data connection.
20230927 09:54:50:402 - 20230927 09:54:50.402 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:50:403 - 20230927 09:54:50.403 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 1300 bytes of data through data connection.
20230927 09:54:50:404 - 20230927 09:54:50.403 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:50:499 - 20230927 09:54:50.499 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 5760 bytes of data through data connection.
....
20230927 09:54:51:548 - 20230927 09:54:51.547 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:51:548 - 20230927 09:54:51.548 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 52351 bytes of data through data connection.
20230927 09:54:51:549 - 20230927 09:54:51.549 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:51:549 - 20230927 09:54:51.549 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 28800 bytes of data through data connection.
20230927 09:54:51:550 - 20230927 09:54:51.550 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:51:550 - 20230927 09:54:51.550 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 31679 bytes of data through data connection.
20230927 09:54:51:551 - 20230927 09:54:51.551 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:51:552 - 20230927 09:54:51.551 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received 18725 bytes of data through data connection.
20230927 09:54:51:552 - 20230927 09:54:51.552 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Checking incoming data.
20230927 09:54:51:553 - 20230927 09:54:51.552 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Data transfer ended. 1474167 bytes transferred.
20230927 09:54:51:554 - 20230927 09:54:51.553 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Closing downloading data connection.
20230927 09:54:51:554 - 20230927 09:54:51.554 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Waiting for data transfer ending message.
20230927 09:54:51:555 - 20230927 09:54:51.554 - Log level=Verbose, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Received data over control connection: , offset=0, length=23
20230927 09:54:51:555 - 20230927 09:54:51.555 - Log level=Info, objectType=Rebex.Net.Ftp, objectId=1, area=Response, message=226 Transfer complete
20230927 09:54:51:555 - 20230927 09:54:51.555 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Data transfer ended.
20230927 09:54:51:556 - 20230927 09:54:51.556 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Transfer ended successfully.
20230927 09:54:51:556 - 20230927 09:54:51.556 - Log level=Debug, objectType=Rebex.Net.Ftp, objectId=1, area=Info, message=Data connection closed.
20230927 09:54:51:567 - DownloadFile, dimensione non corrispondente (1474167/1474169)

The last line is my check on the downloaded file size against the remote file size retrieved from the FTP server. Using the async version of the calls to the FTP object leads to the same result. It's not a big deal for now, as the app is not on development at this time, I was just moving from C1.Zip to System.IO.Compression for the zip file handling. Any suggestion would be appreciated.

Upvotes: 0

Views: 94

Answers (0)

Related Questions