search

deltachat / deltachat-core-rust

Delta Chat Rust Core library, used by Android/iOS/desktop apps, bindings and bots 📧
https://delta.chat/en/contribute
Other
630 stars 79 forks source link

Battery drain when using `only_fetch_mvbox` option #5722

Closed sven3 closed 1 day ago

sven3 commented 1 week ago 
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 commented 5 days ago

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 commented 4 days ago

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 commented 1 day ago

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 https://github.com/deltachat/deltachat-core-rust/pull/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 commented 1 day ago

Made a fix: https://github.com/deltachat/deltachat-core-rust/pull/5731