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?


  • Kopano

    Hi romeor,

    there’s something strange going on with your profile on the device. It syncs the folder with the id ‘Uce2aa’ but tries to modify the item ‘U96461:042f7fc33be041bb9a6382c616b31ca2ff4a00000000’ which is in another folder (the FolderId and ServerEntryId part before ‘:’ must be equal).

    Could you post the output of

    z-push-admin -a list -u roman -d androidc1650660868
    

    ?

    Do you have multiple ActiveSync accounts on your device?

    For now I don’t have any idea you could try other than to remove profile from the device, remove the device with z-push-admin, create the profile on the mobile again.

    Manfred



  • @manfred
    Hi, thanks for an answer.
    Actually, as soon as I get these errors I have remove the account from phone and add it again to get things going. This happens pretty often, so I decided to ask for a help and help myself to debug the issue.

    There are two accounts on the phone: one syncs calendar, contacts and e-mail.
    Another one is so named shared calendar used among multiple users. The problem occurs only with first one and it seems like only on my phone.

    The output is here:

    Synchronized by user: roman
    -----------------------------------------------------
    DeviceId:               androidc1650660868
    Device type:            Android
    UserAgent:              Android/7.0-EAS-2.0
    Device Model:           WAS-LX1
    Device IMEI:            IMEI-HERE
    Device friendly name:   WAS-LX1
    Device OS:              Android 7.0
    ActiveSync version:     14.0
    First sync:             2017-06-05 12:02
    Last sync:              2017-10-23 16:17
    Total folders:          39
    Short folder Ids:       Yes
    Synchronized folders:   7
    Synchronized data:      Emails(5) Contacts Calendars
    Additional Folders:     none
    Status:                 OK
    WipeRequest on:         not set
    WipeRequest by:         not set
    Wiped on:               not set
    Policy name:            default
    Attention needed:       No errors known
    

    But I’ve already recreated the account so there is no issue for some time. Should I post the output, when I’ll have the same issue?


  • Kopano

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

    But I’ve already recreated the account so there is no issue for some time. Should I post the output, when I’ll have the same issue?

    Yes, please. If possible you could also add the debug from the device (e.g. via adb).

    Manfred


  • Kopano

    Perhaps it would be helpful to get a WBXML log from before this issue happens. In the log snipped you’ve posted the device tries to mark an email as read. The only explanation I can find is that this email is located in a Contact folder.

    Could you resync your device and attach the WBXML output? Btw, WBXML log level is enough (no need for WBXMLSTACK).
    Especially interesting would be the log of the FolderSync command (on of the first commands to be triggered after resync).

    Just confirming: is this a Huawei P10 lite?



  • Hello,

    I’m sorry. I’m not able to follow this issue any more. I’ve dropped my phone and it’s glass cracked so I can’t use it anymore. As glass change costs as same as almost new xiaomi phone I’ve decided to just buy new phone.

    I will try to get back if I’ll get same problems with my new phone.

    And yes, it was Huawei P10 Lite.


Log in to reply
 

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