Outlook 365 crashes with recurring to-dos marked as done on Nine (Android)

itserv

Backend: KOE 8.6.8, z-push 2.4.5
Desktop: Outlook 2003 or Outlook 365, connected with zarafaclient-7.2.6-52190
Mobile: 9folder Nine, Version 4.3.1 on Android

I have created an infinite recurring task in Outlook 2003 or OL365, which is synched via z-push to my Android device running Nine. So far, so good.

Next, I mark the recurring item as “done” on the mobile device, and wait for the resync. This works, too. All looks good in Outlook, except the done-checkmark is missing. Hmm.

Now I mark the current active to-do as done using Outlook - and Outlook either crashes (OL365) or sets the due-time to a weird random value (OL 2003).

I wonder where I have to send this issue to, who’s “guilty”?

Here are the WBXMLs, where the last one (clicking done in OL) is the curious one, because it transmitts stupid dates.

(truncated) WBXML for creating a new recurring task in OL365:

 O  <Synchronize>
 O   <Folders>
 O    <Folder>
 O     <SyncKey>
 O     {f05e74b0-98c9-442c-92f4-c96395f41858}86
 O     </SyncKey>
 O     <FolderId>
 O     U9586e
 O     </FolderId>
 O     <Status>
 O     1
 O     </Status>
 O     <Perform>
 O      <Add>
 O       <ServerEntryId>
 O       U9586e:56cabf443b954d0c8caedab84208fdf0460100000000
 O       </ServerEntryId>
 O       <Data>
 O        <POOMTASKS:Complete>
 O        0
 O        </POOMTASKS:Complete>
 O        <POOMTASKS:DueDate>
 O        2018-11-09T00:00:00.000Z
 O        </POOMTASKS:DueDate>
 O        <POOMTASKS:UtcDueDate>
 O        2018-11-08T23:00:00.000Z
 O        </POOMTASKS:UtcDueDate>
 O        <POOMTASKS:Importance>
 O        1
 O        </POOMTASKS:Importance>
 O        <POOMTASKS:Recurrence>
 O         <POOMTASKS:Type>
 O         0
 O         </POOMTASKS:Type>
 O         <POOMTASKS:Interval>
 O         1
 O         </POOMTASKS:Interval>
 O        </POOMTASKS:Recurrence>
 O        <POOMTASKS:ReminderSet>
 O        0
 O        </POOMTASKS:ReminderSet>
 O        <POOMTASKS:Sensitivity>
 O        0
 O        </POOMTASKS:Sensitivity>
 O        <POOMTASKS:Subject>
 O        OL365 infinite daily recurring 
 O        </POOMTASKS:Subject>
 O        <AirSyncBase:Body>
 O         <AirSyncBase:Type>
 O         1
 O         </AirSyncBase:Type>
 O         <AirSyncBase:EstimatedDataSize>
 O         2
 O         </AirSyncBase:EstimatedDataSize>
 O         <AirSyncBase:Data>
 O         <<< written 2 of 2 bytes of plain data >>>
 O         </AirSyncBase:Data>
 O        </AirSyncBase:Body>
 O       </Data>
 O      </Add>
 O     </Perform>
 O    </Folder>
 O   </Folders>
 O  </Synchronize>
 WBXMLEncoder->endTag() WBXML output completed
 WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH04NgABUgNVOTU4NmUAAU4DMQABVkdNA1U5NTg2ZTo1NmNhYmY0NDNiOTU0ZDBjOGNhZWRhYjg0MjA4ZmRmMDQ2MDEwMDAwMDAwMAABXQAJSgMwAAFMAzIwMTgtMTEtMDlUMDA6MDA6MDAuMDAwWgABTQMyMDE4LTExLTA4VDIzOjAwOjAwLjAwMFoAAU4DMQABT1ADMAABVAMxAAEBWwMwAAFdAzAAAWADT0wzNjUgaW5maW5pdGUgZGFpbHkgcmVjdXJyaW5nIAABABFKRgMxAAFMAzIAAUsDDQoAAQEBAQEBAQE=
 WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH04NQABUgNVOTU4NmUAAV4DMQABUwMxAAFVAzUAAVdYAzAAAVsDMQABABFFRgMxAAFIAzAAAQEBAQEB

Now, the task is marked completed on the mobile. Fun fact: Nine creates a two new tasks, then deltes the one which originally marked as done:

 I  <Synchronize>
 I   <Folders>
 I    <Folder>
 I     <SyncKey>
 I      {f05e74b0-98c9-442c-92f4-c96395f41858}86
 I     </SyncKey>
 I     <FolderId>
 I      U9586e
 I     </FolderId>
 I     <DeletesAsMoves>
 I      1
 I     </DeletesAsMoves>
 I     <GetChanges>
 I      1
 I     </GetChanges>
 I     <WindowSize>
 I      5
 I     </WindowSize>
 I     <Options>
 I      <FilterType>
 I       0
 I      </FilterType>
 I      <Conflict>
 I       1
 I      </Conflict>
 I      <AirSyncBase:BodyPreference>
 I       <AirSyncBase:Type>
 I        1
 I       </AirSyncBase:Type>
 I       <AirSyncBase:AllOrNone>
 I        0
 I       </AirSyncBase:AllOrNone>
 I      </AirSyncBase:BodyPreference>
 I     </Options>
 I     <Perform>
 I      <Add>
 I       <ClientEntryId>
 I        4521
 I       </ClientEntryId>
 I       <Data>
 I        <AirSyncBase:Body>
 I         <AirSyncBase:Type>
 I          1
 I         </AirSyncBase:Type>
 I         <AirSyncBase:Data>
 I          
 I         </AirSyncBase:Data>
 I        </AirSyncBase:Body>
 I        <POOMTASKS:Subject>
 I         OL365 infinite daily recurring 
 I        </POOMTASKS:Subject>
 I        <POOMTASKS:Importance>
 I         1
 I        </POOMTASKS:Importance>
 I        <POOMTASKS:UtcDueDate>
 I         2018-11-08T23:00:00.000Z
 I        </POOMTASKS:UtcDueDate>
 I        <POOMTASKS:DueDate>
 I         2018-11-09T00:00:00.000Z
 I        </POOMTASKS:DueDate>
 I        <POOMTASKS:Recurrence>
 I         <POOMTASKS:Regenerate>
 I          0
 I         </POOMTASKS:Regenerate>
 I         <POOMTASKS:DeadOccur>
 I          1
 I         </POOMTASKS:DeadOccur>
 I         <POOMTASKS:Type>
 I          0
 I         </POOMTASKS:Type>
 I         <POOMTASKS:Interval>
 I          1
 I         </POOMTASKS:Interval>
 I         <POOMTASKS:FirstDayOfWeek>
 I          0
 I         </POOMTASKS:FirstDayOfWeek>
 I        </POOMTASKS:Recurrence>
 I        <POOMTASKS:Complete>
 I         1
 I        </POOMTASKS:Complete>
 I        <POOMTASKS:DateCompleted>
 I         2018-11-09T00:00:00.000Z
 I        </POOMTASKS:DateCompleted>
 I        <POOMTASKS:Sensitivity>
 I         0
 I        </POOMTASKS:Sensitivity>
 I        <POOMTASKS:ReminderSet>
 I         0
 I        </POOMTASKS:ReminderSet>
 I       </Data>
 I      </Add>
 I      <Add>
 I       <ClientEntryId>
 I        4522
 I       </ClientEntryId>
 I       <Data>
 I        <AirSyncBase:Body>
 I         <AirSyncBase:Type>
 I          1
 I         </AirSyncBase:Type>
 I         <AirSyncBase:Data>
 I          
 I         </AirSyncBase:Data>
 I        </AirSyncBase:Body>
 I        <POOMTASKS:Subject>
 I         OL365 infinite daily recurring 
 I        </POOMTASKS:Subject>
 I        <POOMTASKS:Importance>
 I         1
 I        </POOMTASKS:Importance>
 I        <POOMTASKS:UtcDueDate>
 I         2018-11-09T23:00:00.000Z
 I        </POOMTASKS:UtcDueDate>
 I        <POOMTASKS:DueDate>
 I         2018-11-10T00:00:00.000Z
 I        </POOMTASKS:DueDate>
 I        <POOMTASKS:Recurrence>
 I         <POOMTASKS:Regenerate>
 I          0
 I         </POOMTASKS:Regenerate>
 I         <POOMTASKS:DeadOccur>
 I          0
 I         </POOMTASKS:DeadOccur>
 I         <POOMTASKS:Type>
 I          0
 I         </POOMTASKS:Type>
 I         <POOMTASKS:Interval>
 I          1
 I         </POOMTASKS:Interval>
 I         <POOMTASKS:FirstDayOfWeek>
 I          0
 I         </POOMTASKS:FirstDayOfWeek>
 I        </POOMTASKS:Recurrence>
 I        <POOMTASKS:Complete>
 I         0
 I        </POOMTASKS:Complete>
 I        <POOMTASKS:Sensitivity>
 I         0
 I        </POOMTASKS:Sensitivity>
 I        <POOMTASKS:ReminderSet>
 I         0
 I        </POOMTASKS:ReminderSet>
 I       </Data>
 I      </Add>
 I      <Remove>
 I       <ServerEntryId>
 I        U9586e:56cabf443b954d0c8caedab84208fdf0460100000000
 I       </ServerEntryId>
 I      </Remove>
 I     </Perform>
 I    </Folder>
 I   </Folders>
 I  </Synchronize>
 WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
 O  <Ping:Ping>
 O   <Ping:Status>
 O   2
 O   </Ping:Status>
 O   <Ping:Folders>
 O    <Ping:Folder>
 O    U9586e
 O    </Ping:Folder>
 O   </Ping:Folders>
 WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
 O  </Ping:Ping>
 WBXMLEncoder->endTag() WBXML output completed
 O  <Synchronize>
 WBXML-OUT: AwFqAAANRUcDMgABSUoDVTk1ODZlAAEBAQ==
 WBXML-IN : AwFqAAANRUgDODQwAAFJSksDVTk1ODZlAAFMA1Rhc2tzAAEBAQE=
 O   <Folders>
 O    <Folder>
 O     <SyncKey>
 O     {f05e74b0-98c9-442c-92f4-c96395f41858}87
 O     </SyncKey>
 O     <FolderId>
 O     U9586e
 O     </FolderId>
 O     <Status>
 O     1
 O     </Status>
 O     <Replies>
 O      <Add>
 O       <ClientEntryId>
 O       4521
 O       </ClientEntryId>
 O       <ServerEntryId>
 O       U9586e:56cabf443b954d0c8caedab84208fdf0470100000000
 O       </ServerEntryId>
 O       <Status>
 O       1
 O       </Status>
 O      </Add>
 O      <Add>
 O       <ClientEntryId>
 O       4522
 O       </ClientEntryId>
 O       <ServerEntryId>
 O       U9586e:56cabf443b954d0c8caedab84208fdf0480100000000
 O       </ServerEntryId>
 O       <Status>
 O       1
 O       </Status>
 O      </Add>
 O     </Replies>
 O     <Perform>
 O      <Remove>
 O       <ServerEntryId>
 O       U9586e:56cabf443b954d0c8caedab84208fdf0460100000000
 O       </ServerEntryId>
 O      </Remove>
 O     </Perform>
 O    </Folder>
 O   </Folders>
 O  </Synchronize>
 WBXMLEncoder->endTag() WBXML output completed
 WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH04NwABUgNVOTU4NmUAAU4DMQABRkdMAzQ1MjEAAU0DVTk1ODZlOjU2Y2FiZjQ0M2I5NTRkMGM4Y2FlZGFiODQyMDhmZGYwNDcwMTAwMDAwMDAwAAFOAzEAAQFHTAM0NTIyAAFNA1U5NTg2ZTo1NmNhYmY0NDNiOTU0ZDBjOGNhZWRhYjg0MjA4ZmRmMDQ4MDEwMDAwMDAwMAABTgMxAAEBAVZJTQNVOTU4NmU6NTZjYWJmNDQzYjk1NGQwYzhjYWVkYWI4NDIwOGZkZjA0NjAxMDAwMDAwMDAAAQEBAQEB
 WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH04NgABUgNVOTU4NmUAAV4DMQABUwMxAAFVAzUAAVdYAzAAAVsDMQABABFFRgMxAAFIAzAAAQEBAABWR0wDNDUyMQABXQARSkYDMQABSwMNCgABAQAJYANPTDM2NSBpbmZpbml0ZSBkYWlseSByZWN1cnJpbmcgAAFOAzEAAU0DMjAxOC0xMS0wOFQyMzowMDowMC4wMDBaAAFMAzIwMTgtMTEtMDlUMDA6MDA6MDAuMDAwWgABT1kDMAABWgMxAAFQAzAAAVQDMQABZgMwAAEBSgMxAAFLAzIwMTgtMTEtMDlUMDA6MDA6MDAuMDAwWgABXQMwAAFbAzAAAQEBAABHTAM0NTIyAAFdABFKRgMxAAFLAw0KAAEBAAlgA09MMzY1IGluZmluaXRlIGRhaWx5IHJlY3VycmluZyAAAU4DMQABTQMyMDE4LTExLTA5VDIzOjAwOjAwLjAwMFoAAUwDMjAxOC0xMS0xMFQwMDowMDowMC4wMDBaAAFPWQMwAAFaAzAAAVADMAABVAMxAAFmAzAAAQFKAzAAAV0DMAABWwMwAAEBAQAASU0DVTk1ODZlOjU2Y2FiZjQ0M2I5NTRkMGM4Y2FlZGFiODQyMDhmZGYwNDYwMTAwMDAwMDAwAAEBAQEBAQ==

Finally, the current to-do is marked as done in Outlook 365. As a result, OL crashes.

When using OL2003 instead of OL365, the following WBXML has been transmitted. This WBXML is not directly related to the above example, since it was recorded sooner.

Notify the strange DueDate and UTCDueDate records:

 WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
 O  <Synchronize>
 O   <Folders>
 O    <Folder>
 O     <SyncKey>
 O     {f05e74b0-98c9-442c-92f4-c96395f41858}62
 O     </SyncKey>
 O     <FolderId>
 O     U9586e
 O     </FolderId>
 O     <Status>
 O     1
 O     </Status>
 O     <Perform>
 O      <Modify>
 O       <ServerEntryId>
 O       U9586e:56cabf443b954d0c8caedab84208fdf0f40000000000
 O       </ServerEntryId>
 O       <Data>
 O        <POOMTASKS:Complete>
 O        0
 O        </POOMTASKS:Complete>
 O        <POOMTASKS:DueDate>
 O        1601-01-01T00:00:00.000Z                 <---- WTF???
 O        </POOMTASKS:DueDate>
 O        <POOMTASKS:UtcDueDate>
 O        8907-12-05T17:42:00.000Z                 <---- WTF???
 O        </POOMTASKS:UtcDueDate>
 O        <POOMTASKS:Importance>
 O        1
 O        </POOMTASKS:Importance>
 O        <POOMTASKS:Recurrence>
 O         <POOMTASKS:Type>
 O         0
 O         </POOMTASKS:Type>
 O        </POOMTASKS:Recurrence>
 O        <POOMTASKS:ReminderSet>
 O        0
 O        </POOMTASKS:ReminderSet>
 O        <POOMTASKS:Sensitivity>
 O        0
 O        </POOMTASKS:Sensitivity>
 O        <POOMTASKS:Subject>
 O        Recurring-updated
 O        </POOMTASKS:Subject>
 O        <AirSyncBase:Body>
 O         <AirSyncBase:Type>
 O         1
 O         </AirSyncBase:Type>
 O         <AirSyncBase:EstimatedDataSize>
 O         1
 O         </AirSyncBase:EstimatedDataSize>
 O         <AirSyncBase:Data>
 O         <<< written 1 of 1 bytes of plain data >>>
 O         </AirSyncBase:Data>
 O        </AirSyncBase:Body>
 O       </Data>
 O      </Modify>
 O     </Perform>
 O    </Folder>
 O   </Folders>
 O  </Synchronize>
 WBXMLEncoder->endTag() WBXML output completed
 WBXML-OUT: AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH02MgABUgNVOTU4NmUAAU4DMQABVkhNA1U5NTg2ZTo1NmNhYmY0NDNiOTU0ZDBjOGNhZWRhYjg0MjA4ZmRmMGY0MDAwMDAwMDAwMAABXQAJSgMwAAFMAzE2MDEtMDEtMDFUMDA6MDA6MDAuMDAwWgABTQM4OTA3LTEyLTA1VDE3OjQyOjAwLjAwMFoAAU4DMQABT1ADMAABAVsDMAABXQMwAAFgA1JlY3VycmluZy11cGRhdGVkAAEAEUpGAzEAAUwDMQABSwMgAAEBAQEBAQEB
 WBXML-IN : AwFqAEVcT0sDe2YwNWU3NGIwLTk4YzktNDQyYy05MmY0LWM5NjM5NWY0MTg1OH02MQABUgNVOTU4NmUAAV4DMQABUwMxAAFVAzUAAVdYAzAAAVsDMQABABFFRgMxAAFIAzAAAQEBAQEB

There is something broken - somewhere. Please help. Thank you.

itserv

I just found the following in z-push-error.log:

09/11/2018 14:24:24 [12411] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8)
09/11/2018 14:24:24 [12411] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2)
09/11/2018 14:24:24 [12411] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:103 Undefined offset: -2138701566 (8)
09/11/2018 14:24:24 [12411] [WARN] [someuser] /usr/share/z-push/backend/kopano/mapi/class.taskrecurrence.php:104 Invalid argument supplied for foreach() (2)

This happens after I mark the task as done on Nine, and at the moment Nine syncs back to Kopano.

Manfred

Hi itserv,

@itserv said in Outlook 365 crashes with recurring to-dos marked as done on Nine (Android):

Finally, the current to-do is marked as done in Outlook 365. As a result, OL crashes.

When using OL2003 instead of OL365, the following WBXML has been transmitted. This WBXML is not directly related to the above example, since it was recorded sooner.

Notify the strange DueDate and UTCDueDate records:

It would be more helpful if you would provide the WBXML log for requests which actually are for the same items.

Does Outlook also crash if you only sync to Nine, but don’t perform any write operations on it (like editing a task or marking a task complete)?

I don’t have a setup with Nine / Outlook, but my guess is that some properties are missing in Outlook (probably not being set by Z-Push) which causes Outlook to crash.

Regarding your second post with the errors - the property missing is recurring_data which should be set for a recurring task. It would be more helpful if you’d provide the complete WBXML log for marking a task done on Nine.

Manfred

itserv

Good morning, and first of all thank you for your support. I highly appreciate it, and since I more and more require rock-solid synchronisation of recurring to-dos (which I can’t now), you keep me from switching to Exchange.

OK, here are the complete WBXML logs, created with

define('LOGUSERLEVEL', LOGLEVEL_WBXML);
$specialLogUsers = array('someuser');

The logs are created with Outlook 2003 first, then I do the same with Outlook 365. I’ll always do for steps:

create an daily recurring (never ending) to-do/task in Outlook
mark the to-do as done on my Android device using Nine
mark the now current to-do as done on Outlook

You will see three different issues:

when I mark a to-do as done on Nine, it does not modify the current to do and set it to completed, and then create a new to-do for the next iteration. Nine (by reading the WBXML) creates a new to-do for the CURRENT with POOMTASKS:Complete=1, it then creates another new to-do for the next iteration with POOMTASKS:Complete=0, and finally it deletes the original to-do. However, adding a to-do with POOMTASKS:Complete=1 seems not correctly be processed by z-push/kopano, since the checkbox in Outlook is not marked.
marking a task as done after this has been done at least once on Nine, creates weird due dates (see screenshot) on OL2003
marking a task as done after this has been done at least once on Nine, crashes OL365

itserv

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:

itserv

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:

itserv

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:

itserv

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:

itserv

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

itserv

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.

itserv

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.

fbartels

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.

itserv

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.

Manfred

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