[horde] ActiveSync problem
Simon Wilson
simon at simonandkate.net
Sun Jul 17 13:34:19 UTC 2011
I have been trying to get ActiveSync working for a while with limited success.
Horde 4.0.7, Turba 3.0.4. Hordeauth is set to use LDAP. Turba links
into LDAP for both a Personal LDAP address book and also a Shared
Address Book.
In Turba this config works fine, I have all the appropriate access
across all users to their relevant address books and also the shared
one.
Now ActiveSync.
I have tried this on multiple devices - an iPhone that has other
"Exchange" email accounts active, and an iPad that does not, which is
what I am testing on now.
Initial discovery and sync - works fine. The iPad "sees" Horde, and
syncs the Contacts from LDAP immediately.
Changes in Turba - add, delete, edit: all sync almost immediately thru
to the iPad.
Changes on iPad end - This is the problem child. Nothing happens in
Turba. The iPad sits spinning its "network activity" wheel, and Turba
doesn't update. All through this period, I see this set of messages
every five seconds in the Activesync log:
2011-07-17T22:52:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Attempting to load
PING state for: Contacts
2011-07-17T22:52:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Obtained last sync
time for Contacts - 1310907098
2011-07-17T22:52:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Initializing
message diff engine for Contacts
2011-07-17T22:52:14+10:00 DEBUG:
Horde_ActiveSync_Driver_Horde::getServerChanges(Contacts, 1310907098,
1310907134, 0)
2011-07-17T22:52:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Found 0 message
changes, checking for PIM initiated changes.
2011-07-17T22:52:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] No PIM changes
present, returning all messages.
And nothing changes in Turba.
As an unrelated thing I restarted Apache on the server, and then when
it came back up BANG - the queued test entry activity hit Turba with
the following log messages:
2011-07-17T22:56:42+10:00 INFO: Horde_ActiveSync_Driver_Horde::logon
attempt for: simon
2011-07-17T22:56:42+10:00 INFO: Request received from device:
ApplDLXFT5X3DFJ2 Supporting protocol version: 2.5
2011-07-17T22:56:42+10:00 INFO: [ApplDLXFT5X3DFJ2] Handling SYNC command.
2011-07-17T22:56:42+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Checking policykey
for device Key: 0 User: simon
2011-07-17T22:56:42+10:00 DEBUG: Policykey: 0 verified.
2011-07-17T22:56:42+10:00 DEBUG: I <Synchronize>
2011-07-17T22:56:42+10:00 DEBUG: I <Folders>
2011-07-17T22:56:42+10:00 DEBUG: I <Folder>
2011-07-17T22:56:42+10:00 DEBUG: I <FolderType>
2011-07-17T22:56:42+10:00 DEBUG: I Contacts
2011-07-17T22:56:42+10:00 INFO: [ApplDLXFT5X3DFJ2] Syncing folder
class: Contacts
2011-07-17T22:56:42+10:00 DEBUG: I </FolderType>
2011-07-17T22:56:42+10:00 DEBUG: I <SyncKey>
2011-07-17T22:56:42+10:00 DEBUG: I
{4e22daa7-bc04-4fd4-a63a-3d51c0a801aa}3
2011-07-17T22:56:42+10:00 DEBUG: I </SyncKey>
2011-07-17T22:56:42+10:00 DEBUG: I <FolderId>
2011-07-17T22:56:42+10:00 DEBUG: I Contacts
2011-07-17T22:56:42+10:00 INFO: [ApplDLXFT5X3DFJ2] Folder server id: Contacts
2011-07-17T22:56:42+10:00 DEBUG: I </FolderId>
2011-07-17T22:56:42+10:00 DEBUG: I <DeletesAsMoves/>
2011-07-17T22:56:42+10:00 DEBUG: Unmatched tagSupported:
2011-07-17T22:56:42+10:00 DEBUG: I <GetChanges/>
2011-07-17T22:56:42+10:00 DEBUG: I <WindowSize>
2011-07-17T22:56:42+10:00 DEBUG: I 25
2011-07-17T22:56:42+10:00 DEBUG: I </WindowSize>
2011-07-17T22:56:42+10:00 DEBUG: I <Commands>
2011-07-17T22:56:42+10:00 DEBUG: Unmatched tagOptions:
2011-07-17T22:56:42+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Loading state for
synckey {4e22daa7-bc04-4fd4-a63a-3d51c0a801aa}3
2011-07-17T22:56:42+10:00 DEBUG: [ApplDLXFT5X3DFJ2] SQL query by
Horde_ActiveSync_State:_gc(): SELECT sync_key FROM
horde_activesync_state WHERE sync_devid = ? AND sync_folderid = ?
VALUES: Array
(
[0] => ApplDLXFT5X3DFJ2
[1] => Contacts
)
2011-07-17T22:56:42+10:00 DEBUG: I <Add>
2011-07-17T22:56:42+10:00 DEBUG: I <ClientEntryId>
2011-07-17T22:56:42+10:00 DEBUG: Unmatched tagServerEntryId:
2011-07-17T22:56:42+10:00 DEBUG: I 721
2011-07-17T22:56:42+10:00 DEBUG: I </ClientEntryId>
2011-07-17T22:56:42+10:00 DEBUG: I <Data>
2011-07-17T22:56:42+10:00 DEBUG: I <POOMCONTACTS:Body/>
2011-07-17T22:56:42+10:00 DEBUG: I <POOMCONTACTS:Email1Address>
2011-07-17T22:56:42+10:00 DEBUG: I test at simonandkate.net
2011-07-17T22:56:42+10:00 DEBUG: I </POOMCONTACTS:Email1Address>
2011-07-17T22:56:42+10:00 DEBUG: I <POOMCONTACTS:FileAs>
2011-07-17T22:56:42+10:00 DEBUG: I Test, Test
2011-07-17T22:56:42+10:00 DEBUG: I </POOMCONTACTS:FileAs>
2011-07-17T22:56:42+10:00 DEBUG: I <POOMCONTACTS:FirstName>
2011-07-17T22:56:42+10:00 DEBUG: I Test
2011-07-17T22:56:42+10:00 DEBUG: I </POOMCONTACTS:FirstName>
2011-07-17T22:56:42+10:00 DEBUG: I <POOMCONTACTS:LastName>
2011-07-17T22:56:42+10:00 DEBUG: I Test
2011-07-17T22:56:42+10:00 DEBUG: I </POOMCONTACTS:LastName>
2011-07-17T22:56:42+10:00 DEBUG: I <POOMCONTACTS:Picture/>
2011-07-17T22:56:42+10:00 DEBUG: I </Data>
2011-07-17T22:56:42+10:00 DEBUG: Horde::changeMessage(Contacts, )
2011-07-17T22:56:43+10:00 DEBUG:
ActiveSync_Driver_Horde::_smartStatMessage:Contacts:20110717225642.WKMBMdJO7vlOItwKLfKj5vA at mail.simonandkate.net
2011-07-17T22:56:43+10:00 DEBUG: I </Add>
2011-07-17T22:56:43+10:00 DEBUG: I </Commands>
2011-07-17T22:56:43+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Processed 1
incoming changes
2011-07-17T22:56:43+10:00 DEBUG: I </Folder>
2011-07-17T22:56:43+10:00 DEBUG: I </Folders>
2011-07-17T22:56:43+10:00 DEBUG: Unmatched tagFolder:
2011-07-17T22:56:43+10:00 DEBUG: I </Synchronize>
2011-07-17T22:56:43+10:00 INFO: [ApplDLXFT5X3DFJ2] Beginning SYNC Response.
2011-07-17T22:56:43+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Initializing
message diff engine for Contacts
2011-07-17T22:56:43+10:00 DEBUG:
Horde_ActiveSync_Driver_Horde::getServerChanges(Contacts, 1310907098,
1310907403, 0)
2011-07-17T22:56:43+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Found 0 message
changes, checking for PIM initiated changes.
2011-07-17T22:56:43+10:00 DEBUG: O <Synchronize>
2011-07-17T22:56:43+10:00 DEBUG: O <Folders>
2011-07-17T22:56:43+10:00 DEBUG: O <Folder>
2011-07-17T22:56:43+10:00 DEBUG: O <FolderType>
2011-07-17T22:56:43+10:00 DEBUG: O Contacts
2011-07-17T22:56:43+10:00 DEBUG: O <FolderType/>
2011-07-17T22:56:43+10:00 DEBUG: O <SyncKey>
2011-07-17T22:56:43+10:00 DEBUG: O {4e22daa7-bc04-4fd4-a63a-3d51c0a801aa}4
2011-07-17T22:56:43+10:00 DEBUG: O <SyncKey/>
2011-07-17T22:56:43+10:00 DEBUG: O <FolderId>
2011-07-17T22:56:43+10:00 DEBUG: O Contacts
2011-07-17T22:56:43+10:00 DEBUG: O <FolderId/>
2011-07-17T22:56:43+10:00 DEBUG: O <Status>
2011-07-17T22:56:43+10:00 DEBUG: O 1
2011-07-17T22:56:43+10:00 DEBUG: O <Status/>
2011-07-17T22:56:43+10:00 DEBUG: O <Replies>
2011-07-17T22:56:43+10:00 DEBUG: O <Add>
2011-07-17T22:56:43+10:00 DEBUG: O <ClientEntryId>
2011-07-17T22:56:43+10:00 DEBUG: O 721
2011-07-17T22:56:43+10:00 DEBUG: O <ClientEntryId/>
2011-07-17T22:56:43+10:00 DEBUG: O <ServerEntryId>
2011-07-17T22:56:43+10:00 DEBUG: O
20110717225642.WKMBMdJO7vlOItwKLfKj5vA at mail.simonandkate.net
2011-07-17T22:56:43+10:00 DEBUG: O <ServerEntryId/>
2011-07-17T22:56:43+10:00 DEBUG: O <Status>
2011-07-17T22:56:43+10:00 DEBUG: O 1
2011-07-17T22:56:43+10:00 DEBUG: O <Status/>
2011-07-17T22:56:43+10:00 DEBUG: O <Add/>
2011-07-17T22:56:43+10:00 DEBUG: O <Replies/>
2011-07-17T22:56:43+10:00 DEBUG: O <Folder/>
2011-07-17T22:56:43+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Saving state: Array
(
[0] => {4e22daa7-bc04-4fd4-a63a-3d51c0a801aa}4
[1] => a:0:{}
[2] => ApplDLXFT5X3DFJ2
[3] => 1310907403
[4] => Contacts
[5] => simon
)
2011-07-17T22:56:43+10:00 DEBUG: O <Folders/>
2011-07-17T22:56:43+10:00 DEBUG: O <Synchronize/>
2011-07-17T22:56:43+10:00 INFO: User simon logged off
That got me interested - so i tried again. Created a new contact on
the iPad. The iPad sat there trying to contact server, but nothing
synced.
Every 5 seconds in the activesync log:
2011-07-17T23:16:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Attempting to load
PING state for: Contacts
2011-07-17T23:16:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Obtained last sync
time for Contacts - 1310907403
2011-07-17T23:16:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Initializing
message diff engine for Contacts
2011-07-17T23:16:14+10:00 DEBUG:
Horde_ActiveSync_Driver_Horde::getServerChanges(Contacts, 1310907403,
1310908574, 0)
2011-07-17T23:16:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] Found 0 message
changes, checking for PIM initiated changes.
2011-07-17T23:16:14+10:00 DEBUG: [ApplDLXFT5X3DFJ2] No PIM changes
present, returning all messages.
But nothing into Turba. Waited for ten minutes. Still nothing. Stopped
Apache, iPad activity wheel goes into immediate intermittent motion
instead of constant. Restart Apache, Horde Portal presents 503 error
for about 15 seconds, then at the same instant that the iPad
successfully syncs the contact the Portal comes back to life. The
contact is now synced back into Turba LDAP, and the logs show that as
per above first example.
I can now reproduce this every time, even the 503 errors from Horde
portal for 15 seconds after an Apache restart. If there are no queued
ActiveSync requests then the 503 errors don't occur, the Portal
responds again immediately after an Apache restart. Apache logs
nothing unusual, just the usual "resuming normal operations" messages
it does on a restart.
Simon
--
Simon Wilson
M: 0400 12 11 16
More information about the horde
mailing list