[sync] activesync no more working for iphone?

Fri May 27 09:18:33 UTC 2011

2011/5/11 LALOT Dominique <dom.lalot at gmail.com>

> Hello,
>
> I started to play with activesync in March using git, then beta then
> install 4.0, 4.0.1, then 4.0.2 (last update)
> what is sure is that it was working in 4.0.0 or 4.0.1.
> During that time I had many things to improve, prefs and so on so I did not
> test activesync each time.
>
> I was "playing" with shibboleth and was unable to sync, as the
> authentication driver was not suited for. I patched just Horde/Rpc.php in
> order to do an ldap bind in case of failure.
> As nothing worked (it was ok for the authentication), I went back to imap
> or ldap auth in order to be sure that the normal tested driver was working.
> But it does not work anymore.
>
> Nothing in apache error.log
> I destroyed my device state, went back to my iphone and destroy data, set
> up a new account (iphone os 3.1)
> That's difficult to understand the problem's origin and also there is no
> way to look at a log on the iphone side...
>
> 90.84.144.186 - lalot [11/May/2011:16:57:23 +0200] "GET
> /horde/rpc.php/kronolith/lalot/lalot.ics HTTP/1.1" 200 12756 "-"
> "DataAccess/1.0 (7E18)"
> 90.84.144.186 - lalot [11/May/2011:16:52:47 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Ping
> HTTP/1.1" 200 612 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:16:58:06 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Sync
> HTTP/1.1" 200 676 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:16:58:07 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Sync
> HTTP/1.1" 200 4858 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:16:58:10 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Sync
> HTTP/1.1" 200 538 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:16:58:10 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Sync
> HTTP/1.1" 200 4858 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:16:57:22 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Ping
> HTTP/1.1" 200 612 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:16:58:20 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Ping
> HTTP/1.1" 200 612 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:17:03:36 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Ping
> HTTP/1.1" 200 5070 "-" "Apple-iPhone/705.18"
> 90.84.144.186 - lalot [11/May/2011:17:13:46 +0200] "POST
> /Microsoft-Server-ActiveSync?User=lalot&DeviceId=Appl83750EYRWH8&DeviceType=iPhone&Cmd=Ping
> HTTP/1.1" 200 5070 "-" "Apple-iPhone/705.18"
>
> I put debug in activesync:
> 2011-05-11T17:49:03+02:00 INFO: [Appl83750EYRWH8] Sending response for
> PING.
> 2011-05-11T17:49:03+02:00 DEBUG: O  <Ping:Ping>
> 2011-05-11T17:49:03+02:00 DEBUG: O   <Ping:Status>
> 2011-05-11T17:49:03+02:00 DEBUG: O   1
> 2011-05-11T17:49:03+02:00 DEBUG: O    <Ping:Status/>
> 2011-05-11T17:49:03+02:00 DEBUG: O   <Ping:Ping/>
> 2011-05-11T17:49:03+02:00 INFO: User lalot logged off
> 2011-05-11T17:49:13+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for: lalot
> 2011-05-11T17:49:13+02:00 DEBUG: SQL QUERY: SELECT device_type,
> device_agent, device_ping, device_policykey, device_rwstatus,
> device_supported FROM horde_activesync_device d INNER JOIN
> horde_activesync_device_users u ON d.device_id = u.device_id WHERE
> u.device_id = ? AND u.device_user = ? VALUES: Appl83750EYRWH8 lalot
> 2011-05-11T17:49:13+02:00 INFO: Request received from device:
> Appl83750EYRWH8 Supporting protocol version: 2.5
> 2011-05-11T17:49:13+02:00 INFO: [Appl83750EYRWH8] PING received at
> timestamp: 1305128953.
> 2011-05-11T17:49:13+02:00 DEBUG: I  <Ping:Ping>
> 2011-05-11T17:49:13+02:00 DEBUG: I   <Ping:HeartbeatInterval>
> 2011-05-11T17:49:13+02:00 DEBUG: I    1500
> 2011-05-11T17:49:13+02:00 DEBUG: I   </Ping:HeartbeatInterval>
> 2011-05-11T17:49:13+02:00 DEBUG: I  </Ping:Ping>
> 2011-05-11T17:49:13+02:00 DEBUG: Unmatched tagPing:Folders:
> 2011-05-11T17:49:13+02:00 INFO: [Appl83750EYRWH8] Waiting for changes
> (heartbeat interval: 1500)
> 2011-05-11T17:49:13+02:00 DEBUG: [Appl83750EYRWH8] Attempting to load PING
> state for: Calendar
> 2011-05-11T17:49:13+02:00 DEBUG: [Appl83750EYRWH8] Obtained lasst sync time
> for Calendar - 1305125890
> 2011-05-11T17:49:13+02:00 DEBUG: [Appl83750EYRWH8] Initializing message
> diff engine for Calendar
> 2011-05-11T17:49:13+02:00 DEBUG:
> Horde_ActiveSync_Driver_Horde::getServerChanges(Calendar, 1305125890,
> 1305128953, 0)
> 2011-05-11T17:49:13+02:00 DEBUG: [Appl83750EYRWH8] Found 0 message changes,
> checking for PIM initiated changes.
>
> many, many lines like this:
> 2011-05-11T17:49:13+02:00 DEBUG:
> Horde_ActiveSync_Driver_Horde::getServerChanges(Calendar, 1305125890,
> 1305128953, 0)
> 2011-05-11T17:49:13+02:00 DEBUG: [Appl83750EYRWH8] Found 0 message changes,
> checking for PIM initiated changes.
> 2011-05-11T17:49:13+02:00 DEBUG: [Appl83750EYRWH8] No PIM changes present,
> returning all messages.
> 2011-05-11T17:49:18+02:00 DEBUG: [Appl83750EYRWH8] Attempting to load PING
> state for: Calendar
> 2011-05-11T17:49:18+02:00 DEBUG: [Appl83750EYRWH8] Obtained lasst sync time
> for Calendar - 1305125890
>
> 2011-05-11T16:52:36+02:00 INFO: User lalot logged off
> 2011-05-11T16:52:38+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for: lalot
> 2011-05-11T16:52:38+02:00 DEBUG: SQL QUERY: SELECT device_type,
> device_agent, device_ping, device_policykey, device_rwstatus,
> device_supported FROM horde_activesync_device d INNER JOIN
> horde_activesync_device_users u ON d.device_id = u.device_id WHERE
> u.device_id = ? AND u.device_user = ? VALUES: Appl83750EYRWH8 lalot
> 2011-05-11T16:52:38+02:00 INFO: Request received from device:
> Appl83750EYRWH8 Supporting protocol version: 2.5
> 2011-05-11T16:52:38+02:00 INFO: [Appl83750EYRWH8] Handling SYNC command.
> 2011-05-11T16:52:38+02:00 DEBUG: Policykey: 0 verified.
> 2011-05-11T16:52:38+02:00 DEBUG: I  <Synchronize>
> 2011-05-11T16:52:38+02:00 DEBUG: I   <Folders>
> 2011-05-11T16:52:38+02:00 DEBUG: I    <Folder>
> 2011-05-11T16:52:38+02:00 DEBUG: I     <FolderType>
> 2011-05-11T16:52:38+02:00 DEBUG: I      Calendar
> 2011-05-11T16:52:38+02:00 INFO: [Appl83750EYRWH8] Syncing folder class:
> Calendar
> 2011-05-11T16:52:38+02:00 DEBUG: I     </FolderType>
> 2011-05-11T16:52:38+02:00 DEBUG: I     <SyncKey>
> 2011-05-11T16:52:38+02:00 DEBUG: I      0
> 2011-05-11T16:52:38+02:00 DEBUG: I     </SyncKey>
> 2011-05-11T16:52:38+02:00 DEBUG: I     <FolderId>
> 2011-05-11T16:52:38+02:00 DEBUG: I      Calendar
> 2011-05-11T16:52:38+02:00 INFO: [Appl83750EYRWH8] Folder server id:
> Calendar
> 2011-05-11T16:52:38+02:00 DEBUG: I     </FolderId>
> 2011-05-11T16:52:38+02:00 DEBUG: I     <Options>
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagSupported:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagDeletesAsMoves:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagGetChanges:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagWindowSize:
> 2011-05-11T16:52:38+02:00 DEBUG: I      <FilterType>
> 2011-05-11T16:52:38+02:00 DEBUG: I       5
> 2011-05-11T16:52:38+02:00 DEBUG: I      </FilterType>
> 2011-05-11T16:52:38+02:00 DEBUG: I     </Options>
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagTruncation:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagRtfTruncation:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagMIMESupport:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagMIMETruncation:
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagConflict:
> 2011-05-11T16:52:38+02:00 DEBUG: [Appl83750EYRWH8] Resetting device state.
> 2011-05-11T16:52:38+02:00 DEBUG: I    </Folder>
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagCommands:
> 2011-05-11T16:52:38+02:00 DEBUG: I   </Folders>
> 2011-05-11T16:52:38+02:00 DEBUG: Unmatched tagFolder:
> 2011-05-11T16:52:38+02:00 DEBUG: I  </Synchronize>
> 2011-05-11T16:52:38+02:00 INFO: [Appl83750EYRWH8] Beginning SYNC Response.
> 2011-05-11T16:52:38+02:00 DEBUG: O  <Synchronize>
> 2011-05-11T16:52:38+02:00 DEBUG: O   <Folders>
> 2011-05-11T16:52:38+02:00 DEBUG: O    <Folder>
> 2011-05-11T16:52:38+02:00 DEBUG: O     <FolderType>
> 2011-05-11T16:52:38+02:00 DEBUG: O     Calendar
> 2011-05-11T16:52:38+02:00 DEBUG: O      <FolderType/>
> 2011-05-11T16:52:38+02:00 DEBUG: O     <SyncKey>
> 2011-05-11T16:52:38+02:00 DEBUG: O
> {4dcaa2b6-540c-4026-8d26-510b8b7c847e}1
> 2011-05-11T16:52:38+02:00 DEBUG: O      <SyncKey/>
> 2011-05-11T16:52:38+02:00 DEBUG: O     <FolderId>
> 2011-05-11T16:52:38+02:00 DEBUG: O     Calendar
> 2011-05-11T16:52:38+02:00 DEBUG: O      <FolderId/>
> 2011-05-11T16:52:38+02:00 DEBUG: O     <Status>
> 2011-05-11T16:52:38+02:00 DEBUG: O     1
> 2011-05-11T16:52:38+02:00 DEBUG: O      <Status/>
> 2011-05-11T16:52:38+02:00 DEBUG: O     <Folder/>
> 2011-05-11T16:52:38+02:00 DEBUG: [Appl83750EYRWH8] Saving state for synckey
> {4dcaa2b6-540c-4026-8d26-510b8b7c847e}1
> 2011-05-11T16:52:38+02:00 DEBUG: O    <Folders/>
> 2011-05-11T16:52:38+02:00 DEBUG: O   <Synchronize/>
> 2011-05-11T16:52:38+02:00 INFO: User lalot logged off
> 2011-05-11T16:52:38+02:00 INFO: Horde_ActiveSync_Driver_Horde::logon
> attempt for: lalot
> 2011-05-11T16:52:38+02:00 DEBUG: SQL QUERY: SELECT device_type,
> device_agent, device_ping, device_policykey, device_rwstatus,
> device_supported FROM horde_activesync_device d INNER JOIN
> horde_activesync_device_users u ON d.device_id = u.device_id WHERE
> u.device_id = ? AND u.device_user = ? VALUES: Appl83750EYRWH8 lalot
>
> any ideas?
>
> --
> Dominique LALOT
> Ingénieur Systèmes et Réseaux
> http://annuaire.univmed.fr/showuser.php?uid=lalot
>

I transfer a new database from prod, migrate again, then it works (no change
on Iphone side)... Hope, it will be stable when we will go to horde 4

Dom

-- 
Dominique LALOT
Ingénieur Systèmes et Réseaux
http://annuaire.univmed.fr/showuser.php?uid=lalot