diff --git a/package.json b/package.json index 668bc370c..26507b638 100644 --- a/package.json +++ b/package.json @@ -74,8 +74,9 @@ "expect": "^1.20.2", "istanbul": "^0.4.5", "jsdoc": "^3.5.5", + "loglevel": "1.6.1", "lolex": "^1.5.2", - "matrix-mock-request": "^1.2.0", + "matrix-mock-request": "^1.2.2", "mocha": "^5.2.0", "mocha-jenkins-reporter": "^0.4.0", "rimraf": "^2.5.4", diff --git a/spec/TestClient.js b/spec/TestClient.js index 1a7fa0816..1c08c2c7a 100644 --- a/spec/TestClient.js +++ b/spec/TestClient.js @@ -102,9 +102,11 @@ TestClient.prototype.start = function() { /** * stop the client + * @return {Promise} Resolves once the mock http backend has finished all pending flushes */ TestClient.prototype.stop = function() { this.client.stopClient(); + return this.httpBackend.stop(); }; /** diff --git a/spec/integ/devicelist-integ-spec.js b/spec/integ/devicelist-integ-spec.js index f3f889deb..b671ce5bf 100644 --- a/spec/integ/devicelist-integ-spec.js +++ b/spec/integ/devicelist-integ-spec.js @@ -97,7 +97,7 @@ describe("DeviceList management:", function() { }); afterEach(function() { - aliceTestClient.stop(); + return aliceTestClient.stop(); }); it("Alice shouldn't do a second /query for non-e2e-capable devices", function() { diff --git a/spec/integ/matrix-client-crypto.spec.js b/spec/integ/matrix-client-crypto.spec.js index 31a40aaf6..96bdd408e 100644 --- a/spec/integ/matrix-client-crypto.spec.js +++ b/spec/integ/matrix-client-crypto.spec.js @@ -410,10 +410,10 @@ describe("MatrixClient crypto", function() { }); afterEach(function() { - aliTestClient.stop(); aliTestClient.httpBackend.verifyNoOutstandingExpectation(); - bobTestClient.stop(); bobTestClient.httpBackend.verifyNoOutstandingExpectation(); + + return Promise.all([aliTestClient.stop(), bobTestClient.stop()]); }); it("Bob uploads device keys", function() { diff --git a/spec/integ/matrix-client-event-emitter.spec.js b/spec/integ/matrix-client-event-emitter.spec.js index c494e8bc4..e2fc810af 100644 --- a/spec/integ/matrix-client-event-emitter.spec.js +++ b/spec/integ/matrix-client-event-emitter.spec.js @@ -30,6 +30,7 @@ describe("MatrixClient events", function() { afterEach(function() { httpBackend.verifyNoOutstandingExpectation(); client.stopClient(); + return httpBackend.stop(); }); describe("emissions", function() { diff --git a/spec/integ/matrix-client-event-timeline.spec.js b/spec/integ/matrix-client-event-timeline.spec.js index 6fd3778be..2f1c9fa87 100644 --- a/spec/integ/matrix-client-event-timeline.spec.js +++ b/spec/integ/matrix-client-event-timeline.spec.js @@ -111,6 +111,7 @@ describe("getEventTimeline support", function() { if (client) { client.stopClient(); } + return httpBackend.stop(); }); it("timeline support must be enabled to work", function(done) { diff --git a/spec/integ/matrix-client-methods.spec.js b/spec/integ/matrix-client-methods.spec.js index 5077a8ef4..e27a1a5b7 100644 --- a/spec/integ/matrix-client-methods.spec.js +++ b/spec/integ/matrix-client-methods.spec.js @@ -41,6 +41,7 @@ describe("MatrixClient", function() { afterEach(function() { httpBackend.verifyNoOutstandingExpectation(); + return httpBackend.stop(); }); describe("uploadContent", function() { diff --git a/spec/integ/matrix-client-opts.spec.js b/spec/integ/matrix-client-opts.spec.js index 201ae7960..f2bc17e01 100644 --- a/spec/integ/matrix-client-opts.spec.js +++ b/spec/integ/matrix-client-opts.spec.js @@ -64,6 +64,7 @@ describe("MatrixClient opts", function() { afterEach(function() { httpBackend.verifyNoOutstandingExpectation(); + return httpBackend.stop(); }); describe("without opts.store", function() { diff --git a/spec/integ/matrix-client-retrying.spec.js b/spec/integ/matrix-client-retrying.spec.js index af59e1ef6..b82294f2c 100644 --- a/spec/integ/matrix-client-retrying.spec.js +++ b/spec/integ/matrix-client-retrying.spec.js @@ -36,6 +36,7 @@ describe("MatrixClient retrying", function() { afterEach(function() { httpBackend.verifyNoOutstandingExpectation(); + return httpBackend.stop(); }); xit("should retry according to MatrixScheduler.retryFn", function() { diff --git a/spec/integ/matrix-client-room-timeline.spec.js b/spec/integ/matrix-client-room-timeline.spec.js index fdc5ea097..5970ceb66 100644 --- a/spec/integ/matrix-client-room-timeline.spec.js +++ b/spec/integ/matrix-client-room-timeline.spec.js @@ -130,6 +130,7 @@ describe("MatrixClient room timelines", function() { afterEach(function() { httpBackend.verifyNoOutstandingExpectation(); client.stopClient(); + return httpBackend.stop(); }); describe("local echo events", function() { diff --git a/spec/integ/matrix-client-syncing.spec.js b/spec/integ/matrix-client-syncing.spec.js index a74eea53a..6002436c4 100644 --- a/spec/integ/matrix-client-syncing.spec.js +++ b/spec/integ/matrix-client-syncing.spec.js @@ -38,6 +38,7 @@ describe("MatrixClient syncing", function() { afterEach(function() { httpBackend.verifyNoOutstandingExpectation(); client.stopClient(); + return httpBackend.stop(); }); describe("startClient", function() { diff --git a/spec/integ/megolm-integ.spec.js b/spec/integ/megolm-integ.spec.js index cb59ab5da..9a37e0b38 100644 --- a/spec/integ/megolm-integ.spec.js +++ b/spec/integ/megolm-integ.spec.js @@ -296,7 +296,7 @@ describe("megolm", function() { }); afterEach(function() { - aliceTestClient.stop(); + return aliceTestClient.stop(); }); it("Alice receives a megolm message", function() { diff --git a/spec/unit/crypto.spec.js b/spec/unit/crypto.spec.js index 1b28ad683..ee06ef369 100644 --- a/spec/unit/crypto.spec.js +++ b/spec/unit/crypto.spec.js @@ -18,7 +18,6 @@ describe("Crypto", function() { }); it("Crypto exposes the correct olm library version", function() { - console.log(Crypto); - expect(Crypto.getOlmVersion()[0]).toEqual(2); + expect(Crypto.getOlmVersion()[0]).toEqual(3); }); }); diff --git a/src/crypto/DeviceList.js b/src/crypto/DeviceList.js index c3a86ae1e..853299f31 100644 --- a/src/crypto/DeviceList.js +++ b/src/crypto/DeviceList.js @@ -24,6 +24,7 @@ limitations under the License. import Promise from 'bluebird'; +import logger from '../logger'; import DeviceInfo from './deviceinfo'; import olmlib from './olmlib'; import IndexedDBCryptoStore from './store/indexeddb-crypto-store'; @@ -113,7 +114,7 @@ export default class DeviceList { 'readwrite', [IndexedDBCryptoStore.STORE_DEVICE_DATA], (txn) => { this._cryptoStore.getEndToEndDeviceData(txn, (deviceData) => { if (deviceData === null) { - console.log("Migrating e2e device data..."); + logger.log("Migrating e2e device data..."); this._devices = this._sessionStore.getAllEndToEndDevices() || {}; this._deviceTrackingStatus = ( this._sessionStore.getEndToEndDeviceTrackingStatus() || {} @@ -206,7 +207,7 @@ export default class DeviceList { const resolveSavePromise = this._resolveSavePromise; this._savePromiseTime = targetTime; this._saveTimer = setTimeout(() => { - console.log('Saving device tracking data at token ' + this._syncToken); + logger.log('Saving device tracking data at token ' + this._syncToken); // null out savePromise now (after the delay but before the write), // otherwise we could return the existing promise when the save has // actually already happened. Likewise for the dirty flag. @@ -274,7 +275,7 @@ export default class DeviceList { if (this._keyDownloadsInProgressByUser[u]) { // already a key download in progress/queued for this user; its results // will be good enough for us. - console.log( + logger.log( `downloadKeys: already have a download in progress for ` + `${u}: awaiting its result`, ); @@ -285,13 +286,13 @@ export default class DeviceList { }); if (usersToDownload.length != 0) { - console.log("downloadKeys: downloading for", usersToDownload); + logger.log("downloadKeys: downloading for", usersToDownload); const downloadPromise = this._doKeyDownload(usersToDownload); promises.push(downloadPromise); } if (promises.length === 0) { - console.log("downloadKeys: already have all necessary keys"); + logger.log("downloadKeys: already have all necessary keys"); } return Promise.all(promises).then(() => { @@ -466,7 +467,7 @@ export default class DeviceList { throw new Error('userId must be a string; was '+userId); } if (!this._deviceTrackingStatus[userId]) { - console.log('Now tracking device list for ' + userId); + logger.log('Now tracking device list for ' + userId); this._deviceTrackingStatus[userId] = TRACKING_STATUS_PENDING_DOWNLOAD; } // we don't yet persist the tracking status, since there may be a lot @@ -485,7 +486,7 @@ export default class DeviceList { */ stopTrackingDeviceList(userId) { if (this._deviceTrackingStatus[userId]) { - console.log('No longer tracking device list for ' + userId); + logger.log('No longer tracking device list for ' + userId); this._deviceTrackingStatus[userId] = TRACKING_STATUS_NOT_TRACKED; // we don't yet persist the tracking status, since there may be a lot @@ -520,7 +521,7 @@ export default class DeviceList { */ invalidateUserDeviceList(userId) { if (this._deviceTrackingStatus[userId]) { - console.log("Marking device list outdated for", userId); + logger.log("Marking device list outdated for", userId); this._deviceTrackingStatus[userId] = TRACKING_STATUS_PENDING_DOWNLOAD; // we don't yet persist the tracking status, since there may be a lot @@ -589,7 +590,7 @@ export default class DeviceList { ).then(() => { finished(true); }, (e) => { - console.error( + logger.error( 'Error downloading keys for ' + users + ":", e, ); finished(false); @@ -612,7 +613,7 @@ export default class DeviceList { // since we started this request. If that happens, we should // ignore the completion of the first one. if (this._keyDownloadsInProgressByUser[u] !== prom) { - console.log('Another update in the queue for', u, + logger.log('Another update in the queue for', u, '- not marking up-to-date'); return; } @@ -623,7 +624,7 @@ export default class DeviceList { // we didn't get any new invalidations since this download started: // this user's device list is now up to date. this._deviceTrackingStatus[u] = TRACKING_STATUS_UP_TO_DATE; - console.log("Device list for", u, "now up to date"); + logger.log("Device list for", u, "now up to date"); } else { this._deviceTrackingStatus[u] = TRACKING_STATUS_PENDING_DOWNLOAD; } @@ -698,7 +699,7 @@ class DeviceListUpdateSerialiser { if (this._downloadInProgress) { // just queue up these users - console.log('Queued key download for', users); + logger.log('Queued key download for', users); return this._queuedQueryDeferred.promise; } @@ -718,7 +719,7 @@ class DeviceListUpdateSerialiser { const deferred = this._queuedQueryDeferred; this._queuedQueryDeferred = null; - console.log('Starting key download for', downloadUsers); + logger.log('Starting key download for', downloadUsers); this._downloadInProgress = true; const opts = {}; @@ -745,7 +746,7 @@ class DeviceListUpdateSerialiser { return prom; }).done(() => { - console.log('Completed key download for ' + downloadUsers); + logger.log('Completed key download for ' + downloadUsers); this._downloadInProgress = false; deferred.resolve(); @@ -755,7 +756,7 @@ class DeviceListUpdateSerialiser { this._doQueuedQueries(); } }, (e) => { - console.warn('Error downloading keys for ' + downloadUsers + ':', e); + logger.warn('Error downloading keys for ' + downloadUsers + ':', e); this._downloadInProgress = false; deferred.reject(e); }); @@ -764,7 +765,7 @@ class DeviceListUpdateSerialiser { } async _processQueryResponseForUser(userId, response) { - console.log('got keys for ' + userId + ':', response); + logger.log('got keys for ' + userId + ':', response); // map from deviceid -> deviceinfo for this user const userStore = {}; @@ -802,7 +803,7 @@ async function _updateStoredDeviceKeysForUser(_olmDevice, userId, userStore, } if (!(deviceId in userResult)) { - console.log("Device " + userId + ":" + deviceId + + logger.log("Device " + userId + ":" + deviceId + " has been removed"); delete userStore[deviceId]; updated = true; @@ -819,12 +820,12 @@ async function _updateStoredDeviceKeysForUser(_olmDevice, userId, userStore, // check that the user_id and device_id in the response object are // correct if (deviceResult.user_id !== userId) { - console.warn("Mismatched user_id " + deviceResult.user_id + + logger.warn("Mismatched user_id " + deviceResult.user_id + " in keys from " + userId + ":" + deviceId); continue; } if (deviceResult.device_id !== deviceId) { - console.warn("Mismatched device_id " + deviceResult.device_id + + logger.warn("Mismatched device_id " + deviceResult.device_id + " in keys from " + userId + ":" + deviceId); continue; } @@ -854,7 +855,7 @@ async function _storeDeviceKeys(_olmDevice, userStore, deviceResult) { const signKeyId = "ed25519:" + deviceId; const signKey = deviceResult.keys[signKeyId]; if (!signKey) { - console.warn("Device " + userId + ":" + deviceId + + logger.warn("Device " + userId + ":" + deviceId + " has no ed25519 key"); return false; } @@ -864,7 +865,7 @@ async function _storeDeviceKeys(_olmDevice, userStore, deviceResult) { try { await olmlib.verifySignature(_olmDevice, deviceResult, userId, deviceId, signKey); } catch (e) { - console.warn("Unable to verify signature on device " + + logger.warn("Unable to verify signature on device " + userId + ":" + deviceId + ":" + e); return false; } @@ -881,7 +882,7 @@ async function _storeDeviceKeys(_olmDevice, userStore, deviceResult) { // best off sticking with the original keys. // // Should we warn the user about it somehow? - console.warn("Ed25519 key for device " + userId + ":" + + logger.warn("Ed25519 key for device " + userId + ":" + deviceId + " has changed"); return false; } diff --git a/src/crypto/OlmDevice.js b/src/crypto/OlmDevice.js index 74e46e2a4..0b763fc1c 100644 --- a/src/crypto/OlmDevice.js +++ b/src/crypto/OlmDevice.js @@ -15,6 +15,7 @@ See the License for the specific language governing permissions and limitations under the License. */ +import logger from '../logger'; import IndexedDBCryptoStore from './store/indexeddb-crypto-store'; // The maximum size of an event is 65K, and we base64 the content, so this is a @@ -173,7 +174,7 @@ OlmDevice.prototype._migrateFromSessionStore = async function() { // Migrate from sessionStore pickledAccount = this._sessionStore.getEndToEndAccount(); if (pickledAccount !== null) { - console.log("Migrating account from session store"); + logger.log("Migrating account from session store"); this._cryptoStore.storeAccount(txn, pickledAccount); } } @@ -195,7 +196,7 @@ OlmDevice.prototype._migrateFromSessionStore = async function() { // has run against the same localstorage and created some spurious sessions. this._cryptoStore.countEndToEndSessions(txn, (count) => { if (count) { - console.log("Crypto store already has sessions: not migrating"); + logger.log("Crypto store already has sessions: not migrating"); return; } let numSessions = 0; @@ -207,7 +208,7 @@ OlmDevice.prototype._migrateFromSessionStore = async function() { ); } } - console.log( + logger.log( "Migrating " + numSessions + " sessions from session store", ); }); @@ -236,14 +237,14 @@ OlmDevice.prototype._migrateFromSessionStore = async function() { ), txn, ); } catch (e) { - console.warn( + logger.warn( "Failed to migrate session " + s.senderKey + "/" + s.sessionId + ": " + e.stack || e, ); } ++numIbSessions; } - console.log( + logger.log( "Migrated " + numIbSessions + " inbound group sessions from session store", ); @@ -889,7 +890,7 @@ OlmDevice.prototype.addInboundGroupSession = async function( roomId, senderKey, sessionId, txn, (existingSession, existingSessionData) => { if (existingSession) { - console.log( + logger.log( "Update for megolm session " + senderKey + "/" + sessionId, ); // for now we just ignore updates. TODO: implement something here @@ -1034,7 +1035,7 @@ OlmDevice.prototype.hasInboundSessionKeys = async function(roomId, senderKey, se } if (roomId !== sessionData.room_id) { - console.warn( + logger.warn( `requested keys for inbound group session ${senderKey}|` + `${sessionId}, with incorrect room_id ` + `(expected ${sessionData.room_id}, ` + diff --git a/src/crypto/OutgoingRoomKeyRequestManager.js b/src/crypto/OutgoingRoomKeyRequestManager.js index 75ab35454..4c9b7cbf5 100644 --- a/src/crypto/OutgoingRoomKeyRequestManager.js +++ b/src/crypto/OutgoingRoomKeyRequestManager.js @@ -16,6 +16,7 @@ limitations under the License. import Promise from 'bluebird'; +import logger from '../logger'; import utils from '../utils'; /** @@ -108,7 +109,7 @@ export default class OutgoingRoomKeyRequestManager { * Called when the client is stopped. Stops any running background processes. */ stop() { - console.log('stopping OutgoingRoomKeyRequestManager'); + logger.log('stopping OutgoingRoomKeyRequestManager'); // stop the timer on the next run this._clientRunning = false; } @@ -173,7 +174,7 @@ export default class OutgoingRoomKeyRequestManager { // may have seen it, so we still need to send a cancellation // in that case :/ - console.log( + logger.log( 'deleting unnecessary room key request for ' + stringifyRequestBody(requestBody), ); @@ -201,7 +202,7 @@ export default class OutgoingRoomKeyRequestManager { // the request cancelled. There is no point in // sending another cancellation since the other tab // will do it. - console.log( + logger.log( 'Tried to cancel room key request for ' + stringifyRequestBody(requestBody) + ' but it was already cancelled in another tab', @@ -222,7 +223,7 @@ export default class OutgoingRoomKeyRequestManager { updatedReq, andResend, ).catch((e) => { - console.error( + logger.error( "Error sending room key request cancellation;" + " will retry later.", e, ); @@ -261,7 +262,7 @@ export default class OutgoingRoomKeyRequestManager { }).catch((e) => { // this should only happen if there is an indexeddb error, // in which case we're a bit stuffed anyway. - console.warn( + logger.warn( `error in OutgoingRoomKeyRequestManager: ${e}`, ); }).done(); @@ -282,7 +283,7 @@ export default class OutgoingRoomKeyRequestManager { return Promise.resolve(); } - console.log("Looking for queued outgoing room key requests"); + logger.log("Looking for queued outgoing room key requests"); return this._cryptoStore.getOutgoingRoomKeyRequestByState([ ROOM_KEY_REQUEST_STATES.CANCELLATION_PENDING, @@ -290,7 +291,7 @@ export default class OutgoingRoomKeyRequestManager { ROOM_KEY_REQUEST_STATES.UNSENT, ]).then((req) => { if (!req) { - console.log("No more outgoing room key requests"); + logger.log("No more outgoing room key requests"); this._sendOutgoingRoomKeyRequestsTimer = null; return; } @@ -312,7 +313,7 @@ export default class OutgoingRoomKeyRequestManager { // go around the loop again return this._sendOutgoingRoomKeyRequests(); }).catch((e) => { - console.error("Error sending room key request; will retry later.", e); + logger.error("Error sending room key request; will retry later.", e); this._sendOutgoingRoomKeyRequestsTimer = null; this._startTimer(); }).done(); @@ -321,7 +322,7 @@ export default class OutgoingRoomKeyRequestManager { // given a RoomKeyRequest, send it and update the request record _sendOutgoingRoomKeyRequest(req) { - console.log( + logger.log( `Requesting keys for ${stringifyRequestBody(req.requestBody)}` + ` from ${stringifyRecipientList(req.recipients)}` + `(id ${req.requestId})`, @@ -347,7 +348,7 @@ export default class OutgoingRoomKeyRequestManager { // Given a RoomKeyRequest, cancel it and delete the request record unless // andResend is set, in which case transition to UNSENT. _sendOutgoingRoomKeyRequestCancellation(req, andResend) { - console.log( + logger.log( `Sending cancellation for key request for ` + `${stringifyRequestBody(req.requestBody)} to ` + `${stringifyRecipientList(req.recipients)} ` + diff --git a/src/crypto/algorithms/megolm.js b/src/crypto/algorithms/megolm.js index d1115f00e..e36f46783 100644 --- a/src/crypto/algorithms/megolm.js +++ b/src/crypto/algorithms/megolm.js @@ -24,6 +24,7 @@ limitations under the License. import Promise from 'bluebird'; +const logger = require("../../logger"); const utils = require("../../utils"); const olmlib = require("../olmlib"); const base = require("./base"); @@ -65,7 +66,7 @@ OutboundSessionInfo.prototype.needsRotation = function( if (this.useCount >= rotationPeriodMsgs || sessionLifetime >= rotationPeriodMs ) { - console.log( + logger.log( "Rotating megolm session after " + this.useCount + " messages, " + sessionLifetime + "ms", ); @@ -103,7 +104,7 @@ OutboundSessionInfo.prototype.sharedWithTooManyDevices = function( } if (!devicesInRoom.hasOwnProperty(userId)) { - console.log("Starting new session because we shared with " + userId); + logger.log("Starting new session because we shared with " + userId); return true; } @@ -113,7 +114,7 @@ OutboundSessionInfo.prototype.sharedWithTooManyDevices = function( } if (!devicesInRoom[userId].hasOwnProperty(deviceId)) { - console.log( + logger.log( "Starting new session because we shared with " + userId + ":" + deviceId, ); @@ -182,7 +183,7 @@ MegolmEncryption.prototype._ensureOutboundSession = function(devicesInRoom) { if (session && session.needsRotation(self._sessionRotationPeriodMsgs, self._sessionRotationPeriodMs) ) { - console.log("Starting new megolm session because we need to rotate."); + logger.log("Starting new megolm session because we need to rotate."); session = null; } @@ -192,7 +193,7 @@ MegolmEncryption.prototype._ensureOutboundSession = function(devicesInRoom) { } if (!session) { - console.log(`Starting new megolm session for room ${self._roomId}`); + logger.log(`Starting new megolm session for room ${self._roomId}`); session = await self._prepareNewSession(); } @@ -327,7 +328,7 @@ MegolmEncryption.prototype._splitUserDeviceMap = function( continue; } - console.log( + logger.log( "share keys with device " + userId + ":" + deviceId, ); @@ -449,10 +450,10 @@ MegolmEncryption.prototype._shareKeyWithDevices = async function(session, device await this._encryptAndSendKeysToDevices( session, key.chain_index, userDeviceMaps[i], payload, ); - console.log(`Completed megolm keyshare in ${this._roomId} ` + logger.log(`Completed megolm keyshare in ${this._roomId} ` + `(slice ${i + 1}/${userDeviceMaps.length})`); } catch (e) { - console.log(`megolm keyshare in ${this._roomId} ` + logger.log(`megolm keyshare in ${this._roomId} ` + `(slice ${i + 1}/${userDeviceMaps.length}) failed`); throw e; @@ -471,7 +472,7 @@ MegolmEncryption.prototype._shareKeyWithDevices = async function(session, device */ MegolmEncryption.prototype.encryptMessage = function(room, eventType, content) { const self = this; - console.log(`Starting to encrypt event for ${this._roomId}`); + logger.log(`Starting to encrypt event for ${this._roomId}`); return this._getDevicesInRoom(room).then(function(devicesInRoom) { // check if any of these devices are not yet known to the user. @@ -790,12 +791,12 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) { !sessionId || !content.session_key ) { - console.error("key event is missing fields"); + logger.error("key event is missing fields"); return; } if (!senderKey) { - console.error("key event has no sender key (not encrypted?)"); + logger.error("key event has no sender key (not encrypted?)"); return; } @@ -812,13 +813,13 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) { senderKey = content.sender_key; if (!senderKey) { - console.error("forwarded_room_key event is missing sender_key field"); + logger.error("forwarded_room_key event is missing sender_key field"); return; } const ed25519Key = content.sender_claimed_ed25519_key; if (!ed25519Key) { - console.error( + logger.error( `forwarded_room_key_event is missing sender_claimed_ed25519_key field`, ); return; @@ -831,7 +832,7 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) { keysClaimed = event.getKeysClaimed(); } - console.log(`Adding key for megolm session ${senderKey}|${sessionId}`); + logger.log(`Adding key for megolm session ${senderKey}|${sessionId}`); return this._olmDevice.addInboundGroupSession( content.room_id, senderKey, forwardingKeyChain, sessionId, content.session_key, keysClaimed, @@ -857,7 +858,7 @@ MegolmDecryption.prototype.onRoomKeyEvent = function(event) { ); } }).catch((e) => { - console.error(`Error handling m.room_key_event: ${e}`); + logger.error(`Error handling m.room_key_event: ${e}`); }); }; @@ -899,7 +900,7 @@ MegolmDecryption.prototype.shareKeysWithDevice = function(keyRequest) { return null; } - console.log( + logger.log( "sharing keys for session " + body.sender_key + "|" + body.session_id + " with device " + userId + ":" + deviceId, diff --git a/src/crypto/algorithms/olm.js b/src/crypto/algorithms/olm.js index 69390b064..2ef4bdebb 100644 --- a/src/crypto/algorithms/olm.js +++ b/src/crypto/algorithms/olm.js @@ -22,6 +22,7 @@ limitations under the License. */ import Promise from 'bluebird'; +const logger = require("../../logger"); const utils = require("../../utils"); const olmlib = require("../olmlib"); const DeviceInfo = require("../deviceinfo"); @@ -273,7 +274,7 @@ OlmDecryption.prototype._decryptMessage = async function( const payload = await this._olmDevice.decryptMessage( theirDeviceIdentityKey, sessionId, message.type, message.body, ); - console.log( + logger.log( "Decrypted Olm message from " + theirDeviceIdentityKey + " with session " + sessionId, ); @@ -328,7 +329,7 @@ OlmDecryption.prototype._decryptMessage = async function( ); } - console.log( + logger.log( "created new inbound Olm session ID " + res.session_id + " with " + theirDeviceIdentityKey, ); diff --git a/src/crypto/index.js b/src/crypto/index.js index 2f1c39bd9..70a398078 100644 --- a/src/crypto/index.js +++ b/src/crypto/index.js @@ -25,6 +25,7 @@ const anotherjson = require('another-json'); import Promise from 'bluebird'; import {EventEmitter} from 'events'; +const logger = require("../logger"); const utils = require("../utils"); const OlmDevice = require("./OlmDevice"); const olmlib = require("./olmlib"); @@ -136,8 +137,6 @@ utils.inherits(Crypto, EventEmitter); * Returns a promise which resolves once the crypto module is ready for use. */ Crypto.prototype.init = async function() { - // Olm is just an object with a .then, not a fully-fledged promise, so - // pass it into bluebird to make it a proper promise. await global.Olm.init(); const sessionStoreHasAccount = Boolean(this._sessionStore.getEndToEndAccount()); @@ -321,7 +320,7 @@ Crypto.prototype.registerEventHandlers = function(eventEmitter) { try { crypto._onRoomMembership(event, member, oldMembership); } catch (e) { - console.error("Error handling membership change:", e); + logger.error("Error handling membership change:", e); } }); @@ -506,7 +505,7 @@ function _maybeUploadOneTimeKeys(crypto) { // create any more keys. return uploadLoop(keyCount); }).catch((e) => { - console.error("Error uploading one-time keys", e.stack || e); + logger.error("Error uploading one-time keys", e.stack || e); }).finally(() => { // reset _oneTimeKeyCount to prevent start uploading based on old data. // it will be set again on the next /sync-response @@ -731,13 +730,13 @@ Crypto.prototype.getEventSenderDeviceInfo = function(event) { const claimedKey = event.getClaimedEd25519Key(); if (!claimedKey) { - console.warn("Event " + event.getId() + " claims no ed25519 key: " + + logger.warn("Event " + event.getId() + " claims no ed25519 key: " + "cannot verify sending device"); return null; } if (claimedKey !== device.getFingerprint()) { - console.warn( + logger.warn( "Event " + event.getId() + " claims ed25519 key " + claimedKey + "but sender device has key " + device.getFingerprint()); return null; @@ -783,7 +782,7 @@ Crypto.prototype.setRoomEncryption = async function(roomId, config, inhibitDevic const existingConfig = this._roomList.getRoomEncryption(roomId); if (existingConfig) { if (JSON.stringify(existingConfig) != JSON.stringify(config)) { - console.error("Ignoring m.room.encryption event which requests " + + logger.error("Ignoring m.room.encryption event which requests " + "a change of config in " + roomId); return; } @@ -830,7 +829,7 @@ Crypto.prototype.setRoomEncryption = async function(roomId, config, inhibitDevic } if (!this._lazyLoadMembers) { - console.log("Enabling encryption in " + roomId + "; " + + logger.log("Enabling encryption in " + roomId + "; " + "starting to track device lists for all users therein"); await this.trackRoomDevices(roomId); @@ -842,7 +841,7 @@ Crypto.prototype.setRoomEncryption = async function(roomId, config, inhibitDevic this._deviceList.refreshOutdatedDeviceLists(); } } else { - console.log("Enabling encryption in " + roomId); + logger.log("Enabling encryption in " + roomId); } }; @@ -863,7 +862,7 @@ Crypto.prototype.trackRoomDevices = function(roomId) { if (!room) { throw new Error(`Unable to start tracking devices in unknown room ${roomId}`); } - console.log(`Starting to track devices for room ${roomId} ...`); + logger.log(`Starting to track devices for room ${roomId} ...`); const members = await room.getEncryptionTargetMembers(); members.forEach((m) => { this._deviceList.startTrackingDeviceList(m.userId); @@ -960,7 +959,7 @@ Crypto.prototype.importRoomKeys = function(keys) { return Promise.map( keys, (key) => { if (!key.room_id || !key.algorithm) { - console.warn("ignoring room key entry with missing fields", key); + logger.warn("ignoring room key entry with missing fields", key); return null; } @@ -1209,7 +1208,7 @@ Crypto.prototype.requestRoomKey = function(requestBody, recipients) { requestBody, recipients, ).catch((e) => { // this normally means we couldn't talk to the store - console.error( + logger.error( 'Error requesting key for event', e, ); }).done(); @@ -1226,7 +1225,7 @@ Crypto.prototype.requestRoomKey = function(requestBody, recipients) { Crypto.prototype.cancelRoomKeyRequest = function(requestBody, andResend) { this._outgoingRoomKeyRequestManager.cancelRoomKeyRequest(requestBody, andResend) .catch((e) => { - console.warn("Error clearing pending room key requests", e); + logger.warn("Error clearing pending room key requests", e); }).done(); }; @@ -1244,7 +1243,7 @@ Crypto.prototype.onCryptoEvent = async function(event) { // finished processing the sync, in onSyncCompleted. await this.setRoomEncryption(roomId, content, true); } catch (e) { - console.error("Error configuring encryption in room " + roomId + + logger.error("Error configuring encryption in room " + roomId + ":", e); } }; @@ -1260,7 +1259,7 @@ Crypto.prototype.onSyncWillProcess = async function(syncData) { // scratch, so mark everything as untracked. onCryptoEvent will // be called for all e2e rooms during the processing of the sync, // at which point we'll start tracking all the users of that room. - console.log("Initial sync performed - resetting device tracking state"); + logger.log("Initial sync performed - resetting device tracking state"); this._deviceList.stopTrackingAllDeviceLists(); this._roomDeviceTrackingState = {}; } @@ -1378,7 +1377,7 @@ Crypto.prototype._onToDeviceEvent = function(event) { }); } } catch (e) { - console.error("Error handling toDeviceEvent:", e); + logger.error("Error handling toDeviceEvent:", e); } }; @@ -1392,7 +1391,7 @@ Crypto.prototype._onRoomKeyEvent = function(event) { const content = event.getContent(); if (!content.room_id || !content.algorithm) { - console.error("key event is missing fields"); + logger.error("key event is missing fields"); return; } @@ -1436,12 +1435,12 @@ Crypto.prototype._onRoomMembership = function(event, member, oldMembership) { // by calling _trackRoomDevices if (this._roomDeviceTrackingState[roomId]) { if (member.membership == 'join') { - console.log('Join event for ' + member.userId + ' in ' + roomId); + logger.log('Join event for ' + member.userId + ' in ' + roomId); // make sure we are tracking the deviceList for this user this._deviceList.startTrackingDeviceList(member.userId); } else if (member.membership == 'invite' && this._clientStore.getRoom(roomId).shouldEncryptForInvitedMembers()) { - console.log('Invite event for ' + member.userId + ' in ' + roomId); + logger.log('Invite event for ' + member.userId + ' in ' + roomId); this._deviceList.startTrackingDeviceList(member.userId); } } @@ -1508,7 +1507,7 @@ Crypto.prototype._processReceivedRoomKeyRequests = async function() { this._processReceivedRoomKeyRequestCancellation(cancellation), ); } catch (e) { - console.error(`Error processing room key requsts: ${e}`); + logger.error(`Error processing room key requsts: ${e}`); } finally { this._processingRoomKeyRequests = false; } @@ -1527,13 +1526,13 @@ Crypto.prototype._processReceivedRoomKeyRequest = async function(req) { const roomId = body.room_id; const alg = body.algorithm; - console.log(`m.room_key_request from ${userId}:${deviceId}` + + logger.log(`m.room_key_request from ${userId}:${deviceId}` + ` for ${roomId} / ${body.session_id} (id ${req.requestId})`); if (userId !== this._userId) { // TODO: determine if we sent this device the keys already: in // which case we can do so again. - console.log("Ignoring room key request from other user for now"); + logger.log("Ignoring room key request from other user for now"); return; } @@ -1543,18 +1542,18 @@ Crypto.prototype._processReceivedRoomKeyRequest = async function(req) { // if we don't have a decryptor for this room/alg, we don't have // the keys for the requested events, and can drop the requests. if (!this._roomDecryptors[roomId]) { - console.log(`room key request for unencrypted room ${roomId}`); + logger.log(`room key request for unencrypted room ${roomId}`); return; } const decryptor = this._roomDecryptors[roomId][alg]; if (!decryptor) { - console.log(`room key request for unknown alg ${alg} in room ${roomId}`); + logger.log(`room key request for unknown alg ${alg} in room ${roomId}`); return; } if (!await decryptor.hasKeysForKeyRequest(req)) { - console.log( + logger.log( `room key request for unknown session ${roomId} / ` + body.session_id, ); @@ -1568,7 +1567,7 @@ Crypto.prototype._processReceivedRoomKeyRequest = async function(req) { // if the device is is verified already, share the keys const device = this._deviceList.getStoredDevice(userId, deviceId); if (device && device.isVerified()) { - console.log('device is already verified: sharing keys'); + logger.log('device is already verified: sharing keys'); req.share(); return; } @@ -1585,7 +1584,7 @@ Crypto.prototype._processReceivedRoomKeyRequest = async function(req) { Crypto.prototype._processReceivedRoomKeyRequestCancellation = async function( cancellation, ) { - console.log( + logger.log( `m.room_key_request cancellation for ${cancellation.userId}:` + `${cancellation.deviceId} (id ${cancellation.requestId})`, ); diff --git a/src/crypto/olmlib.js b/src/crypto/olmlib.js index bbe942036..2098ffe72 100644 --- a/src/crypto/olmlib.js +++ b/src/crypto/olmlib.js @@ -23,6 +23,7 @@ limitations under the License. import Promise from 'bluebird'; const anotherjson = require('another-json'); +const logger = require("../logger"); const utils = require("../utils"); /** @@ -70,7 +71,7 @@ module.exports.encryptMessageForDevice = async function( return; } - console.log( + logger.log( "Using sessionid " + sessionId + " for device " + recipientUserId + ":" + recipientDevice.deviceId, ); @@ -195,7 +196,7 @@ module.exports.ensureOlmSessionsForDevices = async function( } if (!oneTimeKey) { - console.warn( + logger.warn( "No one-time keys (alg=" + oneTimeKeyAlgorithm + ") for device " + userId + ":" + deviceId, ); @@ -224,7 +225,7 @@ async function _verifyKeyAndStartSession(olmDevice, oneTimeKey, userId, deviceIn deviceInfo.getFingerprint(), ); } catch (e) { - console.error( + logger.error( "Unable to verify signature on one-time key for device " + userId + ":" + deviceId + ":", e, ); @@ -238,12 +239,12 @@ async function _verifyKeyAndStartSession(olmDevice, oneTimeKey, userId, deviceIn ); } catch (e) { // possibly a bad key - console.error("Error starting session with device " + + logger.error("Error starting session with device " + userId + ":" + deviceId + ": " + e); return null; } - console.log("Started new sessionid " + sid + + logger.log("Started new sessionid " + sid + " for device " + userId + ":" + deviceId); return sid; } diff --git a/src/crypto/store/indexeddb-crypto-store-backend.js b/src/crypto/store/indexeddb-crypto-store-backend.js index d5b66c30f..c27c48e3b 100644 --- a/src/crypto/store/indexeddb-crypto-store-backend.js +++ b/src/crypto/store/indexeddb-crypto-store-backend.js @@ -16,6 +16,8 @@ limitations under the License. */ import Promise from 'bluebird'; + +import logger from '../../logger'; import utils from '../../utils'; export const VERSION = 6; @@ -38,7 +40,7 @@ export class Backend { // attempts to delete the database will block (and subsequent // attempts to re-create it will also block). db.onversionchange = (ev) => { - console.log(`versionchange for indexeddb ${this._dbName}: closing`); + logger.log(`versionchange for indexeddb ${this._dbName}: closing`); db.close(); }; } @@ -64,7 +66,7 @@ export class Backend { this._getOutgoingRoomKeyRequest(txn, requestBody, (existing) => { if (existing) { // this entry matches the request - return it. - console.log( + logger.log( `already have key request outstanding for ` + `${requestBody.room_id} / ${requestBody.session_id}: ` + `not sending another`, @@ -75,7 +77,7 @@ export class Backend { // we got to the end of the list without finding a match // - add the new request. - console.log( + logger.log( `enqueueing key request for ${requestBody.room_id} / ` + requestBody.session_id, ); @@ -226,7 +228,7 @@ export class Backend { } const data = cursor.value; if (data.state != expectedState) { - console.warn( + logger.warn( `Cannot update room key request from ${expectedState} ` + `as it was already updated to ${data.state}`, ); @@ -264,7 +266,7 @@ export class Backend { } const data = cursor.value; if (data.state != expectedState) { - console.warn( + logger.warn( `Cannot delete room key request in state ${data.state} ` + `(expected ${expectedState})`, ); @@ -400,7 +402,7 @@ export class Backend { ev.stopPropagation(); // ...and this stops it from aborting the transaction ev.preventDefault(); - console.log( + logger.log( "Ignoring duplicate inbound group session: " + senderCurve25519Key + " / " + sessionId, ); @@ -536,7 +538,7 @@ export class Backend { } export function upgradeDatabase(db, oldVersion) { - console.log( + logger.log( `Upgrading IndexedDBCryptoStore from version ${oldVersion}` + ` to ${VERSION}`, ); diff --git a/src/crypto/store/indexeddb-crypto-store.js b/src/crypto/store/indexeddb-crypto-store.js index 052b4dd33..0cfa86b5a 100644 --- a/src/crypto/store/indexeddb-crypto-store.js +++ b/src/crypto/store/indexeddb-crypto-store.js @@ -17,6 +17,7 @@ limitations under the License. import Promise from 'bluebird'; +import logger from '../../logger'; import LocalStorageCryptoStore from './localStorage-crypto-store'; import MemoryCryptoStore from './memory-crypto-store'; import * as IndexedDBCryptoStoreBackend from './indexeddb-crypto-store-backend'; @@ -64,7 +65,7 @@ export default class IndexedDBCryptoStore { return; } - console.log(`connecting to indexeddb ${this._dbName}`); + logger.log(`connecting to indexeddb ${this._dbName}`); const req = this._indexedDB.open( this._dbName, IndexedDBCryptoStoreBackend.VERSION, @@ -77,7 +78,7 @@ export default class IndexedDBCryptoStore { }; req.onblocked = () => { - console.log( + logger.log( `can't yet open IndexedDBCryptoStore because it is open elsewhere`, ); }; @@ -89,7 +90,7 @@ export default class IndexedDBCryptoStore { req.onsuccess = (r) => { const db = r.target.result; - console.log(`connected to indexeddb ${this._dbName}`); + logger.log(`connected to indexeddb ${this._dbName}`); resolve(new IndexedDBCryptoStoreBackend.Backend(db)); }; }).then((backend) => { @@ -106,13 +107,13 @@ export default class IndexedDBCryptoStore { }, ); }).catch((e) => { - console.warn( + logger.warn( `unable to connect to indexeddb ${this._dbName}` + `: falling back to localStorage store: ${e}`, ); return new LocalStorageCryptoStore(global.localStorage); }).catch((e) => { - console.warn( + logger.warn( `unable to open localStorage: falling back to in-memory store: ${e}`, ); return new MemoryCryptoStore(); @@ -133,11 +134,11 @@ export default class IndexedDBCryptoStore { return; } - console.log(`Removing indexeddb instance: ${this._dbName}`); + logger.log(`Removing indexeddb instance: ${this._dbName}`); const req = this._indexedDB.deleteDatabase(this._dbName); req.onblocked = () => { - console.log( + logger.log( `can't yet delete IndexedDBCryptoStore because it is open elsewhere`, ); }; @@ -147,14 +148,14 @@ export default class IndexedDBCryptoStore { }; req.onsuccess = () => { - console.log(`Removed indexeddb instance: ${this._dbName}`); + logger.log(`Removed indexeddb instance: ${this._dbName}`); resolve(); }; }).catch((e) => { // in firefox, with indexedDB disabled, this fails with a // DOMError. We treat this as non-fatal, so that people can // still use the app. - console.warn(`unable to delete IndexedDBCryptoStore: ${e}`); + logger.warn(`unable to delete IndexedDBCryptoStore: ${e}`); }); } diff --git a/src/crypto/store/localStorage-crypto-store.js b/src/crypto/store/localStorage-crypto-store.js index cad6a7d64..b88b8f9bd 100644 --- a/src/crypto/store/localStorage-crypto-store.js +++ b/src/crypto/store/localStorage-crypto-store.js @@ -15,6 +15,8 @@ limitations under the License. */ import Promise from 'bluebird'; + +import logger from '../../logger'; import MemoryCryptoStore from './memory-crypto-store.js'; /** @@ -251,8 +253,8 @@ function getJsonItem(store, key) { // JSON.parse(null) === null, so this returns null. return JSON.parse(store.getItem(key)); } catch (e) { - console.log("Error: Failed to get key %s: %s", key, e.stack || e); - console.log(e.stack); + logger.log("Error: Failed to get key %s: %s", key, e.stack || e); + logger.log(e.stack); } return null; } diff --git a/src/crypto/store/memory-crypto-store.js b/src/crypto/store/memory-crypto-store.js index 6af312219..d9cfb8b98 100644 --- a/src/crypto/store/memory-crypto-store.js +++ b/src/crypto/store/memory-crypto-store.js @@ -17,6 +17,7 @@ limitations under the License. import Promise from 'bluebird'; +import logger from '../../logger'; import utils from '../../utils'; /** @@ -73,7 +74,7 @@ export default class MemoryCryptoStore { if (existing) { // this entry matches the request - return it. - console.log( + logger.log( `already have key request outstanding for ` + `${requestBody.room_id} / ${requestBody.session_id}: ` + `not sending another`, @@ -83,7 +84,7 @@ export default class MemoryCryptoStore { // we got to the end of the list without finding a match // - add the new request. - console.log( + logger.log( `enqueueing key request for ${requestBody.room_id} / ` + requestBody.session_id, ); @@ -165,7 +166,7 @@ export default class MemoryCryptoStore { } if (req.state != expectedState) { - console.warn( + logger.warn( `Cannot update room key request from ${expectedState} ` + `as it was already updated to ${req.state}`, ); @@ -196,7 +197,7 @@ export default class MemoryCryptoStore { } if (req.state != expectedState) { - console.warn( + logger.warn( `Cannot delete room key request in state ${req.state} ` + `(expected ${expectedState})`, ); diff --git a/src/logger.js b/src/logger.js new file mode 100644 index 000000000..ee77c2918 --- /dev/null +++ b/src/logger.js @@ -0,0 +1,36 @@ +/* +Copyright 2018 André Jaenisch + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +/** + * @module logger + */ +const log = require("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 +// application. +// An idea would be to control this via an environment variable (on Node.js). +// See https://www.npmjs.com/package/debug to see how this could be implemented +// Part of #332 is introducing a logging library in the first place. +const DEFAULT_NAME_SPACE = "matrix"; +const logger = log.getLogger(DEFAULT_NAME_SPACE); +logger.setLevel(log.levels.DEBUG); + +/** + * Drop-in replacement for console using {@link https://www.npmjs.com/package/loglevel|loglevel}. + * Can be tailored down to specific use cases if needed. +*/ +module.exports = logger;