[sync] PING-SYNC storm

[Arjen de Korte]

Citeren Michael J Rubinsky <mrubinsk at horde.org>:

> 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.

I saw this again this morning and lo-and-behold, it happened after  
moving a couple of messages (through Horde webmail, not on the mobile  
device). It stopped when I flipped the unseen flag on a message, so I  
think this must indeed be the failure mechanism.

> 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.

http://bugs.horde.org/ticket/12075

Arjen