mystiq/hydrogen-web
Archived
4
1
Fork 1
Code Issues Pull requests Projects Releases Packages Wiki Activity

Merge pull request #273 from vector-im/bwindels/keybackuplogging

Browse source 
Add logging to key backup operations
This commit is contained in:
Bruno Windels 2021-03-15 16:20:37 +00:00 committed by GitHub
commit ab732bcfbe
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 125 additions and 60 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

3
src/logging/LogItem.js
View file

@ -140,7 +140,8 @@ export class LogItem {
// (e)rror // (e)rror
item.e = { item.e = {
stack: this.error.stack, stack: this.error.stack,
name: this.error.name name: this.error.name,
message: this.error.message.split("\n")[0]
}; };
} }
if (forced) { if (forced) {

41
src/logging/NullLogger.js
View file

@ -15,16 +15,30 @@ limitations under the License.
*/ */
import {LogLevel} from "./LogFilter.js"; import {LogLevel} from "./LogFilter.js";
// TODO: add missing methods function noop () {}
export class NullLogger { export class NullLogger {
constructor() { constructor() {
this._item = new NullLogItem(); this.item = new NullLogItem();
} }
log() {} log() {}
run(_, callback) { run(_, callback) {
return callback(this._item); return callback(this.item);
}
wrapOrRun(item, _, callback) {
if (item) {
item.wrap(null, callback);
} else {
this.run(null, callback);
}
}
runDetached(_, callback) {
new Promise(r => r(callback(this.item))).then(noop, noop);
} }
async export() { async export() {
@ -42,12 +56,29 @@ class NullLogItem {
} }
log() {} log() {}
set() {} set() {}
anonymize() {}
runDetached(_, callback) {
new Promise(r => r(callback(this))).then(noop, noop);
}
wrapDetached(_, callback) {
return this.refDetached(null, callback);
}
run(callback) {
return callback(this);
}
refDetached() {}
get level() { get level() {
return LogLevel; return LogLevel;
} }
get duration() {
return 0;
}
catch(err) { catch(err) {
return err; return err;
} }
@ -58,3 +89,5 @@ class NullLogItem {
finish() {} finish() {}
} }
export const Instance = new NullLogger();

16
src/logging/utils.js Normal file
View file

@ -0,0 +1,16 @@
// these are helper functions if you can't assume you always have a log item (e.g. some code paths call with one set, others don't)
// if you know you always have a log item, better to use the methods on the log item than these utility functions.
import {Instance as NullLoggerInstance} from "./NullLogger.js";
export function wrapOrRunNullLogger(logItem, labelOrValues, callback, logLevel = null, filterCreator = null) {
if (logItem) {
return logItem.wrap(logItem, labelOrValues, callback, logLevel, filterCreator);
} else {
return NullLoggerInstance.run(null, callback);
}
}
export function ensureLogItem(logItem) {
return logItem || NullLoggerInstance.item;
}

1
src/matrix/SessionContainer.js
View file

@ -146,6 +146,7 @@ export class SessionContainer {
} }
async _loadSessionInfo(sessionInfo, isNewLogin, log) { async _loadSessionInfo(sessionInfo, isNewLogin, log) {
log.set("appVersion", this._platform.version);
const clock = this._platform.clock; const clock = this._platform.clock;
this._sessionStartedByReconnector = false; this._sessionStartedByReconnector = false;
this._status.set(LoadStatus.Loading); this._status.set(LoadStatus.Loading);

61
src/matrix/e2ee/RoomEncryption.js
View file

@ -56,7 +56,7 @@ export class RoomEncryption {
this._sessionBackup = sessionBackup; this._sessionBackup = sessionBackup;
} }
async restoreMissingSessionsFromBackup(entries) { async restoreMissingSessionsFromBackup(entries, log) {
const events = entries.filter(e => e.isEncrypted && !e.isDecrypted && e.event).map(e => e.event); const events = entries.filter(e => e.isEncrypted && !e.isDecrypted && e.event).map(e => e.event);
const eventsBySession = groupEventsBySession(events); const eventsBySession = groupEventsBySession(events);
const groups = Array.from(eventsBySession.values()); const groups = Array.from(eventsBySession.values());
@ -69,7 +69,7 @@ export class RoomEncryption {
// start with last sessions which should be for the last items in the timeline // start with last sessions which should be for the last items in the timeline
for (var i = missingSessions.length - 1; i >= 0; i--) { for (var i = missingSessions.length - 1; i >= 0; i--) {
const session = missingSessions[i]; const session = missingSessions[i];
await this._requestMissingSessionFromBackup(session.senderKey, session.sessionId); await log.wrap("session", log => this._requestMissingSessionFromBackup(session.senderKey, session.sessionId, log));
} }
} }
} }
@ -98,9 +98,6 @@ export class RoomEncryption {
return shouldFlush; return shouldFlush;
} }
// this happens before entries exists, as they are created by the syncwriter
// but we want to be able to map it back to something in the timeline easily
// when retrying decryption.
async prepareDecryptAll(events, newKeys, source, txn) { async prepareDecryptAll(events, newKeys, source, txn) {
const errors = new Map(); const errors = new Map();
const validEvents = []; const validEvents = [];
@ -137,7 +134,7 @@ export class RoomEncryption {
return new DecryptionPreparation(preparation, errors, source, this, events); return new DecryptionPreparation(preparation, errors, source, this, events);
} }
async _processDecryptionResults(events, results, errors, source, txn) { async _processDecryptionResults(events, results, errors, source, txn, log) {
const missingSessionEvents = events.filter(event => { const missingSessionEvents = events.filter(event => {
const error = errors.get(event.event_id); const error = errors.get(event.event_id);
return error?.code === "MEGOLM_NO_SESSION"; return error?.code === "MEGOLM_NO_SESSION";
@ -145,20 +142,26 @@ export class RoomEncryption {
if (!missingSessionEvents.length) { if (!missingSessionEvents.length) {
return; return;
} }
const eventsBySession = groupEventsBySession(events); // store missing event ids if received from sync
const missingEventsBySession = groupEventsBySession(missingSessionEvents);
if (source === DecryptionSource.Sync) { if (source === DecryptionSource.Sync) {
await Promise.all(Array.from(eventsBySession.values()).map(async group => { await Promise.all(Array.from(missingEventsBySession.values()).map(async group => {
const eventIds = group.events.map(e => e.event_id); const eventIds = group.events.map(e => e.event_id);
return this._megolmDecryption.addMissingKeyEventIds( return this._megolmDecryption.addMissingKeyEventIds(
this._room.id, group.senderKey, group.sessionId, eventIds, txn); this._room.id, group.senderKey, group.sessionId, eventIds, txn);
})); }));
} }
// TODO: do proper logging here if (!this._sessionBackup) {
// run detached return;
Promise.resolve().then(async () => { }
log.wrapDetached("check key backup", async log => {
// if the message came from sync, wait 10s to see if the room key arrives late, // if the message came from sync, wait 10s to see if the room key arrives late,
// and only after that proceed to request from backup // and only after that proceed to request from backup
log.set("source", source);
log.set("events", missingSessionEvents.length);
log.set("sessions", missingEventsBySession.size);
if (source === DecryptionSource.Sync) { if (source === DecryptionSource.Sync) {
await this._clock.createTimeout(10000).elapsed(); await this._clock.createTimeout(10000).elapsed();
if (this._disposed) { if (this._disposed) {
@ -166,18 +169,15 @@ export class RoomEncryption {
} }
// now check which sessions have been received already // now check which sessions have been received already
const txn = await this._storage.readTxn([this._storage.storeNames.inboundGroupSessions]); const txn = await this._storage.readTxn([this._storage.storeNames.inboundGroupSessions]);
await Promise.all(Array.from(eventsBySession).map(async ([key, group]) => { await Promise.all(Array.from(missingEventsBySession).map(async ([key, group]) => {
if (await this._megolmDecryption.hasSession(this._room.id, group.senderKey, group.sessionId, txn)) { if (await this._megolmDecryption.hasSession(this._room.id, group.senderKey, group.sessionId, txn)) {
eventsBySession.delete(key); missingEventsBySession.delete(key);
} }
})); }));
} }
await Promise.all(Array.from(eventsBySession.values()).map(group => { await Promise.all(Array.from(missingEventsBySession.values()).map(group => {
return this._requestMissingSessionFromBackup(group.senderKey, group.sessionId); return log.wrap("session", log => this._requestMissingSessionFromBackup(group.senderKey, group.sessionId, log));
})); }));
}).catch(err => {
console.log("failed to fetch missing session from key backup");
console.error(err);
}); });
} }
@ -194,18 +194,21 @@ export class RoomEncryption {
} }
} }
async _requestMissingSessionFromBackup(senderKey, sessionId) { async _requestMissingSessionFromBackup(senderKey, sessionId, log) {
// show prompt to enable secret storage // show prompt to enable secret storage
if (!this._sessionBackup) { if (!this._sessionBackup) {
log.set("enabled", false);
this._notifyMissingMegolmSession(); this._notifyMissingMegolmSession();
return; return;
} }
log.set("id", sessionId);
log.set("senderKey", senderKey);
try { try {
const session = await this._sessionBackup.getSession(this._room.id, sessionId); const session = await this._sessionBackup.getSession(this._room.id, sessionId, log);
if (session?.algorithm === MEGOLM_ALGORITHM) { if (session?.algorithm === MEGOLM_ALGORITHM) {
if (session["sender_key"] !== senderKey) { if (session["sender_key"] !== senderKey) {
console.warn("Got session key back from backup with different sender key, ignoring", {session, senderKey}); log.set("wrong_sender_key", session["sender_key"]);
log.logLevel = log.level.Warn;
return; return;
} }
let roomKey = this._megolmDecryption.roomKeyFromBackup(this._room.id, sessionId, session); let roomKey = this._megolmDecryption.roomKeyFromBackup(this._room.id, sessionId, session);
@ -216,6 +219,7 @@ export class RoomEncryption {
const txn = await this._storage.readWriteTxn([this._storage.storeNames.inboundGroupSessions]); const txn = await this._storage.readWriteTxn([this._storage.storeNames.inboundGroupSessions]);
try { try {
keyIsBestOne = await this._megolmDecryption.writeRoomKey(roomKey, txn); keyIsBestOne = await this._megolmDecryption.writeRoomKey(roomKey, txn);
log.set("isBetter", keyIsBestOne);
if (keyIsBestOne) { if (keyIsBestOne) {
retryEventIds = roomKey.eventIds; retryEventIds = roomKey.eventIds;
} }
@ -230,15 +234,18 @@ export class RoomEncryption {
roomKey.dispose(); roomKey.dispose();
} }
if (keyIsBestOne) { if (keyIsBestOne) {
await this._room.notifyRoomKey(roomKey, retryEventIds || []); await log.wrap("retryDecryption", log => this._room.notifyRoomKey(roomKey, retryEventIds || [], log));
} }
} }
} else if (session?.algorithm) { } else if (session?.algorithm) {
console.info(`Backed-up session of unknown algorithm: ${session.algorithm}`); log.set("unknown algorithm", session.algorithm);
} }
} catch (err) { } catch (err) {
if (!(err.name === "HomeServerError" && err.errcode === "M_NOT_FOUND")) { if (!(err.name === "HomeServerError" && err.errcode === "M_NOT_FOUND")) {
console.error(`Could not get session ${sessionId} from backup`, err); log.set("not_found", true);
} else {
log.error = err;
log.logLevel = log.level.Error;
} }
} }
} }
@ -485,10 +492,10 @@ class DecryptionChanges {
this._events = events; this._events = events;
} }
async write(txn) { async write(txn, log) {
const {results, errors} = await this._megolmDecryptionChanges.write(txn); const {results, errors} = await this._megolmDecryptionChanges.write(txn);
mergeMap(this._extraErrors, errors); mergeMap(this._extraErrors, errors);
await this._roomEncryption._processDecryptionResults(this._events, results, errors, this._source, txn); await this._roomEncryption._processDecryptionResults(this._events, results, errors, this._source, txn, log);
return new BatchDecryptionResult(results, errors, this._roomEncryption); return new BatchDecryptionResult(results, errors, this._roomEncryption);
} }
} }

4
src/matrix/e2ee/megolm/SessionBackup.js
View file

@ -21,8 +21,8 @@ export class SessionBackup {
this._hsApi = hsApi; this._hsApi = hsApi;
} }
async getSession(roomId, sessionId) { async getSession(roomId, sessionId, log) {
const sessionResponse = await this._hsApi.roomKeyForRoomAndSession(this._backupInfo.version, roomId, sessionId).response(); const sessionResponse = await this._hsApi.roomKeyForRoomAndSession(this._backupInfo.version, roomId, sessionId, {log}).response();
const sessionInfo = this._decryption.decrypt( const sessionInfo = this._decryption.decrypt(
sessionResponse.session_data.ephemeral, sessionResponse.session_data.ephemeral,
sessionResponse.session_data.mac, sessionResponse.session_data.mac,

27
src/matrix/room/Room.js
View file

@ -29,6 +29,7 @@ import {EventEntry} from "./timeline/entries/EventEntry.js";
import {ObservedEventMap} from "./ObservedEventMap.js"; import {ObservedEventMap} from "./ObservedEventMap.js";
import {AttachmentUpload} from "./AttachmentUpload.js"; import {AttachmentUpload} from "./AttachmentUpload.js";
import {DecryptionSource} from "../e2ee/common.js"; import {DecryptionSource} from "../e2ee/common.js";
import {ensureLogItem} from "../../logging/utils.js";
const EVENT_ENCRYPTED_TYPE = "m.room.encrypted"; const EVENT_ENCRYPTED_TYPE = "m.room.encrypted";
@ -81,7 +82,7 @@ export class Room extends EventEmitter {
* @param {Array<string>} eventIds any event ids that should be retried. There might be more in the timeline though for this key. * @param {Array<string>} eventIds any event ids that should be retried. There might be more in the timeline though for this key.
* @return {Promise} * @return {Promise}
*/ */
async notifyRoomKey(roomKey, eventIds) { async notifyRoomKey(roomKey, eventIds, log) {
if (!this._roomEncryption) { if (!this._roomEncryption) {
return; return;
} }
@ -95,7 +96,7 @@ export class Room extends EventEmitter {
retryEntries = retryEntries.concat(retryTimelineEntries); retryEntries = retryEntries.concat(retryTimelineEntries);
} }
if (retryEntries.length) { if (retryEntries.length) {
const decryptRequest = this._decryptEntries(DecryptionSource.Retry, retryEntries, txn); const decryptRequest = this._decryptEntries(DecryptionSource.Retry, retryEntries, txn, log);
// this will close txn while awaiting decryption // this will close txn while awaiting decryption
await decryptRequest.complete(); await decryptRequest.complete();
@ -125,8 +126,8 @@ export class Room extends EventEmitter {
* Used for decrypting when loading/filling the timeline, and retrying decryption, * Used for decrypting when loading/filling the timeline, and retrying decryption,
* not during sync, where it is split up during the multiple phases. * not during sync, where it is split up during the multiple phases.
*/ */
_decryptEntries(source, entries, inboundSessionTxn = null) { _decryptEntries(source, entries, inboundSessionTxn, log = null) {
const request = new DecryptionRequest(async r => { const request = new DecryptionRequest(async (r, log) => {
if (!inboundSessionTxn) { if (!inboundSessionTxn) {
inboundSessionTxn = await this._storage.readTxn([this._storage.storeNames.inboundGroupSessions]); inboundSessionTxn = await this._storage.readTxn([this._storage.storeNames.inboundGroupSessions]);
} }
@ -148,7 +149,7 @@ export class Room extends EventEmitter {
const writeTxn = await this._storage.readWriteTxn(stores); const writeTxn = await this._storage.readWriteTxn(stores);
let decryption; let decryption;
try { try {
decryption = await changes.write(writeTxn); decryption = await changes.write(writeTxn, log);
if (isTimelineOpen) { if (isTimelineOpen) {
await decryption.verifySenders(writeTxn); await decryption.verifySenders(writeTxn);
} }
@ -162,7 +163,7 @@ export class Room extends EventEmitter {
if (this._observedEvents) { if (this._observedEvents) {
this._observedEvents.updateEvents(entries); this._observedEvents.updateEvents(entries);
} }
}); }, ensureLogItem(log));
return request; return request;
} }
@ -248,7 +249,7 @@ export class Room extends EventEmitter {
await log.wrap("syncWriter", log => this._syncWriter.writeSync(roomResponse, txn, log), log.level.Detail); await log.wrap("syncWriter", log => this._syncWriter.writeSync(roomResponse, txn, log), log.level.Detail);
let allEntries = newEntries; let allEntries = newEntries;
if (decryptChanges) { if (decryptChanges) {
const decryption = await decryptChanges.write(txn); const decryption = await log.wrap("decryptChanges", log => decryptChanges.write(txn, log));
log.set("decryptionResults", decryption.results.size); log.set("decryptionResults", decryption.results.size);
log.set("decryptionErrors", decryption.errors.size); log.set("decryptionErrors", decryption.errors.size);
if (this._isTimelineOpen) { if (this._isTimelineOpen) {
@ -510,7 +511,7 @@ export class Room extends EventEmitter {
} }
await txn.complete(); await txn.complete();
if (this._roomEncryption) { if (this._roomEncryption) {
const decryptRequest = this._decryptEntries(DecryptionSource.Timeline, gapResult.entries); const decryptRequest = this._decryptEntries(DecryptionSource.Timeline, gapResult.entries, null, log);
await decryptRequest.complete(); await decryptRequest.complete();
} }
// once txn is committed, update in-memory state & emit events // once txn is committed, update in-memory state & emit events
@ -588,7 +589,9 @@ export class Room extends EventEmitter {
this._roomEncryption?.enableSessionBackup(sessionBackup); this._roomEncryption?.enableSessionBackup(sessionBackup);
// TODO: do we really want to do this every time you open the app? // TODO: do we really want to do this every time you open the app?
if (this._timeline) { if (this._timeline) {
this._roomEncryption.restoreMissingSessionsFromBackup(this._timeline.remoteEntries); this._platform.logger.run("enableSessionBackup", log => {
return this._roomEncryption.restoreMissingSessionsFromBackup(this._timeline.remoteEntries, log);
});
} }
} }
@ -675,7 +678,7 @@ export class Room extends EventEmitter {
if (this._roomEncryption) { if (this._roomEncryption) {
this._timeline.enableEncryption(this._decryptEntries.bind(this, DecryptionSource.Timeline)); this._timeline.enableEncryption(this._decryptEntries.bind(this, DecryptionSource.Timeline));
} }
await this._timeline.load(this._user); await this._timeline.load(this._user, log);
return this._timeline; return this._timeline;
}); });
} }
@ -745,10 +748,10 @@ export class Room extends EventEmitter {
} }
class DecryptionRequest { class DecryptionRequest {
constructor(decryptFn) { constructor(decryptFn, log) {
this._cancelled = false; this._cancelled = false;
this.preparation = null; this.preparation = null;
this._promise = decryptFn(this); this._promise = log.wrap("decryptEntries", log => decryptFn(this, log));
} }
complete() { complete() {

4
src/matrix/room/timeline/Timeline.js
View file

@ -45,7 +45,7 @@ export class Timeline {
} }
/** @package */ /** @package */
async load(user) { async load(user, log) {
const txn = await this._storage.readTxn(this._timelineReader.readTxnStores.concat(this._storage.storeNames.roomMembers)); const txn = await this._storage.readTxn(this._timelineReader.readTxnStores.concat(this._storage.storeNames.roomMembers));
const memberData = await txn.roomMembers.get(this._roomId, user.id); const memberData = await txn.roomMembers.get(this._roomId, user.id);
this._ownMember = new RoomMember(memberData); this._ownMember = new RoomMember(memberData);
@ -54,7 +54,7 @@ export class Timeline {
// if they are populated already, the sender profile would be empty // if they are populated already, the sender profile would be empty
// 30 seems to be a good amount to fill the entire screen // 30 seems to be a good amount to fill the entire screen
const readerRequest = this._disposables.track(this._timelineReader.readFromEnd(30, txn)); const readerRequest = this._disposables.track(this._timelineReader.readFromEnd(30, txn, log));
try { try {
const entries = await readerRequest.complete(); const entries = await readerRequest.complete();
this._remoteEntries.setManySorted(entries); this._remoteEntries.setManySorted(entries);

24
src/matrix/room/timeline/persistence/TimelineReader.js
View file

@ -20,9 +20,9 @@ import {EventEntry} from "../entries/EventEntry.js";
import {FragmentBoundaryEntry} from "../entries/FragmentBoundaryEntry.js"; import {FragmentBoundaryEntry} from "../entries/FragmentBoundaryEntry.js";
class ReaderRequest { class ReaderRequest {
constructor(fn) { constructor(fn, log) {
this.decryptRequest = null; this.decryptRequest = null;
this._promise = fn(this); this._promise = fn(this, log);
} }
complete() { complete() {
@ -106,15 +106,15 @@ export class TimelineReader {
return stores; return stores;
} }
readFrom(eventKey, direction, amount) { readFrom(eventKey, direction, amount, log) {
return new ReaderRequest(async r => { return new ReaderRequest(async (r, log) => {
const txn = await this._storage.readTxn(this.readTxnStores); const txn = await this._storage.readTxn(this.readTxnStores);
return await this._readFrom(eventKey, direction, amount, r, txn); return await this._readFrom(eventKey, direction, amount, r, txn, log);
}); }, log);
} }
readFromEnd(amount, existingTxn = null) { readFromEnd(amount, existingTxn = null, log) {
return new ReaderRequest(async r => { return new ReaderRequest(async (r, log) => {
const txn = existingTxn || await this._storage.readTxn(this.readTxnStores); const txn = existingTxn || await this._storage.readTxn(this.readTxnStores);
const liveFragment = await txn.timelineFragments.liveFragment(this._roomId); const liveFragment = await txn.timelineFragments.liveFragment(this._roomId);
let entries; let entries;
@ -125,17 +125,17 @@ export class TimelineReader {
this._fragmentIdComparer.add(liveFragment); this._fragmentIdComparer.add(liveFragment);
const liveFragmentEntry = FragmentBoundaryEntry.end(liveFragment, this._fragmentIdComparer); const liveFragmentEntry = FragmentBoundaryEntry.end(liveFragment, this._fragmentIdComparer);
const eventKey = liveFragmentEntry.asEventKey(); const eventKey = liveFragmentEntry.asEventKey();
entries = await this._readFrom(eventKey, Direction.Backward, amount, r, txn); entries = await this._readFrom(eventKey, Direction.Backward, amount, r, txn, log);
entries.unshift(liveFragmentEntry); entries.unshift(liveFragmentEntry);
} }
return entries; return entries;
}); }, log);
} }
async _readFrom(eventKey, direction, amount, r, txn) { async _readFrom(eventKey, direction, amount, r, txn, log) {
const entries = await readRawTimelineEntriesWithTxn(this._roomId, eventKey, direction, amount, this._fragmentIdComparer, txn); const entries = await readRawTimelineEntriesWithTxn(this._roomId, eventKey, direction, amount, this._fragmentIdComparer, txn);
if (this._decryptEntries) { if (this._decryptEntries) {
r.decryptRequest = this._decryptEntries(entries, txn); r.decryptRequest = this._decryptEntries(entries, txn, log);
try { try {
await r.decryptRequest.complete(); await r.decryptRequest.complete();
} finally { } finally {

4
src/platform/web/Platform.js
View file

@ -195,4 +195,8 @@ export class Platform {
get devicePixelRatio() { get devicePixelRatio() {
return window.devicePixelRatio || 1; return window.devicePixelRatio || 1;
} }
get version() {
return window.HYDROGEN_VERSION;
}
} }