Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

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

    Synchronising (mobile) devices via Z-Push
    3
    14
    952
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • itserv
      itserv last edited by

      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.

      1 Reply Last reply Reply Quote 0
      • Manfred
        Manfred Kopano @itserv last edited by

        Hi itserv,

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

        1. 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

        1 Reply Last reply Reply Quote 0
        • itserv
          itserv last edited by

          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:

          1. create an daily recurring (never ending) to-do/task in Outlook
          2. mark the to-do as done on my Android device using Nine
          3. 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 fbartels 2 Replies Last reply Reply Quote 0
          • itserv
            itserv @itserv last edited by

            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:
            0_1541838581597_2003-01.png

            itserv 1 Reply Last reply Reply Quote 0
            • itserv
              itserv @itserv last edited by

              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:

              0_1541838633089_2003-02.png

              1 Reply Last reply Reply Quote 0
              • itserv
                itserv last edited by

                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:

                0_1541838674617_2003-03.png

                1 Reply Last reply Reply Quote 0
                • itserv
                  itserv last edited by

                  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:

                  0_1541838714676_365-1.png

                  1 Reply Last reply Reply Quote 0
                  • itserv
                    itserv last edited by

                    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

                    0_1541838503777_365-2.png

                    1 Reply Last reply Reply Quote 0
                    • itserv
                      itserv last edited by

                      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.
                      0_1541838876640_365-3.png

                      1 Reply Last reply Reply Quote 0
                      • itserv
                        itserv last edited by

                        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.

                        1 Reply Last reply Reply Quote 0
                        • fbartels
                          fbartels Kopano @itserv last edited by

                          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.

                          Regards Felix

                          Resources:
                          https://kopano.com/blog/how-to-get-kopano/
                          https://documentation.kopano.io/
                          https://kb.kopano.io/

                          Support overview:
                          https://kopano.com/support/

                          1 Reply Last reply Reply Quote 0
                          • itserv
                            itserv last edited by

                            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 1 Reply Last reply Reply Quote 0
                            • Manfred
                              Manfred Kopano @itserv last edited by

                              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

                              1 Reply Last reply Reply Quote 2
                              • First post
                                Last post