Merge pull request #1638 from matrix-org/jryans/rm-olm-profiling

Remove detailed Olm session logging

Author: jryans

src/crypto/olmlib.js

@@ -213,9 +213,8 @@ export async function ensureOlmSessionsForDevices(
     // synchronous operation, as otherwise it is possible to have deadlocks
     // where multiple tasks wait indefinitely on another task to update some set
     // of common devices.
-    for (const [userId, devices] of Object.entries(devicesByUser)) {
+    for (const [, devices] of Object.entries(devicesByUser)) {
         for (const deviceInfo of devices) {
-            const deviceId = deviceInfo.deviceId;
             const key = deviceInfo.getIdentityKey();
 
             if (key === olmDevice.deviceCurve25519Key) {
@@ -224,15 +223,12 @@ export async function ensureOlmSessionsForDevices(
                 continue;
             }
 
-            const forWhom = `for ${key} (${userId}:${deviceId})`;
             if (!olmDevice._sessionsInProgress[key]) {
                 // pre-emptively mark the session as in-progress to avoid race
                 // conditions.  If we find that we already have a session, then
                 // we'll resolve
-                log.debug(`Marking Olm session in progress ${forWhom}`);
                 olmDevice._sessionsInProgress[key] = new Promise(resolve => {
                     resolveSession[key] = (...args) => {
-                        log.debug(`Resolved Olm session in progress ${forWhom}`);
                         delete olmDevice._sessionsInProgress[key];
                         resolve(...args);
                     };
@@ -266,11 +262,9 @@ export async function ensureOlmSessionsForDevices(
             }
 
             const forWhom = `for ${key} (${userId}:${deviceId})`;
-            log.debug(`Ensuring Olm session ${forWhom}`);
             const sessionId = await olmDevice.getSessionIdForDevice(
                 key, resolveSession[key], log,
             );
-            log.debug(`Got Olm session ${sessionId} ${forWhom}`);
             if (sessionId !== null && resolveSession[key]) {
                 // we found a session, but we had marked the session as
                 // in-progress, so resolve it now, which will unmark it and
@@ -299,18 +293,6 @@ export async function ensureOlmSessionsForDevices(
     const oneTimeKeyAlgorithm = "signed_curve25519";
     let res;
     let taskDetail = `one-time keys for ${devicesWithoutSession.length} devices`;
-    // If your homeserver takes a nap here and never replies, this process
-    // would hang indefinitely. While that's easily fixed by setting a
-    // timeout on this request, let's first log whether that's the root
-    // cause we're seeing in practice.
-    // See also https://github.com/vector-im/element-web/issues/16194
-    let otkTimeoutLogger;
-    // XXX: Perhaps there should be a default timeout?
-    if (otkTimeout) {
-        otkTimeoutLogger = setTimeout(() => {
-            log.error(`Homeserver never replied while claiming ${taskDetail}`);
-        }, otkTimeout);
-    }
     try {
         log.debug(`Claiming ${taskDetail}`);
         res = await baseApis.claimOneTimeKeys(
@@ -323,8 +305,6 @@ export async function ensureOlmSessionsForDevices(
         }
         log.log(`Failed to claim ${taskDetail}`, e, devicesWithoutSession);
         throw e;
-    } finally {
-        clearTimeout(otkTimeoutLogger);
     }
 
     if (failedServers && "failures" in res) {

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

@@ -20,6 +20,7 @@ import {logger} from '../../logger';
 import * as utils from "../../utils";
 
 export const VERSION = 9;
+const PROFILE_TRANSACTIONS = false;
 
 /**
  * Implementation of a CryptoStore which is backed by an existing
@@ -759,20 +760,26 @@ export class Backend {
     }
 
     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}`);
+        let startTime;
+        let description;
+        if (PROFILE_TRANSACTIONS) {
+            const txnId = this._nextTxnId++;
+            startTime = Date.now();
+            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`);
-        });
+        if (PROFILE_TRANSACTIONS) {
+            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/store/indexeddb-local-backend.js

@@ -435,7 +435,7 @@ LocalIndexedDBStoreBackend.prototype = {
      * @return {Promise} Resolves if the data was persisted.
      */
     _persistSyncData: function(nextBatch, roomsData, groupsData) {
-        logger.log("Persisting sync data up to ", nextBatch);
+        logger.log("Persisting sync data up to", nextBatch);
         return utils.promiseTry(() => {
             const txn = this.db.transaction(["sync"], "readwrite");
             const store = txn.objectStore("sync");