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.


  • Kopano

    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


  • Kopano

    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


  • Kopano

    Yes, the ticket is scheduled for 2.3.7.

    Cheers,
    Sebastian


  • Kopano

    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.


Log in to reply
 

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.