[BUG] FTPS (explicit) is broken since last update

[JesusArmy]

Checks

• [X] I have read the FAQ section, searched the open issues, and still think this is a new bug.

Describe the bug you encountered:

I used to sync my database using FTPS Explicit for years, but after updating to Keepass2android last week I can barely go beyond the loading phase.

Looking at the FTP logs, if I leave it loading it may end up completing the download after about 7 minutes for an 9MB file (from same LAN).

I can download the file instantly when using an ftp client from the same device. And same behavior with another Android phone after updating to last version.

I have cleared data and cache but issue persist. No issue to open same DB through network from a PC as well.

Describe what you expected to happen:

Type DB password, click open and get it sync and open at a few seconds (instead of getting such on DB loading step)

What version of Keepass2Android are you using?

1.10-pre

Which version of Android are you on?

14

[JesusArmy]

Adding some logs from FTP server side to compare download from another client versus Keepass from the same Android device :

Download from LAN, we can see that Keepass download at 42KB/s while the FTPES client is hitting about 15MB/s.

//Download using Keepass2Android
Wed Feb  7 14:17:24 2024 [pid 1979] CONNECT: Client "::ffff:192.168.11.171"
Wed Feb  7 14:17:24 2024 [pid 1978] [ftp_xxx] OK LOGIN: Client "::ffff:192.168.11.171"
Wed Feb  7 14:21:25 2024 [pid 1980] [ftp_xxx] OK DOWNLOAD: Client "::ffff:192.168.11.171", "/KP/KPdb.kdbx", 10142462 bytes, 41.03Kbyte/sec

//Download using another FTP Client (Solid Explorer)
Wed Feb  7 14:26:05 2024 [pid 2266] CONNECT: Client "::ffff:192.168.11.171"
Wed Feb  7 14:26:06 2024 [pid 2265] [ftp_xxx] OK LOGIN: Client "::ffff:192.168.11.171"
Wed Feb  7 14:26:15 2024 [pid 2267] [ftp_xxx] OK DOWNLOAD: Client "::ffff:192.168.11.171", "/KP/KPdb.kdbx", 10142462 bytes, 15450.00Kbyte/sec

[maxim-klsnk]

I have the same problem.

[JesusArmy]

Hey Maxim. Thanks for sharing. Good to know I am now alone. Last 2023 updates advertise more reliable FTP(S), but well... it seems to come with some bugs as well... :sweat_smile:

[PhilippC]

does one of you have a publicly available server on which you can setup an account for testing for me?

[JesusArmy]

Hi Phillipp, Thanks for your reply and interest in our issue. I do not have anonymous access available but I can create you a temp account with a dummy file to try as a test. Where can I send you the address and credential so that it is not public?

[JesusArmy]

Hi Phillipp,

For info I have tried using IPv6 address just in case, and it does not make any difference. Still getting that very slow db download from FTPS.

I would bet that the guilty code part is what have been done in 1.10 pre release to "Improve the FTP and SFTP implementation ".

[JesusArmy]

Not sure I have not seen it before, but I have enabled debig logs in the app and extracted that below. There is a little bit of anonymisation to remove IP and password, but otherwise all logs for the period when it seems to hang is there. (By the way, not sure where to purge logs from the device, not to keen to have a raw txt file on my phone with my ftp password in clear text there).

My assumption of where is the problem is that action, that does not seems to end up as expected and then is repeated multiple time for approx 30 secs: [FluentFTP] Testing connectivity using Socket.Poll()...

Here is the whole logs: (Sorry some logs lines are in French, but that does not seems to be important ones)

---

01/05/2024 01:12:24:487 -- ftp://SETftp_USER:PASSWORD:2#[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx isCached = True 01/05/2024 01:12:24:487 -- LockingActivity: OnActivityResult 01/05/2024 01:12:24:488 -- PasswordActivity.OnActivityResult 874348/1000 01/05/2024 01:12:24:495 -- status message: Initializing... 01/05/2024 01:12:24:496 -- status submessage: 01/05/2024 01:12:24:523 -- status message: Chargement de la base de données… 01/05/2024 01:12:29:707 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:12:44:708 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:12:59:711 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:13:14:712 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:13:29:715 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:13:44:716 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:13:59:716 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:14:14:716 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:14:29:717 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:14:34:530 -- PasswordActivity.OnPause 5 01/05/2024 01:14:34:580 -- PasswordActivity.OnStop 5 01/05/2024 01:14:46:499 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:15:03:247 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:15:20:194 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:15:44:859 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:16:02:387 -- [FluentFTP] Testing connectivity using Socket.Poll()... 01/05/2024 01:16:36:294 -- [FluentFTP] Closing/Disposing FtpSocketStream(control connection) 01/05/2024 01:16:36:295 -- [FluentFTP] Command:  QUIT 01/05/2024 01:16:36:295 -- [FluentFTP] Waiting for response to: QUIT 01/05/2024 01:16:36:296 -- [FluentFTP] FtpClient.Disconnect(): Exception caught and discarded while closing control connection 01/05/2024 01:16:36:296 -- [FluentFTP] Closing/Disposing FtpSocketStream(control connection) 01/05/2024 01:16:36:296 -- [FluentFTP] Closing/Disposing FtpSocketStream(control connection) 01/05/2024 01:16:36:432 -- CFS: Files in Sync 01/05/2024 01:16:36:437 -- Pre-loading database file completed 01/05/2024 01:16:36:477 -- status submessage: Changement de la clé principale… 01/05/2024 01:16:36:529 -- status submessage: Décodage de la base de données… 01/05/2024 01:16:36:530 -- status submessage: Décodage de la base de données… 01/05/2024 01:16:36:531 -- status submessage: Analyse de la base de données… 01/05/2024 01:17:34:525 -- ReadXmlStreamed: 1076ms 01/05/2024 01:17:34:529 -- status submessage: 01/05/2024 01:17:34:530 -- status message: Mise à jour de la sauvegarde locale... 01/05/2024 01:17:34:531 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:540 -- Timeout cancel 01/05/2024 01:17:34:546 -- LoadDB OK 01/05/2024 01:17:34:547 -- Starting/Updating OngoingNotificationsService. Database Unlocked 01/05/2024 01:17:34:564 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:578 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:796 -- SelectCurrentDbActivity.OnStart 1 01/05/2024 01:17:34:800 -- SelectCurrentDbActivity 1: OnActivityResult Ok/1 01/05/2024 01:17:34:800 -- No AppTask in OnActivityResult 01/05/2024 01:17:34:816 -- SelectCurrentDbActivity.OnResume 1 01/05/2024 01:17:34:816 --  DatabaseIsUnlocked=True 1 01/05/2024 01:17:34:817 -- SelectCurrentDbActivity.OnResume 1 01/05/2024 01:17:34:818 --  DatabaseIsUnlocked=True 1 01/05/2024 01:17:34:819 -- SelectCurrentDbActivity.OnPause 1 01/05/2024 01:17:34:825 -- PasswordActivity.OnDestroyTrue 5 01/05/2024 01:17:34:917 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:919 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:928 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:929 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:932 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:933 -- FTP: IocToUri out = ftp://[2400:4050:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx]/Keypass/TokyoSRV.kdbx 01/05/2024 01:17:34:942 -- GroupActivity.OnCreate 6 01/05/2024 01:17:34:942 -- GroupActivity:apptask= 6 01/05/2024 01:17:34:947 -- Loaded task keepass2android.NullTask 01/05/2024 01:17:34:953 -- Task in activity GroupActivity 6 changed to NullTask 01/05/2024 01:17:35:69 -- GroupActivity.OnStart 6 01/05/2024 01:17:35:71 -- GroupActivity.OnResume 6 01/05/2024 01:17:35:71 --  DatabaseIsUnlocked=True 6 01/05/2024 01:17:35:72 -- Timeout cancel 01/05/2024 01:17:35:125 -- GroupActivity.OnPause 6 01/05/2024 01:17:35:125 -- Timeout start 01/05/2024 01:17:35:131 -- SelectCurrentDbActivity.OnStop 1 01/05/2024 01:17:35:172 -- Populating group view False Folder1 01/05/2024 01:17:35:181 -- Populating group view False Folder2 01/05/2024 01:17:35:190 -- Populating group view False Folder3 01/05/2024 01:17:35:202 -- Populating group view False Folder4  01/05/2024 01:17:35:209 -- Populating group view False Recycle Bin 01/05/2024 01:17:35:287 -- GroupActivity.OnStop 6 01/05/2024 01:17:35:347 -- GroupActivity.OnStart 6 01/05/2024 01:17:35:348 -- GroupActivity.OnResume 6 01/05/2024 01:17:35:348 --  DatabaseIsUnlocked=True 6 01/05/2024 01:17:35:349 -- Timeout cancel

---

Hopefully that will help to pin point the issue. Thanks again for the great app and the energy that you are putting into having an open source Keepass version for Android ! :)

[JesusArmy]

It looks like we are affected by this FluentFTP bug here: https://github.com/robinrodricks/FluentFTP/issues/273