deltachat-core-rust IMAP loop sometimes gets into busy loop and consumes 100% CPU after suspend

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.

Jan 25 '25 15:01 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

Jan 27 '25 21:01 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.

Jan 27 '25 22:01 link2xt

I improved logging around IMAP in https://github.com/deltachat/deltachat-core-rust/pull/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

Jan 28 '25 06:01 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.

Feb 03 '25 15:02 link2xt

maybe related? https://github.com/deltachat/deltachat-ios/issues/2579

Feb 03 '25 16:02 r10s

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 https://github.com/deltachat/deltachat-core-rust/pull/6526

Feb 08 '25 22:02 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.

Feb 10 '25 20:02 link2xt

Hey, I don't know if this is the right issue, but my Delta Chat desktop 1.54.2 started taking up CPU on Windows after leaving it open for a while. deltachat-rpc-server is taking 100% of one core.

Edit: DC Desktop 1.54.2 (git: v1.54.2), core v1.156.2.

Just this account is affected. Other ones can receive messages. Exactly as in https://github.com/chatmail/core/issues/6532#issuecomment-2650490240, I can send messages, and see them on the other device, but I cannot receive.

I see this in the logs, several hours before I noticed the forever "Connecting". Could it be related?

log

2025-03-06T02:14:00.243Z	core/event            	INFO	""	1	"src/imap/idle.rs:86: \"INBOX\": Idle has NewData ResponseData { raw: 4096, response: Data { status: Bye, code: None, information: Some(\"Server shutting down.\") } }"
2025-03-06T02:14:00.244Z	core/event            	INFO	""	1	"src/imap/idle.rs:86: \"DeltaChat\": Idle has NewData ResponseData { raw: 4096, response: Data { status: Bye, code: None, information: Some(\"Server shutting down.\") } }"
2025-03-06T02:14:00.437Z	core/event            	WARNING	""	1	"src/scheduler.rs:731: Failed fetch_idle: idle: DeltaChat: IMAP IDLE failed: io: deflate decompression error: deflate decompression error"
2025-03-06T02:14:00.437Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:00.439Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:00.439Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:00.440Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:00.440Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:00.721Z	core/event            	WARNING	""	1	"src/scheduler.rs:418: Failed fetch_idle: idle: INBOX: IMAP IDLE failed: io: deflate decompression error: deflate decompression error"
2025-03-06T02:14:00.721Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:00.723Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:00.723Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:00.724Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:00.724Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:01.815Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): An existing connection was forcibly closed by the remote host. (os error 10054)."
2025-03-06T02:14:01.816Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: An existing connection was forcibly closed by the remote host. (os error 10054)."
2025-03-06T02:14:01.816Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:01.817Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:01.817Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:01.817Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): An existing connection was forcibly closed by the remote host. (os error 10054)."
2025-03-06T02:14:01.818Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: An existing connection was forcibly closed by the remote host. (os error 10054)."
2025-03-06T02:14:01.818Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:01.819Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:01.819Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:01.820Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:01.820Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:04.119Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:04.120Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:04.121Z	core/event            	WARNING	""	1	"src/scheduler.rs:720: Failed to prepare Mvbox connection: An existing connection was forcibly closed by the remote host. (os error 10054)."
2025-03-06T02:14:04.121Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:04.124Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:04.125Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:04.125Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:04.126Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:04.126Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:04.127Z	core/event            	WARNING	""	1	"src/scheduler.rs:410: Failed to prepare INBOX connection: An existing connection was forcibly closed by the remote host. (os error 10054)."
2025-03-06T02:14:04.127Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:04.128Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:04.128Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:04.129Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:04.129Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:04.129Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:06.444Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:06.445Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:06.445Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:06.446Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:06.446Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:06.447Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:06.447Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:06.448Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:06.448Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:06.449Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:06.449Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:06.450Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:08.761Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:08.762Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:08.763Z	core/event            	WARNING	""	1	"src/scheduler.rs:720: Failed to prepare Mvbox connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:08.764Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 1s until can connect."
2025-03-06T02:14:08.764Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:08.765Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:08.766Z	core/event            	WARNING	""	1	"src/scheduler.rs:410: Failed to prepare INBOX connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:08.766Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 1s until can connect."
2025-03-06T02:14:10.513Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:10.514Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:10.515Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:10.516Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:10.516Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:10.702Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:10.703Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:10.704Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:10.705Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:10.705Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:12.853Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:12.854Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:12.855Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:12.855Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:12.856Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:12.856Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:13.031Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:13.032Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:13.032Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:13.033Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:13.033Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:13.034Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:15.184Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:15.185Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:15.187Z	core/event            	WARNING	""	1	"src/scheduler.rs:410: Failed to prepare INBOX connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:15.187Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 6s until can connect."
2025-03-06T02:14:15.326Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:15.327Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:15.328Z	core/event            	WARNING	""	1	"src/scheduler.rs:720: Failed to prepare Mvbox connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:15.329Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 8s until can connect."
2025-03-06T02:14:22.129Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:22.130Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:22.131Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:22.131Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:22.132Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:23.449Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:23.451Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:23.451Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:23.452Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:23.453Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:24.460Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:24.461Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:24.462Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:24.462Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:24.463Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:24.463Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:25.785Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:25.786Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:25.786Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:25.787Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:25.787Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:25.788Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:26.801Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:26.802Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:26.803Z	core/event            	WARNING	""	1	"src/scheduler.rs:410: Failed to prepare INBOX connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:26.804Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 18s until can connect."
2025-03-06T02:14:28.116Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:28.116Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:28.118Z	core/event            	WARNING	""	1	"src/scheduler.rs:720: Failed to prepare Mvbox connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:28.118Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 16s until can connect."
2025-03-06T02:14:44.685Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:44.686Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:44.687Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:44.688Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:44.688Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:45.352Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:14:45.353Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:14:45.354Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:45.354Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:45.355Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:14:47.019Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:47.020Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:47.021Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:47.021Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:47.022Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:47.022Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:47.686Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:47.687Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:47.688Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:14:47.688Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:14:47.689Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:14:47.689Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:14:49.383Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:49.384Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:49.385Z	core/event            	WARNING	""	1	"src/scheduler.rs:720: Failed to prepare Mvbox connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:49.386Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 34s until can connect."
2025-03-06T02:14:50.084Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:143): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:50.084Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:50.086Z	core/event            	WARNING	""	1	"src/scheduler.rs:410: Failed to prepare INBOX connection: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:14:50.086Z	core/event            	WARNING	""	1	"src/imap.rs:308: IMAP got rate limited, waiting for 0h 0m 33s until can connect."
2025-03-06T02:15:23.234Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:15:23.235Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:15:23.236Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:15:23.236Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:15:23.237Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:15:23.518Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:15:23.519Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:993:tls."
2025-03-06T02:15:23.520Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:15:23.520Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:15:23.521Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:993)."
2025-03-06T02:15:25.565Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:15:25.566Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:15:25.566Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:15:25.567Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:15:25.567Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:15:25.568Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:15:25.838Z	core/event            	WARNING	""	1	"src/imap/client.rs:151: Failed to connect to testrun.org (5.1.76.52:993): connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:15:25.839Z	core/event            	WARNING	""	1	"src/imap.rs:354: IMAP failed to connect: connection failure: No connection could be made because the target machine actively refused it. (os error 10061)."
2025-03-06T02:15:25.839Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:15:25.840Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:15:25.840Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:15:25.841Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:15:26.643Z	core/event            	INFO	""	1	"src/imap.rs:379: Logging into IMAP server with LOGIN."
2025-03-06T02:15:26.917Z	core/event            	INFO	""	1	"src/imap.rs:388: Enabling IMAP compression."
2025-03-06T02:15:26.933Z	core/event            	INFO	""	1	"src/imap.rs:379: Logging into IMAP server with LOGIN."
2025-03-06T02:15:26.978Z	core/event            	INFO	""	1	"src/imap.rs:411: Successfully logged into IMAP server"
2025-03-06T02:15:27.034Z	core/event            	INFO	""	1	"src/imap.rs:553: No new emails in folder \"DeltaChat\"."
2025-03-06T02:15:27.171Z	core/event            	INFO	""	1	"src/imap.rs:388: Enabling IMAP compression."
2025-03-06T02:15:27.233Z	core/event            	INFO	""	1	"src/imap.rs:411: Successfully logged into IMAP server"
2025-03-06T02:15:27.332Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T02:15:27.387Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T02:15:27.389Z	core/event            	WARNING	""	1	"src/quota.rs:153: cannot get highest quota usage: no quota_resource found, this is unexpected"
2025-03-06T02:15:27.449Z	core/event            	INFO	""	1	"src/imap.rs:553: No new emails in folder \"INBOX\"."
2025-03-06T02:20:27.389Z	core/event            	INFO	""	1	"src/imap/idle.rs:89: \"DeltaChat\": Idle-wait timeout or interruption."
2025-03-06T02:20:42.393Z	core/event            	WARNING	""	1	"src/scheduler.rs:731: Failed fetch_idle: idle: DeltaChat: IMAP IDLE protocol timed out: deadline has elapsed"
2025-03-06T02:20:42.394Z	core/event            	INFO	""	1	"src/imap.rs:327: Connecting to IMAP server"
2025-03-06T02:20:42.395Z	core/event            	INFO	""	1	"src/imap.rs:342: IMAP trying to connect to testrun.org:143:starttls."
2025-03-06T02:20:42.396Z	core/event            	INFO	""	1	"src/net/dns.rs:133: Using memory-cached DNS resolution for testrun.org."
2025-03-06T02:20:42.396Z	core/event            	INFO	""	1	"src/net/dns.rs:179: Resolved testrun.org into 5.1.76.52."
2025-03-06T02:20:42.397Z	core/event            	INFO	""	1	"src/imap/client.rs:122: Attempting IMAP connection to testrun.org (5.1.76.52:143)."
2025-03-06T02:20:42.642Z	core/event            	INFO	""	1	"src/imap.rs:379: Logging into IMAP server with LOGIN."
2025-03-06T02:20:42.941Z	core/event            	INFO	""	1	"src/imap.rs:388: Enabling IMAP compression."
2025-03-06T02:20:42.999Z	core/event            	INFO	""	1	"src/imap.rs:411: Successfully logged into IMAP server"
2025-03-06T02:20:43.055Z	core/event            	INFO	""	1	"src/imap.rs:553: No new emails in folder \"DeltaChat\"."
2025-03-06T02:20:43.340Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T02:20:43.396Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T07:48:47.035Z	core/event            	INFO	""	1	"src/ephemeral.rs:462: Attempting to delete 51 messages."
2025-03-06T07:48:47.835Z	core/event            	INFO	""	1	"src/ephemeral.rs:609: Ephemeral loop waiting for deletion in 4h 35m 56s or interrupt"
2025-03-06T08:00:38.768Z	renderer/ScreenController	INFO	""	"onResumeFromSleep"
2025-03-06T08:00:38.772Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:00:38.782Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:00:38.786Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:00:38.792Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:00:38.793Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:00:38.799Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:00:38.800Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:00:39.170Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:00:39.449Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:00:39.505Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:10:16.447Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:10:16.473Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:10:16.477Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:10:16.479Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:10:16.488Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:10:16.488Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:10:16.492Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:10:16.493Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:10:16.815Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:10:17.008Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:10:17.040Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:25:44.791Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:25:44.819Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:25:44.820Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:25:44.824Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:25:44.831Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:25:44.895Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:25:44.985Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:25:44.986Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:25:45.011Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:25:45.676Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:25:45.729Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:26:00.156Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:26:00.167Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:26:00.172Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:26:00.183Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:26:00.214Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:26:00.214Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:26:00.248Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:26:00.249Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:26:00.381Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:26:00.604Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:26:00.660Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:26:54.369Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:26:54.392Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:26:54.395Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:26:54.399Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:26:54.399Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:26:54.400Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:26:54.401Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:26:54.403Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:26:54.567Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:26:54.926Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:26:54.981Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:29:44.039Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:29:44.076Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:29:44.077Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:29:44.080Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:29:44.086Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:29:44.087Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:29:44.154Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:29:44.155Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:29:44.294Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:29:44.712Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:29:44.768Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:30:50.109Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:30:50.183Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:30:50.186Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:30:50.189Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:30:50.199Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:30:50.205Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:30:50.206Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:30:50.216Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:30:50.555Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:30:50.749Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:30:50.753Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:33:22.050Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:33:22.056Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:33:22.062Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:33:22.066Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:33:22.091Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:33:22.091Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:33:22.106Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:33:22.108Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:33:22.230Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:33:22.603Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:33:22.609Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:34:48.473Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:34:48.492Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:34:48.494Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:34:48.496Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:34:48.550Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:34:48.551Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:34:48.556Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:34:48.558Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:34:49.099Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:34:49.330Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:34:49.332Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:34:56.682Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:34:56.708Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:34:56.710Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:34:56.710Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:34:56.711Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:34:57.004Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:34:57.007Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:34:57.008Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:34:57.111Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:34:57.249Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:34:57.305Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:35:42.809Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:35:42.835Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:35:42.836Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:35:42.837Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:35:42.860Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:35:42.860Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:35:42.881Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:35:42.882Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:35:43.030Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:35:43.325Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:35:43.380Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:35:52.349Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:35:52.363Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:35:52.364Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:35:52.372Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:35:52.375Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:35:52.376Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:35:52.377Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:35:52.382Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:35:52.580Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:35:52.878Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:35:52.932Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:36:30.142Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:36:30.153Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:36:30.162Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:36:30.163Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:36:30.173Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:36:30.174Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:36:30.239Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:36:30.240Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:36:30.322Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:36:30.600Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:36:30.656Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:36:58.377Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:36:58.402Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:36:58.423Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:36:58.424Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:36:58.473Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:36:58.474Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:36:58.521Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:36:58.523Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:36:58.589Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:36:58.888Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:36:58.944Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."
2025-03-06T08:42:18.083Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:42:24.039Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:43:24.646Z	main/menu             	INFO	""	"rebuilding menu with locale en"
2025-03-06T08:43:25.410Z	core/event            	INFO	""	1	"src/scheduler.rs:822: SMTP fake idle interrupted."
2025-03-06T08:43:25.414Z	core/event            	INFO	""	1	"src/imap/idle.rs:77: \"DeltaChat\": Received interrupt, stopping IDLE."
2025-03-06T08:43:25.415Z	core/event            	INFO	""	1	"src/imap/idle.rs:92: \"DeltaChat\": Idle wait was interrupted manually."
2025-03-06T08:43:25.427Z	core/event            	INFO	""	1	"src/smtp.rs:511: Selected rows from SMTP queue: []."
2025-03-06T08:43:25.429Z	core/event            	INFO	""	1	"src/smtp.rs:616: Sending MDNs."
2025-03-06T08:43:25.439Z	core/event            	INFO	""	1	"src/scheduler.rs:790: SMTP fake idle started."
2025-03-06T08:43:25.439Z	core/event            	INFO	""	1	"src/scheduler.rs:818: SMTP has no messages to retry, waiting for interrupt."
2025-03-06T08:43:25.667Z	core/event            	INFO	""	1	"src/imap.rs:755: 0 mails read from \"DeltaChat\"."
2025-03-06T08:43:25.935Z	core/event            	INFO	""	1	"src/scheduler.rs:674: IMAP session in folder \"DeltaChat\" supports IDLE, using it."
2025-03-06T08:43:25.991Z	core/event            	INFO	""	1	"src/imap/idle.rs:63: IDLE entering wait-on-remote state in folder \"DeltaChat\"."

I'll leave DC in that state for a while, please let me know if you'd like me to try something, or to get more logs.

Mar 06 '25 09:03 WofWca

@WofWca Is this the first account (account ID, the one at the top of your account list) that got stuck?

The last entry for account 1 and INBOX is this?

2025-03-06T02:14:00.721Z	core/event            	WARNING	""	1	"src/scheduler.rs:418: Failed fetch_idle: idle: INBOX: IMAP IDLE failed: io: deflate decompression error: deflate decompression error"

Mar 06 '25 18:03 link2xt

Yes, the first account, with ID 1. I filtered out the entries for other accounts.

I didn't get the second question.

Mar 06 '25 18:03 WofWca

I didn't get the second question.

Are there any more log entries for the "INBOX" of account 1 below? Or did IMAP loop for INBOX folder got stuck completely after this line?

Mar 06 '25 18:03 link2xt

I'm not that good at reading core logs, so I edited the post to include the logs for the next few hours, to when I focused the Delta Chat window.

Mar 06 '25 18:03 WofWca

@adbenitez collected a log with https://github.com/ArcaneChat/core 1.159.5 where inbox loop got stuck on Android after logging src/imap.rs:555: No new emails in folder "INBOX". Apparently this got stuck outside of the IDLE loop so read timeout should be set, but the loop seems to never recover. Mvbox loop continued to run. It's not clear if this was using 100% CPU as this is on Android.

This was after https://github.com/chatmail/core/pull/6848 was merged, so apparently it did not fix the problem or fixed a different problem.

There is a PR merged adding some more logging: https://github.com/chatmail/core/pull/6859

Buffering is hard, so I suspect there might be a bug in async-compression or async-imap or imap-proto that results in the reader being stuck in infinite loop on EOF or error without bubbling up the error. We previously had problems with async-compression that involved buffering, e.g. here: https://github.com/chatmail/core/issues/6656

I have tried to test async-compression with turmoil and maybe reveal more bugs there, but have not found anything. It seems turmoil does not help with revealing buffering issues currently: https://github.com/tokio-rs/turmoil/issues/240

If some layer like async-compression or rustls does not pass the timeout error from the TcpStream through, we might get stuck while trying to read from the stream or write into it.

async-imap besides buffering also parses from the buffer and has complicated logic there: https://github.com/chatmail/async-imap/blob/545171e28afe63229322a4fc8a6058480990e94c/src/imap_stream.rs#L71-L125 In async-imap we have a MockStream, but we do not test for setting the error (err_on_read) in the middle of the stream: https://github.com/chatmail/async-imap/blob/545171e28afe63229322a4fc8a6058480990e94c/src/mock_stream.rs Maybe parser gets stuck if the network error happens in some particular state.

What we can do:

Collect another log with https://github.com/chatmail/core/pull/6859 merged and try to find more precisely what got stuck.
Add logging layer between TcpStream and TLS/compression layer to log immediately when network errors occur, directly from the AsyncWrite and AsyncRead implementations so errors will show up in the log before IMAP client has to react to them.
~Add tests to async-imap simulating a network error at various offsets during reading and make sure the error bubbles up without the test getting stuck.~ See the next post, I reviewed the code again and it does not look like it should hang in infinite loop.
~Test async-compression over a stream that randomly stalls, splits or concatenates packets. Either improve turmoil for this or find some other way to simulate this.~ See below, I tried to do something and the writer seems to behave correctly.
Add an option to disable compression and see if it helps. It will not necessarily mean that the bug is in async-compression if it helps, though, or help debugging the problem much.
Attach debugger if this ever happens on desktop.

May 20 '25 00:05 link2xt

I have looked at async-imap again. It only implements its own buffering logic for reading and it does not look like it can get stuck in a loop to me. Pushed some commits as a result, refining the test and added an assertion, but overall the code looks good: https://github.com/chatmail/async-imap/commit/262b84df471a635152d028f691f3aea6b72b758d https://github.com/chatmail/async-imap/commit/034202fa52cd51d2269e98cd609853268cc8d96a

So now I suspect it might be a problem in async-compression, it has somewhat complex logic starting here: https://github.com/chatmail/async-imap/commit/034202fa52cd51d2269e98cd609853268cc8d96a Internal BufWriter sometimes throws the error away if it has already wrote something: https://github.com/Nullus157/async-compression/blob/aa03267e075d43a6a201a6d7fe573f682f7a65c9/src/tokio/write/buf_writer.rs#L67 I don't know if it is ok to ignore the error, because we likely don't want to keep writing into the stream that returned an error at some point even if it later recovered. Especially if it was a write timeout error, will we get another write timeout error if we try again and will we get it immediately or after another minute?

Similar code in the tokio BufWriter does not ever throw the error away. When writing, we first flush the buffer and then either write into the buffer or write through if this write is over the buffer capacity: https://github.com/tokio-rs/tokio/blob/0cf95f067347bca820099dcec1e457bbe993390b/tokio/src/io/util/buf_writer.rs#L119-L134 Flushing itself never throws the error away, does not matter if we managed to flush some bytes before the error occurs: https://github.com/tokio-rs/tokio/blob/0cf95f067347bca820099dcec1e457bbe993390b/tokio/src/io/util/buf_writer.rs#L74

Looking at the tokio-io-timeout implementation, it seems that it should be fine to call poll_write again after timeout and it will return the timeout immediately, but I am not sure about EPIPE or ECONNRESET errors.

May 20 '25 03:05 link2xt

Test async-compression over a stream that randomly stalls, splits or concatenates packets. Either improve turmoil for this or find some other way to simulate this.

I tried to make a test for async-compression handling of errors and stalls and it does not fail:

use async_compression::tokio::write::DeflateEncoder;
use std::task::{Poll, Context};
use std::pin::Pin;

use tokio::io::AsyncWrite;
use tokio::io::AsyncWriteExt;

use proptest::prelude::*;

struct FaultyStream {
    fail_at: usize,

    total_written: usize,

    hiccup: bool
}

impl FaultyStream {
    fn new(fail_at: usize) -> Self {
        Self {
            fail_at,
            total_written: 0,
            hiccup: false
        }
    }
}

impl AsyncWrite for FaultyStream {
    fn poll_write(
        mut self: Pin<&mut Self>,
        cx: &mut Context<'_>,
        buf: &[u8]
    ) -> Poll<std::io::Result<usize>> {
        if !self.hiccup && self.total_written % 3 == 0 {
            self.hiccup = true;
            cx.waker().wake_by_ref();
            Poll::Pending
        } else {
            self.hiccup = false;
            let written = std::cmp::min(buf.len(), 15123);
            self.total_written += written;
            if self.total_written >= self.fail_at {
                return Poll::Ready(Err(std::io::Error::new(std::io::ErrorKind::UnexpectedEof, "EOF")));
            }
            Poll::Ready(Ok(written))
        }
    }

    fn poll_flush(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<std::io::Result<()>> {
        Poll::Ready(Ok(()))
    }

    fn poll_shutdown(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<std::io::Result<()>> {
        Poll::Ready(Ok(()))
    }
}

async fn write_into_faulty_stream(input: Vec<u8>) {
    let stream = FaultyStream::new(input.len());
    let mut stream = DeflateEncoder::new(stream);
    while stream.write_all(&input).await.is_ok() {
        eprintln!("another loop");
    }
    assert!(stream.flush().await.is_err());
}

proptest! {
    #[test]
    fn test_faulty_stream(input in proptest::collection::vec(0u8..=255, 50000)) {
        tokio::runtime::Builder::new_multi_thread()
        .enable_all()
        .build()
        .unwrap()
        .block_on(write_into_faulty_stream(input));
    }
}

May 20 '25 11:05 link2xt

https://github.com/chatmail/core/pull/6848 was merged into core 1.159.4. But with 1.159.5 @hpk42 still got the problem of IMAP loop getting stuck. The log of an app running with 1 account looks like this:

--------- beginning of main
07-06 11:52:39.975 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #535
07-06 11:52:43.046 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #536
07-06 11:52:46.190 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #537
07-06 11:54:13.117 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #538
07-06 11:54:25.499 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #539
07-06 11:55:05.637 12402 12495 🟠 DeltaChat: [accId=0] Background fetch timed out.
07-06 11:55:10.663 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #130
07-06 11:58:08.024 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #540
07-06 11:58:08.025 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #541
07-06 11:58:08.025 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #542
07-06 11:58:08.026 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #543
07-06 11:58:08.027 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #544
07-06 11:58:08.028 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #131
07-06 11:58:08.110 12402 17361 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() started ++++++++++++++++++
07-06 11:58:35.083 12402 12402 🟠 JobService: onNetworkChanged() not implemented in androidx.work.impl.background.systemjob.SystemJobService. Must override in a subclass.
07-06 11:58:35.091 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #545
07-06 11:59:08.125 12402 17361 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() will return ++++++++++++++++++
07-06 11:59:08.133 12402 12514 🔵 WM-WorkerWrapper: Worker result SUCCESS for Work [ id=45032cde-c612-46fd-a7ae-e8ee6ca901c9, tags={ org.thoughtcrime.securesms.connect.FetchWorker } ]
07-06 11:59:13.182 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #132
07-06 12:02:51.767 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #546
07-06 12:02:51.770 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #547
07-06 12:02:51.770 12402 12500 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #133
07-06 12:02:51.819 12402  1358 🔵 FcmReceiveService: FCM push notification received
07-06 12:02:51.828 12402 12402 🔵 FcmReceiveService: Creating fetch service
07-06 12:02:51.836 12402 26136 🔵 FcmReceiveService: Starting fetch
07-06 12:02:51.837 12402 12495 🔵 DeltaChat: [accId=0] Starting background fetch for 1 accounts.
07-06 12:02:51.840 12402 12495 🔵 DeltaChat: [accId=1] src/context.rs:564: background_fetch started fetching [email protected].
07-06 12:02:51.840 12402 12495 🔵 DeltaChat: [accId=1] src/scheduler.rs:836: SMTP fake idle interrupted.
07-06 12:02:51.840 12402 12495 🔵 DeltaChat: [accId=1] src/smtp.rs:514: Selected rows from SMTP queue: [].
07-06 12:02:51.840 12402 12495 🔵 DeltaChat: [accId=1] src/smtp.rs:619: Sending MDNs.
07-06 12:02:51.841 12402 12495 🔵 DeltaChat: [accId=1] src/scheduler.rs:804: SMTP fake idle started.
07-06 12:02:51.841 12402 12495 🔵 DeltaChat: [accId=1] src/scheduler.rs:832: SMTP has no messages to retry, waiting for interrupt.
07-06 12:03:47.038 12402  1358 🔵 FcmReceiveService: FCM push notification received
07-06 12:03:58.411 12402  1358 🔵 FcmReceiveService: FCM push notification received
07-06 12:04:58.192 12402  1358 🔵 FcmReceiveService: FCM push notification received
07-06 12:05:03.227 12402  1358 🔵 FcmReceiveService: FCM push notification received
07-06 12:05:08.259 12402  1358 🔵 FcmReceiveService: FCM push notification received

It's a chatmail account, so it should only have an IMAP loop for INBOX. There are no IMAP messages in the log, so IMAP loop got stuck long ago and it's unclear where exactly.

Jul 06 '25 22:07 link2xt

Core 1.160.0 includes change https://github.com/chatmail/core/pull/6910 that simplifies IMAP loop shutdown.

Jul 10 '25 18:07 link2xt

There are no IMAP messages in the log, so IMAP loop got stuck long ago and it's unclear where exactly.

The problem with recent Android is that it uses small ringbuffer for logs. This limits the logs stored much more than the limit we have for loading the logs on Android (10k lines): https://github.com/deltachat/deltachat-android/blob/fa40d4fb44eee3c99c5952f0f4194dbcdb0efc63/src/main/java/org/thoughtcrime/securesms/LogViewFragment.java#L127 Old versions of Android stored more logs and this even resulted in adding a limit: https://github.com/deltachat/deltachat-android/pull/3247

Now the limit can be increased by going into Developer settings on Android and switching the buffer size:

Developer settings can be enabled as described in https://developer.android.com/studio/debug/dev-options, usually by tapping 7 times on the "Build number" in "About phone".

See also https://stackoverflow.com/questions/12243736/how-long-are-logcat-entries-kept-in-memory

Jul 15 '25 00:07 link2xt

So we now have two logs.

First log from a mailcow account, with INBOX loop and movebox loop (account IDs other than 4 are filtered out):

07-15 13:39:32.051  4447 12516 🔵 FcmReceiveService: FCM push notification received
07-15 13:39:32.066  4447  4447 🔵 FcmReceiveService: Creating fetch service
07-15 13:39:32.071  4447 11177 🔵 FcmReceiveService: Starting fetch
07-15 13:39:32.071  4447  4478 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #23
07-15 13:39:32.087  4447  4484 🔵 DeltaChat: [accId=4] src/context.rs:569: background_fetch started fetching [email protected].
07-15 13:39:32.088  4447  4484 🔵 DeltaChat: [accId=4] src/imap/idle.rs:78: "DeltaChat": Received interrupt, stopping IDLE.
07-15 13:39:32.088  4447  4484 🔵 DeltaChat: [accId=4] src/imap/idle.rs:93: "DeltaChat": Idle wait was interrupted manually.
07-15 13:39:32.088  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:839: SMTP fake idle interrupted.
07-15 13:39:32.089  4447  4484 🔵 DeltaChat: [accId=4] src/smtp.rs:517: Selected rows from SMTP queue: [].
07-15 13:39:32.090  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:807: SMTP fake idle started.
07-15 13:39:32.091  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:835: SMTP has no messages to retry, waiting for interrupt.
07-15 13:39:32.093  4447  5359 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() started ++++++++++++++++++
07-15 13:39:32.185  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:746: IMAP loop iteration for Mvbox finished, keeping the session
07-15 13:39:32.269  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:747: 0 mails read from "DeltaChat".
07-15 13:39:32.367  4447 12516 🔵 FcmReceiveService: FCM push notification received
07-15 13:39:32.386  4447 12516 🔵 FcmReceiveService: FCM push notification received
07-15 13:39:33.093  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:683: IMAP session in folder "DeltaChat" supports IDLE, using it.
07-15 13:39:33.236  4447  4484 🔵 DeltaChat: [accId=4] src/imap/idle.rs:64: IDLE entering wait-on-remote state in folder "DeltaChat".
07-15 13:39:41.888  4447 12516 🔵 FcmReceiveService: FCM push notification received
07-15 13:39:42.349  4447 12516 🔵 FcmReceiveService: FCM push notification received
07-15 13:39:42.385  4447 12516 🔵 FcmReceiveService: FCM push notification received
07-15 13:39:48.277  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:683: IMAP session in folder "INBOX" supports IDLE, using it.
07-15 13:39:48.278  4447  4484 🔵 DeltaChat: [accId=4] src/imap/idle.rs:47: Skip IDLE in "INBOX" because we got interrupt.
07-15 13:39:48.279  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:424: IMAP loop iteration for inbox finished, keeping the session.
07-15 13:39:48.370  4447  4484 🔵 DeltaChat: [accId=4] src/context.rs:607: background_fetch done for [email protected] took 16.281823738s.
07-15 13:39:48.386  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:553: No new emails in folder "INBOX".
07-15 13:39:48.392  4447  4478 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #24
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper: Work [ id=d1ca7c5e-2296-4907-b208-9f2af55054c5, tags={ org.thoughtcrime.securesms.connect.FetchWorker } ] was cancelled
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper: java.util.concurrent.CancellationException: Task was cancelled.
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at Q0.i.d(SourceFile:33)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at Q0.i.get(Unknown Source:21)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at C.i.run(SourceFile:1320)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at C.i.d(SourceFile:5)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at C.i.run(SourceFile:876)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1156)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:651)
07-15 13:39:48.425  4447  4468 🔵 WM-WorkerWrapper:     at java.lang.Thread.run(Thread.java:1119)
07-15 13:40:00.743  4447  9912 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() will return ++++++++++++++++++
07-15 13:40:35.287  4447  5359 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() will return ++++++++++++++++++
07-15 13:42:23.975  4447  4484 🟠 DeltaChat: [accId=4] src/imap/idle.rs:96: "DeltaChat": Idle wait errored: Io(Os { code: 103, kind: ConnectionAborted, message: "Software caused connection abort" }).
07-15 13:42:23.975  4447  4484 🟠 DeltaChat: [accId=4] src/scheduler.rs:744: Failed fetch_idle: idle: DeltaChat: IMAP IDLE failed: io: Broken pipe (os error 32): Broken pipe (os error 32)
07-15 13:42:23.975  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:730: Preparing new IMAP session for Mvbox.
07-15 13:42:23.975  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:327: Connecting to IMAP server.
07-15 13:42:23.984  4447 12925 🔵 FcmReceiveService: FCM push notification received
07-15 13:42:23.996  4447  4478 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #25
07-15 13:42:23.996  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:342: IMAP trying to connect to mailcow.testrun.org:993:tls.
07-15 13:42:23.996  4447  4484 🔵 DeltaChat: [accId=4] src/net/dns.rs:134: Using memory-cached DNS resolution for mailcow.testrun.org.
07-15 13:42:23.996  4447  4484 🔵 DeltaChat: [accId=4] src/net/dns.rs:180: Resolved mailcow.testrun.org into 2a00:f820:417:0:5:1:76:52.
07-15 13:42:24.076  4447  4447 🔵 FcmReceiveService: Creating fetch service
07-15 13:42:24.083  4447 11177 🔵 FcmReceiveService: Starting fetch
07-15 13:42:24.095  4447  6993 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() started ++++++++++++++++++
07-15 13:42:24.139  4447  4484 🔵 DeltaChat: [accId=4] src/context.rs:569: background_fetch started fetching [email protected].
07-15 13:42:24.139  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:839: SMTP fake idle interrupted.
07-15 13:42:24.143  4447  4484 🔵 DeltaChat: [accId=4] src/smtp.rs:517: Selected rows from SMTP queue: [].
07-15 13:42:24.155  4447 12925 🔵 FcmReceiveService: FCM push notification received
07-15 13:42:24.162  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:807: SMTP fake idle started.
07-15 13:42:24.162  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:835: SMTP has no messages to retry, waiting for interrupt.
07-15 13:42:24.169  4447 12925 🔵 FcmReceiveService: FCM push notification received
07-15 13:42:24.299  4447  4484 🔵 DeltaChat: [accId=4] src/imap/client.rs:123: Attempting IMAP connection to mailcow.testrun.org ([2a00:f820:417:0:5:1:76:52]:993).
07-15 13:42:24.595  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:380: Logging into IMAP server with LOGIN.
07-15 13:42:27.029  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:389: Enabling IMAP compression.
07-15 13:42:27.064  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:412: Successfully logged into IMAP server.
07-15 13:42:27.109  4447  4484 🔵 DeltaChat: [accId=4] src/imap/select_folder.rs:79: Selected folder "DeltaChat".
07-15 13:42:27.110  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:553: No new emails in folder "DeltaChat".
07-15 13:42:27.790  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:683: IMAP session in folder "DeltaChat" supports IDLE, using it.
07-15 13:42:27.790  4447  4484 🔵 DeltaChat: [accId=4] src/imap/idle.rs:47: Skip IDLE in "DeltaChat" because we got interrupt.
07-15 13:42:27.790  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:746: IMAP loop iteration for Mvbox finished, keeping the session
07-15 13:42:27.790  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:553: No new emails in folder "DeltaChat".
07-15 13:42:28.454  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:683: IMAP session in folder "DeltaChat" supports IDLE, using it.
07-15 13:42:28.512  4447  4484 🔵 DeltaChat: [accId=4] src/imap/idle.rs:64: IDLE entering wait-on-remote state in folder "DeltaChat".
07-15 13:43:24.137  4447  6993 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() will return ++++++++++++++++++
07-15 13:43:24.155  4447  4474 🔵 WM-WorkerWrapper: Worker result SUCCESS for Work [ id=d1ca7c5e-2296-4907-b208-9f2af55054c5, tags={ org.thoughtcrime.securesms.connect.FetchWorker } ]
07-15 13:43:24.682  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:43:25.018  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:43:25.038  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:46:53.088  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:46:53.416  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:46:53.429  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:47:01.065  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:47:01.856  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:47:01.868  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:47:37.244  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:47:38.036  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:47:38.047  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:48:16.691  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:48:16.702  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:48:16.713  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:48:25.996  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:48:26.007  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:48:26.068  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:49:25.638  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:49:25.650  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:49:25.662  4447 12991 🔵 FcmReceiveService: FCM push notification received
07-15 13:57:27.961  4447  4484 🟠 DeltaChat: [accId=0] Background fetch timed out.
07-15 13:57:27.985  4447  4478 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #26
07-15 13:58:24.034  4447  4478 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #181
07-15 13:58:24.866  4447  4478 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #182
07-15 14:22:10.837  4447  4484 🟠 DeltaChat: [accId=4] src/imap/idle.rs:96: "DeltaChat": Idle wait errored: Io(Os { code: 103, kind: ConnectionAborted, message: "Software caused connection abort" }).
07-15 14:22:11.073  4447  4484 🟠 DeltaChat: [accId=4] src/scheduler.rs:744: Failed fetch_idle: idle: DeltaChat: IMAP IDLE failed: io: Broken pipe (os error 32): Broken pipe (os error 32)
07-15 14:22:11.073  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:730: Preparing new IMAP session for Mvbox.
07-15 14:22:11.073  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:327: Connecting to IMAP server.
07-15 14:22:11.073  4447  4484 🔵 DeltaChat: [accId=4] src/imap.rs:342: IMAP trying to connect to mailcow.testrun.org:993:tls.
07-15 14:22:11.073  4447  4484 🔵 DeltaChat: [accId=4] src/net/dns.rs:134: Using memory-cached DNS resolution for mailcow.testrun.org.
07-15 14:22:11.168  4447  4484 🔵 DeltaChat: [accId=4] src/net/dns.rs:180: Resolved mailcow.testrun.org into 2a00:f820:417:0:5:1:76:52.
07-15 14:22:11.169  4447  4484 🔵 DeltaChat: [accId=4] src/net/dns.rs:180: Resolved mailcow.testrun.org into 5.1.76.52.
07-15 14:22:11.169  4447  4484 🔵 DeltaChat: [accId=4] src/imap/client.rs:123: Attempting IMAP connection to mailcow.testrun.org (5.1.76.52:993).
07-15 14:22:11.234  4447 14837 🔵 FcmReceiveService: FCM push notification received
07-15 14:22:11.250  4447  4484 🟠 DeltaChat: [accId=4] src/net/dns.rs:125: Failed to revalidate results for "mailcow.testrun.org": DNS lookup failure: failed to lookup address information: No address associated with hostname.

Inbox loop died, movebox has nothing to do because new messages arrive into inbox.

Another log with a chatmail account, accId=2:

07-15 23:21:00.978  6968  6997 🔵 DeltaChat: [accId=2] src/imap/scan_folders.rs:104: Found folders: ["INBOX"].
07-15 23:21:00.978  6968  6997 🔵 DeltaChat: [accId=2] src/imap.rs:553: No new emails in folder "INBOX".
07-15 23:21:01.581  6968  6968 🟠 JobService: onNetworkChanged() not implemented in androidx.work.impl.background.systemjob.SystemJobService. Must override in a subclass.
07-15 23:21:01.587  6968  6968 🟠 JobService: onNetworkChanged() not implemented in androidx.work.impl.background.systemjob.SystemJobService. Must override in a subclass.
07-15 23:21:01.605  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #18
07-15 23:21:01.722  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:683: IMAP session in folder "INBOX" supports IDLE, using it.
07-15 23:21:01.722  6968  6997 🔵 DeltaChat: [accId=2] src/imap/idle.rs:47: Skip IDLE in "INBOX" because we got interrupt.
07-15 23:21:01.722  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:424: IMAP loop iteration for inbox finished, keeping the session.
07-15 23:21:03.596  6968  6968 🟠 JobService: onNetworkChanged() not implemented in androidx.work.impl.background.systemjob.SystemJobService. Must override in a subclass.
07-15 23:21:03.606  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #19
07-15 23:21:08.616  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #24
07-15 23:21:08.631  6968  6968 🔵 DeltaChat: ++++++++++++++++++ last ForegroundDetector.onActivityStopped() ++++++++++++++++++
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper: Work [ id=d1ca7c5e-2296-4907-b208-9f2af55054c5, tags={ org.thoughtcrime.securesms.connect.FetchWorker } ] was cancelled
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper: java.util.concurrent.CancellationException: Task was cancelled.
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at Q0.i.d(SourceFile:33)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at Q0.i.get(Unknown Source:21)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at C.i.run(SourceFile:1320)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at C.i.d(SourceFile:5)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at C.i.run(SourceFile:876)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1156)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:651)
07-15 23:21:08.642  6968  6982 🔵 WM-WorkerWrapper:     at java.lang.Thread.run(Thread.java:1119)
07-15 23:21:09.568  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #20
07-15 23:21:59.654  6968  7094 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() will return ++++++++++++++++++
07-16 00:08:21.523  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onAvailable() #4
07-16 00:08:21.526  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #21
07-16 00:08:21.526  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onLinkPropertiesChanged() #5
07-16 00:08:21.526  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #25
07-16 00:08:21.526  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #22
07-16 00:08:21.527  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #23
07-16 00:08:21.527  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #24
07-16 00:08:21.527  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #25
07-16 00:08:21.527  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #26
07-16 00:08:21.527  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #27
07-16 00:08:21.527  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #28
07-16 00:08:21.528  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #29
07-16 00:08:21.528  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:839: SMTP fake idle interrupted.
07-16 00:08:21.528  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #30
07-16 00:08:21.528  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onCapabilitiesChanged() #31
07-16 00:08:21.555  6968  6968 🔵 thub.arcanechat: AssetManager2(0xb400007ea32b2eb8) locale list changing from [] to [en-US]
07-16 00:08:21.572  6968  6997 🔵 DeltaChat: [accId=2] src/smtp.rs:517: Selected rows from SMTP queue: [].
07-16 00:08:21.572  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:807: SMTP fake idle started.
07-16 00:08:21.573  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:835: SMTP has no messages to retry, waiting for interrupt.
07-16 00:08:21.751  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:21.751  6968  6997 🔵 DeltaChat: [accId=2] src/ephemeral.rs:462: Attempting to delete 18 messages.
07-16 00:08:21.757  6968  6995 🔵 DeltaChat: ++++++++++++++++++ NetworkCallback.onBlockedStatusChanged() #26
07-16 00:08:21.758  6968  6968 🔵 FcmReceiveService: Creating fetch service
07-16 00:08:21.763  6968 14418 🔵 FcmReceiveService: Starting fetch
07-16 00:08:21.768  6968  6997 🔵 DeltaChat: [accId=2] src/context.rs:569: background_fetch started fetching [email protected].
07-16 00:08:21.768  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:839: SMTP fake idle interrupted.
07-16 00:08:21.779  6968  7207 🔵 DeltaChat: ++++++++++++++++++ FetchWorker.doWork() started ++++++++++++++++++
07-16 00:08:21.784  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:21.792  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:807: SMTP fake idle started.
07-16 00:08:21.792  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:835: SMTP has no messages to retry, waiting for interrupt.
07-16 00:08:21.796  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:21.806  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:21.815  6968 20461 🔵 FcmReceiveService: FCM push notification received
... (lots of FCM push notifications skipped) ...
07-16 00:08:22.015  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.026  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.038  6968  6997 🔵 DeltaChat: [accId=2] src/ephemeral.rs:604: Ephemeral loop waiting for deletion in 0h 12m 42s or interrupt
07-16 00:08:22.039  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.049  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.056  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.066  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.074  6968 20461 🔵 FcmReceiveService: FCM push notification received
... (lots of FCM push notifications skipped) ...
07-16 00:08:22.442  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.449  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:22.456  6968 20461 🔵 FcmReceiveService: FCM push notification received
07-16 00:08:32.537  6968  6968 🔵 DeltaChat: ++++++++++++++++++ first ForegroundDetector.onActivityStarted() ++++++++++++++++++
07-16 00:08:32.538  6968 20537 🔵 DeltaChat: calling maybeNetwork()
07-16 00:08:32.538  6968 20537 🔵 DeltaChat: maybeNetwork() returned
07-16 00:08:32.538  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:839: SMTP fake idle interrupted.

Both with core v2.0.0.

Android never stops I/O I think, so this stop of Inbox loop never happens and does not appear in the log: https://github.com/chatmail/core/blob/a0f6bdffeb454588f0570c90fdda01ea54a64832/src/scheduler.rs#L437

But in the first log Inbox loop does not print anything after this:

07-15 13:39:48.279  4447  4484 🔵 DeltaChat: [accId=4] src/scheduler.rs:424: IMAP loop iteration for inbox finished, keeping the session.

So either inbox loop got stuck after going into the next iteration and inbox_fetch_idle before logging anything, or something happened to the thread it is scheduled to.

Same for the second log, the last from the inbox loop are:

07-15 23:21:01.722  6968  6997 🔵 DeltaChat: [accId=2] src/imap/idle.rs:47: Skip IDLE in "INBOX" because we got interrupt.
07-15 23:21:01.722  6968  6997 🔵 DeltaChat: [accId=2] src/scheduler.rs:424: IMAP loop iteration for inbox finished, keeping the session.

Jul 16 '25 02:07 link2xt

I don't have FCM notifications and never get this problem on Android while @hpk42 and @adbenitez have FCM notifications via microG and this happens. So this is probably related to background_fetch. background_fetch cancels futures on timeout and future cancellation is tricky.

~~But I also have some suspicion that this might be related to peer channels, because at the time when we played peer channels more I had the problem of 100% CPU usage and one account getting stuck on desktop several times. If there is a deadlock in iroh or its dependencies, it may hog one of the executor threads and prevent some loop scheduled there from running.~~ This is not peerchannels, the bug reproduces with disabled peerchannels.

Jul 16 '25 09:07 link2xt

It is also suspicious that in both logs IMAP loop dies after src/imap/idle.rs:47: Skip IDLE in "INBOX" because we got interrupt. log. It skips IDLE and then the thread gets stuck. Maybe there is some problem with our usage of channel::bounded(1) and try_send and try_recv for sending interrupts. Channel with a single item is an edge case and maybe async-channel implementation is not that well tested in this case.

Jul 16 '25 10:07 link2xt

Another thought I had is that Android uses CFFI call for dc_accounts_background_fetch (and other functions as well). This in turn uses block_on which runs the future on the current thread, i.e. the thread that called CFFI. If Android does this on a separate thread and then cancels the thread, it may be possible that tokio moved some task on the thread but does not expect that thread disappears and task may be lost as a result. Android should make sure that it never cancels a thread that is inside a CFFI call to the core.

EDIT: I don't think however that Android cancels threads that easily. While https://firebase.google.com/docs/cloud-messaging/android/receive says that messages should be handled in 20 seconds, OS controls this by killing the process or reducing the time it allows the process to run, not going inside the process and killing the threads. Unless we do this manually somehow, threads from the thread pool should not just disappear.

Jul 16 '25 11:07 link2xt

And for the case that it is IMAP parser getting stuck, maybe https://github.com/chatmail/core/pull/6924 will help detect it.

Jul 16 '25 11:07 link2xt

When there is a problem, connectivity view displays IO timeout error in the storage section. So current explanation for how the bug happens:

Application is in background and is put to foreground by FCM notification.
Application creates a new connection and does one loop.
When the loop finishes, connectivity status is set to "connected".
background_fetch finishes because wait_for_all_work_done returns: https://github.com/chatmail/core/blob/8fc6ea19b45c0a6579239d09afbd7620c1362229/src/context.rs#L569
FCM handler finishes and application is put into background again.
Connection is lost to NAT while the app is in background.
Next time the application is in foreground, it still thinks it has a valid connection, but the next read will timeout.
Since a lot of time has passed, the first thing IMAP loop does is checks quota.
quota is a timeout error here and if block is not entered: https://github.com/chatmail/core/blob/8fc6ea19b45c0a6579239d09afbd7620c1362229/src/quota.rs#L134
update_recent_quota exits without returning an error, error is only stored into quota.recent.
Parser tries to read from the stream again and gets stuck somehow. Maybe tokio_io_timout does not rewind the timer after returning a timeout error once.

We should have bubbled up the error and dropped the stream, but in update_recent_quota we ignore the error. Also there are no logs in update_recent_quota and before it.

Jul 16 '25 15:07 link2xt

Another attempt at fixing this bug: https://github.com/chatmail/core/pull/7010

Jul 16 '25 18:07 link2xt

@adbenitez reproduced the bug with https://github.com/chatmail/core/pull/6924 merged. The whole log looks like this:

07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.
07-19 22:43:46.084 19620 19646 🟠 DeltaChat: [accId=2] Read error on stream 192.168.1.20:443 after reading 9118 and writing 1036 bytes: timed out.

(original IP address edited out)

So something got stuck trying to read from the stream over and over and ignoring the error. Could be async-compression, but that's just a guess. Maybe the bug can be reproduced by making the stream return fake error once the counter of bytes read reaches 9118.

I also expected that timeout to be triggered once per minute, but it is not reset between reads and I think this is a bug in tokio-io-timeout: https://github.com/sfackler/tokio-io-timeout/issues/13 This is why 100% CPU is used and the log is full of this message repeated.

Jul 19 '25 21:07 link2xt

100% CPU usage and log spamming should be fixed by https://github.com/chatmail/core/pull/7019

Jul 20 '25 02:07 link2xt

Since it attempts to read, it is not a CPU-only loop, e.g. not an infinite loop in IMAP parser.

Before https://github.com/sfackler/tokio-io-timeout/commit/f3c0e8c658f179a941f40b021dbf64e144fab419 the loop got stuck in an infinite loop calling poll_read(), which returned timeout error repeatedly. Now that https://github.com/chatmail/core/pull/7019 updating tokio-io-timeout to 1.2.1 is merged, this bug should still result in infinite loop, but logging timeout error once a minute instead of spamming the log. The error may change eventually since calls will reach the underlying socket and it may return e.g. "connection reset by peer" error, but as long as the code does not match the error, the loop will not terminate.

The logs which have a problem show that no proxy is used and inbox IMAP loop gets stuck, so we can rule out the possibility of the bug in fast-socks5 or shadowsocks.

Non-proxied TLS stream is built as async_imap::imap_stream::ImapStream<tokio::io::BufWriter<tokio_rustls::client::TlsStream<LoggingStream<TcpStream>>>> ImapStream internally wraps the stream into async_compression::tokio::bufread::DeflateDecoder<tokio::io::BufReader<async_compression::tokio::write::DeflateEncoder<T>>> when compression is used. There is no tokio::io::BufReader or tokio::io::BufStream around the uncompressed stream because async-imap has its own custom buffering.

The code is distributed between the following packages:

tokio (tokio::io::BufReader)
rustls
async-imap
async-compression
chatmail

I have looked through async-imap, but have not found any bugs that can result in infinite loop inside the library. ImapStream in async-imap is built on top of non-buffered stream and immediately bubbles up all poll_read() errors in poll_next() implementation of ImapStream. ImapStream should be used carefully to make sure the errors are not ignored because on error repeted calls to next() return Some(Err(_)) and if you are looking for None, you may get stuck in infinite loop. I have however created a refactoring PR to use try_next() instead of next() when reading from the stream: https://github.com/chatmail/async-imap/pull/121

I have found a problem in chatmail: https://github.com/chatmail/core/pull/7022 This may cause the problem and it is definitely a bug. I don't know how easy it is to trigger. It may be that it is the bug and it is triggered mostly on mobile connection because when user is on mobile connection there is usually a desktop client open as well that moves the messages and triggres FETCH responses that we want to ignore. I don't have full explanation of what happens, better merge the fix and see if the problem goes away.

I have also looked into async-compression. It uses AsyncBufRead stream and cals poll_fill_buf. From a quick look all errors from poll_fill_buf in src/tokio/bufread/generic/decoder.rs are bubbled up and terminate the loops.

I have not looked into tokio and rustls, any bugs that cause infinite read loops there should also cause problems to at least all HTTPS users, so I expect that the bug is not there.

Jul 21 '25 09:07 link2xt

This is now closed as there is hope that #7022 fixed it, but can be reopened if the problem appears again.

Jul 21 '25 13:07 link2xt

deltachat-core-rust deltachat-core-rust copied to clipboard

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

deltachat-core-rust
deltachat-core-rust copied to clipboard