Exception: (WBXMLException) - Unknown error in Sync->Handle()



  • Hi, getting these errors with my latest stable Z-push and Huawei P10 Lite

    07/10/2017 20:34:24 [  348] [FATAL] [roman] Exception: (WBXMLException) - Unknown error in Sync->Handle()
    07/10/2017 20:34:24 [  348] [FATAL] [roman] Request could not be processed correctly due to a WBXMLException. Please report this including the 'WBXML debug data' logged. Be aware that the debug data could contain confidential information.
    07/10/2017 20:35:27 [11598] [ERROR] [roman] WBXMLDecoder->getElementEndTag(): could not read end tag in '/usr/share/z-push/lib/request/sync.php:492'. Please enable the LOGLEVEL_WBXML and send the log to the Z-Push dev team.
    07/10/2017 20:35:27 [11598] [FATAL] [roman] WBXMLException: Unknown error in Sync->Handle() - code: 0 - file: /usr/share/z-push/lib/request/requestprocessor.php:113
    07/10/2017 20:35:27 [11598] [FATAL] [roman] WBXML 10K debug data: AwFqAEVcT0sDezkzNDczYTNlLTE0MWItNDU5Mi1hMjZiLWNkMDAyNTFiZjdlNX0yNDcAAVIDVWNlMmFhAAFeAzEAAVMDMAABVkhNA1U5NjQ2MTowNDJmN2ZjMzNiZTA0MWJiOWE2MzgyYzYxNmIzMWNhMjhkNGEwMDAwMDAwMAABXQACVQMxAAEBAQEBAQE=
    


  • And here is the debug

    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] -------- Start
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] cmd='Ping' devType='Android' devId='androidc1650660868' getUser='roman' from='185.158.178.166' version='2.3.8+0-0' method='POST'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] Used timezone 'Europe/Tallinn'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] BackendKopano using PHP-MAPI version: 7.2.5-109 - PHP version: 5.6.30-0+deb8u1
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] Request::ProcessHeaders() ASVersion: 14.0
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsProvisioning(18): false
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsAuthentication(18): true
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->Logon(): Trying to authenticate user 'roman'..
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '6160' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-devicedata'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ASDevice data loaded for user: 'roman'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] TopCollector(): Initialized mutexid Resource id #19 and memid Resource id #20.
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] LoopDetection(): Initialized mutexid Resource id #23 and memid Resource id #24.
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::HierarchyCommand(18): false
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->openMessageStore('roman'): Found 'DEFAULT' store: 'Resource id #30'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->Logon(): User 'roman' is authenticated
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] Store supports properties containing Unicode characters.
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsPlainInput(18): false
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I  <Ping:Ping>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1048' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-f2d48d89-e29b-45b9-aa2a-06cc07ea5135-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c40200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'U96461' : ref. PolicyKey '608877122', ref. Lifetime '1080', last sync at '1507092233'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Updated reference PolicyKey '608877122', reference Lifetime '1080', Last sync at '1507092233'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{f2d48d89-e29b-45b9-aa2a-06cc07ea5135}262'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-f2d48d89-e29b-45b9-aa2a-06cc07ea5135-262'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1092' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-93473a3e-141b-4592-a26b-cd00251bf7e5-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c60200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'Uce2aa' : ref. PolicyKey '608877122', ref. Lifetime '1680', last sync at '1507092232'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{93473a3e-141b-4592-a26b-cd00251bf7e5}247'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-93473a3e-141b-4592-a26b-cd00251bf7e5-247'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1049' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-8b411180-16bd-40c9-a171-8a06ba97f3e9-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c70200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'Ufa47f' : ref. PolicyKey '608877122', ref. Lifetime '1080', last sync at '1506813002'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{8b411180-16bd-40c9-a171-8a06ba97f3e9}62'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-8b411180-16bd-40c9-a171-8a06ba97f3e9-62'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1031' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-36631614-2cda-4724-8f28-b2c49410e4af-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c80200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'U9c5c8' : ref. PolicyKey '608877122', ref. Lifetime '1080', last sync at '1507390471'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Updated reference PolicyKey '608877122', reference Lifetime '1080', Last sync at '1507390471'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{36631614-2cda-4724-8f28-b2c49410e4af}129'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-36631614-2cda-4724-8f28-b2c49410e4af-129'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1030' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-0d98bea4-d4d1-473b-b93b-8a2ace94fa71-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c90200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'U5dd25' : ref. PolicyKey '608877122', ref. Lifetime '1080', last sync at '1505611035'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{0d98bea4-d4d1-473b-b93b-8a2ace94fa71}9'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-0d98bea4-d4d1-473b-b93b-8a2ace94fa71-9'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1013' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-533a624a-7509-4e25-8a92-c293a2ff4047-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2f20400000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'U954ad' : ref. PolicyKey '608877122', ref. Lifetime '', last sync at '1506955812'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{533a624a-7509-4e25-8a92-c293a2ff4047}1'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-533a624a-7509-4e25-8a92-c293a2ff4047-1'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1020' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-a49b2115-4bbd-49cf-9676-155043942453-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2584300000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'U518ac' : ref. PolicyKey '608877122', ref. Lifetime '1680', last sync at '1501516454'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{a49b2115-4bbd-49cf-9676-155043942453}3'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-a49b2115-4bbd-49cf-9676-155043942453-3'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-6b7a58e3-41d6-4b5e-a2b4-558fc101f86a-fd'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '608877122', ref. Lifetime '10', last sync at '1507011143'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->GetLatestSyncKey(): '{6b7a58e3-41d6-4b5e-a2b4-558fc101f86a}3'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] StateManager->loadHierarchyCache(): 'androidc1650660868-6b7a58e3-41d6-4b5e-a2b4-558fc101f86a-hc-3'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '9708' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-6b7a58e3-41d6-4b5e-a2b4-558fc101f86a-hc-3'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-6b7a58e3-41d6-4b5e-a2b4-558fc101f86a-3'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] HandlePing(): reference PolicyKey for PING: 608877122
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] HandlePing(): initialization data received
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I   <Ping:LifeTime>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    480
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I   </Ping:LifeTime>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I   <Ping:Folders>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    <Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      U96461
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      Email
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    </Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] HandlePing(): using saved sync state for 'Email' id 'U96461'
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    <Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      Ufa47f
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      Email
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    </Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] HandlePing(): using saved sync state for 'Email' id 'Ufa47f'
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    <Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      U9c5c8
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      Contacts
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    </Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] HandlePing(): using saved sync state for 'Contacts' id 'U9c5c8'
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    <Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      U5dd25
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:ServerEntryId>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     <Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I      Calendar
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I     </Ping:FolderType>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I    </Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] HandlePing(): using saved sync state for 'Calendar' id 'U5dd25'
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I   </Ping:Folders>
    08/10/2017 02:03:31 [ 1875] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Ping:Folder' matching '' type '2' flags ''
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] I  </Ping:Ping>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] PingTracking(): Initialized mutexid Resource id #152 and memid Resource id #153.
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] Announce process as PUSH connection
    08/10/2017 02:03:31 [ 1875] [ INFO] [roman] [androidc1650660868] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 480 seconds)
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->HasChangesSink(): created - HierarchyHash: 8fe2e012f80673fcb30f4a2174c791b5
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->adviseStoreToSink(): advised store 'Resource id #30'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c40200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->ChangesSinkInitialize(): folderid '042f7fc33be041bb9a6382c616b31ca2c40200000000'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] KopanoBackend->GetFolderStat() fetched status information of 51 folders for store 'roman'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->IsExporterRunRequired(): true - current: 1507397716/117/0/28 - saved: 1507092231/113/1/26 - expiring: 2017-10-10 21:17:52
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c70200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->IsExporterRunRequired(): true - current: 1507283887/1041/0/0 - saved: 1506813000/1037/0/0 - expiring: 2017-10-07 18:20:39
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c80200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->IsExporterRunRequired(): false - current: 1507390470/217/0/0 - saved: 1507390470/217/0/0 - expiring: 2017-11-07 14:05:49
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c90200000000'): 'false'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncParameters->IsExporterRunRequired(): false - current: 1505611034/45/0/0 - saved: 1505611034/45/0/0 - expiring: 2017-10-15 21:12:39
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] SyncCollections->CheckForChanges(): Using ChangesSink but found changes verifying the folder stats
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O  <Ping:Ping>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O   <Ping:Status>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O   2
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O   </Ping:Status>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O   <Ping:Folders>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O    <Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O    U96461
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O    </Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] LoopDetection->ProcessLoopDetectionAddStatus: 'U96461' with status 2
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O    <Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O    Ufa47f
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O    </Ping:Folder>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] LoopDetection->ProcessLoopDetectionAddStatus: 'Ufa47f' with status 2
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O   </Ping:Folders>
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] O  </Ping:Ping>
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] WBXMLEncoder->endTag() WBXML output completed
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk2NDYxAAFKA1VmYTQ3ZgABAQE=
    08/10/2017 02:03:31 [ 1875] [WBXML] [roman] [androidc1650660868] WBXML-IN : AwFqAAANRUgDNDgwAAFJSksDVTk2NDYxAAFMA0VtYWlsAAEBSksDVWZhNDdmAAFMA0VtYWlsAAEBSksDVTljNWM4AAFMA0NvbnRhY3RzAAEBSksDVTVkZDI1AAFMA0NhbGVuZGFyAAEBAQE=
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] LoopDetection->ProcessLoopDetectionTerminate()
    08/10/2017 02:03:31 [ 1875] [ INFO] [roman] [androidc1650660868] cmd='Ping' memory='2.77 MiB/3.25 MiB' time='0.23s' devType='Android' devId='androidc1650660868' getUser='roman' from='185.158.178.166' idle='0s' version='2.3.8+0-0' method='POST' httpcode='200'
    08/10/2017 02:03:31 [ 1875] [DEBUG] [roman] [androidc1650660868] -------- End
    
    


  • And should I change my password after I’ve published my debug?


  • Kopano

    Hi romeor,

    I don’t see anything wrong in WBXML debug data you posted in the initial post. There are two different requests (pid 348 and 11598). Is this the complete error log?

    The 2nd post is not helpful for us because it’s for a ‘Ping’ command and not for a ‘Sync’ command which was causing the issues.

    Is it a new installation or an update? Have you installed using the repositories or the tar archive?

    @romeor said in Exception: (WBXMLException) - Unknown error in Sync->Handle():

    And should I change my password after I’ve published my debug?

    Z-Push doesn’t output the password to the logs.

    Manfred



  • Thanks for the answer. It suddenly started to work again. I will come back, when I see same problem again. When this happens my phone is unable to sync.



  • Well, here it comes again:

    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] -------- Start
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] cmd='Sync' devType='Android' devId='androidc1650660868' getUser='roman' from='37.157.96.39' version='2.3.8+0-0' method='POST'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] Used timezone 'Europe/Tallinn'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] BackendKopano using PHP-MAPI version: 7.2.5-109 - PHP version: 5.6.30-0+deb8u1
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] Request::ProcessHeaders() ASVersion: 14.0
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsProvisioning(0): true
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '6160' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-devicedata'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] ASDevice data loaded for user: 'roman'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] TopCollector(): Initialized mutexid Resource id #55 and memid Resource id #56.
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] LoopDetection(): Initialized mutexid Resource id #60 and memid Resource id #61.
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] ZPush::HierarchyCommand(0): false
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] DeviceManager->ProvisioningRequired('608877122') saved device key '608877122': false
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] DeviceManager->getPolicyName(): determined policy name: 'default'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsAuthentication(0): true
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] KopanoBackend->Logon(): Trying to authenticate user 'roman'..
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] KopanoBackend->openMessageStore('roman'): Found 'DEFAULT' store: 'Resource id #76'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] KopanoBackend->Logon(): User 'roman' is authenticated
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] Store supports properties containing Unicode characters.
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsPlainInput(0): false
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I  <Synchronize>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I   <Folders>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Version' matching 'Folders' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I    <Folder>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     <SyncKey>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'FolderType' matching 'SyncKey' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I      {93473a3e-141b-4592-a26b-cd00251bf7e5}363
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     </SyncKey>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     <FolderId>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I      Uce2aa
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     </FolderId>
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1092' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-93473a3e-141b-4592-a26b-cd00251bf7e5-fd'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] DeviceManager->GetBackendIdForFolderId(): folderid Uce2aa => 042f7fc33be041bb9a6382c616b31ca2c60200000000
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'Uce2aa' : ref. PolicyKey '608877122', ref. Lifetime '1380', last sync at '1507624065'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Updated reference PolicyKey '608877122', reference Lifetime '1380', Last sync at '1507624065'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     <DeletesAsMoves>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Supported' matching 'DeletesAsMoves' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I      1
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     </DeletesAsMoves>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     <GetChanges>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I      0
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     </GetChanges>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     <Perform>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'WindowSize' matching 'Perform' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'ConversationMode' matching 'Perform' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Options' matching 'Perform' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I      <Modify>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I       <ServerEntryId>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'FolderType' matching 'ServerEntryId' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I        U96461:042f7fc33be041bb9a6382c616b31ca2ff4a00000000
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I       </ServerEntryId>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I       <Data>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'ClientEntryId' matching 'Data' type '1' flags '1'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I        <POOMMAIL:Read>
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] Tag 'POOMMAIL:Read' unexpected in type XML type 'SyncContact'
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I         1
    10/10/2017 11:42:31 [27691] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementEndTag(): unmatched WBXML tag: '' type '3' flags ''
    10/10/2017 11:42:31 [27691] [ERROR] [roman] [androidc1650660868] WBXMLDecoder->getElementEndTag(): could not read end tag in '/usr/share/z-push/lib/request/sync.php:492'. Please enable the LOGLEVEL_WBXML and send the log to the Z-Push dev team.
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I        </POOMMAIL:Read>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I       </Data>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I      </Modify>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I     </Perform>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I    </Folder>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I   </Folders>
    10/10/2017 11:42:31 [27691] [WBXML] [roman] [androidc1650660868] I  </Synchronize>
    10/10/2017 11:42:31 [27691] [FATAL] [roman] [androidc1650660868] WBXMLException: Unknown error in Sync->Handle() - code: 0 - file: /usr/share/z-push/lib/request/requestprocessor.php:113
    10/10/2017 11:42:31 [27691] [FATAL] [roman] [androidc1650660868] WBXML 10K debug data: AwFqAEVcT0sDezkzNDczYTNlLTE0MWItNDU5Mi1hMjZiLWNkMDAyNTFiZjdlNX0zNjMAAVIDVWNlMmFhAAFeAzEAAVMDMAABVkhNA1U5NjQ2MTowNDJmN2ZjMzNiZTA0MWJiOWE2MzgyYzYxNmIzMWNhMmZmNGEwMDAwMDAwMAABXQACVQMxAAEBAQEBAQE=
    10/10/2017 11:42:31 [27691] [ INFO] [roman] [androidc1650660868] User-agent: 'Android/7.0-EAS-2.0'
    10/10/2017 11:42:31 [27691] [FATAL] [roman] [androidc1650660868] Exception: (WBXMLException) - Unknown error in Sync->Handle()
    10/10/2017 11:42:31 [27691] [FATAL] [roman] [androidc1650660868] Request could not be processed correctly due to a WBXMLException. Please report this including the 'WBXML debug data' logged. Be aware that the debug data could contain confidential information.
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] LoopDetection->ProcessLoopDetectionTerminate()
    10/10/2017 11:42:31 [27691] [ INFO] [roman] [androidc1650660868] cmd='Sync' memory='3.14 MiB/4.50 MiB' time='0.26s' devType='Android' devId='androidc1650660868' getUser='roman' from='37.157.96.39' idle='0s' version='2.3.8+0-0' method='POST' httpcode='500'
    10/10/2017 11:42:31 [27691] [DEBUG] [roman] [androidc1650660868] -------- End
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] -------- Start
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] cmd='Sync' devType='Android' devId='androidc1650660868' getUser='roman' from='37.157.96.39' version='2.3.8+0-0' method='POST'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] Used timezone 'Europe/Tallinn'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] BackendKopano using PHP-MAPI version: 7.2.5-109 - PHP version: 5.6.30-0+deb8u1
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] Request::ProcessHeaders() ASVersion: 14.0
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsProvisioning(0): true
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '6160' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-devicedata'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] ASDevice data loaded for user: 'roman'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] TopCollector(): Initialized mutexid Resource id #17 and memid Resource id #18.
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] LoopDetection(): Initialized mutexid Resource id #21 and memid Resource id #22.
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] ZPush::HierarchyCommand(0): false
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] DeviceManager->ProvisioningRequired('608877122') saved device key '608877122': false
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] DeviceManager->getPolicyName(): determined policy name: 'default'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsAuthentication(0): true
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] KopanoBackend->Logon(): Trying to authenticate user 'roman'..
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] KopanoBackend->openMessageStore('roman'): Found 'DEFAULT' store: 'Resource id #33'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] KopanoBackend->Logon(): User 'roman' is authenticated
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] Store supports properties containing Unicode characters.
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] ZPush::CommandNeedsPlainInput(0): false
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I  <Synchronize>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I   <Folders>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Version' matching 'Folders' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I    <Folder>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     <SyncKey>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'FolderType' matching 'SyncKey' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      {0d98bea4-d4d1-473b-b93b-8a2ace94fa71}9
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     </SyncKey>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     <FolderId>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      U5dd25
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     </FolderId>
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] FileStateMachine->GetState() read '1030' bytes from file: '/var/lib/z-push/8/6/androidc1650660868-0d98bea4-d4d1-473b-b93b-8a2ace94fa71-fd'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] DeviceManager->GetBackendIdForFolderId(): folderid U5dd25 => 042f7fc33be041bb9a6382c616b31ca2c90200000000
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Folder id 'U5dd25' : ref. PolicyKey '608877122', ref. Lifetime '1080', last sync at '1505611035'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] SyncCollections->AddCollection(): Updated reference PolicyKey '608877122', reference Lifetime '1080', Last sync at '1505611035'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     <DeletesAsMoves/>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Supported' matching 'DeletesAsMoves' type '1' flags '0'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     <GetChanges/>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementContent(): unmatched WBXML content: 'GetChanges' type '1' flags '0'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     <WindowSize>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementContent(): unmatched WBXML content: 'WindowSize' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      10
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     </WindowSize>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     <Options>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'ConversationMode' matching 'Options' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      <FilterType>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'FolderType' matching 'FilterType' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] SyncParameters->UseCPO('DEFAULT')
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I       4
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      </FilterType>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      <AirSyncBase:BodyPreference>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Truncation' matching 'AirSyncBase:BodyPreference' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'RtfTruncation' matching 'AirSyncBase:BodyPreference' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'MIMESupport' matching 'AirSyncBase:BodyPreference' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'MIMETruncation' matching 'AirSyncBase:BodyPreference' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Conflict' matching 'AirSyncBase:BodyPreference' type '1' flags '1'
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I       <AirSyncBase:Type>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I        1
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I       </AirSyncBase:Type>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I       <AirSyncBase:TruncationSize>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I        200000
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I       </AirSyncBase:TruncationSize>
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I      </AirSyncBase:BodyPreference>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'AirSyncBase:AllOrNone' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'AirSyncBase:Preview' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I     </Options>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'AirSyncBase:BodyPreference' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I    </Folder>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Options' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Perform' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I   </Folders>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Folder' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] I  </Synchronize>
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'HeartbeatInterval' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Wait' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'WindowSize' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [WBXMLSTACK] [roman] [androidc1650660868] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: 'Partial' matching '' type '2' flags ''
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] HandleSync(): Start Output
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] ZPush::GetAdditionalSyncFolderStore('042f7fc33be041bb9a6382c616b31ca2c90200000000'): 'false'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] KopanoBackend->GetFolderStat() fetched status information of 52 folders for store 'roman'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] SyncParameters->IsExporterRunRequired(): false - current: 1505611034/45/0/0 - saved: 1505611034/45/0/0 - expiring: 2017-10-15 21:12:39
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] HandleSync: No changes found for Calendar folder id 'U5dd25'. Omitting output.
    10/10/2017 11:42:32 [27692] [WBXML] [roman] [androidc1650660868] WBXML-IN : AwFqAEVcT0sDezBkOThiZWE0LWQ0ZDEtNDczYi1iOTNiLThhMmFjZTk0ZmE3MX05AAFSA1U1ZGQyNQABHhNVAzEwAAFXWAM0AAEAEUVGAzEAAUcDMjAwMDAwAAEBAQEBAQ==
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] LoopDetection->ProcessLoopDetectionTerminate()
    10/10/2017 11:42:32 [27692] [ INFO] [roman] [androidc1650660868] cmd='Sync' memory='2.36 MiB/2.75 MiB' time='0.22s' devType='Android' devId='androidc1650660868' getUser='roman' from='37.157.96.39' idle='0s' version='2.3.8+0-0' method='POST' httpcode='200'
    10/10/2017 11:42:32 [27692] [DEBUG] [roman] [androidc1650660868] -------- End
    

    z-push is installed from repository



  • Any thoughts?


Log in to reply
 

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