PUSH Stop working after closing app, but restart if clicking on "Tap to learn more" on bell notification

[mello7tre]

Checklist

• I have used the search function to see if someone else has already submitted the same bug report.
• I will describe the problem with as much detail as possible.

App

K-9 Mail

App version

8.2

Where did you get the app from?

F-Droid

Android version

14

Device model

Jelly Max

Steps to reproduce

1. Turn on Push for inbox folder (with relative permission to schedule alarm)
2. Launch App
3. Close App
4. notification bell in status bar disappear and after few seconds appear again
5. send mail
6. no notification
7. pull down notification area and click on Waiting for new emails and then Tap to learn more (informative windows appear)
8. notification for previous mail arrive immediately

Expected behavior

If there is notification service active and bell notification icon i expect that push notification should work.

Actual behavior

Seems that when application is closed, imap idle connection is closed too, then bell notification reappear but push notification do not work anymore until i click on "tap to learn more".

Logs

It's a strange behavior, consider that the push service is always running i can see from Android "Developer Option/Running service" that it's never stopped, it's even listed in "Active Apps" warning with running time equals to boot time (i attach a screen).
I own the mail server that i use for imap push, so i have looked at the mail logs; when application is stopped IMAP idle connection is closed.
Then even if bell icon reappear in notification status bar, connection is not re-established until i click on "Tap to learn more".
As soon as i click on "Tap to learn more" imap connection is established and if there are pending emails i am immediately notified.

[cketti]

What exactly do you mean by "Close App"? It sounds like you're killing the app and it is immediately restarted by the system because it had an active foreground service. If that's the case, please don't kill the app. Just move it to the background.

With the push service active the app should be counted as being in the foreground. However, if that's not working properly and the app is denied network access in the background, it would explain the behavior you're seeing. If background data is disabled for the app, try enabling it (in Android's "App info" screen for the app).

If none of the above helps, please enable debug logging in settings. Then perform all steps to reproduce the issue. Then export the log and attach it here.

[mello7tre]

For "close App", i simply swipe up on the recent task window.
K9 is configured to use background data and is not power optimized.
Tomorrow i will try to catch a log while closing the app, thanks.

[cketti]

For "close App", i simply swipe up on the recent task window.

Don't do that. It will kill the app which will terminate all connections to the mail server(s). Android then restarts the app because of the push service. But all connections will have to be re-established. This is most likely not the cause of your problem. But it might be a contributing factor. At the very least it's an unnecessary drain on your battery.

[mello7tre]

I attach k9 debug log up to closing the app and adb logcat relative to com.fsck.k9 (grep -i com.fsck.k9).

k9mail-logs-obs.txt
logcat-k9.log

[cketti]

The logs seem to be missing the relevant protocol communication data. Please use the export using the app method to save the debug log.

[mello7tre]

I have followed the instructions on the wiki Learn how to report it and used export log inside k9 mail app

[cketti]

Hm. If you didn't manually remove entire lines of the log after the export, there's something wrong with your app installation. Please uninstall the app and reinstall.

[mello7tre]

I do not have flagged "log sensitive data", but apart replacing my account and server with XXXXX and YYYYYY i do not have removed anything.
I see multiple messages like:

01-16 09:41:04.849  2646  2670 I ImapSync: Done synchronizing folder XXXXX at YYYYYY:INBOX
01-16 09:41:04.850  2646  2670 I MessagingController:  Command 'synchronizeMailbox' completed
01-16 09:41:04.850  2646  2670 I MessagingController: Running command 'clearNotifications', seq = 2 (foreground priority)
01-16 09:41:04.851  2646  2670 I MessagingController:  Command 'clearNotifications' completed 
01-16 09:41:04.851  2646  2670 I MessagingController: Running command 'clearNotifications', seq = 7 (foreground priority)
01-16 09:41:04.851  2646  2670 I MessagingController:  Command 'clearNotifications' completed
01-16 09:41:04.851  2646  2670 I MessagingController: Running command 'synchronizeMailbox', seq = 1 (background priority)
01-16 09:41:04.852  2646  2670 I ImapSync: Synchronizing folder XXXXX at YYYYYY:Sent
01-16 09:41:06.474  2646  2670 I ImapSync: Done synchronizing folder XXXXX at YYYYYY:Sent
01-16 09:41:06.474  2646  2670 I MessagingController:  Command 'synchronizeMailbox' completed
01-16 09:41:06.474  2646  2670 I MessagingController: Running command 'synchronizeMailbox', seq = 3 (background priority)
01-16 09:41:06.474  2646  2670 I ImapSync: Synchronizing folder XXXXX at YYYYYY:INBOX
01-16 09:41:07.396  2646  2670 I ImapSync: Done synchronizing folder XXXXX at YYYYYY:INBOX
01-16 09:41:07.397  2646  2670 I MessagingController:  Command 'synchronizeMailbox' completed
01-16 09:41:07.397  2646  2670 I MessagingController: Running command 'synchronizeMailbox', seq = 4 (background priority)
01-16 09:41:07.397  2646  2670 I ImapSync: Synchronizing folder XXXXX at YYYYYY:Sent
01-16 09:41:08.314  2646  2670 I ImapSync: Done synchronizing folder XXXXX at YYYYYY:Sent
01-16 09:41:08.314  2646  2670 I MessagingController:  Command 'synchronizeMailbox' completed
01-16 09:41:08.314  2646  2670 I MessagingController: Running command 'synchronizeMailbox', seq = 5 (background priority)
01-16 09:41:08.315  2646  2670 I ImapSync: Synchronizing folder XXXXX at YYYYYY:Sent

Apart that i need to click on notification every time i close (swipe app) k9 mail to re-enable push, application works without any problem, so reinstalling it do not seems a probable solution...

[cketti]

The file is missing log messages of the communication with the IMAP server. This is not a user-configurable setting. If debug logging is enabled, that information is always included. This suggests the app code is corrupted. And if this corruption impacts logging, why not also push? But even if the corruption doesn't impact push, a working log system is required to diagnose the push problem.

You can of course choose to not reinstall the app. But then we've reached the end of this investigation and you're on your own with this problem.

[mello7tre]

Reinstalled App, enabled debug even enabled "log sensitive data", completely stopped app from "App info page", relaunched it but the log output is always the same!
App have been installed by fdroid.
The message E com.fsck.k9: Not starting debugger since process cannot load the jdwp agent. can be the cause of missing communication data ?

[mello7tre]

Found out that to show verbose log i need to do:
adb shell setprop persist.log.tag V
maybe can be added in wiki as advice if VERBOSE log tag are missing.
Now log is over 1.2MB, do you prefer that i post it full?
(If i skip SQLite tag, it's became "only" 247K, maybe it's better to post this one)

[cketti]

Found out that to show verbose log i need to do:
adb shell setprop persist.log.tag V

Interesting. I've never heard of the default on a device not include all log messages from an app. Have you used adb shell setprop persist.log.tag with a different value before?

Now log is over 1.2MB, do you prefer that i post it full?
(If i skip SQLite tag, it's became "only" 247K, maybe it's better to post this one)

The one without the SQLite tag is probably enough.

[mello7tre]

Interesting. I've never heard of the default on a device not include all log messages from an app. Have you used adb shell setprop persist.log.tag with a different value before?

No i never changed it, i have this cell from 1 month..

Now log is over 1.2MB, do you prefer that i post it full?
(If i skip SQLite tag, it's became "only" 247K, maybe it's better to post this one)

The one without the SQLite tag is probably enough.

k9mail-logs-01.txt
(as before i have replaced account name with XXXXX and server name with YYYYY)

I have launched k9, enabled debug, closed k9, reopened (waiting for sync) and exported debug, please tell me if need to make other actions, thanks.

[cketti]

It looks like the log buffer is too small to hold all relevant information. The log only contains information about the time when you reopened the app to export the log. By that time push had already recovered and from the log it looks like it was working fine.

Can you connect the phone to the PC and record a log using adb? When you record the log, please make sure to wait a while between killing the app and re-opening it to give the push service a chance to start again in the background. It's most likely that this is the time where something goes wrong, i.e. the push service is started and the "waiting for new emails" notification is displayed, but the connection to the mail server is not properly established.

[mello7tre]

It's not so easy, directly using adb the log (with verbosity increased) is quite big and confusing.
And i cannot use the --pid method because as task get killed the pid change.
I tried with:

adb shell 'logcat | egrep -v "(AALService|mtk_storageproxyd|ULogGuard|BatteryChangeCtroller)"' | egrep --line-buffered -i "(k9|imap)" | grep --line-buffered -v SQLite

i attach the log

• after closing k9
  log_kill.txt
  last lines are:

01-17 18:57:15.257 23674 23674 V K9JobManager: scheduling all jobs
01-17 18:57:15.257 23674 23674 V K9JobManager: canceling mail sync job

canceling mail sync job is suspicious...

• and when tapping on the notification:
  log_notify_obs.txt
  imap connection to server is present

[cketti]

You've left out the important part between killing the app and opening a screen of the app. That "closing" the app will kill the process and stop push is not in question or a problem. That opening an app screen, e.g. "push info" will restart push and things continue to work is not in question or a problem.

The problem is that shortly after killing the app the OS restarts the push service as expected, but the app won't actually connect to the mail server to listen for new messages. That is what (should) happen after killing the app and before manually opening a screen of the app. We need logs of that time period.