Calendar sync stopping midway

  • 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.

Similar topics