Log when we show, and hide, encryption setup toasts (#29235)

It's currently hard to debug when someone sees or hides one of these
toasts. Lets's add some logging.

src/DeviceListener.ts

@@ -15,7 +15,7 @@ import {
     type SyncState,
     ClientStoppedError,
 } from "matrix-js-sdk/src/matrix";
-import { logger } from "matrix-js-sdk/src/logger";
+import { logger as baseLogger } from "matrix-js-sdk/src/logger";
 import { CryptoEvent, type KeyBackupInfo } from "matrix-js-sdk/src/crypto-api";
 import { type CryptoSessionStateChange } from "@matrix-org/analytics-events/types/typescript/CryptoSessionStateChange";
 
@@ -48,6 +48,8 @@ import { asyncSomeParallel } from "./utils/arrays.ts";
 
 const KEY_BACKUP_POLL_INTERVAL = 5 * 60 * 1000;
 
+const logger = baseLogger.getChild("DeviceListener:");
+
 export default class DeviceListener {
     private dispatcherRef?: string;
     // device IDs for which the user has dismissed the verify toast ('Later')
@@ -131,7 +133,7 @@ export default class DeviceListener {
      * @param {String[]} deviceIds List of device IDs to dismiss notifications for
      */
     public async dismissUnverifiedSessions(deviceIds: Iterable<string>): Promise<void> {
-        logger.log("Dismissing unverified sessions: " + Array.from(deviceIds).join(","));
+        logger.debug("Dismissing unverified sessions: " + Array.from(deviceIds).join(","));
         for (const d of deviceIds) {
             this.dismissed.add(d);
         }
@@ -309,16 +311,20 @@ export default class DeviceListener {
             if (!crossSigningReady) {
                 // This account is legacy and doesn't have cross-signing set up at all.
                 // Prompt the user to set it up.
+                logger.info("Cross-signing not ready: showing SET_UP_ENCRYPTION toast");
                 showSetupEncryptionToast(SetupKind.SET_UP_ENCRYPTION);
             } else if (!isCurrentDeviceTrusted) {
                 // cross signing is ready but the current device is not trusted: prompt the user to verify
+                logger.info("Current device not verified: showing VERIFY_THIS_SESSION toast");
                 showSetupEncryptionToast(SetupKind.VERIFY_THIS_SESSION);
             } else if (!allCrossSigningSecretsCached) {
                 // cross signing ready & device trusted, but we are missing secrets from our local cache.
                 // prompt the user to enter their recovery key.
+                logger.info("Some secrets not cached: showing KEY_STORAGE_OUT_OF_SYNC toast");
                 showSetupEncryptionToast(SetupKind.KEY_STORAGE_OUT_OF_SYNC);
             } else if (defaultKeyId === null) {
                 // the user just hasn't set up 4S yet: prompt them to do so
+                logger.info("No default 4S key: showing SET_UP_RECOVERY toast");
                 showSetupEncryptionToast(SetupKind.SET_UP_RECOVERY);
             } else {
                 // some other condition... yikes! Show the 'set up encryption' toast: this is what we previously did

src/stores/ToastStore.ts

@@ -7,6 +7,7 @@ Please see LICENSE files in the repository root for full details.
 */
 
 import EventEmitter from "events";
+import { logger } from "matrix-js-sdk/src/logger";
 
 import type React from "react";
 import { type ComponentClass } from "../@types/common";
@@ -54,10 +55,12 @@ export default class ToastStore extends EventEmitter {
     public addOrReplaceToast<C extends ComponentClass>(newToast: IToast<C>): void {
         const oldIndex = this.toasts.findIndex((t) => t.key === newToast.key);
         if (oldIndex === -1) {
+            logger.info(`Opening toast with key '${newToast.key}': title '${newToast.title}'`);
             let newIndex = this.toasts.length;
             while (newIndex > 0 && this.toasts[newIndex - 1].priority < newToast.priority) --newIndex;
             this.toasts.splice(newIndex, 0, newToast);
         } else {
+            logger.info(`Replacing existing toast with key '${newToast.key}': title now '${newToast.title}'`);
             this.toasts[oldIndex] = newToast;
         }
         this.emit("update");
@@ -71,6 +74,7 @@ export default class ToastStore extends EventEmitter {
         const length = this.toasts.length;
         this.toasts = this.toasts.filter((t) => t.key !== key);
         if (length !== this.toasts.length) {
+            logger.info(`Removed toast with key '${key}'`);
             if (this.toasts.length === 0) {
                 this.countSeen = 0;
             }

test/unit-tests/DeviceListener-test.ts

@@ -8,7 +8,6 @@ Please see LICENSE files in the repository root for full details.
 
 import { type Mocked, mocked } from "jest-mock";
 import { MatrixEvent, type Room, type MatrixClient, Device, ClientStoppedError } from "matrix-js-sdk/src/matrix";
-import { logger } from "matrix-js-sdk/src/logger";
 import {
     CryptoEvent,
     type CrossSigningStatus,
@@ -33,9 +32,6 @@ import { UIFeature } from "../../src/settings/UIFeature";
 import { isBulkUnverifiedDeviceReminderSnoozed } from "../../src/utils/device/snoozeBulkUnverifiedDeviceReminder";
 import { PosthogAnalytics } from "../../src/PosthogAnalytics";
 
-// don't litter test console with logs
-jest.mock("matrix-js-sdk/src/logger");
-
 jest.mock("../../src/dispatcher/dispatcher", () => ({
     dispatch: jest.fn(),
     register: jest.fn(),
@@ -63,6 +59,12 @@ describe("DeviceListener", () => {
     beforeEach(() => {
         jest.resetAllMocks();
 
+        // don't litter the console with logs
+        jest.spyOn(console, "debug").mockImplementation(() => {});
+        jest.spyOn(console, "info").mockImplementation(() => {});
+        jest.spyOn(console, "warn").mockImplementation(() => {});
+        jest.spyOn(console, "error").mockImplementation(() => {});
+
         // spy on various toasts' hide and show functions
         // easier than mocking
         jest.spyOn(SetupEncryptionToast, "showToast").mockReturnValue(undefined);
@@ -158,14 +160,17 @@ describe("DeviceListener", () => {
             });
 
             it("catches error and logs when saving client information fails", async () => {
-                const errorLogSpy = jest.spyOn(logger, "error");
                 const error = new Error("oups");
                 mockClient!.setAccountData.mockRejectedValue(error);
 
                 // doesn't throw
                 await createAndStart();
 
-                expect(errorLogSpy).toHaveBeenCalledWith("Failed to update client information", error);
+                expect(console.error).toHaveBeenCalledWith(
+                    "DeviceListener:",
+                    "Failed to update client information",
+                    error,
+                );
             });
 
             it("saves client information on logged in action", async () => {
@@ -275,14 +280,14 @@ describe("DeviceListener", () => {
                 throw new ClientStoppedError();
             });
             await createAndStart();
-            expect(logger.error).not.toHaveBeenCalled();
+            expect(console.error).not.toHaveBeenCalled();
         });
         it("correctly handles other errors", async () => {
             mockCrypto!.isCrossSigningReady.mockImplementation(() => {
                 throw new Error("blah");
             });
             await createAndStart();
-            expect(logger.error).toHaveBeenCalledTimes(1);
+            expect(console.error).toHaveBeenCalledTimes(1);
         });
 
         describe("set up encryption", () => {