[horde] ActiveSync syncs single messages countlessly
Jens Hellermann
hellermann at we-do.com
Tue Sep 22 07:59:08 UTC 2015
Am 21.09.2015 um 16:53 schrieb Michael J Rubinsky:
>
> 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).
Hmm, I'm sorry indeed, I'm not familiar with the request structure. I'll
provide you with the full log split in three parts. I'll send you the
download links via your direct email Adress again.
Kind regards, Jens.
>
>
>
More information about the horde
mailing list