Improve IMAP logging

https://github.com/deltachat/deltachat-core-rust/pull/3749

CHANGELOG.md

@@ -8,6 +8,8 @@
 - add `configured_inbox_folder` to account info #3748
 
 ### Fixes
+- improve IMAP logging, in particular fix incorrect "IMAP IDLE protocol
+  timed out" message on network error during IDLE #3749
 
 
 ## 1.100.0

src/imap.rs

@@ -494,6 +494,8 @@ impl Imap {
     }
 
     async fn disconnect(&mut self, context: &Context) {
+        info!(context, "disconnecting");
+
         // Close folder if messages should be expunged
         if let Err(err) = self.close_folder(context).await {
             warn!(context, "failed to close folder: {:?}", err);

src/imap/idle.rs

@@ -54,10 +54,10 @@ impl Imap {
                 Interrupt(InterruptInfo),
             }
 
+            let folder_name = watch_folder.as_deref().unwrap_or("None");
             info!(
                 context,
-                "{}: Idle entering wait-on-remote state",
+                "{}: Idle entering wait-on-remote state", folder_name
-                watch_folder.as_deref().unwrap_or("None")
             );
             let fut = idle_wait.map(|ev| ev.map(Event::IdleResponse)).race(async {
                 let info = self.idle_interrupt.recv().await;
@@ -70,26 +70,36 @@ impl Imap {
 
             match fut.await {
                 Ok(Event::IdleResponse(IdleResponse::NewData(x))) => {
-                    info!(context, "Idle has NewData {:?}", x);
+                    info!(context, "{}: Idle has NewData {:?}", folder_name, x);
                 }
                 Ok(Event::IdleResponse(IdleResponse::Timeout)) => {
-                    info!(context, "Idle-wait timeout or interruption");
+                    info!(
+                        context,
+                        "{}: Idle-wait timeout or interruption", folder_name
+                    );
                 }
                 Ok(Event::IdleResponse(IdleResponse::ManualInterrupt)) => {
-                    info!(context, "Idle wait was interrupted");
+                    info!(
+                        context,
+                        "{}: Idle wait was interrupted manually", folder_name
+                    );
                 }
                 Ok(Event::Interrupt(i)) => {
+                    info!(
+                        context,
+                        "{}: Idle wait was interrupted: {:?}", folder_name, &i
+                    );
                     info = i;
-                    info!(context, "Idle wait was interrupted");
                 }
                 Err(err) => {
-                    warn!(context, "Idle wait errored: {:?}", err);
+                    warn!(context, "{}: Idle wait errored: {:?}", folder_name, err);
                 }
             }
 
             let session = tokio::time::timeout(Duration::from_secs(15), handle.done())
-                .await?
+                .await
-                .context("IMAP IDLE protocol timed out")?;
+                .with_context(|| format!("{}: IMAP IDLE protocol timed out", folder_name))?
+                .with_context(|| format!("{}: IMAP IDLE failed", folder_name))?;
             self.session = Some(Session { inner: session });
         } else {
             warn!(context, "Attempted to idle without a session");
@@ -173,6 +183,7 @@ impl Imap {
                 }
                 Event::Interrupt(info) => {
                     // Interrupt
+                    info!(context, "Fake IDLE interrupted");
                     break info;
                 }
             }

src/imap/select_folder.rs

@@ -19,35 +19,31 @@ pub enum Error {
     #[error("Got a NO response when trying to select {0}, usually this means that it doesn't exist: {1}")]
     NoFolder(String, String),
 
-    #[error("IMAP close/expunge failed")]
-    CloseExpungeFailed(#[from] async_imap::error::Error),
-
     #[error("IMAP other error: {0}")]
     Other(String),
 }
 
+impl From<anyhow::Error> for Error {
+    fn from(err: anyhow::Error) -> Error {
+        Error::Other(format!("{:#}", err))
+    }
+}
+
 impl Imap {
     /// Issues a CLOSE command to expunge selected folder.
     ///
     /// CLOSE is considerably faster than an EXPUNGE, see
     /// <https://tools.ietf.org/html/rfc3501#section-6.4.2>
-    pub(super) async fn close_folder(&mut self, context: &Context) -> Result<()> {
+    pub(super) async fn close_folder(&mut self, context: &Context) -> anyhow::Result<()> {
         if let Some(ref folder) = self.config.selected_folder {
             info!(context, "Expunge messages in \"{}\".", folder);
 
-            if let Some(ref mut session) = self.session {
+            let session = self.session.as_mut().context("no session")?;
-                match session.close().await {
+            if let Err(err) = session.close().await.context("IMAP close/expunge failed") {
-                    Ok(_) => {
-                        info!(context, "close/expunge succeeded");
-                    }
-                    Err(err) => {
                 self.trigger_reconnect(context).await;
-                        return Err(Error::CloseExpungeFailed(err));
+                return Err(err);
-                    }
-                }
-            } else {
-                return Err(Error::NoSession);
             }
+            info!(context, "close/expunge succeeded");
         }
         self.config.selected_folder = None;
         self.config.selected_folder_needs_expunge = false;
@@ -56,7 +52,7 @@ impl Imap {
     }
 
     /// Issues a CLOSE command if selected folder needs expunge.
-    pub(crate) async fn maybe_close_folder(&mut self, context: &Context) -> Result<()> {
+    pub(crate) async fn maybe_close_folder(&mut self, context: &Context) -> anyhow::Result<()> {
         if self.config.selected_folder_needs_expunge {
             self.close_folder(context).await?;
         }

src/scheduler.rs

@@ -166,16 +166,33 @@ async fn inbox_loop(ctx: Context, started: Sender<()>, inbox_handlers: ImapConne
         .await;
 }
 
-async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> InterruptInfo {
+async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) -> InterruptInfo {
-    match ctx.get_config(folder).await {
+    let folder = match ctx.get_config(folder_config).await {
-        Ok(Some(watch_folder)) => {
+        Ok(folder) => folder,
+        Err(err) => {
+            warn!(
+                ctx,
+                "Can not watch {} folder, failed to retrieve config: {:#}", folder_config, err
+            );
+            return connection.fake_idle(ctx, None).await;
+        }
+    };
+
+    let watch_folder = if let Some(watch_folder) = folder {
+        watch_folder
+    } else {
+        connection.connectivity.set_not_configured(ctx).await;
+        info!(ctx, "Can not watch {} folder, not set", folder_config);
+        return connection.fake_idle(ctx, None).await;
+    };
+
     // connect and fake idle if unable to connect
     if let Err(err) = connection.prepare(ctx).await {
         warn!(ctx, "imap connection failed: {}", err);
         return connection.fake_idle(ctx, Some(watch_folder)).await;
     }
 
-            if folder == Config::ConfiguredInboxFolder {
+    if folder_config == Config::ConfiguredInboxFolder {
         if let Err(err) = connection
             .store_seen_flags_on_imap(ctx)
             .await
@@ -189,6 +206,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> Int
     if let Err(err) = connection
         .fetch_move_delete(ctx, &watch_folder, false)
         .await
+        .context("fetch_move_delete")
     {
         connection.trigger_reconnect(ctx).await;
         warn!(ctx, "{:#}", err);
@@ -201,7 +219,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> Int
     // otherwise slow down message fetching.
     if let Err(err) = delete_expired_imap_messages(ctx)
         .await
-                .context("delete_expired_imap_messages failed")
+        .context("delete_expired_imap_messages")
     {
         warn!(ctx, "{:#}", err);
     }
@@ -210,13 +228,13 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> Int
     //
     // On iOS the application has strictly limited time to work in background, so we may not
     // be able to scan all folders before time is up if there are many of them.
-            if folder == Config::ConfiguredInboxFolder {
+    if folder_config == Config::ConfiguredInboxFolder {
         // Only scan on the Inbox thread in order to prevent parallel scans, which might lead to duplicate messages
-                match connection.scan_folders(ctx).await {
+        match connection.scan_folders(ctx).await.context("scan_folders") {
             Err(err) => {
                 // Don't reconnect, if there is a problem with the connection we will realize this when IDLEing
                 // but maybe just one folder can't be selected or something
-                        warn!(ctx, "{}", err);
+                warn!(ctx, "{:#}", err);
             }
             Ok(true) => {
                 // Fetch the watched folder again in case scanning other folder moved messages
@@ -228,6 +246,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> Int
                 if let Err(err) = connection
                     .fetch_move_delete(ctx, &watch_folder, false)
                     .await
+                    .context("fetch_move_delete after scan_folders")
                 {
                     connection.trigger_reconnect(ctx).await;
                     warn!(ctx, "{:#}", err);
@@ -248,43 +267,29 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> Int
     connection.connectivity.set_connected(ctx).await;
 
     // idle
-            if connection.can_idle() {
+    if !connection.can_idle() {
+        return connection.fake_idle(ctx, Some(watch_folder)).await;
+    }
+
     match connection.idle(ctx, Some(watch_folder)).await {
         Ok(v) => v,
         Err(err) => {
             connection.trigger_reconnect(ctx).await;
-                        warn!(ctx, "{}", err);
+            warn!(ctx, "{:#}", err);
             InterruptInfo::new(false)
         }
     }
-            } else {
-                connection.fake_idle(ctx, Some(watch_folder)).await
-            }
-        }
-        Ok(None) => {
-            connection.connectivity.set_not_configured(ctx).await;
-            info!(ctx, "Can not watch {} folder, not set", folder);
-            connection.fake_idle(ctx, None).await
-        }
-        Err(err) => {
-            warn!(
-                ctx,
-                "Can not watch {} folder, failed to retrieve config: {:?}", folder, err
-            );
-            connection.fake_idle(ctx, None).await
-        }
-    }
 }
 
 async fn simple_imap_loop(
     ctx: Context,
     started: Sender<()>,
     inbox_handlers: ImapConnectionHandlers,
-    folder: Config,
+    folder_config: Config,
 ) {
     use futures::future::FutureExt;
 
-    info!(ctx, "starting simple loop for {}", folder.as_ref());
+    info!(ctx, "starting simple loop for {}", folder_config);
     let ImapConnectionHandlers {
         mut connection,
         stop_receiver,
@@ -300,7 +305,7 @@ async fn simple_imap_loop(
         }
 
         loop {
-            fetch_idle(&ctx, &mut connection, folder).await;
+            fetch_idle(&ctx, &mut connection, folder_config).await;
         }
     };