Outlook 365 crashes with recurring to-dos marked as done on Nine (Android)
-
Outlook 2003, Step 1 (Create recurring to-do)
10/11/2018 08:49:26 [19437] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:49:26 [19437] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 08:49:26 [19437] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e' 10/11/2018 08:49:26 [19437] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 08:49:26 [19437] [WBXML] O <Ping:Ping> 10/11/2018 08:49:26 [19437] [WBXML] O <Ping:Status> 10/11/2018 08:49:26 [19437] [WBXML] O 2 10/11/2018 08:49:26 [19437] [WBXML] O </Ping:Status> 10/11/2018 08:49:26 [19437] [WBXML] O <Ping:Folders> 10/11/2018 08:49:26 [19437] [WBXML] O <Ping:Folder> 10/11/2018 08:49:26 [19437] [WBXML] O U9586e 10/11/2018 08:49:26 [19437] [WBXML] O </Ping:Folder> 10/11/2018 08:49:26 [19437] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 2 10/11/2018 08:49:26 [19437] [WBXML] O </Ping:Folders> 10/11/2018 08:49:26 [19437] [WBXML] O </Ping:Ping> 10/11/2018 08:49:26 [19437] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 08:49:26 [19437] [WBXML] WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk1ODZlAAEBAQ== 10/11/2018 08:49:26 [19437] [WBXML] WBXML-IN : AwFqAAANRUgDNzIwAAFJSksDVTk1ODZlAAFMA1Rhc2tzAAEBAQE= 10/11/2018 08:49:26 [19437] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 08:49:26 [19437] [ INFO] cmd='Ping' memory='2.04 MiB/2.00 MiB' time='22.26s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='22s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 08:49:26 [19437] [DEBUG] -------- End 10/11/2018 08:49:27 [19022] [DEBUG] -------- Start 10/11/2018 08:49:27 [19022] [DEBUG] cmd='Sync' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 08:49:27 [19022] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 08:49:27 [19022] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 08:49:27 [19022] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::CommandNeedsProvisioning(0): true 10/11/2018 08:49:27 [19022] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 08:49:27 [19022] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 08:49:27 [19022] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 08:49:27 [19022] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 08:49:27 [19022] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 08:49:27 [19022] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::HierarchyCommand(0): false 10/11/2018 08:49:27 [19022] [DEBUG] DeviceManager->ProvisioningRequired('833158280') saved device key '833158280': false 10/11/2018 08:49:27 [19022] [DEBUG] DeviceManager->getPolicyName(): determined policy name: 'default' 10/11/2018 08:49:27 [19022] [DEBUG] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::CommandNeedsAuthentication(0): true 10/11/2018 08:49:27 [19022] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 08:49:27 [19022] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 08:49:27 [19022] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 08:49:27 [19022] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::CommandNeedsPlainInput(0): false 10/11/2018 08:49:27 [19022] [WBXML] I <Synchronize> 10/11/2018 08:49:27 [19022] [WBXML] I <Folders> 10/11/2018 08:49:27 [19022] [WBXML] I <Folder> 10/11/2018 08:49:27 [19022] [WBXML] I <SyncKey> 10/11/2018 08:49:27 [19022] [WBXML] I {f05e74b0-98c9-442c-92f4-c96395f41858}115 10/11/2018 08:49:27 [19022] [WBXML] I </SyncKey> 10/11/2018 08:49:27 [19022] [WBXML] I <FolderId> 10/11/2018 08:49:27 [19022] [WBXML] I U9586e 10/11/2018 08:49:27 [19022] [WBXML] I </FolderId> 10/11/2018 08:49:27 [19022] [DEBUG] FileStateMachine->GetState() read '1016' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:49:27 [19022] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:49:27 [19022] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:49:27 [19022] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541836136' 10/11/2018 08:49:27 [19022] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541836136' 10/11/2018 08:49:27 [19022] [WBXML] I <DeletesAsMoves> 10/11/2018 08:49:27 [19022] [WBXML] I 1 10/11/2018 08:49:27 [19022] [WBXML] I </DeletesAsMoves> 10/11/2018 08:49:27 [19022] [WBXML] I <GetChanges> 10/11/2018 08:49:27 [19022] [WBXML] I 1 10/11/2018 08:49:27 [19022] [WBXML] I </GetChanges> 10/11/2018 08:49:27 [19022] [WBXML] I <WindowSize> 10/11/2018 08:49:27 [19022] [WBXML] I 5 10/11/2018 08:49:27 [19022] [WBXML] I </WindowSize> 10/11/2018 08:49:27 [19022] [WBXML] I <Options> 10/11/2018 08:49:27 [19022] [WBXML] I <FilterType> 10/11/2018 08:49:27 [19022] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:49:27 [19022] [WBXML] I 0 10/11/2018 08:49:27 [19022] [WBXML] I </FilterType> 10/11/2018 08:49:27 [19022] [WBXML] I <Conflict> 10/11/2018 08:49:27 [19022] [WBXML] I 1 10/11/2018 08:49:27 [19022] [WBXML] I </Conflict> 10/11/2018 08:49:27 [19022] [WBXML] I <AirSyncBase:BodyPreference> 10/11/2018 08:49:27 [19022] [WBXML] I <AirSyncBase:Type> 10/11/2018 08:49:27 [19022] [WBXML] I 1 10/11/2018 08:49:27 [19022] [WBXML] I </AirSyncBase:Type> 10/11/2018 08:49:27 [19022] [WBXML] I <AirSyncBase:AllOrNone> 10/11/2018 08:49:27 [19022] [WBXML] I 0 10/11/2018 08:49:27 [19022] [WBXML] I </AirSyncBase:AllOrNone> 10/11/2018 08:49:27 [19022] [WBXML] I </AirSyncBase:BodyPreference> 10/11/2018 08:49:27 [19022] [WBXML] I </Options> 10/11/2018 08:49:27 [19022] [WBXML] I </Folder> 10/11/2018 08:49:27 [19022] [WBXML] I </Folders> 10/11/2018 08:49:27 [19022] [WBXML] I </Synchronize> 10/11/2018 08:49:27 [19022] [DEBUG] HandleSync(): Start Output 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:49:27 [19022] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 08:49:27 [19022] [DEBUG] SyncParameters->IsExporterRunRequired(): true - current: 1541836166/1/0/30 - saved: 1541836135/0/0/30 - expiring: 2018-12-11 05:56:40 10/11/2018 08:49:27 [19022] [DEBUG] Sync->loadStates(): loading states for folder 'U9586e' 10/11/2018 08:49:27 [19022] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-115' 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:49:27 [19022] [DEBUG] ExportChangesICS->Config() initialized with state: 0x8000000085020000 10/11/2018 08:49:27 [19022] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 08:49:27 [19022] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 1 10/11/2018 08:49:27 [19022] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 08:49:27 [19022] [DEBUG] Folder type: Tasks 10/11/2018 08:49:27 [19022] [WBXML] O <Synchronize> 10/11/2018 08:49:27 [19022] [WBXML] O <Folders> 10/11/2018 08:49:27 [19022] [WBXML] O <Folder> 10/11/2018 08:49:27 [19022] [WBXML] O <SyncKey> 10/11/2018 08:49:27 [19022] [WBXML] O {f05e74b0-98c9-442c-92f4-c96395f41858}116 10/11/2018 08:49:27 [19022] [WBXML] O </SyncKey> 10/11/2018 08:49:27 [19022] [WBXML] O <FolderId> 10/11/2018 08:49:27 [19022] [WBXML] O U9586e 10/11/2018 08:49:27 [19022] [WBXML] O </FolderId> 10/11/2018 08:49:27 [19022] [WBXML] O <Status> 10/11/2018 08:49:27 [19022] [WBXML] O 1 10/11/2018 08:49:27 [19022] [WBXML] O </Status> 10/11/2018 08:49:27 [19022] [DEBUG] LoopDetection->Detect(): folderid:'U9586e' uuid:'f05e74b0-98c9-442c-92f4-c96395f41858' counter:'115' max:'5' queued:'1' 10/11/2018 08:49:27 [19022] [DEBUG] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: '56cabf443b954d0c8caedab84208fdf0800100000000', parentsourcekey: '56cabf443b954d0c8caedab84208fdf02f0000000000', entryid: '000000009c956e50afc34d66bd0faad6901b0124010000000500000068b0aab3693d004597bc8df15cc1138300000000' 10/11/2018 08:49:27 [19022] [DEBUG] BodyPreference types: 1 10/11/2018 08:49:27 [19022] [DEBUG] GetBodyPreferenceBestMatch: 1 10/11/2018 08:49:27 [19022] [DEBUG] bpo: truncation size:'0', allornone:'0', preview:'0' 10/11/2018 08:49:27 [19022] [DEBUG] MAPIStreamWrapper::stream_open(): initialized mapistream: - streamlength: 0 - HTML-safe-truncate: false 10/11/2018 08:49:27 [19022] [WBXML] O <Perform> 10/11/2018 08:49:27 [19022] [WBXML] O <Add> 10/11/2018 08:49:27 [19022] [WBXML] O <ServerEntryId> 10/11/2018 08:49:27 [19022] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0800100000000 10/11/2018 08:49:27 [19022] [WBXML] O </ServerEntryId> 10/11/2018 08:49:27 [19022] [WBXML] O <Data> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Complete> 10/11/2018 08:49:27 [19022] [WBXML] O 0 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Complete> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:DueDate> 10/11/2018 08:49:27 [19022] [WBXML] O 2018-11-10T00:00:00.000Z 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:DueDate> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:UtcDueDate> 10/11/2018 08:49:27 [19022] [WBXML] O 2018-11-09T23:00:00.000Z 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:UtcDueDate> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Importance> 10/11/2018 08:49:27 [19022] [WBXML] O 1 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Importance> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Recurrence> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Type> 10/11/2018 08:49:27 [19022] [WBXML] O 0 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Type> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Interval> 10/11/2018 08:49:27 [19022] [WBXML] O 1 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Interval> 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Recurrence> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:ReminderSet> 10/11/2018 08:49:27 [19022] [WBXML] O 0 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:ReminderSet> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Sensitivity> 10/11/2018 08:49:27 [19022] [WBXML] O 0 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Sensitivity> 10/11/2018 08:49:27 [19022] [WBXML] O <POOMTASKS:Subject> 10/11/2018 08:49:27 [19022] [WBXML] O OL2003 daily recurring 10/11/2018 08:49:27 [19022] [WBXML] O </POOMTASKS:Subject> 10/11/2018 08:49:27 [19022] [WBXML] O <AirSyncBase:Body> 10/11/2018 08:49:27 [19022] [WBXML] O <AirSyncBase:Type> 10/11/2018 08:49:27 [19022] [WBXML] O 1 10/11/2018 08:49:27 [19022] [WBXML] O </AirSyncBase:Type> 10/11/2018 08:49:27 [19022] [WBXML] O <AirSyncBase:EstimatedDataSize> 10/11/2018 08:49:27 [19022] [WBXML] O 0 10/11/2018 08:49:27 [19022] [WBXML] O </AirSyncBase:EstimatedDataSize> 10/11/2018 08:49:27 [19022] [WBXML] O <AirSyncBase:Data> 10/11/2018 08:49:27 [19022] [WBXML] O <<< written 0 of 0 bytes of plain data >>> 10/11/2018 08:49:27 [19022] [WBXML] O </AirSyncBase:Data> 10/11/2018 08:49:27 [19022] [WBXML] O </AirSyncBase:Body> 10/11/2018 08:49:27 [19022] [WBXML] O </Data> 10/11/2018 08:49:27 [19022] [WBXML] O </Add> 10/11/2018 08:49:27 [19022] [DEBUG] PHPWrapper->ImportMessageChange(): change for: 'U9586e:56cabf443b954d0c8caedab84208fdf0800100000000' 10/11/2018 08:49:27 [19022] [WBXML] O </Perform> 10/11/2018 08:49:27 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:49:27 [19022] [DEBUG] Sync()->setFolderStat() on U9586e: 1541836166/1/0/30 expiring 2018-12-11 00:47:15 10/11/2018 08:49:27 [19022] [WBXML] O </Folder> 10/11/2018 08:49:27 [19022] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-116' 10/11/2018 08:49:27 [19022] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 08:49:27 [19022] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:49:27 [19022] [WBXML] O </Folders> 10/11/2018 08:49:27 [19022] [WBXML] O </Synchronize> 10/11/2018 08:49:27 [19022] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 08:49:27 [19022] [WBXML] WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTYAAVIDVTk1ODZlAAFOAzEAAVZHTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4MDAxMDAwMDAwMDAAAV0ACUoDMAABTAMyMDE4LTExLTEwVDAwOjAwOjAwLjAwMFoAAU0DMjAxOC0xMS0wOVQyMzowMDowMC4wMDBaAAFOAzEAAU9QAzAAAVQDMQABAVsDMAABXQMwAAFgA09MMjAwMyBkYWlseSByZWN1cnJpbmcAAQARSkYDMQABTAMwAAFLAwABAQEBAQEBAQ== 10/11/2018 08:49:27 [19022] [WBXML] WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTUAAVIDVTk1ODZlAAFeAzEAAVMDMQABVQM1AAFXWAMwAAFbAzEAAQARRUYDMQABSAMwAAEBAQEBAQ== 10/11/2018 08:49:27 [19022] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 08:49:27 [19022] [ INFO] cmd='Sync' memory='2.02 MiB/2.00 MiB' time='0.06s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='0s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 08:49:27 [19022] [DEBUG] -------- End 10/11/2018 08:49:33 [19021] [DEBUG] -------- Start 10/11/2018 08:49:33 [19021] [DEBUG] cmd='Ping' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 08:49:33 [19021] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 08:49:33 [19021] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 08:49:33 [19021] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::CommandNeedsProvisioning(18): false 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::CommandNeedsAuthentication(18): true 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 08:49:33 [19021] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 08:49:33 [19021] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 08:49:33 [19021] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 08:49:33 [19021] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 08:49:33 [19021] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::HierarchyCommand(18): false 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 08:49:33 [19021] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::CommandNeedsPlainInput(18): false 10/11/2018 08:49:33 [19021] [WBXML] I <Ping:Ping> 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->GetState() read '1045' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:49:33 [19021] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:49:33 [19021] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541836167' 10/11/2018 08:49:33 [19021] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541836167' 10/11/2018 08:49:33 [19021] [DEBUG] SyncParameters->GetLatestSyncKey(): '{f05e74b0-98c9-442c-92f4-c96395f41858}116' 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-116' 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-fd' 10/11/2018 08:49:33 [19021] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:49:33 [19021] [DEBUG] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '833158280', ref. Lifetime '10', last sync at '1541673725' 10/11/2018 08:49:33 [19021] [DEBUG] SyncParameters->GetLatestSyncKey(): '{a84379ed-5fa2-4d92-9dfe-019db2be003f}1' 10/11/2018 08:49:33 [19021] [DEBUG] StateManager->loadHierarchyCache(): 'nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-hc-1' 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->GetState() read '2800' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-hc-1' 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-1' 10/11/2018 08:49:33 [19021] [DEBUG] HandlePing(): reference PolicyKey for PING: 833158280 10/11/2018 08:49:33 [19021] [DEBUG] HandlePing(): initialization data received 10/11/2018 08:49:33 [19021] [WBXML] I <Ping:LifeTime> 10/11/2018 08:49:33 [19021] [WBXML] I 720 10/11/2018 08:49:33 [19021] [WBXML] I </Ping:LifeTime> 10/11/2018 08:49:33 [19021] [WBXML] I <Ping:Folders> 10/11/2018 08:49:33 [19021] [WBXML] I <Ping:Folder> 10/11/2018 08:49:33 [19021] [WBXML] I <Ping:ServerEntryId> 10/11/2018 08:49:33 [19021] [WBXML] I U9586e 10/11/2018 08:49:33 [19021] [WBXML] I </Ping:ServerEntryId> 10/11/2018 08:49:33 [19021] [WBXML] I <Ping:FolderType> 10/11/2018 08:49:33 [19021] [WBXML] I Tasks 10/11/2018 08:49:33 [19021] [WBXML] I </Ping:FolderType> 10/11/2018 08:49:33 [19021] [WBXML] I </Ping:Folder> 10/11/2018 08:49:33 [19021] [DEBUG] HandlePing(): using saved sync state for 'Tasks' id 'U9586e' 10/11/2018 08:49:33 [19021] [WBXML] I </Ping:Folders> 10/11/2018 08:49:33 [19021] [WBXML] I </Ping:Ping> 10/11/2018 08:49:33 [19021] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 08:49:33 [19021] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:49:33 [19021] [DEBUG] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false 10/11/2018 08:49:33 [19021] [DEBUG] PingTracking(): Initialized mutexid Resource id #79 and memid Resource id #80. 10/11/2018 08:49:33 [19021] [DEBUG] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2' 10/11/2018 08:49:33 [19021] [DEBUG] Announce process as PUSH connection 10/11/2018 08:49:33 [19021] [ INFO] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 720 seconds) 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->HasChangesSink(): created - HierarchyHash: 94ed1ea95fc21618ea602b51250f8bc2 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->adviseStoreToSink(): advised store 'Resource id #15' 10/11/2018 08:49:33 [19021] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->ChangesSinkInitialize(): folderid '56cabf443b954d0c8caedab84208fdf02f0000000000' 10/11/2018 08:49:33 [19021] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 08:49:33 [19021] [DEBUG] SyncParameters->IsExporterRunRequired(): false - current: 1541836166/1/0/30 - saved: 1541836166/1/0/30 - expiring: 2018-12-11 00:47:15 10/11/2018 08:49:33 [19021] [DEBUG] refpolkey:'833158280', sent polkey:'833158280' 10/11/2018 08:49:33 [19021] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11 10/11/2018 08:49:33 [19021] [DEBUG] ExportChangesICS->Config() initialized with state: 0x7f000000b2000000 10/11/2018 08:49:33 [19021] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 3 changes ready to sync for 'hierarchy'. 10/11/2018 08:49:33 [19021] [DEBUG] MAPIProvider->GetStoreProps(): Getting store properties. 10/11/2018 08:49:33 [19021] [DEBUG] MAPIProvider->GetFolder(): folder 'Suggested Contacts' should not be synchronized 10/11/2018 08:49:33 [19021] [DEBUG] MAPIProvider->getInboxProps(): Getting inbox properties. 10/11/2018 08:49:33 [19021] [DEBUG] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant. 10/11/2018 08:49:33 [19021] [DEBUG] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Tasks' will not be sent as modification is not relevant.
Outlook shows:
-
Outlook 2003, Step 2 (mark to-do done on Nine)
10/11/2018 08:51:51 [19121] [DEBUG] -------- Start 10/11/2018 08:51:51 [19121] [DEBUG] cmd='Sync' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 08:51:51 [19121] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 08:51:51 [19121] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 08:51:51 [19121] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::CommandNeedsProvisioning(0): true 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 08:51:51 [19121] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 08:51:51 [19121] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 08:51:51 [19121] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::HierarchyCommand(0): false 10/11/2018 08:51:51 [19121] [DEBUG] DeviceManager->ProvisioningRequired('833158280') saved device key '833158280': false 10/11/2018 08:51:51 [19121] [DEBUG] DeviceManager->getPolicyName(): determined policy name: 'default' 10/11/2018 08:51:51 [19121] [DEBUG] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::CommandNeedsAuthentication(0): true 10/11/2018 08:51:51 [19121] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 08:51:51 [19121] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 08:51:51 [19121] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 08:51:51 [19121] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::CommandNeedsPlainInput(0): false 10/11/2018 08:51:51 [19121] [WBXML] I <Synchronize> 10/11/2018 08:51:51 [19121] [WBXML] I <Folders> 10/11/2018 08:51:51 [19121] [WBXML] I <Folder> 10/11/2018 08:51:51 [19121] [WBXML] I <SyncKey> 10/11/2018 08:51:51 [19121] [WBXML] I {f05e74b0-98c9-442c-92f4-c96395f41858}116 10/11/2018 08:51:51 [19121] [WBXML] I </SyncKey> 10/11/2018 08:51:51 [19121] [WBXML] I <FolderId> 10/11/2018 08:51:51 [19121] [WBXML] I U9586e 10/11/2018 08:51:51 [19121] [WBXML] I </FolderId> 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->GetState() read '1016' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:51:51 [19121] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:51:51 [19121] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:51:51 [19121] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541836167' 10/11/2018 08:51:51 [19121] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541836167' 10/11/2018 08:51:51 [19121] [WBXML] I <DeletesAsMoves> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </DeletesAsMoves> 10/11/2018 08:51:51 [19121] [WBXML] I <GetChanges> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </GetChanges> 10/11/2018 08:51:51 [19121] [WBXML] I <WindowSize> 10/11/2018 08:51:51 [19121] [WBXML] I 5 10/11/2018 08:51:51 [19121] [WBXML] I </WindowSize> 10/11/2018 08:51:51 [19121] [WBXML] I <Options> 10/11/2018 08:51:51 [19121] [WBXML] I <FilterType> 10/11/2018 08:51:51 [19121] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </FilterType> 10/11/2018 08:51:51 [19121] [WBXML] I <Conflict> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </Conflict> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:BodyPreference> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Type> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Type> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:AllOrNone> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:AllOrNone> 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:BodyPreference> 10/11/2018 08:51:51 [19121] [WBXML] I </Options> 10/11/2018 08:51:51 [19121] [WBXML] I <Perform> 10/11/2018 08:51:51 [19121] [WBXML] I <Add> 10/11/2018 08:51:51 [19121] [WBXML] I <ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] I 4547 10/11/2018 08:51:51 [19121] [WBXML] I </ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] I <Data> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Body> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Type> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Type> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Data> 10/11/2018 08:51:51 [19121] [WBXML] I 10/11/2018 08:51:51 [19121] [DEBUG] StringStreamWrapper::stream_open(): initialized stream length: 1 - HTML-safe-truncate: false 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Data> 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Body> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Subject> 10/11/2018 08:51:51 [19121] [WBXML] I OL2003 daily recurring 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Subject> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Importance> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Importance> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:UtcDueDate> 10/11/2018 08:51:51 [19121] [WBXML] I 2018-11-09T23:00:00.000Z 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:UtcDueDate> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:DueDate> 10/11/2018 08:51:51 [19121] [WBXML] I 2018-11-10T00:00:00.000Z 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:DueDate> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Recurrence> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Regenerate> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Regenerate> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:DeadOccur> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:DeadOccur> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Type> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Type> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Interval> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Interval> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:FirstDayOfWeek> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:FirstDayOfWeek> 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Recurrence> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Complete> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Complete> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:DateCompleted> 10/11/2018 08:51:51 [19121] [WBXML] I 2018-11-10T00:00:00.000Z 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:DateCompleted> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Sensitivity> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Sensitivity> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:ReminderSet> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:ReminderSet> 10/11/2018 08:51:51 [19121] [WBXML] I </Data> 10/11/2018 08:51:51 [19121] [DEBUG] Sync->getImporter(): initialize importer 10/11/2018 08:51:51 [19121] [DEBUG] Sync->loadStates(): loading states for folder 'U9586e' 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-115' 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-116' 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fs-113' 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:51:51 [19121] [DEBUG] BackendKopano->GetImporter() folderid: '56cabf443b954d0c8caedab84208fdf02f0000000000' 10/11/2018 08:51:51 [19121] [DEBUG] ImportChangesICS->Config(): initializing importer with state: 0x8000000088020000 10/11/2018 08:51:51 [19121] [DEBUG] ImportChangesICS->LoadConflicts(): will be loaded later if necessary 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f05e74b0-98c9-442c-92f4-c96395f41858 counter: 116 10/11/2018 08:51:51 [19121] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 08:51:51 [19121] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2) 10/11/2018 08:51:51 [19121] [DEBUG] Sync->importMessage(): message imported 10/11/2018 08:51:51 [19121] [WBXML] I </Add> 10/11/2018 08:51:51 [19121] [WBXML] I <Add> 10/11/2018 08:51:51 [19121] [WBXML] I <ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] I 4548 10/11/2018 08:51:51 [19121] [WBXML] I </ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] I <Data> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Body> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Type> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Type> 10/11/2018 08:51:51 [19121] [WBXML] I <AirSyncBase:Data> 10/11/2018 08:51:51 [19121] [WBXML] I 10/11/2018 08:51:51 [19121] [DEBUG] StringStreamWrapper::stream_open(): initialized stream length: 1 - HTML-safe-truncate: false 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Data> 10/11/2018 08:51:51 [19121] [WBXML] I </AirSyncBase:Body> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Subject> 10/11/2018 08:51:51 [19121] [WBXML] I OL2003 daily recurring 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Subject> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Importance> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Importance> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:UtcDueDate> 10/11/2018 08:51:51 [19121] [WBXML] I 2018-11-10T23:00:00.000Z 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:UtcDueDate> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:DueDate> 10/11/2018 08:51:51 [19121] [WBXML] I 2018-11-11T00:00:00.000Z 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:DueDate> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Recurrence> 10/11/2018 08:51:51 [19021] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:51:51 [19021] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e', but it is not relevant 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Regenerate> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Regenerate> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:DeadOccur> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:DeadOccur> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Type> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Type> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Interval> 10/11/2018 08:51:51 [19121] [WBXML] I 1 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Interval> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:FirstDayOfWeek> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:FirstDayOfWeek> 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Recurrence> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Complete> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Complete> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:Sensitivity> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:Sensitivity> 10/11/2018 08:51:51 [19121] [WBXML] I <POOMTASKS:ReminderSet> 10/11/2018 08:51:51 [19121] [WBXML] I 0 10/11/2018 08:51:51 [19121] [WBXML] I </POOMTASKS:ReminderSet> 10/11/2018 08:51:51 [19121] [WBXML] I </Data> 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f05e74b0-98c9-442c-92f4-c96395f41858 counter: 116 10/11/2018 08:51:51 [19121] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 08:51:51 [19121] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2) 10/11/2018 08:51:51 [19021] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:51:51 [19021] [DEBUG] KopanoChangesWrapper::GetWrapper(): Found existing notification check exporter. Reinitializing. 10/11/2018 08:51:51 [19121] [DEBUG] Sync->importMessage(): message imported 10/11/2018 08:51:51 [19121] [WBXML] I </Add> 10/11/2018 08:51:51 [19121] [WBXML] I <Remove> 10/11/2018 08:51:51 [19021] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e', but it is not relevant 10/11/2018 08:51:51 [19121] [WBXML] I <ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] I U9586e:56cabf443b954d0c8caedab84208fdf0800100000000 10/11/2018 08:51:51 [19121] [WBXML] I </ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] I </Remove> 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f05e74b0-98c9-442c-92f4-c96395f41858 counter: 116 10/11/2018 08:51:51 [19121] [DEBUG] Got waste basket with id '56cabf443b954d0c8caedab84208fdf0280000000000' 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf0280000000000'): 'false' 10/11/2018 08:51:51 [19121] [DEBUG] KopanoBackend->GetMAPIStoreForFolderId('', '56cabf443b954d0c8caedab84208fdf0280000000000'): no store specified, returning default store 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf0280000000000'): 'false' 10/11/2018 08:51:51 [19121] [DEBUG] KopanoBackend->GetMAPIStoreForFolderId('', '56cabf443b954d0c8caedab84208fdf0280000000000'): no store specified, returning default store 10/11/2018 08:51:51 [19121] [DEBUG] Sync->importMessage(): message imported 10/11/2018 08:51:51 [19121] [WBXML] I </Perform> 10/11/2018 08:51:51 [19121] [ INFO] Processed '3' incoming changes 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fs-116' 10/11/2018 08:51:51 [19121] [WBXML] I </Folder> 10/11/2018 08:51:51 [19121] [WBXML] I </Folders> 10/11/2018 08:51:51 [19121] [WBXML] I </Synchronize> 10/11/2018 08:51:51 [19121] [DEBUG] HandleSync(): Start Output 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:51:51 [19021] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:51:51 [19021] [DEBUG] KopanoChangesWrapper::GetWrapper(): Found existing notification check exporter. Reinitializing. 10/11/2018 08:51:51 [19021] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 08:51:51 [19021] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e' 10/11/2018 08:51:51 [19021] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 08:51:51 [19021] [WBXML] O <Ping:Ping> 10/11/2018 08:51:51 [19021] [WBXML] O <Ping:Status> 10/11/2018 08:51:51 [19121] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 08:51:51 [19121] [DEBUG] SyncParameters->IsExporterRunRequired(): true - current: 1541836311/2/0/31 - saved: 1541836166/1/0/30 - expiring: 2018-12-11 00:47:15 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:51:51 [19021] [WBXML] O 2 10/11/2018 08:51:51 [19021] [WBXML] O </Ping:Status> 10/11/2018 08:51:51 [19021] [WBXML] O <Ping:Folders> 10/11/2018 08:51:51 [19021] [WBXML] O <Ping:Folder> 10/11/2018 08:51:51 [19021] [WBXML] O U9586e 10/11/2018 08:51:51 [19021] [WBXML] O </Ping:Folder> 10/11/2018 08:51:51 [19021] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 2 10/11/2018 08:51:51 [19021] [WBXML] O </Ping:Folders> 10/11/2018 08:51:51 [19021] [WBXML] O </Ping:Ping> 10/11/2018 08:51:51 [19021] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 08:51:51 [19121] [DEBUG] ExportChangesICS->Config() initialized with state: 0x8000000088020000 10/11/2018 08:51:51 [19021] [WBXML] WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk1ODZlAAEBAQ== 10/11/2018 08:51:51 [19021] [WBXML] WBXML-IN : AwFqAAANRUgDNzIwAAFJSksDVTk1ODZlAAFMA1Rhc2tzAAEBAQE= 10/11/2018 08:51:51 [19021] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 08:51:51 [19121] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 08:51:51 [19021] [ INFO] cmd='Ping' memory='2.04 MiB/2.00 MiB' time='138.92s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='138s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 1 10/11/2018 08:51:51 [19021] [DEBUG] -------- End 10/11/2018 08:51:51 [19121] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 08:51:51 [19121] [DEBUG] Folder type: Tasks 10/11/2018 08:51:51 [19121] [WBXML] O <Synchronize> 10/11/2018 08:51:51 [19121] [WBXML] O <Folders> 10/11/2018 08:51:51 [19121] [WBXML] O <Folder> 10/11/2018 08:51:51 [19121] [WBXML] O <SyncKey> 10/11/2018 08:51:51 [19121] [WBXML] O {f05e74b0-98c9-442c-92f4-c96395f41858}117 10/11/2018 08:51:51 [19121] [WBXML] O </SyncKey> 10/11/2018 08:51:51 [19121] [WBXML] O <FolderId> 10/11/2018 08:51:51 [19121] [WBXML] O U9586e 10/11/2018 08:51:51 [19121] [WBXML] O </FolderId> 10/11/2018 08:51:51 [19121] [WBXML] O <Status> 10/11/2018 08:51:51 [19121] [WBXML] O 1 10/11/2018 08:51:51 [19121] [WBXML] O </Status> 10/11/2018 08:51:51 [19121] [WBXML] O <Replies> 10/11/2018 08:51:51 [19121] [WBXML] O <Add> 10/11/2018 08:51:51 [19121] [WBXML] O <ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O 4547 10/11/2018 08:51:51 [19121] [WBXML] O </ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O <ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0810100000000 10/11/2018 08:51:51 [19121] [WBXML] O </ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O <Status> 10/11/2018 08:51:51 [19121] [WBXML] O 1 10/11/2018 08:51:51 [19121] [WBXML] O </Status> 10/11/2018 08:51:51 [19121] [WBXML] O </Add> 10/11/2018 08:51:51 [19121] [WBXML] O <Add> 10/11/2018 08:51:51 [19121] [WBXML] O <ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O 4548 10/11/2018 08:51:51 [19121] [WBXML] O </ClientEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O <ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0820100000000 10/11/2018 08:51:51 [19121] [WBXML] O </ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O <Status> 10/11/2018 08:51:51 [19121] [WBXML] O 1 10/11/2018 08:51:51 [19121] [WBXML] O </Status> 10/11/2018 08:51:51 [19121] [WBXML] O </Add> 10/11/2018 08:51:51 [19121] [WBXML] O </Replies> 10/11/2018 08:51:51 [19121] [DEBUG] LoopDetection->Detect(): folderid:'U9586e' uuid:'f05e74b0-98c9-442c-92f4-c96395f41858' counter:'116' max:'5' queued:'1' 10/11/2018 08:51:51 [19121] [DEBUG] PHPWrapper->ImportMessageDeletion(): Received 1 remove requests from ICS 10/11/2018 08:51:51 [19121] [WBXML] O <Perform> 10/11/2018 08:51:51 [19121] [WBXML] O <Remove> 10/11/2018 08:51:51 [19121] [WBXML] O <ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0800100000000 10/11/2018 08:51:51 [19121] [WBXML] O </ServerEntryId> 10/11/2018 08:51:51 [19121] [WBXML] O </Remove> 10/11/2018 08:51:51 [19121] [DEBUG] PHPWrapper->ImportMessageDeletion(): delete for :'U9586e:56cabf443b954d0c8caedab84208fdf0800100000000' 10/11/2018 08:51:51 [19121] [WBXML] O </Perform> 10/11/2018 08:51:51 [19121] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:51:51 [19121] [DEBUG] Sync()->setFolderStat() on U9586e: 1541836311/2/0/31 expiring 2018-12-10 21:46:44 10/11/2018 08:51:51 [19121] [WBXML] O </Folder> 10/11/2018 08:51:51 [19121] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-117' 10/11/2018 08:51:51 [19121] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 08:51:52 [19121] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:51:52 [19121] [WBXML] O </Folders> 10/11/2018 08:51:52 [19121] [WBXML] O </Synchronize> 10/11/2018 08:51:52 [19121] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 08:51:52 [19121] [WBXML] WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTcAAVIDVTk1ODZlAAFOAzEAAUZHTAM0NTQ3AAFNA1U5NTg2ZTo1NmNhYmY0NDNiOTU0ZDBjOGNhZWRhYjg0MjA4ZmRmMDgxMDEwMDAwMDAwMAABTgMxAAEBR0wDNDU0OAABTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4MjAxMDAwMDAwMDAAAU4DMQABAQFWSU0DVTk1ODZlOjU2Y2FiZjQ0M2I5NTRkMGM4Y2FlZGFiODQyMDhmZGYwODAwMTAwMDAwMDAwAAEBAQEBAQ== 10/11/2018 08:51:52 [19121] [WBXML] WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTYAAVIDVTk1ODZlAAFeAzEAAVMDMQABVQM1AAFXWAMwAAFbAzEAAQARRUYDMQABSAMwAAEBAQAAVkdMAzQ1NDcAAV0AEUpGAzEAAUsDIAABAQAJYANPTDIwMDMgZGFpbHkgcmVjdXJyaW5nAAFOAzEAAU0DMjAxOC0xMS0wOVQyMzowMDowMC4wMDBaAAFMAzIwMTgtMTEtMTBUMDA6MDA6MDAuMDAwWgABT1kDMAABWgMxAAFQAzAAAVQDMQABZgMwAAEBSgMxAAFLAzIwMTgtMTEtMTBUMDA6MDA6MDAuMDAwWgABXQMwAAFbAzAAAQEBAABHTAM0NTQ4AAFdABFKRgMxAAFLAyAAAQEACWADT0wyMDAzIGRhaWx5IHJlY3VycmluZwABTgMxAAFNAzIwMTgtMTEtMTBUMjM6MDA6MDAuMDAwWgABTAMyMDE4LTExLTExVDAwOjAwOjAwLjAwMFoAAU9ZAzAAAVoDMAABUAMwAAFUAzEAAWYDMAABAUoDMAABXQMwAAFbAzAAAQEBAABJTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4MDAxMDAwMDAwMDAAAQEBAQEB 10/11/2018 08:51:52 [19121] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 08:51:52 [19121] [ INFO] cmd='Sync' memory='2.01 MiB/2.00 MiB' time='0.17s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='0s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 08:51:52 [19121] [DEBUG] -------- End
z-push-error.log reads
10/11/2018 08:51:51 [19121] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 08:51:51 [19121] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2) 10/11/2018 08:51:51 [19121] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 08:51:51 [19121] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2)
Outlook shows:
-
Outlook 2003, Step 3 (mark to-do done on Outlook, giving weird due-date)
10/11/2018 08:55:03 [19025] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:55:03 [19025] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 08:55:03 [19025] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e' 10/11/2018 08:55:03 [19025] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 08:55:03 [19025] [WBXML] O <Ping:Ping> 10/11/2018 08:55:03 [19025] [WBXML] O <Ping:Status> 10/11/2018 08:55:03 [19025] [WBXML] O 2 10/11/2018 08:55:03 [19025] [WBXML] O </Ping:Status> 10/11/2018 08:55:03 [19025] [WBXML] O <Ping:Folders> 10/11/2018 08:55:03 [19025] [WBXML] O <Ping:Folder> 10/11/2018 08:55:03 [19025] [WBXML] O U9586e 10/11/2018 08:55:03 [19025] [WBXML] O </Ping:Folder> 10/11/2018 08:55:03 [19025] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 2 10/11/2018 08:55:03 [19025] [WBXML] O </Ping:Folders> 10/11/2018 08:55:03 [19025] [WBXML] O </Ping:Ping> 10/11/2018 08:55:03 [19025] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 08:55:03 [19025] [WBXML] WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk1ODZlAAEBAQ== 10/11/2018 08:55:03 [19025] [WBXML] WBXML-IN : AwFqAAANRUgDNzIwAAFJSksDVTk1ODZlAAFMA1Rhc2tzAAEBAQE= 10/11/2018 08:55:03 [19025] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 08:55:03 [19025] [ INFO] cmd='Ping' memory='2.04 MiB/4.00 MiB' time='174.14s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='174s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 08:55:03 [19025] [DEBUG] -------- End 10/11/2018 08:55:05 [19019] [DEBUG] -------- Start 10/11/2018 08:55:05 [19019] [DEBUG] cmd='Sync' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 08:55:05 [19019] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 08:55:05 [19019] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 08:55:05 [19019] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::CommandNeedsProvisioning(0): true 10/11/2018 08:55:05 [19019] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 08:55:05 [19019] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 08:55:05 [19019] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 08:55:05 [19019] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 08:55:05 [19019] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 08:55:05 [19019] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::HierarchyCommand(0): false 10/11/2018 08:55:05 [19019] [DEBUG] DeviceManager->ProvisioningRequired('833158280') saved device key '833158280': false 10/11/2018 08:55:05 [19019] [DEBUG] DeviceManager->getPolicyName(): determined policy name: 'default' 10/11/2018 08:55:05 [19019] [DEBUG] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::CommandNeedsAuthentication(0): true 10/11/2018 08:55:05 [19019] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 08:55:05 [19019] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 08:55:05 [19019] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 08:55:05 [19019] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::CommandNeedsPlainInput(0): false 10/11/2018 08:55:05 [19019] [WBXML] I <Synchronize> 10/11/2018 08:55:05 [19019] [WBXML] I <Folders> 10/11/2018 08:55:05 [19019] [WBXML] I <Folder> 10/11/2018 08:55:05 [19019] [WBXML] I <SyncKey> 10/11/2018 08:55:05 [19019] [WBXML] I {f05e74b0-98c9-442c-92f4-c96395f41858}117 10/11/2018 08:55:05 [19019] [WBXML] I </SyncKey> 10/11/2018 08:55:05 [19019] [WBXML] I <FolderId> 10/11/2018 08:55:05 [19019] [WBXML] I U9586e 10/11/2018 08:55:05 [19019] [WBXML] I </FolderId> 10/11/2018 08:55:05 [19019] [DEBUG] FileStateMachine->GetState() read '1016' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:55:05 [19019] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:55:05 [19019] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 08:55:05 [19019] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541836312' 10/11/2018 08:55:05 [19019] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541836312' 10/11/2018 08:55:05 [19019] [WBXML] I <DeletesAsMoves> 10/11/2018 08:55:05 [19019] [WBXML] I 1 10/11/2018 08:55:05 [19019] [WBXML] I </DeletesAsMoves> 10/11/2018 08:55:05 [19019] [WBXML] I <GetChanges> 10/11/2018 08:55:05 [19019] [WBXML] I 1 10/11/2018 08:55:05 [19019] [WBXML] I </GetChanges> 10/11/2018 08:55:05 [19019] [WBXML] I <WindowSize> 10/11/2018 08:55:05 [19019] [WBXML] I 5 10/11/2018 08:55:05 [19019] [WBXML] I </WindowSize> 10/11/2018 08:55:05 [19019] [WBXML] I <Options> 10/11/2018 08:55:05 [19019] [WBXML] I <FilterType> 10/11/2018 08:55:05 [19019] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:55:05 [19019] [WBXML] I 0 10/11/2018 08:55:05 [19019] [WBXML] I </FilterType> 10/11/2018 08:55:05 [19019] [WBXML] I <Conflict> 10/11/2018 08:55:05 [19019] [WBXML] I 1 10/11/2018 08:55:05 [19019] [WBXML] I </Conflict> 10/11/2018 08:55:05 [19019] [WBXML] I <AirSyncBase:BodyPreference> 10/11/2018 08:55:05 [19019] [WBXML] I <AirSyncBase:Type> 10/11/2018 08:55:05 [19019] [WBXML] I 1 10/11/2018 08:55:05 [19019] [WBXML] I </AirSyncBase:Type> 10/11/2018 08:55:05 [19019] [WBXML] I <AirSyncBase:AllOrNone> 10/11/2018 08:55:05 [19019] [WBXML] I 0 10/11/2018 08:55:05 [19019] [WBXML] I </AirSyncBase:AllOrNone> 10/11/2018 08:55:05 [19019] [WBXML] I </AirSyncBase:BodyPreference> 10/11/2018 08:55:05 [19019] [WBXML] I </Options> 10/11/2018 08:55:05 [19019] [WBXML] I </Folder> 10/11/2018 08:55:05 [19019] [WBXML] I </Folders> 10/11/2018 08:55:05 [19019] [WBXML] I </Synchronize> 10/11/2018 08:55:05 [19019] [DEBUG] HandleSync(): Start Output 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:55:05 [19019] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 08:55:05 [19019] [DEBUG] SyncParameters->IsExporterRunRequired(): true - current: 1541836503/2/0/31 - saved: 1541836311/2/0/31 - expiring: 2018-12-11 08:17:03 10/11/2018 08:55:05 [19019] [DEBUG] Sync->loadStates(): loading states for folder 'U9586e' 10/11/2018 08:55:05 [19019] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-117' 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:55:05 [19019] [DEBUG] ExportChangesICS->Config() initialized with state: 0x800000008c020000 10/11/2018 08:55:05 [19019] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 08:55:05 [19019] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 1 10/11/2018 08:55:05 [19019] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 08:55:05 [19019] [DEBUG] Folder type: Tasks 10/11/2018 08:55:05 [19019] [WBXML] O <Synchronize> 10/11/2018 08:55:05 [19019] [WBXML] O <Folders> 10/11/2018 08:55:05 [19019] [WBXML] O <Folder> 10/11/2018 08:55:05 [19019] [WBXML] O <SyncKey> 10/11/2018 08:55:05 [19019] [WBXML] O {f05e74b0-98c9-442c-92f4-c96395f41858}118 10/11/2018 08:55:05 [19019] [WBXML] O </SyncKey> 10/11/2018 08:55:05 [19019] [WBXML] O <FolderId> 10/11/2018 08:55:05 [19019] [WBXML] O U9586e 10/11/2018 08:55:05 [19019] [WBXML] O </FolderId> 10/11/2018 08:55:05 [19019] [WBXML] O <Status> 10/11/2018 08:55:05 [19019] [WBXML] O 1 10/11/2018 08:55:05 [19019] [WBXML] O </Status> 10/11/2018 08:55:05 [19019] [DEBUG] LoopDetection->Detect(): folderid:'U9586e' uuid:'f05e74b0-98c9-442c-92f4-c96395f41858' counter:'117' max:'5' queued:'1' 10/11/2018 08:55:05 [19019] [DEBUG] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: '56cabf443b954d0c8caedab84208fdf0820100000000', parentsourcekey: '56cabf443b954d0c8caedab84208fdf02f0000000000', entryid: '000000009c956e50afc34d66bd0faad6901b012401000000050000007247a6e0d6374519b5df0b244a662a6b00000000' 10/11/2018 08:55:05 [19019] [DEBUG] BodyPreference types: 1 10/11/2018 08:55:05 [19019] [DEBUG] GetBodyPreferenceBestMatch: 1 10/11/2018 08:55:05 [19019] [DEBUG] bpo: truncation size:'0', allornone:'0', preview:'0' 10/11/2018 08:55:05 [19019] [DEBUG] MAPIStreamWrapper::stream_open(): initialized mapistream: Resource id #123 - streamlength: 1 - HTML-safe-truncate: false 10/11/2018 08:55:05 [19019] [WARN] /usr/share/z-push/backend/kopano/mapiprovider.php:484 Invalid argument supplied for foreach() (2) 10/11/2018 08:55:05 [19019] [WARN] /usr/share/z-push/backend/kopano/mapiprovider.php:544 Invalid argument supplied for foreach() (2) 10/11/2018 08:55:05 [19019] [DEBUG] SyncObject->Check(): Fixed object from type SyncTaskRecurrence: parameter 'type' is set to 0 10/11/2018 08:55:05 [19019] [WBXML] O <Perform> 10/11/2018 08:55:05 [19019] [WBXML] O <Modify> 10/11/2018 08:55:05 [19019] [WBXML] O <ServerEntryId> 10/11/2018 08:55:05 [19019] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0820100000000 10/11/2018 08:55:05 [19019] [WBXML] O </ServerEntryId> 10/11/2018 08:55:05 [19019] [WBXML] O <Data> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:Complete> 10/11/2018 08:55:05 [19019] [WBXML] O 1 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:Complete> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:DateCompleted> 10/11/2018 08:55:05 [19019] [WBXML] O 2018-11-09T23:00:00.000Z 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:DateCompleted> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:DueDate> 10/11/2018 08:55:05 [19019] [WBXML] O 1601-01-01T00:00:00.000Z <------ weird 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:DueDate> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:UtcDueDate> 10/11/2018 08:55:05 [19019] [WBXML] O 8907-12-05T17:42:00.000Z <------ weird 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:UtcDueDate> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:Importance> 10/11/2018 08:55:05 [19019] [WBXML] O 1 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:Importance> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:Recurrence> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:Type> 10/11/2018 08:55:05 [19019] [WBXML] O 0 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:Type> 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:Recurrence> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:ReminderSet> 10/11/2018 08:55:05 [19019] [WBXML] O 0 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:ReminderSet> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:Sensitivity> 10/11/2018 08:55:05 [19019] [WBXML] O 0 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:Sensitivity> 10/11/2018 08:55:05 [19019] [WBXML] O <POOMTASKS:Subject> 10/11/2018 08:55:05 [19019] [WBXML] O OL2003 daily recurring 10/11/2018 08:55:05 [19019] [WBXML] O </POOMTASKS:Subject> 10/11/2018 08:55:05 [19019] [WBXML] O <AirSyncBase:Body> 10/11/2018 08:55:05 [19019] [WBXML] O <AirSyncBase:Type> 10/11/2018 08:55:05 [19019] [WBXML] O 1 10/11/2018 08:55:05 [19019] [WBXML] O </AirSyncBase:Type> 10/11/2018 08:55:05 [19019] [WBXML] O <AirSyncBase:EstimatedDataSize> 10/11/2018 08:55:05 [19019] [WBXML] O 1 10/11/2018 08:55:05 [19019] [WBXML] O </AirSyncBase:EstimatedDataSize> 10/11/2018 08:55:05 [19019] [WBXML] O <AirSyncBase:Data> 10/11/2018 08:55:05 [19019] [WBXML] O <<< written 1 of 1 bytes of plain data >>> 10/11/2018 08:55:05 [19019] [WBXML] O </AirSyncBase:Data> 10/11/2018 08:55:05 [19019] [WBXML] O </AirSyncBase:Body> 10/11/2018 08:55:05 [19019] [WBXML] O </Data> 10/11/2018 08:55:05 [19019] [WBXML] O </Modify> 10/11/2018 08:55:05 [19019] [DEBUG] PHPWrapper->ImportMessageChange(): change for: 'U9586e:56cabf443b954d0c8caedab84208fdf0820100000000' 10/11/2018 08:55:05 [19019] [WBXML] O </Perform> 10/11/2018 08:55:05 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:55:05 [19019] [DEBUG] Sync()->setFolderStat() on U9586e: 1541836503/2/0/31 expiring 2018-12-11 05:11:40 10/11/2018 08:55:05 [19019] [WBXML] O </Folder> 10/11/2018 08:55:05 [19019] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-118' 10/11/2018 08:55:05 [19019] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 08:55:05 [19019] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:55:05 [19019] [WBXML] O </Folders> 10/11/2018 08:55:05 [19019] [WBXML] O </Synchronize> 10/11/2018 08:55:05 [19019] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 08:55:05 [19019] [WBXML] WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTgAAVIDVTk1ODZlAAFOAzEAAVZITQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4MjAxMDAwMDAwMDAAAV0ACUoDMQABSwMyMDE4LTExLTA5VDIzOjAwOjAwLjAwMFoAAUwDMTYwMS0wMS0wMVQwMDowMDowMC4wMDBaAAFNAzg5MDctMTItMDVUMTc6NDI6MDAuMDAwWgABTgMxAAFPUAMwAAEBWwMwAAFdAzAAAWADT0wyMDAzIGRhaWx5IHJlY3VycmluZwABABFKRgMxAAFMAzEAAUsDIAABAQEBAQEBAQ== 10/11/2018 08:55:05 [19019] [WBXML] WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTcAAVIDVTk1ODZlAAFeAzEAAVMDMQABVQM1AAFXWAMwAAFbAzEAAQARRUYDMQABSAMwAAEBAQEBAQ== 10/11/2018 08:55:05 [19019] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 08:55:05 [19019] [ INFO] cmd='Sync' memory='2.02 MiB/2.00 MiB' time='0.05s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='0s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 08:55:05 [19019] [DEBUG] -------- End 10/11/2018 08:55:13 [19016] [DEBUG] -------- Start 10/11/2018 08:55:13 [19016] [DEBUG] cmd='Ping' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 08:55:13 [19016] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 08:55:13 [19016] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 08:55:13 [19016] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::CommandNeedsProvisioning(18): false 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::CommandNeedsAuthentication(18): true 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 08:55:13 [19016] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 08:55:13 [19016] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 08:55:13 [19016] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 08:55:13 [19016] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 08:55:13 [19016] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::HierarchyCommand(18): false 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 08:55:13 [19016] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::CommandNeedsPlainInput(18): false 10/11/2018 08:55:13 [19016] [WBXML] I <Ping:Ping> 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->GetState() read '1045' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:55:13 [19016] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:55:13 [19016] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541836505' 10/11/2018 08:55:13 [19016] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541836505' 10/11/2018 08:55:13 [19016] [DEBUG] SyncParameters->GetLatestSyncKey(): '{f05e74b0-98c9-442c-92f4-c96395f41858}118' 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-118' 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-fd' 10/11/2018 08:55:13 [19016] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 08:55:13 [19016] [DEBUG] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '833158280', ref. Lifetime '10', last sync at '1541673725' 10/11/2018 08:55:13 [19016] [DEBUG] SyncParameters->GetLatestSyncKey(): '{a84379ed-5fa2-4d92-9dfe-019db2be003f}1' 10/11/2018 08:55:13 [19016] [DEBUG] StateManager->loadHierarchyCache(): 'nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-hc-1' 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->GetState() read '2800' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-hc-1' 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-1' 10/11/2018 08:55:13 [19016] [DEBUG] HandlePing(): reference PolicyKey for PING: 833158280 10/11/2018 08:55:13 [19016] [DEBUG] HandlePing(): initialization data received 10/11/2018 08:55:13 [19016] [WBXML] I <Ping:LifeTime> 10/11/2018 08:55:13 [19016] [WBXML] I 720 10/11/2018 08:55:13 [19016] [WBXML] I </Ping:LifeTime> 10/11/2018 08:55:13 [19016] [WBXML] I <Ping:Folders> 10/11/2018 08:55:13 [19016] [WBXML] I <Ping:Folder> 10/11/2018 08:55:13 [19016] [WBXML] I <Ping:ServerEntryId> 10/11/2018 08:55:13 [19016] [WBXML] I U9586e 10/11/2018 08:55:13 [19016] [WBXML] I </Ping:ServerEntryId> 10/11/2018 08:55:13 [19016] [WBXML] I <Ping:FolderType> 10/11/2018 08:55:13 [19016] [WBXML] I Tasks 10/11/2018 08:55:13 [19016] [WBXML] I </Ping:FolderType> 10/11/2018 08:55:13 [19016] [WBXML] I </Ping:Folder> 10/11/2018 08:55:13 [19016] [DEBUG] HandlePing(): using saved sync state for 'Tasks' id 'U9586e' 10/11/2018 08:55:13 [19016] [WBXML] I </Ping:Folders> 10/11/2018 08:55:13 [19016] [WBXML] I </Ping:Ping> 10/11/2018 08:55:13 [19016] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 08:55:13 [19016] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 08:55:13 [19016] [DEBUG] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false 10/11/2018 08:55:13 [19016] [DEBUG] PingTracking(): Initialized mutexid Resource id #79 and memid Resource id #80. 10/11/2018 08:55:13 [19016] [DEBUG] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2' 10/11/2018 08:55:13 [19016] [DEBUG] Announce process as PUSH connection 10/11/2018 08:55:13 [19016] [ INFO] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 720 seconds) 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->HasChangesSink(): created - HierarchyHash: 94ed1ea95fc21618ea602b51250f8bc2 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->adviseStoreToSink(): advised store 'Resource id #15' 10/11/2018 08:55:13 [19016] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->ChangesSinkInitialize(): folderid '56cabf443b954d0c8caedab84208fdf02f0000000000' 10/11/2018 08:55:13 [19016] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 08:55:13 [19016] [DEBUG] SyncParameters->IsExporterRunRequired(): false - current: 1541836503/2/0/31 - saved: 1541836503/2/0/31 - expiring: 2018-12-11 05:11:40 10/11/2018 08:55:13 [19016] [DEBUG] refpolkey:'833158280', sent polkey:'833158280' 10/11/2018 08:55:13 [19016] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11 10/11/2018 08:55:13 [19016] [DEBUG] ExportChangesICS->Config() initialized with state: 0x7f000000b2000000 10/11/2018 08:55:13 [19016] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 3 changes ready to sync for 'hierarchy'. 10/11/2018 08:55:13 [19016] [DEBUG] MAPIProvider->GetStoreProps(): Getting store properties. 10/11/2018 08:55:13 [19016] [DEBUG] MAPIProvider->GetFolder(): folder 'Suggested Contacts' should not be synchronized 10/11/2018 08:55:13 [19016] [DEBUG] MAPIProvider->getInboxProps(): Getting inbox properties. 10/11/2018 08:55:13 [19016] [DEBUG] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant. 10/11/2018 08:55:13 [19016] [DEBUG] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Tasks' will not be sent as modification is not relevant.
z-push-error.log has new lines:
10/11/2018 08:55:05 [19019] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapiprovider.php:484 Invalid argument supplied for foreach() (2) 10/11/2018 08:55:05 [19019] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapiprovider.php:544 Invalid argument supplied for foreach() (2)
Outlook shows:
-
Outlook 365, Step 1 (Create recurring to-do)
10/11/2018 09:19:27 [19025] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 09:19:27 [19025] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 09:19:27 [19025] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e' 10/11/2018 09:19:27 [19025] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 09:19:27 [19025] [WBXML] O <Ping:Ping> 10/11/2018 09:19:27 [19025] [WBXML] O <Ping:Status> 10/11/2018 09:19:27 [19025] [WBXML] O 2 10/11/2018 09:19:27 [19025] [WBXML] O </Ping:Status> 10/11/2018 09:19:27 [19025] [WBXML] O <Ping:Folders> 10/11/2018 09:19:27 [19025] [WBXML] O <Ping:Folder> 10/11/2018 09:19:27 [19025] [WBXML] O U9586e 10/11/2018 09:19:27 [19025] [WBXML] O </Ping:Folder> 10/11/2018 09:19:27 [19025] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 2 10/11/2018 09:19:27 [19025] [WBXML] O </Ping:Folders> 10/11/2018 09:19:27 [19025] [WBXML] O </Ping:Ping> 10/11/2018 09:19:27 [19025] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 09:19:27 [19025] [WBXML] WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk1ODZlAAEBAQ== 10/11/2018 09:19:27 [19025] [WBXML] WBXML-IN : AwFqAAANRUgDOTAwAAFJSksDVTk1ODZlAAFMA1Rhc2tzAAEBAQE= 10/11/2018 09:19:27 [19025] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 09:19:27 [19025] [ INFO] cmd='Ping' memory='2.04 MiB/2.00 MiB' time='415.18s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='415s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 09:19:27 [19025] [DEBUG] -------- End 10/11/2018 09:19:28 [19022] [DEBUG] -------- Start 10/11/2018 09:19:28 [19022] [DEBUG] cmd='Sync' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 09:19:28 [19022] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 09:19:28 [19022] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 09:19:28 [19022] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::CommandNeedsProvisioning(0): true 10/11/2018 09:19:28 [19022] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 09:19:28 [19022] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 09:19:28 [19022] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 09:19:28 [19022] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 09:19:28 [19022] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 09:19:28 [19022] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::HierarchyCommand(0): false 10/11/2018 09:19:28 [19022] [DEBUG] DeviceManager->ProvisioningRequired('833158280') saved device key '833158280': false 10/11/2018 09:19:28 [19022] [DEBUG] DeviceManager->getPolicyName(): determined policy name: 'default' 10/11/2018 09:19:28 [19022] [DEBUG] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::CommandNeedsAuthentication(0): true 10/11/2018 09:19:28 [19022] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 09:19:28 [19022] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 09:19:28 [19022] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 09:19:28 [19022] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::CommandNeedsPlainInput(0): false 10/11/2018 09:19:28 [19022] [WBXML] I <Synchronize> 10/11/2018 09:19:28 [19022] [WBXML] I <Folders> 10/11/2018 09:19:28 [19022] [WBXML] I <Folder> 10/11/2018 09:19:28 [19022] [WBXML] I <SyncKey> 10/11/2018 09:19:28 [19022] [WBXML] I {f05e74b0-98c9-442c-92f4-c96395f41858}119 10/11/2018 09:19:28 [19022] [WBXML] I </SyncKey> 10/11/2018 09:19:28 [19022] [WBXML] I <FolderId> 10/11/2018 09:19:28 [19022] [WBXML] I U9586e 10/11/2018 09:19:28 [19022] [WBXML] I </FolderId> 10/11/2018 09:19:28 [19022] [DEBUG] FileStateMachine->GetState() read '1016' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 09:19:28 [19022] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 09:19:28 [19022] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 09:19:28 [19022] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541836783' 10/11/2018 09:19:28 [19022] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541836783' 10/11/2018 09:19:28 [19022] [WBXML] I <DeletesAsMoves> 10/11/2018 09:19:28 [19022] [WBXML] I 1 10/11/2018 09:19:28 [19022] [WBXML] I </DeletesAsMoves> 10/11/2018 09:19:28 [19022] [WBXML] I <GetChanges> 10/11/2018 09:19:28 [19022] [WBXML] I 1 10/11/2018 09:19:28 [19022] [WBXML] I </GetChanges> 10/11/2018 09:19:28 [19022] [WBXML] I <WindowSize> 10/11/2018 09:19:28 [19022] [WBXML] I 5 10/11/2018 09:19:28 [19022] [WBXML] I </WindowSize> 10/11/2018 09:19:28 [19022] [WBXML] I <Options> 10/11/2018 09:19:28 [19022] [WBXML] I <FilterType> 10/11/2018 09:19:28 [19022] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 09:19:28 [19022] [WBXML] I 0 10/11/2018 09:19:28 [19022] [WBXML] I </FilterType> 10/11/2018 09:19:28 [19022] [WBXML] I <Conflict> 10/11/2018 09:19:28 [19022] [WBXML] I 1 10/11/2018 09:19:28 [19022] [WBXML] I </Conflict> 10/11/2018 09:19:28 [19022] [WBXML] I <AirSyncBase:BodyPreference> 10/11/2018 09:19:28 [19022] [WBXML] I <AirSyncBase:Type> 10/11/2018 09:19:28 [19022] [WBXML] I 1 10/11/2018 09:19:28 [19022] [WBXML] I </AirSyncBase:Type> 10/11/2018 09:19:28 [19022] [WBXML] I <AirSyncBase:AllOrNone> 10/11/2018 09:19:28 [19022] [WBXML] I 0 10/11/2018 09:19:28 [19022] [WBXML] I </AirSyncBase:AllOrNone> 10/11/2018 09:19:28 [19022] [WBXML] I </AirSyncBase:BodyPreference> 10/11/2018 09:19:28 [19022] [WBXML] I </Options> 10/11/2018 09:19:28 [19022] [WBXML] I </Folder> 10/11/2018 09:19:28 [19022] [WBXML] I </Folders> 10/11/2018 09:19:28 [19022] [WBXML] I </Synchronize> 10/11/2018 09:19:28 [19022] [DEBUG] HandleSync(): Start Output 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:19:28 [19022] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 09:19:28 [19022] [DEBUG] SyncParameters->IsExporterRunRequired(): true - current: 1541837967/1/0/31 - saved: 1541836869/0/0/31 - expiring: 2018-12-11 01:32:04 10/11/2018 09:19:28 [19022] [DEBUG] Sync->loadStates(): loading states for folder 'U9586e' 10/11/2018 09:19:28 [19022] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-119' 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:19:28 [19022] [DEBUG] ExportChangesICS->Config() initialized with state: 0x8000000091020000 10/11/2018 09:19:28 [19022] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 09:19:28 [19022] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 1 10/11/2018 09:19:28 [19022] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 09:19:28 [19022] [DEBUG] Folder type: Tasks 10/11/2018 09:19:28 [19022] [WBXML] O <Synchronize> 10/11/2018 09:19:28 [19022] [WBXML] O <Folders> 10/11/2018 09:19:28 [19022] [WBXML] O <Folder> 10/11/2018 09:19:28 [19022] [WBXML] O <SyncKey> 10/11/2018 09:19:28 [19022] [WBXML] O {f05e74b0-98c9-442c-92f4-c96395f41858}120 10/11/2018 09:19:28 [19022] [WBXML] O </SyncKey> 10/11/2018 09:19:28 [19022] [WBXML] O <FolderId> 10/11/2018 09:19:28 [19022] [WBXML] O U9586e 10/11/2018 09:19:28 [19022] [WBXML] O </FolderId> 10/11/2018 09:19:28 [19022] [WBXML] O <Status> 10/11/2018 09:19:28 [19022] [WBXML] O 1 10/11/2018 09:19:28 [19022] [WBXML] O </Status> 10/11/2018 09:19:28 [19022] [DEBUG] LoopDetection->Detect(): folderid:'U9586e' uuid:'f05e74b0-98c9-442c-92f4-c96395f41858' counter:'119' max:'5' queued:'1' 10/11/2018 09:19:28 [19022] [DEBUG] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: '56cabf443b954d0c8caedab84208fdf0860100000000', parentsourcekey: '56cabf443b954d0c8caedab84208fdf02f0000000000', entryid: '000000009c956e50afc34d66bd0faad6901b0124010000000500000008547beb675b0e44908015c8e68af6b800000000' 10/11/2018 09:19:28 [19022] [DEBUG] BodyPreference types: 1 10/11/2018 09:19:28 [19022] [DEBUG] GetBodyPreferenceBestMatch: 1 10/11/2018 09:19:28 [19022] [DEBUG] bpo: truncation size:'0', allornone:'0', preview:'0' 10/11/2018 09:19:28 [19022] [DEBUG] MAPIStreamWrapper::stream_open(): initialized mapistream: Resource id #124 - streamlength: 2 - HTML-safe-truncate: false 10/11/2018 09:19:28 [19022] [WBXML] O <Perform> 10/11/2018 09:19:28 [19022] [WBXML] O <Add> 10/11/2018 09:19:28 [19022] [WBXML] O <ServerEntryId> 10/11/2018 09:19:28 [19022] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0860100000000 10/11/2018 09:19:28 [19022] [WBXML] O </ServerEntryId> 10/11/2018 09:19:28 [19022] [WBXML] O <Data> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Complete> 10/11/2018 09:19:28 [19022] [WBXML] O 0 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Complete> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:DueDate> 10/11/2018 09:19:28 [19022] [WBXML] O 2018-11-10T00:00:00.000Z 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:DueDate> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:UtcDueDate> 10/11/2018 09:19:28 [19022] [WBXML] O 2018-11-09T23:00:00.000Z 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:UtcDueDate> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Importance> 10/11/2018 09:19:28 [19022] [WBXML] O 1 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Importance> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Recurrence> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Type> 10/11/2018 09:19:28 [19022] [WBXML] O 0 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Type> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Interval> 10/11/2018 09:19:28 [19022] [WBXML] O 1 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Interval> 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Recurrence> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:ReminderSet> 10/11/2018 09:19:28 [19022] [WBXML] O 0 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:ReminderSet> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Sensitivity> 10/11/2018 09:19:28 [19022] [WBXML] O 0 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Sensitivity> 10/11/2018 09:19:28 [19022] [WBXML] O <POOMTASKS:Subject> 10/11/2018 09:19:28 [19022] [WBXML] O OL365 daily recurring 10/11/2018 09:19:28 [19022] [WBXML] O </POOMTASKS:Subject> 10/11/2018 09:19:28 [19022] [WBXML] O <AirSyncBase:Body> 10/11/2018 09:19:28 [19022] [WBXML] O <AirSyncBase:Type> 10/11/2018 09:19:28 [19022] [WBXML] O 1 10/11/2018 09:19:28 [19022] [WBXML] O </AirSyncBase:Type> 10/11/2018 09:19:28 [19022] [WBXML] O <AirSyncBase:EstimatedDataSize> 10/11/2018 09:19:28 [19022] [WBXML] O 2 10/11/2018 09:19:28 [19022] [WBXML] O </AirSyncBase:EstimatedDataSize> 10/11/2018 09:19:28 [19022] [WBXML] O <AirSyncBase:Data> 10/11/2018 09:19:28 [19022] [WBXML] O <<< written 2 of 2 bytes of plain data >>> 10/11/2018 09:19:28 [19022] [WBXML] O </AirSyncBase:Data> 10/11/2018 09:19:28 [19022] [WBXML] O </AirSyncBase:Body> 10/11/2018 09:19:28 [19022] [WBXML] O </Data> 10/11/2018 09:19:28 [19022] [WBXML] O </Add> 10/11/2018 09:19:28 [19022] [DEBUG] PHPWrapper->ImportMessageChange(): change for: 'U9586e:56cabf443b954d0c8caedab84208fdf0860100000000' 10/11/2018 09:19:28 [19022] [WBXML] O </Perform> 10/11/2018 09:19:28 [19022] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:19:28 [19022] [DEBUG] Sync()->setFolderStat() on U9586e: 1541837967/1/0/31 expiring 2018-12-10 23:59:56 10/11/2018 09:19:28 [19022] [WBXML] O </Folder> 10/11/2018 09:19:28 [19022] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-120' 10/11/2018 09:19:28 [19022] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 09:19:28 [19022] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 09:19:28 [19022] [WBXML] O </Folders> 10/11/2018 09:19:28 [19022] [WBXML] O </Synchronize> 10/11/2018 09:19:28 [19022] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 09:19:28 [19022] [WBXML] WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMjAAAVIDVTk1ODZlAAFOAzEAAVZHTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4NjAxMDAwMDAwMDAAAV0ACUoDMAABTAMyMDE4LTExLTEwVDAwOjAwOjAwLjAwMFoAAU0DMjAxOC0xMS0wOVQyMzowMDowMC4wMDBaAAFOAzEAAU9QAzAAAVQDMQABAVsDMAABXQMwAAFgA09MMzY1IGRhaWx5IHJlY3VycmluZwABABFKRgMxAAFMAzIAAUsDDQoAAQEBAQEBAQE= 10/11/2018 09:19:28 [19022] [WBXML] WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMTkAAVIDVTk1ODZlAAFeAzEAAVMDMQABVQM1AAFXWAMwAAFbAzEAAQARRUYDMQABSAMwAAEBAQEBAQ== 10/11/2018 09:19:28 [19022] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 09:19:28 [19022] [ INFO] cmd='Sync' memory='2.02 MiB/2.00 MiB' time='0.07s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='0s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 09:19:28 [19022] [DEBUG] -------- End 10/11/2018 09:19:34 [19780] [DEBUG] -------- Start 10/11/2018 09:19:34 [19780] [DEBUG] cmd='Ping' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 09:19:34 [19780] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 09:19:34 [19780] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 09:19:34 [19780] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::CommandNeedsProvisioning(18): false 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::CommandNeedsAuthentication(18): true 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 09:19:34 [19780] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 09:19:34 [19780] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 09:19:34 [19780] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 09:19:34 [19780] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 09:19:34 [19780] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::HierarchyCommand(18): false 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 09:19:34 [19780] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::CommandNeedsPlainInput(18): false 10/11/2018 09:19:34 [19780] [WBXML] I <Ping:Ping> 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->GetState() read '1045' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 09:19:34 [19780] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:19:34 [19780] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '720', last sync at '1541837968' 10/11/2018 09:19:34 [19780] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '720', Last sync at '1541837968' 10/11/2018 09:19:34 [19780] [DEBUG] SyncParameters->GetLatestSyncKey(): '{f05e74b0-98c9-442c-92f4-c96395f41858}120' 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-120' 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-fd' 10/11/2018 09:19:34 [19780] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 09:19:34 [19780] [DEBUG] SyncCollections->AddCollection(): Folder id '' : ref. PolicyKey '833158280', ref. Lifetime '10', last sync at '1541673725' 10/11/2018 09:19:34 [19780] [DEBUG] SyncParameters->GetLatestSyncKey(): '{a84379ed-5fa2-4d92-9dfe-019db2be003f}1' 10/11/2018 09:19:34 [19780] [DEBUG] StateManager->loadHierarchyCache(): 'nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-hc-1' 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->GetState() read '2800' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-hc-1' 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-a84379ed-5fa2-4d92-9dfe-019db2be003f-1' 10/11/2018 09:19:34 [19780] [DEBUG] HandlePing(): reference PolicyKey for PING: 833158280 10/11/2018 09:19:34 [19780] [DEBUG] HandlePing(): initialization data received 10/11/2018 09:19:34 [19780] [WBXML] I <Ping:LifeTime> 10/11/2018 09:19:34 [19780] [WBXML] I 900 10/11/2018 09:19:34 [19780] [WBXML] I </Ping:LifeTime> 10/11/2018 09:19:34 [19780] [WBXML] I <Ping:Folders> 10/11/2018 09:19:34 [19780] [WBXML] I <Ping:Folder> 10/11/2018 09:19:34 [19780] [WBXML] I <Ping:ServerEntryId> 10/11/2018 09:19:34 [19780] [WBXML] I U9586e 10/11/2018 09:19:34 [19780] [WBXML] I </Ping:ServerEntryId> 10/11/2018 09:19:34 [19780] [WBXML] I <Ping:FolderType> 10/11/2018 09:19:34 [19780] [WBXML] I Tasks 10/11/2018 09:19:34 [19780] [WBXML] I </Ping:FolderType> 10/11/2018 09:19:34 [19780] [WBXML] I </Ping:Folder> 10/11/2018 09:19:34 [19780] [DEBUG] HandlePing(): using saved sync state for 'Tasks' id 'U9586e' 10/11/2018 09:19:34 [19780] [WBXML] I </Ping:Folders> 10/11/2018 09:19:34 [19780] [WBXML] I </Ping:Ping> 10/11/2018 09:19:34 [19780] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 09:19:34 [19780] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 09:19:34 [19780] [DEBUG] DeviceManager->DoAutomaticASDeviceSaving(): save automatically: false 10/11/2018 09:19:34 [19780] [DEBUG] PingTracking(): Initialized mutexid Resource id #79 and memid Resource id #80. 10/11/2018 09:19:34 [19780] [DEBUG] PingTracking initialised with IPC provider 'IpcSharedMemoryProvider' with type '2' 10/11/2018 09:19:34 [19780] [DEBUG] Announce process as PUSH connection 10/11/2018 09:19:34 [19780] [ INFO] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 900 seconds) 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->HasChangesSink(): created - HierarchyHash: 94ed1ea95fc21618ea602b51250f8bc2 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->adviseStoreToSink(): advised store 'Resource id #15' 10/11/2018 09:19:34 [19780] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->ChangesSinkInitialize(): folderid '56cabf443b954d0c8caedab84208fdf02f0000000000' 10/11/2018 09:19:34 [19780] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 09:19:34 [19780] [DEBUG] SyncParameters->IsExporterRunRequired(): false - current: 1541837967/1/0/31 - saved: 1541837967/1/0/31 - expiring: 2018-12-10 23:59:56 10/11/2018 09:19:34 [19780] [DEBUG] refpolkey:'833158280', sent polkey:'833158280' 10/11/2018 09:19:34 [19780] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 11 10/11/2018 09:19:34 [19780] [DEBUG] ExportChangesICS->Config() initialized with state: 0x7f000000b2000000 10/11/2018 09:19:34 [19780] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 3 changes ready to sync for 'hierarchy'. 10/11/2018 09:19:34 [19780] [DEBUG] MAPIProvider->GetStoreProps(): Getting store properties. 10/11/2018 09:19:34 [19780] [DEBUG] MAPIProvider->GetFolder(): folder 'Suggested Contacts' should not be synchronized 10/11/2018 09:19:34 [19780] [DEBUG] MAPIProvider->getInboxProps(): Getting inbox properties. 10/11/2018 09:19:34 [19780] [DEBUG] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant. 10/11/2018 09:19:34 [19780] [DEBUG] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Tasks' will not be sent as modification is not relevant.
Outlook shows:
-
Outlook 365, Step 2 (mark to-do done on Nine)
10/11/2018 09:21:33 [19019] [DEBUG] -------- Start 10/11/2018 09:21:33 [19019] [DEBUG] cmd='Sync' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' version='2.4.5+0-0' method='POST' 10/11/2018 09:21:33 [19019] [DEBUG] Used timezone 'Europe/Amsterdam' 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 10/11/2018 09:21:33 [19019] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.8 - PHP version: 7.0.30-0+deb9u1 10/11/2018 09:21:33 [19019] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::CommandNeedsProvisioning(0): true 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->GetState() read '1871' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-devicedata' 10/11/2018 09:21:33 [19019] [DEBUG] ASDevice data loaded for user: 'someuser' 10/11/2018 09:21:33 [19019] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 10/11/2018 09:21:33 [19019] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::HierarchyCommand(0): false 10/11/2018 09:21:33 [19019] [DEBUG] DeviceManager->ProvisioningRequired('833158280') saved device key '833158280': false 10/11/2018 09:21:33 [19019] [DEBUG] DeviceManager->getPolicyName(): determined policy name: 'default' 10/11/2018 09:21:33 [19019] [DEBUG] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::CommandNeedsAuthentication(0): true 10/11/2018 09:21:33 [19019] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'someuser'.. 10/11/2018 09:21:33 [19019] [DEBUG] KopanoBackend->openMessageStore('someuser'): Found 'DEFAULT' store: 'Resource id #15' 10/11/2018 09:21:33 [19019] [DEBUG] KopanoBackend->Logon(): User 'someuser' is authenticated 10/11/2018 09:21:33 [19019] [DEBUG] Store supports properties containing Unicode characters. 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::CommandNeedsPlainInput(0): false 10/11/2018 09:21:33 [19019] [WBXML] I <Synchronize> 10/11/2018 09:21:33 [19019] [WBXML] I <Folders> 10/11/2018 09:21:33 [19019] [WBXML] I <Folder> 10/11/2018 09:21:33 [19019] [WBXML] I <SyncKey> 10/11/2018 09:21:33 [19019] [WBXML] I {f05e74b0-98c9-442c-92f4-c96395f41858}120 10/11/2018 09:21:33 [19019] [WBXML] I </SyncKey> 10/11/2018 09:21:33 [19019] [WBXML] I <FolderId> 10/11/2018 09:21:33 [19019] [WBXML] I U9586e 10/11/2018 09:21:33 [19019] [WBXML] I </FolderId> 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->GetState() read '1016' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 09:21:33 [19019] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 09:21:33 [19019] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 09:21:33 [19019] [DEBUG] SyncCollections->AddCollection(): Folder id 'U9586e' : ref. PolicyKey '833158280', ref. Lifetime '900', last sync at '1541837968' 10/11/2018 09:21:33 [19019] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '833158280', reference Lifetime '900', Last sync at '1541837968' 10/11/2018 09:21:33 [19019] [WBXML] I <DeletesAsMoves> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </DeletesAsMoves> 10/11/2018 09:21:33 [19019] [WBXML] I <GetChanges> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </GetChanges> 10/11/2018 09:21:33 [19019] [WBXML] I <WindowSize> 10/11/2018 09:21:33 [19019] [WBXML] I 5 10/11/2018 09:21:33 [19019] [WBXML] I </WindowSize> 10/11/2018 09:21:33 [19019] [WBXML] I <Options> 10/11/2018 09:21:33 [19019] [WBXML] I <FilterType> 10/11/2018 09:21:33 [19019] [DEBUG] SyncParameters->UseCPO('DEFAULT') 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </FilterType> 10/11/2018 09:21:33 [19019] [WBXML] I <Conflict> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </Conflict> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:BodyPreference> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Type> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Type> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:AllOrNone> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:AllOrNone> 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:BodyPreference> 10/11/2018 09:21:33 [19019] [WBXML] I </Options> 10/11/2018 09:21:33 [19019] [WBXML] I <Perform> 10/11/2018 09:21:33 [19019] [WBXML] I <Add> 10/11/2018 09:21:33 [19019] [WBXML] I <ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] I 4550 10/11/2018 09:21:33 [19019] [WBXML] I </ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] I <Data> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Body> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Type> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Type> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Data> 10/11/2018 09:21:33 [19019] [WBXML] I 10/11/2018 09:21:33 [19019] [DEBUG] StringStreamWrapper::stream_open(): initialized stream length: 2 - HTML-safe-truncate: false 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Data> 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Body> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Subject> 10/11/2018 09:21:33 [19019] [WBXML] I OL365 daily recurring 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Subject> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Importance> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Importance> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:UtcDueDate> 10/11/2018 09:21:33 [19019] [WBXML] I 2018-11-09T23:00:00.000Z 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:UtcDueDate> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:DueDate> 10/11/2018 09:21:33 [19019] [WBXML] I 2018-11-10T00:00:00.000Z 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:DueDate> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Recurrence> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Regenerate> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Regenerate> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:DeadOccur> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:DeadOccur> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Type> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Type> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Interval> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Interval> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:FirstDayOfWeek> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:FirstDayOfWeek> 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Recurrence> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Complete> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Complete> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:DateCompleted> 10/11/2018 09:21:33 [19019] [WBXML] I 2018-11-10T00:00:00.000Z 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:DateCompleted> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Sensitivity> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Sensitivity> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:ReminderSet> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:ReminderSet> 10/11/2018 09:21:33 [19019] [WBXML] I </Data> 10/11/2018 09:21:33 [19019] [DEBUG] Sync->getImporter(): initialize importer 10/11/2018 09:21:33 [19019] [DEBUG] Sync->loadStates(): loading states for folder 'U9586e' 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-119' 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-120' 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fs-116' 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:21:33 [19019] [DEBUG] BackendKopano->GetImporter() folderid: '56cabf443b954d0c8caedab84208fdf02f0000000000' 10/11/2018 09:21:33 [19019] [DEBUG] ImportChangesICS->Config(): initializing importer with state: 0x8000000098020000 10/11/2018 09:21:33 [19019] [DEBUG] ImportChangesICS->LoadConflicts(): will be loaded later if necessary 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f05e74b0-98c9-442c-92f4-c96395f41858 counter: 120 10/11/2018 09:21:33 [19019] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 09:21:33 [19019] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2) 10/11/2018 09:21:33 [19780] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 09:21:33 [19780] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e', but it is not relevant 10/11/2018 09:21:33 [19019] [DEBUG] Sync->importMessage(): message imported 10/11/2018 09:21:33 [19019] [WBXML] I </Add> 10/11/2018 09:21:33 [19019] [WBXML] I <Add> 10/11/2018 09:21:33 [19019] [WBXML] I <ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] I 4551 10/11/2018 09:21:33 [19019] [WBXML] I </ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] I <Data> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Body> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Type> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Type> 10/11/2018 09:21:33 [19019] [WBXML] I <AirSyncBase:Data> 10/11/2018 09:21:33 [19019] [WBXML] I 10/11/2018 09:21:33 [19019] [DEBUG] StringStreamWrapper::stream_open(): initialized stream length: 2 - HTML-safe-truncate: false 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Data> 10/11/2018 09:21:33 [19019] [WBXML] I </AirSyncBase:Body> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Subject> 10/11/2018 09:21:33 [19019] [WBXML] I OL365 daily recurring 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Subject> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Importance> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Importance> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:UtcDueDate> 10/11/2018 09:21:33 [19019] [WBXML] I 2018-11-10T23:00:00.000Z 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:UtcDueDate> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:DueDate> 10/11/2018 09:21:33 [19019] [WBXML] I 2018-11-11T00:00:00.000Z 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:DueDate> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Recurrence> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Regenerate> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Regenerate> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:DeadOccur> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:DeadOccur> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Type> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Type> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Interval> 10/11/2018 09:21:33 [19019] [WBXML] I 1 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Interval> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:FirstDayOfWeek> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:FirstDayOfWeek> 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Recurrence> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Complete> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Complete> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:Sensitivity> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:Sensitivity> 10/11/2018 09:21:33 [19019] [WBXML] I <POOMTASKS:ReminderSet> 10/11/2018 09:21:33 [19019] [WBXML] I 0 10/11/2018 09:21:33 [19019] [WBXML] I </POOMTASKS:ReminderSet> 10/11/2018 09:21:33 [19019] [WBXML] I </Data> 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f05e74b0-98c9-442c-92f4-c96395f41858 counter: 120 10/11/2018 09:21:33 [19019] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 09:21:33 [19019] [WARN] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2) 10/11/2018 09:21:33 [19780] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 09:21:33 [19780] [DEBUG] KopanoChangesWrapper::GetWrapper(): Found existing notification check exporter. Reinitializing. 10/11/2018 09:21:33 [19780] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e', but it is not relevant 10/11/2018 09:21:33 [19019] [DEBUG] Sync->importMessage(): message imported 10/11/2018 09:21:33 [19019] [WBXML] I </Add> 10/11/2018 09:21:33 [19019] [WBXML] I <Remove> 10/11/2018 09:21:33 [19019] [WBXML] I <ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] I U9586e:56cabf443b954d0c8caedab84208fdf0860100000000 10/11/2018 09:21:33 [19019] [WBXML] I </ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] I </Remove> 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f05e74b0-98c9-442c-92f4-c96395f41858 counter: 120 10/11/2018 09:21:33 [19019] [DEBUG] Got waste basket with id '56cabf443b954d0c8caedab84208fdf0280000000000' 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf0280000000000'): 'false' 10/11/2018 09:21:33 [19019] [DEBUG] KopanoBackend->GetMAPIStoreForFolderId('', '56cabf443b954d0c8caedab84208fdf0280000000000'): no store specified, returning default store 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf0280000000000'): 'false' 10/11/2018 09:21:33 [19019] [DEBUG] KopanoBackend->GetMAPIStoreForFolderId('', '56cabf443b954d0c8caedab84208fdf0280000000000'): no store specified, returning default store 10/11/2018 09:21:33 [19019] [DEBUG] Sync->importMessage(): message imported 10/11/2018 09:21:33 [19019] [WBXML] I </Perform> 10/11/2018 09:21:33 [19019] [ INFO] Processed '3' incoming changes 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fs-120' 10/11/2018 09:21:33 [19019] [WBXML] I </Folder> 10/11/2018 09:21:33 [19019] [WBXML] I </Folders> 10/11/2018 09:21:33 [19019] [WBXML] I </Synchronize> 10/11/2018 09:21:33 [19019] [DEBUG] HandleSync(): Start Output 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:21:33 [19780] [DEBUG] DeviceManager->GetBackendIdForFolderId(): folderid U9586e => 56cabf443b954d0c8caedab84208fdf02f0000000000 10/11/2018 09:21:33 [19780] [DEBUG] KopanoChangesWrapper::GetWrapper(): Found existing notification check exporter. Reinitializing. 10/11/2018 09:21:33 [19780] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 09:21:33 [19780] [DEBUG] SyncCollections->CheckForChanges(): Notification received on folder 'U9586e' 10/11/2018 09:21:33 [19780] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 09:21:33 [19780] [WBXML] O <Ping:Ping> 10/11/2018 09:21:33 [19780] [WBXML] O <Ping:Status> 10/11/2018 09:21:33 [19780] [WBXML] O 2 10/11/2018 09:21:33 [19019] [DEBUG] KopanoBackend->GetFolderStat() fetched status information of 28 folders for store 'someuser' 10/11/2018 09:21:33 [19780] [WBXML] O </Ping:Status> 10/11/2018 09:21:33 [19780] [WBXML] O <Ping:Folders> 10/11/2018 09:21:33 [19019] [DEBUG] SyncParameters->IsExporterRunRequired(): true - current: 1541838093/2/0/32 - saved: 1541837967/1/0/31 - expiring: 2018-12-10 23:59:56 10/11/2018 09:21:33 [19780] [WBXML] O <Ping:Folder> 10/11/2018 09:21:33 [19780] [WBXML] O U9586e 10/11/2018 09:21:33 [19780] [WBXML] O </Ping:Folder> 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:21:33 [19780] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 2 10/11/2018 09:21:33 [19780] [WBXML] O </Ping:Folders> 10/11/2018 09:21:33 [19780] [WBXML] O </Ping:Ping> 10/11/2018 09:21:33 [19780] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 09:21:33 [19780] [WBXML] WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk1ODZlAAEBAQ== 10/11/2018 09:21:33 [19780] [WBXML] WBXML-IN : AwFqAAANRUgDOTAwAAFJSksDVTk1ODZlAAFMA1Rhc2tzAAEBAQE= 10/11/2018 09:21:33 [19780] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 09:21:33 [19780] [ INFO] cmd='Ping' memory='2.04 MiB/4.00 MiB' time='119.56s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='119s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 09:21:33 [19780] [DEBUG] -------- End 10/11/2018 09:21:33 [19019] [DEBUG] ExportChangesICS->Config() initialized with state: 0x8000000098020000 10/11/2018 09:21:33 [19019] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for '56cabf443b954d0c8caedab84208fdf02f0000000000'. 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection->ProcessLoopDetectionAddStatus: 'U9586e' with status 1 10/11/2018 09:21:33 [19019] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 10/11/2018 09:21:33 [19019] [DEBUG] Folder type: Tasks 10/11/2018 09:21:33 [19019] [WBXML] O <Synchronize> 10/11/2018 09:21:33 [19019] [WBXML] O <Folders> 10/11/2018 09:21:33 [19019] [WBXML] O <Folder> 10/11/2018 09:21:33 [19019] [WBXML] O <SyncKey> 10/11/2018 09:21:33 [19019] [WBXML] O {f05e74b0-98c9-442c-92f4-c96395f41858}121 10/11/2018 09:21:33 [19019] [WBXML] O </SyncKey> 10/11/2018 09:21:33 [19019] [WBXML] O <FolderId> 10/11/2018 09:21:33 [19019] [WBXML] O U9586e 10/11/2018 09:21:33 [19019] [WBXML] O </FolderId> 10/11/2018 09:21:33 [19019] [WBXML] O <Status> 10/11/2018 09:21:33 [19019] [WBXML] O 1 10/11/2018 09:21:33 [19019] [WBXML] O </Status> 10/11/2018 09:21:33 [19019] [WBXML] O <Replies> 10/11/2018 09:21:33 [19019] [WBXML] O <Add> 10/11/2018 09:21:33 [19019] [WBXML] O <ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O 4550 10/11/2018 09:21:33 [19019] [WBXML] O </ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O <ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0870100000000 10/11/2018 09:21:33 [19019] [WBXML] O </ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O <Status> 10/11/2018 09:21:33 [19019] [WBXML] O 1 10/11/2018 09:21:33 [19019] [WBXML] O </Status> 10/11/2018 09:21:33 [19019] [WBXML] O </Add> 10/11/2018 09:21:33 [19019] [WBXML] O <Add> 10/11/2018 09:21:33 [19019] [WBXML] O <ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O 4551 10/11/2018 09:21:33 [19019] [WBXML] O </ClientEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O <ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0880100000000 10/11/2018 09:21:33 [19019] [WBXML] O </ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O <Status> 10/11/2018 09:21:33 [19019] [WBXML] O 1 10/11/2018 09:21:33 [19019] [WBXML] O </Status> 10/11/2018 09:21:33 [19019] [WBXML] O </Add> 10/11/2018 09:21:33 [19019] [WBXML] O </Replies> 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection->Detect(): folderid:'U9586e' uuid:'f05e74b0-98c9-442c-92f4-c96395f41858' counter:'120' max:'5' queued:'1' 10/11/2018 09:21:33 [19019] [DEBUG] PHPWrapper->ImportMessageDeletion(): Received 1 remove requests from ICS 10/11/2018 09:21:33 [19019] [WBXML] O <Perform> 10/11/2018 09:21:33 [19019] [WBXML] O <Remove> 10/11/2018 09:21:33 [19019] [WBXML] O <ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O U9586e:56cabf443b954d0c8caedab84208fdf0860100000000 10/11/2018 09:21:33 [19019] [WBXML] O </ServerEntryId> 10/11/2018 09:21:33 [19019] [WBXML] O </Remove> 10/11/2018 09:21:33 [19019] [DEBUG] PHPWrapper->ImportMessageDeletion(): delete for :'U9586e:56cabf443b954d0c8caedab84208fdf0860100000000' 10/11/2018 09:21:33 [19019] [WBXML] O </Perform> 10/11/2018 09:21:33 [19019] [DEBUG] ZPush::GetAdditionalSyncFolderStore('56cabf443b954d0c8caedab84208fdf02f0000000000'): 'false' 10/11/2018 09:21:33 [19019] [DEBUG] Sync()->setFolderStat() on U9586e: 1541838093/2/0/32 expiring 2018-12-11 05:50:00 10/11/2018 09:21:33 [19019] [WBXML] O </Folder> 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-121' 10/11/2018 09:21:33 [19019] [DEBUG] SyncCollections->SaveCollection(): Data of folder 'U9586e' changed 10/11/2018 09:21:33 [19019] [DEBUG] FileStateMachine->SetState() written 1 bytes on file: '/var/lib/z-push/2/8/nine0c2f371d7682-f05e74b0-98c9-442c-92f4-c96395f41858-fd' 10/11/2018 09:21:33 [19019] [WBXML] O </Folders> 10/11/2018 09:21:33 [19019] [WBXML] O </Synchronize> 10/11/2018 09:21:33 [19019] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 10/11/2018 09:21:33 [19019] [WBXML] WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMjEAAVIDVTk1ODZlAAFOAzEAAUZHTAM0NTUwAAFNA1U5NTg2ZTo1NmNhYmY0NDNiOTU0ZDBjOGNhZWRhYjg0MjA4ZmRmMDg3MDEwMDAwMDAwMAABTgMxAAEBR0wDNDU1MQABTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4ODAxMDAwMDAwMDAAAU4DMQABAQFWSU0DVTk1ODZlOjU2Y2FiZjQ0M2I5NTRkMGM4Y2FlZGFiODQyMDhmZGYwODYwMTAwMDAwMDAwAAEBAQEBAQ== 10/11/2018 09:21:33 [19019] [WBXML] WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH0xMjAAAVIDVTk1ODZlAAFeAzEAAVMDMQABVQM1AAFXWAMwAAFbAzEAAQARRUYDMQABSAMwAAEBAQAAVkdMAzQ1NTAAAV0AEUpGAzEAAUsDDQoAAQEACWADT0wzNjUgZGFpbHkgcmVjdXJyaW5nAAFOAzEAAU0DMjAxOC0xMS0wOVQyMzowMDowMC4wMDBaAAFMAzIwMTgtMTEtMTBUMDA6MDA6MDAuMDAwWgABT1kDMAABWgMxAAFQAzAAAVQDMQABZgMwAAEBSgMxAAFLAzIwMTgtMTEtMTBUMDA6MDA6MDAuMDAwWgABXQMwAAFbAzAAAQEBAABHTAM0NTUxAAFdABFKRgMxAAFLAw0KAAEBAAlgA09MMzY1IGRhaWx5IHJlY3VycmluZwABTgMxAAFNAzIwMTgtMTEtMTBUMjM6MDA6MDAuMDAwWgABTAMyMDE4LTExLTExVDAwOjAwOjAwLjAwMFoAAU9ZAzAAAVoDMAABUAMwAAFUAzEAAWYDMAABAUoDMAABXQMwAAFbAzAAAQEBAABJTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA4NjAxMDAwMDAwMDAAAQEBAQEB 10/11/2018 09:21:33 [19019] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 10/11/2018 09:21:33 [19019] [ INFO] cmd='Sync' memory='2.01 MiB/2.00 MiB' time='0.29s' devType='Android' devId='nine0c2f371d7682' getUser='someuser' from='217.224.175.231' idle='0s' version='2.4.5+0-0' method='POST' httpcode='200' 10/11/2018 09:21:33 [19019] [DEBUG] -------- End
z-push-error.log reads:
10/11/2018 09:21:33 [19019] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 09:21:33 [19019] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2) 10/11/2018 09:21:33 [19019] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8) 10/11/2018 09:21:33 [19019] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2)
Outlook shows
-
Outlook 365, Step 3 (mark to-do done on Outlook, crashing OL)
No logs are written, no z-push action, as outlook immediately crashes and restarts.After the restart, OL365 looks the same as before the crash.
-
Wow, that was a lot of data. I really hope this all helps diagnosing what’s going on. Feel free to come back with more questions or tries, I’l gladly support you.
-
Hi @itserv ,
many thanks for your detailed report. I have discussed this internally in our management team and with the developers.
Unfortunately recurring tasks is more of an edge functionality (Kopano WebApp does currently not support it, I only encountered a few ActiveSync clients that do), therefore we do not want to commit the resources required to really do a deep dive into why you get the behaviour you are reporting.
@itserv said in Outlook 365 crashes with recurring to-dos marked as done on Nine (Android):
require rock-solid synchronisation of recurring to-dos
Even if this would come down to an issue within Z-Push we cannot give any guarantees that Outlook would work with this feature afterwards. The past has shown that Microsoft implemented ActiveSync just for the narrow use case of syncing Hotmail and has since then moved on and migrated their users to Office 365 instead of continuing to use ActiveSync.
I personally am also missing some flexibility of tasks within Outlook (and that even with the old Mapi client), therefore I am using a third party task manager instead of the built in tasks in Outlook (yes, I am marking mails for followup in Outlook, but I do not work with the actual tasks). After some years I have landed at Todoist for both private and work related tasks. Its sadly not self hostable, but imho very worth the money you pay for it.
-
Felix,
thank you for your warm words. Unfortunatly, your answer is making me sad, because I read it like, cobined with the road map, as “Kopano is moving more and more away from Outlook” (MAPI support in Outlook will go/is already gone, zarafa-Plugin will sooner or later no longer work and it’s beyond your influence), and moves towards WebApp and DeskApp (where I never understood the difference - so what).
Is it so strange that we work with recurring tasks? So few do this, that neither WebApp, DeskApp nor z-push professionaly offers this functionality? To-Do’s without recurring is maybe 20% for the worth someone can have from to-do lists …
Well, then … time to either learn professional PHP programming, or evaluate my options. Luckily a business partner has a running Zimbra server - I will evaluate, how Zimbra handles the situation. And let’s see which solution Microsoft offers for recurring to-dos with Android smartphones.
Again, thank you for your support.
-
Hi itserv,
@itserv said in Outlook 365 crashes with recurring to-dos marked as done on Nine (Android):
Is it so strange that we work with recurring tasks? So few do this, that neither WebApp, DeskApp nor z-push professionaly offers this functionality? To-Do’s without recurring is maybe 20% for the worth someone can have from to-do lists …
I wouldn’t say strange. Rare would be a more appropriate word. If you search for recurring tasks in Z-Push JIRA there are only 4 issues. In now more than 11 years I work on Z-Push there were maybe 5 (for sure not more than 10) questions/requests regarding recurring tasks. The default iOS and Android ActiveSync clients do not even support this functionality and one needs a third party solution like Nine.
I don’t say that this is not a useful feature, just wanted you to give you a perspective of a developer who deals with mobile synchronisation daily.Manfred