[horde] ActiveSync problem
Michael J Rubinsky
mrubinsk at horde.org
Sun Jul 17 15:00:00 UTC 2011
Simon Wilson <simon at simonandkate.net> wrote:
>
>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
>
>
>--
>Horde mailing list
>Frequently Asked Questions: http://horde.org/faq/
>To unsubscribe, mail: horde-unsubscribe at lists.horde.org
That sounds as if there are no more apace or php-cgi processes available to answer the HTTP requests, i.e., a configuration issue.
--
Mike
Sent from mobile
More information about the horde
mailing list