laurent22 / joplin

Joplin - the privacy-focused note taking app with sync capabilities for Windows, macOS, Linux, Android and iOS.
https://joplinapp.org
Other
46.35k stars 5.04k forks source link

Mobile: Slow startup when there are many master keys #9331

Open personalizedrefrigerator opened 1 year ago

personalizedrefrigerator commented 1 year ago

Operating system

Android

Joplin version

2.13.7

Desktop version info

No response

Current behaviour

Steps to reproduce:

  1. Acquire a large number of master keys. To do this (on a client with data that can be safely deleted):
    1. Create a note
    2. Enable encryption
    3. Set up a sync target
    4. Sync
    5. Clear the app's data (e.g. uninstall & reinstall)
    6. Repeat steps 1-4 for a different sync target
    7. Repeat steps 1-4 for the original sync target
    8. Repeat steps 1-7 several times
  2. Restart the app
  3. Disable sync
  4. Restart the app

Expected behaviour

Having a large number of master keys (particularly when unused) should not make Joplin slow to start.

On one Android simulator, each master key adds about half of a second to the startup time. On a physical Android device, each master key adds about three seconds to the startup time.

Logs

Below is a modified startup log, with the number of milliseconds since the last log included.

For example,

 INFO  14:14:36: 54: Database was open successfully

means that Database was open successfully was logged at 14:14:36, and 54 milliseconds after the previous log statement.

 LOG  Running "Joplin" with {"rootTag":131}
 INFO  14:26:43: 7: ====================================
 INFO  14:26:43: 63: Starting application net.cozic.joplin-mobile v2.13.7 (dev)
 INFO  14:26:43: 54: Database was open successfully
 INFO  14:26:43: 10: Checking for database schema update...
 INFO  14:26:43: 8: Current database version {"table_fields_version": 44, "version": 44}
 INFO  14:26:43: 34: Upgrading database from version 44
 INFO  14:26:43: 1: New version: 44. Previously recorded version: 44
 INFO  14:26:43: 158: Database is ready.
 INFO  14:26:43: 1: Loading settings...
 LOG  14:26:43: 20: SettingUtils: Loading settings...
 LOG  14:26:43: 81: Setting up recurrent sync with interval 300
 INFO  14:26:43: 1: Recurrent sync operation DISABLED!!!
 INFO  14:26:43: 15: e2ee/utils: activeMasterKeySanityCheck: Active key is an enabled key - nothing to do
 LOG  14:26:43: 3: SettingUtils: Loaded settings!
 INFO  14:26:43: 3: e2ee/utils: Trying to load 6 master keys...
 INFO  14:26:46: 3328: KeychainService: checking if keychain supported
 INFO  14:26:46: 2: KeychainService: check was already done - skipping. Supported: 0
 INFO  14:26:46: 2: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:26:46: 1: Client ID: 42ec64d2c3074580bd2f6579483716b4
 INFO  14:26:46: 2: models/Setting: Applying default migrations...
 INFO  14:26:46: 7: EncryptionService: Loading master key: eaf2284f74364444829e8e49b4818ec2. Make active: true
 INFO  14:26:49: 3320: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:26:50: 2: EncryptionService: Loading master key: d86a45eb982f4f42b1e55d88d18f80d5. Make active: false
 INFO  14:26:53: 3319: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:26:53: 1: EncryptionService: Loading master key: 322216d474654639b91729ef3c901c05. Make active: false
 INFO  14:26:56: 3322: e2ee/utils: findMasterKeyPassword: No master password is defined - trying to get master key specific password
 INFO  14:26:59: 3298: e2ee/utils: findMasterKeyPassword: No master password is defined - trying to get master key specific password
 INFO  14:27:03: 3309: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:27:03: 1: EncryptionService: Loading master key: ab297a18420348cf9216cf0d8618ab28. Make active: false
 INFO  14:27:03: 6: e2ee/utils: Loaded master keys: 4
 LOG  14:27:03: 12: Scheduling sync operation... 10000
 INFO  14:27:03: 3: autodetectTheme: Theme autodetect disabled, not switching theme to match system.
 INFO  14:27:03: 124: PluginAssetsLoader: Assets are up to date. Hash: 0f14c5392fd01275e9aec0841c384482
 INFO  14:27:03: 86: Sync target: 0
 INFO  14:27:03: 6: e2ee/utils: activeMasterKeySanityCheck: Active key is an enabled key - nothing to do
 INFO  14:27:03: 2: e2ee/utils: Trying to load 6 master keys...
 INFO  14:27:03: 6: e2ee/utils: findMasterKeyPassword: No master password is defined - trying to get master key specific password
 INFO  14:27:03: 6: e2ee/utils: findMasterKeyPassword: No master password is defined - trying to get master key specific password
 INFO  14:27:03: 1: e2ee/utils: Loaded master keys: 4
 INFO  14:27:03: 2: Loading folders...
 LOG  14:27:03: 56: Setting up recurrent sync with interval 300
 INFO  14:27:03: 0: Recurrent sync operation DISABLED!!!
 INFO  14:27:03: 28: ResourceFetcher: Auto-add resources: Mode: always
 LOG  14:27:03: 7: Scheduling sync operation... 100
 INFO  14:27:03: 5: RevisionService: runInBackground: Starting background service with revision collection interval 30000
 INFO  RSA Tests: Running integration tests...
 INFO  RSA Tests: Decrypting and encrypting using desktop data...
 INFO  14:27:03: 15: ResourceFetcher: Auto-added resources: 0
 INFO  RSA Tests: Data could be decrypted
 INFO  RSA Tests: Data could be encrypted then decrypted
 INFO  RSA Tests: Decrypting and encrypting using mobile data...
 INFO  RSA Tests: Data could be decrypted
 INFO  RSA Tests: Data could be encrypted then decrypted
 INFO  RSA Tests: Decrypting and encrypting using local data...
 INFO  14:27:03: 97: Preparing scheduled sync
 INFO  14:27:03: 1: Sync cancelled - no sync target is selected.
 INFO  14:27:03: 3: Updating all notifications...
 INFO  14:27:03: 2: Garbage collecting alarms...
 INFO  14:27:04: 554: DecryptionWorker: starting decryption...
 INFO  14:27:04: 48: DecryptionWorker: completed decryption.
 INFO  RSA Tests: Data could be decrypted
 INFO  RSA Tests: Data could be encrypted then decrypted
 INFO  14:27:04: 20: fs-driver-tests: Testing fsDriver.appendFile...
 INFO  14:27:04: 36: fs-driver-tests: Testing fsDriver.writeFile and fsDriver.readFile with utf-8...
 INFO  14:27:04: 32: fs-driver-tests: Testing fsDriver.readFileChunk...
 INFO  14:27:04: 53: fs-driver-tests: Testing fsDriver.tarCreate...
 INFO  14:27:04: 479: Application initialized
 INFO  14:27:04: 4: sensorInfo: Start
 INFO  14:27:04: 1: sensorInfo: security.biometricsEnabled false
 INFO  14:27:05: 150: root: root.biometrics: biometricsDone false
 INFO  14:27:05: 1: root: root.biometrics: biometricsEnabled false
 INFO  14:27:05: 1: root: root.biometrics: shouldShowMainContent true
 INFO  14:27:05: 1: root: root.biometrics: this.state.sensorInfo {"enabled": false, "sensorsHaveChanged": false, "supportedSensors": ""}
 INFO  14:27:06: 1198: autodetectTheme: Theme autodetect disabled, not switching theme to match system.
 INFO  14:27:06: 57: root: root.biometrics: biometricsDone true
 INFO  14:27:06: 1: root: root.biometrics: biometricsEnabled false
 INFO  14:27:06: 1: root: root.biometrics: shouldShowMainContent true
 INFO  14:27:06: 1: root: root.biometrics: this.state.sensorInfo {"enabled": false, "sensorsHaveChanged": false, "supportedSensors": ""}
 INFO  14:27:06: 45: root: Sharing: componentDidUpdate: biometricsDone
 INFO  14:27:06: 158: root: Sharing: received empty share data.
 INFO  14:27:07: 1083: RevisionService: maintenance: Starting...
 INFO  14:27:07: 5: RevisionService: maintenance: Service is enabled
 INFO  14:27:07: 288: RevisionService: collectRevisions: Created revisions for 0 notes
 INFO  14:27:07: 35: RevisionService: maintenance: Done in 328ms

The part of this relevant to master keys decryption:

 INFO  14:26:43: 3: e2ee/utils: Trying to load 6 master keys...
 INFO  14:26:46: 3328: KeychainService: checking if keychain supported
 INFO  14:26:46: 2: KeychainService: check was already done - skipping. Supported: 0
 INFO  14:26:46: 2: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:26:46: 1: Client ID: 42ec64d2c3074580bd2f6579483716b4
 INFO  14:26:46: 2: models/Setting: Applying default migrations...
 INFO  14:26:46: 7: EncryptionService: Loading master key: eaf2284f74364444829e8e49b4818ec2. Make active: true
 INFO  14:26:49: 3320: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:26:50: 2: EncryptionService: Loading master key: d86a45eb982f4f42b1e55d88d18f80d5. Make active: false
 INFO  14:26:53: 3319: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:26:53: 1: EncryptionService: Loading master key: 322216d474654639b91729ef3c901c05. Make active: false
 INFO  14:26:56: 3322: e2ee/utils: findMasterKeyPassword: No master password is defined - trying to get master key specific password
 INFO  14:26:59: 3298: e2ee/utils: findMasterKeyPassword: No master password is defined - trying to get master key specific password
 INFO  14:27:03: 3309: e2ee/utils: findMasterKeyPassword: Using master password
 INFO  14:27:03: 1: EncryptionService: Loading master key: ab297a18420348cf9216cf0d8618ab28. Make active: false
laurent22 commented 1 year ago

Do you know what part of the process makes it slow? Is it because we're decrypting all the master key in startup?

personalizedrefrigerator commented 1 year ago

Do you know what part of the process makes it slow? Is it because we're decrypting all the master key in startup?

That seems to be the case. Applying this patch,

diff --git a/packages/lib/services/e2ee/utils.ts b/packages/lib/services/e2ee/utils.ts
index 38c04bc0c..cd145023a 100644
--- a/packages/lib/services/e2ee/utils.ts
+++ b/packages/lib/services/e2ee/utils.ts
@@ -141,6 +141,10 @@ export async function loadMasterKeysFromSettings(service: EncryptionService) {
    for (let i = 0; i < masterKeys.length; i++) {
        const mk = masterKeys[i];
        if (service.isMasterKeyLoaded(mk)) continue;
+       if (!masterKeyEnabled(mk)) {
+           logger.info(`Skipping disabled master key.`);
+           continue;
+       }

        const password = await findMasterKeyPassword(service, mk);
        if (!password) continue;

then disabling most master keys (requires additional patching), seems to decrease startup time.

Log with all but one key disabled ``` INFO 16:37:42: 7: ==================================== INFO 16:37:42: 71: Starting application net.cozic.joplin-mobile v2.13.7 (dev) INFO 16:37:42: 67: Database was open successfully INFO 16:37:42: 2: Checking for database schema update... INFO 16:37:42: 8: Current database version {"table_fields_version": 44, "version": 44} INFO 16:37:42: 28: Upgrading database from version 44 INFO 16:37:42: 1: New version: 44. Previously recorded version: 44 INFO 16:37:42: 153: Database is ready. INFO 16:37:42: 1: Loading settings... LOG 16:37:42: 20: SettingUtils: Loading settings... LOG 16:37:42: 74: Setting up recurrent sync with interval 300 INFO 16:37:42: 1: Recurrent sync operation DISABLED!!! INFO 16:37:42: 20: e2ee/utils: activeMasterKeySanityCheck: Active key is an enabled key - nothing to do LOG 16:37:42: 2: SettingUtils: Loaded settings! INFO 16:37:42: 4: e2ee/utils: Trying to load 6 master keys... INFO 16:37:45: 3321: KeychainService: checking if keychain supported INFO 16:37:45: 1: KeychainService: check was already done - skipping. Supported: 0 INFO 16:37:45: 3: e2ee/utils: findMasterKeyPassword: Using master password INFO 16:37:45: 1: Client ID: 42ec64d2c3074580bd2f6579483716b4 INFO 16:37:45: 1: models/Setting: Applying default migrations... INFO 16:37:45: 7: EncryptionService: Loading master key: eaf2284f74364444829e8e49b4818ec2. Make active: true INFO 16:37:45: 7: e2ee/utils: Skipping disabled master key. INFO 16:37:45: 1: e2ee/utils: Skipping disabled master key. INFO 16:37:45: 1: e2ee/utils: Skipping disabled master key. INFO 16:37:45: 1: e2ee/utils: Skipping disabled master key. INFO 16:37:45: 0: e2ee/utils: Skipping disabled master key. INFO 16:37:45: 1: e2ee/utils: Loaded master keys: 1 LOG 16:37:45: 9: Scheduling sync operation... 10000 INFO 16:37:45: 3: autodetectTheme: Theme autodetect disabled, not switching theme to match system. INFO 16:37:45: 123: PluginAssetsLoader: Assets are up to date. Hash: 0f14c5392fd01275e9aec0841c384482 INFO 16:37:46: 93: Sync target: 0 INFO 16:37:46: 6: e2ee/utils: activeMasterKeySanityCheck: Active key is an enabled key - nothing to do INFO 16:37:46: 2: e2ee/utils: Trying to load 6 master keys... INFO 16:37:46: 1: e2ee/utils: Skipping disabled master key. INFO 16:37:46: 1: e2ee/utils: Skipping disabled master key. INFO 16:37:46: 0: e2ee/utils: Skipping disabled master key. INFO 16:37:46: 1: e2ee/utils: Skipping disabled master key. INFO 16:37:46: 0: e2ee/utils: Skipping disabled master key. INFO 16:37:46: 2: e2ee/utils: Loaded master keys: 1 INFO 16:37:46: 2: Loading folders... LOG 16:37:46: 58: Setting up recurrent sync with interval 300 INFO 16:37:46: 0: Recurrent sync operation DISABLED!!! INFO 16:37:46: 30: ResourceFetcher: Auto-add resources: Mode: always LOG 16:37:46: 7: Scheduling sync operation... 100 INFO 16:37:46: 4: RevisionService: runInBackground: Starting background service with revision collection interval 30000 INFO RSA Tests: Running integration tests... INFO RSA Tests: Decrypting and encrypting using desktop data... INFO 16:37:46: 17: ResourceFetcher: Auto-added resources: 0 INFO RSA Tests: Data could be decrypted INFO RSA Tests: Data could be encrypted then decrypted INFO RSA Tests: Decrypting and encrypting using mobile data... INFO RSA Tests: Data could be decrypted INFO RSA Tests: Data could be encrypted then decrypted INFO RSA Tests: Decrypting and encrypting using local data... INFO 16:37:46: 91: Preparing scheduled sync INFO 16:37:46: 1: Sync cancelled - no sync target is selected. INFO 16:37:46: 4: Updating all notifications... INFO 16:37:46: 2: Garbage collecting alarms... INFO 16:37:46: 569: DecryptionWorker: starting decryption... INFO RSA Tests: Data could be decrypted INFO RSA Tests: Data could be encrypted then decrypted INFO 16:37:46: 24: fs-driver-tests: Testing fsDriver.appendFile... INFO 16:37:46: 47: fs-driver-tests: Testing fsDriver.writeFile and fsDriver.readFile with utf-8... INFO 16:37:46: 3: DecryptionWorker: completed decryption. INFO 16:37:46: 36: fs-driver-tests: Testing fsDriver.readFileChunk... INFO 16:37:46: 52: fs-driver-tests: Testing fsDriver.tarCreate... INFO 16:37:47: 482: Application initialized INFO 16:37:47: 3: sensorInfo: Start INFO 16:37:47: 2: sensorInfo: security.biometricsEnabled false INFO 16:37:47: 145: root: root.biometrics: biometricsDone false INFO 16:37:47: 2: root: root.biometrics: biometricsEnabled false INFO 16:37:47: 1: root: root.biometrics: shouldShowMainContent true INFO 16:37:47: 0: root: root.biometrics: this.state.sensorInfo {"enabled": false, "sensorsHaveChanged": false, "supportedSensors": ""} INFO 16:37:48: 1166: autodetectTheme: Theme autodetect disabled, not switching theme to match system. INFO 16:37:48: 56: root: root.biometrics: biometricsDone true INFO 16:37:48: 1: root: root.biometrics: biometricsEnabled false INFO 16:37:48: 1: root: root.biometrics: shouldShowMainContent true INFO 16:37:48: 0: root: root.biometrics: this.state.sensorInfo {"enabled": false, "sensorsHaveChanged": false, "supportedSensors": ""} INFO 16:37:48: 46: root: Sharing: componentDidUpdate: biometricsDone INFO 16:37:49: 177: root: Sharing: received empty share data. INFO 16:37:50: 1104: RevisionService: maintenance: Starting... INFO 16:37:50: 13: RevisionService: maintenance: Service is enabled INFO 16:37:50: 257: RevisionService: collectRevisions: Created revisions for 0 notes INFO 16:37:50: 51: RevisionService: maintenance: Done in 321ms ```
personalizedrefrigerator commented 1 year ago

Another option might be to store unlocked master keys encrypted with a library like expo-secure-store.

Loading master keys from expo-secure-store (or a similar library) may be faster than decrypting keys on each startup with sjcl.

github-actions[bot] commented 11 months ago

Hey there, it looks like there has been no activity on this issue recently. Has the issue been fixed, or does it still require the community's attention? If you require support or are requesting an enhancement or feature then please create a topic on the Joplin forum. This issue may be closed if no further activity occurs. You may comment on the issue and I will leave it open. Thank you for your contributions.

github-actions[bot] commented 10 months ago

Hey there, it looks like there has been no activity on this issue recently. Has the issue been fixed, or does it still require the community's attention? If you require support or are requesting an enhancement or feature then please create a topic on the Joplin forum. This issue may be closed if no further activity occurs. You may comment on the issue and I will leave it open. Thank you for your contributions.