diff --git a/src/logging/LogItem.js b/src/logging/LogItem.js index 28f02d8e..fcb88eff 100644 --- a/src/logging/LogItem.js +++ b/src/logging/LogItem.js @@ -140,7 +140,8 @@ export class LogItem { // (e)rror item.e = { stack: this.error.stack, - name: this.error.name + name: this.error.name, + message: this.error.message.split("\n")[0] }; } if (forced) { diff --git a/src/logging/NullLogger.js b/src/logging/NullLogger.js index 0842e4c0..1860e697 100644 --- a/src/logging/NullLogger.js +++ b/src/logging/NullLogger.js @@ -15,16 +15,30 @@ limitations under the License. */ import {LogLevel} from "./LogFilter.js"; -// TODO: add missing methods +function noop () {} + + export class NullLogger { constructor() { - this._item = new NullLogItem(); + this.item = new NullLogItem(); } log() {} 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() { @@ -42,12 +56,29 @@ class NullLogItem { } log() {} 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() { return LogLevel; } + get duration() { + return 0; + } + catch(err) { return err; } @@ -58,3 +89,5 @@ class NullLogItem { finish() {} } + +export const Instance = new NullLogger(); diff --git a/src/logging/utils.js b/src/logging/utils.js new file mode 100644 index 00000000..3da9aa5d --- /dev/null +++ b/src/logging/utils.js @@ -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; +} diff --git a/src/matrix/SessionContainer.js b/src/matrix/SessionContainer.js index 76212aca..efbf70e3 100644 --- a/src/matrix/SessionContainer.js +++ b/src/matrix/SessionContainer.js @@ -146,6 +146,7 @@ export class SessionContainer { } async _loadSessionInfo(sessionInfo, isNewLogin, log) { + log.set("appVersion", this._platform.version); const clock = this._platform.clock; this._sessionStartedByReconnector = false; this._status.set(LoadStatus.Loading); diff --git a/src/matrix/e2ee/RoomEncryption.js b/src/matrix/e2ee/RoomEncryption.js index 1f6365a4..ddb6e4c4 100644 --- a/src/matrix/e2ee/RoomEncryption.js +++ b/src/matrix/e2ee/RoomEncryption.js @@ -56,7 +56,7 @@ export class RoomEncryption { 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 eventsBySession = groupEventsBySession(events); 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 for (var i = missingSessions.length - 1; i >= 0; 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; } - // 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) { const errors = new Map(); const validEvents = []; @@ -137,7 +134,7 @@ export class RoomEncryption { 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 error = errors.get(event.event_id); return error?.code === "MEGOLM_NO_SESSION"; @@ -145,20 +142,26 @@ export class RoomEncryption { if (!missingSessionEvents.length) { return; } - const eventsBySession = groupEventsBySession(events); + // store missing event ids if received from sync + const missingEventsBySession = groupEventsBySession(missingSessionEvents); 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); return this._megolmDecryption.addMissingKeyEventIds( this._room.id, group.senderKey, group.sessionId, eventIds, txn); })); } + + if (!this._sessionBackup) { + return; + } - // TODO: do proper logging here - // run detached - 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, // 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) { await this._clock.createTimeout(10000).elapsed(); if (this._disposed) { @@ -166,18 +169,15 @@ export class RoomEncryption { } // now check which sessions have been received already 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)) { - eventsBySession.delete(key); + missingEventsBySession.delete(key); } })); } - await Promise.all(Array.from(eventsBySession.values()).map(group => { - return this._requestMissingSessionFromBackup(group.senderKey, group.sessionId); + await Promise.all(Array.from(missingEventsBySession.values()).map(group => { + 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 if (!this._sessionBackup) { + log.set("enabled", false); this._notifyMissingMegolmSession(); return; } - + log.set("id", sessionId); + log.set("senderKey", senderKey); 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["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; } 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]); try { keyIsBestOne = await this._megolmDecryption.writeRoomKey(roomKey, txn); + log.set("isBetter", keyIsBestOne); if (keyIsBestOne) { retryEventIds = roomKey.eventIds; } @@ -230,15 +234,18 @@ export class RoomEncryption { roomKey.dispose(); } if (keyIsBestOne) { - await this._room.notifyRoomKey(roomKey, retryEventIds || []); + await log.wrap("retryDecryption", log => this._room.notifyRoomKey(roomKey, retryEventIds || [], log)); } } } else if (session?.algorithm) { - console.info(`Backed-up session of unknown algorithm: ${session.algorithm}`); + log.set("unknown algorithm", session.algorithm); } } catch (err) { 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; } - async write(txn) { + async write(txn, log) { const {results, errors} = await this._megolmDecryptionChanges.write(txn); 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); } } diff --git a/src/matrix/e2ee/megolm/SessionBackup.js b/src/matrix/e2ee/megolm/SessionBackup.js index e4c3788c..daba9961 100644 --- a/src/matrix/e2ee/megolm/SessionBackup.js +++ b/src/matrix/e2ee/megolm/SessionBackup.js @@ -21,8 +21,8 @@ export class SessionBackup { this._hsApi = hsApi; } - async getSession(roomId, sessionId) { - const sessionResponse = await this._hsApi.roomKeyForRoomAndSession(this._backupInfo.version, roomId, sessionId).response(); + async getSession(roomId, sessionId, log) { + const sessionResponse = await this._hsApi.roomKeyForRoomAndSession(this._backupInfo.version, roomId, sessionId, {log}).response(); const sessionInfo = this._decryption.decrypt( sessionResponse.session_data.ephemeral, sessionResponse.session_data.mac, diff --git a/src/matrix/room/Room.js b/src/matrix/room/Room.js index d3d04c93..7326e32f 100644 --- a/src/matrix/room/Room.js +++ b/src/matrix/room/Room.js @@ -29,6 +29,7 @@ import {EventEntry} from "./timeline/entries/EventEntry.js"; import {ObservedEventMap} from "./ObservedEventMap.js"; import {AttachmentUpload} from "./AttachmentUpload.js"; import {DecryptionSource} from "../e2ee/common.js"; +import {ensureLogItem} from "../../logging/utils.js"; const EVENT_ENCRYPTED_TYPE = "m.room.encrypted"; @@ -81,7 +82,7 @@ export class Room extends EventEmitter { * @param {Array} eventIds any event ids that should be retried. There might be more in the timeline though for this key. * @return {Promise} */ - async notifyRoomKey(roomKey, eventIds) { + async notifyRoomKey(roomKey, eventIds, log) { if (!this._roomEncryption) { return; } @@ -95,7 +96,7 @@ export class Room extends EventEmitter { retryEntries = retryEntries.concat(retryTimelineEntries); } 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 await decryptRequest.complete(); @@ -125,8 +126,8 @@ export class Room extends EventEmitter { * Used for decrypting when loading/filling the timeline, and retrying decryption, * not during sync, where it is split up during the multiple phases. */ - _decryptEntries(source, entries, inboundSessionTxn = null) { - const request = new DecryptionRequest(async r => { + _decryptEntries(source, entries, inboundSessionTxn, log = null) { + const request = new DecryptionRequest(async (r, log) => { if (!inboundSessionTxn) { 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); let decryption; try { - decryption = await changes.write(writeTxn); + decryption = await changes.write(writeTxn, log); if (isTimelineOpen) { await decryption.verifySenders(writeTxn); } @@ -162,7 +163,7 @@ export class Room extends EventEmitter { if (this._observedEvents) { this._observedEvents.updateEvents(entries); } - }); + }, ensureLogItem(log)); 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); let allEntries = newEntries; 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("decryptionErrors", decryption.errors.size); if (this._isTimelineOpen) { @@ -510,7 +511,7 @@ export class Room extends EventEmitter { } await txn.complete(); if (this._roomEncryption) { - const decryptRequest = this._decryptEntries(DecryptionSource.Timeline, gapResult.entries); + const decryptRequest = this._decryptEntries(DecryptionSource.Timeline, gapResult.entries, null, log); await decryptRequest.complete(); } // once txn is committed, update in-memory state & emit events @@ -588,7 +589,9 @@ export class Room extends EventEmitter { this._roomEncryption?.enableSessionBackup(sessionBackup); // TODO: do we really want to do this every time you open the app? 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) { 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; }); } @@ -745,10 +748,10 @@ export class Room extends EventEmitter { } class DecryptionRequest { - constructor(decryptFn) { + constructor(decryptFn, log) { this._cancelled = false; this.preparation = null; - this._promise = decryptFn(this); + this._promise = log.wrap("decryptEntries", log => decryptFn(this, log)); } complete() { diff --git a/src/matrix/room/timeline/Timeline.js b/src/matrix/room/timeline/Timeline.js index 9abd5b88..2cccdf83 100644 --- a/src/matrix/room/timeline/Timeline.js +++ b/src/matrix/room/timeline/Timeline.js @@ -45,7 +45,7 @@ export class Timeline { } /** @package */ - async load(user) { + async load(user, log) { const txn = await this._storage.readTxn(this._timelineReader.readTxnStores.concat(this._storage.storeNames.roomMembers)); const memberData = await txn.roomMembers.get(this._roomId, user.id); this._ownMember = new RoomMember(memberData); @@ -54,7 +54,7 @@ export class Timeline { // if they are populated already, the sender profile would be empty // 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 { const entries = await readerRequest.complete(); this._remoteEntries.setManySorted(entries); diff --git a/src/matrix/room/timeline/persistence/TimelineReader.js b/src/matrix/room/timeline/persistence/TimelineReader.js index dc759cc5..27b88ea9 100644 --- a/src/matrix/room/timeline/persistence/TimelineReader.js +++ b/src/matrix/room/timeline/persistence/TimelineReader.js @@ -20,9 +20,9 @@ import {EventEntry} from "../entries/EventEntry.js"; import {FragmentBoundaryEntry} from "../entries/FragmentBoundaryEntry.js"; class ReaderRequest { - constructor(fn) { + constructor(fn, log) { this.decryptRequest = null; - this._promise = fn(this); + this._promise = fn(this, log); } complete() { @@ -106,15 +106,15 @@ export class TimelineReader { return stores; } - readFrom(eventKey, direction, amount) { - return new ReaderRequest(async r => { + readFrom(eventKey, direction, amount, log) { + return new ReaderRequest(async (r, log) => { 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) { - return new ReaderRequest(async r => { + readFromEnd(amount, existingTxn = null, log) { + return new ReaderRequest(async (r, log) => { const txn = existingTxn || await this._storage.readTxn(this.readTxnStores); const liveFragment = await txn.timelineFragments.liveFragment(this._roomId); let entries; @@ -125,17 +125,17 @@ export class TimelineReader { this._fragmentIdComparer.add(liveFragment); const liveFragmentEntry = FragmentBoundaryEntry.end(liveFragment, this._fragmentIdComparer); 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); } 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); if (this._decryptEntries) { - r.decryptRequest = this._decryptEntries(entries, txn); + r.decryptRequest = this._decryptEntries(entries, txn, log); try { await r.decryptRequest.complete(); } finally { diff --git a/src/platform/web/Platform.js b/src/platform/web/Platform.js index e4ad3a88..a1e8e52c 100644 --- a/src/platform/web/Platform.js +++ b/src/platform/web/Platform.js @@ -195,4 +195,8 @@ export class Platform { get devicePixelRatio() { return window.devicePixelRatio || 1; } + + get version() { + return window.HYDROGEN_VERSION; + } }