[sync] PING-SYNC storm

[Michael J Rubinsky]

Quoting Arjen de Korte <arjen+horde at de-korte.org>:

> Occasionally I see a significant battery drain on my mobile phone  
> that syncs through ActiveSync. I enabled debugging and found that  
> during such an event it continuously repeats the same PING-SYNC sycle.
>
> When it PINGs the server, it will get a reply status of 2 and in the  
> logs it mentions
>
> 2013-02-22T14:36:53+01:00 DEBUG: [29575] Initializing state for  
> collection: Commercieel, synckey:  
> {512745e0-365c-4a01-9e3f-4202c0a8010a}2
> 2013-02-22T14:36:53+01:00 DEBUG: [29575] Loading state for synckey  
> {512745e0-365c-4a01-9e3f-4202c0a8010a}2
> 2013-02-22T14:36:53+01:00 DEBUG: [29575] Initializing message diff  
> engine for Commercieel
> 2013-02-22T14:36:53+01:00 DEBUG: [29575]  
> Horde_Core_ActiveSync_Driver::getServerChanges(Commercieel,  
> 1361528289, 1361540213, 0, 1)
> 2013-02-22T14:36:54+01:00 DEBUG: [29575] Found 1 message changes in  
> Commercieel.
> 2013-02-22T14:36:54+01:00 DEBUG: [29575] No PIM changes present,  
> returning all messages.
>
> But when it subsequently attempts to SYNC that folder, no changes are found:
>
> 2013-02-22T14:36:56+01:00 DEBUG: [29598] Initializing state for  
> collection: Commercieel, synckey:  
> {512745e0-365c-4a01-9e3f-4202c0a8010a}2
> 2013-02-22T14:36:56+01:00 DEBUG: [29598] Loading state for synckey  
> {512745e0-365c-4a01-9e3f-4202c0a8010a}2
> 2013-02-22T14:36:56+01:00 DEBUG: [29598] Initializing message diff  
> engine for Commercieel
> 2013-02-22T14:36:56+01:00 DEBUG: [29598]  
> Horde_Core_ActiveSync_Driver::getServerChanges(Commercieel,  
> 1361528289, 1361540216, 1359121016, 0)
> 2013-02-22T14:36:57+01:00 DEBUG: IMAP status: Array
> (
>     [uidnext] => 1349
>     [uidvalidity] => 1108813680
>     [highestmodseq] => 1506
> )
>
> 2013-02-22T14:36:57+01:00 DEBUG: CONDSTORE and CHANGES
> 2013-02-22T14:36:57+01:00 DEBUG: [29598] Found 0 message changes in  
> Commercieel.
>
> This cycle repeats every few seconds until a new message arrives in  
> that folder, after which the situation is back to normal. It looks  
> like at times the cached state is out of sync with the IMAP server,  
> which is only resolved if new messages arrive. Is there any way I  
> can assist in debugging what is going on here?

The only thing that triggers a PING to detect a change in a mailbox is  
an increase in the UIDNEXT value. So...what is probably happening here  
is that a new message arrived in the mailbox, which triggered the PING  
to report a change, but in the meantime the message was deleted or  
moved to another mailbox, so when the SYNC does the more expensive  
checks, it doesn't find the message.

This is almost certainly a bug in the logic somewhere, so I'll start  
digging. Please create a ticket on bugs.horde.org so I don't lose this.

-- 
mike

The Horde Project (www.horde.org)
mrubinsk at horde.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 6062 bytes
Desc: S/MIME Cryptographic Signature
URL: <http://lists.horde.org/archives/sync/attachments/20130226/4c52f6de/attachment.bin>