matrix/matrix-js-sdk
1
0
Fork 0
mirror of https://github.com/matrix-org/matrix-js-sdk.git synced 2025-11-26 17:03:12 +03:00
Code Activity

Merge pull request #1090 from matrix-org/matthew/more_e2ee_logging

Browse Source 
expand e2ee logging to better debug UISIs
This commit is contained in:
Matthew Hodgson
2019-11-26 10:18:28 +00:00
committed by GitHub
parent 32234ee7fc 3787b6f1c7
commit fcbfaac1fd
6 changed files with 38 additions and 30 deletions
Download Patch File Download Diff File Expand all files Collapse all files

6
src/client.js
View File

@@ -73,7 +73,7 @@ function keysFromRecoverySession(sessions, decryptionKey, roomId) {
decrypted.room_id = roomId; decrypted.room_id = roomId;
keys.push(decrypted); keys.push(decrypted);
} catch (e) { } catch (e) {
logger.log("Failed to decrypt session from backup"); logger.log("Failed to decrypt megolm session from backup", e);
} }
} }
return keys; return keys;
@@ -1626,7 +1626,7 @@ MatrixClient.prototype._restoreKeyBackup = function(
key.session_id = targetSessionId; key.session_id = targetSessionId;
keys.push(key); keys.push(key);
} catch (e) { } catch (e) {
logger.log("Failed to decrypt session from backup"); logger.log("Failed to decrypt megolm session from backup", e);
} }
} }
@@ -4708,7 +4708,7 @@ function setupCallEventHandler(client) {
const content = event.getContent(); const content = event.getContent();
let call = content.call_id ? client.callList[content.call_id] : undefined; let call = content.call_id ? client.callList[content.call_id] : undefined;
let i; let i;
//console.log("RECV %s content=%s", event.getType(), JSON.stringify(content)); //console.info("RECV %s content=%s", event.getType(), JSON.stringify(content));
if (event.getType() === "m.call.invite") { if (event.getType() === "m.call.invite") {
if (event.getSender() === client.credentials.userId) { if (event.getSender() === client.credentials.userId) {

18
src/crypto/OlmDevice.js
View File

@@ -462,7 +462,7 @@ OlmDevice.prototype.createInboundSession = async function(
*/ */
OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityKey) { OlmDevice.prototype.getSessionIdsForDevice = async function(theirDeviceIdentityKey) {
if (this._sessionsInProgress[theirDeviceIdentityKey]) { if (this._sessionsInProgress[theirDeviceIdentityKey]) {
logger.log("waiting for session to be created"); logger.log("waiting for olm session to be created");
try { try {
await this._sessionsInProgress[theirDeviceIdentityKey]; await this._sessionsInProgress[theirDeviceIdentityKey];
} catch (e) { } catch (e) {
@@ -543,7 +543,7 @@ OlmDevice.prototype.getSessionIdForDevice = async function(
*/ */
OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey, nowait) { OlmDevice.prototype.getSessionInfoForDevice = async function(deviceIdentityKey, nowait) {
if (this._sessionsInProgress[deviceIdentityKey] && !nowait) { if (this._sessionsInProgress[deviceIdentityKey] && !nowait) {
logger.log("waiting for session to be created"); logger.log("waiting for olm session to be created");
try { try {
await this._sessionsInProgress[deviceIdentityKey]; await this._sessionsInProgress[deviceIdentityKey];
} catch (e) { } catch (e) {
@@ -595,8 +595,8 @@ OlmDevice.prototype.encryptMessage = async function(
(txn) => { (txn) => {
this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => { this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => {
const sessionDesc = sessionInfo.session.describe(); const sessionDesc = sessionInfo.session.describe();
console.log( logger.log(
"Session ID " + sessionId + " to " + "encryptMessage: Olm Session ID " + sessionId + " to " +
theirDeviceIdentityKey + ": " + sessionDesc, theirDeviceIdentityKey + ": " + sessionDesc,
); );
res = sessionInfo.session.encrypt(payloadString); res = sessionInfo.session.encrypt(payloadString);
@@ -627,8 +627,8 @@ OlmDevice.prototype.decryptMessage = async function(
(txn) => { (txn) => {
this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => { this._getSession(theirDeviceIdentityKey, sessionId, txn, (sessionInfo) => {
const sessionDesc = sessionInfo.session.describe(); const sessionDesc = sessionInfo.session.describe();
console.log( logger.log(
"Session ID " + sessionId + " to " + "decryptMessage: Olm Session ID " + sessionId + " from " +
theirDeviceIdentityKey + ": " + sessionDesc, theirDeviceIdentityKey + ": " + sessionDesc,
); );
payloadString = sessionInfo.session.decrypt(messageType, ciphertext); payloadString = sessionInfo.session.decrypt(messageType, ciphertext);
@@ -740,6 +740,8 @@ OlmDevice.prototype.createOutboundGroupSession = function() {
OlmDevice.prototype.encryptGroupMessage = function(sessionId, payloadString) { OlmDevice.prototype.encryptGroupMessage = function(sessionId, payloadString) {
const self = this; const self = this;
logger.log(`encrypting msg with megolm session ${sessionId}`);
checkPayloadLength(payloadString); checkPayloadLength(payloadString);
return this._getOutboundGroupSession(sessionId, function(session) { return this._getOutboundGroupSession(sessionId, function(session) {
@@ -886,7 +888,9 @@ OlmDevice.prototype.addInboundGroupSession = async function(
<= session.first_known_index()) { <= session.first_known_index()) {
// existing session has lower index (i.e. can // existing session has lower index (i.e. can
// decrypt more), so keep it // decrypt more), so keep it
logger.log("Keeping existing session"); logger.log(
`Keeping existing megolm session ${sessionId}`,
);
return; return;
} }
} }

33
src/crypto/algorithms/megolm.js
View File

@@ -104,7 +104,7 @@ OutboundSessionInfo.prototype.sharedWithTooManyDevices = function(
} }
if (!devicesInRoom.hasOwnProperty(userId)) { if (!devicesInRoom.hasOwnProperty(userId)) {
logger.log("Starting new session because we shared with " + userId); logger.log("Starting new megolm session because we shared with " + userId);
return true; return true;
} }
@@ -115,7 +115,7 @@ OutboundSessionInfo.prototype.sharedWithTooManyDevices = function(
if (!devicesInRoom[userId].hasOwnProperty(deviceId)) { if (!devicesInRoom[userId].hasOwnProperty(deviceId)) {
logger.log( logger.log(
"Starting new session because we shared with " + "Starting new megolm session because we shared with " +
userId + ":" + deviceId, userId + ":" + deviceId,
); );
return true; return true;
@@ -200,6 +200,8 @@ MegolmEncryption.prototype._ensureOutboundSession = function(devicesInRoom) {
if (!session) { if (!session) {
logger.log(`Starting new megolm session for room ${self._roomId}`); logger.log(`Starting new megolm session for room ${self._roomId}`);
session = await self._prepareNewSession(); session = await self._prepareNewSession();
logger.log(`Started new megolm session ${session.sessionId} ` +
`for room ${self._roomId}`);
self._outboundSessions[session.sessionId] = session; self._outboundSessions[session.sessionId] = session;
} }
@@ -278,7 +280,7 @@ MegolmEncryption.prototype._prepareNewSession = async function() {
).catch((e) => { ).catch((e) => {
// This throws if the upload failed, but this is fine // This throws if the upload failed, but this is fine
// since it will have written it to the db and will retry. // since it will have written it to the db and will retry.
logger.log("Failed to back up group session", e); logger.log("Failed to back up megolm session", e);
}); });
} }
@@ -440,19 +442,19 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
) { ) {
const obSessionInfo = this._outboundSessions[sessionId]; const obSessionInfo = this._outboundSessions[sessionId];
if (!obSessionInfo) { if (!obSessionInfo) {
logger.debug("Session ID " + sessionId + " not found: not re-sharing keys"); logger.debug(`megolm session ${sessionId} not found: not re-sharing keys`);
return; return;
} }
// The chain index of the key we previously sent this device // The chain index of the key we previously sent this device
if (obSessionInfo.sharedWithDevices[userId] === undefined) { if (obSessionInfo.sharedWithDevices[userId] === undefined) {
logger.debug("Session ID " + sessionId + " never shared with user " + userId); logger.debug(`megolm session ${sessionId} never shared with user ${userId}`);
return; return;
} }
const sentChainIndex = obSessionInfo.sharedWithDevices[userId][device.deviceId]; const sentChainIndex = obSessionInfo.sharedWithDevices[userId][device.deviceId];
if (sentChainIndex === undefined) { if (sentChainIndex === undefined) {
logger.debug( logger.debug(
"Session ID " + sessionId + " never shared with device " + "megolm session ID " + sessionId + " never shared with device " +
userId + ":" + device.deviceId, userId + ":" + device.deviceId,
); );
return; return;
@@ -466,7 +468,7 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
if (!key) { if (!key) {
logger.warn( logger.warn(
"No outbound session key found for " + sessionId + ": not re-sharing keys", `No inbound session key found for megolm ${sessionId}: not re-sharing keys`,
); );
return; return;
} }
@@ -513,9 +515,8 @@ MegolmEncryption.prototype.reshareKeyWithDevice = async function(
[device.deviceId]: encryptedContent, [device.deviceId]: encryptedContent,
}, },
}); });
logger.debug( logger.debug(`Re-shared key for megolm session ${sessionId} ` +
`Re-shared key for session ${sessionId} with ${userId}:${device.deviceId}`, `with ${userId}:${device.deviceId}`);
);
}; };
/** /**
@@ -550,10 +551,10 @@ MegolmEncryption.prototype._shareKeyWithDevices = async function(session, device
await this._encryptAndSendKeysToDevices( await this._encryptAndSendKeysToDevices(
session, key.chain_index, userDeviceMaps[i], payload, session, key.chain_index, userDeviceMaps[i], payload,
); );
logger.log(`Completed megolm keyshare in ${this._roomId} ` logger.log(`Completed megolm keyshare for ${session.sessionId} `
+ `(slice ${i + 1}/${userDeviceMaps.length})`); + `in ${this._roomId} (slice ${i + 1}/${userDeviceMaps.length})`);
} catch (e) { } catch (e) {
logger.log(`megolm keyshare in ${this._roomId} ` logger.log(`megolm keyshare for ${session.sessionId} in ${this._roomId} `
+ `(slice ${i + 1}/${userDeviceMaps.length}) failed`); + `(slice ${i + 1}/${userDeviceMaps.length}) failed`);
throw e; throw e;
@@ -922,7 +923,7 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) {
keysClaimed = event.getKeysClaimed(); keysClaimed = event.getKeysClaimed();
} }
logger.log(`Adding key for megolm session ${senderKey}|${sessionId}`); logger.log(`Received and adding key for megolm session ${senderKey}|${sessionId}`);
return this._olmDevice.addInboundGroupSession( return this._olmDevice.addInboundGroupSession(
content.room_id, senderKey, forwardingKeyChain, sessionId, content.room_id, senderKey, forwardingKeyChain, sessionId,
content.session_key, keysClaimed, content.session_key, keysClaimed,
@@ -955,7 +956,7 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) {
).catch((e) => { ).catch((e) => {
// This throws if the upload failed, but this is fine // This throws if the upload failed, but this is fine
// since it will have written it to the db and will retry. // since it will have written it to the db and will retry.
logger.log("Failed to back up group session", e); logger.log("Failed to back up megolm session", e);
}); });
} }
}).catch((e) => { }).catch((e) => {
@@ -1088,7 +1089,7 @@ MegolmDecryption.prototype.importRoomKey = function(session) {
).catch((e) => { ).catch((e) => {
// This throws if the upload failed, but this is fine // This throws if the upload failed, but this is fine
// since it will have written it to the db and will retry. // since it will have written it to the db and will retry.
logger.log("Failed to back up group session", e); logger.log("Failed to back up megolm session", e);
}); });
} }
// have another go at decrypting events sent with this session. // have another go at decrypting events sent with this session.

5
src/crypto/index.js
View File

@@ -1638,7 +1638,7 @@ Crypto.prototype.setRoomEncryption = async function(roomId, config, inhibitDevic
// It would otherwise just throw later as an unknown algorithm would, but we may // It would otherwise just throw later as an unknown algorithm would, but we may
// as well catch this here // as well catch this here
if (!config.algorithm) { if (!config.algorithm) {
console.log("Ignoring setRoomEncryption with no algorithm"); logger.log("Ignoring setRoomEncryption with no algorithm");
return; return;
} }
@@ -2294,6 +2294,9 @@ Crypto.prototype._getTrackedE2eRooms = function() {
Crypto.prototype._onToDeviceEvent = function(event) { Crypto.prototype._onToDeviceEvent = function(event) {
try { try {
logger.log(`received to_device ${event.getType()} from: ` +
`${event.getSender()} id: ${event.getId()}`);
if (event.getType() == "m.room_key" if (event.getType() == "m.room_key"
|| event.getType() == "m.forwarded_room_key") { || event.getType() == "m.forwarded_room_key") {
this._onRoomKeyEvent(event); this._onRoomKeyEvent(event);

4
src/crypto/olmlib.js
View File

@@ -287,12 +287,12 @@ async function _verifyKeyAndStartSession(olmDevice, oneTimeKey, userId, deviceIn
); );
} catch (e) { } catch (e) {
// possibly a bad key // possibly a bad key
logger.error("Error starting session with device " + logger.error("Error starting olm session with device " +
userId + ":" + deviceId + ": " + e); userId + ":" + deviceId + ": " + e);
return null; return null;
} }
logger.log("Started new sessionid " + sid + logger.log("Started new olm sessionid " + sid +
" for device " + userId + ":" + deviceId); " for device " + userId + ":" + deviceId);
return sid; return sid;
} }

2
src/crypto/store/indexeddb-crypto-store.js
View File

@@ -407,7 +407,7 @@ export default class IndexedDBCryptoStore {
}); });
} }
// Inbound group saessions // Inbound group sessions
/** /**
* Retrieve the end-to-end inbound group session for a given * Retrieve the end-to-end inbound group session for a given