Merge remote-tracking branch 'origin/develop' into dbkr/e2e_backups

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",

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();
 };
 
 /**

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() {

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() {

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() {

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) {

spec/integ/matrix-client-methods.spec.js

@@ -41,6 +41,7 @@ describe("MatrixClient", function() {
 
     afterEach(function() {
         httpBackend.verifyNoOutstandingExpectation();
+        return httpBackend.stop();
     });
 
     describe("uploadContent", function() {

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() {

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() {

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() {

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() {

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() {

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(3);
-        expect(Crypto.getOlmVersion()[0]).toEqual(2);
     });
 });

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;
         }

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}, ` +

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)} ` +

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,

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,
     );

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})`,
     );

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;
 }

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}`,
     );

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}`);
         });
     }
 

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);
+        logger.log("Error: Failed to get key %s: %s", key, e.stack || e);
-        console.log(e.stack);
+        logger.log(e.stack);
     }
     return null;
 }

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})`,
                 );

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 <code>console</code> using {@link https://www.npmjs.com/package/loglevel|loglevel}.
+ * Can be tailored down to specific use cases if needed.
+*/
+module.exports = logger;