CalDAV sync trouble against Apple CCS



  • I’ve been trying to get z-push working against a local instance of Apple’s CalendarServer. Contacts (CardDAV) work fine, calendars are a different issue.

    I’m running CalendarServer 9.1 from debian testing, and testing with a macOS desktop CalDav client (macOS Calendar) and iOS Active Sync client (iOS 11.0.3).

    The symptoms are:

    1. events created via desktop client never appear on the mobile device
    2. events created on the mobile device appear momentarily on the device, then vanish, but persist as expected in the CalDAV server and appear on the desktop client. [Edit: I’ve added a CalDav account on the iOS device, and both the desktop-created and mobile-created events appear as expected.]

    I’ve turned on WBXML logging for my user while creating an event on the iOS device and have a log file which I don’t pretend to grok.

    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] -------- Start
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] cmd='Sync' devType='iPad' devId='jll4a0h7ul4hv4vhmjr3ai8urg' getUser='dberger' from='192.168.0.2' version='2.3.8+0-0' method='POST'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Used timezone 'America/Los_Angeles'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Including backend file: '/usr/share/z-push/backend/imap/imap.php'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Including backend file: '/usr/share/z-push/backend/caldav/caldav.php'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Including backend file: '/usr/share/z-push/backend/carddav/carddav.php'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined 3 backends loaded.
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Request::ProcessHeaders() ASVersion: 14.0
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ZPush::CommandNeedsProvisioning(0): true
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] FileStateMachine->GetState() read '3517' bytes from file: '/var/lib/z-push/g/r/jll4a0h7ul4hv4vhmjr3ai8urg-devicedata'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ASDevice data loaded for user: 'dberger'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] TopCollector(): Initialized mutexid Resource id #10 and memid Resource id #11.
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] LoopDetection(): Initialized mutexid Resource id #12 and memid Resource id #13.
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ZPush::HierarchyCommand(0): false
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] DeviceManager->ProvisioningRequired('890874710') saved device key '890874710': false
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] DeviceManager->getPolicyName(): determined policy name: 'default'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ZPush::CommandNeedsAuthentication(0): true
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Logon('dberger', '',***))
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendIMAP->Logon(): User 'dberger' is authenticated on '{mail.oubliette.org:993/imap/ssl/norsh}'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCalDAV->Logon(): User 'dberger' is authenticated on CalDAV 'https://ccs.lan:8443/calendars/users/dberger/'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCardDAV->Logon(): User 'dberger' is authenticated on 'https://ccs.lan:8443/addressbooks/users/dberger/'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCardDAV::discoverAddressbooks() Found addressbook 'https://ccs.lan:8443/addressbooks/users/dberger/addressbook/'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Logon() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ZPush::CommandNeedsPlainInput(0): false
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I  <Synchronize>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I   <Folders>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I    <Folder>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     <SyncKey>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      {781a10c6-04f4-4e1c-9f8e-f51b0366a3bc}1
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     </SyncKey>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     <FolderId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      c/Ccalendar
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     </FolderId>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] FileStateMachine->GetState() read '893' bytes from file: '/var/lib/z-push/g/r/jll4a0h7ul4hv4vhmjr3ai8urg-781a10c6-04f4-4e1c-9f8e-f51b0366a3bc-fd'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] SyncParameters->UseCPO('DEFAULT')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'c/Ccalendar', returning as is.
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] SyncCollections->AddCollection(): Folder id 'c/Ccalendar' : ref. PolicyKey '890874710', ref. Lifetime '900', last sync at '1509318656'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] SyncCollections->AddCollection(): Updated reference PolicyKey '890874710', reference Lifetime '900', Last sync at '1509318656'
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     <GetChanges/>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     <WindowSize>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      25
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     </WindowSize>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     <Options>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      <FilterType>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] SyncParameters->UseCPO('DEFAULT')
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       5
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      </FilterType>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      <AirSyncBase:BodyPreference>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       <AirSyncBase:Type>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        1
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       </AirSyncBase:Type>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       <AirSyncBase:TruncationSize>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        32768
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       </AirSyncBase:TruncationSize>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      </AirSyncBase:BodyPreference>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     </Options>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     <Perform>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      <Add>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       <ClientEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        2519
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       </ClientEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       <Data>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <AirSyncBase:Body>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         <AirSyncBase:Type>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I          1
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         </AirSyncBase:Type>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         <AirSyncBase:Data/>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </AirSyncBase:Body>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:Timezone>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         4AEAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAsAAAABAAIAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAMAAAACAAIAAAAAAAAAxP///w==
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:Timezone>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:AllDayEvent>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         0
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:AllDayEvent>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:BusyStatus>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         2
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:BusyStatus>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:DtStamp>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         20171029T231249Z
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:DtStamp>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:EndTime>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         20171030T000000Z
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:EndTime>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:Sensitivity>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         0
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:Sensitivity>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:Subject>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         Created on ipad
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:Subject>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:StartTime>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         20171029T230000Z
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:StartTime>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:UID>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         26496597317F40E0A32659BDFECCC5710
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:UID>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        <POOMCAL:MeetingStatus>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I         0
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I        </POOMCAL:MeetingStatus>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I       </Data>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Sync->getImporter(): initialize importer
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Sync->loadStates(): loading states for folder 'c/Ccalendar'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] FileStateMachine->GetState() read '6' bytes from file: '/var/lib/z-push/g/r/jll4a0h7ul4hv4vhmjr3ai8urg-781a10c6-04f4-4e1c-9f8e-f51b0366a3bc-1'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Setup('', 'false', '', 'false')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Setup() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->GetImporter() Content: ImportChangesCombined:('c/Ccalendar')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ImportChangesCombined->SetMoveStates()
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ImportChangesCombined->SetMoveStates() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ImportChangesCombined->Config(...)
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ImportChangesCombined->Config() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ImportChangesCombined->ConfigContentParameters()
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ImportChangesCombined->ConfigContentParameters() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] LoopDetection->SetSyncStateUsage(): uuid: 781a10c6-04f4-4e1c-9f8e-f51b0366a3bc  counter: 1
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCalDAV->ChangeMessage('Ccalendar','')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCalDAV->StatMessage('Ccalendar','20171029T231250Z-67eb723bca9091d11b80980b274723be.ics')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Sync->importMessage(): message imported
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I      </Add>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I     </Perform>
    29/10/2017 16:12:50 [23814] [ INFO] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Processed '1' incoming changes
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] FileStateMachine->SetState() written 393 bytes on file: '/var/lib/z-push/g/r/jll4a0h7ul4hv4vhmjr3ai8urg-781a10c6-04f4-4e1c-9f8e-f51b0366a3bc-fs-1'
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I    </Folder>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I   </Folders>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] I  </Synchronize>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] HandleSync(): Start Output
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ZPush::GetAdditionalSyncFolderStore('c/Ccalendar'): 'false'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Setup('', 'false', '', 'false')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Setup() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->GetExporter('c/Ccalendar')
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '1' messages in state
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCalDAV->GetMessageList('Ccalendar','1506640370')
    29/10/2017 16:12:50 [23814] [ INFO] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] ExportChangesDiff->InitializeExporter(): Found '1' changes for 'Ccalendar'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] LoopDetection->ProcessLoopDetectionAddStatus: 'c/Ccalendar' with status 1
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Folder type: Calendar
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O  <Synchronize>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O   <Folders>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O    <Folder>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     <SyncKey>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     {781a10c6-04f4-4e1c-9f8e-f51b0366a3bc}2
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     </SyncKey>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     <FolderId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     c/Ccalendar
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     </FolderId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     <Status>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     1
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     </Status>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     <Replies>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O      <Add>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       <ClientEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       2519
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       </ClientEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       <ServerEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       20171029T231250Z-67eb723bca9091d11b80980b274723be.ics
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       </ServerEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       <Status>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       1
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       </Status>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O      </Add>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     </Replies>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] LoopDetection->Detect(): folderid:'c/Ccalendar' uuid:'781a10c6-04f4-4e1c-9f8e-f51b0366a3bc' counter:'1' max:'25' queued:'1'
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     <Perform>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O      <Remove>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       <ServerEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       20171029T231250Z-67eb723bca9091d11b80980b274723be.ics
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O       </ServerEntryId>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O      </Remove>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O     </Perform>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O    </Folder>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] FileStateMachine->SetState() written 6 bytes on file: '/var/lib/z-push/g/r/jll4a0h7ul4hv4vhmjr3ai8urg-781a10c6-04f4-4e1c-9f8e-f51b0366a3bc-2'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] SyncCollections->SaveCollection(): Data of folder 'c/Ccalendar' changed
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] FileStateMachine->SetState() written 919 bytes on file: '/var/lib/z-push/g/r/jll4a0h7ul4hv4vhmjr3ai8urg-781a10c6-04f4-4e1c-9f8e-f51b0366a3bc-fd'
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O   </Folders>
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] O  </Synchronize>
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] WBXMLEncoder->endTag() WBXML output completed
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] WBXML-OUT: AwFqAEVcT0sDezc4MWExMGM2LTA0ZjQtNGUxYy05ZjhlLWY1MWIwMzY2YTNiY30yAAFSA2MvQ2NhbGVuZGFyAAFOAzEAAUZHTAMyNTE5AAFNAzIwMTcxMDI5VDIzMTI1MFotNjdlYjcyM2JjYTkwOTFkMTFiODA5ODBiMjc0NzIzYmUuaWNzAAFOAzEAAQEBVklNAzIwMTcxMDI5VDIzMTI1MFotNjdlYjcyM2JjYTkwOTFkMTFiODA5ODBiMjc0NzIzYmUuaWNzAAEBAQEBAQ==
    29/10/2017 16:12:50 [23814] [WBXML] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] WBXML-IN : AwFqAEVcT0sDezc4MWExMGM2LTA0ZjQtNGUxYy05ZjhlLWY1MWIwMzY2YTNiY30xAAFSA2MvQ2NhbGVuZGFyAAETVQMyNQABV1gDNQABABFFRgMxAAFHAzMyNzY4AAEBAQAAVkdMAzI1MTkAAV0AEUpGAzEAAQsBAARFAzRBRUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFzQUFBQUJBQUlBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBQUFBTUFBQUFDQUFJQUFBQUFBQUFBeFAvLy93PT0AAUYDMAABTQMyAAFRAzIwMTcxMDI5VDIzMTI0OVoAAVIDMjAxNzEwMzBUMDAwMDAwWgABZQMwAAFmA0NyZWF0ZWQgb24gaXBhZAABZwMyMDE3MTAyOVQyMzAwMDBaAAFoAzI2NDk2NTk3MzE3RjQwRTBBMzI2NTlCREZFQ0NDNTcxMAABWAMwAAEBAQEBAQE=
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Logoff()
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendIMAP->close_connection(): disconnected from IMAP server
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCalDAV->Logoff(): disconnected from CALDAV server
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] BackendCardDAV->Logoff(): disconnected from CARDDAV server
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] Combined->Logoff() success
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] LoopDetection->ProcessLoopDetectionTerminate()
    29/10/2017 16:12:50 [23814] [ INFO] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] cmd='Sync' memory='2.17 MiB/4.00 MiB' time='0.40s' devType='iPad' devId='jll4a0h7ul4hv4vhmjr3ai8urg' getUser='dberger' from='192.168.0.2' idle='0s' version='2.3.8+0-0' method='POST' httpcode='200'
    29/10/2017 16:12:50 [23814] [DEBUG] [dberger] [jll4a0h7ul4hv4vhmjr3ai8urg] -------- End
    
    

Log in to reply
 

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