thunderbird
IMAP IDLE push dies intermittently
Checklist
- [X] I have used the search function to see if someone else has already submitted the same bug report.
- [X] I will describe the problem with as much detail as possible.
App version
6.000
Where did you get the app from?
Google Play
Android version
10
Device model
No response
Steps to reproduce
- I'm connected to the imap server
- With IDLE refresh set to 24 minutes (default)
- And "Max folders to check with push" set to 5
- k9 works fine for days on end with push notifications to my Inbox working great
- 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]]]
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.
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.txtuseadb 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.
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.
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?
Good question. I don't have time to check right now. I'm guessing the text won't change.
This is still happening from time to time. This is what I was able to capture with the suggested method. k9log.txt
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.
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)
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!
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.
