[horde] ActiveSync Problem with HTC Device

Michael J Rubinsky mrubinsk at horde.org
Thu Sep 5 12:56:13 UTC 2013 

Quoting lst_hoe02 at kwsoft.de:

> Zitat von Michael J Rubinsky <mrubinsk at horde.org>:
>
>> Yes. Though, it could be that Horde sent that to the device as the  
>> collection id in the initial foldersync, so I would need to see the  
>> log for the initial sync pairing. If you weren't logging then,  
>> recreate the device account with logging enabled.
>
> After removing the device as administrator to get a fresh resync:
>
> 2013-09-03T18:29:47+02:00 INFO: [24660]  
> Horde_Core_ActiveSync_Driver::authenticate() attempt for xxxx
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] PING request received for user xxxx
> 2013-09-03T18:29:47+02:00 INFO: [24660] Device entry exists for  
> HTCC19C292891BEA121A5D3B337E47B9, updating userAgent and version.
> 2013-09-03T18:29:47+02:00 INFO: [24660] Device entry does not exist  
> for device HTCC19C292891BEA121A5D3B337E47B9 and user xxxx - creating  
> it.
> 2013-09-03T18:29:47+02:00 INFO: [24660] Request being handled for  
> device: HTCC19C292891BEA121A5D3B337E47B9, Supporting protocol  
> version: 12.1, Using Horde_ActiveSync v2.7.2
> 2013-09-03T18:29:47+02:00 INFO: [24660] Handling PING command  
> received at timestamp: 1378225787.
> 2013-09-03T18:29:47+02:00 INFO: [24660] Using cached heartbeat of 480
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I  <Ping:Ping>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I   <Ping:HeartbeatInterval>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     960
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I   </Ping:HeartbeatInterval>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I   <Ping:Folders>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       @Contacts@
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Contacts
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection @Contacts@ from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       @Calendar@
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Calendar
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection @Calendar@ from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       @Tasks@
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Tasks
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection @Tasks@ from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       3ff19e04
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Email
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection 3ff19e04 from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       -1
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Email
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection -1 from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       e92e4517
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Email
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection e92e4517 from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       6b31deb1
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Email
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection 6b31deb1 from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    <Ping:Folder>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       43e6c38a
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:ServerEntryId>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     <Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I       Email
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I     </Ping:FolderType>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I    </Ping:Folder>
> 2013-09-03T18:29:47+02:00 INFO: [24660] Obtained synckey for  
> collection 43e6c38a from cache: 0
> 2013-09-03T18:29:47+02:00 INFO: [24660] Collection added to  
> collection handler: collection: , synckey: NONE.
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I   </Ping:Folders>
> 2013-09-03T18:29:47+02:00 DEBUG: [24660] I  </Ping:Ping>
> 2013-09-03T18:29:47+02:00 INFO: Waiting for changes for 960 seconds
> 2013-09-03T18:29:47+02:00 ERR: No pingable collections.
> 2013-09-03T18:29:47+02:00 WARN: [24660] Version is < 14.0, returning  
> false since we have no PINGABLE collections.
> 2013-09-03T18:29:47+02:00 INFO: [24660] User xxxx logged off
>
> So it really looks like the Phone sent "-1" as ID. Maybe this is  
> meant as "does not exist"?


This is not a log from an initial FOLDERSYNC, it's a PING request made  
using the existing account on the client. Most likely, this request  
returned a status code indicating the device should re-pair, which  
would trigger the initial FOLDERSYNC further down in the log.
-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-keys
Size: 2200 bytes
Desc: PGP Public Key
URL: <http://lists.horde.org/archives/horde/attachments/20130905/5822e993/attachment.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 5849 bytes
Desc: S/MIME Signature
URL: <http://lists.horde.org/archives/horde/attachments/20130905/5822e993/attachment-0001.bin>

More information about the horde mailing list