Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
personalizedrefrigerator opened this issue Nov 16, 2023 · 5 comments
Open

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

personalizedrefrigerator opened this issue Nov 16, 2023 · 5 comments
Labels
bug It's a bug medium Medium priority issues mobile All mobile platforms

Comments

@personalizedrefrigerator
Copy link
Collaborator

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
Copy link
Owner

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

@personalizedrefrigerator
Copy link
Collaborator Author

personalizedrefrigerator commented Nov 16, 2023

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
Copy link
Collaborator Author

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.

Copy link
Contributor

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 github-actions bot added the stale An issue that hasn't been active for a while... label Dec 17, 2023
@personalizedrefrigerator personalizedrefrigerator removed the stale An issue that hasn't been active for a while... label Dec 22, 2023
Copy link
Contributor

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 github-actions bot added the stale An issue that hasn't been active for a while... label Jan 22, 2024
@personalizedrefrigerator personalizedrefrigerator removed the stale An issue that hasn't been active for a while... label Jan 22, 2024
@laurent22 laurent22 added the medium Medium priority issues label Jan 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug It's a bug medium Medium priority issues mobile All mobile platforms
Projects
None yet
Development

No branches or pull requests

2 participants