fix(connections): Added additional logging to detect broken reconnect…

…ions

data/google-crawlers.json

@@ -1,5 +1,5 @@
 {
-    "creationTime": "2024-03-05T23:00:43.000000",
+    "creationTime": "2024-03-12T23:00:54.000000",
     "prefixes": [
         {
             "ipv6Prefix": "2001:4860:4801:2008::/64"

lib/imap-connection.js

@@ -148,6 +148,8 @@ class IMAPConnection extends BaseClient {
 
         this.syncing = false;
 
+        this.connectionCount = 0;
+
         this.state = 'connecting';
     }
 
@@ -203,7 +205,7 @@ class IMAPConnection extends BaseClient {
                 return null;
             }
 
-            const commandCid = `${this.cid}:c`;
+            const commandCid = `${this.cid}:c:${this.connectionCount++}`;
 
             let imapConfig = await this.getImapConfig(accountData);
 
@@ -621,7 +623,7 @@ class IMAPConnection extends BaseClient {
         });
 
         imapClient.on('close', async () => {
-            this.logger.info({ msg: 'Connection closed', type: 'imapClient', account: this.account });
+            this.logger.info({ msg: 'Connection closed', type: 'imapClient', account: this.account, disabled: imapClient.disabled });
 
             try {
                 for (let [, mailbox] of this.mailboxes) {
@@ -662,7 +664,18 @@ class IMAPConnection extends BaseClient {
     }
 
     async reconnect(force) {
+        this.logger.debug({ msg: 'Establishing connection', force });
         if (this.paused || this._connecting || this.isClosing || (this.isClosed && !force)) {
+            this.logger.debug({
+                msg: 'Skipped establishing connection',
+                paused: this.paused,
+                hasClient: !!this.imapClient,
+                usable: this.imapClient?.usable,
+                connecting: this._connecting,
+                closing: this.isClosing,
+                closed: this.isClosed,
+                force
+            });
             return false;
         }
 
@@ -677,31 +690,63 @@ class IMAPConnection extends BaseClient {
         }
 
         try {
+            this.logger.debug({ msg: 'Initiating connection to IMAP' });
             await backOff(() => this.start(), {
                 maxDelay: MAX_BACKOFF_DELAY,
                 numOfAttempts: Infinity,
                 retry: () => !this.isClosing && !this.isClosed,
                 startingDelay: 2000
             });
+            this.logger.debug({
+                msg: 'Connection initiated',
+                hasClient: !!this.imapClient,
+                usable: this.imapClient && this.imapClient.usable,
+                connected: this.isConnected()
+            });
         } finally {
             this._connecting = false;
         }
 
         if (this.paused) {
+            this.logger.debug({ msg: 'Skipped connection setup', reason: 'paused' });
             return;
         }
 
         if (this.state === 'unset') {
+            this.logger.debug({ msg: 'Skipped connection setup', reason: 'unset' });
             return;
         }
 
         try {
             await this.checkIMAPConnection();
+            this.logger.debug({ msg: 'Starting mailbox sync' });
             await this.syncMailboxes();
+            this.logger.debug({ msg: 'Mailboxes synced', usable: this.imapClient?.usable });
+
+            if (this.imapClient?.usable) {
+                // was able to finish syncing, clear the failure flag
+                try {
+                    await this.connection.redis.hdel(this.connection.getAccountKey(), 'syncError');
+                } catch (err) {
+                    // ignore
+                }
+            }
         } catch (err) {
             // ended in an unconncted state
-            this.logger.error({ msg: 'Failed to set up connection', err });
+            this.logger.error({ msg: 'Failed to set up connection, will retry', err });
+            return setTimeout(() => {
+                this.reconnect().catch(err => {
+                    this.logger.error({ msg: 'Gave up setting up a connection', err });
+                });
+            }, 1000);
         }
+
+        this.logger.debug({
+            msg: 'Connection established',
+            hasClient: !!this.imapClient,
+            usable: this.imapClient && this.imapClient.usable,
+            connected: this.isConnected()
+        });
     }
 
     async setStateVal() {
@@ -730,7 +775,8 @@ class IMAPConnection extends BaseClient {
         clearTimeout(this.resyncTimer);
         clearTimeout(this.completedTimer);
 
-        if (!this.imapClient) {
+        if (!this.imapClient || !this.imapClient.usable) {
+            this.logger.debug({ msg: 'Skipped syncing', reason: 'no imap client' });
             return;
         }
 
@@ -741,7 +787,8 @@ class IMAPConnection extends BaseClient {
             }
         }
 
-        if (!this.imapClient) {
+        if (!this.imapClient || !this.imapClient.usable) {
+            this.logger.debug({ msg: 'Syncing completed, skipping state change', reason: 'no imap client' });
             return;
         }
 
@@ -777,21 +824,27 @@ class IMAPConnection extends BaseClient {
             return;
         }
 
+        this.logger.debug({ msg: 'Syncing completed, selecting main path', path: mainPath });
         // start waiting for changes
         await this.select(mainPath);
 
         // schedule next sync
-        clearTimeout(this.resyncTimer);
-        this.resyncTimer = setTimeout(() => {
-            this.syncMailboxes().catch(err => {
-                this.logger.error({ msg: 'Mailbox Sync Error', err });
-            });
-        }, this.resyncDelay);
+        let setSyncTimer = () => {
+            clearTimeout(this.resyncTimer);
+            this.resyncTimer = setTimeout(() => {
+                this.syncMailboxes().catch(err => {
+                    this.logger.error({ msg: 'Mailbox Sync Error', err });
+                    setSyncTimer();
+                });
+            }, this.resyncDelay);
+        };
+        setSyncTimer();
     }
 
     async select(path) {
         if (!this.mailboxes.has(normalizePath(path))) {
             // nothing to do here, mailbox not found
+            this.logger.debug({ msg: 'Can not select unlisted path', path });
             return;
         }
 
@@ -1130,12 +1183,14 @@ class IMAPConnection extends BaseClient {
 
     async start() {
         if (this.paused) {
+            this.logger.debug({ msg: 'Skipped start', reason: 'paused' });
             return;
         }
 
         let initialState = this.state;
 
         if (this.imapClient) {
+            this.logger.debug({ msg: 'Clearing previous connection' });
             this.imapClient.disabled = true;
             try {
                 this.imapClient.removeAllListeners();
@@ -1144,6 +1199,7 @@ class IMAPConnection extends BaseClient {
                 });
                 this.imapClient.close();
                 if (this.connectionClient) {
+                    this.logger.debug({ msg: 'Clearing previous command connection' });
                     this.connectionClient.close();
                 }
             } catch (err) {
@@ -1166,6 +1222,7 @@ class IMAPConnection extends BaseClient {
             }
 
             let imapConfig = await this.getImapConfig(accountData);
+            imapConfig.id = `${imapConfig.id}:m:${this.connectionCount++}`;
 
             this.imapClient = new ImapFlow(
                 Object.assign({}, imapConfig, {

package.json

@@ -46,7 +46,7 @@
         "@hapi/boom": "10.0.1",
         "@hapi/cookie": "12.0.1",
         "@hapi/crumb": "9.0.1",
-        "@hapi/hapi": "21.3.3",
+        "@hapi/hapi": "21.3.6",
         "@hapi/inert": "7.1.0",
         "@hapi/vision": "7.0.3",
         "@phc/pbkdf2": "1.1.14",
@@ -93,7 +93,7 @@
         "murmurhash": "2.0.1",
         "nanoid": "3.3.4",
         "node-gettext": "3.0.0",
-        "nodemailer": "6.9.11",
+        "nodemailer": "6.9.12",
         "pino": "8.19.0",
         "prom-client": "15.1.0",
         "psl": "1.9.0",

static/licenses.html

@@ -1,6 +1,6 @@
 <!doctype html><html><head><meta charset="utf-8"><title>EmailEngine Licenses</title><meta name="viewport" content="width=device-width, initial-scale=1, shrink-to-fit=no"><link rel="stylesheet" href="https://cdn.jsdelivr.net/npm/bootstrap@4.6.1/dist/css/bootstrap.min.css" integrity="sha384-zCbKRCUGaJDkqS1kPbPd7TveP5iyJE0EjAuZQTgFLD2ylzuqKfdKlfG/eSrtxUkn" crossorigin="anonymous"></head><body>
 <div class="container-fluid">
-<h1>EmailEngine v2.40.2</h1><p>EmailEngine includes code from the following software packages:</p>
+<h1>EmailEngine v2.40.3</h1><p>EmailEngine includes code from the following software packages:</p>
 <table class="table table-sm">
 <tr><thead class="thead-dark"><th>Package</th><th>Version</th><th>License</th><th>Publisher</th><th>Publisher's Email</th><th>Package URL</th></tr>
 <tbody>
@@ -426,7 +426,7 @@ <h1>EmailEngine v2.40.2</h1><p>EmailEngine includes code from the following soft
 </tr>
 <tr>
 <td><a href="https://npmjs.com/package/@hapi/hapi">@hapi/hapi</a></td>
-<td>21.3.3</td>
+<td>21.3.6</td>
 <td>BSD-3-Clause</td>
 <td></td>
 <td></td>
@@ -3585,7 +3585,7 @@ <h1>EmailEngine v2.40.2</h1><p>EmailEngine includes code from the following soft
 </tr>
 <tr>
 <td><a href="https://npmjs.com/package/hasown">hasown</a></td>
-<td>2.0.1</td>
+<td>2.0.2</td>
 <td>MIT</td>
 <td>Jordan Harband</td>
 <td>ljharb@gmail.com</td>
@@ -5424,6 +5424,16 @@ <h1>EmailEngine v2.40.2</h1><p>EmailEngine includes code from the following soft
 </td
 </tr>
 <tr>
+<td><a href="https://npmjs.com/package/nodemailer">nodemailer</a></td>
+<td>6.9.12</td>
+<td>MIT-0</td>
+<td>Andris Reinman</td>
+<td></td>
+<td>
+<a href="https://github.com/nodemailer/nodemailer">github.com/nodemailer/nodemailer</a>
+</td
+</tr>
+<tr>
 <td><a href="https://npmjs.com/package/nopt">nopt</a></td>
 <td>3.0.6</td>
 <td>ISC</td>
@@ -6585,7 +6595,7 @@ <h1>EmailEngine v2.40.2</h1><p>EmailEngine includes code from the following soft
 </tr>
 <tr>
 <td><a href="https://npmjs.com/package/set-function-length">set-function-length</a></td>
-<td>1.2.1</td>
+<td>1.2.2</td>
 <td>MIT</td>
 <td>Jordan Harband</td>
 <td>ljharb@gmail.com</td>
@@ -7005,7 +7015,7 @@ <h1>EmailEngine v2.40.2</h1><p>EmailEngine includes code from the following soft
 </tr>
 <tr>
 <td><a href="https://npmjs.com/package/swagger-ui-dist">swagger-ui-dist</a></td>
-<td>5.11.10</td>
+<td>5.12.0</td>
 <td>Apache-2.0</td>
 <td></td>
 <td></td>

translations/messages.pot

@@ -1,18 +1,14 @@
 msgid ""
 msgstr ""
 "Content-Type: text/plain; charset=ascii\n"
-"POT-Creation-Date: 2024-03-08 09:05+0000\n"
+"POT-Creation-Date: 2024-03-14 11:13+0000\n"
 
 #: views/config/license.hbs:48
 msgid "%d day"
 msgid_plural "%d days"
 msgstr[0] ""
 msgstr[1] ""
 
-#: views/redirect.hbs:1
-msgid "Click <a href=\"%s\">here</a> to continue&mldr;"
-msgstr ""
-
 #: views/unsubscribe.hbs:1
 #: views/unsubscribe.hbs:79
 msgid "Unsubscribe"
@@ -57,6 +53,10 @@ msgstr ""
 msgid "Enter your email address"
 msgstr ""
 
+#: views/redirect.hbs:1
+msgid "Click <a href=\"%s\">here</a> to continue&mldr;"
+msgstr ""
+
 #: views/accounts/register/imap.hbs:11
 msgid "Your name"
 msgstr ""
@@ -80,14 +80,6 @@ msgstr ""
 msgid "Continue"
 msgstr ""
 
-#: views/accounts/register/index.hbs:2
-msgid "Choose your email account provider"
-msgstr ""
-
-#: views/accounts/register/index.hbs:15
-msgid "Standard IMAP"
-msgstr ""
-
 #: views/accounts/register/imap-server.hbs:18
 msgid "IMAP"
 msgstr ""
@@ -189,6 +181,14 @@ msgstr ""
 msgid "HTTP error!"
 msgstr ""
 
+#: views/accounts/register/index.hbs:2
+msgid "Choose your email account provider"
+msgstr ""
+
+#: views/accounts/register/index.hbs:15
+msgid "Standard IMAP"
+msgstr ""
+
 #: lib/routes-ui.js:580
 msgid "Invalid API key for OpenAI"
 msgstr ""