Tickets :: [#12117] ActiveSync via iOS 6.1.2 for INBOX stops syncing after ERR "Collection does not exist"

6.0.0-beta1

9/24/25

Summary	ActiveSync via iOS 6.1.2 for INBOX stops syncing after ERR "Collection does not exist"
Queue	Synchronization
Queue Version	Git master
Type	Bug
State	Resolved
Priority	2. Medium
Owners	mrubinsk (at) horde (dot) org
Requester	vt (at) volkerthen (dot) de
Created	03/14/2013 (4577 days ago)
Due
Updated	03/19/2013 (4572 days ago)
Assigned	03/19/2013 (4572 days ago)
Resolved	03/19/2013 (4572 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch	No

03/19/2013 06:29:26 PM	catalin (dot) draghiciu (at) primeit (dot) ro	Comment #8	Reply to this comment
Can you see if the latest commit fixes this for you? This resolved my problem. Thank you.

03/19/2013 06:09:47 PM	Michael Rubinsky	State ⇒ Resolved

03/19/2013 06:00:56 PM	vt (at) volkerthen (dot) de	Comment #7	Reply to this comment
The fix works for me. Sent now a few dozen test mails during the last thirty minutes. All stable.

03/19/2013 05:15:56 PM	Michael Rubinsky	Comment #6	Reply to this comment
Can you see if the latest commit fixes this for you?

03/19/2013 05:15:25 PM	Michael Rubinsky	Comment #5	Reply to this comment
For some reason, the ticket was not updated: commit 6fcfa96ea2e260c9e74610e95c4db0329d381442 Author: Michael J Rubinsky <mrubinsk@horde.org> Date: Tue Mar 19 13:12:09 2013 -0400 ~~Bug #12117~~ Include the lasthbsyncstarted time check for PING requests also. Prevents multiple PING requests from running against the same syncCache. framework/ActiveSync/lib/Horde/ActiveSync/Request/Ping.php \| 6 ++++++ framework/ActiveSync/lib/Horde/ActiveSync/SyncCache.php \| 3 ++- 2 files changed, 8 insertions(+), 1 deletions(-) http://git.horde.org/horde-git/-/commit/6fcfa96ea2e260c9e74610e95c4db0329d381442

03/19/2013 02:26:59 PM	Michael Rubinsky	Comment #4	Reply to this comment
Initial observations after receiving your log: For some reason, your client is running at least 3 different PING threads, and multiple SYNC threads all against the same collections. What's happening is one of the "older" threads is still asking for an obsolete state. This shouldn't happen, but there is code in the syncCache that is supposed to catch this.

03/19/2013 01:48:42 PM	Michael Rubinsky	Comment #3 State ⇒ Feedback	Reply to this comment
[Show Quoted Text - 15 lines][Hide Quoted Text] ActiveSync was working for quite some time on my iPhone4 (6.1.2) with "Push" activated in the iPhone settings. But now the Syncing of my inbox fails after a few dozen of messages. In the log file I can see this: 2013-03-14T16:06:58+01:00 DEBUG: [26682] Initializing state for collection: INBOX, synckey: {5141e457-bd6c-4454-8b16-6b44c0a8bb01}28 2013-03-14T16:06:58+01:00 DEBUG: [26682] Loading state for synckey {5141e457-bd6c-4454-8b16-6b44c0a8bb01}28 2013-03-14T16:06:58+01:00 ERR: [26682] Could not find state for synckey {5141e457-bd6c-4454-8b16-6b44c0a8bb01}28. 2013-03-14T16:06:58+01:00 ERR: [26682] State gone, PING terminating and forcing a SYNC: 2013-03-14T16:06:58+01:00 DEBUG: [26682] Changes available! I would really need a complete synclog. The first error above is due to the fact that the state was dropped from storage - something that normally wouldn't happen without either user intervention (explicitly clearing the state from the UI) or an infinite sync loop (which is detected by the code and causes the state to be forcibly cleared). Without seeing the earlier entries in the log, it's impossible to determine what is going on that initially caused this issue.

03/17/2013 08:35:41 PM	catalin (dot) draghiciu (at) primeit (dot) ro	Comment #2	Reply to this comment
I have the same problem on iPhone 5 and 4s on iOS 6.1.2, iPhone 4 on iOS 6.1 and iPod 4 on iOS 5.1.1. In observed also that sometimes, inbox folder just dissapears from sync log without an error message. Here is an example: 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing state for collection: @Tasks@, synckey: {51462227-16e8-4b1d-9a6a-6f7e524c92eb}2 2013-03-17T22:08:41+02:00 DEBUG: [27216] Loading state for synckey {51462227-16e8-4b1d-9a6a-6f7e524c92eb}2 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing message diff engine for @Tasks@ 2013-03-17T22:08:41+02:00 DEBUG: [27216] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1363550760, 1363550921, 0, 1) 2013-03-17T22:08:41+02:00 DEBUG: [27216] Found 0 message changes in @Tasks@. 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing state for collection: @Calendar@, synckey: {51462225-fdc0-4e46-b40a-6f7e524c92eb}2 2013-03-17T22:08:41+02:00 DEBUG: [27216] Loading state for synckey {51462225-fdc0-4e46-b40a-6f7e524c92eb}2 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing message diff engine for @Calendar@ 2013-03-17T22:08:41+02:00 DEBUG: [27216] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1363550758, 1363550921, 1361131721, 1) 2013-03-17T22:08:41+02:00 DEBUG: [27216] Found 0 message changes in @Calendar@. 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing state for collection: INBOX, synckey: {51462219-0dfc-40fc-bd58-67a5524c92eb}11 2013-03-17T22:08:41+02:00 DEBUG: [27216] Loading state for synckey {51462219-0dfc-40fc-bd58-67a5524c92eb}11 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing message diff engine for INBOX 2013-03-17T22:08:41+02:00 DEBUG: [27216] Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1363550894, 1363550921, 1363464521, 1) 2013-03-17T22:08:41+02:00 DEBUG: [27216] Found 0 message changes in INBOX. 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing state for collection: @Contacts@, synckey: {5146221f-c270-499a-8eae-6f26524c92eb}2 2013-03-17T22:08:41+02:00 DEBUG: [27216] Loading state for synckey {5146221f-c270-499a-8eae-6f26524c92eb}2 2013-03-17T22:08:41+02:00 DEBUG: [27216] Initializing message diff engine for @Contacts@ 2013-03-17T22:08:41+02:00 DEBUG: [27216] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1363550752, 1363550921, 0, 1) 2013-03-17T22:08:41+02:00 DEBUG: [27216] Found 0 message changes in @Contacts@. 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing state for collection: @Tasks@, synckey: {51462227-16e8-4b1d-9a6a-6f7e524c92eb}2 2013-03-17T22:08:44+02:00 DEBUG: [28101] Loading state for synckey {51462227-16e8-4b1d-9a6a-6f7e524c92eb}2 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing message diff engine for @Tasks@ 2013-03-17T22:08:44+02:00 DEBUG: [28101] Horde_Core_ActiveSync_Driver::getServerChanges(@Tasks@, 1363550760, 1363550924, 0, 1) 2013-03-17T22:08:44+02:00 DEBUG: [28101] Found 0 message changes in @Tasks@. 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing state for collection: @Calendar@, synckey: {51462225-fdc0-4e46-b40a-6f7e524c92eb}2 2013-03-17T22:08:44+02:00 DEBUG: [28101] Loading state for synckey {51462225-fdc0-4e46-b40a-6f7e524c92eb}2 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing message diff engine for @Calendar@ 2013-03-17T22:08:44+02:00 DEBUG: [28101] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 1363550758, 1363550924, 1361131724, 1) 2013-03-17T22:08:44+02:00 DEBUG: [28101] Found 0 message changes in @Calendar@. 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing state for collection: INBOX, synckey: {51462219-0dfc-40fc-bd58-67a5524c92eb}11 2013-03-17T22:08:44+02:00 DEBUG: [28101] Loading state for synckey {51462219-0dfc-40fc-bd58-67a5524c92eb}11 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing message diff engine for INBOX 2013-03-17T22:08:44+02:00 DEBUG: [28101] Horde_Core_ActiveSync_Driver::getServerChanges(INBOX, 1363550894, 1363550924, 1363464524, 1) 2013-03-17T22:08:44+02:00 DEBUG: [28101] Found 0 message changes in INBOX. 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing state for collection: @Contacts@, synckey: {5146221f-c270-499a-8eae-6f26524c92eb}2 2013-03-17T22:08:44+02:00 DEBUG: [28101] Loading state for synckey {5146221f-c270-499a-8eae-6f26524c92eb}2 2013-03-17T22:08:44+02:00 DEBUG: [28101] Initializing message diff engine for @Contacts@ 2013-03-17T22:08:44+02:00 DEBUG: [28101] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 1363550752, 1363550924, 0, 1) 2013-03-17T22:08:44+02:00 DEBUG: [28101] Found 0 message changes in @Contacts@. 2013-03-17T22:08:44+02:00 INFO: [28542] Horde_Core_ActiveSync_Driver::authenticate() attempt for catalin.draghiciu@primeit.ro 2013-03-17T22:08:44+02:00 DEBUG: [28542] PING request received for user catalin.draghiciu@primeit.ro 2013-03-17T22:08:44+02:00 DEBUG: [ApplF2LK60R6DTWD] loadDeviceInfo: catalin.draghiciu@primeit.ro 2013-03-17T22:08:44+02:00 INFO: Request being handled for device: ApplF2LK60R6DTWD Supporting protocol version: 12.1 2013-03-17T22:08:44+02:00 INFO: [28542] Handling PING command received at timestamp: 1363550924. 2013-03-17T22:08:44+02:00 DEBUG: Reusing PING state: Array ( [@Tasks@] => Array ( [class] => Tasks [windowsize] => 25 [truncation] => 0 [mimesupport] => 0 [mimetruncation] => 8 [conflict] => 1 [bodyprefs] => Array ( [wanted] => 1 [1] => Array ( [type] => 1 [truncationsize] => 32768 ) ) [lastsynckey] => {51462227-16e8-4b1d-9a6a-6f7e524c92eb}2 [pingable] => 1 [id] => @Tasks@ [synckey] => {51462227-16e8-4b1d-9a6a-6f7e524c92eb}2 ) [@Calendar@] => Array ( [class] => Calendar [windowsize] => 25 [filtertype] => 5 [truncation] => 0 [mimesupport] => 0 [mimetruncation] => 8 [conflict] => 1 [bodyprefs] => Array ( [wanted] => 1 [1] => Array ( [type] => 1 [truncationsize] => 32768 ) ) [lastsynckey] => {51462225-fdc0-4e46-b40a-6f7e524c92eb}2 [id] => @Calendar@ [pingable] => 1 [synckey] => {51462225-fdc0-4e46-b40a-6f7e524c92eb}2 ) [@Contacts@] => Array ( [class] => Contacts [windowsize] => 25 [truncation] => 0 [mimesupport] => 0 [mimetruncation] => 8 [conflict] => 1 [bodyprefs] => Array ( [wanted] => 1 [1] => Array ( [type] => 1 [truncationsize] => 32768 ) ) [lastsynckey] => {5146221f-c270-499a-8eae-6f26524c92eb}2 [id] => @Contacts@ [pingable] => 1 [synckey] => {5146221f-c270-499a-8eae-6f26524c92eb}2 ) ) 2013-03-17T22:08:44+02:00 DEBUG: [28542] Waiting for changes (heartbeat interval: 900)

03/15/2013 09:28:54 AM	Jan Schneider	Assigned to Michael Rubinsky State ⇒ Assigned

03/14/2013 07:34:15 PM	vt (at) volkerthen (dot) de	Comment #1 Priority ⇒ 2. Medium State ⇒ Unconfirmed Patch ⇒ No Milestone ⇒ Queue ⇒ Synchronization Summary ⇒ ActiveSync via iOS 6.1.2 for INBOX stops syncing after ERR "Collection does not exist" Type ⇒ Bug	Reply to this comment
ActiveSync was working for quite some time on my iPhone4 (6.1.2) with "Push" activated in the iPhone settings. But now the Syncing of my inbox fails after a few dozen of messages. In the log file I can see this: 2013-03-14T16:06:58+01:00 DEBUG: [26682] Initializing state for collection: INBOX, synckey: {5141e457-bd6c-4454-8b16-6b44c0a8bb01}28 2013-03-14T16:06:58+01:00 DEBUG: [26682] Loading state for synckey {5141e457-bd6c-4454-8b16-6b44c0a8bb01}28 2013-03-14T16:06:58+01:00 ERR: [26682] Could not find state for synckey {5141e457-bd6c-4454-8b16-6b44c0a8bb01}28. 2013-03-14T16:06:58+01:00 ERR: [26682] State gone, PING terminating and forcing a SYNC: 2013-03-14T16:06:58+01:00 DEBUG: [26682] Changes available! and a few seconds later this: 2013-03-14T16:07:10+01:00 DEBUG: [28973] Found 1 message changes in INBOX. 2013-03-14T16:07:10+01:00 DEBUG: [28973] Checking for PIM initiated changes. 2013-03-14T16:07:10+01:00 ERR: Collection does not exist. and after this, no more email messages get synced. In the first place I suspected the jailbroken device doing something to the syncing operations. Then I reset the phone to factory defaults and tried again, same result. Contacts, calendar and tasks are still working with "Push" activated. I'm using Debian 7.0 (wheezy) and the most recent Horde version (incl. ActiveSync 2.3.2) Let me know, if you need the complete sync log.