Improve logs for decrypting events (#2879)

Some attempts to make debugging UISIs a bit easier
matrix-org · Nov 15, 2022 · f86f67f · f86f67f
1 parent 4dcf54f
commit f86f67f
Show file tree

Hide file tree

Showing 2 changed files with 37 additions and 8 deletions.
diff --git a/src/crypto/olmlib.ts b/src/crypto/olmlib.ts
@@ -88,12 +88,16 @@ export async function encryptMessageForDevice(
     if (sessionId === null) {
         // If we don't have a session for a device then
         // we can't encrypt a message for it.
+        logger.log(
+            `[olmlib.encryptMessageForDevice] Unable to find Olm session for device ` +
+            `${recipientUserId}:${recipientDevice.deviceId}`,
+        );
         return;
     }
 
     logger.log(
-        "Using sessionid " + sessionId + " for device " +
-            recipientUserId + ":" + recipientDevice.deviceId,
+        `[olmlib.encryptMessageForDevice] Using Olm session ${sessionId} for device ` +
+        `${recipientUserId}:${recipientDevice.deviceId}`,
     );
 
     const payload = {

diff --git a/src/models/event.ts b/src/models/event.ts
@@ -452,6 +452,26 @@ export class MatrixEvent extends TypedEventEmitter<MatrixEventEmittedEvents, Mat
         return this.event.origin_server_ts ? new Date(this.event.origin_server_ts) : null;
     }
 
+    /**
+     * Get a string containing details of this event
+     *
+     * This is intended for logging, to help trace errors. Example output:
+     *
+     * id=$HjnOHV646n0SjLDAqFrgIjim7RCpB7cdMXFrekWYAn type=m.room.encrypted sender=@user:example.com room=!room:example.com ts=2022-10-25T17:30:28.404Z
+     */
+    public getDetails(): string {
+        let details = `id=${this.getId()} type=${this.getWireType()} sender=${this.getSender()}`;
+        const room = this.getRoomId();
+        if (room) {
+            details += ` room=${room}`;
+        }
+        const date = this.getDate();
+        if (date) {
+            details += ` ts=${date.toISOString()}`;
+        }
+        return details;
+    }
+
     /**
      * Get the (decrypted, if necessary) event content JSON, even if the event
      * was replaced by another event.
@@ -780,7 +800,7 @@ export class MatrixEvent extends TypedEventEmitter<MatrixEventEmittedEvents, Mat
                 } else {
                     res = await crypto.decryptEvent(this);
                     if (options.isRetry === true) {
-                        logger.info(`Decrypted event on retry (id=${this.getId()})`);
+                        logger.info(`Decrypted event on retry (${this.getDetails()})`);
                     }
                 }
             } catch (e) {
@@ -790,7 +810,7 @@ export class MatrixEvent extends TypedEventEmitter<MatrixEventEmittedEvents, Mat
                     const re = options.isRetry ? 're' : '';
                     // For find results: this can produce "Error decrypting event (id=$ev)" and
                     // "Error redecrypting event (id=$ev)".
-                    logger.error(`Error ${re}decrypting event (id=${this.getId()})`, e);
+                    logger.error(`Error ${re}decrypting event (${this.getDetails()})`, e);
                     this.decryptionPromise = null;
                     this.retryDecryption = false;
                     return;
@@ -814,16 +834,21 @@ export class MatrixEvent extends TypedEventEmitter<MatrixEventEmittedEvents, Mat
                 //
                 if (this.retryDecryption) {
                     // decryption error, but we have a retry queued.
-                    logger.log(`Got error decrypting event (id=${this.getId()}: ` +
-                        `${(<DecryptionError>e).detailedString}), but retrying`, e);
+                    logger.log(
+                        `Error decrypting event (${this.getDetails()}), but retrying: ` +
+                        (<DecryptionError>e).detailedString,
+                    );
                     continue;
                 }
 
                 // decryption error, no retries queued. Warn about the error and
                 // set it to m.bad.encrypted.
+                //
+                // the detailedString already includes the name and message of the error, and the stack isn't much use,
+                // so we don't bother to log `e` separately.
                 logger.warn(
-                    `Got error decrypting event (id=${this.getId()}: ${(<DecryptionError>e).detailedString})`,
-                    e,
+                    `Error decrypting event (${this.getDetails()}): ` +
+                    (<DecryptionError>e).detailedString,
                 );
 
                 res = this.badEncryptedMessage((<DecryptionError>e).message);