2013-12-24T13:53:26+00:00 INFO: [31325] Horde_Core_ActiveSync_Driver::authenticate() attempt for mail-test
2013-12-24T13:53:26+00:00 INFO: [] SYNC request received for user mail-test
2013-12-24T13:53:26+00:00 INFO: [31325] Device entry exists for APPL888298T71R4, updating userAgent and version.
2013-12-24T13:53:26+00:00 INFO: [31325] Request being handled for device: APPL888298T71R4, Supporting protocol version: 14.0, Using Horde_ActiveSync v2.9.2
2013-12-24T13:53:26+00:00 INFO: [31325] Handling SYNC command.
2013-12-24T13:53:26+00:00 INFO: [31325] Checking policykey for device: APPL888298T71R4 user: mail-test
2013-12-24T13:53:26+00:00 INFO: [31325] Policykey: 0 verified.
2013-12-24T13:53:26+00:00 DEBUG: [31325] I  <Synchronize>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I   <Folders>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I    <Folder>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     <SyncKey>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       {52b98eba-0514-46d3-a1f9-76cdb220dc12}3
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     </SyncKey>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     <FolderId>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       @Contacts@
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     </FolderId>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     <GetChanges />
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     <WindowSize>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       25
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     </WindowSize>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     <Options>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I      <AirSyncBase:BodyPreference>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       <AirSyncBase:Type>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         1
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       </AirSyncBase:Type>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       <AirSyncBase:TruncationSize>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         32768
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       </AirSyncBase:TruncationSize>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I      </AirSyncBase:BodyPreference>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     </Options>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I     <Commands>
2013-12-24T13:53:26+00:00 INFO: [31325] Obtaining collection class of Contacts for collection id @Contacts@
2013-12-24T13:53:26+00:00 INFO: [31325] Initializing state for collection: @Contacts@, synckey: {52b98eba-0514-46d3-a1f9-76cdb220dc12}3
2013-12-24T13:53:26+00:00 INFO: [31325] Loading state for synckey {52b98eba-0514-46d3-a1f9-76cdb220dc12}3
2013-12-24T13:53:26+00:00 DEBUG: [31325] I      <Modify>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       <ServerEntryId>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         [59 bytes of content]
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       </ServerEntryId>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       <Data>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        <AirSyncBase:Body>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         <AirSyncBase:Type>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I           1
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         </AirSyncBase:Type>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         <AirSyncBase:Data>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I           Test
2013-12-24T13:53:26+00:00 DEBUG: [31325] I         </AirSyncBase:Data>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        </AirSyncBase:Body>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        <POOMCONTACTS:Birthday>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I          1981-05-05T22:00:00.000Z
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        </POOMCONTACTS:Birthday>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        <POOMCONTACTS:FileAs>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I          Mail Test
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        </POOMCONTACTS:FileAs>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        <POOMCONTACTS:FirstName>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I          Test
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        </POOMCONTACTS:FirstName>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        <POOMCONTACTS:LastName>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I          Mail
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        </POOMCONTACTS:LastName>
2013-12-24T13:53:26+00:00 DEBUG: [31325] I        <POOMCONTACTS:Picture />
2013-12-24T13:53:26+00:00 DEBUG: [31325] I       </Data>
2013-12-24T13:53:26+00:00 INFO: [31325] Horde_Core_ActiveSync_Driver::_smartStatMessage(@Contacts@, 20131224135133.Uoa6DtHeKZkZe-Pkfe99PA3@mail-test.example.fr)
2013-12-24T13:53:26+00:00 INFO: [31325] Horde_Core_ActiveSync_Driver::changeMessage(@Contacts@, 20131224135133.Uoa6DtHeKZkZe-Pkfe99PA3@mail-test.example.fr ...)
2013-12-24T13:53:27+00:00 INFO: [31325] Horde_Core_ActiveSync_Driver::_smartStatMessage(@Contacts@, 20131224135133.Uoa6DtHeKZkZe-Pkfe99PA3@mail-test.example.fr)
2013-12-24T13:53:27+00:00 INFO: [31325] Updating state during change
2013-12-24T13:53:27+00:00 DEBUG: [31325] I      </Modify>
2013-12-24T13:53:27+00:00 DEBUG: [31325] I     </Commands>
2013-12-24T13:53:27+00:00 INFO: [31325] Processed 1 incoming changes
2013-12-24T13:53:27+00:00 DEBUG: [31325] I    </Folder>
2013-12-24T13:53:27+00:00 INFO: [31325] Collection added to collection handler: collection: @Contacts@, synckey: {52b98eba-0514-46d3-a1f9-76cdb220dc12}3.
2013-12-24T13:53:27+00:00 DEBUG: [31325] I   </Folders>
2013-12-24T13:53:27+00:00 DEBUG: [31325] I  </Synchronize>
2013-12-24T13:53:27+00:00 INFO: [31325] Clearing all collection synckeys from the cache.
2013-12-24T13:53:27+00:00 INFO: Have syncable collections
2013-12-24T13:53:27+00:00 INFO: [31325] Replacing SYNC_CACHE entry for user mail-test and device APPL888298T71R4: a:10:{s:18:"confirmed_synckeys";a:0:{}s:17:"lasthbsyncstarted";i:1387893125;s:17:"lastsyncendnormal";i:1387893118;s:9:"timestamp";s:10:"1387893207";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:12:{s:9:"Fde7a1f27";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX.Sent";}s:9:"Fcebfbcfc";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:11:"INBOX.Spams";}s:9:"Fb233a00b";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:12:"INBOX.Level1";}s:9:"F87304457";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:15:"INBOX.Templates";}s:9:"F404e014d";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:5:"INBOX";}s:9:"F33bc60fb";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:13:"INBOX.Deleted";}s:9:"F10d5b5ba";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:12:"INBOX.Drafts";}s:9:"F00c1999e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:19:"INBOX.Level1.Level6";}s:7:"@Tasks@";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:7:"@Tasks@";}s:7:"@Notes@";a:2:{s:5:"class";s:5:"Notes";s:8:"serverid";s:7:"@Notes@";}s:10:"@Contacts@";a:2:{s:5:"class";s:8:"Contacts";s:8:"serverid";s:10:"@Contacts@";}s:10:"@Calendar@";a:2:{s:5:"class";s:8:"Calendar";s:8:"serverid";s:10:"@Calendar@";}}s:9:"hierarchy";s:39:"{52b98eb5-0564-4461-8b5a-696eb220dc12}1";s:11:"collections";a:1:{s:10:"@Contacts@";a:11:{s:5:"class";s:8:"Contacts";s:10:"windowsize";s:2:"25";s:10:"filtertype";s:1:"0";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@Contacts@";s:11:"lastsynckey";s:39:"{52b98eba-0514-46d3-a1f9-76cdb220dc12}3";s:8:"pingable";b:1;}}s:13:"pingheartbeat";b:0;}
2013-12-24T13:53:27+00:00 INFO: [31325] All synckeys confirmed. Continuing with SYNC
2013-12-24T13:53:27+00:00 DEBUG: [31325] O  <Synchronize>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O   <Status>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O    1
2013-12-24T13:53:27+00:00 DEBUG: [31325] O   </Status>
2013-12-24T13:53:27+00:00 INFO: [31325] Initializing state for collection: @Contacts@, synckey: {52b98eba-0514-46d3-a1f9-76cdb220dc12}3
2013-12-24T13:53:27+00:00 INFO: [31325] Loading state for synckey {52b98eba-0514-46d3-a1f9-76cdb220dc12}3
2013-12-24T13:53:27+00:00 INFO: [31325] Initializing message diff engine for @Contacts@ (@Contacts@)
2013-12-24T13:53:27+00:00 INFO: [31325] Using SYNCSTAMP 551002 for @Contacts@.
2013-12-24T13:53:27+00:00 INFO: [31325] Horde_Core_ActiveSync_Driver::getServerChanges(@Contacts@, 551001, 551002, 0, 0)
2013-12-24T13:53:27+00:00 INFO: [31325] Fetching changes for contacts using MODSEQ.
2013-12-24T13:53:27+00:00 INFO: [31325] Found 1 message changes in @Contacts@.
2013-12-24T13:53:27+00:00 INFO: [31325] Checking for PIM initiated changes.
2013-12-24T13:53:27+00:00 INFO: [31325] Horde_Core_ActiveSync_Driver::_smartStatMessage(@Contacts@, 20131224135133.Uoa6DtHeKZkZe-Pkfe99PA3@mail-test.example.fr)
2013-12-24T13:53:27+00:00 INFO: [31325] Ignoring PIM initiated change for 20131224135133.Uoa6DtHeKZkZe-Pkfe99PA3@mail-test.example.fr (PIM TS: 551002 Stat TS: 551002)
2013-12-24T13:53:27+00:00 INFO: [31325] Old SYNCKEY: {52b98eba-0514-46d3-a1f9-76cdb220dc12}3, New SYNCKEY: {52b98eba-0514-46d3-a1f9-76cdb220dc12}4
2013-12-24T13:53:27+00:00 DEBUG: [31325] O   <Folders>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O    <Folder>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O     <SyncKey>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O      {52b98eba-0514-46d3-a1f9-76cdb220dc12}4
2013-12-24T13:53:27+00:00 DEBUG: [31325] O     </SyncKey>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O     <FolderId>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O      @Contacts@
2013-12-24T13:53:27+00:00 DEBUG: [31325] O     </FolderId>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O     <Status>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O      1
2013-12-24T13:53:27+00:00 DEBUG: [31325] O     </Status>
2013-12-24T13:53:27+00:00 INFO: [31325] Saving state: a:8:{i:0;s:39:"{52b98eba-0514-46d3-a1f9-76cdb220dc12}4";i:1;O:21:"Horde_Db_Value_Binary":1:{s:9:"^@*^@_value";s:117:"C:34:"Horde_ActiveSync_Folder_Collection":70:{{"s":[],"f":"@Contacts@","c":"Contacts","lsd":0,"sd":0,"i":true,"v":1}}";}i:2;s:15:"APPL888298T71R4";i:3;i:551002;i:4;s:10:"@Contacts@";i:5;s:9:"mail-test";i:6;i:0;i:7;i:1387893207;}
2013-12-24T13:53:27+00:00 DEBUG: [31325] O    </Folder>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O   </Folders>
2013-12-24T13:53:27+00:00 DEBUG: [31325] O  </Synchronize>
2013-12-24T13:53:27+00:00 INFO: [31325] Replacing SYNC_CACHE entry for user mail-test and device APPL888298T71R4: a:10:{s:18:"confirmed_synckeys";a:1:{s:39:"{52b98eba-0514-46d3-a1f9-76cdb220dc12}4";b:1;}s:17:"lasthbsyncstarted";i:1387893125;s:17:"lastsyncendnormal";i:1387893207;s:9:"timestamp";s:10:"1387893207";s:4:"wait";b:0;s:10:"hbinterval";b:0;s:7:"folders";a:12:{s:9:"Fde7a1f27";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:10:"INBOX.Sent";}s:9:"Fcebfbcfc";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:11:"INBOX.Spams";}s:9:"Fb233a00b";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:12:"INBOX.Level1";}s:9:"F87304457";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:15:"INBOX.Templates";}s:9:"F404e014d";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:5:"INBOX";}s:9:"F33bc60fb";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:13:"INBOX.Deleted";}s:9:"F10d5b5ba";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:12:"INBOX.Drafts";}s:9:"F00c1999e";a:2:{s:5:"class";s:5:"Email";s:8:"serverid";s:19:"INBOX.Level1.Level6";}s:7:"@Tasks@";a:2:{s:5:"class";s:5:"Tasks";s:8:"serverid";s:7:"@Tasks@";}s:7:"@Notes@";a:2:{s:5:"class";s:5:"Notes";s:8:"serverid";s:7:"@Notes@";}s:10:"@Contacts@";a:2:{s:5:"class";s:8:"Contacts";s:8:"serverid";s:10:"@Contacts@";}s:10:"@Calendar@";a:2:{s:5:"class";s:8:"Calendar";s:8:"serverid";s:10:"@Calendar@";}}s:9:"hierarchy";s:39:"{52b98eb5-0564-4461-8b5a-696eb220dc12}1";s:11:"collections";a:1:{s:10:"@Contacts@";a:11:{s:5:"class";s:8:"Contacts";s:10:"windowsize";s:2:"25";s:10:"filtertype";s:1:"0";s:10:"truncation";i:0;s:11:"mimesupport";i:0;s:14:"mimetruncation";i:8;s:8:"conflict";i:1;s:9:"bodyprefs";a:1:{i:1;a:2:{s:4:"type";s:1:"1";s:14:"truncationsize";s:5:"32768";}}s:8:"serverid";s:10:"@Contacts@";s:11:"lastsynckey";s:39:"{52b98eba-0514-46d3-a1f9-76cdb220dc12}4";s:8:"pingable";b:1;}}s:13:"pingheartbeat";b:0;}
2013-12-24T13:53:27+00:00 INFO: [] Maximum memory usage for ActiveSync request: 7318840 bytes.