Messages not coming in anymore (probably due to dead idle tasks caused by network change)

[gerryfrancis]

• Operating System (Linux/Mac/Windows/iOS/Android):
  Android 11.

• Delta Chat Version:
  1.33.0-1.34.5.

• Expected behavior:
  Messages are coming in when the app is not focused and WLAN is the active network gateway.

• Actual behavior:
  Messages are not coming in when the app is not focused and WLAN is the active network gateway.

• Steps to reproduce the problem:
  -- Wait for the issue to occur, but use some other apps in the meantime. (WLAN and mobile data must be enabled on the device.)

• Screenshots:
  N/A.

• Logs:
  deltachat-log-20220921-131932_2.txt

• Remarks:
  I doubt that the change from async-std to tokio has something to do with it. I think the culprit lies in how Delta Chat core recognizes old and new network tasks after a different network gateway is activated by the OS.
  
  This switch in Android developer options seems to drive two networks, e.g. LTE and WLAN, in parallel to improve delays for switching between the two networks. When enabled (default setting), the tasks bound to the LTE connection might remain in the back when WLAN is active. Delta Chat might try to hold on to the LTE connection tasks at some time, probably the app cannot distinguish between the "old" and "new" idle tasks properly, and various requests might run into a timeout. I cannot reproduce the issue after I disabled this developer function.
  An Android technote says this:
  All Android apps have a default network. The system decides which should be the default network. The system typically prefers unmetered networks to metered ones and faster networks to slower ones. When an app issues a network request, such as with [HttpsURLConnection](https://developer.android.com/reference/javax/net/ssl/HttpsURLConnection), the system satisfies this request using the default network. Apps can send traffic on other networks, too.
  And further:
  When a new network becomes the default, any new connection the app opens uses this network. At some point later, all remaining connections on the previous default network are forcefully terminated.
  So, the old connections seem to exist for a while, but they do not carry any data as soon as a different network has been set as default. The core might see the old tasks in memory, and therefore does not create any new ones. At a later time, the old tasks are getting killed by the OS, and new network tasks are never created when the app is never focused. This is just speculation, of course, but I guess that is what occurs in the connectivity background.
  Folks, this is a serious issue that has been torturing a few Delta Chat users (including myself), and messages can be delayed for hours. Some users are losing their temper, and things are derailing a little bit. These users have no idea about Android developer options, some cannot even get to them (and I am quite glad about it, otherwise they might mess up their device). Please have a look at this stuff as soon as possible, thank you very much! :)

[gerryfrancis]

Two weeks passed, and I can confirm that disabling this setting has helped to work around this issue, I no longer experience these huge delays in receiving new messages! :)

Has anyone been able to dive into this? My contacts who use WLAN are very frustrated now, but cannot (or should not) change that described Android developer setting. They find that the app is unreliable and are literally climbing up walls and go nuts already! :'( So, please take a closer look at this, guys, and many thanks for your support in advance! ❤️

[link2xt]

Only reception is broken and cannot be recovered with maybe_network, but SMTP is still working? If this is reproducible somehow, could you try if messages can still be sent out in this state? We fixed a similar bug for SMTP deltachat/deltachat-core-rust#3092 previously.

If this only affects IMAP connection, then we can narrow it down to the need to implement some sort of active probing on the application layer with timeout, e.g. cancel IDLE or send a NOOP command and start a timeout, then start a new connection if the command does not respond within a timeout.

[gerryfrancis]

@link2xt Many thanks for your reply.

I think it is important for the app to realize which network (mobile data or WiFi) is default at its time, according to the Android technote. Connectivity tasks seem to be bound to the respective network gateway.

SMTP is triggered by the user, so the app actively rebuilds a connection to the host by request when connectivity is down. While I think the fix you mentioned for SMTP might suffice, an incoming email that has been delivered to the Inbox cannot invoke the mailserver to reach out to the app when the connection is down. Obviously data cannot get through due to broken (muted) mobile data network tasks. My impression is that when the switch "Mobile data always active" is on, the remaining network tasks which are bound to mobile data are muted as soon as the gateway has changed (from mobile data to WiFi). These tasks will be killed (or made available again when mobile data returns) by the OS after some time (, which is described in that article, too), but until then, Delta Chat just seems to look if the unusable tasks still exist. It does not realize that they no longer work.

Starting a new connection after a while may reduce the delay until a new message is received, but it would be better to watch out for the default network instead. Unfortunately this switch has become default for the Android stock ROM since Oreo (version 8.0), either by OTA updates or by the release of 11. And I think other messengers (e.g. Signal) use an API for the Connectivity Manager to get notified by Android when the default network has changed, to restore connectivity. I think we should take a look on how they are handling this situation and try to implement similar code into Delta Chat, maybe that will solve the issue. What do you think?

[link2xt]

We already have a dc_maybe_network() method in the core, so there are two tasks:

• check that dc_maybe_network() is called by Android app on any network state change (doesn't matter if default network changed, wi-fi enabled, whatever)
• ensure that we actively probe that IMAP connection is still working when dc_maybe_network() is called and create a new connection if we cannot get a reply from the server within timeout

Currently this file is responsible for calling maybe_network on Android:
https://github.com/deltachat/deltachat-android/blob/master/src/org/thoughtcrime/securesms/connect/NetworkStateReceiver.java

We register this listener here:

deltachat-android/src/org/thoughtcrime/securesms/ApplicationContext.java

Line 124 in a209872

registerReceiver(networkStateReceiver, new IntentFilter(android.net.ConnectivityManager.CONNECTIVITY_ACTION));

The documentation says this way of setting up listener is deprecated since API level 28, and we use targetSdkVersion 30 in build.gradle:
https://developer.android.com/reference/android/net/ConnectivityManager#CONNECTIVITY_ACTION
"Note that this broadcast is deprecated and generally tries to implement backwards compatibility with older versions of Android. As such, it may not reflect new capabilities of the system, like multiple networks being connected at the same time, the details of newer technology, or changes in tethering state."

Alternatives to CONNECTIVITY_ACTION are suggested in https://developer.android.com/reference/android/net/ConnectivityManager and we should probably use them instead.

@gerryfrancis Could you confirm that focusing the app triggers downloading of all messages immediately? This is not clear from your description. If this is the case and bringing the app to the foreground results in downloading of messages, then it means dc_maybe_network() (core function) is working correctly and there is no core issue, because Android also triggers maybeNetwork in foreground detector: https://github.com/deltachat/deltachat-android/blob/a2098724e8f772b4039a4d3c66b85bed42873703/src/org/thoughtcrime/securesms/connect/ForegroundDetector.java

[link2xt]

The log you posted shows maybeNetwork triggered by foreground detector and downloading of multiple messages, so maybeNetwork seems to be working correctly, the problem is Android not triggering maybeNetwork on some network changes.

Moving this to Android repository.

[gerryfrancis]

Could you confirm that focusing the app triggers downloading of all messages immediately?

When this setting ("mobile network always active") is enabled: Sometimes yes, sometimes no.
When this setting is disabled: New messages are received 24/7. (And I have not had that issue since I disabled it.)

The log you posted shows maybeNetwork triggered by foreground detector

Correct, but I am trying to explain that Delta Chat does not receive new messages while not focused, and that this circumstance happens immediately after a network gateway change from mobile data to WiFi. (The contacts who have this problem use mobile data and WiFi on their phones, and the experience is the same.)

[gerryfrancis]

we use targetSdkVersion 30

From https://developer.android.com/google/play/requirements/target-sdk :

Starting in November 2022, app updates must target API level 31 or above and adjust for behavioral changes in Android 12; except for Wear OS apps, which must target API level 30 or higher.

@link2xt @r10s Does the app have to comply with API level/SDK version 31 until the end of October?

[link2xt]

When this setting ("mobile network always active") is enabled: Sometimes yes, sometimes no.

If you can reproduce the situation where you bring the app to foreground, maybeNetwork is called, but messages are not downloaded over IMAP and collect the log, this will be useful for core debugging.

[gerryfrancis]

If you can reproduce the situation where you bring the app to foreground, maybeNetwork is called, but messages are not downloaded over IMAP and collect the log, this will be useful for core debugging.

@link2xt In fact, new messages are received (downloaded) after maybeNetwork is triggered by focusing Delta Chat. The problem appears when that developer function switch is on - remember, that is a default value since Android >10 in some ROMs, probably introduced with a certain API level - , Delta Chat is not focused, and the network has changed from mobile data to WiFi before. I cannot get a log out of Delta Chat and see what has happened so far unless I focus the app to do so. Is there any other information I could submit to you to support you?

[link2xt]

I think it's enough, if we are sure that focusing the app on Android always downloads the messages, then the problem is that Android does not trigger maybeNetwork in background when it should. This is an Android bug then that could probably be solved by adding more listeners for new ConnectivityManager APIs.

[link2xt]

@hpk42 Also reported that on Desktop after laptop suspend and network change the app sometimes never again downloads messages until restart, but that's a different problem I think. Maybe it's caused by monotonic clock being freezed or jumping too much, in any case it's a different problem.

[gerryfrancis]

I think Google wants Android app developers to cope with the newer requirements the recent API levels come along with. So much for Google's compatibility dedication... ;)

[ghost]

I also confirm this bug.

[r10s]

[...] so there are two tasks:

• check that dc_maybe_network() is called by Android app on any network state change (doesn't matter if default network changed, wi-fi enabled, whatever)

i tried a fix at #2403, but i am a bit sceptical, see comment in the pr.

• ensure that we actively probe that IMAP connection is still working when dc_maybe_network() is called and create a new connection if we cannot get a reply from the server within timeout

@link2xt does core actually take care of that? this is not clear to me by the following comments.

[r10s]

beside #2403 there is now also #2407, updating appcompat dependencies, that may help on this issue.

[gerryfrancis]

I have got news from my mate currently using version 1.34.3 from F-Droid, she still has been experiencing no new messages coming in unless the app gets into foreground. Here is the log from her device, a Google Pixel 3a running Android 12:

deltachat-log-20221112-172039_052816_2.txt

Especially this line has caught my eye:

11-12 15:41:55.343 23384 23417 W DeltaChat: src/imap/idle.rs:86: Idle wait errored: Io(Os { code: 103, kind: ConnectionAborted, message: "Software caused connection abort" })

This is plain Google factory ROM, no antivirus, no firewall. no proxy, not even a Google account.

Mobile data always active is enabled.
WiFi is enabled.
Bluetooth is enabled.
Mobile data is enabled.

[link2xt]

This is an ECONNABORTED:

$ errno 103
ECONNABORTED 103 Software caused connection abort

ECONNABORTED is more useful for search than Rust error: https://stackoverflow.com/questions/9646550/what-does-econnaborted-mean-when-trying-to-connect-a-socket

---

There is not much difference between what DC does in ForegroundDetector.onActivityStarted() and NetworkCallback.onAvailable() cases. In both cases it calls maybeNetwork. In case of ForegroundDetector it also calls start_io(), but it is a no-op.

After calling maybeNetwork, there are src/imap/idle.rs:83: Idle wait was interrupted (twice, once for Inbox and once for DeltaChat). In case of foreground detector, attempt to IDLE on old connection times out, new connections are created and DC starts receiving messages. In case of NetworkCallback.onAvailable() called in background, old connection times out, new connection is created and also times out, aborted etc., so it looks like the system is blocking it.

What is strange is that full folder scan still works. And it scans INBOX even though inbox is already watched, so I opened #3748 to see how the Inbox folder that is watched is called.

Also trying to add more logs etc. in #3749, it's hard to read the logs currently because folder names are not logged and Inbox connection is indistinguishable from DeltaChat (movebox) connection.

[link2xt]

Short summary of the start of the log:

1. At 15:41:55 IMAP-fake-idle can't connect to the server because of "Network is unreachable" error.
2. At 15:42:49 network becomes available, onAvailable is triggered and interrupts fake idle.
3. At 15:43:19 real IDLE is started on the connection, it successfully receives some response to IDLE command and enters wait-on-remote state, which means it now waits for interrupt, 23 minutes timeout or read() syscall error.
4. 15:44:14 read() syscall error happens, it's ECONNABORTED. Operating system reconfigured the interface or something like this, so both connections are now aborted.

"IMAP IDLE protocol timed out" is wrong: it has errored out, not timed out. Note that ? that handles timeout is before the "IMAP IDLE protocol timed out" here:
https://github.com/deltachat/deltachat-core-rust/blob/13f30c31677aca4944a831d24849357dda4a5da9/src/imap/idle.rs#L91
The real error is not in the log because in scheduler.rs the error was formatted with {} instead of {:#}.
I'll fix error reporting in deltachat/deltachat-core-rust#3749

[gerryfrancis]

I am afraid to report that the bug has striked again:

deltachat-log-20221120-210635_2.txt

Maybe this time the log includes more information on why this fails. I wished I could read the code, so I suspect the Worker threads to be unable to hold/maintain IMAP idle after they have been rebuilt. They just seem to be silent and do nothing.

[gerryfrancis]

deltachat-log-20221122-013039_2.txt

Any idea why getChatMsgs(39) behaves like it is out of control?

[gerryfrancis]

A current log from a Google Pixel 3a device running stock Android 12 with reliableService=true:

deltachat-log-20221128-201006_2.txt

IMAP IDLE failed: io: Connection reset by peer (os error 104), I got this on my own device (Fairphone FP2), too. My email provider is different (Posteo, for this case it is Magenta/T-Mobile Austria). In fact, so are the device, the Internet access, the Android version (mine is 11), eventually everything is different.

ignoreBatteryOptimizations is true for both cases.

It seems that the reliableService obviously is not reliable. The email was delivered to the recipients Inbox just five seconds after it had been sent off, so the supply chain of email hosts is not to blame.

Do you need any further information to troubleshoot and pinpoint? I am willing to perform and deliver anything I can to get this under control, my contact has lost faith in the reliability of message delivery.

reliableService has been set back to false because it did not help to cure the problem.

Many thanks in advance, guys! ❤️ ❤️ ❤️

[hpk42]

I am not sure it's related but on a somewhat recent core master (a week or two ago maybe) i also got a dead imap/receive loop. smtp contiunued to work. Below is a log excerpt from the console -- the imap loop or idle never appeared again after second 11215 -- while smtp was still working. I had to restart desktop i order to receive the missing messages. There seems to be a code path that ends up with the imap loosing its looping.

11214.8s [i]core/event: 4 src/receive_imf.rs:99: Receiving message, seen=true...
11214.8s [i]core/event: 4 src/decrypt.rs:46: Detected Autocrypt-mime message
11214.8s [w]core/event: 4 src/mimeparser.rs:739: Ignoring nested protected headers
11214.8s [i]core/event: 4 src/receive_imf.rs:121: received message has Message-Id: Gr.CovhGgau8M-.o_SFf6UCpns@testrun.org
11214.8s [i]core/event: 4 src/receive_imf.rs:1375: Assigning message to Chat#414 as it's a reply to Gr.CovhGgau8M-.qEJRfe_fQpG@testrun.org
11214.8s [i]core/event: 4 src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#414.
11214.8s [i]core/event: 4 src/contact.rs:1547: Recently seen loop is not waiting, event is already due.
11214.8s [D]core/event: ContactsChanged 4 { contactId: 348, type: 'ContactsChanged' }
11214.8s [i]core/event: 4 src/contact.rs:1518: Recently seen loop waiting for 24h 0m 0s or interrupt
11214.8s [D]core/event: MsgsChanged 4 { chatId: 414, msgId: 356563, type: 'MsgsChanged' }
11214.9s [i]core/event: 4 src/receive_imf.rs:99: Receiving message, seen=true...
11214.9s [i]core/event: 4 src/decrypt.rs:46: Detected Autocrypt-mime message
11215s [w]core/event: 4 src/mimeparser.rs:739: Ignoring nested protected headers
11215s [i]core/event: 4 src/receive_imf.rs:121: received message has Message-Id: Gr.CovhGgau8M-.unxu7Lde6ut@testrun.org
11215s [i]core/event: 4 src/receive_imf.rs:1375: Assigning message to Chat#414 as it's a reply to Gr.CovhGgau8M-.o_SFf6UCpns@testrun.org
11215s [i]core/event: 4 src/receive_imf.rs:1217: Message has 1 parts and is assigned to chat #Chat#414.
11215s [i]core/event: 4 src/contact.rs:1547: Recently seen loop is not waiting, event is already due.
11215s [D]core/event: ContactsChanged 4 { contactId: 348, type: 'ContactsChanged' }
11215s [i]core/event: 4 src/contact.rs:1518: Recently seen loop waiting for 24h 0m 0s or interrupt
11215s [D]core/event: MsgsChanged 4 { chatId: 414, msgId: 356564, type: 'MsgsChanged' }
11216.7s [i]core/event: 4 src/scheduler.rs:389: smtp fake idle - interrupted
11216.7s [i]core/event: 4 src/scheduler.rs:363: smtp fake idle - started
11216.7s [D]core/event: ConnectivityChanged 4 { type: 'ConnectivityChanged' }
11216.7s [i]core/event: 4 src/scheduler.rs:385: smtp has no messages to retry, waiting for interrupt
11260s [i]core/event: 4 src/scheduler.rs:389: smtp fake idle - interrupted
11260s [i]core/event: 4 src/scheduler.rs:363: smtp fake idle - started
11260s [D]core/event: ConnectivityChanged 4 { type: 'ConnectivityChanged' }
11260s [i]core/event: 4 src/scheduler.rs:385: smtp has no messages to retry, waiting for interrupt
11264.1s [i]core/event: 4 src/scheduler.rs:389: smtp fake idle - interrupted
11264.1s [i]core/event: 4 src/scheduler.rs:363: smtp fake idle - started
11264.1s [D]core/event: ConnectivityChanged 4 { type: 'ConnectivityChanged' }
11264.1s [i]core/event: 4 src/scheduler.rs:385: smtp has no messages to retry, waiting for interrupt
39196.2s [i]core/event: 4 src/scheduler.rs:389: smtp fake idle - interrupted
39196.2s [i]core/event: 4 src/scheduler.rs:363: smtp fake idle - started
39196.2s [D]core/event: ConnectivityChanged 4 { type: 'ConnectivityChanged' }

[gerryfrancis]

@hpk42 I think it is related, but I did not know that it affects the Desktop client, too. So is this a core issue?

[link2xt]

I am not sure it's related but on a somewhat recent core master (a week or two ago maybe) i also got a dead imap/receive loop. smtp contiunued to work. Below is a log excerpt from the console -- the imap loop or idle never appeared again after second 11215 -- while smtp was still working. I had to restart desktop i order to receive the missing messages. There seems to be a code path that ends up with the imap loosing its looping.

This looks like fetch_many_msgs was processing messages and then it's unclear if it finished or got stuck in parsing somehow. Possibly even fixed in deltachat/deltachat-core-rust#3789, see thread at deltachat/deltachat-core-rust#3789 (comment)
I am going to refactor fetch_many_msgs and add more logging there in any case.

[link2xt]

Made a PR to add more logging: deltachat/deltachat-core-rust#3811

[link2xt]

Very likely the cause of this problem (IMAP seemingly dead) is the lack of timeouts in IMAP reads and writes:
async-email/async-imap#63

I opened a bug in the core repository: deltachat/deltachat-core-rust#3816

@gerryfrancis It is unclear whether it fixes your problem with messages not received in the background, because IMAP appears to be unstuck. But maybe it is unstuck when Android shutdowns the interface, causing connection to be killed and all read/write operations to be aborted. So I will keep this issue to track your particular Android setup.

[gerryfrancis]

@link2xt Thank you very much for the new test build and the detailed explanation. I am running the nightly build from 2022-12-10 (core version 1.103.0), but unfortunately the issue has reappeared. Please view the (anonymized) current log file from my device:

deltachat-log-20221212-200050_2.txt

An "unsolicited response" ("Still here") from the IMAP server was ignored, though I have no idea whether this is relevant or not:

12-12 19:08:16.846 11260 11299 I DeltaChat: src/imap.rs:1685: ignoring unsolicited response Other(ResponseData { raw: 4096, response: Data { status: Ok, code: None, information: Some("Still here") } })

[gerryfrancis]

Using "reliable background connection" reliableService=true seems to bring no joy, too:

deltachat-log-20221214-223823_2.txt

The app received new messages just after it had been foregrounded, while Desktop received them instantly about an hour ago. (The phone did not leave the home WiFi frequency area.) What I still do not understand are the starting IO lines without calling maybeNetwork(). How can IO be started when maybeNetwork() is not called afterwards?

[gerryfrancis]

Another log:

deltachat-log-20221216-202658_2.txt

[gerryfrancis]

Maybe I have found the culprit, at least I hope so:

Delta Chat seems to struggle with a sudden IP address change of the device, especially when the DHCP lease time has expired. The Android client itself welcomes the new IP address successfully, and can be pinged from my notebook immediately, but the running app no longer receives any messages.

My access point features a DHCP server, and its IP address lease times for network clients are set to 86400 seconds (24 hours) equally. (They cannot be adjusted unfortunately, that SOHO router is provided by "A1 Austria", they do not seem to allow that.) Sometimes my phone ("Fairphone FP2", running the latest build of "Lineage OS" based on Android 11) connects to the WiFi network earlier (when in range), sometimes later, which could explain why connectivity in Delta Chat is lost on one day and on the other one it is not.

However, the app recovers and receives new messages when WiFi connectivity is lost, but found (by switching the access point WLAN signal off and on) again after some time, or - more likely - due to a poor WiFi signal that has caused a dis- of and a reconnecting to a WiFi network.

In order to not only cover an IP address change caused either by DHCP lease timeout that has been reached, or by a manual static IP address modification, we could listen to a dedicated Android network event that informs about available IP addresses of the currently active network (e.g. use onLinkPropertiesChanged() and getLinkAddresses() of LinkProperties()), and compare them to the one that has been used to connect so far:

https://developer.android.com/reference/android/net/ConnectivityManager.NetworkCallback#onLinkPropertiesChanged(android.net.Network,%20android.net.LinkProperties)

The document also says:

Starting with [Build.VERSION_CODES.O](https://developer.android.com/reference/android/os/Build.VERSION_CODES#O) this method is guaranteed to be called immediately after [onAvailable(Network)](https://developer.android.com/reference/android/net/ConnectivityManager.NetworkCallback#onAvailable(android.net.Network)).

That makes sense, as the phone might connect to another WiFi network than the one used before, allocating a completely different client IP address.

In any case, should the IP address differ, we may intend to kill the respective idle tasks in memory, and initiate new ones afterwards, to reestablish these connections.

I think that approach might be successful and solves the issue for good (hopefully), what do you think, @r10s and @link2xt?

[link2xt]

So if the address changed due to DHCP lease timeout, onLinkPropertiesChanged is called without onAvailable?

Normally the phone should keep renewing the lease even if it stays on the same network forever, so 24h timeout is not a problem.

[gerryfrancis]

@link2xt

So if the address changed due to DHCP lease timeout, onLinkPropertiesChanged is called without onAvailable?

I guess so. It seems logical to me, as the network itself has not changed in this case.

Normally the phone should keep renewing the lease even if it stays on the same network forever, so 24h timeout is not a problem.

Yes, that is what the phone does, but the open app tasks cannot hold their connections anymore after the IP address has changed.

[gerryfrancis]

Also wondering if and which consequences would follow when the IP address changes from IPv4 to IPv6 and back (or vice versa).

[link2xt]

Normally the phone should keep renewing the lease even if it stays on the same network forever, so 24h timeout is not a problem.

Yes, that is what the phone does, but the open app tasks cannot hold their connections anymore after the IP address has changed.

IP address should not change when the lease is renewed. DHCP-assigned address can be renewed as many times as needed.

[gerryfrancis]

IP address should not change when the lease is renewed. DHCP-assigned address can be renewed as many times as needed.

@link2xt The integrated DHCP server of that ADSL modem can assign the same IP address when a permanent entry for a certain MAC address of a device is configured, of course, but I did not care for it. Also there are times when the phone is connected to at least one other WiFi network.

[gerryfrancis]

I am closing this one, as I believe that this issue has been resolved "as good as possible". Thank you very much to everybody involved for the hard work, overall the app seems to be much more stable and reliable to date! :)