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.
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.
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?
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
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
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?
@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
Thanks for the logs!
Unfortunately, I don’t have any idea what the problem could be.
