[horde] ActiveSync syncs single messages countlessly

Michael J Rubinsky mrubinsk at horde.org
Mon Sep 21 14:53:52 UTC 2015 

Quoting Jens Hellermann <hellermann at we-do.com>:

> Am 16.09.2015 um 14:16 schrieb Michael J Rubinsky:
>>
>> Quoting Jens Hellermann <hellermann at we-do.com>:
>>
>>> Am 15.09.2015 um 17:26 schrieb Michael J Rubinsky:
>>>>
>>>> Quoting Jens Hellermann <hellermann at we-do.com>:
>>>>
>>>>> Dear Horde List members,
>>>>>
>>>>> I still have problems syncing a very large email account via  
>>>>> activesync to an Outlook 2013 client. The imap account shows  
>>>>> 54.517 email entries in Horde Webmail.
>>>>>
>>>>> To a certain point the sync seems to work normally, but after  
>>>>> hours Outlook starts repeatedly to fetch the same message again  
>>>>> and again.  (Approximatly a 100 times)
>>>>>
>>>>> Then it goes over to the next message and does the very same  
>>>>> thing again. Something in the communication between Outlook and  
>>>>> horde seems to go wrong.
>>>>>
>>>>> Has anyone ever heard of a similar problem? I'm going to do some  
>>>>> extra research tomorrow, but its difficult to go through the log  
>>>>> file as it is extremely large.
>>>>
>>>> This *usually* means that there is some issue with that specific  
>>>> email. Try to find the spot in the log where that email is first  
>>>> requested and sent to the client and post the log with some  
>>>> context before and after that request.
>>>>
>>> Hello Michael,
>>>
>>> here is one example for a mail that has been fetched very often.  
>>> Here come the parts of the log when it turns up the first and the  
>>> second time. As you can see, the next mail in the log is also  
>>> getting fetched a second time.
>>>
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Updating state during change
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Peak memory usage after  
>>> message: 68419584
>>> 2015-09-08T15:15:36+02:00 INFO: [1965]  
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 19429)
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Sending MIME Message.
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Checking MIMETRUNCATION: ,  
>>> ServerData: 33875
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Fetching verb for  
>>> <9E9BE3F2-C32E-4759-96BE-E89CA76E8B9D at we-do.eu>.
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O      <Add>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <ServerEntryId>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O        19429
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </ServerEntryId>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O       <Data>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:To>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O marschall at nexus-netsoft.com
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:To>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Cc>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         [171 bytes of content]
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:Cc>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:From>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Christoph Franz  
>>> - WE DO <franz at we-do.eu>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:From>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Subject>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Re: UBSKM:  
>>> Hilfeportal ▒^▒bernahme - offene Fragen
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:Subject>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Reply-To>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Christoph Franz  
>>> - WE DO <franz at we-do.eu>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:Reply-To>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:DateReceived>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O 2015-01-13T15:46:15.000Z
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:DateReceived>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:DisplayTo>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Ricardo Marschall
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:DisplayTo>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:ThreadTopic>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Re: UBSKM:  
>>> Hilfeportal ▒^▒bernahme - offene Fragen
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:ThreadTopic>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Importance>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         1
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:Importance>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Read>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         1
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:Read>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:MessageClass>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         IPM.Note
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:MessageClass>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:InternetCPID>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         65001
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:InternetCPID>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <AirSyncBase:NativeBodyType>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         2
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </AirSyncBase:NativeBodyType>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <AirSyncBase:Body>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <AirSyncBase:Type>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O          4
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </AirSyncBase:Type>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <AirSyncBase:EstimatedDataSize>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O          33875
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </AirSyncBase:EstimatedDataSize>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <AirSyncBase:Truncated>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O          0
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </AirSyncBase:Truncated>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <AirSyncBase:Data>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O          [STREAM]
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </AirSyncBase:Data>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </AirSyncBase:Body>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Flag/>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:ContentClass>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O urn:content-classes:message
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:ContentClass>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Categories/>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O       </Data>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O      </Add>
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Updating state during change
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Peak memory usage after  
>>> message: 68419584
>>> 2015-09-08T15:15:36+02:00 INFO: [1965]  
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 19431)
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Sending MIME Message.
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Checking MIMETRUNCATION: ,  
>>> ServerData: 21084
>>> 2015-09-08T15:15:36+02:00 INFO: [1965] Fetching verb for  
>>> <8ADBA7D7-3910-401B-B0A7-26E70B5B8761 at we-do.com>.
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O      <Add>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <ServerEntryId>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O        19431
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </ServerEntryId>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O       <Data>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:To>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         [52 bytes of content]
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:To>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Cc>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         [85 bytes of content]
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:Cc>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:From>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Christoph Franz  
>>> - WE DO <franz at we-do.com>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O </POOMMAIL:From>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O <POOMMAIL:Subject>
>>> 2015-09-08T15:15:36+02:00 DEBUG: [1965] O         Auth-Codes + SSL  
>>> Zertifikat für Domains
>>>
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Updating state during change
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Peak memory usage after  
>>> message: 68681728
>>> 2015-09-08T15:58:17+02:00 INFO: [1968]  
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 19429)
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Sending MIME Message.
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Checking MIMETRUNCATION: ,  
>>> ServerData: 33875
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Fetching verb for  
>>> <9E9BE3F2-C32E-4759-96BE-E89CA76E8B9D at we-do.eu>.
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O      <Add>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <ServerEntryId>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O        19429
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </ServerEntryId>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O       <Data>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:To>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O marschall at nexus-netsoft.com
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:To>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Cc>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         [171 bytes of content]
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:Cc>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:From>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Christoph Franz  
>>> - WE DO <franz at we-do.eu>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:From>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Subject>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Re: UBSKM:  
>>> Hilfeportal ▒^▒bernahme - offene Fragen
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:Subject>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Reply-To>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Christoph Franz  
>>> - WE DO <franz at we-do.eu>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:Reply-To>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:DateReceived>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O 2015-01-13T15:46:15.000Z
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:DateReceived>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:DisplayTo>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Ricardo Marschall
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:DisplayTo>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:ThreadTopic>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Re: UBSKM:  
>>> Hilfeportal ▒^▒bernahme - offene Fragen
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:ThreadTopic>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Importance>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         1
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:Importance>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Read>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         1
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:Read>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:MessageClass>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         IPM.Note
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:MessageClass>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:InternetCPID>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         65001
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:InternetCPID>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <AirSyncBase:NativeBodyType>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         2
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </AirSyncBase:NativeBodyType>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <AirSyncBase:Body>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <AirSyncBase:Type>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O          4
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </AirSyncBase:Type>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <AirSyncBase:EstimatedDataSize>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O          33875
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </AirSyncBase:EstimatedDataSize>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <AirSyncBase:Truncated>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O          0
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </AirSyncBase:Truncated>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <AirSyncBase:Data>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O          [STREAM]
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </AirSyncBase:Data>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </AirSyncBase:Body>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Flag/>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:ContentClass>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O urn:content-classes:message
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:ContentClass>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Categories/>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O       </Data>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O      </Add>
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Updating state during change
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Peak memory usage after  
>>> message: 68681728
>>> 2015-09-08T15:58:17+02:00 INFO: [1968]  
>>> Horde_Core_ActiveSync_Driver::getMessage(INBOX, 19431)
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Sending MIME Message.
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Checking MIMETRUNCATION: ,  
>>> ServerData: 21084
>>> 2015-09-08T15:58:17+02:00 INFO: [1968] Fetching verb for  
>>> <8ADBA7D7-3910-401B-B0A7-26E70B5B8761 at we-do.com>.
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O      <Add>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <ServerEntryId>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O        19431
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </ServerEntryId>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O       <Data>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:To>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         [52 bytes of content]
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:To>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Cc>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         [85 bytes of content]
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:Cc>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:From>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Christoph Franz  
>>> - WE DO <franz at we-do.com>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O </POOMMAIL:From>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O <POOMMAIL:Subject>
>>> 2015-09-08T15:58:17+02:00 DEBUG: [1968] O         Auth-Codes + SSL  
>>> Zertifikat für Domains
>>
>> That's not enough of the log to determine anything. I need the  
>> entire request and response. Of at least two instances of this  
>> happening. Preferably the first one, and the second one.
>>
>> Requests like this rarely contain only a single email message, so  
>> it's not unusual that multiple messages are synchronized each time.  
>> If a single error occurs with any of the messages in a specific  
>> request (identified by a synckey), depending on the error, the  
>> client makes the same request again, which results in the same  
>> response, until the client gives up.
>>
>>
>
> Hello Michael, I answered directly to your account with a  
> downloadlink to the shortend logfile as there is to much information  
> involved for publishing it here.

Sorry, but the file you provided still only shows a single  
request/response (along with some other, unrelated requests).

-- 
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 5751 bytes
Desc: S/MIME Signature
URL: <http://lists.horde.org/archives/horde/attachments/20150921/0c01b68a/attachment.bin>

More information about the horde mailing list