feat: improve IMAP loop logs

Only inbox loop is changed because non-inbox loop is going to be removed
together with `mvbox_move`.

Added transport IDs to the log and logging around quota updates.
Removed some logs that add noise,
like logging that IDLE is supported each time right before using it.

src/imap.rs

@@ -296,6 +296,11 @@ impl Imap {
         Ok(imap)
     }
 
+    /// Returns transport ID of the IMAP client.
+    pub fn transport_id(&self) -> u32 {
+        self.transport_id
+    }
+
     /// Connects to IMAP server and returns a new IMAP session.
     ///
     /// Calling this function is not enough to perform IMAP operations. Use [`Imap::prepare`]
@@ -551,8 +556,13 @@ impl Imap {
         folder: &str,
         folder_meaning: FolderMeaning,
     ) -> Result<bool> {
+        let transport_id = session.transport_id();
+
         if should_ignore_folder(context, folder, folder_meaning).await? {
-            info!(context, "Not fetching from {folder:?}.");
+            info!(
+                context,
+                "Transport {transport_id}: Not fetching from {folder:?}."
+            );
             session.new_mail = false;
             return Ok(false);
         }
@@ -563,7 +573,10 @@ impl Imap {
             .with_context(|| format!("Failed to select folder {folder:?}"))?;
 
         if !session.new_mail {
-            info!(context, "No new emails in folder {folder:?}.");
+            info!(
+                context,
+                "Transport {transport_id}: No new emails in folder {folder:?}."
+            );
             return Ok(false);
         }
         // Make sure not to return before setting new_mail to false
@@ -1566,11 +1579,18 @@ impl Session {
             return Ok(());
         }
 
+        let transport_id = self.transport_id();
+
         let Some(device_token) = context.push_subscriber.device_token().await else {
             return Ok(());
         };
 
         if self.can_metadata() && self.can_push() {
+            info!(
+                context,
+                "Transport {transport_id}: Subscribing for push notifications."
+            );
+
             let old_encrypted_device_token =
                 context.get_config(Config::EncryptedDeviceToken).await?;
 

src/imap/idle.rs

@@ -27,6 +27,8 @@ impl Session {
         idle_interrupt_receiver: Receiver<()>,
         folder: &str,
     ) -> Result<Self> {
+        let transport_id = self.transport_id();
+
         self.select_with_uidvalidity(context, folder).await?;
 
         if self.drain_unsolicited_responses(context)? {
@@ -36,13 +38,16 @@ impl Session {
         if self.new_mail {
             info!(
                 context,
-                "Skipping IDLE in {folder:?} because there may be new mail."
+                "Transport {transport_id}: Skipping IDLE in {folder:?} because there may be new mail."
             );
             return Ok(self);
         }
 
         if let Ok(()) = idle_interrupt_receiver.try_recv() {
-            info!(context, "Skip IDLE in {folder:?} because we got interrupt.");
+            info!(
+                context,
+                "Transport {transport_id}: Skip IDLE in {folder:?} because we got interrupt."
+            );
             return Ok(self);
         }
 
@@ -61,7 +66,7 @@ impl Session {
 
         info!(
             context,
-            "IDLE entering wait-on-remote state in folder {folder:?}."
+            "Transport {transport_id}: IDLE entering wait-on-remote state in folder {folder:?}."
         );
 
         // Spawn a task to relay interrupts from `idle_interrupt_receiver`

src/imap/select_folder.rs

@@ -71,13 +71,18 @@ impl ImapSession {
             self.select(folder).await
         };
 
+        let transport_id = self.transport_id();
+
         // <https://tools.ietf.org/html/rfc3501#section-6.3.1>
         // says that if the server reports select failure we are in
         // authenticated (not-select) state.
 
         match res {
             Ok(mailbox) => {
-                info!(context, "Selected folder {folder:?}.");
+                info!(
+                    context,
+                    "Transport {transport_id}: Selected folder {folder:?}."
+                );
                 self.selected_folder = Some(folder.to_string());
                 self.selected_mailbox = Some(mailbox);
                 Ok(NewlySelected::Yes)

src/push.rs

@@ -136,6 +136,7 @@ impl PushSubscriber {
             return Ok(());
         };
 
+        info!(context, "Subscribing for heartbeat notifications.");
         if http::post_string(
             context,
             "https://notifications.delta.chat/register",
@@ -143,6 +144,7 @@ impl PushSubscriber {
         )
         .await?
         {
+            info!(context, "Subscribed for heartbeat notifications.");
             state.heartbeat_subscribed = true;
         }
         Ok(())

src/quota.rs

@@ -123,6 +123,10 @@ impl Context {
     /// in case for some providers the quota is always at ~100%
     /// and new space is allocated as needed.
     pub(crate) async fn update_recent_quota(&self, session: &mut ImapSession) -> Result<()> {
+        let transport_id = session.transport_id();
+
+        info!(self, "Transport {transport_id}: Updating quota.");
+
         let quota = if session.can_check_quota() {
             let folders = get_watched_folders(self).await?;
             get_unique_quota_roots_and_usage(session, folders).await
@@ -149,18 +153,22 @@ impl Context {
                             .await?;
                     }
                 }
-                Err(err) => warn!(self, "cannot get highest quota usage: {:#}", err),
+                Err(err) => warn!(
+                    self,
+                    "Transport {transport_id}: Cannot get highest quota usage: {err:#}"
+                ),
             }
         }
 
         self.quota.write().await.insert(
-            session.transport_id(),
+            transport_id,
             QuotaInfo {
                 recent: quota,
                 modified: tools::Time::now(),
             },
         );
 
+        info!(self, "Transport {transport_id}: Updated quota.");
         self.emit_event(EventType::ConnectivityChanged);
         Ok(())
     }

src/scheduler.rs

@@ -355,6 +355,7 @@ async fn inbox_loop(
         stop_token,
     } = inbox_handlers;
 
+    let transport_id = connection.transport_id();
     let ctx1 = ctx.clone();
     let fut = async move {
         let ctx = ctx1;
@@ -368,23 +369,34 @@ async fn inbox_loop(
             let session = if let Some(session) = old_session.take() {
                 session
             } else {
-                info!(ctx, "Preparing new IMAP session for inbox.");
+                info!(
+                    ctx,
+                    "Transport {transport_id}: Preparing new IMAP session for inbox."
+                );
                 match connection.prepare(&ctx).await {
                     Err(err) => {
-                        warn!(ctx, "Failed to prepare inbox connection: {err:#}.");
+                        warn!(
+                            ctx,
+                            "Transport {transport_id}: Failed to prepare inbox connection: {err:#}."
+                        );
                         continue;
                     }
-                    Ok(session) => session,
+                    Ok(session) => {
+                        info!(
+                            ctx,
+                            "Transport {transport_id}: Prepared new IMAP session for inbox."
+                        );
+                        session
+                    }
                 }
             };
 
             match inbox_fetch_idle(&ctx, &mut connection, session).await {
-                Err(err) => warn!(ctx, "Failed inbox fetch_idle: {err:#}."),
+                Err(err) => warn!(
+                    ctx,
+                    "Transport {transport_id}: Failed inbox fetch_idle: {err:#}."
+                ),
                 Ok(session) => {
-                    info!(
-                        ctx,
-                        "IMAP loop iteration for inbox finished, keeping the session."
-                    );
                     old_session = Some(session);
                 }
             }
@@ -394,7 +406,7 @@ async fn inbox_loop(
     stop_token
         .cancelled()
         .map(|_| {
-            info!(ctx, "Shutting down inbox loop.");
+            info!(ctx, "Transport {transport_id}: Shutting down inbox loop.");
         })
         .race(fut)
         .await;
@@ -431,17 +443,25 @@ pub async fn convert_folder_meaning(
 }
 
 async fn inbox_fetch_idle(ctx: &Context, imap: &mut Imap, mut session: Session) -> Result<Session> {
+    let transport_id = session.transport_id();
+
     // Update quota no more than once a minute.
     if ctx.quota_needs_update(session.transport_id(), 60).await
         && let Err(err) = ctx.update_recent_quota(&mut session).await
     {
-        warn!(ctx, "Failed to update quota: {:#}.", err);
+        warn!(
+            ctx,
+            "Transport {transport_id}: Failed to update quota: {err:#}."
+        );
     }
 
     if let Ok(()) = imap.resync_request_receiver.try_recv()
         && let Err(err) = session.resync_folders(ctx).await
     {
-        warn!(ctx, "Failed to resync folders: {:#}.", err);
+        warn!(
+            ctx,
+            "Transport {transport_id}: Failed to resync folders: {err:#}."
+        );
         imap.resync_request_sender.try_send(()).ok();
     }
 
@@ -456,7 +476,10 @@ async fn inbox_fetch_idle(ctx: &Context, imap: &mut Imap, mut session: Session)
             }
         }
         Err(err) => {
-            warn!(ctx, "Failed to get last housekeeping time: {}", err);
+            warn!(
+                ctx,
+                "Transport {transport_id}: Failed to get last housekeeping time: {err:#}"
+            );
         }
     };
 
@@ -486,6 +509,8 @@ async fn fetch_idle(
     mut session: Session,
     folder_meaning: FolderMeaning,
 ) -> Result<Session> {
+    let transport_id = session.transport_id();
+
     let Some((folder_config, watch_folder)) = convert_folder_meaning(ctx, folder_meaning).await?
     else {
         // The folder is not configured.
@@ -537,7 +562,7 @@ async fn fetch_idle(
     if !session.can_idle() {
         info!(
             ctx,
-            "IMAP session does not support IDLE, going to fake idle."
+            "Transport {transport_id}: IMAP session does not support IDLE, going to fake idle."
         );
         connection.fake_idle(ctx, watch_folder).await?;
         return Ok(session);
@@ -550,15 +575,14 @@ async fn fetch_idle(
         .log_err(ctx)
         .unwrap_or_default()
     {
-        info!(ctx, "IMAP IDLE is disabled, going to fake idle.");
+        info!(
+            ctx,
+            "Transport {transport_id}: IMAP IDLE is disabled, going to fake idle."
+        );
         connection.fake_idle(ctx, watch_folder).await?;
         return Ok(session);
     }
 
-    info!(
-        ctx,
-        "IMAP session in folder {watch_folder:?} supports IDLE, using it."
-    );
     let session = session
         .idle(
             ctx,
@@ -619,10 +643,6 @@ async fn simple_imap_loop(
             match fetch_idle(&ctx, &mut connection, session, folder_meaning).await {
                 Err(err) => warn!(ctx, "Failed fetch_idle: {err:#}"),
                 Ok(session) => {
-                    info!(
-                        ctx,
-                        "IMAP loop iteration for {folder_meaning} finished, keeping the session"
-                    );
                     old_session = Some(session);
                 }
             }