[sync] activesync no more working for iphone?

LALOT Dominique dom.lalot at gmail.com
Wed May 11 16:01:00 UTC 2011


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


More information about the sync mailing list