Battery drain when using `only_fetch_mvbox` option

[sven3]

• Android version: 14 (LineageOS 21)
• Device: OnePlus 6T (fajita)
• Delta Chat version: 1.46.5
• Expected behavior: "normal" battery drain
• Actual behavior: DeltaChat accounts for more than 50% battery usage
• Steps to reproduce the problem: for me it is enough to start DeltaChat
• Logs:

06-20 21:13:17.761 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.762 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.784 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.784 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.784 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.785 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.785 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.801 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.801 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.802 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.802 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.802 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.818 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.819 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.819 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.819 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.820 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.834 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.835 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.835 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.835 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.837 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.890 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.890 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.890 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.890 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.891 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.909 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.909 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.909 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.910 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.911 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.925 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.925 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.925 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)
06-20 21:13:17.925 I/DeltaChat(10534): src/scheduler.rs:674: IMAP session supports IDLE, using it.
06-20 21:13:17.925 I/DeltaChat(10534): src/imap.rs:542: Not fetching from "INBOX".
06-20 21:13:17.941 I/DeltaChat(10534): src/imap/scan_folders.rs:31: Starting full folder scan
06-20 21:13:17.941 W/DeltaChat(10534): src/scheduler.rs:619: scan_folders: io: Broken pipe (os error 32): Broken pipe (os error 32)
06-20 21:13:17.942 W/DeltaChat(10534): /Users/bpetersen/projects/deltachat-android/jni/deltachat-core-rust/src/scheduler.rs:642: sync_seen_flags: failed to fetch flags: io: Broken pipe (os error 32): Broken pipe
 (os error 32)

This repeats all the time and floods the log.

Is there anything I can do to hunt down the bug behind this?

Thanks!

[sven3]

I just noticed that my Linux desktop Delta Chat also produces a constant 91%-95% CPU load. The messages in the log file are comparable:

2024-06-27T12:35:57.144Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.157Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.158Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.172Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.173Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.186Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.187Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.200Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.202Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.218Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.233Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.248Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.250Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.264Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.265Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.281Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.282Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.297Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.298Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.309Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.311Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.323Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.324Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.335Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.336Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.348Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.349Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.365Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.366Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.380Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.381Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.392Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.394Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.407Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.408Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.420Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.421Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.435Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.436Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.449Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.450Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.462Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.463Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."
2024-06-27T12:35:57.476Z        core/event              INFO    ""      1       "src/scheduler.rs:674: IMAP session supports IDLE, using it."
2024-06-27T12:35:57.477Z        core/event              INFO    ""      1       "src/imap.rs:542: Not fetching from \"INBOX\"."

This is Delta Chat 1.46.1 on Gnome 3 running on Debian Bookworm amd64.

Apart from eating all CPU resources, both Delta Chat on Android as well as Delta Chat on Linux desktop work completely normal. There is no delay in receiving a message.

[iequidoo]

Apparently you are using the "Advanced :: Only Fetch from DeltaChat Folder" option. If the bug affects you a lot, you can try disabling it. Anyway this is likely a core bug and should be moved there.

[link2xt]

inbox_fetch_idle/fetch_idle succeeds, otherwise a warning "Failed fetch_idle" should have been printed. This means idle quits immediately, likely because self.new_mail is set.

Recent issue may be caused by #5669 that got into core 1.140.1. Delta Chat Android 1.46.5 is using core 1.140.2 which has this PR merged.

If we are not fetching or fail to select folder, new_mail is not reset and IDLE is skipped again every time.

[link2xt]

Made a fix: #5731

[sven3]

I just updated to DeltaChat-Android 1.46.8, which solves the problem for me. Many thanks for your effort, @link2xt !

[r10s]

thanks for the suuuuuuuuper quick check - i updated the version only one minute before - and did not even announce or link it somewhere 😀

[sven3]

did not even announce or link it somewhere 😀

I'm kind of "Chuck Norris of software" guy - if there's happening something exciting about my favorite open source projects, I will know it before I get informed. ;-)