From 9790ec575f405820d05dd4777987a88e0a4e819d Mon Sep 17 00:00:00 2001
From: Andris Reinman <andris@reinman.eu>
Date: Tue, 19 Mar 2024 14:13:09 +0200
Subject: [PATCH] fix(locking): log extra information about locks

---
 lib/commands/idle.js |  6 ++---
 lib/imap-flow.js     | 61 +++++++++++++++++++++++++++++++++++---------
 2 files changed, 52 insertions(+), 15 deletions(-)

diff --git a/lib/commands/idle.js b/lib/commands/idle.js
index 4f9fcbd..1a4a19b 100644
--- a/lib/commands/idle.js
+++ b/lib/commands/idle.js
@@ -21,7 +21,7 @@ async function runIdle(connection) {
                     src: 'c',
                     msg: `DONE`,
                     comment: `breaking IDLE`,
-                    lockId: connection.currentLockId,
+                    lockId: connection.currentLock?.lockId,
                     path: connection.mailbox && connection.mailbox.path
                 });
                 connection.write('DONE');
@@ -44,7 +44,7 @@ async function runIdle(connection) {
 
             connection.log.trace({
                 msg: 'Requesting IDLE break',
-                lockId: connection.currentLockId,
+                lockId: connection.currentLock?.lockId,
                 path: connection.mailbox && connection.mailbox.path,
                 queued: preCheckWaitQueue.length,
                 doneRequested,
@@ -74,7 +74,7 @@ async function runIdle(connection) {
         if (typeof connection.preCheck === 'function') {
             connection.log.trace({
                 msg: 'Clearing pre-check function',
-                lockId: connection.currentLockId,
+                lockId: connection.currentLock?.lockId,
                 path: connection.mailbox && connection.mailbox.path,
                 queued: preCheckWaitQueue.length,
                 doneRequested,
diff --git a/lib/imap-flow.js b/lib/imap-flow.js
index ef7ccb2..585b276 100644
--- a/lib/imap-flow.js
+++ b/lib/imap-flow.js
@@ -211,7 +211,7 @@ class ImapFlow extends EventEmitter {
         this.state = this.states.NOT_AUTHENTICATED;
 
         this.lockCounter = 0;
-        this.currentLockId = 0;
+        this.currentLock = false;
 
         this.tagCounter = 0;
         this.requestTagMap = new Map();
@@ -2844,7 +2844,13 @@ class ImapFlow extends EventEmitter {
                 msg: 'Mailbox locking queued',
                 path: this.mailbox && this.mailbox.path,
                 pending: this.locks.length,
-                idling: this.idling
+                idling: this.idling,
+                activeLock: this.currentLock
+                    ? {
+                          lockId: this.currentLock.lockId,
+                          ...(this.currentLock.options?.description && { description: this.currentLock.options?.description })
+                      }
+                    : null
             });
             return;
         }
@@ -2861,20 +2867,21 @@ class ImapFlow extends EventEmitter {
         this.processingLock = true;
 
         const release = () => {
-            if (this.currentLockId) {
+            if (this.currentLock) {
                 this.log.trace({
                     msg: 'Mailbox lock released',
-                    lockId: this.currentLockId,
+                    lockId: this.currentLock.lockId,
                     path: this.mailbox && this.mailbox.path,
                     pending: this.locks.length,
                     idling: this.idling
                 });
-                this.currentLockId = 0;
+                this.currentLock = false;
             }
             this.processLocks(true).catch(err => this.log.error({ err, cid: this.id }));
         };
 
-        const { resolve, reject, path, options, lockId } = this.locks.shift();
+        const lock = this.locks.shift();
+        const { resolve, reject, path, options, lockId } = lock;
 
         if (!this.usable || this.socket.destroyed) {
             this.log.trace({ msg: 'Failed to acquire mailbox lock', path, lockId, idling: this.idling });
@@ -2887,15 +2894,27 @@ class ImapFlow extends EventEmitter {
 
         if (this.mailbox && this.mailbox.path === path && !!this.mailbox.readOnly === !!options.readOnly) {
             // nothing to do here, already selected
-            this.log.trace({ msg: 'Mailbox lock acquired', path, lockId, idling: this.idling });
-            this.currentLockId = lockId;
+            this.log.trace({
+                msg: 'Mailbox lock acquired [existing]',
+                path,
+                lockId,
+                idling: this.idling,
+                ...(options.description && { description: options.description })
+            });
+            this.currentLock = lock;
             return resolve({ path, release });
         } else {
             try {
                 // Try to open. Throws if mailbox does not exists or can't open
                 await this.mailboxOpen(path, options);
-                this.log.trace({ msg: 'Lock acquired', path, lockId, idling: this.idling, ...(options.description && { description: options.description }) });
-                this.currentLockId = lockId;
+                this.log.trace({
+                    msg: 'Mailbox lock acquired [selected]',
+                    path,
+                    lockId,
+                    idling: this.idling,
+                    ...(options.description && { description: options.description })
+                });
+                this.currentLock = lock;
                 return resolve({ path, release });
             } catch (err) {
                 if (err.responseStatus === 'NO') {
@@ -2909,7 +2928,14 @@ class ImapFlow extends EventEmitter {
                     }
                 }
 
-                this.log.trace({ msg: 'Failed to acquire mailbox lock', path, lockId, idling: this.idling });
+                this.log.trace({
+                    msg: 'Failed to acquire mailbox lock',
+                    path,
+                    lockId,
+                    idling: this.idling,
+                    ...(options.description && { description: options.description }),
+                    err
+                });
                 reject(err);
                 await this.processLocks(true);
             }
@@ -2943,7 +2969,18 @@ class ImapFlow extends EventEmitter {
         path = normalizePath(this, path);
 
         let lockId = ++this.lockCounter;
-        this.log.trace({ msg: 'Requesting lock', path, lockId, ...(options.description && { description: options.description }) });
+        this.log.trace({
+            msg: 'Requesting lock',
+            path,
+            lockId,
+            ...(options.description && { description: options.description }),
+            activeLock: this.currentLock
+                ? {
+                      lockId: this.currentLock.lockId,
+                      ...(this.currentLock.options?.description && { description: this.currentLock.options?.description })
+                  }
+                : null
+        });
 
         return await new Promise((resolve, reject) => {
             this.locks.push({ resolve, reject, path, options, lockId });