Skip to content

WIP: more delay debugging #8039

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
link2xt wants to merge 2 commits into from
Closed

WIP: more delay debugging #8039

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
84459b6
WIP: more delay debugging
link2xt Mar 25, 2026
8ac9c6b
more debug logging
link2xt Mar 25, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
74 changes: 62 additions & 12 deletions src/imap.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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();
Expand All @@ -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,
Expand Down Expand Up @@ -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<dyn SessionStream> = Box::new(s);
Expand Down Expand Up @@ -436,15 +447,21 @@ 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);
}

Err(err) => {
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:
Expand All @@ -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)
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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!(
Expand Down Expand Up @@ -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(
Expand Down Expand Up @@ -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
Expand All @@ -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(())
}
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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
);
}
}
Expand Down Expand Up @@ -1563,6 +1612,7 @@ impl Session {
create_fallback_ice_servers()
};

info!(context, "Transport {transport_id}: Got IMAP metadata.");
*lock = Some(ServerMetadata {
comment,
admin,
Expand Down
1 change: 1 addition & 0 deletions src/stats.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -554,6 +554,7 @@ async fn get_message_stats(context: &Context) -> Result<BTreeMap<Chattype, Messa
}

pub(crate) async fn update_message_stats(context: &Context) -> Result<()> {
info!(context, "Updating message statistics.");
for chattype in [Chattype::Single, Chattype::Group, Chattype::OutBroadcast] {
update_message_stats_inner(context, chattype).await?;
}
Expand Down
3 changes: 3 additions & 0 deletions src/tools.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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};
Expand Down Expand Up @@ -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");
Expand Down
Loading