Sync stopped working, nothing to go by in terms of debugging



  • I did a dirty reflash of the ROM and wiped Dalvik/Cache, and it’s been working since then. Still curious to find out what happened… let’s see if it comes back!



  • It’s back within less than a day. The “Firefox method” doesn’t work, and neither does restarting.

    Wiping cache and Dalvik does seem to make it work again. Now I feel like I have a lead, and will try wiping app caches instead of Dalvik next time it happens.

    I do wonder what the system app behind the sync threads are. Any idea?



  • This issue is still ongoing, and it’s a real pain as I cannot use my calendar on the device. I am at the point where I will need to reinstall, which is just terrible to be honest, because it’s such a waste of time. I’ll try one more time and maybe you guys have an idea? cc. @devvv4ever @rfc2822

    If DAVDroid and Firefox are both using the Android Sync Framework, and both are not syncing, then maybe the problem is with the sync framework. If I manually tell Firefox to run a sync, the logs will just show:

    I FxAccounts: firefox :: FirefoxAccounts :: Requesting sync.
    I FxAccounts: firefox :: FirefoxAccounts :: Sync options -- scheduling now: true
    

    If I manually tell DAVDroid to sync, I get no log output. There is a toast saying “Synchronize now” for 5 seconds, but no progress indicator appears under the calendar/addressbook resources, as it would when an actual sync is running. This makes me think that maybe the same thing is happening, i.e. the sync is being scheduled, but then never executed.

    I am not sure how the Android Sync Service works, or how to verify that it works. But I did stumble over this explanation of how Oreo changed wrt. background services, and since the problem started to appear after my upgrade to Oreo, I wonder if there is maybe a lead here? Could it be that DAVDroid is still using AlarmManager, rather than JobScheduler? A grep of the source code unfortunately revealed no matches for either.

    I also found the following log entries during boot, which may well be related too:

    11-30 10:44:29.552  4057  4057 W AlarmManagerEXT: Out of bounds, Allowed Values 1s ~ 3600s, Setting syncInterval : 300000
    11-30 10:44:29.552  4057  4057 W AlarmManagerEXT: Out of bounds, Allowed Values 1s ~ 225s, Setting deltaFromTriggers : 10000
    […]
    11-30 10:44:31.874  4057  4620 E Watchdog: !@Sync 0 [2018-11-30 10:44:31.874]
    […]
    11-30 10:44:32.709  4057  4057 W ContextImpl: Calling a method in the system process without a qualified user: android.app.ContextImpl.startService:0 com.android.server.content.SyncManager$13.run:8 android.os.Handler.handleCallback:2 android.os.Handler.dispatchMessage:4 android.os.Looper.loop:139
    

    At least the first two suggest that something is wrong with AlarmManager, which is somehow set to run every 300000s, which is almost 4 days. However, the last successful sync is now 6 days old.

    So I am really at a loss, and would greatly appreciate any help or insights.

    Thank you,
    martin



  • I found out more stuff.

    So in the Android settings dialog, under accounts, if I go to a DAVDroid account and choose “Sync Account”, I take note that all syncs are enabled.

    If I choose “sync now” under the menu, nothing happens, except the menu changes to “cancel sync”. If I choose “cancel sync”, then it goes back to sync now.

    Toggling the slider on e.g. “Sync Calendar” has no effect.

    Except I’ve seen the arrow-circle start turning (though the DAV server sees no traffic). And occasionally, I’ve now run into the error message at the bottom, that “Sync is currently experiencing problems. It will be back shortly”:

    0_1543533997596_Screenshot_20181130-121519_Settings.jpg

    Nothing in logcat about that though.

    Finally, I took note that every time I want to sync with DAVDroid, the following is logged:

    11-30 12:20:05.139  4075  5727 D SecContentProvider: query(), uri = 16 selection = isGoogleAccountsAutoSyncAllowed
    

    I do not have any Google accounts or services running on this phone, and I don’t think that this should really affect DAVDroid either, because it has sync’d in the past on this install.

    Please help. 😞



  • Hi madduck,

    sorry, I can’t provide any help in here - just wanted to give you one more voice.
    Thanks for your research so far!

    I have exactly the same problem:

    • first -time setup works fine, calendars are synced
    • “some” time later (about next day) syncing stops
    • manual sync has no effect except toast showing “syncing started” - the “colored moving line” which usually comes up while syncing does not show
    • nothing to find in logs (logcat nor davdroid logs)
    • no (HTTP-)request is logged by the server
    • (manual) reloading the calendars (not the events, “Kalender neu erkennen”) works fine
    • manual re-installation of Android re-enables the sync, scheduled and manual sync works fine
    • wiping DALVIK/ART-cache re-enables syncing

    My phone is on LineageOS 15.1 = Android 8.1.0

    As I don’t sync any other services/apps I can’t check the alternatives.

    Regards
    MG



  • Well - I have to correct one thing in my list above:

    • it’s not necessary to wipe the DALVIK-cache, a reboot re-enables the sync (on reboot the calendars are synced immediately, manual sync works also)

    Cheers
    MG



  • Hey @MadGoose, thanks for the input. Are you using something like TitantiumBackup to freeze services?

    Here is what I found out recently:

    I have been freezing Google and Samsung software that unfortunately comes pre-installed. It turns out that the Android sync framework, while independent (and a core service of Android), does somehow link into these services. Long story short — I don’t really understand all this — I thawed the services, rebooted and wiped Dalvik/Cache, then refroze the services after the boot, and now it’s working fine again.

    I wish I knew what’s going on…



  • Hi there,

    well I found some time just to verify the logs (I can recommend “MatLog Libre”, https://f-droid.org/de/packages/com.pluscubed.matloglibre/ to write logcat to file on the phone).
    It looks like the davdroid is just killed by the system (what’s usual in android), but davdroid does not start again by its own and can’t be started manually after that kill.
    So @madduck - maybe my problem is different from yours.

    Typically the last lines in the log are like these:

    ------------> end of last sync
    12-09 22:01:21.723 22195 23304 I davdroid: [syncadapter.CalendarsSyncAdapterService] Calendar sync complete
    12-09 22:01:21.725 22195 23304 I davdroid: [syncadapter.SyncAdapterService] Sync for (com.android.calendar, Account {name=XXX, type=bitfire.at.davdroid}) finished
    ------------> process gets killed
    12-09 22:34:52.955  1068  1728 I ActivityManager: Killing 22195:at.bitfire.davdroid:sync/u0a216 (adj 906): empty for 2011s
    12-09 22:34:53.105  1068  1731 W zygote  : kill(-22195, 9) failed: No such process
    12-09 22:34:53.105  1068  1731 I zygote  : Successfully killed process cgroup uid 10216 pid 22195 in 0ms
    
    ------------> end of last sync
    12-12 20:22:03.779  4654  7831 I davdroid: [syncadapter.CalendarsSyncAdapterService] Calendar sync complete
    12-12 20:22:03.781  4654  7831 I davdroid: [syncadapter.SyncAdapterService] Sync for (com.android.calendar, Account {name=XXX, type=bitfire.at.davdroid}) finished
    ------------> process gets killed
    12-12 21:09:01.420  1260  4329 I ActivityManager: Killing 4654:at.bitfire.davdroid:sync/u0a216 (adj 906): empty for 2817s
    12-12 21:09:01.421  1260  1732 W zygote  : kill(-4654, 9) failed: No such process
    12-12 21:09:01.459  1260  1732 W zygote  : kill(-4654, 9) failed: No such process
    12-12 21:09:01.459  1260  1732 I zygote  : Successfully killed process cgroup uid 10216 pid 4654 in 38ms
    ------------> manual restart
    12-12 22:36:02.565  1260  4328 I ActivityManager: START u0 {cmp=at.bitfire.davdroid/.ui.AccountActivity (has extras)} from uid 10216
    12-12 22:36:02.637  4728  7733 W Adreno-EGL: <qeglDrvAPI_eglGetConfigAttrib:607>: EGL_BAD_ATTRIBUTE
    12-12 22:36:02.639  4728  7733 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace.
    12-12 22:36:02.682  1260  1746 I ActivityManager: Displayed at.bitfire.davdroid/.ui.AccountActivity: +101ms
    
    ------------> end of last sync
    12-13 16:19:18.054 I/davdroid( 4757): [syncadapter.CalendarsSyncAdapterService] Calendar sync complete
    12-13 16:19:18.060 I/davdroid( 4757): [syncadapter.SyncAdapterService] Sync for (com.android.calendar, Account {name=XXX, type=bitfire.at.davdroid}) finished
    ------------> process gets killed
    12-13 16:24:20.940 I/ActivityManager( 1042): Killing 4757:at.bitfire.davdroid:sync/u0a216 (adj 906): empty #17
    12-13 16:24:20.946 W/zygote  ( 1042): kill(-4757, 9) failed: No such process
    12-13 16:24:20.980 W/zygote  ( 1042): kill(-4757, 9) failed: No such process
    12-13 16:24:20.980 I/zygote  ( 1042): Successfully killed process cgroup uid 10216 pid 4757 in 33ms
    ------------> manual restart
    12-13 22:23:40.511  1042  2985 I ActivityManager: Start proc 5172:at.bitfire.davdroid/u0a216 for activity at.bitfire.davdroid/.ui.AccountsActivity
    12-13 22:23:40.698  5172  5172 I davdroid: Verbose logging: false; to file: false
    12-13 22:23:40.717  5172  5192 I davdroid: [PackageChangedReceiver] Package (un)installed; OpenTasks provider now available = false
    12-13 22:23:40.892  1042  3064 W ActivityManager: Unable to start service Intent { cmp=at.bitfire.davdroid/.ui.AccountsActivity$Settings } U=0: not found
    12-13 22:23:40.914  5172  5196 D OpenGLRenderer: HWUI GL Pipeline
    12-13 22:23:40.924  5172  5172 I davdroid: [settings.Settings] Initializing Settings service
    12-13 22:23:41.125  1042  1741 I ActivityManager: Displayed at.bitfire.davdroid/.ui.AccountsActivity: +630ms
    12-13 22:23:42.395  5172  5196 D vndksupport: Loading /vendor/lib/hw/gralloc.msm8974.so from current namespace instead of sphal namespace.
    12-13 22:23:42.468  1042  1741 I ActivityManager: Displayed at.bitfire.davdroid/.ui.AccountActivity: +156ms
    
    

    I’m not too firm with android killing apps but there’s an interesting article at https://medium.com/inloopx/android-process-kill-and-the-big-implications-for-your-app-1ecbed4921cb which might explain the problem.

    (Well, yes I switched off “battery optimisation” for davdroid.)

    Other apps that are killed regularly get restartet again, for example:

    12-13 16:24:13.187  1042  4441 I ActivityManager: Killing 14881:se.stephanson.YRWidgetHD/u0a85 (adj 906): empty #17
    12-13 16:24:13.805  1042 22888 I ActivityManager: Start proc 22951:se.stephanson.YRWidgetHD/u0a85 for broadcast se.stephanson.YRWidgetHD/se.stephanson.YRWidgetLibrary.NetworkStateReceiver
    12-13 20:35:30.240  1042  4441 I ActivityManager: Killing 22951:se.stephanson.YRWidgetHD/u0a85 (adj 906): empty #18
    12-13 20:37:00.499  1042 22890 I ActivityManager: Start proc 29752:se.stephanson.YRWidgetHD/u0a85 for broadcast se.stephanson.YRWidgetHD/se.stephanson.YRWidgetLibrary.NetworkStateReceiver
    12-13 21:07:13.658  1042  1536 I ActivityManager: Killing 29752:se.stephanson.YRWidgetHD/u0a85 (adj 906): empty for 1807s
    12-13 22:27:03.184  1042  1536 I ActivityManager: Start proc 5368:se.stephanson.YRWidgetHD/u0a85 for broadcast se.stephanson.YRWidgetHD/se.stephanson.YRWidgetLibrary.WidgetProvider
    12-13 16:24:13.187  1042  4441 I ActivityManager: Killing 14881:se.stephanson.YRWidgetHD/u0a85 (adj 906): empty #17
    12-13 16:24:13.805  1042 22888 I ActivityManager: Start proc 22951:se.stephanson.YRWidgetHD/u0a85 for broadcast se.stephanson.YRWidgetHD/se.stephanson.YRWidgetLibrary.NetworkStateReceiver
    12-13 20:35:30.240  1042  4441 I ActivityManager: Killing 22951:se.stephanson.YRWidgetHD/u0a85 (adj 906): empty #18
    12-13 20:37:00.499  1042 22890 I ActivityManager: Start proc 29752:se.stephanson.YRWidgetHD/u0a85 for broadcast se.stephanson.YRWidgetHD/se.stephanson.YRWidgetLibrary.NetworkStateReceiver
    12-13 21:07:13.658  1042  1536 I ActivityManager: Killing 29752:se.stephanson.YRWidgetHD/u0a85 (adj 906): empty for 1807s
    12-13 22:27:03.184  1042  1536 I ActivityManager: Start proc 5368:se.stephanson.YRWidgetHD/u0a85 for broadcast se.stephanson.YRWidgetHD/se.stephanson.YRWidgetLibrary.WidgetProvider
    
    

    Maybe davdroid is just not prepared for Android 8 (or 7+)?

    Cheers
    MG


  • developer

    @MadGoose As far as I know, synchronization threads should not be killed by the system. They can be interrupted (and then killed), but we would see that in the logs. Synchronization threads are different from normal apps, which can be killed as soon as they are in background (and there is no foreground notification).

    In your logs, DAVdroid is killed when the synchronization has been finished. This is absolutely OK and working as intended.

    but davdroid does not start again by its own

    DAVdroid never starts itself. It’s being started by Android’s synchronization framework.

    Maybe davdroid is just not prepared for Android 8 (or 7+)?

    There are 10.000s of working installations with Android 7 and newer (including my own one). However, if you find out any specific thing what could be missing, please let me know…



  • @rfc2822 I’m fully with you that processes can be killed by the system. And you’re right - I should have been more precise when writing that “davdroid does not start again” I meant “does not start again and is not started again” - opposite to other processes.
    As you seem to know Android much better than me it would have been great to provide some hints to debug that situation better.

    Nevertheless it seems that I have found the cause for my not-synchronizing my calendars:
    Android (or should I say Google?) checks the internet-connectivity with it’s so-called “captive portal detection”.
    Whenever the network state changes, Android sends requests to different google servers.
    When these requests are answered by a login page (instead of the expected google-answer), Android presumes that you need to login somewhere to enable internet connectivity.
    If no connection can be enabled - for example because “captive portal” is blocked by a firewall - Android thinks that the internet is not reachable and shows this with a little “x” near the wifi-connection symbol. (And sometimes ask you whether you want to continue using that connection.)
    When Android thinks that there is no internet connection, it disables a diversity of other services - seemingly also synchronisation tasks.
    On rooted phones you can switch off the “captive portal service” by issuing this command:

    settings put global captive_portal_detection_enabled 0
    

    via root shell or adb root shell (the local shell sometimes needs two “su”).
    See also: https://android.stackexchange.com/questions/100657/how-to-disable-captive-portal-detection-how-to-remove-exclamation-mark-on-wi-fi

    Since inssuing this command, my calendars get synchronized again.

    Regards
    MG


  • developer

    @MadGoose Thanks for sharing your solution!

    So, your problem was basically firewall settings which were incompatible with the way how Android detects Internet connection, so that synchronization was never started (not only of DAVdroid, but all account types).

    By the way, you can also use settings put global captive_portal_server <yourserver> and create your own captive portal server 🙂 It only has to return HTTP 204. (Side effect: you also have the IP address of your device in your Web server logs.) I had this up and running once, but I don’t know whether this settings still works with current Android versions.


  • developer

    Assuming that this was the problem in the original posting, too and marking as solved. If not, I can reopen.



  • For the record, I don’t have the capitve portal service enabled, and this was not the root cause of my problem. I described how I solved it on 2018-12-08, and even though I don’t actually know what exactly went wrong, it’s been fixed ever since.

    Next time I suggest to keep separate issues in separate threads, please.



  • … spoke to soon. The problem is back. Syncing stopped working again, exhibiting the exact same symptoms as before.

    I went ahead to disable the captive portal detection and rebooted, and now it’s synchronising again. So maybe this was the problem, after all, though I don’t understand why it would have worked in the past.



  • @rfc2822 said in Sync stopped working, nothing to go by in terms of debugging:

    @MadGoose Thanks for sharing your solution!

    So, your problem was basically firewall settings which were incompatible with the way how Android detects Internet connection, so that synchronization was never started (not only of DAVdroid, but all account types).

    Well, not quite:

    • DAVDroid synced after a reboot for a certain time - just until i got killed (by the system?). It just was not restarted to continue synchronization.
    • All other apps continued their “synchronization” - but I guess all other apps I use do not rely on the synchronization framework by Android but use other methods to restart after having been killed by the system.

    But for sure it was no DAVdroid-related problem but the - in my opinion - not too clear documented (well, where could that be found?) behavior of synchronization framework and “internet connectivity detection”.

    Cheers
    MG


Log in to reply