From b66fed9ae9ea90842aa7dba30fff4b027eed045b Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 9 Feb 2017 17:36:22 +0000 Subject: [PATCH] Clean up/improve e2e logging In an attempt to make the rageshake logs a bit more useful, try to make the logging a bit saner. Firstly, make sure we log every decryption failure, and log it exactly once, rather than in several places. Also record when we receive megolm keys. Also add some more explicit logging in the sync loop. --- src/client.js | 3 +++ src/crypto/DeviceList.js | 8 +++---- src/crypto/algorithms/base.js | 34 +++++++++++++++++++++++--- src/crypto/algorithms/megolm.js | 20 +++++++++++----- src/crypto/algorithms/olm.js | 42 +++++++++++++-------------------- src/sync.js | 12 ++++++---- 6 files changed, 76 insertions(+), 43 deletions(-) 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; }