feat: improve logging around IMAP IDLE

This commit is contained in:
link2xt
2025-01-27 22:58:44 +00:00
committed by l
parent 3b6369a8c8
commit 14d048bea8
3 changed files with 24 additions and 13 deletions

View File

@@ -1983,7 +1983,7 @@ def test_fetch_deleted_msg(acfactory, lp):
if ev.name == "DC_EVENT_MSGS_CHANGED": if ev.name == "DC_EVENT_MSGS_CHANGED":
pytest.fail("A deleted message was shown to the user") pytest.fail("A deleted message was shown to the user")
if ev.name == "DC_EVENT_INFO" and "INBOX: Idle entering wait-on-remote state" in ev.data2: if ev.name == "DC_EVENT_INFO" and 'IDLE entering wait-on-remote state in folder "INBOX".' in ev.data2:
break # DC is done with reading messages break # DC is done with reading messages

View File

@@ -1,6 +1,6 @@
use std::time::Duration; use std::time::Duration;
use anyhow::{bail, Context as _, Result}; use anyhow::{Context as _, Result};
use async_channel::Receiver; use async_channel::Receiver;
use async_imap::extensions::idle::IdleResponse; use async_imap::extensions::idle::IdleResponse;
use futures_lite::FutureExt; use futures_lite::FutureExt;
@@ -38,18 +38,23 @@ impl Session {
} }
if self.new_mail { if self.new_mail {
info!(
context,
"Skipping IDLE in {folder:?} because there may be new mail."
);
return Ok(self); return Ok(self);
} }
if let Ok(()) = idle_interrupt_receiver.try_recv() { if let Ok(()) = idle_interrupt_receiver.try_recv() {
info!(context, "skip idle, got interrupt"); info!(context, "Skip IDLE in {folder:?} because we got interrupt.");
return Ok(self); return Ok(self);
} }
let mut handle = self.inner.idle(); let mut handle = self.inner.idle();
if let Err(err) = handle.init().await { handle
bail!("IMAP IDLE protocol failed to init/complete: {}", err); .init()
} .await
.with_context(|| format!("IMAP IDLE protocol failed to init in folder {folder:?}"))?;
// At this point IDLE command was sent and we received a "+ idling" response. We will now // At this point IDLE command was sent and we received a "+ idling" response. We will now
// read from the stream without getting any data for up to `IDLE_TIMEOUT`. If we don't // read from the stream without getting any data for up to `IDLE_TIMEOUT`. If we don't
@@ -63,7 +68,10 @@ impl Session {
Interrupt, Interrupt,
} }
info!(context, "{folder}: Idle entering wait-on-remote state"); info!(
context,
"IDLE entering wait-on-remote state in folder {folder:?}."
);
let fut = idle_wait.map(|ev| ev.map(Event::IdleResponse)).race(async { let fut = idle_wait.map(|ev| ev.map(Event::IdleResponse)).race(async {
idle_interrupt_receiver.recv().await.ok(); idle_interrupt_receiver.recv().await.ok();
@@ -75,19 +83,19 @@ impl Session {
match fut.await { match fut.await {
Ok(Event::IdleResponse(IdleResponse::NewData(x))) => { Ok(Event::IdleResponse(IdleResponse::NewData(x))) => {
info!(context, "{folder}: Idle has NewData {:?}", x); info!(context, "{folder:?}: Idle has NewData {x:?}");
} }
Ok(Event::IdleResponse(IdleResponse::Timeout)) => { Ok(Event::IdleResponse(IdleResponse::Timeout)) => {
info!(context, "{folder}: Idle-wait timeout or interruption"); info!(context, "{folder:?}: Idle-wait timeout or interruption.");
} }
Ok(Event::IdleResponse(IdleResponse::ManualInterrupt)) => { Ok(Event::IdleResponse(IdleResponse::ManualInterrupt)) => {
info!(context, "{folder}: Idle wait was interrupted manually"); info!(context, "{folder:?}: Idle wait was interrupted manually.");
} }
Ok(Event::Interrupt) => { Ok(Event::Interrupt) => {
info!(context, "{folder}: Idle wait was interrupted"); info!(context, "{folder:?}: Idle wait was interrupted.");
} }
Err(err) => { Err(err) => {
warn!(context, "{folder}: Idle wait errored: {err:?}"); warn!(context, "{folder:?}: Idle wait errored: {err:?}.");
} }
} }

View File

@@ -671,7 +671,10 @@ async fn fetch_idle(
return Ok(session); return Ok(session);
} }
info!(ctx, "IMAP session supports IDLE, using it."); info!(
ctx,
"IMAP session in folder {watch_folder:?} supports IDLE, using it."
);
let session = session let session = session
.idle( .idle(
ctx, ctx,