Use client logger in more places (core code) (#4899)

* Use client logger for sync

Use the logger attached to the MatrixClient when writing log messages out of
the sync api. This helps figure out what's going on when multiple clients are
running in the same JS environment.

* Use client logger for to-device message queue

* Use client logger in `PushProcessor.rewriteDefaultRules`

* use client logger in `ServerCapabilities`

* Mark global `logger` as deprecated

Author: richvdh

spec/integ/sliding-sync-sdk.spec.ts

@@ -126,7 +126,7 @@ describe("SlidingSyncSdk", () => {
     // assign client/httpBackend globals
     const setupClient = async (testOpts?: Partial<IStoredClientOpts & { withCrypto: boolean }>) => {
         testOpts = testOpts || {};
-        const syncOpts: SyncApiOptions = {};
+        const syncOpts: SyncApiOptions = { logger };
         const testClient = new TestClient(selfUserId, "DEVICE", selfAccessToken);
         httpBackend = testClient.httpBackend;
         client = testClient.client;

spec/unit/ToDeviceMessageQueue.spec.ts

@@ -5,6 +5,7 @@ import { getMockClientWithEventEmitter } from "../test-utils/client";
 import { StubStore } from "../../src/store/stub";
 import { type IndexedToDeviceBatch } from "../../src/models/ToDeviceMessage";
 import { SyncState } from "../../src/sync";
+import { logger } from "../../src/logger.ts";
 
 describe("onResumedSync", () => {
     let batch: IndexedToDeviceBatch | null;
@@ -55,7 +56,7 @@ describe("onResumedSync", () => {
             }
         });
 
-        queue = new ToDeviceMessageQueue(mockClient);
+        queue = new ToDeviceMessageQueue(mockClient, logger);
     });
 
     it("resends queue after connectivity restored", async () => {

spec/unit/pushprocessor.spec.ts

@@ -28,6 +28,7 @@ import {
     TweakName,
 } from "../../src";
 import { mockClientMethodsUser } from "../test-utils/client";
+import { logger } from "../../src/logger.ts";
 
 const msc3914RoomCallRule: IPushRule = {
     rule_id: ".org.matrix.msc3914.rule.room.call",
@@ -209,7 +210,7 @@ describe("NotificationService", function () {
                 msgtype: "m.text",
             },
         });
-        matrixClient.pushRules = PushProcessor.rewriteDefaultRules(matrixClient.pushRules!);
+        matrixClient.pushRules = PushProcessor.rewriteDefaultRules(logger, matrixClient.pushRules!);
         pushProcessor = new PushProcessor(matrixClient);
     });
 
@@ -731,7 +732,7 @@ describe("Test PushProcessor.partsForDottedKey", function () {
 
 describe("rewriteDefaultRules", () => {
     it("should add default rules in the correct order", () => {
-        const pushRules = PushProcessor.rewriteDefaultRules({
+        const pushRules = PushProcessor.rewriteDefaultRules(logger, {
             device: {},
             global: {
                 content: [],
@@ -867,7 +868,7 @@ describe("rewriteDefaultRules", () => {
     });
 
     it("should add missing msc3914 rule in correct place", () => {
-        const pushRules = PushProcessor.rewriteDefaultRules({
+        const pushRules = PushProcessor.rewriteDefaultRules(logger, {
             device: {},
             global: {
                 // Sample push rules from a Synapse user.

src/ToDeviceMessageQueue.ts

@@ -15,7 +15,7 @@ limitations under the License.
 */
 
 import { ToDeviceMessageId } from "./@types/event.ts";
-import { logger } from "./logger.ts";
+import { type Logger } from "./logger.ts";
 import { type MatrixClient, ClientEvent } from "./client.ts";
 import { type MatrixError } from "./http-api/index.ts";
 import {
@@ -40,7 +40,10 @@ export class ToDeviceMessageQueue {
     private retryTimeout: ReturnType<typeof setTimeout> | null = null;
     private retryAttempts = 0;
 
-    public constructor(private client: MatrixClient) {}
+    public constructor(
+        private client: MatrixClient,
+        private readonly logger: Logger,
+    ) {}
 
     public start(): void {
         this.running = true;
@@ -67,7 +70,7 @@ export class ToDeviceMessageQueue {
             const msgmap = batchWithTxnId.batch.map(
                 (msg) => `${msg.userId}/${msg.deviceId} (msgid ${msg.payload[ToDeviceMessageId]})`,
             );
-            logger.info(
+            this.logger.info(
                 `Enqueuing batch of to-device messages. type=${batch.eventType} txnid=${batchWithTxnId.txnId}`,
                 msgmap,
             );
@@ -83,7 +86,7 @@ export class ToDeviceMessageQueue {
 
         if (this.sending || !this.running) return;
 
-        logger.debug("Attempting to send queued to-device messages");
+        this.logger.debug("Attempting to send queued to-device messages");
 
         this.sending = true;
         let headBatch: IndexedToDeviceBatch | null;
@@ -99,7 +102,7 @@ export class ToDeviceMessageQueue {
             // Make sure we're still running after the async tasks: if not, stop.
             if (!this.running) return;
 
-            logger.debug("All queued to-device messages sent");
+            this.logger.debug("All queued to-device messages sent");
         } catch (e) {
             ++this.retryAttempts;
             // eslint-disable-next-line @typescript-eslint/naming-convention
@@ -109,15 +112,15 @@ export class ToDeviceMessageQueue {
                 // the scheduler function doesn't differentiate between fatal errors and just getting
                 // bored and giving up for now
                 if (Math.floor((<MatrixError>e).httpStatus! / 100) === 4) {
-                    logger.error("Fatal error when sending to-device message - dropping to-device batch!", e);
+                    this.logger.error("Fatal error when sending to-device message - dropping to-device batch!", e);
                     await this.client.store.removeToDeviceBatch(headBatch!.id);
                 } else {
-                    logger.info("Automatic retry limit reached for to-device messages.");
+                    this.logger.info("Automatic retry limit reached for to-device messages.");
                 }
                 return;
             }
 
-            logger.info(`Failed to send batch of to-device messages. Will retry in ${retryDelay}ms`, e);
+            this.logger.info(`Failed to send batch of to-device messages. Will retry in ${retryDelay}ms`, e);
             this.retryTimeout = setTimeout(this.sendQueue, retryDelay);
         } finally {
             this.sending = false;
@@ -133,7 +136,7 @@ export class ToDeviceMessageQueue {
             contentMap.getOrCreate(item.userId).set(item.deviceId, item.payload);
         }
 
-        logger.info(
+        this.logger.info(
             `Sending batch of ${batch.batch.length} to-device messages with ID ${batch.id} and txnId ${batch.txnId}`,
         );
 
@@ -146,7 +149,7 @@ export class ToDeviceMessageQueue {
      */
     private onResumedSync = (state: SyncState | null, oldState: SyncState | null): void => {
         if (state === SyncState.Syncing && oldState !== SyncState.Syncing) {
-            logger.info(`Resuming queue after resumed sync`);
+            this.logger.info(`Resuming queue after resumed sync`);
             this.sendQueue();
         }
     };

src/client.ts

@@ -1364,7 +1364,7 @@ export class MatrixClient extends TypedEventEmitter<EmittedEvents, ClientEventHa
         // the underlying session management and doesn't use any actual media capabilities
         this.matrixRTC = new MatrixRTCSessionManager(this);
 
-        this.serverCapabilitiesService = new ServerCapabilities(this.http);
+        this.serverCapabilitiesService = new ServerCapabilities(this.logger, this.http);
 
         this.on(ClientEvent.Sync, this.fixupRoomNotifications);
 
@@ -1386,7 +1386,7 @@ export class MatrixClient extends TypedEventEmitter<EmittedEvents, ClientEventHa
 
         this.roomNameGenerator = opts.roomNameGenerator;
 
-        this.toDeviceMessageQueue = new ToDeviceMessageQueue(this);
+        this.toDeviceMessageQueue = new ToDeviceMessageQueue(this, this.logger);
 
         // The SDK doesn't really provide a clean way for events to recalculate the push
         // actions for themselves, so we have to kinda help them out when they are encrypted.
@@ -1503,6 +1503,7 @@ export class MatrixClient extends TypedEventEmitter<EmittedEvents, ClientEventHa
                 }
                 return this.canResetTimelineCallback(roomId);
             },
+            logger: this.logger.getChild("sync"),
         };
     }
 
@@ -7324,7 +7325,7 @@ export class MatrixClient extends TypedEventEmitter<EmittedEvents, ClientEventHa
      */
     public setPushRules(rules: IPushRules): void {
         // Fix-up defaults, if applicable.
-        this.pushRules = PushProcessor.rewriteDefaultRules(rules, this.getUserId()!);
+        this.pushRules = PushProcessor.rewriteDefaultRules(this.logger, rules, this.getUserId()!);
         // Pre-calculate any necessary caches.
         this.pushProcessor.updateCachedPushRuleKeys(this.pushRules);
     }

src/logger.ts

@@ -160,6 +160,9 @@ function getPrefixedLogger(prefix?: string): PrefixedLogger {
 /**
  * Drop-in replacement for `console` using {@link https://www.npmjs.com/package/loglevel|loglevel}.
  * Can be tailored down to specific use cases if needed.
+ *
+ * @deprecated avoid the use of this unless you are the constructor of `MatrixClient`: you should be using the logger
+ *    associated with `MatrixClient`.
  */
 export const logger = getPrefixedLogger() as LoggerWithLogMethod;
 

src/pushprocessor.ts

@@ -15,7 +15,7 @@ limitations under the License.
 */
 
 import { deepCompare, escapeRegExp, globToRegexp, isNullOrUndefined } from "./utils.ts";
-import { logger } from "./logger.ts";
+import { type Logger } from "./logger.ts";
 import { type MatrixClient } from "./client.ts";
 import { type MatrixEvent } from "./models/event.ts";
 import {
@@ -170,6 +170,7 @@ const EXPECTED_DEFAULT_UNDERRIDE_RULE_IDS: OrderedRules = [
 /**
  * Make sure that each of the rules listed in `defaultRuleIds` is listed in the given set of push rules.
  *
+ * @param logger - A `Logger` to write log messages to.
  * @param kind - the kind of push rule set being merged.
  * @param incomingRules - the existing set of known push rules for the user.
  * @param defaultRules - a lookup table for the default definitions of push rules.
@@ -178,6 +179,7 @@ const EXPECTED_DEFAULT_UNDERRIDE_RULE_IDS: OrderedRules = [
  * @returns A copy of `incomingRules`, with any missing default rules inserted in the right place.
  */
 function mergeRulesWithDefaults(
+    logger: Logger,
     kind: PushRuleKind,
     incomingRules: IPushRule[],
     defaultRules: Record<string, IPushRule>,
@@ -276,11 +278,17 @@ export class PushProcessor {
      * Rewrites conditions on a client's push rules to match the defaults
      * where applicable. Useful for upgrading push rules to more strict
      * conditions when the server is falling behind on defaults.
+     *
+     * @param logger - A `Logger` to write log messages to.
      * @param incomingRules - The client's existing push rules
      * @param userId - The Matrix ID of the client.
      * @returns The rewritten rules
      */
-    public static rewriteDefaultRules(incomingRules: IPushRules, userId: string | undefined = undefined): IPushRules {
+    public static rewriteDefaultRules(
+        logger: Logger,
+        incomingRules: IPushRules,
+        userId: string | undefined = undefined,
+    ): IPushRules {
         let newRules: IPushRules = JSON.parse(JSON.stringify(incomingRules)); // deep clone
 
         // These lines are mostly to make the tests happy. We shouldn't run into these
@@ -292,13 +300,15 @@ export class PushProcessor {
 
         // Merge the client-level defaults with the ones from the server
         newRules.global.override = mergeRulesWithDefaults(
+            logger,
             PushRuleKind.Override,
             newRules.global.override,
             DEFAULT_OVERRIDE_RULES,
             EXPECTED_DEFAULT_OVERRIDE_RULE_IDS,
         );
 
         newRules.global.underride = mergeRulesWithDefaults(
+            logger,
             PushRuleKind.Underride,
             newRules.global.underride,
             DEFAULT_UNDERRIDE_RULES,

src/serverCapabilities.ts

@@ -15,7 +15,7 @@ limitations under the License.
 */
 
 import { type IHttpOpts, type MatrixHttpApi, Method } from "./http-api/index.ts";
-import { logger } from "./logger.ts";
+import { type Logger } from "./logger.ts";
 
 // How often we update the server capabilities.
 // 6 hours - an arbitrary value, but they should change very infrequently.
@@ -78,7 +78,10 @@ export class ServerCapabilities {
     private retryTimeout?: ReturnType<typeof setTimeout>;
     private refreshTimeout?: ReturnType<typeof setInterval>;
 
-    public constructor(private readonly http: MatrixHttpApi<IHttpOpts & { onlyData: true }>) {}
+    public constructor(
+        private readonly logger: Logger,
+        private readonly http: MatrixHttpApi<IHttpOpts & { onlyData: true }>,
+    ) {}
 
     /**
      * Starts periodically fetching the server capabilities.
@@ -117,12 +120,12 @@ export class ServerCapabilities {
             await this.fetchCapabilities();
             this.clearTimeouts();
             this.refreshTimeout = setTimeout(this.poll, CAPABILITIES_CACHE_MS);
-            logger.debug("Fetched new server capabilities");
+            this.logger.debug("Fetched new server capabilities");
         } catch (e) {
             this.clearTimeouts();
             const howLong = Math.floor(CAPABILITIES_RETRY_MS + Math.random() * 5000);
             this.retryTimeout = setTimeout(this.poll, howLong);
-            logger.warn(`Failed to refresh capabilities: retrying in ${howLong}ms`, e);
+            this.logger.warn(`Failed to refresh capabilities: retrying in ${howLong}ms`, e);
         }
     };
 

src/sliding-sync-sdk.ts

@@ -326,8 +326,8 @@ export class SlidingSyncSdk {
     public constructor(
         private readonly slidingSync: SlidingSync,
         private readonly client: MatrixClient,
-        opts?: IStoredClientOpts,
-        syncOpts?: SyncApiOptions,
+        opts: IStoredClientOpts | undefined,
+        syncOpts: SyncApiOptions,
     ) {
         this.opts = defaultClientOpts(opts);
         this.syncOpts = defaultSyncApiOpts(syncOpts);
@@ -356,7 +356,11 @@ export class SlidingSyncSdk {
         let room = this.client.store.getRoom(roomId);
         if (!room) {
             if (!roomData.initial) {
-                logger.debug("initial flag not set but no stored room exists for room ", roomId, roomData);
+                this.syncOpts.logger.debug(
+                    "initial flag not set but no stored room exists for room ",
+                    roomId,
+                    roomData,
+                );
                 return;
             }
             room = _createAndReEmitRoom(this.client, roomId, this.opts);
@@ -366,7 +370,7 @@ export class SlidingSyncSdk {
 
     private onLifecycle(state: SlidingSyncState, resp: MSC3575SlidingSyncResponse | null, err?: Error): void {
         if (err) {
-            logger.debug("onLifecycle", state, err);
+            this.syncOpts.logger.debug("onLifecycle", state, err);
         }
         switch (state) {
             case SlidingSyncState.Complete:
@@ -407,7 +411,9 @@ export class SlidingSyncSdk {
                     }
                 } else {
                     this.failCount = 0;
-                    logger.log(`SlidingSyncState.RequestFinished with ${Object.keys(resp?.rooms || []).length} rooms`);
+                    this.syncOpts.logger.debug(
+                        `SlidingSyncState.RequestFinished with ${Object.keys(resp?.rooms || []).length} rooms`,
+                    );
                 }
                 break;
         }
@@ -526,7 +532,7 @@ export class SlidingSyncSdk {
     private shouldAbortSync(error: MatrixError): boolean {
         if (error.errcode === "M_UNKNOWN_TOKEN") {
             // The logout already happened, we just need to stop.
-            logger.warn("Token no longer valid - assuming logout");
+            this.syncOpts.logger.warn("Token no longer valid - assuming logout");
             this.stop();
             this.updateSyncState(SyncState.Error, { error });
             return true;
@@ -654,7 +660,7 @@ export class SlidingSyncSdk {
             for (let i = timelineEvents.length - 1; i >= 0; i--) {
                 const eventId = timelineEvents[i].getId();
                 if (room.getTimelineForEvent(eventId)) {
-                    logger.debug("Already have event " + eventId + " in limited " +
+                    this.syncOpts.logger.debug("Already have event " + eventId + " in limited " +
                         "sync - not resetting");
                     limited = false;
 
@@ -863,19 +869,19 @@ export class SlidingSyncSdk {
      * Main entry point. Blocks until stop() is called.
      */
     public async sync(): Promise<void> {
-        logger.debug("Sliding sync init loop");
+        this.syncOpts.logger.debug("Sliding sync init loop");
 
         //   1) We need to get push rules so we can check if events should bing as we get
         //      them from /sync.
         while (!this.client.isGuest()) {
             try {
-                logger.debug("Getting push rules...");
+                this.syncOpts.logger.debug("Getting push rules...");
                 const result = await this.client.getPushRules();
-                logger.debug("Got push rules");
+                this.syncOpts.logger.debug("Got push rules");
                 this.client.pushRules = result;
                 break;
             } catch (err) {
-                logger.error("Getting push rules failed", err);
+                this.syncOpts.logger.error("Getting push rules failed", err);
                 if (this.shouldAbortSync(<MatrixError>err)) {
                     return;
                 }
@@ -890,7 +896,7 @@ export class SlidingSyncSdk {
      * Stops the sync object from syncing.
      */
     public stop(): void {
-        logger.debug("SyncApi.stop");
+        this.syncOpts.logger.debug("SyncApi.stop");
         this.slidingSync.stop();
     }