Tickets :: [#11349] Duplicate synckeys

6.0.0-beta1

7/4/25

Summary	Duplicate synckeys
Queue	Synchronization
Queue Version	Git develop
Type	Bug
State	Resolved
Priority	1. Low
Owners	mrubinsk (at) horde (dot) org
Requester	jan (at) horde (dot) org
Created	08/13/2012 (4708 days ago)
Due
Updated	08/14/2012 (4707 days ago)
Assigned	08/13/2012 (4708 days ago)
Resolved	08/14/2012 (4707 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

08/14/2012 12:41:31 AM	Michael Rubinsky	Comment #4 State ⇒ Resolved	Reply to this comment
Fixed by: http://git.horde.org/horde-git/-/commit/3ff34114cfde899b69e07214f43155d84f85e576

08/13/2012 04:14:47 PM	Jan Schneider	Comment #3	Reply to this comment
This indeed happens continuously. This is the first time it happens in the logs: 2012-08-13T11:25:47+02:00 DEBUG: [30226] Initializing state for collection: INBO X, synckey: {5028c803-917c-47ae-b757-760cc0a83c01}1 2012-08-13T11:25:47+02:00 DEBUG: [30226] Loading state for synckey {5028c803-917 c-47ae-b757-760cc0a83c01}1 2012-08-13T11:25:47+02:00 DEBUG: [30226] Initializing message diff engine for IN BOX 2012-08-13T11:25:47+02:00 DEBUG: Horde_ActiveSync_Driver_Horde::getServerChanges (INBOX, 0, 1344849947, 1344590747, 0) 2012-08-13T11:25:47+02:00 DEBUG: [30226] Found 0 message changes. 2012-08-13T11:25:47+02:00 DEBUG: Old SYNCKEY: {5028c803-917c-47ae-b757-760cc0a83 c01}1, New SYNCKEY: {5028c803-917c-47ae-b757-760cc0a83c01}2 2012-08-13T11:25:47+02:00 DEBUG: O <Synchronize> 2012-08-13T11:25:47+02:00 DEBUG: O <Folders> 2012-08-13T11:25:47+02:00 DEBUG: O <Folder> 2012-08-13T11:25:47+02:00 DEBUG: O <FolderType> 2012-08-13T11:25:47+02:00 DEBUG: O Email 2012-08-13T11:25:47+02:00 DEBUG: O <FolderType/> 2012-08-13T11:25:47+02:00 DEBUG: O <SyncKey> 2012-08-13T11:25:47+02:00 DEBUG: O {5028c803-917c-47ae-b757-760cc0a83c01}2 2012-08-13T11:25:47+02:00 DEBUG: O <SyncKey/> 2012-08-13T11:25:47+02:00 DEBUG: O <FolderId> 2012-08-13T11:25:47+02:00 DEBUG: O INBOX 2012-08-13T11:25:47+02:00 DEBUG: O <FolderId/> 2012-08-13T11:25:47+02:00 DEBUG: O <Status> 2012-08-13T11:25:47+02:00 DEBUG: O 1 2012-08-13T11:25:47+02:00 DEBUG: O <Status/> 2012-08-13T11:25:47+02:00 DEBUG: [30226] Saving state: Array ( [0] => {5028c803-917c-47ae-b757-760cc0a83c01}2 [1] => O:28:"Horde_ActiveSync_Folder_Imap":9:{s:12:"^@^@_messages";a:0:{}s:9:"^@^@_added";a:0:{}s:11:"^@^@_changed";a:0:{}s:11:"^@^@_removed";a:0:{}s:9:"^@^@_flags";a:0:{}s:7:"^@^@_min";i:0;s:10:"^@^@_status";a:0:{}s:12:"^@^@_serverid";s:5:"INBOX";s:9:"^@*^@_class";s:5:"Email";} [2] => androidc135094322 [3] => 1344849947 [4] => INBOX [5] => jan [6] => 0 ) 2012-08-13T11:25:47+02:00 NOTICE: [30226] Error saving state for synckey {5028c803-917c-47ae-b757-760cc0a83c01}2: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '{5028c803-917c-47ae-b757-760cc0a83c01}2' for key 'PRIMARY' - removing previous sync state and trying again. 2012-08-13T11:25:47+02:00 DEBUG: O <Folder/> 2012-08-13T11:25:47+02:00 DEBUG: O <Folders/> 2012-08-13T11:25:47+02:00 DEBUG: O <Synchronize/>

08/13/2012 03:06:40 PM	Michael Rubinsky	Comment #2 State ⇒ Feedback	Reply to this comment
This error, by itself, only means that during a sync attempt that occurred earlier in your logs the device either did not receive or accept the server response with the new synckey. So, when the device connects again, it sends the earlier synckey again. This is expected and is needed to indicate what the state of the device currently is. OTOH, if this continuously happens and the device never properly syncs, we need to find out what the cause of the earlier error is.

08/13/2012 09:49:13 AM	Jan Schneider	Comment #1 Priority ⇒ 1. Low Patch ⇒ No Milestone ⇒ Assigned to Michael Rubinsky Summary ⇒ Duplicate synckeys Type ⇒ Bug State ⇒ Assigned Queue ⇒ Synchronization	Reply to this comment
With a fresh AS sync, I currently get this: 2012-08-13T11:45:37+02:00 DEBUG: [androidc135094322] SYNC request received for user jan 2012-08-13T11:45:37+02:00 DEBUG: [androidc135094322] loadDeviceInfo: jan 2012-08-13T11:45:37+02:00 INFO: Request being handled for device: androidc135094322 Supporting protocol version: 12.0 2012-08-13T11:45:37+02:00 INFO: [androidc135094322] Handling SYNC command. 2012-08-13T11:45:37+02:00 DEBUG: [androidc135094322] Checking policykey for device: 0 user: jan 2012-08-13T11:45:37+02:00 DEBUG: Policykey: 0 verified. 2012-08-13T11:45:37+02:00 DEBUG: I <Synchronize> 2012-08-13T11:45:37+02:00 DEBUG: I <Folders> 2012-08-13T11:45:37+02:00 DEBUG: I <Folder> 2012-08-13T11:45:37+02:00 DEBUG: I <FolderType> 2012-08-13T11:45:37+02:00 DEBUG: I Email 2012-08-13T11:45:37+02:00 INFO: [androidc135094322] Syncing folder class: Email 2012-08-13T11:45:37+02:00 DEBUG: I </FolderType> 2012-08-13T11:45:37+02:00 DEBUG: I <SyncKey> 2012-08-13T11:45:37+02:00 DEBUG: I {5028c803-917c-47ae-b757-760cc0a83c01}1 2012-08-13T11:45:37+02:00 DEBUG: I </SyncKey> 2012-08-13T11:45:37+02:00 DEBUG: I <FolderId> 2012-08-13T11:45:37+02:00 DEBUG: I INBOX 2012-08-13T11:45:37+02:00 INFO: [androidc135094322] Folder server id: INBOX 2012-08-13T11:45:37+02:00 DEBUG: I </FolderId> 2012-08-13T11:45:37+02:00 DEBUG: I <DeletesAsMoves/> 2012-08-13T11:45:37+02:00 DEBUG: I <GetChanges/> 2012-08-13T11:45:37+02:00 ERR: Unmatched content: 2012-08-13T11:45:37+02:00 ERR: Array ( [1] => 1 [2] => GetChanges [4] => 0 ) 2012-08-13T11:45:37+02:00 DEBUG: I <WindowSize> 2012-08-13T11:45:37+02:00 ERR: Unmatched content: 2012-08-13T11:45:37+02:00 ERR: Array ( [1] => 1 [2] => WindowSize [4] => 1 ) 2012-08-13T11:45:37+02:00 DEBUG: I 5 2012-08-13T11:45:37+02:00 DEBUG: I </WindowSize> 2012-08-13T11:45:37+02:00 DEBUG: I <Options> 2012-08-13T11:45:37+02:00 DEBUG: I <FilterType> 2012-08-13T11:45:37+02:00 DEBUG: I 2 2012-08-13T11:45:37+02:00 DEBUG: I </FilterType> 2012-08-13T11:45:37+02:00 DEBUG: I <AirSyncBase:BodyPreference> 2012-08-13T11:45:37+02:00 DEBUG: I <AirSyncBase:Type> 2012-08-13T11:45:37+02:00 DEBUG: I 2 2012-08-13T11:45:37+02:00 DEBUG: I </AirSyncBase:Type> 2012-08-13T11:45:37+02:00 DEBUG: I <AirSyncBase:TruncationSize> 2012-08-13T11:45:37+02:00 DEBUG: I 200000 2012-08-13T11:45:37+02:00 DEBUG: I </AirSyncBase:TruncationSize> 2012-08-13T11:45:37+02:00 DEBUG: I </AirSyncBase:BodyPreference> 2012-08-13T11:45:37+02:00 DEBUG: I </Options> 2012-08-13T11:45:37+02:00 DEBUG: I </Folder> 2012-08-13T11:45:37+02:00 DEBUG: I </Folders> 2012-08-13T11:45:37+02:00 DEBUG: I </Synchronize> 2012-08-13T11:45:37+02:00 DEBUG: Have syncable collections 2012-08-13T11:45:37+02:00 DEBUG: All synckeys confirmed. Continuing with SYNC 2012-08-13T11:45:37+02:00 DEBUG: [30286] Initializing state for collection: INBOX, synckey: {5028c803-917c-47ae-b757-760cc0a83c01}1 2012-08-13T11:45:37+02:00 DEBUG: [30286] Loading state for synckey {5028c803-917c-47ae-b757-760cc0a83c01}1 2012-08-13T11:45:37+02:00 DEBUG: [30286] Initializing message diff engine for INBOX 2012-08-13T11:45:37+02:00 DEBUG: Horde_ActiveSync_Driver_Horde::getServerChanges(INBOX, 0, 1344851137, 1344591937, 0) 2012-08-13T11:45:37+02:00 DEBUG: [30286] Found 0 message changes. 2012-08-13T11:45:37+02:00 DEBUG: Old SYNCKEY: {5028c803-917c-47ae-b757-760cc0a83c01}1, New SYNCKEY: {5028c803-917c-47ae-b757-760cc0a83c01}2 2012-08-13T11:45:37+02:00 DEBUG: O <Synchronize> 2012-08-13T11:45:37+02:00 DEBUG: O <Folders> 2012-08-13T11:45:37+02:00 DEBUG: O <Folder> 2012-08-13T11:45:37+02:00 DEBUG: O <FolderType> 2012-08-13T11:45:37+02:00 DEBUG: O Email 2012-08-13T11:45:37+02:00 DEBUG: O <FolderType/> 2012-08-13T11:45:37+02:00 DEBUG: O <SyncKey> 2012-08-13T11:45:37+02:00 DEBUG: O {5028c803-917c-47ae-b757-760cc0a83c01}2 2012-08-13T11:45:37+02:00 DEBUG: O <SyncKey/> 2012-08-13T11:45:37+02:00 DEBUG: O <FolderId> 2012-08-13T11:45:37+02:00 DEBUG: O INBOX 2012-08-13T11:45:37+02:00 DEBUG: O <FolderId/> 2012-08-13T11:45:37+02:00 DEBUG: O <Status> 2012-08-13T11:45:37+02:00 DEBUG: O 1 2012-08-13T11:45:37+02:00 DEBUG: O <Status/> 2012-08-13T11:45:37+02:00 DEBUG: [30286] Saving state: Array ( [0] => {5028c803-917c-47ae-b757-760cc0a83c01}2 [1] => O:28:"Horde_ActiveSync_Folder_Imap":9:{s:12:"_messages";a:0:{}s:9:"_added";a:0:{}s:11:"_changed";a:0:{}s:11:"_removed";a:0:{}s:9:"_flags";a:0:{}s:7:"_min";i:0;s:10:"_status";a:0:{}s:12:"_serverid";s:5:"INBOX";s:9:"*_class";s:5:"Email";} [2] => androidc135094322 [3] => 1344851137 [4] => INBOX [5] => jan [6] => 0 ) 2012-08-13T11:45:37+02:00 NOTICE: [30286] Error saving state for synckey {5028c803-917c-47ae-b757-760cc0a83c01}2: SQLSTATE[23000]: Integrity constraint violation: 1062 Duplicate entry '{5028c803-917c-47ae-b757-760cc0a83c01}2' for key 'PRIMARY' - removing previous sync state and trying again. 2012-08-13T11:45:37+02:00 DEBUG: O <Folder/> 2012-08-13T11:45:37+02:00 DEBUG: O <Folders/> 2012-08-13T11:45:37+02:00 DEBUG: O <Synchronize/>