[horde] FW: [sync] Activesync Errors

Fri Sep 30 16:51:53 UTC 2011

Originally submitted to sync at lists.horde.org - perhaps that's the not the right location?

Hi

After resolving my logging errors and getting sync to work I was reasonably impressed.

Calendar syncs almost immediately - I made a test appointment in Horde, and by the time I opened the calendar on the phone, it was there.  Deleting it from the phone took a while to replicate on Horde though - and I'm not quite sure why.  Not that I'm complaining - I'd just like to understand the limitations.

Address book is a whole other ball game.  I created a new contact on the phone and it never appeared in Horde.  None of the contacts in Horde appear on the phone either.

The sync.log has these errors:

2011-09-29T20:29:45+01:00 ERR: Returning HTTP 500:Invalid date format 2011-09-29T20:30:39+01:00 ERR: Invalid address book: b3790d4757f941c995645660f0ba886c 2011-09-29T20:30:39+01:00 ERR: Invalid address book: b3790d4757f941c995645660f0ba886c 2011-09-29T20:30:39+01:00 ERR: Invalid address book: b3790d4757f941c995645660f0ba886c 2011-09-29T20:30:39+01:00 ERR: Returning HTTP 500:Invalid date format 2011-09-29T20:31:55+01:00 ERR: Invalid address book:
2011-09-29T20:31:55+01:00 ERR: Invalid address book:
2011-09-29T20:31:55+01:00 ERR: Invalid address book:
2011-09-29T20:31:55+01:00 ERR: Returning HTTP 500:Invalid date format

The invalid date format occurs like this:

2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:Birthday>
2011-09-29T21:22:20+01:00 DEBUG: I         1964-01-01
2011-09-29T21:22:20+01:00 ERR: Returning HTTP 500:Invalid date format

The invalid errors occur like:

2011-09-29T21:22:19+01:00 DEBUG: [androidc1387223434] SYNC request received for user simon at mydomain.net 2011-09-29T21:22:19+01:00 DEBUG: [androidc1387223434] loadDeviceInfo: simon at mydomain.net 2011-09-29T21:22:20+01:00 INFO: Request being handled for device: androidc1387223434 Supporting protocol version: 2.5 2011-09-29T21:22:20+01:00 INFO: [androidc1387223434] Handling SYNC command.
2011-09-29T21:22:20+01:00 DEBUG: [androidc1387223434] Checking policykey for device  Key: 0 User: simon at mydomain.net 2011-09-29T21:22:20+01:00 DEBUG: [androidc1387223434] loadDeviceInfo: simon at mydomain.net 2011-09-29T21:22:20+01:00 DEBUG: Policykey:  verified.
2011-09-29T21:22:20+01:00 DEBUG: I  <Synchronize>
2011-09-29T21:22:20+01:00 DEBUG: I   <Folders>
2011-09-29T21:22:20+01:00 DEBUG: I    <Folder>
2011-09-29T21:22:20+01:00 DEBUG: I     <FolderType>
2011-09-29T21:22:20+01:00 DEBUG: I      Contacts
2011-09-29T21:22:20+01:00 INFO: [androidc1387223434] Syncing folder class: Contacts
2011-09-29T21:22:20+01:00 DEBUG: I     </FolderType>
2011-09-29T21:22:20+01:00 DEBUG: I     <SyncKey>
2011-09-29T21:22:20+01:00 DEBUG: I      {think-I-should-munge-this}1
2011-09-29T21:22:20+01:00 DEBUG: I     </SyncKey>
2011-09-29T21:22:20+01:00 DEBUG: I     <FolderId>
2011-09-29T21:22:20+01:00 DEBUG: I      Contacts
2011-09-29T21:22:20+01:00 INFO: [androidc1387223434] Folder server id: Contacts
2011-09-29T21:22:20+01:00 DEBUG: I     </FolderId>
2011-09-29T21:22:20+01:00 DEBUG: I     <DeletesAsMoves/>
2011-09-29T21:22:20+01:00 DEBUG: I     <GetChanges/>
2011-09-29T21:22:20+01:00 DEBUG: I     <WindowSize>
2011-09-29T21:22:20+01:00 DEBUG: I      4
2011-09-29T21:22:20+01:00 DEBUG: I     </WindowSize>
2011-09-29T21:22:20+01:00 DEBUG: I     <Options>
2011-09-29T21:22:20+01:00 DEBUG: I      <Truncation>
2011-09-29T21:22:20+01:00 DEBUG: I       7
2011-09-29T21:22:20+01:00 DEBUG: I      </Truncation>
2011-09-29T21:22:20+01:00 DEBUG: I     </Options>
2011-09-29T21:22:20+01:00 DEBUG: [androidc1387223434] Loading state for synckey {think-I-should-munge-this}1
2011-09-29T21:22:20+01:00 DEBUG: I     <Commands>
2011-09-29T21:22:20+01:00 DEBUG: I      <Add>
2011-09-29T21:22:20+01:00 DEBUG: I       <ClientEntryId>
2011-09-29T21:22:20+01:00 DEBUG: I        new_33_1317327735434
2011-09-29T21:22:20+01:00 DEBUG: I       </ClientEntryId>
2011-09-29T21:22:20+01:00 DEBUG: I       <Data>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:LastName>
2011-09-29T21:22:20+01:00 DEBUG: I         AIT 
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:LastName>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:FirstName>
2011-09-29T21:22:20+01:00 DEBUG: I         BRAHIM
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:FirstName>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:MiddleName>
2011-09-29T21:22:20+01:00 DEBUG: I
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:MiddleName>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:Suffix>
2011-09-29T21:22:20+01:00 DEBUG: I
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:Suffix>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:Title>
2011-09-29T21:22:20+01:00 DEBUG: I
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:Title>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:FileAs>
2011-09-29T21:22:20+01:00 DEBUG: I         BRAHIM  AIT 
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:FileAs>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:BusinessPhoneNumber>
2011-09-29T21:22:20+01:00 DEBUG: I         +33147979778
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:BusinessPhoneNumber>
2011-09-29T21:22:20+01:00 DEBUG: I        <POOMCONTACTS:MobilePhoneNumber>
2011-09-29T21:22:20+01:00 DEBUG: I         +33610964770
2011-09-29T21:22:20+01:00 DEBUG: I        </POOMCONTACTS:MobilePhoneNumber>
2011-09-29T21:22:20+01:00 DEBUG: I       </Data>
2011-09-29T21:22:20+01:00 DEBUG: Horde::changeMessage(Contacts, ) 2011-09-29T21:22:20+01:00 ERR: Invalid address book: b3790d4757f941c995645660f0ba886c

But all the data - apart from one test contact is coming from Data that's always been in Horde.  Including the data format.  Can someone help me debug this?

Also - it seems to sync the calendar every 5 minutes, which seems a little aggressive (and is killing my Droid's battery).  Is this normal?

Thanks.

Simon