From 43f2d64a6f840bbb180e46326e0fed0bd789c010 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 16:10:06 +0000 Subject: [PATCH 01/12] imap: flatten fetch_idle() --- src/scheduler.rs | 207 ++++++++++++++++++++++++----------------------- 1 file changed, 105 insertions(+), 102 deletions(-) diff --git a/src/scheduler.rs b/src/scheduler.rs index ed8565bfd..1dddbb7dc 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -166,112 +166,115 @@ async fn inbox_loop(ctx: Context, started: Sender<()>, inbox_handlers: ImapConne .await; } -async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder: Config) -> InterruptInfo { - match ctx.get_config(folder).await { - Ok(Some(watch_folder)) => { - // 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 let Err(err) = connection - .store_seen_flags_on_imap(ctx) - .await - .context("store_seen_flags_on_imap failed") - { - warn!(ctx, "{:#}", err); - } - } - - // Fetch the watched folder. - if let Err(err) = connection - .fetch_move_delete(ctx, &watch_folder, false) - .await - { - connection.trigger_reconnect(ctx).await; - warn!(ctx, "{:#}", err); - return InterruptInfo::new(false); - } - - // Mark expired messages for deletion. Marked messages will be deleted from the server - // on the next iteration of `fetch_move_delete`. `delete_expired_imap_messages` is not - // called right before `fetch_move_delete` because it is not well optimized and would - // otherwise slow down message fetching. - if let Err(err) = delete_expired_imap_messages(ctx) - .await - .context("delete_expired_imap_messages failed") - { - warn!(ctx, "{:#}", err); - } - - // Scan additional folders only after finishing fetching the watched folder. - // - // 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 { - // Only scan on the Inbox thread in order to prevent parallel scans, which might lead to duplicate messages - match connection.scan_folders(ctx).await { - 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); - } - Ok(true) => { - // Fetch the watched folder again in case scanning other folder moved messages - // there. - // - // In most cases this will select the watched folder and return because there are - // no new messages. We want to select the watched folder anyway before going IDLE - // there, so this does not take additional protocol round-trip. - if let Err(err) = connection - .fetch_move_delete(ctx, &watch_folder, false) - .await - { - connection.trigger_reconnect(ctx).await; - warn!(ctx, "{:#}", err); - return InterruptInfo::new(false); - } - } - Ok(false) => {} - } - } - - // Synchronize Seen flags. - connection - .sync_seen_flags(ctx, &watch_folder) - .await - .context("sync_seen_flags") - .ok_or_log(ctx); - - connection.connectivity.set_connected(ctx).await; - - // idle - if connection.can_idle() { - match connection.idle(ctx, Some(watch_folder)).await { - Ok(v) => v, - Err(err) => { - connection.trigger_reconnect(ctx).await; - 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 - } +async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) -> InterruptInfo { + let folder = match ctx.get_config(folder_config).await { + Ok(folder) => folder, Err(err) => { warn!( ctx, - "Can not watch {} folder, failed to retrieve config: {:?}", folder, err + "Can not watch {} folder, failed to retrieve config: {:#}", folder_config, err ); - connection.fake_idle(ctx, None).await + 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 == Config::ConfiguredInboxFolder { + if let Err(err) = connection + .store_seen_flags_on_imap(ctx) + .await + .context("store_seen_flags_on_imap failed") + { + warn!(ctx, "{:#}", err); + } + } + + // Fetch the watched folder. + if let Err(err) = connection + .fetch_move_delete(ctx, &watch_folder, false) + .await + { + connection.trigger_reconnect(ctx).await; + warn!(ctx, "{:#}", err); + return InterruptInfo::new(false); + } + + // Mark expired messages for deletion. Marked messages will be deleted from the server + // on the next iteration of `fetch_move_delete`. `delete_expired_imap_messages` is not + // called right before `fetch_move_delete` because it is not well optimized and would + // otherwise slow down message fetching. + if let Err(err) = delete_expired_imap_messages(ctx) + .await + .context("delete_expired_imap_messages failed") + { + warn!(ctx, "{:#}", err); + } + + // Scan additional folders only after finishing fetching the watched folder. + // + // 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 == 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 { + 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); + } + Ok(true) => { + // Fetch the watched folder again in case scanning other folder moved messages + // there. + // + // In most cases this will select the watched folder and return because there are + // no new messages. We want to select the watched folder anyway before going IDLE + // there, so this does not take additional protocol round-trip. + if let Err(err) = connection + .fetch_move_delete(ctx, &watch_folder, false) + .await + { + connection.trigger_reconnect(ctx).await; + warn!(ctx, "{:#}", err); + return InterruptInfo::new(false); + } + } + Ok(false) => {} + } + } + + // Synchronize Seen flags. + connection + .sync_seen_flags(ctx, &watch_folder) + .await + .context("sync_seen_flags") + .ok_or_log(ctx); + + connection.connectivity.set_connected(ctx).await; + + // 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); + InterruptInfo::new(false) } } } From 33839b5667c9be25654e669b33329b44973cd362 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 16:10:24 +0000 Subject: [PATCH 02/12] imap: log disconnection attempts --- src/imap.rs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/imap.rs b/src/imap.rs index ba1fb96e3..f643a2b6a 100644 --- a/src/imap.rs +++ b/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); From 4744f5eecfbc8e1447d58117e52c62b66cd02720 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 16:08:50 +0000 Subject: [PATCH 03/12] Add folder name to IMAP IDLE interrupt logs --- src/imap/idle.rs | 25 +++++++++++++++++-------- 1 file changed, 17 insertions(+), 8 deletions(-) diff --git a/src/imap/idle.rs b/src/imap/idle.rs index 04e971879..3fdff1cbb 100644 --- a/src/imap/idle.rs +++ b/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", - watch_folder.as_deref().unwrap_or("None") + "{}: Idle entering wait-on-remote state", folder_name ); let fut = idle_wait.map(|ev| ev.map(Event::IdleResponse)).race(async { let info = self.idle_interrupt.recv().await; @@ -70,26 +70,35 @@ 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? - .context("IMAP IDLE protocol timed out")?; + .with_context(|| format!("{}: IMAP IDLE protocol timed out", folder_name))?; self.session = Some(Session { inner: session }); } else { warn!(context, "Attempted to idle without a session"); From 516a5e9c5f20f7180f027f73f875e5813465813a Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:21:36 +0000 Subject: [PATCH 04/12] Add contexts to both the timeout and actual IDLE error Note that `IMAP IDLE protocol timed out` was previously added to the wrong error: not the timeout error (first `?`) but actual error happened during IDLE, such as a network error. --- src/imap/idle.rs | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/src/imap/idle.rs b/src/imap/idle.rs index 3fdff1cbb..9a62b9943 100644 --- a/src/imap/idle.rs +++ b/src/imap/idle.rs @@ -97,8 +97,9 @@ impl Imap { } let session = tokio::time::timeout(Duration::from_secs(15), handle.done()) - .await? - .with_context(|| format!("{}: IMAP IDLE protocol timed out", folder_name))?; + .await + .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"); From 9a447e8554023a261b0a59d3470bee3820d832da Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:28:37 +0000 Subject: [PATCH 05/12] Log IDLE errors with all contexts --- src/scheduler.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/scheduler.rs b/src/scheduler.rs index 1dddbb7dc..b176fa771 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -273,7 +273,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) Ok(v) => v, Err(err) => { connection.trigger_reconnect(ctx).await; - warn!(ctx, "{}", err); + warn!(ctx, "{:#}", err); InterruptInfo::new(false) } } From e1d50757b3881c08b2035ca018e665b4aa451247 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:29:18 +0000 Subject: [PATCH 06/12] Better format for `scan_folders` errors --- src/scheduler.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/scheduler.rs b/src/scheduler.rs index b176fa771..773b7a796 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -233,7 +233,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) 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 From 4ee14e6e77be219672478c6196db5ee669d65866 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:29:47 +0000 Subject: [PATCH 07/12] Add more contexts to IMAP errors --- src/scheduler.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/scheduler.rs b/src/scheduler.rs index 773b7a796..cc41dd851 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -206,6 +206,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) 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); @@ -218,7 +219,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) // 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); } @@ -229,7 +230,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) // be able to scan all folders before time is up if there are many of them. 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 @@ -245,6 +246,7 @@ async fn fetch_idle(ctx: &Context, connection: &mut Imap, folder_config: Config) 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); From 1324b5da134e062886a6609b1d0f2207f724771e Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:30:04 +0000 Subject: [PATCH 08/12] Rename `folder` argument into `folder_config` --- src/scheduler.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/scheduler.rs b/src/scheduler.rs index cc41dd851..32f19cf70 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -285,11 +285,11 @@ 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, @@ -305,7 +305,7 @@ async fn simple_imap_loop( } loop { - fetch_idle(&ctx, &mut connection, folder).await; + fetch_idle(&ctx, &mut connection, folder_config).await; } }; From 7db147da1415073e2ff73d29e87e1454a5d2af03 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:30:17 +0000 Subject: [PATCH 09/12] Log fake IDLE interruptions --- src/imap/idle.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/imap/idle.rs b/src/imap/idle.rs index 9a62b9943..f6af1cded 100644 --- a/src/imap/idle.rs +++ b/src/imap/idle.rs @@ -183,6 +183,7 @@ impl Imap { } Event::Interrupt(info) => { // Interrupt + info!(context, "Fake IDLE interrupted"); break info; } } From 09042d12d45a6883a832b8ca7b68261923eec374 Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 20:32:16 +0000 Subject: [PATCH 10/12] Changelog --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 624588375..791e92c89 100644 --- a/CHANGELOG.md +++ b/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 From c0ae5c0fb7fe31436202ef85154c06ef74fa41cd Mon Sep 17 00:00:00 2001 From: link2xt Date: Sun, 13 Nov 2022 23:49:34 +0000 Subject: [PATCH 11/12] Use anyhow for close_folder() errors --- src/imap/select_folder.rs | 30 +++++++++++++----------------- 1 file changed, 13 insertions(+), 17 deletions(-) diff --git a/src/imap/select_folder.rs b/src/imap/select_folder.rs index 70c77ca1e..76edd0e2c 100644 --- a/src/imap/select_folder.rs +++ b/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 for Error { + fn from(err: anyhow::Error) -> Error { + Error::Other(err.to_string()) + } +} + impl Imap { /// Issues a CLOSE command to expunge selected folder. /// /// CLOSE is considerably faster than an EXPUNGE, see /// - 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 { - match session.close().await { - Ok(_) => { - info!(context, "close/expunge succeeded"); - } - Err(err) => { - self.trigger_reconnect(context).await; - return Err(Error::CloseExpungeFailed(err)); - } - } - } else { - return Err(Error::NoSession); + let session = self.session.as_mut().context("no session")?; + if let Err(err) = session.close().await.context("IMAP close/expunge failed") { + self.trigger_reconnect(context).await; + return Err(err); } + 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?; } From 7d45419724a2480a799448b7e912c3ea3a60fabb Mon Sep 17 00:00:00 2001 From: link2xt Date: Mon, 14 Nov 2022 11:40:40 +0000 Subject: [PATCH 12/12] Convert anyhow errors to select_folder errors with alternate fmt --- src/imap/select_folder.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/imap/select_folder.rs b/src/imap/select_folder.rs index 76edd0e2c..1458f59cc 100644 --- a/src/imap/select_folder.rs +++ b/src/imap/select_folder.rs @@ -25,7 +25,7 @@ pub enum Error { impl From for Error { fn from(err: anyhow::Error) -> Error { - Error::Other(err.to_string()) + Error::Other(format!("{:#}", err)) } }