From f43fe366b5ccdf4838a61dfa657c9b3612b4a069 Mon Sep 17 00:00:00 2001
From: "J. Ryan Stinnett" <jryans@gmail.com>
Date: Thu, 25 Feb 2021 15:13:43 +0000
Subject: [PATCH] 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
https://github.com/vector-im/element-web/issues/16194.
---
 src/crypto/OlmDevice.js                            | 13 ++++++++++++-
 src/crypto/store/indexeddb-crypto-store-backend.js | 14 +++++++++++++-
 src/crypto/store/indexeddb-crypto-store.js         |  5 +++--
 3 files changed, 28 insertions(+), 4 deletions(-)

diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js
index 24565507de4..6255863205b 100644
--- a/src/crypto/OlmDevice.js
+++ b/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;
diff --git a/src/crypto/store/indexeddb-crypto-store-backend.js b/src/crypto/store/indexeddb-crypto-store-backend.js
index 505e5fe51ba..6ecffe7be42 100644
--- a/src/crypto/store/indexeddb-crypto-store-backend.js
+++ b/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;
         });
diff --git a/src/crypto/store/indexeddb-crypto-store.js b/src/crypto/store/indexeddb-crypto-store.js
index 3dc49858cd0..217c5e62126 100644
--- a/src/crypto/store/indexeddb-crypto-store.js
+++ b/src/crypto/store/indexeddb-crypto-store.js
@@ -596,6 +596,7 @@ 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
@@ -603,8 +604,8 @@ export class IndexedDBCryptoStore {
      *     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);
     }
 }