diff --git a/src/imap.rs b/src/imap.rs index 56cc8953a..f39e01af4 100644 --- a/src/imap.rs +++ b/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 { + 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?; diff --git a/src/imap/idle.rs b/src/imap/idle.rs index 0a5217a61..9c3ed9455 100644 --- a/src/imap/idle.rs +++ b/src/imap/idle.rs @@ -27,6 +27,8 @@ impl Session { idle_interrupt_receiver: Receiver<()>, folder: &str, ) -> Result { + 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` diff --git a/src/imap/select_folder.rs b/src/imap/select_folder.rs index 1be6482e3..49fe1f878 100644 --- a/src/imap/select_folder.rs +++ b/src/imap/select_folder.rs @@ -71,13 +71,18 @@ impl ImapSession { self.select(folder).await }; + let transport_id = self.transport_id(); + // // 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) diff --git a/src/push.rs b/src/push.rs index 5c9933c9b..8c7580c85 100644 --- a/src/push.rs +++ b/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(()) diff --git a/src/quota.rs b/src/quota.rs index ec93f5877..49d72a6d2 100644 --- a/src/quota.rs +++ b/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(()) } diff --git a/src/scheduler.rs b/src/scheduler.rs index 655b657e2..50b130b75 100644 --- a/src/scheduler.rs +++ b/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 { + 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 { + 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); } }