Freeze on launch, long delays caused by `ipcRenderer.sendSync` in `ElectronRendererSecureStorageService`

[eihli]

Synchronous calls to indefinitely blocking functions

1. electronRendererSecureStorage calls ipcRenderer.sendSync with the keytar message of getPassword.
2. keytarStorageListener hears the keytar message and awaits a call to getPassword from the keytar package https://github.com/atom/node-keytar/blob/master/src/keytar_posix.cc#L49
3. keytar's getPassword calls libsecret's secret_password_lookup_sync https://developer.gnome.org/libsecret/unstable/libsecret-Password-storage.html#secret-password-lookup-sync
4. libsecret's secret_password_lookup_sync has the note "This method may block indefinitely and should not be used in user interface threads."
5. My computer wasn't running a Secret Service implementation https://specifications.freedesktop.org/secret-service/latest/
6. Running gnome-keyring-daemon --start --components=secret results in the application not freezing.

Remaining questions

• ~~Why is this a problem in the desktop application but not the browser plugin?~~ Of course... the browser doesn't use Electron, so wouldn't use ElectronRendererSecureStorage. It uses the browser's secure storage service. And I suppose the browser's storage service differs in keytar in some way such that it doesn't block. Does the browser's storage service not rely on a secrets service? Or does the browser's storage service use async calls to the secrets service? Is this an upstream issue? Should keytar offer an async option?
• Is this something that can be "fixed" in Bitwarden's code?
• If it can't be fixed, should there be documentation and a warning message displayed if a user isn't running a secret's service?

Possible path towards solution

Here's a grep of every synchronous call to secureStorageService.

I imagine it's not safe to just remove the await from all of these. What would the implications be? Race conditions? Something like: we're waiting to retrieve a key and while we're waiting a user logs in and changes the value, then our async code completes with the old stale key and continues with that outdated value?

These are all wrapped in a shouldStoreKey call. Maybe shouldStoreKey can check to see if a secrets service is running?

➜  desktop git:(rc) ✗ rg -C 3 'await.*secureStorageService\.(get|has|save|remove)' .
./jslib/common/src/services/crypto.service.ts
296-    }
297-
298-    async clearStoredKey(keySuffix: KeySuffixOptions) {
299:        await this.secureStorageService.remove(Keys.key, { keySuffix: keySuffix });
300-    }
301-
302-    clearKeyHash(): Promise<any> {

./jslib/electron/src/services/electronCrypto.service.ts
21-
22-    protected async storeKey(key: SymmetricCryptoKey) {
23-        if (await this.shouldStoreKey('auto')) {
24:            await this.secureStorageService.save(Keys.key, key.keyB64, { keySuffix: 'auto' });
25-        } else {
26-            this.clearStoredKey('auto');
27-        }
28-
29-        if (await this.shouldStoreKey('biometric')) {
30:            await this.secureStorageService.save(Keys.key, key.keyB64, { keySuffix: 'biometric' });
31-        } else {
32-            this.clearStoredKey('biometric');
33-        }
--
44-     */
45-    private async upgradeSecurelyStoredKey() {
46-        // attempt key upgrade, but if we fail just delete it. Keys will be stored property upon unlock anyway.
47:        const key = await this.secureStorageService.get<string>(Keys.key);
48-
49-        if (key == null) {
50-            return;
--
52-
53-        try {
54-            if (await this.shouldStoreKey('auto')) {
55:                await this.secureStorageService.save(Keys.key, key, { keySuffix: 'auto' });
56-            }
57-            if (await this.shouldStoreKey('biometric')) {
58:                await this.secureStorageService.save(Keys.key, key, { keySuffix: 'biometric' });
59-            }
60-        } catch (e) {
61-            this.logService.error(`Encountered error while upgrading obsolete Bitwarden secure storage item:`);
62-            this.logService.error(e);
63-        }
64-
65:        await this.secureStorageService.remove(Keys.key);
66-    }
67-}

There's a lot of noisy notes below here that can mostly be ignored. I'm leaving them as historical reference of troubleshooting steps and wrong turns.

---

Begin original message:

I just built a fresh AppImage using (commit 392d7b7638c86c4c757e49ba4580dbfc4e92fcca (HEAD -> rc, origin/rc)) and I'm getting this exception.

➜  desktop git:(rc) dist/Bitwarden-1.26.5-x86_64.AppImage                                  
(node:47690) DeprecationWarning: file property is deprecated and will be removed in v5.
(node:47690) electron: The default of contextIsolation is deprecated and will be changing from false to true in a future release of Electron.  See https://github.com/electron/electron/issues/23506 for more information
17:27:23.731 › Checking for update
17:27:24.412 › Update for version 1.26.5 is not available (latest version: 1.26.5, downgrade is disallowed).
(node:47690) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'setContextMenu' of undefined
    at tray_main_TrayMain.updateContextMenu (/tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:2060:23)
    at messaging_main_MessagingMain.updateTrayMenu (/tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:1509:28)
    at messaging_main_MessagingMain.onMessage (/tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:1450:22)
    at messaging_main_MessagingMain.<anonymous> (/tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:1441:154)
    at Generator.next (<anonymous>)
    at /tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:1419:71
    at new Promise (<anonymous>)
    at messaging_main_awaiter (/tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:1415:12)
    at IpcMainImpl.<anonymous> (/tmp/.mount_BitwarW1vbRp/resources/app.asar/main.js:1441:82)
    at IpcMainImpl.emit (events.js:315:20)
(node:47690) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:47690) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

The app launches and I can interact with the menu but nothing inside the window is responsive. I can see the fields for username and password but there is no blinking cursor in them and I can't interact with them. It sits this way for about 30 seconds until I get that exception and then I'm finally able to interact with elements in the window. I haven't tried logging in and using the app further than that.

Arch Linux, StumpWM

---

Update 1

I'm going to take some notes here in hopes it helps resolve this.

In the tray's initialization, we conditionally call showTray.

showTray is what creates the Tray object and assigns it to this.tray.

What happens if the user doesn't have a system tray? If showTray never gets called, then this.tray never gets initialized, but updateAppMenu still gets called which kicks of the chain where eventually updateContextMenu gets called.

    // TrayMain
    // ...
    async init(appName: string, additionalMenuItems: MenuItemConstructorOptions[] = null) {
       // ...
        this.contextMenu = Menu.buildFromTemplate(menuItemOptions);
        if (await this.storageService.get<boolean>(ElectronConstants.enableTrayKey)) {
            this.showTray();
        }
    }

    showTray() {
        if (this.tray != null) {
            return;
        }

        this.tray = new Tray(this.icon);
        this.tray.setToolTip(this.appName);
        // ...
        if (this.contextMenu != null && !this.isDarwin()) {
            this.tray.setContextMenu(this.contextMenu);
        }
    }

updateContextMenu expects this.tray to be defined (expects showTray to have ran successfully).

    updateContextMenu() {
        if (this.contextMenu != null && this.isLinux()) {
            this.tray.setContextMenu(this.contextMenu);
        }
    }

updateContextMenu gets called by updateTrayMenu which gets called by the messaging service.

    // MessagingMain
    // ...
    init() {
        // ...
        ipcMain.on('messagingService', async (event: any, message: any) => this.onMessage(message));
    }

    onMessage(message: any) {
        switch (message.command) {
            case 'scheduleNextSync':
                this.scheduleNextSync();
                break;
            case 'updateAppMenu':
                this.main.menuMain.updateApplicationMenuState(message.isAuthenticated, message.isLocked);
                this.updateTrayMenu(message.isAuthenticated, message.isLocked);
                break;

---

Update 2

I'm trying to track this down.

Here's the result of a few console.logs I threw around. This includes a console.log in showTray, which you'll notice is never called.

➜  desktop git:(rc) ✗ ELECTRON_IS_DEV=1 ./dist/Bitwarden-1.26.5-x86_64.AppImage
2021-06-17T13:16:29.425Z  messagingMain initialized from main.ts
2021-06-17T13:16:29.965Z trayMain about to init from main.ts
2021-06-17T13:16:29.966Z tray.main.ts init pre-await
2021-06-17T13:16:29.966Z tray.main.ts init post-await
2021-06-17T13:16:29.966Z awaiting storageService from main.ts#bootstrap
2021-06-17T13:16:30.034Z bootstrap complete
(node:71706) electron: The default of contextIsolation is deprecated and will be changing from false to true in a future release of Electron.  See https://github.com/electron/electron/issues/23506 for more information
2021-06-17T13:16:30.970Z received message { command: 'syncStarted' }
2021-06-17T13:16:31.013Z received message { command: 'syncCompleted', successfully: false }
2021-06-17T13:16:31.068Z received message { command: 'authBlocked' }
// **** ~35 second delay... app frozen.
2021-06-17T13:18:57.094Z received message { command: 'updateAppMenu', isAuthenticated: false, isLocked: true }
2021-06-17T13:18:57.096Z updateAppMenu message
updateTrayMenu
Thu Jun 17 2021 08:18:57 GMT-0500 (Central Daylight Time) updateContextMenu
(node:71706) UnhandledPromiseRejectionWarning: TypeError: Cannot read property 'setContextMenu' of undefined

The delay varies between ~20 seconds and ~40 seconds, so maybe something IO-bound rather than a hard-coded timeout?

Still narrowing in on what happens between bootstrapping and the first updateAppMenu message.

~~Actually... here's something kind of odd.~~

~~In TrayMain I'm logging "tray.main.ts init post-await" immediately befor calling this.showTray();. And in showTray() I'm immediately logging again. I see the tray.main.ts init post-await message but I don't see the showTray message.~~

Edit: Whoops. I didn't realize I was logging the same text from two different lines. The first was from inside a conditional. The second was from outside the conditional. I thought when I saw the text it was from the log inside the conditional. I didn't realize I had the same text being logged outside the conditional. So I thought the conditional was running and was confused as to why other lines of code inside the conditional weren't running. Seeing that now makes things a lot easier to debug.

    async init(appName: string, additionalMenuItems: MenuItemConstructorOptions[] = null) {
        // ...
        this.contextMenu = Menu.buildFromTemplate(menuItemOptions);
        console.log(new Date(), "tray.main.ts init pre-await");
        if (await this.storageService.get<boolean>(ElectronConstants.enableTrayKey)) {
            console.log("tray.main.ts init post-await");
            this.showTray();
        }
        console.log(new Date(), "tray.main.ts init post-await");
    }

    showTray() {
        console.log("showTray");
        if (this.tray != null) {
            return;
        }
        // ...
    }

[eihli]

Anyone have any idea on how to pause on breakpoints?

I found the --inspect and chrome://inspect to connect to the remote debugging port of the main process, but I'm not able to get it to pause on the break points.

I'm currently trying launching with

    "electron": "npm run build:main:dev && concurrently -k -n Main,Rend -c yellow,cyan \"electron --inspect --inspect-brk:5858 ./build --watch\" \"npm run build:renderer:watch\"",

and then connecting as soon as it shows up at chrome://inspect/#devices,

            this.contextMenu = Menu.buildFromTemplate(menuItemOptions);
            debugger;
            console.log(new Date(), "tray.main.ts init pre-await");

but I can't get it to pause on any breakpoints.

[eliykat]

Nice work finding the culprit here. I haven't reproduced it yet, but I assume that's why I couldn't repro it on Ubuntu - I would've had gnome-keyring-daemon running on system startup.

I've asked the team for some tips on debugging the main process - so far I've managed to avoid it myself.

Browser doesn't suffer from this issue because it doesn't use the system keychain (I assume due to API limitations of the browser environment). That's why you need the desktop app running to use biometrics in the browser extension.

I'll consider what we can do about this in terms of a fix.

[MGibson1]

@eihli I just recently merged a PR that includes source maps for the main process in development builds (https://github.com/bitwarden/desktop/pull/946).

As long as you're up to date with master, what you're trying should work. However, I haven't tested using chrome's debugger, I use vs code's, which automatically attaches when you run npm run electron in the vs code terminal.

Prior to that PR, you could still debug main process, but you had to do it from the transpiled js code

[eliykat]

@eihli Unfortunately all of keytar's methods appear to be blocking - even though they're wrapped in promises so they look asynchronous. I can't see any safe method available for us to even check whether there's a secrets service running without hitting the same issue. I don't think there's anything we could do at our level - we'd have to fork or change the keytar dependency.

That may happen at some point in the future, but for now just running the lightest secrets service you can find is the most practical workaround.

[shroff]

Facing the same issue here.

I run gnome-keyring-daemon --start in my session startup script, but I am still seeing this issue. I know for a fact that the keyring daemon is running because I use it as my ssh agent.

Running Arch/sway.

[jhakonen]

I stumbled on this issue myself after updating Fedora (v36, KDE). In my case Bitwarden is fine after launch, but freezes permanently some minutes later, and never recovers from it.

My KDE wallet was upgraded from 5.96.0 to 5.97.0. According to https://wiki.archlinux.org/title/KDE_Wallet the 5.97.0 version brought in secret service support. And I can see that the kwallet now is indeed providing the service:

$ gdbus call --session --dest org.freedesktop.DBus --object-path / --method org.freedesktop.DBus.GetConnectionUnixProcessID org.freedesktop.secrets
(uint32 1881,)
$ ps aux | grep 1881
jhakonen    1881  0.0  0.1 497856 49660 ?        SLl  11:23   0:05 /usr/bin/kwalletd5 --pam-login 12 13

Disabling kwallet from System Settings > Personalization > KDE Wallet > untick "Enable KDE wallet subsystem", and then killing the kwallet daemon allows gnome-keyring-daemon take its place. After that Bitwarden seems to be ok again. However, I'm not sure though what else I will lose by disabling kwallet.