Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Debuglog as events #1611

Closed
wants to merge 2 commits into from
Closed

Debuglog as events #1611

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
4e2fdae
Made debuglogging in sync module user configurable, can now output to…
Feb 21, 2021
2d9f430
Merge branch 'develop' into debuglog_as_events
Feb 21, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
11 changes: 11 additions & 0 deletions src/client.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -278,6 +278,8 @@ function keyFromRecoverySession(session, decryptionKey) {
* unique per sender, device pair.
* {DeviceTrustLevel} deviceTrust: The trust status of the device requesting
* the secret as returned by {@link module:client~MatrixClient#checkDeviceTrust}.
* @param {String=} opts.debugLogType How the client debuglog output is handled, can be one of
* 'stdout' | 'event' | 'off', defaults to stdout
*/
export function MatrixClient(opts) {
opts.baseUrl = utils.ensureNoTrailingSlash(opts.baseUrl);
Expand Down Expand Up @@ -393,6 +395,9 @@ export function MatrixClient(opts) {
this._clientWellKnown = undefined;
this._clientWellKnownPromise = undefined;

// Debuglog type
this._debugLogType = opts.debugLogType || 'stdout';

// The SDK doesn't really provide a clean way for events to recalculate the push
// actions for themselves, so we have to kinda help them out when they are encrypted.
// We do this so that push rules are correctly executed on events in their decrypted
Expand Down Expand Up @@ -5067,6 +5072,8 @@ MatrixClient.prototype.deactivateSynapseUser = function(userId) {
* @param {Number=} opts.clientWellKnownPollPeriod The number of seconds between polls
* to /.well-known/matrix/client, undefined to disable. This should be in the order of hours.
* Default: undefined.
* @param {String=} opts.debugLogType How the client debuglog output is handled, can be one of
* 'stdout' | 'event' | 'off', defaults to stdout
*/
MatrixClient.prototype.startClient = async function(opts) {
if (this.clientRunning) {
Expand Down Expand Up @@ -5112,6 +5119,10 @@ MatrixClient.prototype.startClient = async function(opts) {
}
return this._canResetTimelineCallback(roomId);
};

// Transfer debuglog setting
opts.debugLogType = this._debugLogType;

this._clientOpts = opts;
this._syncApi = new SyncApi(this, opts);
this._syncApi.sync();
Expand Down
2 changes: 2 additions & 0 deletions src/matrix.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -207,6 +207,8 @@ export interface IDeviceTrustLevel {
* {@link setCryptoStoreFactory} if unspecified; or if no factory has been
* specified, uses a default implementation (indexeddb in the browser,
* in-memory otherwise).
* @param {String=} opts.debugLogType How the client debuglog output is handled, can be one of
* 'stdout' | 'event' | 'off', defaults to stdout
*
* @return {MatrixClient} A new matrix client.
* @see {@link module:client.MatrixClient} for the full list of options for
Expand Down
76 changes: 43 additions & 33 deletions src/sync.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,8 +36,6 @@ import {PushProcessor} from "./pushprocessor";
import {logger} from './logger';
import {InvalidStoreError} from './errors';

const DEBUG = true;

// /sync requests allow you to set a timeout= but the request may continue
// beyond that and wedge forever, so we need to track how long we are willing
// to keep open the connection. This constant is *ADDED* to the timeout= value
Expand All @@ -55,11 +53,20 @@ function getFilterName(userId, suffix) {
return "FILTER_SYNC_" + userId + (suffix ? "_" + suffix : "");
}

function debuglog(...params) {
if (!DEBUG) {
return;
function debuglog(client, debugLogType, ...params) {
switch (debugLogType) {
case 'event':
client.emit("debuglog", ...params);

break;
case 'off':
return;
case 'stdout':
default:
logger.log(...params);

break;
}
logger.log(...params);
}


Expand All @@ -77,6 +84,8 @@ function debuglog(...params) {
* Default: returns false.
* @param {Boolean=} opts.disablePresence True to perform syncing without automatically
* updating presence.
* @param {String=} opts.debugLogType How the client debuglog output is handled, can be one of
* 'stdout' | 'event' | 'off', defaults to stdout
*/
export function SyncApi(client, opts) {
this.client = client;
Expand Down Expand Up @@ -104,6 +113,7 @@ export function SyncApi(client, opts) {
this._notifEvents = []; // accumulator of sync events in the current sync response
this._failedSyncCount = 0; // Number of consecutive failed /sync requests
this._storeIsInvalid = false; // flag set if the store needs to be cleared before we can start
this._debugLogType = opts.debugLogType || 'stdout'; // stdout | event | off, stdout is "classic" behaviour, and default

if (client.getNotifTimelineSet()) {
client.reEmitter.reEmit(client.getNotifTimelineSet(),
Expand Down Expand Up @@ -350,7 +360,7 @@ SyncApi.prototype.stopPeeking = function() {
*/
SyncApi.prototype._peekPoll = function(peekRoom, token) {
if (this._peekRoom !== peekRoom) {
debuglog("Stopped peeking in room %s", peekRoom.roomId);
debuglog(self.client, this._debugLogType, "Stopped peeking in room %s", peekRoom.roomId);
return;
}

Expand All @@ -362,7 +372,7 @@ SyncApi.prototype._peekPoll = function(peekRoom, token) {
from: token,
}, undefined, 50 * 1000).then(function(res) {
if (self._peekRoom !== peekRoom) {
debuglog("Stopped peeking in room %s", peekRoom.roomId);
debuglog(self.client, self._debugLogType, "Stopped peeking in room %s", peekRoom.roomId);
return;
}
// We have a problem that we get presence both from /events and /sync
Expand Down Expand Up @@ -494,17 +504,17 @@ SyncApi.prototype.sync = function() {

async function getPushRules() {
try {
debuglog("Getting push rules...");
debuglog(client, self._debugLogType, "Getting push rules...");
const result = await client.getPushRules();
debuglog("Got push rules");
debuglog(client, self._debugLogType, "Got push rules");

client.pushRules = result;
} catch (err) {
logger.error("Getting push rules failed", err);
if (self._shouldAbortSync(err)) return;
// wait for saved sync to complete before doing anything else,
// otherwise the sync state will end up being incorrect
debuglog("Waiting for saved sync before retrying push rules...");
debuglog(client, self._debugLogType, "Waiting for saved sync before retrying push rules...");
await self.recoverFromSyncStartupError(savedSyncPromise, err);
getPushRules();
return;
Expand All @@ -519,27 +529,27 @@ SyncApi.prototype.sync = function() {
}

const checkLazyLoadStatus = async () => {
debuglog("Checking lazy load status...");
debuglog(client, self._debugLogType, "Checking lazy load status...");
if (this.opts.lazyLoadMembers && client.isGuest()) {
this.opts.lazyLoadMembers = false;
}
if (this.opts.lazyLoadMembers) {
debuglog("Checking server lazy load support...");
debuglog(client, self._debugLogType, "Checking server lazy load support...");
const supported = await client.doesServerSupportLazyLoading();
if (supported) {
debuglog("Enabling lazy load on sync filter...");
debuglog(client, self._debugLogType, "Enabling lazy load on sync filter...");
if (!this.opts.filter) {
this.opts.filter = buildDefaultFilter();
}
this.opts.filter.setLazyLoadMembers(true);
} else {
debuglog("LL: lazy loading requested but not supported " +
debuglog(client, self._debugLogType, "LL: lazy loading requested but not supported " +
"by server, so disabling");
this.opts.lazyLoadMembers = false;
}
}
// need to vape the store when enabling LL and wasn't enabled before
debuglog("Checking whether lazy loading has changed in store...");
debuglog(client, self._debugLogType, "Checking whether lazy loading has changed in store...");
const shouldClear = await this._wasLazyLoadingToggled(this.opts.lazyLoadMembers);
if (shouldClear) {
this._storeIsInvalid = true;
Expand All @@ -557,9 +567,9 @@ SyncApi.prototype.sync = function() {
this.opts.crypto.enableLazyLoading();
}
try {
debuglog("Storing client options...");
debuglog(client, self._debugLogType, "Storing client options...");
await this.client._storeClientOptions();
debuglog("Stored client options");
debuglog(client, self._debugLogType, "Stored client options");
} catch (err) {
logger.error("Storing client options failed", err);
throw err;
Expand All @@ -569,7 +579,7 @@ SyncApi.prototype.sync = function() {
};

async function getFilter() {
debuglog("Getting filter...");
debuglog(client, self._debugLogType, "Getting filter...");
let filter;
if (self.opts.filter) {
filter = self.opts.filter;
Expand All @@ -587,7 +597,7 @@ SyncApi.prototype.sync = function() {
if (self._shouldAbortSync(err)) return;
// wait for saved sync to complete before doing anything else,
// otherwise the sync state will end up being incorrect
debuglog("Waiting for saved sync before retrying filter...");
debuglog(client, self._debugLogType, "Waiting for saved sync before retrying filter...");
await self.recoverFromSyncStartupError(savedSyncPromise, err);
getFilter();
return;
Expand All @@ -601,12 +611,12 @@ SyncApi.prototype.sync = function() {
if (self._currentSyncRequest === null) {
// Send this first sync request here so we can then wait for the saved
// sync data to finish processing before we process the results of this one.
debuglog("Sending first sync request...");
debuglog(client, self._debugLogType, "Sending first sync request...");
self._currentSyncRequest = self._doSyncRequest({ filterId }, savedSyncToken);
}

// Now wait for the saved sync to finish...
debuglog("Waiting for saved sync before starting sync processing...");
debuglog(client, self._debugLogType, "Waiting for saved sync before starting sync processing...");
await savedSyncPromise;
self._sync({ filterId });
}
Expand All @@ -618,14 +628,14 @@ SyncApi.prototype.sync = function() {
// Pull the saved sync token out first, before the worker starts sending
// all the sync data which could take a while. This will let us send our
// first incremental sync request before we've processed our saved data.
debuglog("Getting saved sync token...");
debuglog(client, self._debugLogType, "Getting saved sync token...");
savedSyncPromise = client.store.getSavedSyncToken().then((tok) => {
debuglog("Got saved sync token");
debuglog(client, self._debugLogType, "Got saved sync token");
savedSyncToken = tok;
debuglog("Getting saved sync...");
debuglog(client, self._debugLogType, "Getting saved sync...");
return client.store.getSavedSync();
}).then((savedSync) => {
debuglog(`Got reply from saved sync, exists? ${!!savedSync}`);
debuglog(client, self._debugLogType, `Got reply from saved sync, exists? ${!!savedSync}`);
if (savedSync) {
return self._syncFromCache(savedSync);
}
Expand All @@ -643,7 +653,7 @@ SyncApi.prototype.sync = function() {
* Stops the sync object from syncing.
*/
SyncApi.prototype.stop = function() {
debuglog("SyncApi.stop");
debuglog(this.client, this._debugLogType, "SyncApi.stop");
if (global.window) {
global.window.removeEventListener("online", this._onOnlineBound, false);
this._onOnlineBound = undefined;
Expand Down Expand Up @@ -676,7 +686,7 @@ SyncApi.prototype.retryImmediately = function() {
* should have been acquired via client.store.getSavedSync().
*/
SyncApi.prototype._syncFromCache = async function(savedSync) {
debuglog("sync(): not doing HTTP hit, instead returning stored /sync data");
debuglog(this.client, this._debugLogType, "sync(): not doing HTTP hit, instead returning stored /sync data");

const nextSyncToken = savedSync.nextBatch;

Expand Down Expand Up @@ -724,7 +734,7 @@ SyncApi.prototype._sync = async function(syncOptions) {
const client = this.client;

if (!this._running) {
debuglog("Sync no longer running: exiting.");
debuglog(client, this._debugLogType, "Sync no longer running: exiting.");
if (this._connectionReturnedDefer) {
this._connectionReturnedDefer.reject();
this._connectionReturnedDefer = null;
Expand Down Expand Up @@ -883,7 +893,7 @@ SyncApi.prototype._getSyncParams = function(syncOptions, syncToken) {

SyncApi.prototype._onSyncError = function(err, syncOptions) {
if (!this._running) {
debuglog("Sync no longer running: exiting");
debuglog(this.client, this._debugLogType, "Sync no longer running: exiting");
if (this._connectionReturnedDefer) {
this._connectionReturnedDefer.reject();
this._connectionReturnedDefer = null;
Expand All @@ -902,7 +912,7 @@ SyncApi.prototype._onSyncError = function(err, syncOptions) {
this._failedSyncCount++;
logger.log('Number of consecutive failed sync requests:', this._failedSyncCount);

debuglog("Starting keep-alive");
debuglog(this.client, this._debugLogType, "Starting keep-alive");
// Note that we do *not* mark the sync connection as
// lost yet: we only do this if a keepalive poke
// fails, since long lived HTTP connections will
Expand Down Expand Up @@ -1206,7 +1216,7 @@ SyncApi.prototype._processSyncResponse = async function(
for (let i = timelineEvents.length - 1; i >= 0; i--) {
const eventId = timelineEvents[i].getId();
if (room.getTimelineForEvent(eventId)) {
debuglog("Already have event " + eventId + " in limited " +
debuglog(client, self._debugLogType, "Already have event " + eventId + " in limited " +
"sync - not resetting");
limited = false;

Expand Down Expand Up @@ -1702,7 +1712,7 @@ SyncApi.prototype._updateSyncState = function(newState, data) {
* but this might help us reconnect a little faster.
*/
SyncApi.prototype._onOnline = function() {
debuglog("Browser thinks we are back online");
debuglog(this.client, this._debugLogType, "Browser thinks we are back online");
this._startKeepAlives(0);
};

Expand Down