IMAP loop sometimes gets into busy loop and consumes 100% CPU after suspend

[link2xt]

On both the latest main (roughly 1.155.1 for me on Linux) and 1.152.1 reported by @Simon-Laux on macOS there are cases when deltachat-rpc-server consumes 100% CPU after suspend and messages are not fetched anymore.

Important detail is that for affected account the last message is "46 mails read from \"DeltaChat\"" or similar, i.e. laptop was suspended before IMAP loop went IDLE.

[link2xt]

We also had similar problem reported by @dignifiedquire on 2025-01-07:

Delta Chat Desktop	1.50.1 (git: v1.33.0-1248-gc04da97a)
Delta Chat Core	v1.152.1

[link2xt]

In my log for non-chatmail account that got into 100% CPU state I have this:

2025-01-25T08:22:57.958Z        core/event              INFO    ""      1       "src/imap/idle.rs:87: INBOX: Idle wait was interrupted"
2025-01-25T08:22:57.959Z        core/event              INFO    ""      1       "src/imap/idle.rs:87: DeltaChat: Idle wait was interrupted"
2025-01-25T08:22:57.961Z        core/event              INFO    ""      1       "src/scheduler.rs:819: SMTP fake idle interrupted."
2025-01-25T08:22:57.979Z        core/event              INFO    ""      1       "src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-01-25T08:22:57.979Z        core/event              INFO    ""      1       "src/smtp.rs:616: Sending MDNs."
2025-01-25T08:22:57.986Z        core/event              INFO    ""      1       "src/scheduler.rs:787: SMTP fake idle started."
2025-01-25T08:22:57.986Z        core/event              DEBUG   ""      "ConnectivityChanged"   1       {"kind":"ConnectivityChanged"}
2025-01-25T08:22:57.986Z        core/event              INFO    ""      1       "src/scheduler.rs:815: SMTP has no messages to retry, waiting for interrupt."
2025-01-25T08:22:57.987Z        renderer/components/ConnectivityToast   DEBUG   ""      "Core thinks we're back online and connected"
2025-01-25T08:22:57.994Z        core/event              INFO    ""      1       "src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-01-25T08:22:58.004Z        core/event              INFO    ""      1       "src/imap.rs:755: 0 mails read from \"INBOX\"."

<laptop was suspended here>

2025-01-25T09:01:16.858Z        core/event              INFO    ""      1       "src/imap/scan_folders.rs:31: Starting full folder scan"
2025-01-25T09:01:16.858Z        core/event              DEBUG   ""      "ConnectivityChanged"   1       {"kind":"ConnectivityChanged"}
2025-01-25T09:01:16.859Z        core/event              DEBUG   ""      "ImapInboxIdle" 1       {"kind":"ImapInboxIdle"}
2025-01-25T09:01:16.859Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2025-01-25T09:01:17.160Z        renderer/components/ConnectivityToast   DEBUG   ""      "Core thinks we're back online and connected"
2025-01-25T09:01:17.754Z        renderer/ScreenController       INFO    ""      "onResumeFromSleep"
2025-01-25T09:01:17.755Z        renderer/Component/Timestamp    DEBUG   ""      "updateTS:"     {"updateRefs":{}}
2025-01-25T09:01:17.787Z        core/event              INFO    ""      1       "src/scheduler.rs:819: SMTP fake idle interrupted."
2025-01-25T09:01:17.797Z        core/event              INFO    ""      1       "src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-01-25T09:01:17.798Z        core/event              INFO    ""      1       "src/smtp.rs:616: Sending MDNs."
2025-01-25T09:01:17.826Z        core/event              INFO    ""      1       "src/scheduler.rs:787: SMTP fake idle started."
2025-01-25T09:01:17.826Z        core/event              DEBUG   ""      "ConnectivityChanged"   1       {"kind":"ConnectivityChanged"}
2025-01-25T09:01:17.827Z        core/event              INFO    ""      1       "src/scheduler.rs:815: SMTP has no messages to retry, waiting for interrupt."
2025-01-25T09:01:18.130Z        renderer/components/ConnectivityToast   DEBUG   ""      "Core thinks we're back online and connected"

<seems laptop regained connectivity here>

2025-01-25T09:02:09.915Z        core/event              INFO    ""      1       "src/imap.rs:379: Logging into IMAP server with LOGIN."
2025-01-25T09:02:11.134Z        core/event              INFO    ""      1       "src/imap.rs:388: Enabling IMAP compression."
2025-01-25T09:02:11.306Z        core/event              DEBUG   ""      "ImapConnected" 1       {"kind":"ImapConnected","msg":"IMAP-LOGIN as XXX"}
2025-01-25T09:02:11.307Z        core/event              DEBUG   ""      "ConnectivityChanged"   1       {"kind":"ConnectivityChanged"}
2025-01-25T09:02:11.307Z        core/event              INFO    ""      1       "src/imap.rs:411: Successfully logged into IMAP server"
2025-01-25T09:02:11.474Z        core/event              INFO    ""      1       "src/imap.rs:553: No new emails in folder \"DeltaChat\"."
2025-01-25T09:02:13.551Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2025-01-25T09:02:13.551Z        core/event              INFO    ""      1       "src/imap/idle.rs:45: skip idle, got interrupt"
2025-01-25T09:02:13.552Z        core/event              INFO    ""      1       "src/imap.rs:553: No new emails in folder \"DeltaChat\"."
2025-01-25T09:02:14.984Z        core/event              INFO    ""      1       "src/imap/idle.rs:66: DeltaChat: Idle entering wait-on-remote state"

...

2025-01-25T09:17:02.404Z        render/components/message/MessageList   DEBUG   ""      "window focused"
2025-01-25T09:17:02.405Z        core/event              INFO    ""      1       "src/imap/idle.rs:87: DeltaChat: Idle wait was interrupted"
2025-01-25T09:17:02.405Z        render/components/message/MessageList   DEBUG   ""      "window was focused: marking 6 visible messages as read"        [593303,593309,593313,593345,593511,593645]
2025-01-25T09:17:02.437Z        core/event              INFO    ""      1       "src/scheduler.rs:819: SMTP fake idle interrupted."
2025-01-25T09:17:02.446Z        core/event              INFO    ""      1       "src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-01-25T09:17:02.466Z        core/event              INFO    ""      1       "src/smtp.rs:616: Sending MDNs."
2025-01-25T09:17:02.469Z        core/event              INFO    ""      1       "src/scheduler.rs:787: SMTP fake idle started."
2025-01-25T09:17:02.469Z        core/event              DEBUG   ""      "ConnectivityChanged"   1       {"kind":"ConnectivityChanged"}
2025-01-25T09:17:02.470Z        core/event              INFO    ""      1       "src/scheduler.rs:815: SMTP has no messages to retry, waiting for interrupt."
2025-01-25T09:17:02.938Z        core/event              INFO    ""      1       "src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-01-25T09:17:06.824Z        core/event              DEBUG   ""      "ConnectivityChanged"   1       {"kind":"ConnectivityChanged"}
2025-01-25T09:17:06.841Z        core/event              DEBUG   ""      "ImapInboxIdle" 1       {"kind":"ImapInboxIdle"}
2025-01-25T09:17:06.842Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2025-01-25T09:17:06.891Z        core/event              INFO    ""      1       "src/imap/idle.rs:66: DeltaChat: Idle entering wait-on-remote state"
2025-01-25T09:17:07.142Z        renderer/components/ConnectivityToast   DEBUG   ""      "Core thinks we're back online and connected"
2025-01-25T09:17:09.847Z        renderer/Component/Timestamp    DEBUG   ""      "updateTS:"     {"updateRefs":{}}
2025-01-25T09:18:09.847Z        renderer/Component/Timestamp    DEBUG   ""      "updateTS:"     {"updateRefs":{}}
2025-01-25T09:18:22.781Z        main/menu               INFO    ""      "rebuilding menu with locale en"
2025-01-25T09:18:22.787Z        renderer/Component/Timestamp    DEBUG   ""      "updateTS:"     {"updateRefs":{}}
2025-01-25T09:18:22.799Z        render/components/message/MessageList   DEBUG   ""      "window focused"
2025-01-25T09:18:22.800Z        render/components/message/MessageList   DEBUG   ""      "window was focused: marking 6 visible messages as read"        [593303,593309,593313,593345,593511,593645]
2025-01-25T09:18:22.804Z        core/event              INFO    ""      1       "src/imap/idle.rs:87: DeltaChat: Idle wait was interrupted"
2025-01-25T09:18:22.806Z        core/event              INFO    ""      1       "src/scheduler.rs:819: SMTP fake idle interrupted."

Overall it looks like INBOX loop got stuck, it is not interrupted anymore. It seems INBOX got into IDLE at 2025-01-25T09:01:16.859Z, and after unsuspend it's DeltaChat loop that logged in and got into IDLE at 2025-01-25T09:02:13.551Z while INBOX loop never recovered.

[link2xt]

I improved logging around IMAP in #6485, this got into 1.155.2

IDLE code inside async-imap looks suspicious, it is not straightforward, I also don't like that it has unwrap, assert and unsafe_pinned!:
https://github.com/async-email/async-imap/blob/ddbf1e9b49620d18fc58f73138703ab4a680daf8/src/extensions/idle.rs#L146-L176

[link2xt]

Got this problem on Desktop again.
Core v1.155.1 without improved logging unfortunately, so did not look into the logs.

Inspecting connections with ss, there is an ESTAB state for connection to port 587 and another to port 993.
Both connections are transmitting something according to wireshark, but there should be a third connection to 993.

Then I tried switching "only watch delta chat folder" setting back and forth, and it recovered, but keeps using 100% CPU. So the stuck task was not killed by stopping and starting IO.

[r10s]

maybe related? deltachat/deltachat-ios#2579

[link2xt]

This code also does not look right:
https://github.com/deltachat/deltachat-core-rust/blob/0973a462450e44094ff3d0fc991cb29364bc9204/src/imap/idle.rs#L75-L82

idle_wait is a future returned by wait_with_timeout and I don't think it is cancellation-safe. If we receive interrupt, dropping interrupt cancellation token does not do anything useful because idle_wait future that waits for the token to be dropped is already dropped as well. Calling handle.done() below works on IMAP session that may be in a broken state because we cancelled idle_wait in the middle.

We should always await idle_wait future. If it needs to be interrupted, drop interrupt token and still await idle_wait. If we drop idle_wait, we must drop handle as well and then open a new IMAP session.

EDIT: made a PR to fix this at #6526

[link2xt]

#6526 is merged. Now I think we need further refactorings to async-imap to get rid of future cancellations there and stop token. Currently async-imap uses timeout internally and this means it can cancel futures there.