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 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); diff --git a/src/imap/idle.rs b/src/imap/idle.rs index 04e971879..f6af1cded 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,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? - .context("IMAP IDLE protocol timed out")?; + .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"); @@ -173,6 +183,7 @@ impl Imap { } Event::Interrupt(info) => { // Interrupt + info!(context, "Fake IDLE interrupted"); break info; } } diff --git a/src/imap/select_folder.rs b/src/imap/select_folder.rs index 70c77ca1e..1458f59cc 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(format!("{:#}", err)) + } +} + 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?; } diff --git a/src/scheduler.rs b/src/scheduler.rs index ed8565bfd..32f19cf70 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -166,112 +166,117 @@ 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 + .context("fetch_move_delete") + { + 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") + { + 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.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); + } + 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 + .context("fetch_move_delete after scan_folders") + { + 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) } } } @@ -280,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, @@ -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; } };