Calendar sync stopping midway



    • Email: Zimbra 8.7.11_GA_1854 (build 20170531151956)
    • Phone: Moto G4 Plus RR-N-v5.8.5-20171022-athene-Final
    • Android: 7.1.2
    • DAVDroid: 1.9-ose (182)
      • Battery optimisation exemption has been activated and all permissions have been granted
      • Calendar sync is set to ignore events older than 90 days old

    When doing an initial sync, watching in logcat shows normal sync behaviour.

    11-02 19:11:14.167  9191 10599 I davdroid: [syncadapter.CalendarSyncManager] Downloading 223 events (20 at once)
    

    After syncing about 80 calendar events, the following lines appear in logcat, then sync stops

    11-02 19:12:11.572   985  1012 W SyncManager: Detected sync making no progress for startTime 1042473, mTimeoutStartTime 1042473, mHistoryRowId 37, syncOperation JobId: 105829, user@server.com.au u0 (bitfire.at.davdroid), com.android.calendar, USER, EXPEDITED, reason: 10175. cancelling.
    11-02 19:12:11.579  9191  9191 E ActivityThread: Service at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService has leaked ServiceConnection at.bitfire.cert4android.CustomCertManager$1@5668dfc that was originally bound here
    11-02 19:12:11.579  9191  9191 E ActivityThread: android.app.ServiceConnectionLeaked: Service at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService has leaked ServiceConnection at.bitfire.cert4android.CustomCertManager$1@5668dfc that was originally bound here
    11-02 19:12:11.579  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.HttpClient$Builder.<init>(HttpClient.kt:96)
    11-02 19:12:11.579  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.HttpClient$Builder.<init>(HttpClient.kt:48)
    11-02 19:12:11.579  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.syncadapter.SyncManager.<init>(SyncManager.kt:69)
    11-02 19:12:11.579  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.syncadapter.CalendarSyncManager.<init>(CalendarSyncManager.kt:52)
    11-02 19:12:11.579  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService$SyncAdapter.sync(CalendarsSyncAdapterService.kt:54)
    11-02 19:12:11.579  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:57)
    11-02 19:12:11.589  9191  9191 E ActivityThread: Service at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService has leaked ServiceConnection at.bitfire.davdroid.settings.Settings$Companion$getInstance$serviceConn$1@b2e06b8 that was originally bound here
    11-02 19:12:11.589  9191  9191 E ActivityThread: android.app.ServiceConnectionLeaked: Service at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService has leaked ServiceConnection at.bitfire.davdroid.settings.Settings$Companion$getInstance$serviceConn$1@b2e06b8 that was originally bound here
    11-02 19:12:11.589  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.settings.Settings$Companion.getInstance(Settings.kt:234)
    11-02 19:12:11.589  9191  9191 E ActivityThread: 	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:51)
    11-02 19:12:11.593  8919  8919 I davdroid: [settings.Settings] Shutting down Settings service
    11-02 19:12:11.789  9191 10599 I davdroid: [syncadapter.CalendarSyncManager] Adding bac1e494-e392-43cc-9150-9f893040a4da.ics to local calendar
    11-02 19:12:11.886  9191 10599 I davdroid: [syncadapter.SyncManager] Post-processing
    11-02 19:12:11.888  9191 10599 I davdroid: [syncadapter.SyncManager] Saving sync state
    11-02 19:12:11.889  9191 10599 I davdroid: [syncadapter.SyncManager] Saving CTag=35-2205731
    11-02 19:12:11.926  9191 10599 W cert4android: 	at at.bitfire.davdroid.HttpClient.close(HttpClient.kt:40)
    11-02 19:12:11.926  9191 10599 W cert4android: 	at at.bitfire.davdroid.syncadapter.SyncManager.close(SyncManager.kt:240)
    11-02 19:12:11.926  9191 10599 W cert4android: 	at at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService$SyncAdapter.sync(CalendarsSyncAdapterService.kt:54)
    11-02 19:12:11.926  9191 10599 W cert4android: 	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:57)
    11-02 19:12:11.927  9191 10599 I davdroid: [syncadapter.CalendarsSyncAdapterService] Calendar sync complete
    11-02 19:12:11.929  9191 10599 E davdroid: [settings.Settings] Couldn't unbind Settings service
    11-02 19:12:11.929  9191 10599 E davdroid: EXCEPTION java.lang.IllegalArgumentException: Service not registered: at.bitfire.davdroid.settings.Settings$Companion$getInstance$serviceConn$1@b2e06b8
    11-02 19:12:11.929  9191 10599 E davdroid: 	at android.app.LoadedApk.forgetServiceDispatcher(LoadedApk.java:1289)
    11-02 19:12:11.929  9191 10599 E davdroid: 	at android.app.ContextImpl.unbindService(ContextImpl.java:1483)
    11-02 19:12:11.929  9191 10599 E davdroid: 	at android.content.ContextWrapper.unbindService(ContextWrapper.java:648)
    11-02 19:12:11.929  9191 10599 E davdroid: 	at at.bitfire.davdroid.settings.Settings$Stub.close(Settings.kt:206)
    11-02 19:12:11.929  9191 10599 E davdroid: 	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:56)
    11-02 19:12:11.929  9191 10599 E davdroid: 	at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:272)
    11-02 19:12:11.930  9191 10599 I davdroid: [syncadapter.SyncAdapterService] Sync for com.android.calendar complete
    11-02 19:12:11.974   985  1012 D SyncManager: handleSyncHandlerMessage: dropping since the sync is no longer active: startTime 1042473, mTimeoutStartTime 1042473, mHistoryRowId 37, syncOperation JobId: 105829, user@server.com.au u0 (bitfire.at.davdroid), com.android.calendar, USER, EXPEDITED, reason: 10175
    

    Something seems to be terminating the sync, but I'm unable to pinpoint what it is.
    I'm able to resume a sync normally, and then sync will restart, then stop after about 80 more events, eventually there is nothing left to sync, but this issue happens each iteration of syncing before the full calendar set is synced.


  • developer

    Seems like this is the reason why Android's SyncManager stops the synchronization:

    11-02 19:12:11.572 985 1012 W SyncManager: Detected sync making no progress for startTime 1042473, mTimeoutStartTime 1042473, mHistoryRowId 37, syncOperation JobId: 105829, user@server.com.au u0 (bitfire.at.davdroid), com.android.calendar, USER, EXPEDITED, reason: 10175. cancelling.

    This is strange, I'll have a look at that and try to find out why Android thinks there's no progress.


  • developer

    Those are mixed logs for contacts and calendar sync. Can you please post the complete logs or send them to play@bitfire.at?



  • @rfc2822 those logs were from me adding a single calendar only. They are also filtered with adb logcat | grep davdroid
    Do you want me to delete that calendar profile (and probably all others to avoid log noise pollution) and readd it to capture an entire adb logcat | grep davdroid?


  • developer

    Yes, I think those logs could be useful.



  • @rfc2822 I've emailed you the full log.

    Here are some extra details which might be helpful

    • sync starting normally on each 15 minute interval, but does not seem to pick up outstanding balance of unsynced items unless manual sync button is pressed in davdroid
    • 09:42 created "debug test1" in Zimbra calendar
    • 11-03 09:52:20.810 9760 15487 I davdroid: [syncadapter.CalendarsSyncAdapterService] Synchronizing calendar #12, URL: ....
    • 11-03 09:52:23.896 9760 15487 I davdroid: [syncadapter.CalendarSyncManager] Downloading 158 events (20 at once)
    • sync proceeded as normal after event in zimbra was created
    • 11-03 09:53:20.379 992 1019 W SyncManager: Detected sync making no progress for startTime 5272337, mTimeoutStartTime 5272337, mHistoryRowId 65, syncOperation JobId: 107225, user@server.com.au u0 (bitfire.at.davdroid), com.android.calendar, PERIODIC, reason: Periodic, period: 900000, flexMillis: 36000. cancelling.

    I ran out of time to wait more 15 minute intervals, so please let me know if you need anything specific tested

    Thanks for your help


  • developer

    You can find the string "Detected sync making no progress for %s. cancelling." in Android's SyncManager:

                            if (isSyncNotUsingNetworkH(monitoredSyncContext)) {
                                Log.w(TAG, String.format(
                                        "Detected sync making no progress for %s. cancelling.",
                                        monitoredSyncContext));
    
    // …
    
            private boolean isSyncNotUsingNetworkH(ActiveSyncContext activeSyncContext) {
                final long bytesTransferredCurrent =
                        getTotalBytesTransferredByUid(activeSyncContext.mSyncAdapterUid);
                final long deltaBytesTransferred =
                        bytesTransferredCurrent - activeSyncContext.mBytesTransferredAtLastPoll;
                if (Log.isLoggable(TAG, Log.DEBUG)) {
                    // Bytes transferred
                    long remainder = deltaBytesTransferred;
                    long mb = remainder / (1024 * 1024);
                    remainder %= 1024 * 1024;
                    long kb = remainder / 1024;
                    remainder %= 1024;
                    long b = remainder;
                    Log.d(TAG, String.format(
                            "Time since last update: %ds. Delta transferred: %dMBs,%dKBs,%dBs",
                            (SystemClock.elapsedRealtime()
                                    - activeSyncContext.mLastPolledTimeElapsed)/1000,
                            mb, kb, b)
                    );
                }
                return (deltaBytesTransferred <= SYNC_MONITOR_PROGRESS_THRESHOLD_BYTES);
            }
    

    So, the sync is aborted when there has been no network traffic since a certain time. It seems threads will be aborted when there's less than 10 bytes transmitted in 60 seconds.

    However, DAVdroid has downloaded the events at 9:53:17

    11-03 09:53:17.548 9760 15487 I davdroid: [syncadapter.CalendarSyncManager] Downloading

    and the error occured at 9:53:20:

    11-03 09:53:20.379 992 1019 W SyncManager: Detected sync making no progress for startTime 5272337, mTimeoutStartTime 5272337, mHistoryRowId 65, syncOperation JobId: 107225, xxxx@xxxxx.com.au u0 (bitfire.at.davdroid), com.android.calendar, PERIODIC, reason: Periodic, period: 900000, flexMillis: 36000. cancelling.

    Very strange, and I haven't seen that yet elsewhere … unfortunately, I don't have an idea about that problem.



  • @rfc2822 How is there less than 10 bytes being transmitted if the sync is running? Wouldn't the sync data itself contribute to the data being counted and keep the counter well over 10 bytes until the sync is complete?

    do you want me to run another locgat and include a grep filter for SyncManager as well?

    Another question, why would creating a new event in the calendar(from the zimbra side) cause the balance of items to start syncing again?


  • developer

    @zstephen said in Calendar sync stopping midway:

    @rfc2822 How is there less than 10 bytes being transmitted if the sync is running? Wouldn't the sync data itself contribute to the data being counted and keep the counter well over 10 bytes until the sync is complete?

    Indeed. This is how it should work, and why I don't understand the problem. As said before, I have never experienced or heard of the problem before, so it seems to be quite special.

    do you want me to run another locgat and include a grep filter for SyncManager as well?

    Maybe it could provide additional information. Every new hint could be helpful.

    Another question, why would creating a new event in the calendar(from the zimbra side) cause the balance of items to start syncing again?

    Are you sure that the automatic sync does not continue to download events? If you add an event on the server, the CTag changes. DAVdroid checks the CTag at the beginning of the sync, and synchronizes only when the CTag has changed. However, the CTag is remembered at the end of a successful sync, so DAVdroid should re-try after incomplete synchronization.



  • @rfc2822 said in Calendar sync stopping midway:

    @zstephen said in Calendar sync stopping midway:

    @rfc2822 How is there less than 10 bytes being transmitted if the sync is running? Wouldn't the sync data itself contribute to the data being counted and keep the counter well over 10 bytes until the sync is complete?

    Indeed. This is how it should work, and why I don't understand the problem. As said before, I have never experienced or heard of the problem before, so it seems to be quite special.

    do you want me to run another locgat and include a grep filter for SyncManager as well?

    Maybe it could provide additional information. Every new hint could be helpful.

    I've started another logcat recording session, I'll allow it to run overnight and I won't press manual sync. I have noticed that another batch of the balance of unsynced events is only being attempted if I create an event in zimbra. When I create an event, the phone will sync another batch when the next 15 minute interval passes around.

    Another question, why would creating a new event in the calendar(from the zimbra side) cause the balance of items to start syncing again?

    Are you sure that the automatic sync does not continue to download events?

    Definately, I can't understand what is causing the download to stop, but davdroid shows an event in the lead up to it stopping the download batch. When I email you the log file tomorrow, have a look around this time stamp, it's an example where it stops after around 60 events, this batch of 60 only happens after I've created a new event in zimbra.

    11-03 22:27:36.239   984  1014 W SyncManager: Detected sync making no progress for startTime 38438403, mTimeoutStartTime 38438403, mHistoryRowId 655, syncOperation JobId: 107076, xxxx@xxxx.com.au u0 (bitfire.at.davdroid), com.android.calendar, PERIODIC, reason: Periodic, period: 900000, flexMillis: 36000. cancelling.
    

    Maybe I should broaden the scope of logcat to something else?

    In addition to a new event created in zimbra causing the sync batch to resume for a while, at 22:45 I modified an existing event. There is some sync activity when the next 15 minute window passes around, but it doesn't seem the same as if a new event is created and it's more than the "stalled sync" behaviour

    If you add an event on the server, the CTag changes. DAVdroid checks the CTag at the beginning of the sync, and synchronizes only when the CTag has changed. However, the CTag is remembered at the end of a successful sync, so DAVdroid should re-try after incomplete synchronization.

    I'm not completely sure what CTag is. It sounds like in the context you used it, it denotes whether a sync needs to run on an event because it's not been done yet or the event has been modified? Is there any more testing you want me to do on this area?



  • @zstephen some notes to accompany the log file I just emailed

    05:10 modified event "debug test 2 modified 2"
    05:35 modified event "debug test 2 modified 3"
    06:30 modified event "debug test 2 modified 4"

    I didn't take great notes last night, but I did make some changes to the test event, and it's only after doing that would the balance of unsynced items start again.

    During the test, I did not press manual sync at all


  • developer

    Thanks for the logs!

    Unfortunately, I don't have any idea what the problem could be.


Log in to reply
 

Looks like your connection to Bitfire App Forums was lost, please wait while we try to reconnect.