| Summary | synckey and caching issues |
| Queue | Synchronization |
| Queue Version | Git master |
| Type | Bug |
| State | Not A Bug |
| Priority | 1. Low |
| Owners | mrubinsk (at) horde (dot) org |
| Requester | software-horde (at) interfasys (dot) ch |
| Created | 11/01/2014 (3910 days ago) |
| Due | |
| Updated | 11/03/2014 (3908 days ago) |
| Assigned | 11/03/2014 (3908 days ago) |
| Resolved | 11/03/2014 (3908 days ago) |
| Github Issue Link | |
| Github Pull Request | |
| Milestone | |
| Patch | No |
fresh state. If the server is sending a certain folder id, but the
client is asking for (what I assume is the previously used folder id
for that particular folder) then there is nothing Horde can do about
it.
The fact that it was always the previous one and not always the same
ID got me thinking that it could be related to the recent changes made
in the sync method, but I've tried reversing the patches and it didn't
seem to help.
Assigned to Michael Rubinsky
State ⇒ Feedback
fresh state. If the server is sending a certain folder id, but the
client is asking for (what I assume is the previously used folder id
for that particular folder) then there is nothing Horde can do about it.
Priority ⇒ 1. Low
Type ⇒ Bug
Summary ⇒ synckey and caching issues
Queue ⇒ Synchronization
Milestone ⇒
Patch ⇒ No
State ⇒ Unconfirmed
via the control panel.
That's because it keeps asking for info about a folder which does not exist.
but I think there is a bigger problem as most of the cached data has a
synckey of 0
That's the log for the reset
--------
[65522] GET VARIABLES: Array
[65522] Handling FOLDERSYNC command.
[65522] Checking policykey for device: BBALPHA user: user@domain.tld
[65522] Stored key: 9929581816
[65522] Policykey: 9929581816 verified.
[65522] I <FolderHierarchy:FolderSync>
[65522] I <FolderHierarchy:SyncKey>
[65522] I 0
[65522] I </FolderHierarchy:SyncKey>
NOTICE: [65522] Horde_ActiveSync_State_Base::loadState: clearing folder state.
[65522] Resetting device state for device: BBALPHA, user:
user@domain.tld, and collection: foldersync.
NOTICE: [65522] Clearing foldersync state from synccache.
[65522] Clearing collections data from cache.
[65522] Replacing SYNC_CACHE entry for user user@domain.tld and device
BBALPHA:
a:11:{s:18:"confirmed_synckeys";a:1:{s:39:"{5454f5eb-5fb4-436f-8d45-01d8904cae96}2";b:1;}s:17:"lasthbsyncstarted";b:0;s:17:"lastsyncendnormal";i:1414854125;s:9:"timestamp";s:10:"1414854216";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:0:{}s:9:"hierarchy";s:1:"0";s:11:"collections";a:0:{}s:13:"pingheartbeat";b:0;s:14:"synckeycounter";a:0:{}}
[65522] I </FolderHierarchy:FolderSync>
[65522] Initializing folder diff engine
[65522] Horde_Core_ActiveSync_Driver::getFolderList()
[65522] Device entry exists for BBALPHA, updating userAgent and version.
[65522] Creating new folder uuid for Calendar:6s_Uns1LyNNNTDAJ23ynqA1:
A5cedb59d
[65522] Creating new folder uuid for Contacts:N87-VUrDX0PIrYu6upm29A3:
C9592a20f
[65522] Creating new folder uuid for Tasks:a2vzXJABkjNLFwrHOe_F8g1: Te7d04f54
[65522] Creating new folder uuid for Notes:_IqHpMZrXeXonTgsCOdzng4:
Nae7f1fb5[65522] Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
[65522] Creating new folder uuid for INBOX: Fb9dacd7c
[65522] Creating new folder uuid for shared/global@domain.tld/INBOX: F74b79d60
[65522] Found 15 folder changes.
[65522] Updating state during foldersync
...
[65522] Updating state during foldersync
[65522] O <FolderHierarchy:FolderSync>
[65522] O <FolderHierarchy:Status>
[65522] O 1
[65522] O </FolderHierarchy:Status>
[65522] O <FolderHierarchy:SyncKey>
[65522] O {5454f648-6980-40e9-930b-fff2904cae96}1
[65522] O </FolderHierarchy:SyncKey>
[65522] O <FolderHierarchy:Changes>
[65522] O <FolderHierarchy:Count>
[65522] O 15
[65522] O </FolderHierarchy:Count>
[65522] O <FolderHierarchy:Add>
[65522] O <FolderHierarchy:ServerEntryId>
[65522] O Te7d04f54
[65522] O </FolderHierarchy:ServerEntryId>
[65522] O <FolderHierarchy:ParentId>
[65522] O 0
[65522] O </FolderHierarchy:ParentId>
[65522] O <FolderHierarchy:DisplayName>
[65522] O Tasks folder 1
[65522] O </FolderHierarchy:DisplayName>
[65522] O <FolderHierarchy:Type>
[65522] O 15
[65522] O </FolderHierarchy:Type>
[65522] O </FolderHierarchy:Add>
[65522] Collection without id found:
a:1:{s:8:"serverid";s:29:"Tasks:a2vzXJABkjNLFwrHOe_F8g1";}
...
[65522] O <FolderHierarchy:Add>
[65522] O <FolderHierarchy:ServerEntryId>
[65522] O RI
[65522] O </FolderHierarchy:ServerEntryId>
[65522] O <FolderHierarchy:ParentId>
[65522] O 0
[65522] O </FolderHierarchy:ParentId>
[65522] O <FolderHierarchy:DisplayName>
[65522] O RI
[65522] O </FolderHierarchy:DisplayName>
[65522] O <FolderHierarchy:Type>
[65522] O 19
[65522] O </FolderHierarchy:Type>
[65522] O </FolderHierarchy:Add>
[65522] Collection without id found: a:1:{s:8:"serverid";s:2:"RI";}
...
[65522] O <FolderHierarchy:Add>
[65522] O <FolderHierarchy:ServerEntryId>
[65522] O N66b94b7f
[65522] O </FolderHierarchy:ServerEntryId>
[65522] O <FolderHierarchy:ParentId>
[65522] O 0
[65522] O </FolderHierarchy:ParentId>
[65522] O <FolderHierarchy:DisplayName>
[65522] O Notes folder 2
[65522] O </FolderHierarchy:DisplayName>
[65522] O <FolderHierarchy:Type>
[65522] O 17
[65522] O </FolderHierarchy:Type>
[65522] O </FolderHierarchy:Add>
[65522] Collection without id found:
a:1:{s:8:"serverid";s:42:"Notes:53c1c9ee-a878-4c92-9431-5271904cae96";}
...
[65522] O <FolderHierarchy:Add>
[65522] O <FolderHierarchy:ServerEntryId>
[65522] O Fb9dacd7c
[65522] O </FolderHierarchy:ServerEntryId>
[65522] O <FolderHierarchy:ParentId>
[65522] O 0
[65522] O </FolderHierarchy:ParentId>
[65522] O <FolderHierarchy:DisplayName>
[65522] O Inbox
[65522] O </FolderHierarchy:DisplayName>
[65522] O <FolderHierarchy:Type>
[65522] O 2
[65522] O </FolderHierarchy:Type>
[65522] O </FolderHierarchy:Add>
[65522] Collection without id found: a:1:{s:8:"serverid";s:5:"INBOX";}
...
[65522] O </FolderHierarchy:Changes>
[65522] O </FolderHierarchy:FolderSync>
[65522] Saving state:
a:8:{i:0;s:39:"{5454f648-6980-40e9-930b-fff2904cae96}1";i:1;O:21:"Horde_Db_Value_Binary":1:{s:5:"value";s:2189:"a:15:{i:0;a:5:{s:2:"id";s:9:"Te7d04f54";s:3:"mod";s:11:"Tasks folder 1";s:6:"parent";s:1:"0";s:8:"serverid";s:29:"Tasks:a2vzXJABkjNLFwrHOe_F8g1";s:4:"type";i:15;}i:1;a:5:{s:2:"id";s:9:"T9fce3cbc";s:3:"mod";s:11:"Tasks folder 2";s:6:"parent";s:1:"0";s:8:"serverid";s:29:"Tasks:Qq5-SA5HpXiDvZoid7XCew2";s:4:"type";i:7;}i:2;a:5:{s:2:"id";s:9:"T20005be4";s:3:"mod";s:14:"Tasks folder 3";s:6:"parent";s:1:"0";s:8:"serverid";s:29:"Tasks:ZvPsA8vX_pfrgqw10pr5Sw1";s:4:"type";i:15;}i:3;a:5:{s:2:"id";s:2:"RI";s:3:"mod";s:2:"RI";s:6:"parent";s:1:"0";s:8:"serverid";s:2:"RI";s:4:"type";i:19;}i:4;a:5:{s:2:"id";s:9:"Nae7f1fb5";s:3:"mod";s:11:"Notes folder 1";s:6:"parent";s:1:"0";s:8:"serverid";s:29:"Notes:_IqHpMZrXeXonTgsCOdzng4";s:4:"type";i:10;}i:5;a:5:{s:2:"id";s:9:"N66b94b7f";s:3:"mod";s:19:"Notes folder 2";s:6:"parent";s:1:"0";s:8:"serverid";s:42:"Notes:53c1c9ee-a878-4c92-9431-5271904cae96";s:4:"type";i:17;}i:6;a:5:{s:2:"id";s:9:"Fbe043912";s:3:"mod";s:4:"Sent";s:6:"parent";s:1:"0";s:8:"serverid";s:4:"Sent";s:4:"type";i:5;}i:7;a:5:{s:2:"id";s:9:"Fb9dacd7c";s:3:"mod";s:5:"Inbox";s:6:"parent";s:1:"0";s:8:"serverid";s:5:"INBOX";s:4:"type";i:2;}i:8;a:5:{s:2:"id";s:9:"Fb49d5c74";s:3:"mod";s:6:"Drafts";s:6:"parent";s:1:"0";s:8:"serverid";s:6:"Drafts";s:4:"type";i:3;}i:9;a:5:{s:2:"id";s:9:"Fa4c68c30";s:3:"mod";s:4:"spam";s:6:"parent";s:1:"0";s:8:"serverid";s:10:"INBOX/spam";s:4:"type";i:12;}i:10;a:5:{s:2:"id";s:9:"F74b79d60";s:3:"mod";s:39:"shared/global@domain.tld/INBOX";s:6:"parent";s:1:"0";s:8:"serverid";s:39:"shared/global@domain.tld/INBOX";s:4:"type";i:12;}i:11;a:5:{s:2:"id";s:9:"F39166909";s:3:"mod";s:8:"Facebook";s:6:"parent";s:1:"0";s:8:"serverid";s:14:"INBOX/Facebook";s:4:"type";i:12;}i:12;a:5:{s:2:"id";s:9:"F06e3c9a8";s:3:"mod";s:5:"Trash";s:6:"parent";s:1:"0";s:8:"serverid";s:5:"Trash";s:4:"type";i:12;}i:13;a:5:{s:2:"id";s:9:"C9592a20f";s:3:"mod";s:31:"Addresses of user@domain.tld";s:6:"parent";s:1:"0";s:8:"serverid";s:32:"Contacts:N87-VUrDX0PIrYu6upm29A3";s:4:"type";i:9;}i:14;a:5:{s:2:"id";s:9:"A5cedb59d";s:3:"mod";s:30:"Calendar of
user@domain.tld";s:6:"parent";s:1:"0";s:8:"serverid";s:32:"Calendar:6s_Uns1LyNNNTDAJ23ynqA1";s:4:"type";i:8;}}";}i:2;s:10:"BBALPHA";i:3;i:0;i:4;s:10:"foldersync";i:5;s:18:"user@domain.tld";i:6;i:0;i:7;i:1414854217;}
[65522] Replacing SYNC_CACHE entry for user user@domain.tld and device
BBALPHA:
a:11:{s:18:"confirmed_synckeys";a:1:{s:39:"{5454f5eb-5fb4-436f-8d45-01d8904cae96}2";b:1;}s:17:"lasthbsyncstarted";b:0;s:17:"lastsyncendnormal";i:1414854125;s:9:"timestamp";s:10:"1414854217";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:15:{s:9:"Te7d04f54";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:29:"Tasks:a2vzXJABkjNLFwrHOe_F8g1";}s:9:"T9fce3cbc";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:29:"Tasks:Qq5-SA5HpXiDvZoid7XCew2";}s:9:"T20005be4";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:29:"Tasks:ZvPsA8vX_pfrgqw10pr5Sw1";}s:2:"RI";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:2:"RI";}s:9:"Nae7f1fb5";a:2:{s:5:"class";s:5:"Notes";s:8:"serverid";s:29:"Notes:_IqHpMZrXeXonTgsCOdzng4";}s:9:"N66b94b7f";a:2:{s:5:"class";s:5:"Notes";s:8:"serverid";s:42:"Notes:53c1c9ee-a878-4c92-9431-5271904cae96";}s:9:"Fbe043912";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:4:"Sent";}s:9:"Fb9dacd7c";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:5:"INBOX";}s:9:"Fb49d5c74";a:2:{s:5:"class";s:5:"Em
ail";s:8:"serverid";s:6:"Drafts";}s:9:"Fa4c68c30";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX/spam";}s:9:"F74b79d60";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:39:"shared/global@domain.tld/INBOX";}s:9:"F39166909";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:14:"INBOX/Facebook";}s:9:"F06e3c9a8";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:5:"Trash";}s:9:"C9592a20f";a:2:{s:5:"class";s:8:"Contacts";s:8:"serverid";s:32:"Contacts:N87-VUrDX0PIrYu6upm29A3";}s:9:"A5cedb59d";a:2:{s:5:"class";s:8:"Calendar";s:8:"serverid";s:32:"Calendar:6s_Uns1LyNNNTDAJ23ynqA1";}}s:9:"hierarchy";s:39:"{5454f648-6980-40e9-930b-fff2904cae96}1";s:11:"collections";a:0:{}s:13:"pingheartbeat";b:0;s:14:"synckeycounter";a:0:{}}
[65522] Maximum memory usage for ActiveSync request: 9350320 bytes.
--------
So the calendar's folder id is A5cedb59d.
But all subsequent sync requests will ask for a different one
--------
[65522] I <Synchronize>
[65522] I <Folders>
[65522] I <Folder>
[65522] I <SyncKey>
[65522] I 0
[65522] I </SyncKey>
[65522] I <FolderId>
[65522] I Fb9dacd7c
[65522] I </FolderId>
[65522] I </Folder>
[65522] Obtaining collection class of Email for collection id Fb9dacd7c
[65522] Collection added to collection handler: collection: INBOX,
synckey: NONE.
[65522] I <Folder>
[65522] I <SyncKey>
[65522] I 0
[65522] I </SyncKey>
[65522] I <FolderId>
[65522] I A6f99f74c
[65522] I </FolderId>
[65522] I </Folder>
[65522] Horde_ActiveSync_Collections::getBackendIdForFolderUid failed
because folder was not found in cache.
[65522] O <Synchronize>
[65522] O <Folders>
[65522] O <Folder>
[65522] O <SyncKey>
[65522] O {5454f64c-f0d4-4c4e-95b8-fff2904cae96}1
[65522] O </SyncKey>
[65522] O <FolderId>
[65522] O A6f99f74c
[65522] O </FolderId>
[65522] O <Status>
[65522] O 12
[65522] O </Status>
[65522] O </Folder>
[65522] O </Folders>
[65522] O </Synchronize>
[65522] Maximum memory usage for ActiveSync request: 5803368 bytes.
--------
--------
[65522] I <Synchronize>
[65522] I <Folders>
[65522] I <Folder>
[65522] I <SyncKey>
[65522] I {5454f64d-b3ac-4afc-927f-fff2904cae96}1
[65522] I </SyncKey>
[65522] I <FolderId>
[65522] I A6f99f74c
[65522] I </FolderId>
[65522] I <GetChanges />
[65522] I <WindowSize>
[65522] I 25
[65522] I </WindowSize>
[65522] I <Options>
[65522] I <FolderType>
[65522] I Calendar
[65522] I </FolderType>
[65522] I <FilterType>
[65522] I 6
[65522] I </FilterType>
[65522] I <AirSyncBase:BodyPreference>
[65522] I <AirSyncBase:Type>
[65522] I 1
[65522] I </AirSyncBase:Type>
[65522] I <AirSyncBase:TruncationSize>
[65522] I 1048576
[65522] I </AirSyncBase:TruncationSize>
[65522] I </AirSyncBase:BodyPreference>
[65522] I </Options>
[65522] I </Folder>
[65522] Horde_ActiveSync_Collections::getBackendIdForFolderUid failed
because folder was not found in cache.
[65522] Removing device state for sync_key
{5454f64d-b3ac-4afc-927f-fff2904cae96}1 only.
[65522] O <Synchronize>
[65522] O <Folders>
[65522] O <Folder>
[65522] O <FolderType>
[65522] O Calendar
[65522] O </FolderType>
[65522] O <SyncKey>
[65522] O {5454f64d-b3ac-4afc-927f-fff2904cae96}2
[65522] O </SyncKey>
[65522] O <FolderId>
[65522] O A6f99f74c
[65522] O </FolderId>
[65522] O <Status>
[65522] O 12
[65522] O </Status>
[65522] O </Folder>
[65522] O </Folders>
[65522] O </Synchronize>
[65522] Maximum memory usage for ActiveSync request: 5814208 bytes.
--------