[horde] ActiveSync syncs single messages countlessly

Jens Hellermann hellermann at we-do.com
Mon Sep 21 10:35:55 UTC 2015 


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.

More information about the horde mailing list