Do not attempt to retry an (initial) sync if mailbox is locked

When the app loads a mailbox, we try to fetch the 20 first messages. The
server will respond with a client error of HTTP400 when the mailbox
hasn't been cached yet. The client then first attempts an *intial sync*,
followed by re-fetching of the 20 first messages.

So far for the conflict-free sequence of commands. In the priority inbox
we have three virtual mailboxes that all try to get their data at the
same time. For initialized mailboxes the server will give away the 20
first messages for the respective query. For the very first access,
however, the mailboxes battle for the initial sync. Each of the
mailboxes will run into the HTTP400 for the mailbox that isn't cached,
then they will all three try to do the initial sync. One of them wins.
The other ones previous *retried* the intial sync. And that is where
things blew up. The attempted initial sync resulted in a regular sync.
And since the client requested a sync (diff) with no known message IDs,
the server assumed that all messages of the mailbox are "new". Hence
there was a huge server load and response, followed by a frozen browser
that tried to render hundrets or thousands of messages at once,
depending of the inbox size.

With this patch the initial sync doesn't actually attempt to retry when
it detects a locked mailbox. That is becaues it doesn't make much sense.
If the mailbox is locked then because some other process already takes
care of syncing. We don't have to do it ourselves. Instead we should try
to actually fetch the 20 newest messages. If that works then the process
is done.

Signed-off-by: Christoph Wurst <christoph@winzerhof-wurst.at>

src/components/Mailbox.vue

@@ -143,6 +143,7 @@ export default {
 		mailbox() {
 			this.loadEnvelopes()
 				.then(() => {
+					logger.debug(`syncing mailbox ${this.mailbox.databaseId} (${this.searchQuery}) after mailbox change`)
 					this.sync(false)
 				})
 		},
@@ -159,6 +160,7 @@ export default {
 	async mounted() {
 		this.loadEnvelopes()
 			.then(() => {
+				logger.debug(`syncing mailbox ${this.mailbox.databaseId} (${this.searchQuery}) after mount`)
 				this.sync(false)
 			})
 	},
@@ -173,6 +175,7 @@ export default {
 			this.loadingCacheInitialization = true
 			this.error = false
 
+			logger.debug(`syncing mailbox ${this.mailbox.databaseId} (${this.searchQuery}) during cache initalization`)
 			this.sync(true)
 				.then(() => {
 					this.loadingCacheInitialization = false
@@ -181,7 +184,7 @@ export default {
 				})
 		},
 		async loadEnvelopes() {
-			logger.debug(`fetching envelopes for mailbox ${this.mailbox.databaseId} and query ${this.searchQuery}`, this.mailbox)
+			logger.debug(`Fetching envelopes for mailbox ${this.mailbox.databaseId} (${this.searchQuery})`, this.mailbox)
 			this.loadingEnvelopes = true
 			this.loadingCacheInitialization = false
 			this.error = false
@@ -228,25 +231,25 @@ export default {
 			} catch (error) {
 				await matchError(error, {
 					[MailboxLockedError.getName()]: async(error) => {
-						logger.info('Mailbox is locked', { error })
+						logger.info(`Mailbox ${this.mailbox.databaseId} (${this.searchQuery}) is locked`, { error })
 
 						await wait(15 * 1000)
 						// Keep trying
 						await this.loadEnvelopes()
 					},
 					[MailboxNotCachedError.getName()]: async(error) => {
-						logger.info('Mailbox not cached. Triggering initialization', { error })
+						logger.info(`Mailbox ${this.mailbox.databaseId} (${this.searchQuery}) not cached. Triggering initialization`, { error })
 						this.loadingEnvelopes = false
 
 						try {
 							await this.initializeCache()
 						} catch (error) {
-							logger.error('Could not initialize cache', { error })
+							logger.error(`Could not initialize cache of mailbox ${this.mailbox.databaseId} (${this.searchQuery})`, { error })
 							this.error = error
 						}
 					},
 					default: (error) => {
-						logger.error('Could not fetch envelopes', { error })
+						logger.error(`Could not fetch envelopes of mailbox ${this.mailbox.databaseId} (${this.searchQuery})`, { error })
 						this.loadingEnvelopes = false
 						this.error = error
 					},
@@ -356,7 +359,7 @@ export default {
 				)
 				break
 			case 'refresh':
-				logger.debug('syncing envelopes via shortkey')
+				logger.debug(`syncing mailbox ${this.mailbox.databaseId} (${this.searchQuery}) per shortcut`)
 				this.sync(false)
 
 				break
@@ -374,9 +377,8 @@ export default {
 			}
 		},
 		async sync(init = false) {
-			logger.debug('syncing mailbox')
 			if (this.refreshing) {
-				logger.debug("already sync'ing, aborting")
+				logger.debug(`already sync'ing mailbox ${this.mailbox.databaseId} (${this.searchQuery}), aborting`, { init })
 				return
 			}
 
@@ -390,15 +392,15 @@ export default {
 			} catch (error) {
 				matchError(error, {
 					[MailboxLockedError.getName()](error) {
-						logger.info('Background sync failed because the mailbox is locked', { error })
+						logger.info('Background sync failed because the mailbox is locked', { error, init })
 					},
 					default(error) {
-						logger.error('Could not sync envelopes: ' + error.message, { error })
+						logger.error('Could not sync envelopes: ' + error.message, { error, init })
 					},
 				})
 			} finally {
 				this.refreshing = false
-				logger.debug("finished sync'ing mailbox")
+				logger.debug(`finished sync'ing mailbox ${this.mailbox.databaseId} (${this.searchQuery})`, { init })
 			}
 		},
 		onDelete(id) {
@@ -444,6 +446,7 @@ export default {
 				return
 			}
 			try {
+				logger.debug(`syncing mailbox ${this.mailbox.databaseId} (${this.searchQuery}) in background`)
 				await this.sync(false)
 			} catch (error) {
 				logger.error('Background sync failed: ' + error.message, { error })

src/store/actions.js

@@ -414,6 +414,8 @@ export default {
 		})
 	},
 	syncEnvelopes({ commit, getters, dispatch }, { mailboxId, query, init = false }) {
+		logger.debug(`starting mailbox sync of ${mailboxId} (${query})`)
+
 		const mailbox = getters.getMailbox(mailboxId)
 
 		if (mailbox.isUnified) {
@@ -457,9 +459,10 @@ export default {
 		}
 
 		const ids = getters.getEnvelopes(mailboxId, query).map((env) => env.databaseId)
+		logger.debug(`mailbox sync of ${mailboxId} (${query}) has ${ids.length} known IDs`)
 		return syncEnvelopes(mailbox.accountId, mailboxId, ids, query, init)
 			.then((syncData) => {
-				logger.info(`mailbox ${mailboxId} synchronized, ${syncData.newMessages.length} new, ${syncData.changedMessages.length} changed and ${syncData.vanishedMessages.length} vanished messages`)
+				logger.debug(`mailbox ${mailboxId} (${query}) synchronized, ${syncData.newMessages.length} new, ${syncData.changedMessages.length} changed and ${syncData.vanishedMessages.length} vanished messages`)
 
 				const unifiedMailbox = getters.getUnifiedMailbox(mailbox.specialRole)
 
@@ -491,10 +494,15 @@ export default {
 			.catch((error) => {
 				return matchError(error, {
 					[SyncIncompleteError.getName()]() {
-						console.warn('(initial) sync is incomplete, retriggering')
+						console.warn(`(initial) sync of mailbox ${mailboxId} (${query}) is incomplete, retriggering`)
 						return dispatch('syncEnvelopes', { mailboxId, query, init })
 					},
 					[MailboxLockedError.getName()](error) {
+						if (init) {
+							logger.info('Sync failed because the mailbox is locked, stopping here because this is an initial sync', { error })
+							throw error
+						}
+
 						logger.info('Sync failed because the mailbox is locked, retriggering', { error })
 						return wait(1500).then(() => dispatch('syncEnvelopes', { mailboxId, query, init }))
 					},