Tickets :: [#12075] PING-SYNC storm in ActiveSync

6.0.0-alpha14

6/25/25

Summary	PING-SYNC storm in ActiveSync
Queue	Synchronization
Queue Version	Git master
Type	Bug
State	Resolved
Priority	1. Low
Owners	mrubinsk (at) horde (dot) org
Requester	arjen+horde (at) de-korte (dot) org
Created	02/27/2013 (4501 days ago)
Due
Updated	08/08/2024 (321 days ago)
Assigned
Resolved	03/01/2013 (4499 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

08/08/2024 12:15:07 PM	test2 (at) fidaygestion (dot) fr	Comment #5	Reply to this comment
[Show Quoted Text - 21 lines][Hide Quoted Text] Changes have been made in Git (master): commit 7bf12ddda8c49f9bce0628f42866eb62b11dbf22 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Fri Mar 1 10:52:10 2013 -0500 ~~Bug: 12075~~ Increment the SyncKey if we detected a change during PING. Increment the key even if the change is gone by the time we get to the SYNC. A message might have been added and removed before the change was detected, thus causing a SYNC-PING loop until a new change arrives. .../lib/Horde/ActiveSync/Request/Ping.php \| 3 + .../lib/Horde/ActiveSync/Request/Sync.php \| 12 +++-- .../ActiveSync/lib/Horde/ActiveSync/SyncCache.php \| 51 +++++++++++++++++++- 3 files changed, 60 insertions(+), 6 deletions(-) http://git.horde.org/horde-git/-/commit/7bf12ddda8c49f9bce0628f42866eb62b11dbf22

06/11/2013 08:45:05 PM	Git Commit	Comment #4	Reply to this comment
Changes have been made in Git (master): commit e8b8ebb65de1d70ff92ef1b010a58a00e12c3577 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Tue Jun 11 16:43:30 2013 -0400 ~~Bug: 12339~~ Fix regression of ~~Bug: 12075~~ in preventing PING-SYNC loop. .../lib/Horde/ActiveSync/Collections.php \| 3 +++ .../lib/Horde/ActiveSync/Request/Ping.php \| 1 + 2 files changed, 4 insertions(+), 0 deletions(-) http://git.horde.org/horde-git/-/commit/e8b8ebb65de1d70ff92ef1b010a58a00e12c3577

03/01/2013 04:06:18 PM	Michael Rubinsky	Assigned to Michael Rubinsky State ⇒ Resolved

03/01/2013 04:05:34 PM	Git Commit	Comment #3	Reply to this comment
Changes have been made in Git (master): commit 7bf12ddda8c49f9bce0628f42866eb62b11dbf22 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Fri Mar 1 10:52:10 2013 -0500 ~~Bug: 12075~~ Increment the SyncKey if we detected a change during PING. Increment the key even if the change is gone by the time we get to the SYNC. A message might have been added and removed before the change was detected, thus causing a SYNC-PING loop until a new change arrives. .../lib/Horde/ActiveSync/Request/Ping.php \| 3 + .../lib/Horde/ActiveSync/Request/Sync.php \| 12 +++-- .../ActiveSync/lib/Horde/ActiveSync/SyncCache.php \| 51 +++++++++++++++++++- 3 files changed, 60 insertions(+), 6 deletions(-) http://git.horde.org/horde-git/-/commit/7bf12ddda8c49f9bce0628f42866eb62b11dbf22

02/28/2013 08:48:30 AM	arjen+horde (at) de-korte (dot) org	Comment #2	Reply to this comment
In case it might be helpful, a debug log from the device (here the PING-SYNC cycle repeats in the INBOX): 02-27 18:49:51.896\|W\|dc\|No affected items in this sync, pump up the windowSize... 02-27 18:49:51.876\|I\|bf\|Sync has finished - folderId: INBOX, syncKey: {5128a4bc-4e94-4412-a545-3f17c0a8010a}9,folderName: Inbox, folderKind: 2 02-27 18:49:49.619\|I\|bf\|Sync has started - folderId: INBOX 02-27 18:49:49.350\|I\|bo\|Ping has finished - Status: 2 (Changes occurred in at least one of the folders that were being monitored. The response includes the folders in which these changes have occurred.) 02-27 18:49:46.586\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.SCHEDULE_DIRECT_PUSH 02-27 18:49:46.129\|I\|bo\|Ping has started - failure: 0, heartbeat: 1800 02-27 18:49:45.362\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.RESUME_DIRECT_PUSH 02-27 18:49:45.060\|W\|dc\|No affected items in this sync, pump up the windowSize... 02-27 18:49:45.006\|I\|bf\|Sync has finished - folderId: INBOX, syncKey: {5128a4bc-4e94-4412-a545-3f17c0a8010a}9,folderName: Inbox, folderKind: 2 02-27 18:49:42.831\|I\|bf\|Sync has started - folderId: INBOX 02-27 18:49:42.553\|I\|bo\|Ping has finished - Status: 2 (Changes occurred in at least one of the folders that were being monitored. The response includes the folders in which these changes have occurred.) 02-27 18:49:39.266\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.SCHEDULE_DIRECT_PUSH 02-27 18:49:39.202\|I\|bo\|Ping has started - failure: 0, heartbeat: 1800 02-27 18:49:38.347\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.RESUME_DIRECT_PUSH 02-27 18:49:38.209\|W\|dc\|No affected items in this sync, pump up the windowSize... 02-27 18:49:38.163\|I\|bf\|Sync has finished - folderId: INBOX, syncKey: {5128a4bc-4e94-4412-a545-3f17c0a8010a}9,folderName: Inbox, folderKind: 2 02-27 18:49:36.000\|I\|bf\|Sync has started - folderId: INBOX 02-27 18:49:35.720\|I\|bo\|Ping has finished - Status: 2 (Changes occurred in at least one of the folders that were being monitored. The response includes the folders in which these changes have occurred.) 02-27 18:49:32.382\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.SCHEDULE_DIRECT_PUSH 02-27 18:49:32.314\|I\|bo\|Ping has started - failure: 0, heartbeat: 1800 02-27 18:49:31.435\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.RESUME_DIRECT_PUSH 02-27 18:49:31.252\|W\|dc\|No affected items in this sync, pump up the windowSize... 02-27 18:49:31.200\|I\|bf\|Sync has finished - folderId: INBOX, syncKey: {5128a4bc-4e94-4412-a545-3f17c0a8010a}9,folderName: Inbox, folderKind: 2 02-27 18:49:29.629\|I\|bf\|Sync has started - folderId: INBOX 02-27 18:49:29.168\|I\|bo\|Ping has finished - Status: 2 (Changes occurred in at least one of the folders that were being monitored. The response includes the folders in which these changes have occurred.) 02-27 18:49:26.162\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.SCHEDULE_DIRECT_PUSH 02-27 18:49:26.090\|I\|bo\|Ping has started - failure: 0, heartbeat: 1800 02-27 18:49:25.393\|I\|SyncEngineService\|Service started... com.emtrace.hermes.intent.action.RESUME_DIRECT_PUSH

02/27/2013 09:04:58 AM	arjen+horde (at) de-korte (dot) org	Comment #1 Priority ⇒ 1. Low Type ⇒ Bug Summary ⇒ PING-SYNC storm in ActiveSync Queue ⇒ Synchronization Milestone ⇒ Patch ⇒ No State ⇒ Unconfirmed	Reply to this comment
Occasionally I see a significant battery drain on my mobile phone that syncs through ActiveSync. I enabled debugging and found that during such an event it continuously repeats the same PING-SYNC sycle. When it PINGs the server, it will get a reply status of 2 and in the logs it mentions 2013-02-22T14:36:53+01:00 DEBUG: [29575] Initializing state for collection: Commercieel, synckey: {512745e0-365c-4a01-9e3f-4202c0a8010a}2 2013-02-22T14:36:53+01:00 DEBUG: [29575] Loading state for synckey {512745e0-365c-4a01-9e3f-4202c0a8010a}2 2013-02-22T14:36:53+01:00 DEBUG: [29575] Initializing message diff engine for Commercieel 2013-02-22T14:36:53+01:00 DEBUG: [29575] Horde_Core_ActiveSync_Driver::getServerChanges(Commercieel, 1361528289, 1361540213, 0, 1) 2013-02-22T14:36:54+01:00 DEBUG: [29575] Found 1 message changes in Commercieel. 2013-02-22T14:36:54+01:00 DEBUG: [29575] No PIM changes present, returning all messages. But when it subsequently attempts to SYNC that folder, no changes are found: 2013-02-22T14:36:56+01:00 DEBUG: [29598] Initializing state for collection: Commercieel, synckey: {512745e0-365c-4a01-9e3f-4202c0a8010a}2 2013-02-22T14:36:56+01:00 DEBUG: [29598] Loading state for synckey {512745e0-365c-4a01-9e3f-4202c0a8010a}2 2013-02-22T14:36:56+01:00 DEBUG: [29598] Initializing message diff engine for Commercieel 2013-02-22T14:36:56+01:00 DEBUG: [29598] Horde_Core_ActiveSync_Driver::getServerChanges(Commercieel, 1361528289, 1361540216, 1359121016, 0) 2013-02-22T14:36:57+01:00 DEBUG: IMAP status: Array ( [uidnext] => 1349 [uidvalidity] => 1108813680 [highestmodseq] => 1506 ) 2013-02-22T14:36:57+01:00 DEBUG: CONDSTORE and CHANGES 2013-02-22T14:36:57+01:00 DEBUG: [29598] Found 0 message changes in Commercieel. This cycle repeats every few seconds until a new message arrives in that folder or flags of a message in said folder are changed, after which the situation is back to normal. It looks like at times the cached state is out of sync with the IMAP server. The problem seems to be triggered by moving or deleting messages from folders that are synchronized through ActiveSync with a non-ActiveSync client (I used Horde Webmail). So far it has only occurred minutes after the phone went from the direct-push to manual sync mode, but I'm not entirely sure if this is related (the problem in this case surfaces when the phone goes back to direct-push). But this may also have to do with when the phone is in direct-push mode, a human won't be fast enough to beat ActiveSync from keeping up with the changes on the server.