diff --git a/spec/TestClient.js b/spec/TestClient.js index edd15df80..f7a584eb4 100644 --- a/spec/TestClient.js +++ b/spec/TestClient.js @@ -52,21 +52,21 @@ export default function TestClient(userId, deviceId, accessToken) { /** * start the client, and wait for it to initialise. * - * @param {object?} existingDevices the list of our existing devices to return from - * the /query request. Defaults to empty device list * @return {Promise} */ -TestClient.prototype.start = function(existingDevices) { +TestClient.prototype.start = function() { this.httpBackend.when("GET", "/pushrules").respond(200, {}); this.httpBackend.when("POST", "/filter").respond(200, { filter_id: "fid" }); - this.expectKeyUpload(existingDevices); + this.expectKeyUpload(); this.client.startClient({ // set this so that we can get hold of failed events pendingEventOrdering: 'detached', }); - return this.httpBackend.flush(); + return this.httpBackend.flush().then(() => { + console.log('TestClient[' + this.userId + ']: started'); + }); }; /** @@ -78,22 +78,9 @@ TestClient.prototype.stop = function() { /** * Set up expectations that the client will upload device and one-time keys. - * - * @param {object?} existingDevices the list of our existing devices to return from - * the /query request. Defaults to empty device list */ -TestClient.prototype.expectKeyUpload = function(existingDevices) { +TestClient.prototype.expectKeyUpload = function() { const self = this; - this.httpBackend.when('POST', '/keys/query').respond(200, function(path, content) { - expect(Object.keys(content.device_keys)).toEqual([self.userId]); - expect(content.device_keys[self.userId]).toEqual({}); - let res = existingDevices; - if (!res) { - res = { device_keys: {} }; - res.device_keys[self.userId] = {}; - } - return res; - }); this.httpBackend.when("POST", "/keys/upload").respond(200, function(path, content) { expect(content.one_time_keys).toBe(undefined); expect(content.device_keys).toBeTruthy(); @@ -111,6 +98,24 @@ TestClient.prototype.expectKeyUpload = function(existingDevices) { }); }; +/** + * Set up expectations that the client will query device keys. + * + * We check that the query contains each of the users in `response`. + * + * @param {Object} response response to the query. + */ +TestClient.prototype.expectKeyQuery = function(response) { + this.httpBackend.when('POST', '/keys/query').respond( + 200, (path, content) => { + Object.keys(response.device_keys).forEach((userId) => { + expect(content.device_keys[userId]).toEqual({}); + }); + return response; + }); +}; + + /** * get the uploaded curve25519 device key * diff --git a/spec/integ/matrix-client-crypto.spec.js b/spec/integ/matrix-client-crypto.spec.js index f25ec6725..966385394 100644 --- a/spec/integ/matrix-client-crypto.spec.js +++ b/spec/integ/matrix-client-crypto.spec.js @@ -393,7 +393,9 @@ describe("MatrixClient crypto", function() { afterEach(function() { aliTestClient.stop(); + aliTestClient.httpBackend.verifyNoOutstandingExpectation(); bobTestClient.stop(); + bobTestClient.httpBackend.verifyNoOutstandingExpectation(); }); it('Ali knows the difference between a new user and one with no devices', @@ -620,16 +622,13 @@ describe("MatrixClient crypto", function() { .then(function() { aliTestClient.client.setDeviceBlocked(bobUserId, bobDeviceId, true); const p1 = sendMessage(aliTestClient.client); - const p2 = expectAliQueryKeys() - .then(expectAliClaimKeys) - .then(function() { - return expectSendMessageRequest(aliTestClient.httpBackend); - }).then(function(sentContent) { - // no unblocked devices, so the ciphertext should be empty - expect(sentContent.ciphertext).toEqual({}); - }); + const p2 = expectSendMessageRequest(aliTestClient.httpBackend) + .then(function(sentContent) { + // no unblocked devices, so the ciphertext should be empty + expect(sentContent.ciphertext).toEqual({}); + }); return q.all([p1, p2]); - }).catch(testUtils.failTest).nodeify(done); + }).nodeify(done); }); it("Bob receives two pre-key messages", function(done) { @@ -685,4 +684,44 @@ describe("MatrixClient crypto", function() { }).then(expectAliQueryKeys) .nodeify(done); }); + + it("Ali does a key query when encryption is enabled", function(done) { + // enabling encryption in the room should make alice download devices + // for both members. + q() + .then(() => startClient(aliTestClient)) + .then(() => { + const syncData = { + next_batch: '2', + rooms: { + join: {}, + }, + }; + syncData.rooms.join[roomId] = { + state: { + events: [ + testUtils.mkEvent({ + type: 'm.room.encryption', + skey: '', + content: { + algorithm: 'm.olm.v1.curve25519-aes-sha2', + }, + }), + ], + }, + }; + + aliTestClient.httpBackend.when('GET', '/sync').respond( + 200, syncData); + return aliTestClient.httpBackend.flush('/sync', 1); + }).then(() => { + aliTestClient.expectKeyQuery({ + device_keys: { + [aliUserId]: {}, + [bobUserId]: {}, + }, + }); + return aliTestClient.httpBackend.flush('/keys/query', 1); + }).nodeify(done); + }); }); diff --git a/spec/integ/matrix-client-methods.spec.js b/spec/integ/matrix-client-methods.spec.js index 31c4a3da0..76a92ab9e 100644 --- a/spec/integ/matrix-client-methods.spec.js +++ b/spec/integ/matrix-client-methods.spec.js @@ -351,7 +351,6 @@ describe("MatrixClient", function() { httpBackend.when("POST", "/keys/query").check(function(req) { expect(req.data).toEqual({device_keys: { - '@alice:localhost': {}, 'boris': {}, 'chaz': {}, }}); diff --git a/spec/integ/megolm.spec.js b/spec/integ/megolm.spec.js index 099ab5528..6909b348e 100644 --- a/spec/integ/megolm.spec.js +++ b/spec/integ/megolm.spec.js @@ -349,6 +349,69 @@ describe("megolm", function() { }).nodeify(done); }); + it("Alice receives a megolm message before the session keys", function(done) { + // https://github.com/vector-im/riot-web/issues/2273 + let roomKeyEncrypted; + + return aliceTestClient.start().then(function() { + const p2pSession = createOlmSession(testOlmAccount, aliceTestClient); + + const groupSession = new Olm.OutboundGroupSession(); + groupSession.create(); + + // make the room_key event, but don't send it yet + roomKeyEncrypted = encryptGroupSessionKey({ + senderKey: testSenderKey, + recipient: aliceTestClient, + p2pSession: p2pSession, + groupSession: groupSession, + room_id: ROOM_ID, + }); + + // encrypt a message with the group session + const messageEncrypted = encryptMegolmEvent({ + senderKey: testSenderKey, + groupSession: groupSession, + room_id: ROOM_ID, + }); + + // Alice just gets the message event to start with + const syncResponse = { + next_batch: 1, + rooms: { + join: {}, + }, + }; + syncResponse.rooms.join[ROOM_ID] = { + timeline: { + events: [messageEncrypted], + }, + }; + + aliceTestClient.httpBackend.when("GET", "/sync").respond(200, syncResponse); + return aliceTestClient.httpBackend.flush("/sync", 1); + }).then(function() { + const room = aliceTestClient.client.getRoom(ROOM_ID); + const event = room.getLiveTimeline().getEvents()[0]; + expect(event.getContent().msgtype).toEqual('m.bad.encrypted'); + + // now she gets the room_key event + const syncResponse = { + next_batch: 2, + to_device: { + events: [roomKeyEncrypted], + }, + }; + + aliceTestClient.httpBackend.when("GET", "/sync").respond(200, syncResponse); + return aliceTestClient.httpBackend.flush("/sync", 1); + }).then(function() { + const room = aliceTestClient.client.getRoom(ROOM_ID); + const event = room.getLiveTimeline().getEvents()[0]; + expect(event.getContent().body).toEqual('42'); + }).nodeify(done); + }); + it("Alice gets a second room_key message", function(done) { return aliceTestClient.start().then(function() { const p2pSession = createOlmSession(testOlmAccount, aliceTestClient); @@ -672,9 +735,7 @@ describe("megolm", function() { let inboundGroupSession; let decrypted; - return aliceTestClient.start( - getTestKeysQueryResponse(aliceTestClient.userId), - ).then(function() { + return aliceTestClient.start().then(function() { // an encrypted room with just alice const syncResponse = { next_batch: 1, @@ -701,6 +762,13 @@ describe("megolm", function() { }; aliceTestClient.httpBackend.when('GET', '/sync').respond(200, syncResponse); + // the completion of the first initialsync hould make Alice + // invalidate the device cache for all members in e2e rooms (ie, + // herself), and do a key query. + aliceTestClient.expectKeyQuery( + getTestKeysQueryResponse(aliceTestClient.userId), + ); + return aliceTestClient.httpBackend.flush(); }).then(function() { aliceTestClient.client.setDeviceKnown(aliceTestClient.userId, 'DEVICE_ID'); diff --git a/spec/mock-request.js b/spec/mock-request.js index bbd2e97f3..bf1a1b04e 100644 --- a/spec/mock-request.js +++ b/spec/mock-request.js @@ -49,17 +49,17 @@ HttpBackend.prototype = { const tryFlush = function() { // if there's more real requests and more expected requests, flush 'em. console.log( - " trying to flush queue => reqs=%s expected=%s [%s]", - self.requests.length, self.expectedRequests.length, path, + " trying to flush queue => reqs=[%s] expected=[%s]", + self.requests, self.expectedRequests.map((er) => er.path), ); if (self._takeFromQueue(path)) { // try again on the next tick. - console.log(" flushed. Trying for more. [%s]", path); flushed += 1; if (numToFlush && flushed === numToFlush) { - console.log(" [%s] Flushed assigned amount: %s", path, numToFlush); + console.log(" Flushed assigned amount: %s", numToFlush); defer.resolve(); } else { + console.log(" flushed. Trying for more."); setTimeout(tryFlush, 0); } } else if (flushed === 0 && !triedWaiting) { @@ -68,7 +68,7 @@ HttpBackend.prototype = { setTimeout(tryFlush, 5); triedWaiting = true; } else { - console.log(" no more flushes. [%s]", path); + console.log(" no more flushes."); defer.resolve(); } }; diff --git a/src/client.js b/src/client.js index 7bd607fd1..e7207e22e 100644 --- a/src/client.js +++ b/src/client.js @@ -556,6 +556,9 @@ function _decryptEvent(client, event) { try { client._crypto.decryptEvent(event); } catch (e) { + console.warn( + `Error decrypting event (id=${event.getId()}): ${e}`, + ); if (!(e instanceof Crypto.DecryptionError)) { throw e; } diff --git a/src/crypto/DeviceList.js b/src/crypto/DeviceList.js index fc775cf5f..49b4a4179 100644 --- a/src/crypto/DeviceList.js +++ b/src/crypto/DeviceList.js @@ -64,7 +64,13 @@ export default class DeviceList { // just wait for the existing download to complete promises.push(this._keyDownloadsInProgressByUser[u]); } else { - if (forceDownload || !this.getStoredDevicesForUser(u)) { + if (forceDownload) { + console.log("Invalidating device list for " + u + + " for forceDownload"); + this.invalidateUserDeviceList(u); + } else if (!this.getStoredDevicesForUser(u)) { + console.log("Invalidating device list for " + u + + " due to empty cache"); this.invalidateUserDeviceList(u); } if (this._pendingUsersWithNewDevices[u]) { @@ -398,7 +404,7 @@ function _updateStoredDeviceKeysForUser(_olmDevice, userId, userStore, const signKeyId = "ed25519:" + deviceId; const signKey = deviceResult.keys[signKeyId]; if (!signKey) { - console.log("Device " + userId + ":" + deviceId + + console.warn("Device " + userId + ":" + deviceId + " has no ed25519 key"); return false; } @@ -408,8 +414,8 @@ function _updateStoredDeviceKeysForUser(_olmDevice, userId, userStore, try { olmlib.verifySignature(_olmDevice, deviceResult, userId, deviceId, signKey); } catch (e) { - console.log("Unable to verify signature on device " + - userId + ":" + deviceId + ":", e); + console.warn("Unable to verify signature on device " + + userId + ":" + deviceId + ":" + e); return false; } @@ -425,7 +431,7 @@ function _updateStoredDeviceKeysForUser(_olmDevice, userId, userStore, // best off sticking with the original keys. // // Should we warn the user about it somehow? - console.warn("Ed25519 key for device" + userId + ": " + + console.warn("Ed25519 key for device " + userId + ":" + deviceId + " has changed"); return false; } diff --git a/src/crypto/algorithms/base.js b/src/crypto/algorithms/base.js index 407e09d96..685332085 100644 --- a/src/crypto/algorithms/base.js +++ b/src/crypto/algorithms/base.js @@ -148,14 +148,42 @@ DecryptionAlgorithm.prototype.importRoomKey = function(session) { /** * Exception thrown when decryption fails * + * @alias module:crypto/algorithms/base.DecryptionError * @constructor - * @param {string} msg message describing the problem + * @param {string} msg user-visible message describing the problem + * + * @param {Object=} details key/value pairs reported in the logs but not shown + * to the user. + * * @extends Error */ -module.exports.DecryptionError = function(msg) { +const DecryptionError = function(msg, details) { + this.name = 'DecryptionError'; this.message = msg; + this.details = details; }; -utils.inherits(module.exports.DecryptionError, Error); +utils.inherits(DecryptionError, Error); + +/** override the string used when logging + * + * @returns {String} + */ +DecryptionError.prototype.toString = function() { + let result = this.name + '[msg: ' + this.message; + + if (this.details) { + result += ', ' + + Object.keys(this.details).map( + (k) => k + ': ' + this.details[k], + ).join(', '); + } + + result += ']'; + + return result; +}; + +module.exports.DecryptionError = DecryptionError; /** * Exception thrown specifically when we want to warn the user to consider diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js index 762a86459..f7d7b770e 100644 --- a/src/crypto/algorithms/megolm.js +++ b/src/crypto/algorithms/megolm.js @@ -544,7 +544,11 @@ MegolmDecryption.prototype.decryptEvent = function(event) { if (e.message === 'OLM.UNKNOWN_MESSAGE_INDEX') { this._addEventToPendingList(event); } - throw new base.DecryptionError(e); + throw new base.DecryptionError( + e.toString(), { + session: content.sender_key + '|' + content.session_id, + }, + ); } if (res === null) { @@ -552,6 +556,9 @@ MegolmDecryption.prototype.decryptEvent = function(event) { this._addEventToPendingList(event); throw new base.DecryptionError( "The sender's device has not sent us the keys for this message.", + { + session: content.sender_key + '|' + content.session_id, + }, ); } @@ -593,24 +600,30 @@ MegolmDecryption.prototype._addEventToPendingList = function(event) { * @param {module:models/event.MatrixEvent} event key event */ MegolmDecryption.prototype.onRoomKeyEvent = function(event) { - console.log("Adding key from ", event); const content = event.getContent(); + const senderKey = event.getSenderKey(); + const sessionId = content.session_id; if (!content.room_id || - !content.session_id || + !sessionId || !content.session_key ) { console.error("key event is missing fields"); return; } + if (!senderKey) { + console.error("key event has no sender key (not encrypted?)"); + return; + } + console.log(`Adding key for megolm session ${senderKey}|${sessionId}`); this._olmDevice.addInboundGroupSession( - content.room_id, event.getSenderKey(), content.session_id, + content.room_id, senderKey, sessionId, content.session_key, event.getKeysClaimed(), ); // have another go at decrypting events sent with this session. - this._retryDecryption(event.getSenderKey, content.session_id); + this._retryDecryption(senderKey, sessionId); }; diff --git a/src/crypto/algorithms/olm.js b/src/crypto/algorithms/olm.js index b98dccde5..f8715b1e2 100644 --- a/src/crypto/algorithms/olm.js +++ b/src/crypto/algorithms/olm.js @@ -64,7 +64,7 @@ OlmEncryption.prototype._ensureSession = function(roomMembers) { } const self = this; - this._prepPromise = self._crypto.downloadKeys(roomMembers, true).then(function(res) { + this._prepPromise = self._crypto.downloadKeys(roomMembers).then(function(res) { return self._crypto.ensureOlmSessionsForUsers(roomMembers); }).then(function() { self._sessionPrepared = true; @@ -174,12 +174,12 @@ OlmDecryption.prototype.decryptEvent = function(event) { try { payloadString = this._decryptMessage(deviceKey, message); } catch (e) { - console.warn( - "Failed to decrypt Olm event (id=" + - event.getId() + ") from " + deviceKey + - ": " + e.message, + throw new base.DecryptionError( + "Bad Encrypted Message", { + sender: deviceKey, + err: e, + }, ); - throw new base.DecryptionError("Bad Encrypted Message"); } const payload = JSON.parse(payloadString); @@ -187,22 +187,18 @@ OlmDecryption.prototype.decryptEvent = function(event) { // check that we were the intended recipient, to avoid unknown-key attack // https://github.com/vector-im/vector-web/issues/2483 if (payload.recipient != this._userId) { - console.warn( - "Event " + event.getId() + ": Intended recipient " + - payload.recipient + " does not match our id " + this._userId, - ); throw new base.DecryptionError( "Message was intented for " + payload.recipient, ); } - if (payload.recipient_keys.ed25519 != - this._olmDevice.deviceEd25519Key) { - console.warn( - "Event " + event.getId() + ": Intended recipient ed25519 key " + - payload.recipient_keys.ed25519 + " did not match ours", + if (payload.recipient_keys.ed25519 != this._olmDevice.deviceEd25519Key) { + throw new base.DecryptionError( + "Message not intended for this device", { + intended: payload.recipient_keys.ed25519, + our_key: this._olmDevice.deviceEd25519Key, + }, ); - throw new base.DecryptionError("Message not intended for this device"); } // check that the original sender matches what the homeserver told us, to @@ -210,23 +206,19 @@ OlmDecryption.prototype.decryptEvent = function(event) { // (this check is also provided via the sender's embedded ed25519 key, // which is checked elsewhere). if (payload.sender != event.getSender()) { - console.warn( - "Event " + event.getId() + ": original sender " + payload.sender + - " does not match reported sender " + event.getSender(), - ); throw new base.DecryptionError( - "Message forwarded from " + payload.sender, + "Message forwarded from " + payload.sender, { + reported_sender: event.getSender(), + }, ); } // Olm events intended for a room have a room_id. if (payload.room_id !== event.getRoomId()) { - console.warn( - "Event " + event.getId() + ": original room " + payload.room_id + - " does not match reported room " + event.room_id, - ); throw new base.DecryptionError( - "Message intended for room " + payload.room_id, + "Message intended for room " + payload.room_id, { + reported_room: event.room_id, + }, ); } diff --git a/src/crypto/index.js b/src/crypto/index.js index 72db66621..4f43eafb2 100644 --- a/src/crypto/index.js +++ b/src/crypto/index.js @@ -86,9 +86,6 @@ function Crypto(baseApis, eventEmitter, sessionStore, userId, deviceId, ); if (!myDevices) { - // we don't yet have a list of our own devices; make sure we - // get one when we flush the pendingUsersWithNewDevices. - this._deviceList.invalidateUserDeviceList(this._userId); myDevices = {}; } @@ -545,6 +542,23 @@ Crypto.prototype.setRoomEncryption = function(roomId, config) { config: config, }); this._roomEncryptors[roomId] = alg; + + // if encryption was not previously enabled in this room, we will have been + // ignoring new device events for these users so far. We may well have + // up-to-date lists for some users, for instance if we were sharing other + // e2e rooms with them, so there is room for optimisation here, but for now + // we just invalidate everyone in the room. + if (!existingConfig) { + console.log("Enabling encryption in " + roomId + " for the first time; " + + "invalidating device lists for all users therein"); + const room = this._clientStore.getRoom(roomId); + const members = room.getJoinedMembers(); + members.forEach((m) => { + this._deviceList.invalidateUserDeviceList(m.userId); + }); + // the actual refresh happens once we've finished processing the sync, + // in _onSyncCompleted. + } }; @@ -769,6 +783,8 @@ Crypto.prototype._onSyncCompleted = function(syncData) { } else { // otherwise, we have to invalidate all devices for all users we // share a room with. + console.log("Completed first initialsync; invalidating all " + + "device list caches"); this._invalidateDeviceListForAllActiveUsers(); } } diff --git a/src/sync.js b/src/sync.js index c8d0ace77..9132d7018 100644 --- a/src/sync.js +++ b/src/sync.js @@ -363,9 +363,6 @@ SyncApi.prototype.getSyncState = function() { * Main entry point */ SyncApi.prototype.sync = function() { - debuglog("SyncApi.sync: starting with sync token " + - this.client.store.getSyncToken()); - const client = this.client; const self = this; @@ -520,7 +517,7 @@ SyncApi.prototype._sync = function(syncOptions) { // Don't do an HTTP hit to /sync. Instead, load up the persisted /sync data, // if there is data there. if (data.nextBatch) { - console.log("sync(): not doing HTTP hit, instead returning stored /sync"); + debuglog("sync(): not doing HTTP hit, instead returning stored /sync data"); this._currentSyncRequest = q.resolve({ next_batch: data.nextBatch, rooms: data.roomsData, @@ -530,12 +527,15 @@ SyncApi.prototype._sync = function(syncOptions) { } if (!isCachedResponse) { + debuglog('Starting sync since=' + syncToken); this._currentSyncRequest = client._http.authedRequest( undefined, "GET", "/sync", qps, undefined, clientSideTimeoutMs, ); } this._currentSyncRequest.done(function(data) { + debuglog('Completed sync, next_batch=' + data.next_batch); + // set the sync token NOW *before* processing the events. We do this so // if something barfs on an event we can skip it rather than constantly // polling with the same token. @@ -697,8 +697,10 @@ SyncApi.prototype._processSyncResponse = function(syncToken, data) { toDeviceEvent.getType() == "m.room.message" && content.msgtype == "m.bad.encrypted" ) { - console.warn( - "Unable to decrypt to-device event: " + content.body, + // the mapper already logged a warning. + console.log( + 'Ignoring undecryptable to-device event from ' + + toDeviceEvent.getSender(), ); return; }