diff --git a/src/client.js b/src/client.js index 162f596d8..c744ff33d 100644 --- a/src/client.js +++ b/src/client.js @@ -550,6 +550,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 ebc0a59de..49b4a4179 100644 --- a/src/crypto/DeviceList.js +++ b/src/crypto/DeviceList.js @@ -404,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; } @@ -414,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; } @@ -431,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..bcf536fa2 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 df4fdb5af..f3a76eb1b 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,26 +600,27 @@ 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 || !senderKey ) { - console.error("key event is missing fields"); + console.error(`key event is missing fields`); return; } + console.log(`Adding key for megolm session ${senderKey}|${sessionId}`); this._olmDevice.addInboundGroupSession( - content.room_id, senderKey, 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(senderKey, content.session_id); + this._retryDecryption(senderKey, sessionId); }; diff --git a/src/crypto/algorithms/olm.js b/src/crypto/algorithms/olm.js index 99fb64c29..f8715b1e2 100644 --- a/src/crypto/algorithms/olm.js +++ b/src/crypto/algorithms/olm.js @@ -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/sync.js b/src/sync.js index facf5d6ed..237a1e24a 100644 --- a/src/sync.js +++ b/src/sync.js @@ -360,9 +360,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; @@ -511,11 +508,14 @@ SyncApi.prototype._sync = function(syncOptions) { // normal timeout= plus buffer time const clientSideTimeoutMs = this.opts.pollTimeout + BUFFER_PERIOD_MS; + 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. @@ -666,8 +666,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; }