Add a message ID on each to-device message (#2938)

To make it easier to track down where to-device messages are getting lost,
add a custom property to each one, and log its value. Synapse will also log
this property.

package.json

@@ -63,7 +63,8 @@
     "p-retry": "4",
     "qs": "^6.9.6",
     "sdp-transform": "^2.14.1",
-    "unhomoglyph": "^1.0.6"
+    "unhomoglyph": "^1.0.6",
+    "uuid": "7"
   },
   "devDependencies": {
     "@babel/cli": "^7.12.10",
@@ -86,6 +87,7 @@
     "@types/jest": "^29.0.0",
     "@types/node": "18",
     "@types/sdp-transform": "^2.4.5",
+    "@types/uuid": "7",
     "@typescript-eslint/eslint-plugin": "^5.6.0",
     "@typescript-eslint/parser": "^5.6.0",
     "allchange": "^1.0.6",

spec/unit/crypto.spec.ts

@@ -1010,18 +1010,24 @@ describe("Crypto", function() {
 
         it("encrypts and sends to devices", async () => {
             client.httpBackend
-                .when("PUT", "/sendToDevice/m.room.encrypted", {
+                .when("PUT", "/sendToDevice/m.room.encrypted")
-                    messages: {
+                .check((request) => {
-                        "@bob:example.org": {
+                    const data = request.data;
-                            bobweb: encryptedPayload,
+                    delete data.messages["@bob:example.org"]["bobweb"]["org.matrix.msgid"];
-                            bobmobile: encryptedPayload,
+                    delete data.messages["@bob:example.org"]["bobmobile"]["org.matrix.msgid"];
+                    delete data.messages["@carol:example.org"]["caroldesktop"]["org.matrix.msgid"];
+                    expect(data).toStrictEqual({
+                        messages: {
+                            "@bob:example.org": {
+                                bobweb: encryptedPayload,
+                                bobmobile: encryptedPayload,
+                            },
+                            "@carol:example.org": {
+                                caroldesktop: encryptedPayload,
+                            },
                         },
-                        "@carol:example.org": {
+                    });
-                            caroldesktop: encryptedPayload,
+                }).respond(200, {});
-                        },
-                    },
-                })
-                .respond(200, {});
 
             await Promise.all([
                 client.client.encryptAndSendToDevices(
@@ -1044,9 +1050,14 @@ describe("Crypto", function() {
             });
 
             client.httpBackend
-                .when("PUT", "/sendToDevice/m.room.encrypted", {
+                .when("PUT", "/sendToDevice/m.room.encrypted")
+                .check((req) => {
+                    const data = req.data;
+                    delete data.messages["@bob:example.org"]["bobweb"]["org.matrix.msgid"];
                     // Carol is nowhere to be seen
-                    messages: { "@bob:example.org": { bobweb: encryptedPayload } },
+                    expect(data).toStrictEqual({
+                        messages: { "@bob:example.org": { bobweb: encryptedPayload } },
+                    });
                 })
                 .respond(200, {});
 

spec/unit/crypto/algorithms/megolm.spec.ts

@@ -558,7 +558,9 @@ describe("MegolmDecryption", function() {
         const [msgtype, contentMap] = mocked(aliceClient.sendToDevice).mock.calls[0];
         expect(msgtype).toMatch(/^(org.matrix|m).room_key.withheld$/);
         delete contentMap["@bob:example.com"].bobdevice1.session_id;
+        delete contentMap["@bob:example.com"].bobdevice1["org.matrix.msgid"];
         delete contentMap["@bob:example.com"].bobdevice2.session_id;
+        delete contentMap["@bob:example.com"].bobdevice2["org.matrix.msgid"];
         expect(contentMap).toStrictEqual({
             '@bob:example.com': {
                 bobdevice1: {
@@ -755,6 +757,7 @@ describe("MegolmDecryption", function() {
         expect(aliceClient.sendToDevice).toHaveBeenCalled();
         const [msgtype, contentMap] = mocked(aliceClient.sendToDevice).mock.calls[0];
         expect(msgtype).toMatch(/^(org.matrix|m).room_key.withheld$/);
+        delete contentMap["@bob:example.com"]["bobdevice"]["org.matrix.msgid"];
         expect(contentMap).toStrictEqual({
             '@bob:example.com': {
                 bobdevice: {

src/@types/event.ts

@@ -120,6 +120,8 @@ export enum RoomType {
     ElementVideo = "io.element.video",
 }
 
+export const ToDeviceMessageId = "org.matrix.msgid";
+
 /**
  * Identifier for an [MSC3088](https://github.com/matrix-org/matrix-doc/pull/3088)
  * room purpose. Note that this reference is UNSTABLE and subject to breaking changes,

src/ToDeviceMessageQueue.ts

@@ -14,6 +14,7 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
+import { ToDeviceMessageId } from './@types/event';
 import { logger } from "./logger";
 import { MatrixError, MatrixClient } from "./matrix";
 import { IndexedToDeviceBatch, ToDeviceBatch, ToDeviceBatchWithTxnId, ToDevicePayload } from "./models/ToDeviceMessage";
@@ -54,12 +55,15 @@ export class ToDeviceMessageQueue {
                 txnId: this.client.makeTxnId(),
             };
             batches.push(batchWithTxnId);
-            const recips = batchWithTxnId.batch.map((msg) => `${msg.userId}:${msg.deviceId}`);
+            const msgmap = batchWithTxnId.batch.map(
-            logger.info(`Created batch of to-device messages with txn id ${batchWithTxnId.txnId} for ${recips}`);
+                (msg) => `${msg.userId}/${msg.deviceId} (msgid ${msg.payload[ToDeviceMessageId]})`,
+            );
+            logger.info(
+                `Enqueuing batch of to-device messages. type=${batch.eventType} txnid=${batchWithTxnId.txnId}`, msgmap,
+            );
         }
 
         await this.client.store.saveToDeviceBatches(batches);
-        logger.info(`Enqueued to-device messages with txn ids ${batches.map((batch) => batch.txnId)}`);
         this.sendQueue();
     }
 

src/crypto/OutgoingRoomKeyRequestManager.ts

@@ -14,11 +14,13 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
+import { v4 as uuidv4 } from "uuid";
+
 import { logger } from '../logger';
 import { MatrixClient } from "../client";
 import { IRoomKeyRequestBody, IRoomKeyRequestRecipient } from "./index";
 import { CryptoStore, OutgoingRoomKeyRequest } from './store/base';
-import { EventType } from "../@types/event";
+import { EventType, ToDeviceMessageId } from "../@types/event";
 
 /**
  * Internal module. Management of outgoing room key requests.
@@ -483,7 +485,10 @@ export class OutgoingRoomKeyRequestManager {
             if (!contentMap[recip.userId]) {
                 contentMap[recip.userId] = {};
             }
-            contentMap[recip.userId][recip.deviceId] = message;
+            contentMap[recip.userId][recip.deviceId] = {
+                ...message,
+                [ToDeviceMessageId]: uuidv4(),
+            };
         }
 
         return this.baseApis.sendToDevice(EventType.RoomKeyRequest, contentMap, txnId);

src/crypto/SecretStorage.ts

@@ -14,6 +14,8 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
+import { v4 as uuidv4 } from 'uuid';
+
 import { logger } from '../logger';
 import * as olmlib from './olmlib';
 import { encodeBase64 } from './olmlib';
@@ -25,6 +27,7 @@ import { ClientEvent, ClientEventHandlerMap, MatrixClient } from "../client";
 import { IAddSecretStorageKeyOpts, ISecretStorageKeyInfo } from './api';
 import { TypedEventEmitter } from '../models/typed-event-emitter';
 import { defer, IDeferred } from "../utils";
+import { ToDeviceMessageId } from "../@types/event";
 
 export const SECRET_STORAGE_ALGORITHM_V1_AES = "m.secret_storage.v1.aes-hmac-sha2";
 
@@ -407,6 +410,7 @@ export class SecretStorage<B extends MatrixClient | undefined = MatrixClient> {
             action: "request",
             requesting_device_id: this.baseApis.deviceId,
             request_id: requestId,
+            [ToDeviceMessageId]: uuidv4(),
         };
         const toDevice = {};
         for (const device of devices) {
@@ -490,6 +494,7 @@ export class SecretStorage<B extends MatrixClient | undefined = MatrixClient> {
                     algorithm: olmlib.OLM_ALGORITHM,
                     sender_key: this.baseApis.crypto!.olmDevice.deviceCurve25519Key,
                     ciphertext: {},
+                    [ToDeviceMessageId]: uuidv4(),
                 };
                 await olmlib.ensureOlmSessionsForDevices(
                     this.baseApis.crypto!.olmDevice,

src/crypto/algorithms/megolm.ts

@@ -20,6 +20,8 @@ limitations under the License.
  * @module crypto/algorithms/megolm
  */
 
+import { v4 as uuidv4 } from "uuid";
+
 import { logger } from '../../logger';
 import * as olmlib from "../olmlib";
 import {
@@ -37,7 +39,7 @@ import { DeviceInfo } from "../deviceinfo";
 import { IOlmSessionResult } from "../olmlib";
 import { DeviceInfoMap } from "../DeviceList";
 import { MatrixEvent } from "../../models/event";
-import { EventType, MsgType } from '../../@types/event';
+import { EventType, MsgType, ToDeviceMessageId } from '../../@types/event';
 import { IEncryptedContent, IEventDecryptionResult, IMegolmSessionData, IncomingRoomKeyRequest } from "../index";
 import { RoomKeyRequestState } from '../OutgoingRoomKeyRequestManager';
 import { OlmGroupSessionExtraData } from "../../@types/crypto";
@@ -655,9 +657,13 @@ class MegolmEncryption extends EncryptionAlgorithm {
             const deviceInfo = blockedInfo.deviceInfo;
             const deviceId = deviceInfo.deviceId;
 
-            const message = Object.assign({}, payload);
+            const message = {
-            message.code = blockedInfo.code;
+                ...payload,
-            message.reason = blockedInfo.reason;
+                code: blockedInfo.code,
+                reason: blockedInfo.reason,
+                [ToDeviceMessageId]: uuidv4(),
+            };
+
             if (message.code === "m.no_olm") {
                 delete message.room_id;
                 delete message.session_id;
@@ -759,6 +765,7 @@ class MegolmEncryption extends EncryptionAlgorithm {
             algorithm: olmlib.OLM_ALGORITHM,
             sender_key: this.olmDevice.deviceCurve25519Key,
             ciphertext: {},
+            [ToDeviceMessageId]: uuidv4(),
         };
         await olmlib.encryptMessageForDevice(
             encryptedContent.ciphertext,
@@ -1667,6 +1674,7 @@ class MegolmDecryption extends DecryptionAlgorithm {
                 algorithm: olmlib.OLM_ALGORITHM,
                 sender_key: this.olmDevice.deviceCurve25519Key,
                 ciphertext: {},
+                [ToDeviceMessageId]: uuidv4(),
             };
             await olmlib.encryptMessageForDevice(
                 encryptedContent.ciphertext,
@@ -1748,6 +1756,7 @@ class MegolmDecryption extends DecryptionAlgorithm {
                 algorithm: olmlib.OLM_ALGORITHM,
                 sender_key: this.olmDevice.deviceCurve25519Key,
                 ciphertext: {},
+                [ToDeviceMessageId]: uuidv4,
             };
 
             return this.olmlib.encryptMessageForDevice(
@@ -1923,6 +1932,7 @@ class MegolmDecryption extends DecryptionAlgorithm {
                         algorithm: olmlib.OLM_ALGORITHM,
                         sender_key: this.olmDevice.deviceCurve25519Key!,
                         ciphertext: {},
+                        [ToDeviceMessageId]: uuidv4(),
                     };
                     contentMap[userId][deviceInfo.deviceId] = encryptedContent;
                     promises.push(

src/crypto/index.ts

@@ -22,9 +22,10 @@ limitations under the License.
  */
 
 import anotherjson from "another-json";
+import { v4 as uuidv4 } from "uuid";
 
 import type { PkDecryption, PkSigning } from "@matrix-org/olm";
-import { EventType } from "../@types/event";
+import { EventType, ToDeviceMessageId } from "../@types/event";
 import { TypedReEmitter } from '../ReEmitter';
 import { logger } from '../logger';
 import { IExportedDevice, OlmDevice } from "./OlmDevice";
@@ -234,6 +235,7 @@ export interface IEncryptedContent {
     algorithm: string;
     sender_key: string;
     ciphertext: Record<string, string>;
+    [ToDeviceMessageId]: string;
 }
 /* eslint-enable camelcase */
 
@@ -3173,6 +3175,7 @@ export class Crypto extends TypedEventEmitter<CryptoEvent, CryptoEventHandlerMap
                     algorithm: olmlib.OLM_ALGORITHM,
                     sender_key: this.olmDevice.deviceCurve25519Key!,
                     ciphertext: {},
+                    [ToDeviceMessageId]: uuidv4(),
                 };
 
                 toDeviceBatch.batch.push({
@@ -3232,8 +3235,8 @@ export class Crypto extends TypedEventEmitter<CryptoEvent, CryptoEventHandlerMap
 
     private onToDeviceEvent = (event: MatrixEvent): void => {
         try {
-            logger.log(`received to_device ${event.getType()} from: ` +
+            logger.log(`received to-device ${event.getType()} from: ` +
-                `${event.getSender()} id: ${event.getId()}`);
+                `${event.getSender()} id: ${event.getContent()[ToDeviceMessageId]}`);
 
             if (event.getType() == "m.room_key"
                 || event.getType() == "m.forwarded_room_key") {
@@ -3516,6 +3519,7 @@ export class Crypto extends TypedEventEmitter<CryptoEvent, CryptoEventHandlerMap
             algorithm: olmlib.OLM_ALGORITHM,
             sender_key: this.olmDevice.deviceCurve25519Key,
             ciphertext: {},
+            [ToDeviceMessageId]: uuidv4(),
         };
         await olmlib.encryptMessageForDevice(
             encryptedContent.ciphertext,

src/webrtc/call.ts

@@ -22,12 +22,13 @@ limitations under the License.
  * @module webrtc/call
  */
 
+import { v4 as uuidv4 } from "uuid";
 import { parse as parseSdp, write as writeSdp } from "sdp-transform";
 
 import { logger } from '../logger';
 import * as utils from '../utils';
 import { MatrixEvent } from '../models/event';
-import { EventType } from '../@types/event';
+import { EventType, ToDeviceMessageId } from '../@types/event';
 import { RoomMember } from '../models/room-member';
 import { randomString } from '../randomstring';
 import {
@@ -2278,6 +2279,7 @@ export class MatrixCall extends TypedEventEmitter<CallEvent, CallEventHandlerMap
                 sender_session_id: this.client.getSessionId(),
                 dest_session_id: this.opponentSessionId,
                 seq: toDeviceSeq,
+                [ToDeviceMessageId]: uuidv4(),
             };
 
             this.emit(CallEvent.SendVoipEvent, {

yarn.lock

@@ -1759,6 +1759,11 @@
   resolved "https://registry.yarnpkg.com/@types/tough-cookie/-/tough-cookie-4.0.2.tgz#6286b4c7228d58ab7866d19716f3696e03a09397"
   integrity sha512-Q5vtl1W5ue16D+nIaW8JWebSSraJVlK+EthKn7e7UcD4KWsaSJ8BqGPXNaPghgtcn/fhvrN17Tv8ksUsQpiplw==
 
+"@types/uuid@7":
+  version "7.0.5"
+  resolved "https://registry.yarnpkg.com/@types/uuid/-/uuid-7.0.5.tgz#b1d2f772142a301538fae9bdf9cf15b9f2573a29"
+  integrity sha512-hKB88y3YHL8oPOs/CNlaXtjWn93+Bs48sDQR37ZUqG2tLeCS7EA1cmnkKsuQsub9OKEB/y/Rw9zqJqqNSbqVlQ==
+
 "@types/webidl-conversions@*":
   version "7.0.0"
   resolved "https://registry.yarnpkg.com/@types/webidl-conversions/-/webidl-conversions-7.0.0.tgz#2b8e60e33906459219aa587e9d1a612ae994cfe7"
@@ -6967,6 +6972,11 @@ util@~0.12.0:
     is-typed-array "^1.1.3"
     which-typed-array "^1.1.2"
 
+uuid@7:
+  version "7.0.3"
+  resolved "https://registry.yarnpkg.com/uuid/-/uuid-7.0.3.tgz#c5c9f2c8cf25dc0a372c4df1441c41f5bd0c680b"
+  integrity sha512-DPSke0pXhTZgoF/d+WSt2QaKMCFSfx7QegxEWT+JOuHF5aWrKEn0G+ztjuJg/gG8/ItK+rbPCD/yNv8yyih6Cg==
+
 uuid@8.3.2, uuid@^8.3.2:
   version "8.3.2"
   resolved "https://registry.yarnpkg.com/uuid/-/uuid-8.3.2.tgz#80d5b5ced271bb9af6c445f21a1a04c606cefbe2"