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

@@ -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;
         }

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;
     }
 

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

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);
 };
 
 

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,
+            },
         );
     }
 

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;
                     }