Don't send key requests until after sync processing is finished

Key requests wait for a short time (500ms) before being sent as
an attempt to wait for the key to arrive before sending a request
for it, but client startup takes way longer than this so this
would still result in key requests being sent for keys that we'd
fetched but were still waiting to be read out of the sync response
and put into the database.

spec/unit/crypto.spec.js

@@ -313,6 +313,10 @@ describe("Crypto", function() {
             // make a room key request, and record the transaction ID for the
             // sendToDevice call
             await aliceClient.cancelAndResendEventRoomKeyRequest(event);
+            // key requests get queued until the sync has finished, but we don't
+            // let the client set up enough for that to happen, so gut-wrench a bit
+            // to force it to send now.
+            aliceClient._crypto._outgoingRoomKeyRequestManager.sendQueuedRequests();
             jest.runAllTimers();
             await Promise.resolve();
             expect(aliceClient.sendToDevice).toBeCalledTimes(1);

src/crypto/OutgoingRoomKeyRequestManager.js

@@ -97,10 +97,6 @@ export class OutgoingRoomKeyRequestManager {
      */
     start() {
         this._clientRunning = true;
-
-        // set the timer going, to handle any requests which didn't get sent
-        // on the previous run of the client.
-        this._startTimer();
     }
 
     /**
@@ -113,7 +109,14 @@ export class OutgoingRoomKeyRequestManager {
     }
 
     /**
-     * Send off a room key request, if we haven't already done so.
+     * Send any requests that have been queued
+     */
+    sendQueuedRequests() {
+        this._startTimer();
+    }
+
+    /**
+     * Queue up a room key request, if we haven't already queued or sent one.
      *
      * The `requestBody` is compared (with a deep-equality check) against
      * previous queued or sent requests and if it matches, no change is made.
@@ -129,7 +132,7 @@ export class OutgoingRoomKeyRequestManager {
      *    pending list (or we have established that a similar request already
      *    exists)
      */
-    async sendRoomKeyRequest(requestBody, recipients, resend=false) {
+    async queueRoomKeyRequest(requestBody, recipients, resend=false) {
         const req = await this._cryptoStore.getOutgoingRoomKeyRequest(
             requestBody,
         );
@@ -184,7 +187,7 @@ export class OutgoingRoomKeyRequestManager {
                         // in state ROOM_KEY_REQUEST_STATES.SENT, so we must have
                         // raced with another tab to mark the request cancelled.
                         // Try again, to make sure the request is resent.
-                        return await this.sendRoomKeyRequest(
+                        return await this.queueRoomKeyRequest(
                             requestBody, recipients, resend,
                         );
                     }
@@ -220,9 +223,6 @@ export class OutgoingRoomKeyRequestManager {
                 throw new Error('unhandled state: ' + req.state);
             }
         }
-        // some of the branches require the timer to be started.  Just start it
-        // all the time, because it doesn't hurt to start it.
-        this._startTimer();
     }
 
     /**
@@ -302,7 +302,6 @@ export class OutgoingRoomKeyRequestManager {
                                 "Error sending room key request cancellation;"
                                 + " will retry later.", e,
                             );
-                            this._startTimer();
                         });
                     });
                 }
@@ -332,14 +331,14 @@ export class OutgoingRoomKeyRequestManager {
      * This is intended for situations where something substantial has changed, and we
      * don't really expect the other end to even care about the cancellation.
      * For example, after initialization or self-verification.
-     * @return {Promise} An array of `sendRoomKeyRequest` outputs.
+     * @return {Promise} An array of `queueRoomKeyRequest` outputs.
      */
     async cancelAndResendAllOutgoingRequests() {
         const outgoings = await this._cryptoStore.getAllOutgoingRoomKeyRequestsByState(
             ROOM_KEY_REQUEST_STATES.SENT,
         );
         return Promise.all(outgoings.map(({ requestBody, recipients }) =>
-            this.sendRoomKeyRequest(requestBody, recipients, true)));
+            this.queueRoomKeyRequest(requestBody, recipients, true)));
     }
 
     // start the background timer to send queued requests, if the timer isn't
@@ -381,15 +380,12 @@ export class OutgoingRoomKeyRequestManager {
             return Promise.resolve();
         }
 
-        logger.log("Looking for queued outgoing room key requests");
-
         return this._cryptoStore.getOutgoingRoomKeyRequestByState([
             ROOM_KEY_REQUEST_STATES.CANCELLATION_PENDING,
             ROOM_KEY_REQUEST_STATES.CANCELLATION_PENDING_AND_WILL_RESEND,
             ROOM_KEY_REQUEST_STATES.UNSENT,
         ]).then((req) => {
             if (!req) {
-                logger.log("No more outgoing room key requests");
                 this._sendOutgoingRoomKeyRequestsTimer = null;
                 return;
             }
@@ -413,7 +409,6 @@ export class OutgoingRoomKeyRequestManager {
             }).catch((e) => {
                 logger.error("Error sending room key request; will retry later.", e);
                 this._sendOutgoingRoomKeyRequestsTimer = null;
-                this._startTimer();
             });
         });
     }

src/crypto/index.js

@@ -223,6 +223,11 @@ export function Crypto(baseApis, sessionStore, userId, deviceId,
     this._toDeviceVerificationRequests = new ToDeviceRequests();
     this._inRoomVerificationRequests = new InRoomRequests();
 
+    // This flag will be unset whilst the client processes a sync response
+    // so that we don't start requesting keys until we've actually finished
+    // processing the response.
+    this._sendKeyRequestsImmediately = false;
+
     const cryptoCallbacks = this._baseApis._cryptoCallbacks || {};
     const cacheCallbacks = createCryptoStoreCacheCallbacks(cryptoStore);
 
@@ -2875,7 +2880,7 @@ Crypto.prototype.handleDeviceListChanges = async function(syncData, syncDeviceLi
  * @return {Promise} a promise that resolves when the key request is queued
  */
 Crypto.prototype.requestRoomKey = function(requestBody, recipients, resend=false) {
-    return this._outgoingRoomKeyRequestManager.sendRoomKeyRequest(
+    return this._outgoingRoomKeyRequestManager.queueRoomKeyRequest(
         requestBody, recipients, resend,
     ).catch((e) => {
         // this normally means we couldn't talk to the store
@@ -2883,6 +2888,9 @@ Crypto.prototype.requestRoomKey = function(requestBody, recipients, resend=false
             'Error requesting key for event', e,
         );
     });
+    if (this._sendKeyRequestsImmediately) {
+        this._outgoingRoomKeyRequestManager.sendQueuedRequests();
+    }
 };
 
 /**
@@ -2942,6 +2950,8 @@ Crypto.prototype.onSyncWillProcess = async function(syncData) {
         this._deviceList.startTrackingDeviceList(this._userId);
         this._roomDeviceTrackingState = {};
     }
+
+    this._sendKeyRequestsImmediately = false;
 };
 
 /**
@@ -2973,6 +2983,14 @@ Crypto.prototype.onSyncCompleted = async function(syncData) {
     if (!syncData.catchingUp) {
         _maybeUploadOneTimeKeys(this);
         this._processReceivedRoomKeyRequests();
+
+        // likewise don't start requesting keys until we've caught up
+        // on to_device messages, otherwise we'll request keys that we're
+        // just about to get.
+        this._outgoingRoomKeyRequestManager.sendQueuedRequests();
+
+        // Sync has finished so send key requests straight away.
+        this._sendKeyRequestsImmediately = true;
     }
 };