From 57bb75e8649665b39c80ed9fa2d5b6b564f34b31 Mon Sep 17 00:00:00 2001 From: Bruno Windels Date: Tue, 23 Feb 2021 19:22:25 +0100 Subject: [PATCH] log login & loading a session --- src/matrix/Session.js | 19 +-- src/matrix/SessionContainer.js | 134 ++++++++++-------- src/matrix/e2ee/Account.js | 19 ++- src/matrix/room/Room.js | 30 ++-- .../room/timeline/persistence/SyncWriter.js | 6 +- 5 files changed, 116 insertions(+), 92 deletions(-) diff --git a/src/matrix/Session.js b/src/matrix/Session.js index 23f2c03a..005f58d1 100644 --- a/src/matrix/Session.js +++ b/src/matrix/Session.js @@ -96,7 +96,6 @@ export class Session { // called once this._e2eeAccount is assigned _setupEncryption() { - console.log("loaded e2ee account with keys", this._e2eeAccount.identityKeys); // TODO: this should all go in a wrapper in e2ee/ that is bootstrapped by passing in the account // and can create RoomEncryption objects and handle encrypted to_device messages and device list changes. const senderKeyLock = new LockMap(); @@ -228,7 +227,7 @@ export class Session { } /** @internal */ - async createIdentity() { + async createIdentity(log) { if (this._olm) { if (!this._e2eeAccount) { this._e2eeAccount = await E2EEAccount.create({ @@ -240,15 +239,16 @@ export class Session { olmWorker: this._olmWorker, storage: this._storage, }); + log.set("keys", this._e2eeAccount.identityKeys); this._setupEncryption(); } - await this._e2eeAccount.generateOTKsIfNeeded(this._storage); - await this._e2eeAccount.uploadKeys(this._storage); + await this._e2eeAccount.generateOTKsIfNeeded(this._storage, log); + await log.wrap("uploadKeys", log => this._e2eeAccount.uploadKeys(this._storage, log)); } } /** @internal */ - async load() { + async load(log) { const txn = this._storage.readTxn([ this._storage.storeNames.session, this._storage.storeNames.roomSummary, @@ -271,6 +271,7 @@ export class Session { txn }); if (this._e2eeAccount) { + log.set("keys", this._e2eeAccount.identityKeys); this._setupEncryption(); } } @@ -279,7 +280,7 @@ export class Session { const rooms = await txn.roomSummary.getAll(); await Promise.all(rooms.map(summary => { const room = this.createRoom(summary.roomId, pendingEventsByRoomId.get(summary.roomId)); - return room.load(summary, txn); + return log.wrap("room", log => room.load(summary, txn, log)); })); } @@ -297,7 +298,7 @@ export class Session { * and useful to store so we can later tell what capabilities * our homeserver has. */ - async start(lastVersionResponse) { + async start(lastVersionResponse, log) { if (lastVersionResponse) { // store /versions response const txn = this._storage.readWriteTxn([ @@ -334,7 +335,7 @@ export class Session { if (roomOperations) { roomOperationsByType = groupBy(roomOperations, r => r.type); } - room.start(roomOperationsByType); + room.start(roomOperationsByType, log); } } @@ -438,7 +439,7 @@ export class Session { // are about to receive messages for // (https://github.com/vector-im/riot-web/issues/2782). if (!isCatchupSync) { - const needsToUploadOTKs = await this._e2eeAccount.generateOTKsIfNeeded(this._storage); + const needsToUploadOTKs = await this._e2eeAccount.generateOTKsIfNeeded(this._storage, log); if (needsToUploadOTKs) { promises.push(log.wrap("uploadKeys", log => this._e2eeAccount.uploadKeys(this._storage, log))); } diff --git a/src/matrix/SessionContainer.js b/src/matrix/SessionContainer.js index ebb9e07e..a3cdf0a0 100644 --- a/src/matrix/SessionContainer.js +++ b/src/matrix/SessionContainer.js @@ -73,68 +73,79 @@ export class SessionContainer { return; } this._status.set(LoadStatus.Loading); - try { - const sessionInfo = await this._platform.sessionInfoStorage.get(sessionId); - if (!sessionInfo) { - throw new Error("Invalid session id: " + sessionId); + this._platform.logger.run("load session", async log => { + log.set("id", sessionId); + try { + const sessionInfo = await this._platform.sessionInfoStorage.get(sessionId); + if (!sessionInfo) { + throw new Error("Invalid session id: " + sessionId); + } + await this._loadSessionInfo(sessionInfo, false, log); + log.set("status", this._status.get()); + } catch (err) { + log.catch(err); + this._error = err; + this._status.set(LoadStatus.Error); } - await this._loadSessionInfo(sessionInfo, false); - } catch (err) { - this._error = err; - this._status.set(LoadStatus.Error); - } + }); } async startWithLogin(homeServer, username, password) { if (this._status.get() !== LoadStatus.NotLoading) { return; } - this._status.set(LoadStatus.Login); - const clock = this._platform.clock; - let sessionInfo; - try { - const request = this._platform.request; - const hsApi = new HomeServerApi({homeServer, request, createTimeout: clock.createTimeout}); - const loginData = await hsApi.passwordLogin(username, password, "Hydrogen").response(); - const sessionId = this.createNewSessionId(); - sessionInfo = { - id: sessionId, - deviceId: loginData.device_id, - userId: loginData.user_id, - homeServer: homeServer, - accessToken: loginData.access_token, - lastUsed: clock.now() - }; - await this._platform.sessionInfoStorage.add(sessionInfo); - } catch (err) { - this._error = err; - if (err instanceof HomeServerError) { - if (err.errcode === "M_FORBIDDEN") { - this._loginFailure = LoginFailure.Credentials; + this._platform.logger.run("login", async log => { + this._status.set(LoadStatus.Login); + const clock = this._platform.clock; + let sessionInfo; + try { + const request = this._platform.request; + const hsApi = new HomeServerApi({homeServer, request, createTimeout: clock.createTimeout}); + const loginData = await hsApi.passwordLogin(username, password, "Hydrogen", {log}).response(); + const sessionId = this.createNewSessionId(); + sessionInfo = { + id: sessionId, + deviceId: loginData.device_id, + userId: loginData.user_id, + homeServer: homeServer, + accessToken: loginData.access_token, + lastUsed: clock.now() + }; + log.set("id", sessionId); + await this._platform.sessionInfoStorage.add(sessionInfo); + } catch (err) { + this._error = err; + if (err instanceof HomeServerError) { + if (err.errcode === "M_FORBIDDEN") { + this._loginFailure = LoginFailure.Credentials; + } else { + this._loginFailure = LoginFailure.Unknown; + } + log.set("loginFailure", this._loginFailure); + this._status.set(LoadStatus.LoginFailed); + } else if (err instanceof ConnectionError) { + this._loginFailure = LoginFailure.Connection; + this._status.set(LoadStatus.LoginFailed); } else { - this._loginFailure = LoginFailure.Unknown; + this._status.set(LoadStatus.Error); } - this._status.set(LoadStatus.LoginFailed); - } else if (err instanceof ConnectionError) { - this._loginFailure = LoginFailure.Connection; - this._status.set(LoadStatus.LoginFailed); - } else { + return; + } + // loading the session can only lead to + // LoadStatus.Error in case of an error, + // so separate try/catch + try { + await this._loadSessionInfo(sessionInfo, true, log); + log.set("status", this._status.get()); + } catch (err) { + log.catch(err); + this._error = err; this._status.set(LoadStatus.Error); } - return; - } - // loading the session can only lead to - // LoadStatus.Error in case of an error, - // so separate try/catch - try { - await this._loadSessionInfo(sessionInfo, true); - } catch (err) { - this._error = err; - this._status.set(LoadStatus.Error); - } + }); } - async _loadSessionInfo(sessionInfo, isNewLogin) { + async _loadSessionInfo(sessionInfo, isNewLogin, log) { const clock = this._platform.clock; this._sessionStartedByReconnector = false; this._status.set(LoadStatus.Loading); @@ -178,24 +189,26 @@ export class SessionContainer { mediaRepository, platform: this._platform, }); - await this._session.load(); + await this._session.load(log); if (isNewLogin) { this._status.set(LoadStatus.SessionSetup); - await this._session.createIdentity(); + await log.wrap("createIdentity", log => this._session.createIdentity(log)); } this._sync = new Sync({hsApi: this._requestScheduler.hsApi, storage: this._storage, session: this._session, logger: this._platform.logger}); // notify sync and session when back online this._reconnectSubscription = this._reconnector.connectionStatus.subscribe(state => { if (state === ConnectionStatus.Online) { - // needs to happen before sync and session or it would abort all requests - this._requestScheduler.start(); - this._sync.start(); - this._sessionStartedByReconnector = true; - this._session.start(this._reconnector.lastVersionsResponse); + this._platform.logger.runDetached("reconnect", async log => { + // needs to happen before sync and session or it would abort all requests + this._requestScheduler.start(); + this._sync.start(); + this._sessionStartedByReconnector = true; + await log.wrap("session start", log => this._session.start(this._reconnector.lastVersionsResponse, log)); + }); } }); - await this._waitForFirstSync(); + await log.wrap("wait first sync", log => this._waitForFirstSync(log)); this._status.set(LoadStatus.Ready); @@ -204,12 +217,13 @@ export class SessionContainer { // started to session, so check first // to prevent an extra /versions request if (!this._sessionStartedByReconnector) { - const lastVersionsResponse = await hsApi.versions({timeout: 10000}).response(); - this._session.start(lastVersionsResponse); + const lastVersionsResponse = await hsApi.versions({timeout: 10000, log}).response(); + // log as ref as we don't want to await it + await log.wrap("session start", log => this._session.start(lastVersionsResponse, log)); } } - async _waitForFirstSync() { + async _waitForFirstSync(log) { try { this._sync.start(); this._status.set(LoadStatus.FirstSync); diff --git a/src/matrix/e2ee/Account.js b/src/matrix/e2ee/Account.js index 96990e3b..693d61f8 100644 --- a/src/matrix/e2ee/Account.js +++ b/src/matrix/e2ee/Account.js @@ -80,22 +80,24 @@ export class Account { return this._identityKeys; } - async uploadKeys(storage) { + async uploadKeys(storage, log) { const oneTimeKeys = JSON.parse(this._account.one_time_keys()); // only one algorithm supported by olm atm, so hardcode its name const oneTimeKeysEntries = Object.entries(oneTimeKeys.curve25519); if (oneTimeKeysEntries.length || !this._areDeviceKeysUploaded) { const payload = {}; if (!this._areDeviceKeysUploaded) { + log.set("identity", true); const identityKeys = JSON.parse(this._account.identity_keys()); payload.device_keys = this._deviceKeysPayload(identityKeys); } if (oneTimeKeysEntries.length) { + log.set("otks", true); payload.one_time_keys = this._oneTimeKeysPayload(oneTimeKeysEntries); } - const response = await this._hsApi.uploadKeys(payload, /*{log}*/).response(); + const response = await this._hsApi.uploadKeys(payload, {log}).response(); this._serverOTKCount = response?.one_time_key_counts?.signed_curve25519; - // log.set("serverOTKCount", this._serverOTKCount); + log.set("serverOTKCount", this._serverOTKCount); // TODO: should we not modify this in the txn like we do elsewhere? // we'd have to pickle and unpickle the account to clone it though ... // and the upload has succeed at this point, so in-memory would be correct @@ -114,7 +116,7 @@ export class Account { } } - async generateOTKsIfNeeded(storage) { + async generateOTKsIfNeeded(storage, log) { const maxOTKs = this._account.max_number_of_one_time_keys(); const limit = maxOTKs / 2; if (this._serverOTKCount < limit) { @@ -128,11 +130,16 @@ export class Account { if (totalOTKCount < limit) { // we could in theory also generated the keys and store them in // writeSync, but then we would have to clone the account to avoid side-effects. - await this._updateSessionStorage(storage, sessionStore => { + await log.wrap("generate otks", log => this._updateSessionStorage(storage, sessionStore => { const newKeyCount = maxOTKs - totalOTKCount; + log.set("max", maxOTKs); + log.set("server", this._serverOTKCount); + log.set("unpublished", unpublishedOTKCount); + log.set("new", newKeyCount); + log.set("limit", limit); this._account.generate_one_time_keys(newKeyCount); sessionStore.set(ACCOUNT_SESSION_KEY, this._account.pickle(this._pickleKey)); - }); + })); return true; } } diff --git a/src/matrix/room/Room.js b/src/matrix/room/Room.js index eb44071a..e562e8b1 100644 --- a/src/matrix/room/Room.js +++ b/src/matrix/room/Room.js @@ -167,6 +167,7 @@ export class Room extends EventEmitter { throw err; } await writeTxn.complete(); + // TODO: log decryption errors here decryption.applyToEntries(entries); if (this._observedEvents) { this._observedEvents.updateEvents(entries); @@ -318,30 +319,29 @@ export class Room extends EventEmitter { async afterSyncCompleted(changes, log) { log.set("id", this.id); if (this._roomEncryption) { - // TODO: pass log to flushPendingRoomKeyShares once we also have a logger in `start` - await this._roomEncryption.flushPendingRoomKeyShares(this._hsApi, null); + await this._roomEncryption.flushPendingRoomKeyShares(this._hsApi, null, log); } } /** @package */ - async start(pendingOperations) { + start(pendingOperations, parentLog) { if (this._roomEncryption) { - try { - const roomKeyShares = pendingOperations?.get("share_room_key"); - if (roomKeyShares) { - // if we got interrupted last time sending keys to newly joined members - await this._roomEncryption.flushPendingRoomKeyShares(this._hsApi, roomKeyShares); - } - } catch (err) { - // we should not throw here - console.error(`could not send out (all) pending room keys for room ${this.id}`, err.stack); + const roomKeyShares = pendingOperations?.get("share_room_key"); + if (roomKeyShares) { + // if we got interrupted last time sending keys to newly joined members + parentLog.wrapDetached("flush room keys", log => { + log.set("id", this.id); + return this._roomEncryption.flushPendingRoomKeyShares(this._hsApi, roomKeyShares, log); + }); } } - this._sendQueue.resumeSending(); + + this._sendQueue.resumeSending(parentLog); } /** @package */ - async load(summary, txn) { + async load(summary, txn, log) { + log.set("id", this.id); try { this._summary.load(summary); if (this._summary.data.encryption) { @@ -354,7 +354,7 @@ export class Room extends EventEmitter { const changes = await this._heroes.calculateChanges(this._summary.data.heroes, [], txn); this._heroes.applyChanges(changes, this._summary.data); } - return this._syncWriter.load(txn); + return this._syncWriter.load(txn, log); } catch (err) { throw new WrappedError(`Could not load room ${this._roomId}`, err); } diff --git a/src/matrix/room/timeline/persistence/SyncWriter.js b/src/matrix/room/timeline/persistence/SyncWriter.js index 38617997..bb0da2ea 100644 --- a/src/matrix/room/timeline/persistence/SyncWriter.js +++ b/src/matrix/room/timeline/persistence/SyncWriter.js @@ -41,7 +41,7 @@ export class SyncWriter { this._lastLiveKey = null; } - async load(txn) { + async load(txn, log) { const liveFragment = await txn.timelineFragments.liveFragment(this._roomId); if (liveFragment) { const [lastEvent] = await txn.timelineEvents.lastEvents(this._roomId, liveFragment.id, 1); @@ -53,7 +53,9 @@ export class SyncWriter { } // if there is no live fragment, we don't create it here because load gets a readonly txn. // this is on purpose, load shouldn't modify the store - console.log("room persister load", this._roomId, this._lastLiveKey && this._lastLiveKey.toString()); + if (this._lastLiveKey) { + log.set("live key", this._lastLiveKey.toString()); + } } async _createLiveFragment(txn, previousToken) {