diff --git a/src/imap.rs b/src/imap.rs index f39e01af46..4f8b149855 100644 --- a/src/imap.rs +++ b/src/imap.rs @@ -323,7 +323,8 @@ impl Imap { if !ratelimit_duration.is_zero() { warn!( context, - "IMAP got rate limited, waiting for {} until can connect.", + "Transport {}: IMAP got rate limited, waiting for {} until can connect.", + self.transport_id, duration_to_str(ratelimit_duration), ); let interrupted = async { @@ -335,12 +336,16 @@ impl Imap { if interrupted { info!( context, - "Connecting to IMAP without waiting for ratelimit due to interrupt." + "Transport {}: Connecting to IMAP without waiting for ratelimit due to interrupt.", + self.transport_id ); } } - info!(context, "Connecting to IMAP server."); + info!( + context, + "Transport {}: Connecting to IMAP server.", self.transport_id + ); self.connectivity.set_connecting(context); self.conn_last_try = tools::Time::now(); @@ -355,7 +360,10 @@ impl Imap { let login_params = prioritize_server_login_params(&context.sql, &self.lp, "imap").await?; let mut first_error = None; for lp in login_params { - info!(context, "IMAP trying to connect to {}.", &lp.connection); + info!( + context, + "Transport {}: IMAP trying to connect to {}.", self.transport_id, &lp.connection + ); let connection_candidate = lp.connection.clone(); let client = match Client::connect( context, @@ -403,7 +411,10 @@ impl Imap { let resync_request_sender = self.resync_request_sender.clone(); let session = if capabilities.can_compress { - info!(context, "Enabling IMAP compression."); + info!( + context, + "Transport {}: Enabling IMAP compression.", self.transport_id + ); let compressed_session = session .compress(|s| { let session_stream: Box = Box::new(s); @@ -436,7 +447,10 @@ impl Imap { lp.user ))); self.connectivity.set_preparing(context); - info!(context, "Successfully logged into IMAP server."); + info!( + context, + "Transport {}: Successfully logged into IMAP server.", self.transport_id + ); return Ok(session); } @@ -444,7 +458,10 @@ impl Imap { let imap_user = lp.user.to_owned(); let message = stock_str::cannot_login(context, &imap_user); - warn!(context, "IMAP failed to login: {err:#}."); + warn!( + context, + "Transport {}: IMAP failed to login: {err:#}.", self.transport_id + ); first_error.get_or_insert(format_err!("{message} ({err:#})")); // If it looks like the password is wrong, send a notification: @@ -463,7 +480,11 @@ impl Imap { ) .await { - warn!(context, "Failed to add device message: {e:#}."); + warn!( + context, + "Transport {}: Failed to add device message: {e:#}.", + self.transport_id + ); } else { context .set_config_internal(Config::NotifyAboutWrongPw, None) @@ -525,10 +546,21 @@ impl Imap { bail!("IMAP operation attempted while it is torn down"); } + let transport_id = session.transport_id(); + info!( + context, + "Transport {transport_id}: fetch_move_delete start." + ); + let msgs_fetched = self .fetch_new_messages(context, session, watch_folder, folder_meaning) .await .context("fetch_new_messages")?; + + info!( + context, + "Transport {transport_id}: fetch_move_delete finished fetch_new_messages." + ); if msgs_fetched && context.get_config_delete_device_after().await?.is_some() { // New messages were fetched and shall be deleted later, restart ephemeral loop. // Note that the `Config::DeleteDeviceAfter` timer starts as soon as the messages are @@ -567,10 +599,18 @@ impl Imap { return Ok(false); } + info!( + context, + "Transport {transport_id}: fetch_new_messages selects folder {folder:?}." + ); let folder_exists = session .select_with_uidvalidity(context, folder) .await .with_context(|| format!("Failed to select folder {folder:?}"))?; + info!( + context, + "Transport {transport_id}: fetch_new_messages selected folder {folder:?}." + ); if !session.new_mail { info!( @@ -1104,6 +1144,7 @@ impl Session { } let transport_id = self.transport_id(); + info!(context, "Transport {transport_id}: Storing seen flags."); let rows = context .sql .query_map_vec( @@ -1138,13 +1179,15 @@ impl Session { } else if let Err(err) = self.add_flag_finalized_with_set(&uid_set, "\\Seen").await { warn!( context, - "Cannot mark messages {uid_set} in {folder} as seen, will retry later: {err:#}." + "Transport {transport_id}: Cannot mark messages {uid_set} in {folder} as seen, will retry later: {err:#}." ); continue; } else { info!( context, - "Marked messages {} in folder {} as seen.", uid_set, folder + "Transport {transport_id}: Marked messages {} in folder {} as seen.", + uid_set, + folder ); } context @@ -1159,6 +1202,10 @@ impl Session { .await .context("Cannot remove messages marked as seen from imap_markseen table")?; } + info!( + context, + "Transport {transport_id}: Finished storing seen flags." + ); Ok(()) } @@ -1499,9 +1546,10 @@ impl Session { return Ok(()); } + let transport_id = self.transport_id(); info!( context, - "Server supports metadata, retrieving server comment and admin contact." + "Transport {transport_id}: Server supports metadata, retrieving server comment and admin contact." ); let mut comment = None; @@ -1534,7 +1582,8 @@ impl Session { } else { warn!( context, - "Got invalid URL from iroh relay metadata: {:?}.", value + "Transport {transport_id}: Got invalid URL from iroh relay metadata: {:?}.", + value ); } } @@ -1563,6 +1612,7 @@ impl Session { create_fallback_ice_servers() }; + info!(context, "Transport {transport_id}: Got IMAP metadata."); *lock = Some(ServerMetadata { comment, admin, diff --git a/src/stats.rs b/src/stats.rs index c688b33413..11ee491beb 100644 --- a/src/stats.rs +++ b/src/stats.rs @@ -554,6 +554,7 @@ async fn get_message_stats(context: &Context) -> Result Result<()> { + info!(context, "Updating message statistics."); for chattype in [Chattype::Single, Chattype::Group, Chattype::OutBroadcast] { update_message_stats_inner(context, chattype).await?; } diff --git a/src/tools.rs b/src/tools.rs index a7fd5c1fdb..0a7b7ce70c 100644 --- a/src/tools.rs +++ b/src/tools.rs @@ -21,6 +21,7 @@ pub use std::time::SystemTime as Time; #[cfg(not(test))] pub use std::time::SystemTime; +use crate::log::LogExt as _; use anyhow::{Context as _, Result, bail, ensure}; use base64::Engine as _; use chrono::{Local, NaiveDateTime, NaiveTime, TimeZone}; @@ -248,6 +249,8 @@ async fn maybe_warn_on_bad_time(context: &Context, now: i64, known_past_timestam true, ) .await + .context("Failed to add bad time warning") + .log_err(context) .ok(); } else { warn!(context, "Can't convert current timestamp");