Skip to content

Commit

Permalink
Merge pull request matrix-org#763 from Ryuno-Ki/logging-lib
Browse files Browse the repository at this point in the history 
Logging lib. Fixes matrix-org#332
  • Loading branch information
@dbkr
dbkr authored Oct 25, 2018
2 parents 14071b0 + ae645ad commit cec8936
Show file tree
Hide file tree
Showing 13 changed files with 159 additions and 109 deletions.
1 change: 1 addition & 0 deletions package.json
View file
Original file line number Diff line number Diff line change
Expand Up @@ -73,6 +73,7 @@
"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.2",
"mocha": "^5.2.0",
Expand Down
45 changes: 23 additions & 22 deletions src/crypto/DeviceList.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand Down Expand Up @@ -110,7 +111,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() || {}
Expand Down Expand Up @@ -190,7 +191,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.
Expand Down Expand Up @@ -258,7 +259,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`,
);
Expand All @@ -269,13 +270,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(() => {
Expand Down Expand Up @@ -433,7 +434,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
Expand All @@ -452,7 +453,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
Expand Down Expand Up @@ -487,7 +488,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
Expand Down Expand Up @@ -550,7 +551,7 @@ export default class DeviceList {
).then(() => {
finished(true);
}, (e) => {
console.error(
logger.error(
'Error downloading keys for ' + users + ":", e,
);
finished(false);
Expand All @@ -573,7 +574,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;
}
Expand All @@ -584,7 +585,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;
}
Expand Down Expand Up @@ -659,7 +660,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;
}

Expand All @@ -679,7 +680,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 = {};
Expand All @@ -706,7 +707,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();
Expand All @@ -716,7 +717,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);
});
Expand All @@ -725,7 +726,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 = {};
Expand Down Expand Up @@ -763,7 +764,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;
Expand All @@ -780,12 +781,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;
}
Expand Down Expand Up @@ -815,7 +816,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;
}
Expand All @@ -825,7 +826,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;
}
Expand All @@ -842,7 +843,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;
}
Expand Down
15 changes: 8 additions & 7 deletions src/crypto/OlmDevice.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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';

/**
Expand Down Expand Up @@ -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);
}
}
Expand All @@ -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;
Expand All @@ -207,7 +208,7 @@ OlmDevice.prototype._migrateFromSessionStore = async function() {
);
}
}
console.log(
logger.log(
"Migrating " + numSessions + " sessions from session store",
);
});
Expand Down Expand Up @@ -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",
);
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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}, ` +
Expand Down
21 changes: 11 additions & 10 deletions src/crypto/OutgoingRoomKeyRequestManager.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ limitations under the License.

import Promise from 'bluebird';

import logger from '../logger';
import utils from '../utils';

/**
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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),
);
Expand Down Expand Up @@ -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',
Expand All @@ -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,
);
Expand Down Expand Up @@ -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();
Expand All @@ -282,15 +283,15 @@ 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,
ROOM_KEY_REQUEST_STATES.CANCELLATION_PENDING_AND_WILL_RESEND,
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;
}
Expand All @@ -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();
Expand All @@ -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})`,
Expand All @@ -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)} ` +
Expand Down
Loading

0 comments on commit cec8936

Please sign in to comment.