diff --git a/packages/isomorphic-core/src/imap-connection.js b/packages/isomorphic-core/src/imap-connection.js index ffedc349d..ac64d3286 100644 --- a/packages/isomorphic-core/src/imap-connection.js +++ b/packages/isomorphic-core/src/imap-connection.js @@ -295,10 +295,10 @@ class IMAPConnection extends EventEmitter { resultPromise.then((maybeResult) => { this._currentOperation = null; - this._logger.info({ - operation_type: operation.constructor.name, - operation_description: operation.description(), - }, `Finished sync operation`) + // this._logger.info({ + // operation_type: operation.constructor.name, + // operation_description: operation.description(), + // }, `Finished sync operation`) resolve(maybeResult); this.processNextOperation(); }) diff --git a/packages/local-sync/src/local-sync-worker/imap/fetch-folder-list.js b/packages/local-sync/src/local-sync-worker/imap/fetch-folder-list.js index da0fea963..d1ab8af3d 100644 --- a/packages/local-sync/src/local-sync-worker/imap/fetch-folder-list.js +++ b/packages/local-sync/src/local-sync-worker/imap/fetch-folder-list.js @@ -86,10 +86,10 @@ class FetchFolderList { const boxName = boxPath.join(box.delimiter); - this._logger.info({ - box_name: boxName, - attributes: JSON.stringify(box.attribs), - }, `FetchFolderList: Box Information`) + // this._logger.info({ + // box_name: boxName, + // attributes: JSON.stringify(box.attribs), + // }, `FetchFolderList: Box Information`) if (box.children && box.attribs.includes('\\HasChildren')) { diff --git a/packages/local-sync/src/local-sync-worker/imap/fetch-messages-in-folder.js b/packages/local-sync/src/local-sync-worker/imap/fetch-messages-in-folder.js index 420d575aa..a65423474 100644 --- a/packages/local-sync/src/local-sync-worker/imap/fetch-messages-in-folder.js +++ b/packages/local-sync/src/local-sync-worker/imap/fetch-messages-in-folder.js @@ -100,9 +100,9 @@ class FetchMessagesInFolder { }) if (createdUIDs.length > 0) { - this._logger.info({ - new_messages: createdUIDs.length, - }, `FetchMessagesInFolder: found new messages. These will not be processed because we assume that they will be assigned uid = uidnext, and will be picked up in the next sync when we discover unseen messages.`); + // this._logger.info({ + // new_messages: createdUIDs.length, + // }, `FetchMessagesInFolder: found new messages. These will not be processed because we assume that they will be assigned uid = uidnext, and will be picked up in the next sync when we discover unseen messages.`); } // Step 2: If flags were changed, apply the changes to the corresponding @@ -155,9 +155,9 @@ class FetchMessagesInFolder { return; } - this._logger.info({ - removed_messages: removedUIDs.length, - }, `FetchMessagesInFolder: found messages no longer in the folder`) + // this._logger.info({ + // removed_messages: removedUIDs.length, + // }, `FetchMessagesInFolder: found messages no longer in the folder`) await this._db.sequelize.transaction((transaction) => Message.update({ @@ -223,10 +223,10 @@ class FetchMessagesInFolder { const desiredParts = JSON.parse(key); const bodies = ['HEADER'].concat(desiredParts.map(p => p.id)); - this._logger.info({ - key, - num_messages: uids.length, - }, `FetchMessagesInFolder: Fetching parts for messages`) + // this._logger.info({ + // key, + // num_messages: uids.length, + // }, `FetchMessagesInFolder: Fetching parts for messages`) // note: the order of UIDs in the array doesn't matter, Gmail always // returns them in ascending (oldest => newest) order. @@ -256,18 +256,18 @@ class FetchMessagesInFolder { if (thread) { await thread.updateLabelsAndFolders(); } - this._logger.info({ - message_id: existingMessage.id, - uid: existingMessage.folderImapUID, - }, `FetchMessagesInFolder: Updated message`) + // this._logger.info({ + // message_id: existingMessage.id, + // uid: existingMessage.folderImapUID, + // }, `FetchMessagesInFolder: Updated message`) } else { // TODO investigate batching processing new messages // We could measure load of actual sync vs load of just message processing // to determine how meaningful it is processNewMessage(messageValues, imapMessage) - this._logger.info({ - message: messageValues, - }, `FetchMessagesInFolder: Queued new message for processing`) + // this._logger.info({ + // message: messageValues, + // }, `FetchMessagesInFolder: Queued new message for processing`) } } catch (err) { this._logger.error(err, { @@ -292,12 +292,12 @@ class FetchMessagesInFolder { const lastUIDValidity = this._folder.syncState.uidvalidity; if (lastUIDValidity && (box.uidvalidity !== lastUIDValidity)) { - this._logger.info({ - boxname: box.name, - categoryname: this._folder.name, - remoteuidvalidity: box.uidvalidity, - localuidvalidity: lastUIDValidity, - }, `FetchMessagesInFolder: Recovering from UIDInvalidity`); + // this._logger.info({ + // boxname: box.name, + // categoryname: this._folder.name, + // remoteuidvalidity: box.uidvalidity, + // localuidvalidity: lastUIDValidity, + // }, `FetchMessagesInFolder: Recovering from UIDInvalidity`); await this._recoverFromUIDInvalidity() } @@ -312,9 +312,9 @@ class FetchMessagesInFolder { const desiredRanges = []; - this._logger.info({ - range: `${savedSyncState.fetchedmin}:${savedSyncState.fetchedmax}`, - }, `FetchMessagesInFolder: Fetching messages.`) + // this._logger.info({ + // range: `${savedSyncState.fetchedmin}:${savedSyncState.fetchedmax}`, + // }, `FetchMessagesInFolder: Fetching messages.`) // Todo: In the future, this is where logic should go that limits // sync based on number of messages / age of messages. @@ -326,21 +326,21 @@ class FetchMessagesInFolder { if (savedSyncState.fetchedmax < boxUidnext) { desiredRanges.push({min: savedSyncState.fetchedmax, max: boxUidnext}) } else { - this._logger.info('FetchMessagesInFolder: fetchedmax == uidnext, nothing more recent to fetch.') + // this._logger.info('FetchMessagesInFolder: fetchedmax == uidnext, nothing more recent to fetch.') } if (savedSyncState.fetchedmin > 1) { const lowerbound = Math.max(1, savedSyncState.fetchedmin - FETCH_MESSAGES_COUNT); desiredRanges.push({min: lowerbound, max: savedSyncState.fetchedmin}) } else { - this._logger.info("FetchMessagesInFolder: fetchedmin == 1, nothing older to fetch.") + // this._logger.info("FetchMessagesInFolder: fetchedmin == 1, nothing older to fetch.") } } await PromiseUtils.each(desiredRanges, async ({min, max}) => { - this._logger.info({ - range: `${min}:${max}`, - }, `FetchMessagesInFolder: Fetching range`); + // this._logger.info({ + // range: `${min}:${max}`, + // }, `FetchMessagesInFolder: Fetching range`); await this._fetchMessagesAndQueueForProcessing(`${min}:${max}`); const {fetchedmin, fetchedmax} = this._folder.syncState; @@ -353,7 +353,7 @@ class FetchMessagesInFolder { }); }); - this._logger.info(`FetchMessagesInFolder: Fetching messages finished`); + // this._logger.info(`FetchMessagesInFolder: Fetching messages finished`); } _runScan() { @@ -376,15 +376,15 @@ class FetchMessagesInFolder { let shallowFetch = null; if (this._imap.serverSupports(Capabilities.Condstore)) { - this._logger.info(`FetchMessagesInFolder: Shallow attribute scan (using CONDSTORE)`) + // this._logger.info(`FetchMessagesInFolder: Shallow attribute scan (using CONDSTORE)`) if (nextHighestmodseq === highestmodseq) { - this._logger.info('FetchMessagesInFolder: highestmodseq matches, nothing more to fetch') + // this._logger.info('FetchMessagesInFolder: highestmodseq matches, nothing more to fetch') return Promise.resolve(); } shallowFetch = this._box.fetchUIDAttributes(`1:*`, {changedsince: highestmodseq}); } else { const range = `${this._getLowerBoundUID(SHALLOW_SCAN_UID_COUNT)}:*`; - this._logger.info({range}, `FetchMessagesInFolder: Shallow attribute scan`) + // this._logger.info({range}, `FetchMessagesInFolder: Shallow attribute scan`) shallowFetch = this._box.fetchUIDAttributes(range); } @@ -396,7 +396,7 @@ class FetchMessagesInFolder { await this._updateMessageAttributes(remoteUIDAttributes, localMessageAttributes) - this._logger.info(`FetchMessagesInFolder: finished fetching changes to messages`); + // this._logger.info(`FetchMessagesInFolder: finished fetching changes to messages`); return this.updateFolderSyncState({ highestmodseq: nextHighestmodseq, timeShallowScan: Date.now(), @@ -408,7 +408,7 @@ class FetchMessagesInFolder { const {fetchedmin, fetchedmax} = this._folder.syncState; const range = `${fetchedmin}:${fetchedmax}`; - this._logger.info({range}, `FetchMessagesInFolder: Deep attribute scan: fetching attributes in range`) + // this._logger.info({range}, `FetchMessagesInFolder: Deep attribute scan: fetching attributes in range`) const remoteUIDAttributes = await this._box.fetchUIDAttributes(range) const localMessageAttributes = await Message.findAll({ @@ -421,7 +421,7 @@ class FetchMessagesInFolder { deletes: this._removeDeletedMessages(remoteUIDAttributes, localMessageAttributes), }) - this._logger.info(`FetchMessagesInFolder: Deep scan finished.`); + // this._logger.info(`FetchMessagesInFolder: Deep scan finished.`); return this.updateFolderSyncState({ highestmodseq: this._box.highestmodseq, @@ -439,6 +439,7 @@ class FetchMessagesInFolder { } async run(db, imap) { + console.log(`🔃 📂 ${this._folder.name}`) this._db = db; this._imap = imap; diff --git a/packages/local-sync/src/local-sync-worker/sync-worker.js b/packages/local-sync/src/local-sync-worker/sync-worker.js index b26a79381..f46999b6c 100644 --- a/packages/local-sync/src/local-sync-worker/sync-worker.js +++ b/packages/local-sync/src/local-sync-worker/sync-worker.js @@ -266,6 +266,7 @@ class SyncWorker { return; } + this._syncStart = Date.now() clearTimeout(this._syncTimer); this._syncTimer = null; this._interrupted = false @@ -280,7 +281,8 @@ class SyncWorker { return; } - this._logger.info({reason}, `SyncWorker: Account sync started`) + console.log(`🔃 🆕 reason: ${reason}`) + // this._logger.info({reason}, `SyncWorker: Account sync started`) try { await this._account.update({syncError: null}); @@ -355,14 +357,15 @@ class SyncWorker { lastSyncCompletions.pop(); } - this._logger.info('Syncworker: Completed sync cycle'); + console.log(`🔃 🔚 took ${now - this._syncStart}ms`) + // this._logger.info('Syncworker: Completed sync cycle'); this._account.lastSyncCompletions = lastSyncCompletions; this._account.save(); // Start idling on the inbox const idleFolder = await this._getIdleFolder(); await this._conn.openBox(idleFolder.name); - this._logger.info('SyncWorker: Idling on inbox folder'); + // this._logger.info('SyncWorker: Idling on inbox folder'); } async scheduleNextSync() { @@ -383,13 +386,14 @@ class SyncWorker { const interval = shouldSyncImmediately ? 1 : intervals.active; const nextSyncIn = Math.max(1, this._lastSyncTime + interval - Date.now()) - this._logger.info({ - moreToSync, - shouldSyncImmediately, - interrupted: this._interrupted, - nextSyncStartingIn: `${nextSyncIn}ms`, - syncAttemptsWhileInProgress: this._syncAttemptsWhileInProgress, - }, `SyncWorker: Scheduling next sync iteration`) + // this._logger.info({ + // moreToSync, + // shouldSyncImmediately, + // interrupted: this._interrupted, + // nextSyncStartingIn: `${nextSyncIn}ms`, + // syncAttemptsWhileInProgress: this._syncAttemptsWhileInProgress, + // }, `SyncWorker: Scheduling next sync iteration`) + console.log(`🔃 🔜 in ${nextSyncIn}ms`) this._syncTimer = setTimeout(() => { this.syncNow({reason}); diff --git a/packages/local-sync/src/new-message-processor/index.js b/packages/local-sync/src/new-message-processor/index.js index 0cfd821ee..fc96d67c5 100644 --- a/packages/local-sync/src/new-message-processor/index.js +++ b/packages/local-sync/src/new-message-processor/index.js @@ -28,10 +28,11 @@ function processNewMessage(message, imapMessage) { await Message.create(message); await extractFiles({db, message, imapMessage}); await extractContacts({db, message}); - logger.info({ - message_id: message.id, - uid: message.folderImapUID, - }, `MessageProcessor: Created and processed message`); + console.log(`🔃 ✉️ "${message.subject}"`) + // logger.info({ + // message_id: message.id, + // uid: message.folderImapUID, + // }, `MessageProcessor: Created and processed message`); } catch (err) { logger.error(err, `MessageProcessor: Failed`); }