search

thunderbird / thunderbird-android

K-9 Mail – Open Source Email App for Android
https://k9mail.app/
Apache License 2.0
9.67k stars 2.44k forks source link

IMAP IDLE push dies intermittently #6035

Open J0nnyMak0 opened 2 years ago

J0nnyMak0 commented 2 years ago

Checklist

App version

6.000

Where did you get the app from?

Google Play

Android version

10

Device model

No response

Steps to reproduce

  1. I'm connected to the imap server
  2. With IDLE refresh set to 24 minutes (default)
  3. And "Max folders to check with push" set to 5
  4. k9 works fine for days on end with push notifications to my Inbox working great
  5. Then all of a sudden, I stop receiving new mail unless I manually refresh my Inbox.

Expected behavior

Expect to keep getting messages pushed to my Inbox

Actual behavior

Stop receiving emails

Logs

I'd like some help with understanding how to capture useful info since it takes days for this problem to manifest. However, this is what I see when I refresh my inbox manually after emails stop getting pushed. Killing k9 on my phone and restarting, fixes the problem for a few days until it happens again. I've tried playing around with IDLE refresh times but that doesn't seem to help. Reducing # of max push folders to 5 seems to increase the time between failures.

Not sure it has anything to do with this, but for completeness, I access the same mailbox from a different client on the desktop that also uses IMAP IDLE (refresh set to 15 minutes) and it continues to work fine, pushing emails.

04-25 12:09:41.972  6735  6775 V RealImapConnection: conn189706754<<<#45# [OK, UID FETCH completed]
04-25 12:09:42.579  6735  6775 D ImapSync: SYNC: Synced remote messages for folder INBOX, 1 new messages
04-25 12:09:42.613  6735  6775 D ImapSync: Done synchronizing folder Work:INBOX @ Mon Apr 25 12:09:42 CDT 2022
04-25 12:09:42.616  6735  6775 I ImapSync: Done synchronizing folder Work:INBOX
04-25 12:09:42.616  6735  6775 V ImapSync: Saving new highest known UID: 1120117
04-25 12:09:42.623  6735  6775 I MessagingController:  Command 'synchronizeMailbox' completed
04-25 12:09:42.623  6735  6775 I MessagingController: Running command 'sendPendingMessages', seq = 219 (background priority)
04-25 12:09:42.625  6735  6775 I MessagingController:  Command 'sendPendingMessages' completed

Just before the above, everything seems ok, but I don't get any emails showing up in k9:

04-25 12:09:41.859  6735  6775 V RealImapConnection: conn189706754<<<#44# [OK, UID FETCH completed]
04-25 12:09:41.860  6735  6775 V RealImapConnection: conn189706754>>> 45 UID FETCH 1113984,1113981,1113980,1113976,1113974,1113973,1113972,1113969,1113965,1113963,1113961,1113957,1113953,1113946,1113944,1113943,1113942,1113940,1113939,1113937,1113936,1113935,1113934,1113933,1113928,1113927,1113925,1113924,1113923,1113921,1113920,1113919,1113916,1113915,1113913,1113912,1113911,1113909,1113906,1113903,1113901,1113898,1113897,1113895,1113894,1113892,1113891,1113889,1113888 (UID FLAGS)
04-25 12:09:41.905  6735  6775 V RealImapConnection: conn189706754<<<#null# [24120, FETCH, [UID, 1113888, FLAGS, [\Seen]]]
04-25 12:09:41.907  6735  6775 V RealImapConnection: conn189706754<<<#null# [24121, FETCH, [UID, 1113889, FLAGS, [\Seen]]]
04-25 12:09:41.908  6735  6775 V RealImapConnection: conn189706754<<<#null# [24122, FETCH, [UID, 1113891, FLAGS, [\Seen]]]
04-25 12:09:41.908  6735  6775 V RealImapConnection: conn189706754<<<#null# [24123, FETCH, [UID, 1113892, FLAGS, [\Seen]]]
04-25 12:09:41.909  6735  6775 V RealImapConnection: conn189706754<<<#null# [24124, FETCH, [UID, 1113894, FLAGS, [\Seen]]]
04-25 12:09:41.910  6735  6775 V RealImapConnection: conn189706754<<<#null# [24125, FETCH, [UID, 1113895, FLAGS, [\Seen]]]
04-25 12:09:41.910  6735  6775 V RealImapConnection: conn189706754<<<#null# [24126, FETCH, [UID, 1113897, FLAGS, [\Seen]]]
04-25 12:09:41.911  6735  6775 V RealImapConnection: conn189706754<<<#null# [24127, FETCH, [UID, 1113898, FLAGS, [\Seen]]]
04-25 12:09:41.912  6735  6775 V RealImapConnection: conn189706754<<<#null# [24128, FETCH, [UID, 1113901, FLAGS, [\Seen]]]
04-25 12:09:41.912  6735  6775 V RealImapConnection: conn189706754<<<#null# [24129, FETCH, [UID, 1113903, FLAGS, [\Seen]]]
04-25 12:09:41.913  6735  6775 V RealImapConnection: conn189706754<<<#null# [24130, FETCH, [UID, 1113906, FLAGS, [\Seen]]]
04-25 12:09:41.914  6735  6775 V RealImapConnection: conn189706754<<<#null# [24131, FETCH, [UID, 1113909, FLAGS, [\Answered, \Seen]]]
04-25 12:09:41.914  6735  6775 V RealImapConnection: conn189706754<<<#null# [24132, FETCH, [UID, 1113911, FLAGS, [\Seen]]]
04-25 12:09:41.915  6735  6775 V RealImapConnection: conn189706754<<<#null# [24133, FETCH, [UID, 1113912, FLAGS, [\Seen]]]
04-25 12:09:41.915  6735  6775 V RealImapConnection: conn189706754<<<#null# [24134, FETCH, [UID, 1113913, FLAGS, [\Seen]]]
04-25 12:09:41.916  6735  6775 V RealImapConnection: conn189706754<<<#null# [24135, FETCH, [UID, 1113915, FLAGS, [\Seen]]]
04-25 12:09:41.917  6735  6775 V RealImapConnection: conn189706754<<<#null# [24136, FETCH, [UID, 1113916, FLAGS, [\Seen]]]
04-25 12:09:41.918  6735  6775 V RealImapConnection: conn189706754<<<#null# [24137, FETCH, [UID, 1113919, FLAGS, [\Seen]]]
04-25 12:09:41.919  6735  6775 V RealImapConnection: conn189706754<<<#null# [24138, FETCH, [UID, 1113920, FLAGS, [\Seen]]]
04-25 12:09:41.920  6735  6775 V RealImapConnection: conn189706754<<<#null# [24139, FETCH, [UID, 1113921, FLAGS, [\Seen]]]
04-25 12:09:41.921  6735  6775 V RealImapConnection: conn189706754<<<#null# [24140, FETCH, [UID, 1113923, FLAGS, [\Seen]]]
04-25 12:09:41.921  6735  6775 V RealImapConnection: conn189706754<<<#null# [24141, FETCH, [UID, 1113924, FLAGS, [\Answered, \Seen]]]
04-25 12:09:41.922  6735  6775 V RealImapConnection: conn189706754<<<#null# [24142, FETCH, [UID, 1113925, FLAGS, [\Seen]]]
04-25 12:09:41.954  6735  6775 V RealImapConnection: conn189706754<<<#null# [24143, FETCH, [UID, 1113927, FLAGS, [\Seen]]]
04-25 12:09:41.955  6735  6775 V RealImapConnection: conn189706754<<<#null# [24144, FETCH, [UID, 1113928, FLAGS, [\Answered, \Seen]]]
04-25 12:09:41.955  6735  6775 V RealImapConnection: conn189706754<<<#null# [24145, FETCH, [UID, 1113933, FLAGS, [\Seen]]]
04-25 12:09:41.956  6735  6775 V RealImapConnection: conn189706754<<<#null# [24146, FETCH, [UID, 1113934, FLAGS, [\Seen]]]
04-25 12:09:41.956  6735  6775 V RealImapConnection: conn189706754<<<#null# [24147, FETCH, [UID, 1113935, FLAGS, [\Seen]]]
04-25 12:09:41.957  6735  6775 V RealImapConnection: conn189706754<<<#null# [24148, FETCH, [UID, 1113936, FLAGS, [\Answered, \Seen]]]
04-25 12:09:41.958  6735  6775 V RealImapConnection: conn189706754<<<#null# [24149, FETCH, [UID, 1113937, FLAGS, [\Seen]]]
04-25 12:09:41.958  6735  6775 V RealImapConnection: conn189706754<<<#null# [24150, FETCH, [UID, 1113939, FLAGS, [\Answered, \Seen]]]
04-25 12:09:41.959  6735  6775 V RealImapConnection: conn189706754<<<#null# [24151, FETCH, [UID, 1113940, FLAGS, [\Seen]]]
04-25 12:09:41.960  6735  6775 V RealImapConnection: conn189706754<<<#null# [24152, FETCH, [UID, 1113942, FLAGS, [\Seen]]]
04-25 12:09:41.961  6735  6775 V RealImapConnection: conn189706754<<<#null# [24153, FETCH, [UID, 1113943, FLAGS, [\Seen]]]
04-25 12:09:41.961  6735  6775 V RealImapConnection: conn189706754<<<#null# [24154, FETCH, [UID, 1113944, FLAGS, [\Seen]]]
04-25 12:09:41.962  6735  6775 V RealImapConnection: conn189706754<<<#null# [24155, FETCH, [UID, 1113946, FLAGS, [\Seen]]]
04-25 12:09:41.962  6735  6775 V RealImapConnection: conn189706754<<<#null# [24156, FETCH, [UID, 1113953, FLAGS, [\Seen]]]
04-25 12:09:41.963  6735  6775 V RealImapConnection: conn189706754<<<#null# [24157, FETCH, [UID, 1113957, FLAGS, [\Seen]]]
04-25 12:09:41.964  6735  6775 V RealImapConnection: conn189706754<<<#null# [24158, FETCH, [UID, 1113961, FLAGS, [\Seen]]]
04-25 12:09:41.964  6735  6775 V RealImapConnection: conn189706754<<<#null# [24159, FETCH, [UID, 1113963, FLAGS, [\Seen]]]
04-25 12:09:41.965  6735  6775 V RealImapConnection: conn189706754<<<#null# [24160, FETCH, [UID, 1113965, FLAGS, [\Seen]]]
04-25 12:09:41.965  6735  6775 V RealImapConnection: conn189706754<<<#null# [24161, FETCH, [UID, 1113969, FLAGS, [\Seen]]]
04-25 12:09:41.966  6735  6775 V RealImapConnection: conn189706754<<<#null# [24162, FETCH, [UID, 1113972, FLAGS, [\Seen]]]
04-25 12:09:41.967  6735  6775 V RealImapConnection: conn189706754<<<#null# [24163, FETCH, [UID, 1113973, FLAGS, [\Seen]]]
04-25 12:09:41.968  6735  6775 V RealImapConnection: conn189706754<<<#null# [24164, FETCH, [UID, 1113974, FLAGS, [\Seen]]]
04-25 12:09:41.968  6735  6775 V RealImapConnection: conn189706754<<<#null# [24165, FETCH, [UID, 1113976, FLAGS, [\Seen]]]
04-25 12:09:41.969  6735  6775 V RealImapConnection: conn189706754<<<#null# [24166, FETCH, [UID, 1113980, FLAGS, [\Seen]]]
04-25 12:09:41.970  6735  6775 V RealImapConnection: conn189706754<<<#null# [24167, FETCH, [UID, 1113981, FLAGS, [\Seen]]]
cketti commented 2 years ago

When Push stops working, do you still see the Push notification? If so, what text does it display?

There's not much we can do without more information. You need to capture a log right after Push fails (and doesn't recover). You might be able to accomplish that by leaving your device connected to a PC. See https://github.com/k9mail/k-9/wiki/LoggingErrors

Instead of adb logcat -d --pid=<PID> > k9-log.txt use adb logcat --pid=<PID> > k9-log.txt. Once you've captured the error, press CTRL+C to stop the logging.

J0nnyMak0 commented 2 years ago

When Push stops working, do you still see the Push notification? If so, what text does it display?

Do you mean the persistent notification? It still says "Waiting for new emails", but I don't get any other notifications.

There's not much we can do without more information. You need to capture a log right after Push fails (and doesn't recover). You might be able to accomplish that by leaving your device connected to a PC. See https://github.com/k9mail/k-9/wiki/LoggingErrors

Instead of adb logcat -d --pid=<PID> > k9-log.txt use adb logcat --pid=<PID> > k9-log.txt. Once you've captured the error, press CTRL+C to stop the logging.

Ok, thanks. I'll will try that. I will try to increase the # of push folders and see if I can force this to happen sooner.

cketti commented 2 years ago

Most servers have a limit of how many connections per user they allow. Usually this manifests as an error during authentication. After an authentication error, K-9 Mail's Push code will back off and only retry an hour later.

"Too many open connections" is a condition that could happen if the Android device frequently loses and regains connectivity. From the point of view of the server the old connections will remain open until the server's IDLE timeout is reached, even if there's nobody on the other side of the connection anymore.

J0nnyMak0 commented 2 years ago

After an authentication error, K-9 Mail's Push code will back off and only retry an hour later.

Does the persistent notification text change when k9 is in this mode?

cketti commented 2 years ago

Good question. I don't have time to check right now. I'm guessing the text won't change.

J0nnyMak0 commented 2 years ago

This is still happening from time to time. This is what I was able to capture with the suggested method. k9log.txt

gunterkoenigsmann commented 2 years ago

I have two accounts: One Gmail account and one at IONOS. If i stop being notified immediately on arrival of new mails, but mails still arrive at refresh or triggered by a timer (might be once per hour, but feels faster) that happens for both accounts simultaneously.

Have now told my android not to optimize K9 for battery usage: I suspect that the original reporter of this problem and I both just see the results of our cellphones trying to save some energy.

J0nnyMak0 commented 2 years ago

I suspect that the original reporter of this problem and I both just see the results of our cellphones trying to save some energy.

Nope. Sorry, not in my case. Should have mentioned it, I took K-9 off battery optimization. From the log above it looks like there actually is some sort of an abort? Not sure if "Software caused connection abort" is server side or client side.

04-26 15:34:37.127 19644 19694 V AndroidPowerManager$AndroidWakeLock: AndroidWakeLock for tag ImapFolderPusher-Work-Deleted Messages / id 9: acquired with no timeout.
04-26 15:34:37.134 19644 19694 V ImapFolderPusher: Exception in ImapFolderPusher
04-26 15:34:37.134 19644 19694 V ImapFolderPusher: javax.net.ssl.SSLException: Read error: ssl=0x77724fd388: I/O error during system call, Software caused connection abort
04-26 15:34:37.134 19644 19694 V ImapFolderPusher:      at com.android.org.conscrypt.NativeCrypto.SSL_read(Native Method)
04-26 15:34:37.134 19644 19694 V ImapFolderPusher:      at com.android.org.conscrypt.NativeSsl.read(NativeSsl.java:411)
04-26 15:34:37.134 19644 19694 V ImapFolderPusher:      at com.android.org.conscrypt.ConscryptFileDescriptorSocket$SSLInputStream.read(ConscryptFileDescriptorSocket.java:549)
J0nnyMak0 commented 1 year ago

A quick update. I recently upgraded to a Pixel and running K9 on Android 13. I'm still running into this issue. As @cketti suspected, I think the issue is when I switch from wifi to mobile network and vice versa. I have set my IDLE keep alive to 60 minutes to minimize connections to server.

I think it would be great if there can be a setting where IDLE renews when there is either a change in network connection or an interruption in network connection. If there is such a setting then, when the IDLE connection drops due to network interruptions, there wouldn't be a delay in getting a new connection to the server.

If you think this is worth it, I can submit a new feature request at the thunderbird project. Thanks!

plantroon commented 2 months ago

I also run into this - IMAP idle is almost useless and doesn't work properly anywhere. That's why I used EAS in the past but it's buggy and unreliable. Maybe JMAP will fix things - new standards always do... /s

Btw, while almost unrelated, there exists a standard called Unified Push on Android. There's even a feature request for k9. But imap servers, afaik, don't support this.

jayb-g commented 1 month ago

I think it would be great if there can be a setting where IDLE renews when there is either a change in network connection or an interruption in network connection. If there is such a setting then, when the IDLE connection drops due to network interruptions, there wouldn't be a delay in getting a new connection to the server.

And I always thought that's how IMAP IDLE works, to be able to deliver push notifications instantly. Is that not how k9 does it? Is it not the standard way of doing it?

binki commented 1 month ago

I think it would be great if there can be a setting where IDLE renews when there is either a change in network connection or an interruption in network connection. If there is such a setting then, when the IDLE connection drops due to network interruptions, there wouldn't be a delay in getting a new connection to the server.

I wouldn’t expect this to be a setting. I’d expect this to be the default behavior. The IDLE connection should be reset (i.e., TCP reset) when switching between WiFi and data and the app should instantly reestablish the connection, try a couple times before backing off to save power if that fails, and retry instantly upon any network change which hints at a potential change in internet availability. If the IDLE connection doesn’t get reset, something like an application-layer ping should be sent during the refresh interval to force detection of the break (that is one of the purposes of that refresh setting, right?).

When this push connection dies, does it recover during the “normal” mail fetch interval? I am wondering about the OP’s experience. I noticed that I need to set both the normal fetch interval and push. Oftentimes push works and I get instant notifications, but often I won’t get a notification until the normal fetch interval. Ideally I could set my fetch interval high so that IDLE triggers fetch, but that just isn’t reliable enough. When I am sitting at my PC, that is fine because normally Thunderbird gets an instant notification when my phone doesn’t and vice versa x.x.

gunterkoenigsmann commented 1 month ago

To me this sounds like a energy saver built into the phone's OS that basically randomly kills services hoping that will kill the user experience

binki commented 1 month ago

To me this sounds like a energy saver built into the phone's OS that basically randomly kills services hoping that will kill the user experience

If that were the case, wouldn’t the normal “fetch mail” interval fail to work too? The app uses a foreground service/notification to avoid this and I have also configured the necessary “battery optimization” features for this app on my phone (this was already mentioned here). The instant push works most of the time but seems to sometimes get stuck and wait for the next “fetch mail” interval. I think that I sometimes see a similar (temporary) dropped push even on my desktop email client. I will try to be more attentive and keep this thread in mind.

@J0nnyMak0 I am wondering, do you have the “fetch mail” interval turned off completely in order to rely only on push? If you have it enabled, does your push functionality recover on the next interval (that might be hard to test if you need to check on the email)?