Write a log line when cancelling verification (#4828)

... in an attempt to figure out what might have caused a spurious cancellation
today

Author: richvdh

spec/unit/rust-crypto/verification.spec.ts

@@ -32,6 +32,7 @@ import {
 import { type OutgoingRequestProcessor } from "../../../src/rust-crypto/OutgoingRequestProcessor";
 import { type IDeviceKeys } from "../../../src/@types/crypto";
 import { EventType, MatrixEvent, MsgType } from "../../../src";
+import { logger } from "../../../src/logger.ts";
 
 describe("VerificationRequest", () => {
     describe("pending", () => {
@@ -147,6 +148,7 @@ describe("VerificationRequest", () => {
                 methods,
             );
             const aliceVerificationRequest = new RustVerificationRequest(
+                logger,
                 aliceOlmMachine,
                 innerVerificationRequest,
                 aliceRequestLoop as unknown as OutgoingRequestProcessor,
@@ -174,6 +176,7 @@ describe("VerificationRequest", () => {
                 "$m.key.verification.request",
             )!;
             const bobVerificationRequest = new RustVerificationRequest(
+                logger,
                 bobOlmMachine,
                 bobInnerVerificationRequest,
                 bobRequestLoop as unknown as OutgoingRequestProcessor,
@@ -278,6 +281,7 @@ describe("VerificationRequest", () => {
                 methods,
             );
             const aliceVerificationRequest = new RustVerificationRequest(
+                logger,
                 aliceOlmMachine,
                 innerVerificationRequest,
                 aliceRequestLoop as unknown as OutgoingRequestProcessor,
@@ -305,6 +309,7 @@ describe("VerificationRequest", () => {
                 "$m.key.verification.request",
             )!;
             const bobVerificationRequest = new RustVerificationRequest(
+                logger,
                 bobOlmMachine,
                 bobInnerVerificationRequest,
                 bobRequestLoop as unknown as OutgoingRequestProcessor,
@@ -392,6 +397,7 @@ describe("VerificationRequest", () => {
                 methods,
             );
             const aliceVerificationRequest = new RustVerificationRequest(
+                logger,
                 aliceOlmMachine,
                 innerVerificationRequest,
                 aliceRequestLoop as unknown as OutgoingRequestProcessor,
@@ -419,6 +425,7 @@ describe("VerificationRequest", () => {
                 "$m.key.verification.request",
             )!;
             const bobVerificationRequest = new RustVerificationRequest(
+                logger,
                 bobOlmMachine,
                 bobInnerVerificationRequest,
                 bobRequestLoop as unknown as OutgoingRequestProcessor,
@@ -496,7 +503,7 @@ function makeTestRequest(
     inner ??= makeMockedInner();
     olmMachine ??= {} as RustSdkCryptoJs.OlmMachine;
     outgoingRequestProcessor ??= {} as OutgoingRequestProcessor;
-    return new RustVerificationRequest(olmMachine, inner, outgoingRequestProcessor, []);
+    return new RustVerificationRequest(logger, olmMachine, inner, outgoingRequestProcessor, []);
 }
 
 /** Mock up a rust-side VerificationRequest */

src/rust-crypto/rust-crypto.ts

@@ -969,15 +969,7 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
         );
         return requests
             .filter((request) => request.roomId === undefined)
-            .map(
-                (request) =>
-                    new RustVerificationRequest(
-                        this.olmMachine,
-                        request,
-                        this.outgoingRequestProcessor,
-                        this._supportedVerificationMethods,
-                    ),
-            );
+            .map((request) => this.makeVerificationRequest(request));
     }
 
     /**
@@ -1002,12 +994,7 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
         const request = requests.find((request) => request.roomId?.toString() === roomId);
 
         if (request) {
-            return new RustVerificationRequest(
-                this.olmMachine,
-                request,
-                this.outgoingRequestProcessor,
-                this._supportedVerificationMethods,
-            );
+            return this.makeVerificationRequest(request);
         }
     }
 
@@ -1038,12 +1025,7 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
                 new RustSdkCryptoJs.EventId(eventId),
                 methods,
             );
-            return new RustVerificationRequest(
-                this.olmMachine,
-                request,
-                this.outgoingRequestProcessor,
-                this._supportedVerificationMethods,
-            );
+            return this.makeVerificationRequest(request);
         } finally {
             userIdentity.free();
         }
@@ -1114,12 +1096,7 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
                     this._supportedVerificationMethods.map(verificationMethodIdentifierToMethod),
                 );
             await this.outgoingRequestProcessor.makeOutgoingRequest(outgoingRequest);
-            return new RustVerificationRequest(
-                this.olmMachine,
-                request,
-                this.outgoingRequestProcessor,
-                this._supportedVerificationMethods,
-            );
+            return this.makeVerificationRequest(request);
         } finally {
             userIdentity.free();
         }
@@ -1152,12 +1129,7 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
                 this._supportedVerificationMethods.map(verificationMethodIdentifierToMethod),
             );
             await this.outgoingRequestProcessor.makeOutgoingRequest(outgoingRequest);
-            return new RustVerificationRequest(
-                this.olmMachine,
-                request,
-                this.outgoingRequestProcessor,
-                this._supportedVerificationMethods,
-            );
+            return this.makeVerificationRequest(request);
         } finally {
             device.free();
         }
@@ -1667,15 +1639,7 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
         );
 
         if (request) {
-            this.emit(
-                CryptoEvent.VerificationRequestReceived,
-                new RustVerificationRequest(
-                    this.olmMachine,
-                    request,
-                    this.outgoingRequestProcessor,
-                    this._supportedVerificationMethods,
-                ),
-            );
+            this.emit(CryptoEvent.VerificationRequestReceived, this.makeVerificationRequest(request));
         } else {
             // There are multiple reasons this can happen; probably the most likely is that the event is an
             // in-room event which is too old.
@@ -1685,6 +1649,17 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, CryptoEventH
         }
     }
 
+    /** Utility function to wrap a rust `VerificationRequest` with our own {@link VerificationRequest}. */
+    private makeVerificationRequest(request: RustSdkCryptoJs.VerificationRequest): VerificationRequest {
+        return new RustVerificationRequest(
+            this.logger,
+            this.olmMachine,
+            request,
+            this.outgoingRequestProcessor,
+            this._supportedVerificationMethods,
+        );
+    }
+
     ///////////////////////////////////////////////////////////////////////////////////////////////////////////////////
     //
     // Other public functions

src/rust-crypto/verification.ts

@@ -36,6 +36,7 @@ import { type MatrixEvent } from "../models/event.ts";
 import { EventType, MsgType } from "../@types/event.ts";
 import { defer, type IDeferred } from "../utils.ts";
 import { VerificationMethod } from "../types.ts";
+import type { Logger } from "../logger.ts";
 
 /**
  * An incoming, or outgoing, request to verify a user or a device via cross-signing.
@@ -60,12 +61,14 @@ export class RustVerificationRequest
     /**
      * Construct a new RustVerificationRequest to wrap the rust-level `VerificationRequest`.
      *
+     * @param logger - A logger instance which will be used to log events.
      * @param olmMachine - The `OlmMachine` from the underlying rust crypto sdk.
      * @param inner - VerificationRequest from the Rust SDK.
      * @param outgoingRequestProcessor - `OutgoingRequestProcessor` to use for making outgoing HTTP requests.
      * @param supportedVerificationMethods - Verification methods to use when `accept()` is called.
      */
     public constructor(
+        private readonly logger: Logger,
         private readonly olmMachine: RustSdkCryptoJs.OlmMachine,
         private readonly inner: RustSdkCryptoJs.VerificationRequest,
         private readonly outgoingRequestProcessor: OutgoingRequestProcessor,
@@ -309,6 +312,7 @@ export class RustVerificationRequest
             return;
         }
 
+        this.logger.info("Cancelling verification request with params:", params);
         this._cancelling = true;
         try {
             const req: undefined | OutgoingRequest = this.inner.cancel();