DeltaChat drains battery due to excess IMAP activity

[sven3]

• Android version: 13 (LineageOS 20)
• Device: OnePlus 6T (fajita)
• Delta Chat version: 1.42.3
• Expected behavior: "normal" battery usage
• Actual behavior: DeltaChat is responsible for 95% of my battery drain due to excess IMAP activity. Battery usage logs on Android shows this (see screenshot).
• Steps to reproduce the problem: I don't know how to reproduce. My setup is: Debian Bullseye amd64 with Postfix and Dovecot. Postfix for SMTP over TLS (not STARTTLS, really SMTP over TLS), Dovecot for IMAP over TLS with IMAP IDLE supported. Both services with TLSv1.2 and TLSv1.3. Moving messages to the DeltaChat-IMAP-Folder is done server-side, so I'm only watching the DeltaChat folder and not INBOX. Only one account configured in DeltaChat
• Screenshots:
• Logs:

This is the output of logcat -v time -s DeltaChat, truncated to one second. This is repeated all the time and floods my logcat:

11-23 10:13:05.007 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.011 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.012 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.017 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.021 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.026 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.087 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.092 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.092 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.095 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.098 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.112 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.174 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.179 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.179 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.184 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.188 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.193 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.244 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.252 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.253 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.253 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.257 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.261 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.335 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.339 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.339 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.344 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.348 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.352 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.419 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.423 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.423 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.428 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.432 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.436 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.463 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.467 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.467 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.540 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.543 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.544 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.547 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.548 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.549 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.623 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.627 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.631 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.631 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.636 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.641 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.707 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.710 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.711 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.717 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.722 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.726 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.796 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.805 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.805 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.805 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.809 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.813 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.876 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.881 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.881 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.886 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.889 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "DeltaChat" because UIDNEXT 19705>19704 indicates there are new messages.
11-23 10:13:05.894 I/DeltaChat( 6867): src/imap.rs:893: 0 mails read from "DeltaChat".
11-23 10:13:05.924 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.
11-23 10:13:05.927 I/DeltaChat( 6867): src/imap/idle.rs:44: Skipping IDLE on "INBOX" because UIDNEXT 116456>98353 indicates there are new messages.
11-23 10:13:05.928 I/DeltaChat( 6867): src/imap.rs:701: Not fetching from "INBOX".
11-23 10:13:05.996 I/DeltaChat( 6867): src/scheduler.rs:629: IMAP session supports IDLE, using it.

Anyways, many thanks for this great piece of software that I'm happily using for years now!

[sven3]

I forgot to write that - apart from the battery drain - DeltaChat works normal. I can send messages and I receive messages.

[sven3]

I have a second Android phone (OnePlus 5), also on Android 13 (LineageOS 20) which was still on DeltaChat 1.40.0. The problem did not occur here. After updating DeltaChat from 1.40.0 to 1.42.3 on this phone, this phone shows the same problem. So the reason seems to be something that has changed after 1.40.0.

[link2xt]

@sven3

Moving messages to the DeltaChat-IMAP-Folder is done server-side, so I'm only watching the DeltaChat folder and not INBOX.

Could you provide more details on how exactly this is implemented so I can have the same setup? We run multiple Postfix+Dovecot servers and don't have any problems with them.

This bug looks like #4935 but it is supposed to be fixed by #4936 (commit 7b83bdd).

[sven3]

Could you provide more details on how exactly this is implemented so I can have the same setup? We run multiple Postfix+Dovecot servers and don't have any problems with them.

This is done using a procmail receipt:

:0 H
* ^Chat-Version:
.DeltaChat/

To make Postfix use procmail for local delivery, I set mailbox_command = procmail -a "$EXTENSION" in /etc/postfix/main.cf.

Thanks for taking care of this bug, @link2xt . Do the mentioned details help or is there anything else I can do to help?

[sven3]

I just downgraded DeltaChat to 1.42.2. The bug is present also in 1.42.2. It must have been introduced after 1.40.0 (which works without problems) and before or with 1.42.2.

Any chance I can get the gplay-APKs for:

• 1.40.1
• 1.41.0 Testrun
• 1.41.1 Testrun
• 1.41.2 Testrun
• 1.41.3 Testrun
• 1.41.5 Testrun
• 1.41.6 Testrun
• 1.41.7 Testrun
• 1.41.8 Testrun
• 1.41.9 Testrun
• 1.42.0
• 1.42.1

as mentioned here: https://deltachat.github.io/deltachat-android/CHANGELOG

I could then upgrade step by step and see what version introduces the bug, if that helps.

[link2xt]

We are going to revert this "skip IDLE" check in #5045 anyway because there is a neighbor issue #5043 about the server that has broken STATUS, so we will not rely on STATUS anymore. So no need to test one-by-one.

[sven3]

Many thanks, I can confirm that 1.42.4 fixes the problem for me.

[r10s]

@sven3 there is a new android apk that should fix the bug:

• 🍋 https://download.delta.chat/android/deltachat-gplay-release-1.42.4.apk (android, overwrites existing gplay installs, keeps data)

this is currently on its way to gplay and to the website, however, can already be tested now

[r10s]

Many thanks, I can confirm that 1.42.4 fixes the problem for me.

wow that was fast! you answered even before i sent the message :)

[sven3]

@r10s , oops, a glitch in the matrix. ;-)