Incident: Ignored broken message (SyncMail). Reason: '2'

Date Seen
28.03.2016

Versions
Ubuntu 16.04.2 LTS
Apache 2.4.18
Z-Push 2.3.5

Bug Description
The problematic mails won’t sync to iPhones and are causing a loop.

WBXML Log:

20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] -------- Start
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] cmd='Sync' devType='iPhone' devId='e51i135rs54dl5ar3cu242hkjc' getUser='USERNAME' from='213.225.38.91' version='2.3.5+5' method='POST'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Used timezone 'Europe/Vienna'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetBackend(): trying autoload backend 'BackendKopano'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] BackendKopano using PHP-MAPI version: 8.4.0-344 - PHP version: 7.0.15-0ubuntu0.16.04.4
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Request::ProcessHeaders() ASVersion: 14.0
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::CommandNeedsAuthentication(0): true
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->Logon(): Trying to authenticate user 'USERNAME'..
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->GetState() read '5080' bytes from file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-devicedata'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice data loaded for user: 'USERNAME'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] TopCollector(): Initialized mutexid Resource id #18 and memid Resource id #19.
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection(): Initialized mutexid Resource id #22 and memid Resource id #23.
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::HierarchyCommand(0): false
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->openMessageStore('USERNAME'): Found 'DEFAULT' store: 'Resource id #29'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->Logon(): User 'USERNAME' is authenticated
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Store supports properties containing Unicode characters.
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::CommandNeedsPlainInput(0): false
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I  <Synchronize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I   <Folders>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I    <Folder>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     <SyncKey>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      {3cc25e55-00b9-42ca-82bd-ead0b2066526}1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     </SyncKey>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     <FolderId>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      U5e81d
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     </FolderId>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->GetState() read '934' bytes from file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3cc25e55-00b9-42ca-82bd-ead0b2066526-fd'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SyncParameters->UseCPO('DEFAULT')
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] DeviceManager->GetBackendIdForFolderId(): folderid U5e81d => 786e8a1ff7ed45edad6b2f883fdfb6a0080000000000
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SyncCollections->AddCollection(): Folder id 'U5e81d' : ref. PolicyKey '267709328', ref. Lifetime '', last sync at '1492675384'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SyncCollections->AddCollection(): Updated reference PolicyKey '267709328', reference Lifetime '', Last sync at '1492675384'
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     <GetChanges/>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     <WindowSize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      25
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     </WindowSize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     <Options>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      <MIMETruncation>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SyncParameters->UseCPO('DEFAULT')
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I       1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      </MIMETruncation>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      <MIMESupport>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I       0
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      </MIMESupport>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      <AirSyncBase:BodyPreference>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I       <AirSyncBase:Type>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I        1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I       </AirSyncBase:Type>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I       <AirSyncBase:TruncationSize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I        500
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I       </AirSyncBase:TruncationSize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I      </AirSyncBase:BodyPreference>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I     </Options>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I    </Folder>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I   </Folders>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] I  </Synchronize>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] HandleSync(): Start Output
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->GetFolderStat() fetched status information of 57 folders for store 'USERNAME'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SyncParameters->IsExporterRunRequired(): true - current: 1492675381/1/0/2284 - saved: false - expiring: not set
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Sync->loadStates(): loading states for folder 'U5e81d'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3cc25e55-00b9-42ca-82bd-ead0b2066526-1'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ExportChangesICS->Config(): synching inital data
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ExportChangesICS->Config() initialized with state: 0x9916000000000000
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'.
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->ProcessLoopDetectionAddStatus: 'U5e81d' with status 1
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Folder type: Email
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O  <Synchronize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O   <Folders>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O    <Folder>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     <SyncKey>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     {3cc25e55-00b9-42ca-82bd-ead0b2066526}2
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     </SyncKey>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     <FolderId>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     U5e81d
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     </FolderId>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     <Status>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     </Status>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): folderid:'U5e81d' uuid:'3cc25e55-00b9-42ca-82bd-ead0b2066526' counter:'1' max:'25' queued:'1'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): UUID changed for folder
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): UUID changed and while items where sent to device - forcing loop mode
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): case 3.1 detected - loop detected, init loop mode
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): loop data: loopcount(1), maxCount(2), queued(1), ignored(false)
20/04/2017 10:03:05 [18503] [WARN] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: '786e8a1ff7ed45edad6b2f883fdfb6a0bc6f01000000', parentsourcekey: '786e8a1ff7ed45edad6b2f883fdfb6a0080000000000', entryid: '00000000fffe07b9435e445f933d1a3a5df40c7b010000000500000076546eea4b77408d9a761f073320e82300000000'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] BodyPreference types: 1
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] GetBodyPreferenceBestMatch: 1
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] bpo: truncation size:'500', allornone:'0', preview:'0'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] MAPIStreamWrapper::stream_open(): initialized mapistream: Resource id #235 streamlength: 12031
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] MAPIProvider->setMessageBody(): truncated plain-text body requested, stripping all links and images
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] StringStreamWrapper::stream_open(): initialized stream length: 489
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->IgnoreNextMessage(): Loop mode, potential broken message id 'U5e81d:786e8a1ff7ed45edad6b2f883fdfb6a0bc6f01000000'
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     <Perform>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O      <Add>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O       <ServerEntryId>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O       U5e81d:786e8a1ff7ed45edad6b2f883fdfb6a0bc6f01000000
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O       </ServerEntryId>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O       <Data>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:To>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        "USERNAME SURNAME" <USERNAME@DOMAIN.ME>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:To>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:From>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        "heise Security Summary" <newsletter@listserv.heise.de>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:From>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Subject>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        heise Security News 28.03.2016
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:Subject>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:DateReceived>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        2016-03-28T09:18:42.000Z
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:DateReceived>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:DisplayTo>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        USERNAME SURNAME
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:DisplayTo>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Importance>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:Importance>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Read>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:Read>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:MessageClass>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        IPM.Note
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:MessageClass>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:InternetCPID>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        65001
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:InternetCPID>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <AirSyncBase:Body>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:Type>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:Type>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:EstimatedDataSize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         12031
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:EstimatedDataSize>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:Truncated>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         1
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:Truncated>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:Data>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         <<< written 489 of 489 bytes of plain data >>>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:Data>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </AirSyncBase:Body>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:ContentClass>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        urn:content-classes:message
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:ContentClass>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Flag/>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        <AirSyncBase:NativeBodyType>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        2
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O        </AirSyncBase:NativeBodyType>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O       </Data>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O      </Add>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] PHPWrapper->ImportMessageChange(): change for: 'U5e81d:786e8a1ff7ed45edad6b2f883fdfb6a0bc6f01000000'
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O     </Perform>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SetFolderSyncStatus(): completed for U5e81d
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] Sync()->setFolderStat() on U5e81d: 1492675381/1/0/2284 expiring 2017-05-21 10:03:05
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O    </Folder>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->SetState() written 15 bytes on file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3cc25e55-00b9-42ca-82bd-ead0b2066526-2'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] SyncCollections->SaveCollection(): Data of folder 'U5e81d' changed
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->SetState() written 1045 bytes on file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3cc25e55-00b9-42ca-82bd-ead0b2066526-fd'
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O   </Folders>
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] O  </Synchronize>
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] WBXMLEncoder->endTag() WBXML output completed
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] WBXML-OUT: ...
20/04/2017 10:03:05 [18503] [WBXML] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] WBXML-IN : ...
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] DeviceManager->Save(): Device data changed
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->SetState() written 5062 bytes on file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-devicedata'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] DeviceManager->Save(): Device data saved
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->ProcessLoopDetectionTerminate()
20/04/2017 10:03:05 [18503] [ INFO] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] cmd='Sync' memory='2.09 MiB/4.00 MiB' time='0.62s' devType='iPhone' devId='e51i135rs54dl5ar3cu242hkjc' getUser='USERNAME' from='213.225.38.91' version='2.3.5+5' method='POST' httpcode='200'
20/04/2017 10:03:05 [18503] [DEBUG] [USERNAME] [e51i135rs54dl5ar3cu242hkjc] -------- End

Severity
Major

Steps to Reproduce
I just enabled the option “log_raw_message” in kopano-dagent. If i am receiving a mail causing this loop we are able to reproduce this error.

Actual Behavior
iPhones won’t sync the problematic mails and these are causing loops. The generated error message is “Ignored broken message (SyncMail). Reason: ‘2’”

Expected Behavior
iPhones are able to sync the mails.

Troubleshooting/Testing Steps Attempted
I searched through the internet and didn’t find a solution. I tried to compare two mails but didn’t find anything that points me in a direction.

Workaround
iPhones will continue to sync all other mails, the mails can be viewed via kopano-webapp.

Thanks for opening a topic here. Much better than in the ticket. :slight_smile:

The WBXML-OUT from your log actually gave away a hint about what is going on.

I edited your post and removed that string as it contains lot of data you anonymized in your post.

Anyway, I have a pretty good idea why the message is looping.
It seems as the UTF-8 truncation we use is not working as it should (could be a php7 incompatibility).

First, we should have a reproducible use case.
Could you try to safe this message as EML via the WebApp (right-click on the message and select “download as file”).
You can then try to deliver this eml file to your mailbox, using

kopano-dagent -f <email.eml> <username> 

It should show up as new (current date). Please check if you have the same kind of trouble with it (ignored by loop detection).
If yes, please send me the eml file.
If no, we try to export the original email via python.

Cheers,
Sebastian

Hi Sebastian,

thank you for anonymizing the logs.

If i try to deliver the mail to my mailbox i am getting the following error:

Apr 20 20:49:03 server kopano-dagent[23051]:   Python type: (null)
Apr 20 20:49:03 server kopano-dagent[23051]:   Python error: 'module' object has no attribute 'DAgentPluginmanager'
Apr 20 20:49:03 server kopano-dagent[23051]: K-1732: Unable to initialize the dagent plugin manager: Unknown error code (1).

Any suggestions?

Regards
Richard

I just disabled the plugin manager temporarily to deliver the mail manually. I am able to reproduce this error with the downloaded email and i will send it to you.

Regards
Richard

WBXML log after your provided changes in utils.php and resyncing the problematic mail:

Syncing went fine after changing utils.php with the provided code :thumbsup_tone1:

20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] -------- Start
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] cmd='Sync' devType='iPhone' devId='e51i135rs54dl5ar3cu242hkjc' getUser='FIRSTNAME' from='IPADDRESS' version='2.3.5+5' method='POST'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] Used timezone 'Europe/Vienna'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetBackend(): trying autoload backend 'BackendKopano'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] BackendKopano using PHP-MAPI version: 8.4.0-344 - PHP version: 7.0.15-0ubuntu0.16.04.4
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] Request::ProcessHeaders() ASVersion: 14.0
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::CommandNeedsAuthentication(0): true
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->Logon(): Trying to authenticate user 'FIRSTNAME'..
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->GetState() read '5080' bytes from file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-devicedata'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice data loaded for user: 'FIRSTNAME'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] TopCollector(): Initialized mutexid Resource id #18 and memid Resource id #19.
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection(): Initialized mutexid Resource id #22 and memid Resource id #23.
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::HierarchyCommand(0): false
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->openMessageStore('FIRSTNAME'): Found 'DEFAULT' store: 'Resource id #29'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->Logon(): User 'FIRSTNAME' is authenticated
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] Store supports properties containing Unicode characters.
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::CommandNeedsPlainInput(0): false
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I  <Synchronize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I   <Folders>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I    <Folder>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     <SyncKey>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      {3b545193-f74e-4cde-a0d9-66b9b0915edf}1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     </SyncKey>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     <FolderId>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      U5e81d
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     </FolderId>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->GetState() read '934' bytes from file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3b545193-f74e-4cde-a0d9-66b9b0915edf-fd'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SyncParameters->UseCPO('DEFAULT')
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] DeviceManager->GetBackendIdForFolderId(): folderid U5e81d => 786e8a1ff7ed45edad6b2f883fdfb6a0080000000000
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SyncCollections->AddCollection(): Folder id 'U5e81d' : ref. PolicyKey '267709328', ref. Lifetime '', last sync at '1492716348'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SyncCollections->AddCollection(): Updated reference PolicyKey '267709328', reference Lifetime '', Last sync at '1492716348'
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     <GetChanges/>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     <WindowSize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      25
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     </WindowSize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     <Options>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      <MIMETruncation>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SyncParameters->UseCPO('DEFAULT')
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I       1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      </MIMETruncation>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      <MIMESupport>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I       0
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      </MIMESupport>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      <AirSyncBase:BodyPreference>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I       <AirSyncBase:Type>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I        1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I       </AirSyncBase:Type>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I       <AirSyncBase:TruncationSize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I        500
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I       </AirSyncBase:TruncationSize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I      </AirSyncBase:BodyPreference>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I     </Options>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I    </Folder>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I   </Folders>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] I  </Synchronize>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] HandleSync(): Start Output
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid '0'. Returning as is!
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] KopanoBackend->GetFolderStat() fetched status information of 58 folders for store 'FIRSTNAME'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SyncParameters->IsExporterRunRequired(): true - current: 1492716295/1/0/2288 - saved: false - expiring: not set
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] Sync->loadStates(): loading states for folder 'U5e81d'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3b545193-f74e-4cde-a0d9-66b9b0915edf-1'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ExportChangesICS->Config(): synching inital data
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ExportChangesICS->Config() initialized with state: 0x9f16000000000000
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'.
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->ProcessLoopDetectionAddStatus: 'U5e81d' with status 1
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] Folder type: Email
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O  <Synchronize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O   <Folders>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O    <Folder>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     <SyncKey>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     {3b545193-f74e-4cde-a0d9-66b9b0915edf}2
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     </SyncKey>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     <FolderId>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     U5e81d
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     </FolderId>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     <Status>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     </Status>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): folderid:'U5e81d' uuid:'3b545193-f74e-4cde-a0d9-66b9b0915edf' counter:'1' max:'25' queued:'1'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->Detect(): UUID changed for folder
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: '786e8a1ff7ed45edad6b2f883fdfb6a02e7001000000', parentsourcekey: '786e8a1ff7ed45edad6b2f883fdfb6a0080000000000', entryid: '00000000fffe07b9435e445f933d1a3a5df40c7b01000000050000004dc179be62f640f2a49293f9e1ed5fd100000000'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] BodyPreference types: 1
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] GetBodyPreferenceBestMatch: 1
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] bpo: truncation size:'500', allornone:'0', preview:'0'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] MAPIStreamWrapper::stream_open(): initialized mapistream: Resource id #227 streamlength: 12031
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] MAPIProvider->setMessageBody(): truncated plain-text body requested, stripping all links and images
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] StringStreamWrapper::stream_open(): initialized stream length: 489
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     <Perform>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O      <Add>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O       <ServerEntryId>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O       U5e81d:786e8a1ff7ed45edad6b2f883fdfb6a02e7001000000
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O       </ServerEntryId>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O       <Data>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:To>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        "FIRSTNAME LASTNAME" <FIRSTNAME@LASTNAME.biz>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:To>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:From>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        "heise Security Summary" <newsletter@listserv.heise.de>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:From>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Subject>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        heise Security News 28.03.2016
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:Subject>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:DateReceived>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        2016-03-28T09:18:42.000Z
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:DateReceived>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:DisplayTo>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        FIRSTNAME LASTNAME
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:DisplayTo>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Importance>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:Importance>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Read>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:Read>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:MessageClass>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        IPM.Note
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:MessageClass>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:InternetCPID>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        65001
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:InternetCPID>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <AirSyncBase:Body>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:Type>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:Type>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:EstimatedDataSize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         12031
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:EstimatedDataSize>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:Truncated>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         1
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:Truncated>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         <AirSyncBase:Data>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         <<< written 489 of 489 bytes of plain data >>>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O         </AirSyncBase:Data>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </AirSyncBase:Body>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:ContentClass>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        urn:content-classes:message
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </POOMMAIL:ContentClass>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <POOMMAIL:Flag/>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        <AirSyncBase:NativeBodyType>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        2
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O        </AirSyncBase:NativeBodyType>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O       </Data>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O      </Add>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] PHPWrapper->ImportMessageChange(): change for: 'U5e81d:786e8a1ff7ed45edad6b2f883fdfb6a02e7001000000'
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O     </Perform>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SetFolderSyncStatus(): completed for U5e81d
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] ZPush::GetAdditionalSyncFolderStore('786e8a1ff7ed45edad6b2f883fdfb6a0080000000000'): 'false'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] Sync()->setFolderStat() on U5e81d: 1492716295/1/0/2288 expiring 2017-05-21 21:25:49
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O    </Folder>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->SetState() written 15 bytes on file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3b545193-f74e-4cde-a0d9-66b9b0915edf-2'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] SyncCollections->SaveCollection(): Data of folder 'U5e81d' changed
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->SetState() written 1045 bytes on file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-3b545193-f74e-4cde-a0d9-66b9b0915edf-fd'
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O   </Folders>
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] O  </Synchronize>
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] WBXMLEncoder->endTag() WBXML output completed
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] WBXML-OUT: AwFqAEVcT0sDezNiNTQ1MTkzLWY3NGUtNGNkZS1hMGQ5LTY2YjliMDkxNWVkZn0yAAFSA1U1ZTgxZAABTgMxAAFWR00DVTVlODFkOjc4NmU4YTFmZjdlZDQ1ZWRhZDZiMmY4ODNmZGZiNmEwMmU3MDAxMDAwMDAwAAFdAAJWAyJSaWNoYXJkIE1hcnNjaGlrIiA8cmljaGFyZEBtYXJzY2hpay5iaXo+AAFYAyJoZWlzZSBTZWN1cml0eSBTdW1tYXJ5IiA8bmV3c2xldHRlckBsaXN0c2Vydi5oZWlzZS5kZT4AAVQDaGVpc2UgU2VjdXJpdHkgTmV3cyAyOC4wMy4yMDE2AAFPAzIwMTYtMDMtMjhUMDk6MTg6NDIuMDAwWgABUQNSaWNoYXJkIE1hcnNjaGlrAAFSAzEAAVUDMQABUwNJUE0uTm90ZQABeQM2NTAwMQABABFKRgMxAAFMAzEyMDMxAAFNAzEAAUsDIA0KICAJaGVpc2UgU2VjdXJpdHkgTmV3cyAyOC4wMy4yMDE2DQp3d3cuaGVpc2UuZGUvc2VjdXJpdHkgIAkgICAJICANCiAgDQogIA0KICAJTmFjaHJpY2h0ZW7DvGJlcmJsaWNrIGRlciB2ZXJnYW5nZW5lbiB2aWVyIFRhZ2UJICANCiAgDQogIA0KICAJDQogIA0KaGVpc2UgU2VjdXJpdHkgTmV3cw0KICANCk5ldWUgSW5mZWt0aW9ucy1NYXNjaGU6IEVycHJlc3N1bmdzLVRyb2phbmVyIG1pc3NicmF1Y2h0IFdpbmRvd3MgUG93ZXJTaGVsbCAgDQoNCkRpZSBuZXUgZW50ZGVja3RlIFJhbnNvbXdhcmUgUG93ZXJXYXJlIGJlbcOkY2h0aWd0IHNpY2ggZGVyIFdpbmRvd3MgUG93ZXJTaGVsbCwgdW0gQ29tcHV0ZXIgenUgaW5maXppZXJlbiB1bmQgRGF0ZW4genUgdmVyc2NobMO8c3NlbG4uIA0KDQrigLrCoEFydGlrZWwgbGVzZW4gIMKgDQoNCi0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tDQoNCklyYW46IFVTQSBoYWJlbiBrZWluZSBCZXdlaXNlIGY/AAEBAAJ8A3Vybjpjb250ZW50LWNsYXNzZXM6bWVzc2FnZQABOgARVgMyAAEBAQEBAQE=
20/04/2017 21:25:49 [18988] [WBXML] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] WBXML-IN : AwFqAEVcT0sDezNiNTQ1MTkzLWY3NGUtNGNkZS1hMGQ5LTY2YjliMDkxNWVkZn0xAAFSA1U1ZTgxZAABE1UDMjUAAVdjAzEAAWIDMAABABFFRgMxAAFHAzUwMAABAQEBAQE=
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] DeviceManager->Save(): Device data changed
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] FileStateMachine->SetState() written 5062 bytes on file: '/var/lib/z-push/c/j/e51i135rs54dl5ar3cu242hkjc-devicedata'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] DeviceManager->Save(): Device data saved
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] LoopDetection->ProcessLoopDetectionTerminate()
20/04/2017 21:25:49 [18988] [ INFO] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] cmd='Sync' memory='2.09 MiB/4.00 MiB' time='0.58s' devType='iPhone' devId='e51i135rs54dl5ar3cu242hkjc' getUser='FIRSTNAME' from='IPADDRESS' version='2.3.5+5' method='POST' httpcode='200'
20/04/2017 21:25:49 [18988] [DEBUG] [FIRSTNAME] [e51i135rs54dl5ar3cu242hkjc] -------- End

Regards
Richard

Hey Richard,
can you please keep that fix running for a while? Just to see if you don’t run into this (another) issue.

Cheers,
Seb

Hi Sebastian,

i didn’t restore the original utils.php. So yes, i’ll keep it running and report if i am facing this issue again.

Regards
Richard

@Sebastian

Hi Sebastian,

in the meantime i upgrade z-push to version 2.3.6 and your fix got overwritten. Today i received a “problematic” mail, reapplied your fix and was able to successfully resync the device.

Regards
Richard

Yes, the ticket is scheduled for 2.3.7.

Cheers,
Sebastian

The issue is fixed now, root cause identified.
The new fix is currently in develop and will be merged into release/2.3 soon to go into 2.3.7.

More information is in ticket ZP-1199.