feat: add more IMAP logging

E.g. log when the folder is selected.
This commit is contained in:
link2xt
2025-05-18 23:02:49 +00:00
committed by l
parent 53fa0147ae
commit 877f873910
4 changed files with 35 additions and 21 deletions

View File

@@ -1617,7 +1617,7 @@ def test_immediate_autodelete(acfactory, lp):
lp.sec("ac2: wait for close/expunge on autodelete") lp.sec("ac2: wait for close/expunge on autodelete")
ac2._evtracker.get_matching("DC_EVENT_IMAP_MESSAGE_DELETED") ac2._evtracker.get_matching("DC_EVENT_IMAP_MESSAGE_DELETED")
ac2._evtracker.get_info_contains("close/expunge succeeded") ac2._evtracker.get_info_contains("Close/expunge succeeded.")
lp.sec("ac2: check that message was autodeleted on server") lp.sec("ac2: check that message was autodeleted on server")
assert len(ac2.direct_imap.get_all_messages()) == 0 assert len(ac2.direct_imap.get_all_messages()) == 0
@@ -1653,7 +1653,7 @@ def test_delete_multiple_messages(acfactory, lp):
lp.sec("ac2: test that only one message is left") lp.sec("ac2: test that only one message is left")
while 1: while 1:
ac2._evtracker.get_matching("DC_EVENT_IMAP_MESSAGE_DELETED") ac2._evtracker.get_matching("DC_EVENT_IMAP_MESSAGE_DELETED")
ac2._evtracker.get_info_contains("close/expunge succeeded") ac2._evtracker.get_info_contains("Close/expunge succeeded.")
ac2.direct_imap.select_config_folder("inbox") ac2.direct_imap.select_config_folder("inbox")
nr_msgs = len(ac2.direct_imap.get_all_messages()) nr_msgs = len(ac2.direct_imap.get_all_messages())
assert nr_msgs > 0 assert nr_msgs > 0

View File

@@ -324,7 +324,7 @@ impl Imap {
} }
} }
info!(context, "Connecting to IMAP server"); info!(context, "Connecting to IMAP server.");
self.connectivity.set_connecting(context).await; self.connectivity.set_connecting(context).await;
self.conn_last_try = tools::Time::now(); self.conn_last_try = tools::Time::now();
@@ -409,7 +409,7 @@ impl Imap {
lp.user lp.user
))); )));
self.connectivity.set_preparing(context).await; self.connectivity.set_preparing(context).await;
info!(context, "Successfully logged into IMAP server"); info!(context, "Successfully logged into IMAP server.");
return Ok(session); return Ok(session);
} }
@@ -1046,7 +1046,7 @@ impl Session {
// Expunge folder if needed, e.g. if some jobs have // Expunge folder if needed, e.g. if some jobs have
// deleted messages on the server. // deleted messages on the server.
if let Err(err) = self.maybe_close_folder(context).await { if let Err(err) = self.maybe_close_folder(context).await {
warn!(context, "failed to close folder: {:?}", err); warn!(context, "Failed to close folder: {err:#}.");
} }
Ok(()) Ok(())

View File

@@ -33,10 +33,10 @@ impl ImapSession {
pub(super) async fn maybe_close_folder(&mut self, context: &Context) -> anyhow::Result<()> { pub(super) async fn maybe_close_folder(&mut self, context: &Context) -> anyhow::Result<()> {
if let Some(folder) = &self.selected_folder { if let Some(folder) = &self.selected_folder {
if self.selected_folder_needs_expunge { if self.selected_folder_needs_expunge {
info!(context, "Expunge messages in \"{}\".", folder); info!(context, "Expunge messages in {folder:?}.");
self.close().await.context("IMAP close/expunge failed")?; self.close().await.context("IMAP close/expunge failed")?;
info!(context, "close/expunge succeeded"); info!(context, "Close/expunge succeeded.");
self.selected_folder = None; self.selected_folder = None;
self.selected_folder_needs_expunge = false; self.selected_folder_needs_expunge = false;
self.new_mail = false; self.new_mail = false;
@@ -73,6 +73,7 @@ impl ImapSession {
match res { match res {
Ok(mailbox) => { Ok(mailbox) => {
info!(context, "Selected folder {folder:?}.");
self.selected_folder = Some(folder.to_string()); self.selected_folder = Some(folder.to_string());
self.selected_mailbox = Some(mailbox); self.selected_mailbox = Some(mailbox);
Ok(NewlySelected::Yes) Ok(NewlySelected::Yes)
@@ -94,7 +95,7 @@ impl ImapSession {
Ok(newly_selected) => Ok(newly_selected), Ok(newly_selected) => Ok(newly_selected),
Err(err) => match err { Err(err) => match err {
Error::NoFolder(..) => { Error::NoFolder(..) => {
info!(context, "Failed to select folder {} because it does not exist, trying to create it.", folder); info!(context, "Failed to select folder {folder:?} because it does not exist, trying to create it.");
let create_res = self.create(folder).await; let create_res = self.create(folder).await;
if let Err(ref err) = create_res { if let Err(ref err) = create_res {
info!(context, "Couldn't select folder, then create() failed: {err:#}."); info!(context, "Couldn't select folder, then create() failed: {err:#}.");
@@ -129,7 +130,7 @@ impl ImapSession {
let newly_selected = if create { let newly_selected = if create {
self.select_or_create_folder(context, folder) self.select_or_create_folder(context, folder)
.await .await
.with_context(|| format!("failed to select or create folder {folder}"))? .with_context(|| format!("Failed to select or create folder {folder:?}"))?
} else { } else {
match self.select_folder(context, folder).await { match self.select_folder(context, folder).await {
Ok(newly_selected) => newly_selected, Ok(newly_selected) => newly_selected,
@@ -137,7 +138,7 @@ impl ImapSession {
Error::NoFolder(..) => return Ok(false), Error::NoFolder(..) => return Ok(false),
_ => { _ => {
return Err(err) return Err(err)
.with_context(|| format!("failed to select folder {folder}"))? .with_context(|| format!("Failed to select folder {folder:?}"))?
} }
}, },
} }
@@ -145,14 +146,14 @@ impl ImapSession {
let mailbox = self let mailbox = self
.selected_mailbox .selected_mailbox
.as_mut() .as_mut()
.with_context(|| format!("No mailbox selected, folder: {folder}"))?; .with_context(|| format!("No mailbox selected, folder: {folder:?}"))?;
let old_uid_validity = get_uidvalidity(context, folder) let old_uid_validity = get_uidvalidity(context, folder)
.await .await
.with_context(|| format!("failed to get old UID validity for folder {folder}"))?; .with_context(|| format!("Failed to get old UID validity for folder {folder:?}"))?;
let old_uid_next = get_uid_next(context, folder) let old_uid_next = get_uid_next(context, folder)
.await .await
.with_context(|| format!("failed to get old UID NEXT for folder {folder}"))?; .with_context(|| format!("Failed to get old UID NEXT for folder {folder:?}"))?;
let new_uid_validity = mailbox let new_uid_validity = mailbox
.uid_validity .uid_validity

View File

@@ -386,7 +386,7 @@ async fn inbox_loop(
) { ) {
use futures::future::FutureExt; use futures::future::FutureExt;
info!(ctx, "starting inbox loop"); info!(ctx, "Starting inbox loop.");
let ImapConnectionHandlers { let ImapConnectionHandlers {
mut connection, mut connection,
stop_receiver, stop_receiver,
@@ -396,7 +396,7 @@ async fn inbox_loop(
let fut = async move { let fut = async move {
let ctx = ctx1; let ctx = ctx1;
if let Err(()) = started.send(()) { if let Err(()) = started.send(()) {
warn!(ctx, "inbox loop, missing started receiver"); warn!(ctx, "Inbox loop, missing started receiver.");
return; return;
}; };
@@ -405,9 +405,10 @@ async fn inbox_loop(
let session = if let Some(session) = old_session.take() { let session = if let Some(session) = old_session.take() {
session session
} else { } else {
info!(ctx, "Preparing new IMAP session for inbox.");
match connection.prepare(&ctx).await { match connection.prepare(&ctx).await {
Err(err) => { Err(err) => {
warn!(ctx, "Failed to prepare INBOX connection: {:#}.", err); warn!(ctx, "Failed to prepare inbox connection: {err:#}.");
continue; continue;
} }
Ok(session) => session, Ok(session) => session,
@@ -415,8 +416,12 @@ async fn inbox_loop(
}; };
match inbox_fetch_idle(&ctx, &mut connection, session).await { match inbox_fetch_idle(&ctx, &mut connection, session).await {
Err(err) => warn!(ctx, "Failed fetch_idle: {err:#}"), Err(err) => warn!(ctx, "Failed inbox fetch_idle: {err:#}."),
Ok(session) => { Ok(session) => {
info!(
ctx,
"IMAP loop iteration for inbox finished, keeping the session."
);
old_session = Some(session); old_session = Some(session);
} }
} }
@@ -426,7 +431,7 @@ async fn inbox_loop(
stop_receiver stop_receiver
.recv() .recv()
.map(|_| { .map(|_| {
info!(ctx, "shutting down inbox loop"); info!(ctx, "Shutting down inbox loop.");
}) })
.race(fut) .race(fut)
.await; .await;
@@ -695,7 +700,7 @@ async fn simple_imap_loop(
) { ) {
use futures::future::FutureExt; use futures::future::FutureExt;
info!(ctx, "starting simple loop for {}", folder_meaning); info!(ctx, "Starting simple loop for {folder_meaning}.");
let ImapConnectionHandlers { let ImapConnectionHandlers {
mut connection, mut connection,
stop_receiver, stop_receiver,
@@ -706,7 +711,10 @@ async fn simple_imap_loop(
let fut = async move { let fut = async move {
let ctx = ctx1; let ctx = ctx1;
if let Err(()) = started.send(()) { if let Err(()) = started.send(()) {
warn!(&ctx, "simple imap loop, missing started receiver"); warn!(
ctx,
"Simple imap loop for {folder_meaning}, missing started receiver."
);
return; return;
} }
@@ -715,6 +723,7 @@ async fn simple_imap_loop(
let session = if let Some(session) = old_session.take() { let session = if let Some(session) = old_session.take() {
session session
} else { } else {
info!(ctx, "Preparing new IMAP session for {folder_meaning}.");
match connection.prepare(&ctx).await { match connection.prepare(&ctx).await {
Err(err) => { Err(err) => {
warn!( warn!(
@@ -730,6 +739,10 @@ async fn simple_imap_loop(
match fetch_idle(&ctx, &mut connection, session, folder_meaning).await { match fetch_idle(&ctx, &mut connection, session, folder_meaning).await {
Err(err) => warn!(ctx, "Failed fetch_idle: {err:#}"), Err(err) => warn!(ctx, "Failed fetch_idle: {err:#}"),
Ok(session) => { Ok(session) => {
info!(
ctx,
"IMAP loop iteration for {folder_meaning} finished, keeping the session"
);
old_session = Some(session); old_session = Some(session);
} }
} }
@@ -739,7 +752,7 @@ async fn simple_imap_loop(
stop_receiver stop_receiver
.recv() .recv()
.map(|_| { .map(|_| {
info!(ctx, "shutting down simple loop"); info!(ctx, "Shutting down IMAP loop for {folder_meaning}.");
}) })
.race(fut) .race(fut)
.await; .await;