Add logging to crypto store transactions

We churn through a huge number of crypto store transactions during startup,
which may be the cause of the symptoms in
element-hq/element-web#16194.

src/crypto/OlmDevice.js

@@ -16,7 +16,7 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
-import {logger} from '../logger';
+import {getPrefixedLogger, logger} from '../logger';
 import {IndexedDBCryptoStore} from './store/indexeddb-crypto-store';
 import * as algorithms from './algorithms';
 
@@ -545,6 +545,7 @@ OlmDevice.prototype.createOutboundSession = async function(
                 }
             });
         },
+        getPrefixedLogger("[createOutboundSession]"),
     );
     return newSessionId;
 };
@@ -605,6 +606,7 @@ OlmDevice.prototype.createInboundSession = async function(
                 }
             });
         },
+        getPrefixedLogger("[createInboundSession]"),
     );
 
     return result;
@@ -638,6 +640,7 @@ OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityK
                 },
             );
         },
+        getPrefixedLogger("[getSessionIdsForDevice]"),
     );
 
     return sessionIds;
@@ -727,6 +730,7 @@ OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey,
                 }
             });
         },
+        getPrefixedLogger("[getSessionInfoForDevice]"),
     );
 
     return info;
@@ -761,6 +765,7 @@ OlmDevice.prototype.encryptMessage = async function(
                 this._saveSession(theirDeviceIdentityKey, sessionInfo, txn);
             });
         },
+        getPrefixedLogger("[encryptMessage]"),
     );
     return res;
 };
@@ -794,6 +799,7 @@ OlmDevice.prototype.decryptMessage = async function(
                 this._saveSession(theirDeviceIdentityKey, sessionInfo, txn);
             });
         },
+        getPrefixedLogger("[decryptMessage]"),
     );
     return payloadString;
 };
@@ -825,6 +831,7 @@ OlmDevice.prototype.matchesSession = async function(
                 matches = sessionInfo.session.matches_inbound(ciphertext);
             });
         },
+        getPrefixedLogger("[matchesSession]"),
     );
     return matches;
 };
@@ -1095,6 +1102,7 @@ OlmDevice.prototype.addInboundGroupSession = async function(
                 },
             );
         },
+        getPrefixedLogger("[addInboundGroupSession]"),
     );
 };
 
@@ -1265,6 +1273,7 @@ OlmDevice.prototype.decryptGroupMessage = async function(
                 },
             );
         },
+        getPrefixedLogger("[decryptGroupMessage]"),
     );
 
     if (error) {
@@ -1310,6 +1319,7 @@ OlmDevice.prototype.hasInboundSessionKeys = async function(roomId, senderKey, se
                 },
             );
         },
+        getPrefixedLogger("[hasInboundSessionKeys]"),
     );
 
     return result;
@@ -1369,6 +1379,7 @@ OlmDevice.prototype.getInboundGroupSessionKey = async function(
                 },
             );
         },
+        getPrefixedLogger("[getInboundGroupSessionKey]"),
     );
 
     return result;

src/crypto/store/indexeddb-crypto-store-backend.js

@@ -34,6 +34,7 @@ export class Backend {
      */
     constructor(db) {
         this._db = db;
+        this._nextTxnId = 0;
 
         // make sure we close the db on `onversionchange` - otherwise
         // attempts to delete the database will block (and subsequent
@@ -757,10 +758,21 @@ export class Backend {
         }));
     }
 
-    doTxn(mode, stores, func) {
+    doTxn(mode, stores, func, log = logger) {
+        const txnId = this._nextTxnId++;
+        const startTime = Date.now();
+        const description = `${mode} crypto store transaction ${txnId} in ${stores}`;
+        log.debug(`Starting ${description}`);
         const txn = this._db.transaction(stores, mode);
         const promise = promiseifyTxn(txn);
         const result = func(txn);
+        promise.then(() => {
+            const elapsedTime = Date.now() - startTime;
+            log.debug(`Finished ${description}, took ${elapsedTime} ms`);
+        }, () => {
+            const elapsedTime = Date.now() - startTime;
+            log.error(`Failed ${description}, took ${elapsedTime} ms`);
+        });
         return promise.then(() => {
             return result;
         });

src/crypto/store/indexeddb-crypto-store.js

@@ -596,15 +596,16 @@ export class IndexedDBCryptoStore {
      * @param {function(*)} func Function called with the
      *     transaction object: an opaque object that should be passed
      *     to store functions.
+     * @param {object} [log] A possibly customised log
      * @return {Promise} Promise that resolves with the result of the `func`
      *     when the transaction is complete. If the backend is
      *     async (ie. the indexeddb backend) any of the callback
      *     functions throwing an exception will cause this promise to
      *     reject with that exception. On synchronous backends, the
      *     exception will propagate to the caller of the getFoo method.
      */
-    doTxn(mode, stores, func) {
-        return this._backend.doTxn(mode, stores, func);
+    doTxn(mode, stores, func, log) {
+        return this._backend.doTxn(mode, stores, func, log);
     }
 }