Keepass2android: Opening behavior issue on 1.07-pre2

[Karreg]

With latest version, I have a bad behavior when opening DB.
Here is the behavior:
Open the app
Try to open DB by either fingerprint or password (though the second method can't be achieved on OnePlus 6T because of fingerprint reader, and no screenshot possible)
The app will load the DB. Forever. I can wait for 5 minutes it will still load. Here is the issue.
Then the workaround is random.
Quit the app and restart it, the DB will be open
Or, it will all for password again, return to previous step
Or it will say that the DB is already loaded, and it will need another restart of app...

I can give more information later if needed. I'm writing it from my phone, with kids around...

[upD8R]

HI, I can confirm a strange loading behavior, too (OnePLus 6).
In hangs for around 30s in "Lade Datenbank ... (Führe Schlüsselformationen durch ...)" but then it starts, so not totally equal to Karreg's comment. Qick unlock works as expected.

Some log, not sure if it helps.

05.12.2018 10:26:33:812 -- KeePass.OnCreate 05.12.2018 10:26:33:813 -- KeePass:apptask= 05.12.2018 10:26:33:813 -- Loaded task keepass2android.NullTask 05.12.2018 10:26:33:813 -- KeePass.OnCreate 05.12.2018 10:26:33:817 -- KeePass.OnStart 05.12.2018 10:26:33:817 -- KeePass.OnStart 05.12.2018 10:26:33:864 -- Loaded task keepass2android.NullTask 05.12.2018 10:26:33:892 -- FileSelect.OnCreate 05.12.2018 10:26:33:915 -- FileSelect.OnStart 05.12.2018 10:26:33:947 -- PasswordActivity.OnCreate 05.12.2018 10:26:33:947 -- PasswordActivity:apptask= 05.12.2018 10:26:34:19 -- PasswordActivity.OnStart 05.12.2018 10:26:34:20 -- PasswordActivity.OnResume 05.12.2018 10:26:34:21 -- DB null 05.12.2018 10:26:34:21 -- starting: True, Finishing: False, _performingLoad: False 05.12.2018 10:26:34:23 -- Pre-loading database file starting 05.12.2018 10:26:34:23 -- CFS: OpenWhenNoLocalChanges 05.12.2018 10:26:34:24 -- CFS: hashing cached version 05.12.2018 10:26:34:30 -- PasswordActivity.OnPause 05.12.2018 10:26:34:123 -- PasswordActivity.OnResume 05.12.2018 10:26:34:123 -- DB null 05.12.2018 10:26:34:124 -- starting: False, Finishing: False, _performingLoad: False 05.12.2018 10:26:34:125 -- FP: Create FingerprintDecryption 05.12.2018 10:26:34:127 -- FP: Init for Dec 05.12.2018 10:26:34:148 -- FP: StartListening 05.12.2018 10:26:34:179 -- FileSelect.OnStop 05.12.2018 10:26:34:229 -- FileSelect.OnDestroyTrue 05.12.2018 10:26:34:230 -- KeePass.OnStop 05.12.2018 10:26:34:231 -- KeePass.OnDestroyTrue 05.12.2018 10:26:34:231 -- KeePass.OnDestroyTrue 05.12.2018 10:26:35:105 -- CFS: Files in Sync 05.12.2018 10:26:35:107 -- Pre-loading database file completed 05.12.2018 10:26:37:523 -- FP: OnAuthenticationSucceeded 05.12.2018 10:26:37:523 -- FP: StopListening 05.12.2018 10:26:37:526 -- FP: Decrypting 05.12.2018 10:26:38:104 -- LockingActivity: OnActivityResult 05.12.2018 10:26:38:105 -- PasswordActivity.OnActivityResult 874348/1000 05.12.2018 10:26:38:147 -- com.keepassdroid.crypto.finalkey.NativeFinalKey 05.12.2018 10:27:03:203 -- ReadXmlStreamed: 283ms 05.12.2018 10:27:03:224 -- LoadDB OK 05.12.2018 10:27:03:238 -- Starting/Updating OngoingNotificationsService. Database Unlocked 05.12.2018 10:27:03:342 -- PasswordActivity.OnPause 05.12.2018 10:27:03:342 -- Timeout start 05.12.2018 10:27:03:353 -- StackBaseActivity.OnActivityResult Ok/1 05.12.2018 10:27:03:354 -- No AppTask in OnActivityResult 05.12.2018 10:27:03:416 -- GroupActivity.OnCreate 05.12.2018 10:27:03:417 -- GroupActivity:apptask= 05.12.2018 10:27:03:419 -- Loaded task keepass2android.NullTask 05.12.2018 10:27:03:442 -- GroupActivity.OnStart 05.12.2018 10:27:03:442 -- GroupActivity.OnResume 05.12.2018 10:27:03:443 -- DatabaseIsUnlocked=True 05.12.2018 10:27:03:443 -- Timeout cancel 05.12.2018 10:27:03:983 -- PasswordActivity.OnStop 05.12.2018 10:27:03:984 -- PasswordActivity.OnDestroyTrue 05.12.2018 10:27:11:526 -- GroupActivity.OnPause 05.12.2018 10:27:11:527 -- Timeout start 05.12.2018 10:27:11:557 -- DatabaseSettingsActivity.OnCreate 05.12.2018 10:27:11:558 -- DatabaseSettingsActivity:apptask= 05.12.2018 10:27:11:602 -- DatabaseSettingsActivity.OnStart 05.12.2018 10:27:11:603 -- DatabaseSettingsActivity.OnResume 05.12.2018 10:27:11:603 -- DatabaseIsUnlocked=True 05.12.2018 10:27:11:604 -- Timeout cancel 05.12.2018 10:27:12:63 -- GroupActivity.OnStop 05.12.2018 10:27:16:839 -- DatabaseSettingsActivity.OnPause 05.12.2018 10:27:16:840 -- Timeout start 05.12.2018 10:27:16:864 -- GroupActivity.OnStart 05.12.2018 10:27:16:865 -- GroupActivity.OnResume 05.12.2018 10:27:16:866 -- DatabaseIsUnlocked=True 05.12.2018 10:27:16:866 -- Timeout cancel 05.12.2018 10:27:17:318 -- DatabaseSettingsActivity.OnStop 05.12.2018 10:27:17:320 -- DatabaseSettingsActivity.OnDestroyTrue 05.12.2018 10:27:25:132 -- GroupActivity.OnPause 05.12.2018 10:27:25:133 -- Timeout start 05.12.2018 10:27:25:173 -- DatabaseSettingsActivity.OnCreate 05.12.2018 10:27:25:174 -- DatabaseSettingsActivity:apptask= 05.12.2018 10:27:25:208 -- DatabaseSettingsActivity.OnStart 05.12.2018 10:27:25:209 -- DatabaseSettingsActivity.OnResume 05.12.2018 10:27:25:209 -- DatabaseIsUnlocked=True 05.12.2018 10:27:25:209 -- Timeout cancel 05.12.2018 10:27:25:647 -- GroupActivity.OnStop 05.12.2018 10:27:26:231 -- DatabaseSettingsActivity.OnPause 05.12.2018 10:27:26:231 -- Timeout start 05.12.2018 10:27:26:790 -- DatabaseSettingsActivity.OnStop 05.12.2018 10:27:38:638 -- DatabaseSettingsActivity.OnStart 05.12.2018 10:27:38:639 -- DatabaseSettingsActivity.OnResume 05.12.2018 10:27:38:640 -- DatabaseIsUnlocked=True 05.12.2018 10:27:38:640 -- Timeout cancel

[Karreg]

You're right, I was not waiting long enough. I guess the 5 minutes were because of multiple attempts. Or it happened randomly once. On my side it was precisely 45 seconds to open the database, where it was only 5-10 seconds with previous version.
So yeah, it seems to be an issue on loading performance?

[Karreg]

Here is my log, quite the same...

05/12/2018 11:31:21:187 -- Creating application keepass2android.keepass2android. Version=129
05/12/2018 11:31:21:255 -- KeePass.OnCreate
05/12/2018 11:31:21:257 -- KeePass:apptask=
05/12/2018 11:31:21:260 -- Loaded task keepass2android.NullTask
05/12/2018 11:31:21:261 -- KeePass.OnCreate
05/12/2018 11:31:21:272 -- KeePass.OnStart
05/12/2018 11:31:21:273 -- KeePass.OnStart
05/12/2018 11:31:21:334 -- Loaded task keepass2android.NullTask
05/12/2018 11:31:21:378 -- FileSelect.OnCreate
05/12/2018 11:31:21:458 -- FileSelect.OnStart
05/12/2018 11:31:21:529 -- FileSelect.OnResume
05/12/2018 11:31:21:621 -- KeePass.OnStop
05/12/2018 11:31:21:622 -- KeePass.OnDestroyTrue
05/12/2018 11:31:21:622 -- KeePass.OnDestroyTrue
05/12/2018 11:31:22:961 -- FileSelect.OnPause
05/12/2018 11:31:22:980 -- FSSA.OnCreate
05/12/2018 11:31:23:449 -- FileSelect.OnStop
05/12/2018 11:31:23:899 -- PasswordActivity.OnCreate
05/12/2018 11:31:23:900 -- PasswordActivity:apptask=
05/12/2018 11:31:24:74 -- PasswordActivity.OnStart
05/12/2018 11:31:24:80 -- PasswordActivity.OnResume
05/12/2018 11:31:24:80 --  DB null
05/12/2018 11:31:24:81 -- starting: True, Finishing: False, _performingLoad: False
05/12/2018 11:31:24:98 -- Pre-loading database file starting
05/12/2018 11:31:24:102 -- PasswordActivity.OnPause
05/12/2018 11:31:24:104 -- CFS: OpenWhenNoLocalChanges
05/12/2018 11:31:24:105 -- CFS: hashing cached version
05/12/2018 11:31:24:177 -- PasswordActivity.OnResume
05/12/2018 11:31:24:178 --  DB null
05/12/2018 11:31:24:178 -- starting: False, Finishing: False, _performingLoad: False
05/12/2018 11:31:24:186 -- FP: Create FingerprintDecryption
05/12/2018 11:31:24:191 -- FP: Init for Dec
05/12/2018 11:31:24:219 -- FP: StartListening 
05/12/2018 11:31:24:594 -- FileSelect.OnDestroyTrue
05/12/2018 11:31:25:328 -- CFS: Files in Sync
05/12/2018 11:31:25:332 -- Pre-loading database file completed
05/12/2018 11:31:26:941 -- FP: OnAuthenticationSucceeded 
05/12/2018 11:31:26:946 -- FP: StopListening 
05/12/2018 11:31:26:956 -- FP: Decrypting 
05/12/2018 11:31:27:744 -- PasswordActivity.OnPause
05/12/2018 11:31:27:774 -- FSSA.OnCreate
05/12/2018 11:31:27:834 -- LockingActivity: OnActivityResult 
05/12/2018 11:31:27:836 -- PasswordActivity.OnActivityResult 874348/1000
05/12/2018 11:31:27:851 -- PasswordActivity.OnResume
05/12/2018 11:31:27:851 --  DB null
05/12/2018 11:31:27:852 -- starting: False, Finishing: False, _performingLoad: True
05/12/2018 11:31:27:855 -- FP: Create FingerprintDecryption
05/12/2018 11:31:27:856 -- FP: Init for Dec
05/12/2018 11:31:27:879 -- FP: StartListening 
05/12/2018 11:31:27:987 -- com.keepassdroid.crypto.finalkey.NativeFinalKey
05/12/2018 11:32:12:313 -- ReadXmlStreamed: 400ms
05/12/2018 11:32:12:354 -- LoadDB OK
05/12/2018 11:32:12:373 -- Starting/Updating OngoingNotificationsService. Database Unlocked
05/12/2018 11:32:12:546 -- FP: StopListening 
05/12/2018 11:32:12:548 -- PasswordActivity.OnPause
05/12/2018 11:32:12:552 -- Timeout start
05/12/2018 11:32:12:577 -- FP: OnAuthenticationError: Opération d'empreinte numérique annulée., True
05/12/2018 11:32:12:580 -- StackBaseActivity.OnActivityResult Ok/1
05/12/2018 11:32:12:581 -- No AppTask in OnActivityResult
05/12/2018 11:32:12:730 -- GroupActivity.OnCreate
05/12/2018 11:32:12:730 -- GroupActivity:apptask=
05/12/2018 11:32:12:733 -- Loaded task keepass2android.NullTask
05/12/2018 11:32:12:787 -- GroupActivity.OnStart
05/12/2018 11:32:12:789 -- GroupActivity.OnResume
05/12/2018 11:32:12:789 --  DatabaseIsUnlocked=True
05/12/2018 11:32:12:790 -- Timeout cancel
05/12/2018 11:32:13:382 -- PasswordActivity.OnStop
05/12/2018 11:32:13:386 -- PasswordActivity.OnDestroyTrue
05/12/2018 11:32:18:537 -- GroupActivity.OnPause
05/12/2018 11:32:18:539 -- Timeout start
05/12/2018 11:32:18:564 -- DatabaseSettingsActivity.OnCreate
05/12/2018 11:32:18:565 -- DatabaseSettingsActivity:apptask=
05/12/2018 11:32:18:643 -- DatabaseSettingsActivity.OnStart
05/12/2018 11:32:18:644 -- DatabaseSettingsActivity.OnResume
05/12/2018 11:32:18:644 --  DatabaseIsUnlocked=True
05/12/2018 11:32:18:645 -- Timeout cancel
05/12/2018 11:32:19:101 -- GroupActivity.OnStop

We can see the 45 seconds hole:

05/12/2018 11:31:27:987 -- com.keepassdroid.crypto.finalkey.NativeFinalKey
05/12/2018 11:32:12:313 -- ReadXmlStreamed: 400ms

There's something that could have an impact. When the fingerprint is read, the fingerprint indicator stays visible while the DB is loading. This indicates that the fingerprint can still be read by the app, where it shouldn't be needed anymore. Maybe there's something that was done before and not anymore, or the opposite?

What is ringing a bell to me is this line:

05/12/2018 11:32:12:577 -- FP: OnAuthenticationError: Opération d'empreinte numérique annulée., True

It means something like Numeric (or Digital) Fingerprint operation cancelled and I guess this is a system callback result...

[PhilippC]

I can't say where this comes from at the moment. Are you using Yubikeys to unlock the database?

[upD8R]

Not for me. Plain password plus fingerprint. But it's not related to FP, same delay happens with direct password login.
It just came with latest beta. Interestingly, 2 complaints from OnePlus owners ..

[DDoSolitary]

I got a similar problem on Redmi 5 Plus, Resurrection Remix 8.1. The DB is loading forever. I'm not using Yubikey, and this happens no matter I use password or fingerprint.

[PhilippC]

I only asked because Yubikey handling was the major change I implemented. But I now found that it might be an issue with the way Google is deploying that new apk. I'm still investigating...

[PhilippC]

just published 1.07-pre3 which hopefully fixes the issue. I'm not sure yet because I need to download myself first, but I found something I could change in the build process.

[upD8R]

Works for me! Excellent support, thanks!

[Karreg]

Fix confirmed! Great job! And another beer for you! ;)

[upD8R]

Hi there, I believe this issue appears again with 1.07-pre4.

[Karreg]

Confirmed. And we can't get logs because there's a regression on sharing logs feature too. Makes the app crashing... 🙁

[PhilippC]

sorry, my bad. Looks like the change to fix the problem in pre3 never was commited to the repo and then got reverted. pre5 is now being rolled out in the beta channel.

[Karreg]

Great, thanks! :)
Have you ever considered using CI to build your releases to avoid that? Anything could prevent that?