[horde] FW: [sync] Activesync Errors
Michael J Rubinsky
mrubinsk at horde.org
Sat Oct 1 04:28:00 UTC 2011
Quoting Simon Brereton <simon.brereton at buongiorno.com>:
>> -----Original Message-----
>> From: horde-bounces at lists.horde.org [mailto:horde-
>> bounces at lists.horde.org] On Behalf Of Michael J Rubinsky
>> Quoting Simon Brereton <simon.brereton at buongiorno.com>:
>>
>> >> -----Original Message-----
>> >> From: horde-bounces at lists.horde.org [mailto:horde-
>> >> bounces at lists.horde.org] On Behalf Of Michael J Rubinsky Quoting
>> >> Simon Brereton <simon.brereton at buongiorno.com>:
>> >>
>> >> > Originally submitted to sync at lists.horde.org - perhaps that's
>> the
>> >> not
>> >> > the right location?
>> >> >
>> >> >
>> >> > 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:
>> >>
>> >> Your client is sending broken activesync date datatypes. Per the
>> >> specification:
>> >
>> > Odd. I could have sworn that was from Horde to the client.
>>
>> Well, the only place this error is thrown is during WBXML stream
>> *decoding*, which means it is coming from the client. When it comes
>> from the server we control the format and ensure it is sent
>> correctly.
>> Plus, any errors in date format when going server->client (which
>> would only happen if the turba data became corrupt), would be
>> silently ignored and no date would be sent to the client.
>
> Well, it wouldn't be the first time I was wrong - especially as I
> was syncing before I got the logging sorted. I agree that it's
> device to server - see below. Apologies for the noise.
>
>
>> > Basically, when I removed Funambol from the device the contacts
>> list
>> > on the phone was emptied. I waited 3 hours and nothing was synched
>> > from Horde to the device (as I would have expected and as was the
>> case
>> > with the calendar). In an effort to prompt it, I created a test
>> > contact on the phone (just a name, no number, no DoB, no email)
>> > and waited for it to be synched to Horde. After 2 hours - nada.
>> > Since I needed my contacts, I reloaded them (under the Activesync
>> > account) from an vcard I have on the device SD card...
>>
>> I'm confused...You mean you reloaded them from the SD card directly
>> onto the device? If that's the case, then of course these would be
>> changes from the device to server, you are essentially adding new
>> contacts to the device.
>>
>> > .. The caveat is that vcard on the SD card is a direct export from
>> Horde...
>>
>> Again, what are you doing with the vcard on the SD card?
>
> Long story and rather boring. Short version, Funambol wouldn't
> store the contacts in the same format I had them in Turba
> (+1-347-xxx-xxxx vs. +1347xxxxxxx) and that meant that if I let
> Funambol synch them, I ended up with duplicates in Turba. And I
> didn't see why Turba should fix Funambol's problem.
Ok, but that still doesn't answer my question. What are you doing with
the contacts on the SD card? How are you getting the contacts back
into Horde?
>> > Not saying that Horde isn't doing what it should be - but I have a
>> > standard OG Droid - have you heard of an issue where it doesn't
>> send
>> > the date in UTC? Since the only dates in the contact forms (and in
>> > the logs) that I can see are birthdates - i.e. 1964-01-01 - I'm not
>> > sure how to address this.
>>
>> I also have a OG Droid as my primary day to day phone. I have no
>> issues with this at all.
>
> Stepping back for a moment - before I loaded the contacts from the
> SD card, I created a test contact on the phone. That one never got
> to the server even though it was the only one on the phone.
> However, a test contact created in Horde was also not sent to the
> device. Given how quickly Kronolith sent the event, I'm
> surprised/confused/baffled.
>
> I think there shouldn't be an issue with the date because that data
> was imported from Horde (unless Horde isn't exporting it correctly -
> which I doubt). But realistically, the bigger problem I have
> have/had is that contacts aren't synching in either direction.
>
> If they had just synched from Horde to the device then I wouldn't
> have an issue..
>
> Since I've never seen a synch attempt from Horde to the device, I
> can only assume that during a sync it asks the Device if it has
> anything new first. Accordingly I deleted the account - all
> contacts are now gone.
The device initiates the entire process. Over simplifying but a basic
description is: the device sends an initial sync request that primes
the server state, so to speak. After this initial sync (the synckey
will be zero), the server sends all contacts to the device. After this
initial exchange the device pings the server for changes. The server
NEVER asks the device if there is anything new. If the device has
changes, it sends them to the server in a SYNC request, but this will
ONLY happen after the account has been primed i.e., after all the
existing server contacts are sent to the device. In other words, NO
contacts that exist before the initial sync will be sent from the
device to server.
> I recreate the account and all I have in the logs is:
>
> 2011-09-30T21:32:52+01:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for: simon at mydomain.net
> 2011-09-30T21:32:52+01:00 DEBUG: [androidc1387223434] FOLDERSYNC
> request received for user simon at mydomain.net
> 2011-09-30T21:32:52+01:00 DEBUG: [androidc1387223434]
> loadDeviceInfo: simon at mydomain.net
> 2011-09-30T21:32:52+01:00 DEBUG: Resetting PING state
> 2011-09-30T21:32:52+01:00 INFO: Request being handled for device:
> androidc1387223434 Supporting protocol version: 2.5
> 2011-09-30T21:32:52+01:00 INFO: [Horde_ActiveSync::handleFolderSync]
> Beginning FOLDERSYNC
> 2011-09-30T21:32:52+01:00 DEBUG: [androidc1387223434] Checking
> policykey for device Key: 0 User: simon at mydomain.net
> 2011-09-30T21:32:52+01:00 DEBUG: [androidc1387223434]
> loadDeviceInfo: simon at mydomain.net
> 2011-09-30T21:32:52+01:00 DEBUG: Policykey: verified.
> 2011-09-30T21:32:52+01:00 DEBUG: I <FolderHierarchy:FolderSync>
> 2011-09-30T21:32:52+01:00 DEBUG: I <FolderHierarchy:SyncKey>
> 2011-09-30T21:32:52+01:00 DEBUG: I {munged-data}1
> 2011-09-30T21:32:52+01:00 DEBUG: I </FolderHierarchy:SyncKey>
> 2011-09-30T21:32:52+01:00 DEBUG:
> [Horde_ActiveSync::handleFolderSync] syncKey: {munged-data}1
> 2011-09-30T21:32:52+01:00 DEBUG: [androidc1387223434] Loading state
> for synckey {munged-data}1
> 2011-09-30T21:32:52+01:00 DEBUG: [androidc1387223434] Loading
> FOLDERSYNC state: Array
> (
> [0] => Array
> (
> [id] => Tasks
> [mod] => Tasks
> [parent] => 0
> )
>
> [1] => Array
> (
> [id] => Contacts
> [mod] => Contacts
> [parent] => 0
> )
>
> [2] => Array
> (
> [id] => Calendar
> [mod] => Calendar
> [parent] => 0
> )
>
> )
> 2011-09-30T21:32:52+01:00 DEBUG: I </FolderHierarchy:FolderSync>
> 2011-09-30T21:23:56+01:00 DEBUG:
> [Horde_ActiveSync::handleFolderSync] Preparing to send changes to PIM
> 2011-09-30T21:23:56+01:00 DEBUG:
> [Horde_ActiveSync::handleFolderSync] newSyncKey: {munged-data}2
> 2011-09-30T21:23:56+01:00 DEBUG: [androidc1387223434] Initializing
> folder diff engine
> 2011-09-30T21:23:56+01:00 DEBUG: Horde::getFolderList()
> 2011-09-30T21:23:56+01:00 DEBUG: Horde::statFolder(Calendar)
> 2011-09-30T21:23:56+01:00 DEBUG: Horde::statFolder(Contacts)
> 2011-09-30T21:23:56+01:00 DEBUG: Horde::statFolder(Tasks)
> 2011-09-30T21:23:56+01:00 DEBUG: [androidc1387223434] Found 0 folder changes
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:FolderSync>
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:Status>
> 2011-09-30T21:23:56+01:00 DEBUG: O 1
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:Status/>
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:SyncKey>
> 2011-09-30T21:23:56+01:00 DEBUG: O {munged-data}1
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:SyncKey/>
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:Changes>
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:Count>
> 2011-09-30T21:23:56+01:00 DEBUG: O 0
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:Count/>
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:Changes/>
> 2011-09-30T21:23:56+01:00 DEBUG: O <FolderHierarchy:FolderSync/>
> 2011-09-30T21:23:56+01:00 INFO: User simon at mydomain.net logged off
This log is *not* from a freshly created account. The client is
sending a FOLDERSYNC request with a synckey other than zero, and the
server knows about it (since it successfully loads the state).
Completely remove the account from both the server and the phone.
Reboot the phone. Add your contacts *on the server*. Then create the
AS account on the phone. When you create the account, only enable
contacts, and capture the log for what happens.
> Now I have nothing in the calendar or the address book :)
>
>
>> >> The invalid address book error sounds to me like your "default"
>> >> address book is either corrupt or pointing to an address book that
>> no
>> >> longer exists.
>> >
>> > How do I debug that? I mean ever since I installed H4 and imported
>> > the data from the H3 DB and updates the schemas everything has
>> worked
>> > fine. I can see my default address book, add, edit and delete with
>> no
>> > issue. I have only one address book, so I can't really see how
>> > anything can be pointing to something else. I could reimport the
>> data
>> > (from the vcard above) and overwrite the address book if you think
>> > that would help..
>>
>> What do the turba prefs say about your default and sync'd address
>> books?
>
> Turba says I only have Address book of Simon B and sure enough
> that's the one the Turba preferences say to sync.
>
>
>> I use the defaults. If you want to change them, you'll have to
>> experiment as to what gives you the best performance vs battery life
>> you are looking for.
>
> Thanks! I'll set it to forced and see what gives. Are these rules
> as whether the waitinterval can be? I.e. Not longer than the
> heatbeat, I assume..?
Yes, if waitinterval > heartbeat then you would essentially get a
single poll for changes per heartbeat, since the heartbeat would
expire before the waitinternval and the response would be sent.
Honestly, you should avoid making too many changes until you figure
out what is wrong.
--
mike
The Horde Project (www.horde.org)
mrubinsk at horde.org
More information about the horde
mailing list