v9.8.0-rc.1

Optimise prefixed logger

CHANGELOG.md

@@ -1,3 +1,24 @@
+Changes in [9.8.0-rc.1](https://github.com/matrix-org/matrix-js-sdk/releases/tag/v9.8.0-rc.1) (2021-02-24)
+==========================================================================================================
+[Full Changelog](https://github.com/matrix-org/matrix-js-sdk/compare/v9.7.0...v9.8.0-rc.1)
+
+ * Optimise prefixed logger
+   [\#1615](https://github.com/matrix-org/matrix-js-sdk/pull/1615)
+ * Add debug logs to encryption prep, take 3
+   [\#1614](https://github.com/matrix-org/matrix-js-sdk/pull/1614)
+ * Add functions for upper & lowercase random strings
+   [\#1612](https://github.com/matrix-org/matrix-js-sdk/pull/1612)
+ * Room helpers for invite permissions and join rules
+   [\#1609](https://github.com/matrix-org/matrix-js-sdk/pull/1609)
+ * Fixed wording in "Adding video track with id" log
+   [\#1606](https://github.com/matrix-org/matrix-js-sdk/pull/1606)
+ * Add more debug logs to encryption prep
+   [\#1605](https://github.com/matrix-org/matrix-js-sdk/pull/1605)
+ * Add option to set ice candidate pool size
+   [\#1604](https://github.com/matrix-org/matrix-js-sdk/pull/1604)
+ * Cancel call if no source was selected
+   [\#1601](https://github.com/matrix-org/matrix-js-sdk/pull/1601)
+
 Changes in [9.7.0](https://github.com/matrix-org/matrix-js-sdk/releases/tag/v9.7.0) (2021-02-16)
 ================================================================================================
 [Full Changelog](https://github.com/matrix-org/matrix-js-sdk/compare/v9.7.0-rc.1...v9.7.0)

package.json

@@ -1,6 +1,6 @@
 {
   "name": "matrix-js-sdk",
-  "version": "9.7.0",
+  "version": "9.8.0-rc.1",
   "description": "Matrix Client-Server SDK for Javascript",
   "scripts": {
     "prepublishOnly": "yarn build",

src/client.js

@@ -180,6 +180,11 @@ function keyFromRecoverySession(session, decryptionKey) {
  * @param {boolean} [opts.forceTURN]
  * Optional. Whether relaying calls through a TURN server should be forced.
  *
+ * * @param {boolean} [opts.iceCandidatePoolSize]
+ * Optional. Up to this many ICE candidates will be gathered when an incoming call arrives.
+ * Gathering does not send data to the caller, but will communicate with the configured TURN
+ * server. Default 0.
+ *
  * @param {boolean} [opts.supportsCallTransfer]
  * Optional. True to advertise support for call transfers to other parties on Matrix calls.
  *
@@ -367,6 +372,7 @@ export function MatrixClient(opts) {
     this._cryptoCallbacks = opts.cryptoCallbacks || {};
 
     this._forceTURN = opts.forceTURN || false;
+    this._iceCandidatePoolSize = opts.iceCandidatePoolSize === undefined ? 0 : opts.iceCandidatePoolSize;
     this._supportsCallTransfer = opts.supportsCallTransfer || false;
     this._fallbackICEServerAllowed = opts.fallbackICEServerAllowed || false;
 

src/crypto/algorithms/megolm.js

@@ -22,7 +22,7 @@ limitations under the License.
  * @module crypto/algorithms/megolm
  */
 
-import {logger} from '../../logger';
+import {getPrefixedLogger, logger} from '../../logger';
 import * as utils from "../../utils";
 import {polyfillSuper} from "../../utils";
 import * as olmlib from "../olmlib";
@@ -271,7 +271,7 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                 logger.debug(`Shared keys with existing Olm sessions in ${this._roomId}`);
             })(),
             (async () => {
-                logger.debug(`Sharing keys with new Olm sessions in ${this._roomId}`);
+                logger.debug(`Sharing keys (start phase 1) with new Olm sessions in ${this._roomId}`);
                 const errorDevices = [];
 
                 // meanwhile, establish olm sessions for devices that we don't
@@ -285,6 +285,7 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                     session, key, payload, devicesWithoutSession, errorDevices,
                     singleOlmCreationPhase ? 10000 : 2000, failedServers,
                 );
+                logger.debug(`Shared keys (end phase 1) with new Olm sessions in ${this._roomId}`);
 
                 if (!singleOlmCreationPhase && (Date.now() - start < 10000)) {
                     // perform the second phase of olm session creation if requested,
@@ -313,21 +314,24 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                             }
                         }
 
+                        logger.debug(`Sharing keys (start phase 2) with new Olm sessions in ${this._roomId}`);
                         await this._shareKeyWithDevices(
                             session, key, payload, retryDevices, failedDevices, 30000,
                         );
+                        logger.debug(`Shared keys (end phase 2) with new Olm sessions in ${this._roomId}`);
 
                         await this._notifyFailedOlmDevices(session, key, failedDevices);
                     })();
                 } else {
                     await this._notifyFailedOlmDevices(session, key, errorDevices);
                 }
-                logger.debug(`Shared keys with new Olm sessions in ${this._roomId}`);
+                logger.debug(`Shared keys (all phases done) with new Olm sessions in ${this._roomId}`);
             })(),
             (async () => {
                 logger.debug(`Notifying blocked devices in ${this._roomId}`);
                 // also, notify blocked devices that they're blocked
                 const blockedMap = {};
+                let blockedCount = 0;
                 for (const [userId, userBlockedDevices] of Object.entries(blocked)) {
                     for (const [deviceId, device] of Object.entries(userBlockedDevices)) {
                         if (
@@ -335,13 +339,14 @@ MegolmEncryption.prototype._ensureOutboundSession = async function(
                             session.blockedDevicesNotified[userId][deviceId] === undefined
                         ) {
                             blockedMap[userId] = blockedMap[userId] || {};
-                            blockedMap[userId][deviceId] = {device};
+                            blockedMap[userId][deviceId] = { device };
+                            blockedCount++;
                         }
                     }
                 }
 
                 await this._notifyBlockedDevices(session, blockedMap);
-                logger.debug(`Notified blocked devices in ${this._roomId}`);
+                logger.debug(`Notified ${blockedCount} blocked devices in ${this._roomId}`);
             })(),
         ]);
     };
@@ -728,13 +733,18 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
 MegolmEncryption.prototype._shareKeyWithDevices = async function(
     session, key, payload, devicesByUser, errorDevices, otkTimeout, failedServers,
 ) {
+    logger.debug(`Ensuring Olm sessions for devices in ${this._roomId}`);
     const devicemap = await olmlib.ensureOlmSessionsForDevices(
         this._olmDevice, this._baseApis, devicesByUser, otkTimeout, failedServers,
+        getPrefixedLogger(`[${this._roomId}]`),
     );
+    logger.debug(`Ensured Olm sessions for devices in ${this._roomId}`);
 
     this._getDevicesWithoutSessions(devicemap, devicesByUser, errorDevices);
 
+    logger.debug(`Sharing keys with Olm sessions in ${this._roomId}`);
     await this._shareKeyWithOlmSessions(session, key, payload, devicemap);
+    logger.debug(`Shared keys with Olm sessions in ${this._roomId}`);
 };
 
 MegolmEncryption.prototype._shareKeyWithOlmSessions = async function(
@@ -743,16 +753,17 @@ MegolmEncryption.prototype._shareKeyWithOlmSessions = async function(
     const userDeviceMaps = this._splitDevices(devicemap);
 
     for (let i = 0; i < userDeviceMaps.length; i++) {
+        const taskDetail =
+            `megolm keys for ${session.sessionId} ` +
+            `in ${this._roomId} (slice ${i + 1}/${userDeviceMaps.length})`;
         try {
+            logger.debug(`Sharing ${taskDetail}`);
             await this._encryptAndSendKeysToDevices(
                 session, key.chain_index, userDeviceMaps[i], payload,
             );
-            logger.log(`Completed megolm keyshare for ${session.sessionId} `
-                + `in ${this._roomId} (slice ${i + 1}/${userDeviceMaps.length})`);
+            logger.debug(`Shared ${taskDetail}`);
         } catch (e) {
-            logger.log(`megolm keyshare for ${session.sessionId} in ${this._roomId} `
-                + `(slice ${i + 1}/${userDeviceMaps.length}) failed`);
-
+            logger.error(`Failed to share ${taskDetail}`);
             throw e;
         }
     }
@@ -771,6 +782,11 @@ MegolmEncryption.prototype._shareKeyWithOlmSessions = async function(
 MegolmEncryption.prototype._notifyFailedOlmDevices = async function(
     session, key, failedDevices,
 ) {
+    logger.debug(
+        `Notifying ${failedDevices.length} devices we failed to ` +
+        `create Olm sessions in ${this._roomId}`,
+    );
+
     // mark the devices that failed as "handled" because we don't want to try
     // to claim a one-time-key for dead devices on every message.
     for (const {userId, deviceInfo} of failedDevices) {
@@ -785,6 +801,10 @@ MegolmEncryption.prototype._notifyFailedOlmDevices = async function(
           await this._olmDevice.filterOutNotifiedErrorDevices(
               failedDevices,
           );
+    logger.debug(
+        `Filtered down to ${filteredFailedDevices.length} error devices ` +
+        `in ${this._roomId}`,
+    );
     const blockedMap = {};
     for (const {userId, deviceInfo} of filteredFailedDevices) {
         blockedMap[userId] = blockedMap[userId] || {};
@@ -802,6 +822,10 @@ MegolmEncryption.prototype._notifyFailedOlmDevices = async function(
 
     // send the notifications
     await this._notifyBlockedDevices(session, blockedMap);
+    logger.debug(
+        `Notified ${filteredFailedDevices.length} devices we failed to ` +
+        `create Olm sessions in ${this._roomId}`,
+    );
 };
 
 /**

src/crypto/olmlib.js

@@ -183,18 +183,24 @@ export async function getExistingOlmSessions(
  * @param {Array} [failedServers] An array to fill with remote servers that
  *     failed to respond to one-time-key requests.
  *
+ * @param {Object} [log] A possibly customised log
+ *
  * @return {Promise} resolves once the sessions are complete, to
  *    an Object mapping from userId to deviceId to
  *    {@link module:crypto~OlmSessionResult}
  */
 export async function ensureOlmSessionsForDevices(
-    olmDevice, baseApis, devicesByUser, force, otkTimeout, failedServers,
+    olmDevice, baseApis, devicesByUser, force, otkTimeout, failedServers, log,
 ) {
     if (typeof force === "number") {
+        log = failedServers;
         failedServers = otkTimeout;
         otkTimeout = force;
         force = false;
     }
+    if (!log) {
+        log = logger;
+    }
 
     const devicesWithoutSession = [
         // [userId, deviceId], ...
@@ -216,7 +222,7 @@ export async function ensureOlmSessionsForDevices(
                 // new chain when this side has an active sender chain.
                 // If you see this message being logged in the wild, we should find
                 // the thing that is trying to send Olm messages to itself and fix it.
-                logger.info("Attempted to start session with ourself! Ignoring");
+                log.info("Attempted to start session with ourself! Ignoring");
                 // We must fill in the section in the return value though, as callers
                 // expect it to be there.
                 result[userId][deviceId] = {
@@ -258,9 +264,9 @@ export async function ensureOlmSessionsForDevices(
             }
             if (sessionId === null || force) {
                 if (force) {
-                    logger.info("Forcing new Olm session for " + userId + ":" + deviceId);
+                    log.info(`Forcing new Olm session for ${userId}:${deviceId}`);
                 } else {
-                    logger.info("Making new Olm session for " + userId + ":" + deviceId);
+                    log.info(`Making new Olm session for ${userId}:${deviceId}`);
                 }
                 devicesWithoutSession.push([userId, deviceId]);
             }
@@ -277,16 +283,29 @@ export async function ensureOlmSessionsForDevices(
 
     const oneTimeKeyAlgorithm = "signed_curve25519";
     let res;
+    let taskDetail = `one-time keys for ${devicesWithoutSession.length} devices`;
+    // If your homeserver takes a nap here and never replies, this process
+    // would hang indefinitely. While that's easily fixed by setting a
+    // timeout on this request, let's first log whether that's the root
+    // cause we're seeing in practice.
+    // See also https://github.com/vector-im/element-web/issues/16194
+    const otkTimeoutLogger = setTimeout(() => {
+        log.error(`Homeserver never replied while claiming ${taskDetail}`);
+    }, otkTimeout);
     try {
+        log.debug(`Claiming ${taskDetail}`);
         res = await baseApis.claimOneTimeKeys(
             devicesWithoutSession, oneTimeKeyAlgorithm, otkTimeout,
         );
+        log.debug(`Claimed ${taskDetail}`);
     } catch (e) {
         for (const resolver of Object.values(resolveSession)) {
             resolver.resolve();
         }
-        logger.log("failed to claim one-time keys", e, devicesWithoutSession);
+        log.log(`Failed to claim ${taskDetail}`, e, devicesWithoutSession);
         throw e;
+    } finally {
+        clearTimeout(otkTimeoutLogger);
     }
 
     if (failedServers && "failures" in res) {
@@ -323,9 +342,10 @@ export async function ensureOlmSessionsForDevices(
             }
 
             if (!oneTimeKey) {
-                const msg = "No one-time keys (alg=" + oneTimeKeyAlgorithm +
-                      ") for device " + userId + ":" + deviceId;
-                logger.warn(msg);
+                log.warn(
+                    `No one-time keys (alg=${oneTimeKeyAlgorithm}) ` +
+                    `for device ${userId}:${deviceId}`,
+                );
                 if (resolveSession[key]) {
                     resolveSession[key].resolve();
                 }
@@ -350,7 +370,10 @@ export async function ensureOlmSessionsForDevices(
         }
     }
 
+    taskDetail = `Olm sessions for ${promises.length} devices`;
+    log.debug(`Starting ${taskDetail}`);
     await Promise.all(promises);
+    log.debug(`Started ${taskDetail}`);
     return result;
 }
 

src/logger.ts

@@ -1,6 +1,6 @@
 /*
 Copyright 2018 André Jaenisch
-Copyright 2019 The Matrix.org Foundation C.I.C.
+Copyright 2019, 2021 The Matrix.org Foundation C.I.C.
 
 Licensed under the Apache License, Version 2.0 (the "License");
 you may not use this file except in compliance with the License.
@@ -19,7 +19,7 @@ limitations under the License.
  * @module logger
  */
 
-import log from "loglevel";
+import log, { Logger } from "loglevel";
 
 // This is to demonstrate, that you can use any namespace you want.
 // Namespaces allow you to turn on/off the logging for specific parts of the
@@ -36,6 +36,11 @@ const DEFAULT_NAMESPACE = "matrix";
 // when logging so we always get the current value of console methods.
 log.methodFactory = function(methodName, logLevel, loggerName) {
     return function(...args) {
+        /* eslint-disable babel/no-invalid-this */
+        if (this.prefix) {
+            args.unshift(this.prefix);
+        }
+        /* eslint-enable babel/no-invalid-this */
         const supportedByConsole = methodName === "error" ||
             methodName === "warn" ||
             methodName === "trace" ||
@@ -57,3 +62,16 @@ log.methodFactory = function(methodName, logLevel, loggerName) {
 export const logger = log.getLogger(DEFAULT_NAMESPACE);
 logger.setLevel(log.levels.DEBUG);
 
+interface PrefixedLogger extends Logger {
+    prefix?: any;
+}
+
+export function getPrefixedLogger(prefix): PrefixedLogger {
+    const prefixLogger: PrefixedLogger = log.getLogger(`${DEFAULT_NAMESPACE}-${prefix}`);
+    if (prefixLogger.prefix !== prefix) {
+        // Only do this setup work the first time through, as loggers are saved by name.
+        prefixLogger.prefix = prefix;
+        prefixLogger.setLevel(log.levels.DEBUG);
+    }
+    return prefixLogger;
+}

src/matrix.ts

@@ -142,6 +142,7 @@ export interface ICreateClientOpts {
     unstableClientRelationAggregation?: boolean;
     verificationMethods?: Array<any>;
     forceTURN?: boolean;
+    iceCandidatePoolSize?: number,
     supportsCallTransfer?: boolean,
     fallbackICEServerAllowed?: boolean;
     cryptoCallbacks?: ICryptoCallbacks;

src/models/room-state.js

@@ -23,6 +23,7 @@ import {EventEmitter} from "events";
 import {RoomMember} from "./room-member";
 import {logger} from '../logger';
 import * as utils from "../utils";
+import {EventType} from "../@types/event";
 
 // possible statuses for out-of-band member loading
 const OOB_STATUS_NOTSTARTED = 1;
@@ -718,6 +719,16 @@ RoomState.prototype.mayTriggerNotifOfType = function(notifLevelKey, userId) {
     return member.powerLevel >= notifLevel;
 };
 
+/**
+ * Returns the join rule based on the m.room.join_rule state event, defaulting to `invite`.
+ * @returns {string} the join_rule applied to this room
+ */
+RoomState.prototype.getJoinRule = function() {
+    const joinRuleEvent = this.getStateEvents(EventType.RoomJoinRules, "");
+    const joinRuleContent = joinRuleEvent ? joinRuleEvent.getContent() : {};
+    return joinRuleContent["join_rule"] || "invite";
+};
+
 
 function _updateThirdPartyTokenCache(roomState, memberEvent) {
     if (!memberEvent.getContent().third_party_invite) {

src/models/room.js

@@ -30,6 +30,7 @@ import {RoomMember} from "./room-member";
 import {RoomSummary} from "./room-summary";
 import {logger} from '../logger';
 import {ReEmitter} from '../ReEmitter';
+import {EventType} from "../@types/event";
 
 // These constants are used as sane defaults when the homeserver doesn't support
 // the m.room_versions capability. In practice, KNOWN_SAFE_ROOM_VERSION should be
@@ -1822,7 +1823,7 @@ Room.prototype.getAccountData = function(type) {
 
 
 /**
- * Returns wheter the syncing user has permission to send a message in the room
+ * Returns whether the syncing user has permission to send a message in the room
  * @return {boolean} true if the user should be permitted to send
  *                   message events into the room.
  */
@@ -1831,6 +1832,30 @@ Room.prototype.maySendMessage = function() {
         this.currentState.maySendEvent('m.room.message', this.myUserId);
 };
 
+/**
+ * Returns whether the given user has permissions to issue an invite for this room.
+ * @param {string} userId the ID of the Matrix user to check permissions for
+ * @returns {boolean} true if the user should be permitted to issue invites for this room.
+ */
+Room.prototype.canInvite = function(userId) {
+    let canInvite = this.getMyMembership() === "join";
+    const powerLevelsEvent = this.currentState.getStateEvents(EventType.RoomPowerLevels, "");
+    const powerLevels = powerLevelsEvent && powerLevelsEvent.getContent();
+    const me = this.getMember(userId);
+    if (powerLevels && me && powerLevels.invite > me.powerLevel) {
+        canInvite = false;
+    }
+    return canInvite;
+};
+
+/**
+ * Returns the join rule based on the m.room.join_rule state event, defaulting to `invite`.
+ * @returns {string} the join_rule applied to this room
+ */
+Room.prototype.getJoinRule = function() {
+    return this.currentState.getJoinRule();
+};
+
 /**
  * This is an internal method. Calculates the name of the room from the current
  * room state.
@@ -2048,3 +2073,12 @@ function memberNamesToRoomName(names, count = (names.length + 1)) {
  *
  * @param {EventStatus} oldStatus The previous event status.
  */
+
+/**
+ * Fires when the logged in user's membership in the room is updated.
+ *
+ * @event module:models/room~Room#"Room.myMembership"
+ * @param {Room} room The room in which the membership has been updated
+ * @param {string} membership The new membership value
+ * @param {string} prevMembership The previous membership value
+ */

src/randomstring.ts

@@ -15,9 +15,24 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
+const LOWERCASE = "abcdefghijklmnopqrstuvwxyz";
+const UPPERCASE = "ABCDEFGHIJKLMNOPQRSTUVWXYZ";
+const DIGITS = "0123456789";
+
 export function randomString(len: number): string {
+    return randomStringFrom(len, UPPERCASE + LOWERCASE + DIGITS);
+}
+
+export function randomLowercaseString(len: number): string {
+    return randomStringFrom(len, LOWERCASE);
+}
+
+export function randomUppercaseString(len: number): string {
+    return randomStringFrom(len, UPPERCASE);
+}
+
+function randomStringFrom(len: number, chars: string): string {
     let ret = "";
-    const chars = "ABCDEFGHIJKLMNOPQRSTUVWXYZabcdefghijklmnopqrstuvwxyz0123456789";
 
     for (let i = 0; i < len; ++i) {
         ret += chars.charAt(Math.floor(Math.random() * chars.length));

src/webrtc/call.ts

@@ -377,6 +377,8 @@ export class MatrixCall extends EventEmitter {
             logger.debug("Electron getDesktopCapturerSources() is available...");
             try {
                 const selectedSource = await selectDesktopCapturerSource();
+                // If no source was selected cancel call
+                if (!selectedSource) return;
                 const getUserMediaOptions: MediaStreamConstraints | DesktopCapturerConstraints = {
                     audio: false,
                     video: {
@@ -877,7 +879,7 @@ export class MatrixCall extends EventEmitter {
             this.peerConn.addTrack(audioTrack, stream);
         }
         for (const videoTrack of (this.screenSharingStream || stream).getVideoTracks()) {
-            logger.info("Adding audio track with id " + videoTrack.id);
+            logger.info("Adding video track with id " + videoTrack.id);
             this.peerConn.addTrack(videoTrack, stream);
         }
 
@@ -1684,6 +1686,7 @@ export class MatrixCall extends EventEmitter {
         const pc = new window.RTCPeerConnection({
             iceTransportPolicy: this.forceTURN ? 'relay' : undefined,
             iceServers: this.turnServers,
+            iceCandidatePoolSize: this.client._iceCandidatePoolSize,
         });
 
         // 'connectionstatechange' would be better, but firefox doesn't implement that.