Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

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

Open
link2xt opened this issue Jan 25, 2025 · 12 comments
Open
Labels
bug Something is not working

Comments

@link2xt
Copy link
Collaborator

link2xt commented Jan 25, 2025

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

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

@link2xt
Copy link
Collaborator Author

link2xt commented Jan 27, 2025

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

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

@link2xt link2xt self-assigned this Jan 27, 2025
@link2xt
Copy link
Collaborator Author

link2xt commented Jan 27, 2025

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

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

<laptop was suspended here>

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

<seems laptop regained connectivity here>

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

...

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

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

@link2xt
Copy link
Collaborator Author

link2xt commented Jan 28, 2025

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

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

@link2xt
Copy link
Collaborator Author

link2xt commented Feb 3, 2025

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

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

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

@r10s
Copy link
Contributor

r10s commented Feb 3, 2025

maybe related? deltachat/deltachat-ios#2579

@link2xt
Copy link
Collaborator Author

link2xt commented Feb 8, 2025

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

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

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

EDIT: made a PR to fix this at #6526

@link2xt
Copy link
Collaborator Author

link2xt commented Feb 10, 2025

#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.

@link2xt link2xt marked this as a duplicate of #6532 Feb 11, 2025
@WofWca
Copy link
Collaborator

WofWca commented Mar 6, 2025

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.

Image

Just this account is affected. Other ones can receive messages. Exactly as in #6532 (comment), 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.

@link2xt
Copy link
Collaborator Author

link2xt commented Mar 6, 2025

@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"

@WofWca
Copy link
Collaborator

WofWca commented Mar 6, 2025

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

I didn't get the second question.

@link2xt
Copy link
Collaborator Author

link2xt commented Mar 6, 2025

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?

@WofWca
Copy link
Collaborator

WofWca commented Mar 6, 2025

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something is not working
Projects
None yet
Development

No branches or pull requests

3 participants