[horde] Activesync not working but seems fine in logs?

[Michael J Rubinsky]

Quoting info at pcbase.eu:

> Hi all,
>
> I configured horde for activesync usage, but then I try to sync  
> email, calendar and contacts, it just fails according to my phone.
>
> This is the ActiveSync log:
>
> 2011-06-17T00:31:35+02:00 DEBUG:  
> Horde_ActiveSync_Driver_Horde::getServerChanges(Calendar, 0,  
> 1308263495, 0)
> 2011-06-17T00:31:35+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Found 0 message changes, checking for PIM initiated changes.
> 2011-06-17T00:31:35+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> No PIM changes present, returning all messages.
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Attempting to load PING state for: Contacts
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Obtained lasst sync time for Contacts - 0
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Initializing message diff engine for Contacts
> 2011-06-17T00:31:40+02:00 DEBUG:  
> Horde_ActiveSync_Driver_Horde::getServerChanges(Contacts, 0,  
> 1308263500, 0)
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Found 0 message changes, checking for PIM initiated changes.
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> No PIM changes present, returning all messages.
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Attempting to load PING state for: Calendar
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Obtained lasst sync time for Calendar - 0
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Initializing message diff engine for Calendar
> 2011-06-17T00:31:40+02:00 DEBUG:  
> Horde_ActiveSync_Driver_Horde::getServerChanges(Calendar, 0,  
> 1308263500, 0)
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Found 0 message changes, checking for PIM initiated changes.
> 2011-06-17T00:31:40+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> No PIM changes present, returning all messages.
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Attempting to load PING state for: Contacts
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Obtained lasst sync time for Contacts - 0
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Initializing message diff engine for Contacts
> 2011-06-17T00:31:45+02:00 DEBUG:  
> Horde_ActiveSync_Driver_Horde::getServerChanges(Contacts, 0,  
> 1308263505, 0)
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Found 0 message changes, checking for PIM initiated changes.
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> No PIM changes present, returning all messages.
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Attempting to load PING state for: Calendar
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Obtained lasst sync time for Calendar - 0
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Initializing message diff engine for Calendar
> 2011-06-17T00:31:45+02:00 DEBUG:  
> Horde_ActiveSync_Driver_Horde::getServerChanges(Calendar, 0,  
> 1308263505, 0)
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Found 0 message changes, checking for PIM initiated changes.
> 2011-06-17T00:31:45+02:00 DEBUG: [HTC942974c4d7bf04a7bd941aa283c5d]  
> No PIM changes present, returning all messages.
> 2011-06-17T00:31:50+02:00 INFO: [HTC942974c4d7bf04a7bd941aa283c5d]  
> Sending response for PING.
> 2011-06-17T00:31:50+02:00 DEBUG: O  <Ping:Ping>
> 2011-06-17T00:31:50+02:00 DEBUG: O   <Ping:Status>
> 2011-06-17T00:31:50+02:00 DEBUG: O   1
> 2011-06-17T00:31:50+02:00 DEBUG: O    <Ping:Status/>
> 2011-06-17T00:31:50+02:00 DEBUG: O   <Ping:Ping/>
>
>
>
> I thought that it might be a webserver problem, but that wasn't  
> right, because it just returns a 200 status:
>
> [17/Jun/2011:19:08:38 +0200] "POST  
> /Microsoft-Server-ActiveSync?Cmd=Sync&User=[MYUSER]&DeviceId=HTC942974c4d7bf04a7bd941aa283c5d&DeviceType=htcpyramid HTTP/1.1" 200 82 "-"  
> "Android-EAS/4.0.2115272322.67241"
>
> When I try to access the webportal I can browse my mail, contacts  
> and calandar fine, but AS just won't work. Any ideas why?

What do you mean by "fails on my phone"? What, exactly, happens on the phone?

Can you reset the AS account on the device and on the server  
(prefs->active ync devices), then capture the log from the beginning?  
This log looks like it has already performed a FOLDERSYNC operation,  
but the SYNC operation may have failed for some reason (this log is  
from a PING request - which only happens *after* an initial SYNC is  
performed).

If you could also capture the traffic with wireshark or similar, that  
would be helpful. If not, just the AS log should suffice.

-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org