CardDAV backend to NextCloud not working



  • I have a recently installed NextCloud instance with Calendar & Contacts app. I can connect to it with a CardDAV client (iPhone) and sync my contacts. However, I am trying to merge e-mail, contact and calendar accounts into one using EAS, hence Z-Push.
    I am using the combined backend with IMAP and CardDAV.
    E-mail sync works, contacts do not. The contact list is empty and when I add a new contact the following is logged.

    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] -------- Start
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] cmd='Sync' devType='iPhone' devId='l6ks0va0ip4d7eq44vk20f3688' getUser='<EMAIL>' from='109.102.78.245' version='2.3.8' method='POST'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Used timezone 'Europe/London'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Including backend file: '/srv/www/roundcube/z-push/backend/imap/imap.php'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Including backend file: '/srv/www/roundcube/z-push/backend/carddav/carddav.php'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Combined 2 backends loaded.
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Request::ProcessHeaders() ASVersion: 14.0
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ZPush::CommandNeedsProvisioning(0): true
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] FileStateMachine->GetState() read '2177' bytes from file: '/srv/www/roundcube/z-push//state/8/8/l6ks0va0ip4d7eq44vk20f3688-devicedata'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ASDevice data loaded for user: '<EMAIL>'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] TopCollector(): Initialized mutexid Resource id #18 and memid Resource id #19.
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] LoopDetection(): Initialized mutexid Resource id #22 and memid Resource id #23.
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ZPush::HierarchyCommand(0): false
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] DeviceManager->ProvisioningRequired('833756154') saved device key '833756154': false
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] DeviceManager->getPolicyName(): determined policy name: 'default'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ZPush::CommandNeedsAuthentication(0): true
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Combined->Logon('<EMAIL>', '',***))
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] BackendIMAP->Logon(): User '<EMAIL>' is authenticated on '{localhost:143/imap/notls/norsh}'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] BackendCardDAV->Logon(): User '<EMAIL>' is authenticated on 'https://<HOST>:443/remote.php/dav/principals/users/<EMAIL>/'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Combined->Logon() success
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ZPush::CommandNeedsPlainInput(0): false
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I  <Synchronize>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I   <Folders>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I    <Folder>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     <SyncKey>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I      {56c72c6d-e226-4db1-860f-e345dfdcfe3e}1
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     </SyncKey>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     <FolderId>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I      d/contacts
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     </FolderId>
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] FileStateMachine->GetState() read '857' bytes from file: '/srv/www/roundcube/z-push//state/8/8/l6ks0va0ip4d7eq44vk20f3688-56c72c6d-e226-4db1-860f-e345dfdcfe3e-fd'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] SyncParameters->UseCPO('DEFAULT')
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'd/contacts', returning as is.
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] SyncCollections->AddCollection(): Folder id 'd/contacts' : ref. PolicyKey '833756154', ref. Lifetime '', last sync at '1514731461'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] SyncCollections->AddCollection(): Updated reference PolicyKey '833756154', reference Lifetime '', Last sync at '1514731461'
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     <GetChanges/>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     <WindowSize>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I      25
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     </WindowSize>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     <Options>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I      <AirSyncBase:BodyPreference>
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] SyncParameters->UseCPO('DEFAULT')
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       <AirSyncBase:Type>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        1
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       </AirSyncBase:Type>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       <AirSyncBase:TruncationSize>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        32768
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       </AirSyncBase:TruncationSize>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I      </AirSyncBase:BodyPreference>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     </Options>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I     <Perform>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I      <Add>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       <ClientEntryId>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        274
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       </ClientEntryId>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       <Data>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        <AirSyncBase:Body>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I         <AirSyncBase:Type>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I          1
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I         </AirSyncBase:Type>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I         <AirSyncBase:Data/>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        </AirSyncBase:Body>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        <POOMCONTACTS:FileAs>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I         Testing
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        </POOMCONTACTS:FileAs>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        <POOMCONTACTS:FirstName>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I         Testing
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        </POOMCONTACTS:FirstName>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        <POOMCONTACTS:HomePhoneNumber>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I         54235
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        </POOMCONTACTS:HomePhoneNumber>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I        <POOMCONTACTS:Picture/>
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] I       </Data>
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Sync->getImporter(): initialize importer
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Sync->loadStates(): loading states for folder 'd/contacts'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] FileStateMachine->GetState() read '6' bytes from file: '/srv/www/roundcube/z-push//state/8/8/l6ks0va0ip4d7eq44vk20f3688-56c72c6d-e226-4db1-860f-e345dfdcfe3e-1'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ZPush::GetAdditionalSyncFolderStore('d/contacts'): 'false'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Combined->Setup('', 'false', '', 'false')
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Combined->Setup() success
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] Combined->GetImporter() Content: ImportChangesCombined:('d/contacts')
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ImportChangesCombined->SetMoveStates()
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ImportChangesCombined->SetMoveStates() success
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ImportChangesCombined->Config(...)
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ImportChangesCombined->Config() success
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ImportChangesCombined->ConfigContentParameters()
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] ImportChangesCombined->ConfigContentParameters() success
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] LoopDetection->SetSyncStateUsage(): uuid: 56c72c6d-e226-4db1-860f-e345dfdcfe3e  counter: 1
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] BackendCardDAV->ChangeMessage('contacts', '')
    31/12/2017 15:32:10 [12817] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:1265 stream_get_contents() expects parameter 1 to be resource, null given (2)
    31/12/2017 15:32:10 [12817] [WBXML] [<EMAIL>] BackendCardDAV->ChangeMessage - vCard
    BEGIN:VCARD
    VERSION:3.0
    PRODID:Z-Push
    FN:Testing
    N:;Testing;;;
    TEL;TYPE=HOME,VOICE:54235
    END:VCARD
    
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] FileStateMachine->GetState() read '1342' bytes from file: '/srv/www/roundcube/z-push//state/8/8/l6ks0va0ip4d7eq44vk20f3688-bs-1514540826'
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] BackendCardDAV::getAddressbookFromUrl('https://<HOST>:443/remote.php/dav/principals/users/<EMAIL>/') = not initialized!
    31/12/2017 15:32:10 [12817] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:569 Undefined offset: 0 (8)
    31/12/2017 15:32:10 [12817] [DEBUG] [<EMAIL>] BackendCardDAV::getAddressbookFromUrl('') = not initialized!
    31/12/2017 15:32:10 [12817] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:570 Undefined offset: 0 (8)
    31/12/2017 15:32:12 [ 4260] [DEBUG] [<EMAIL>] BackendCombined->ChangesSink(30)
    31/12/2017 15:32:12 [ 4260] [DEBUG] [<EMAIL>] BackendCombined->ChangesSink - Calling in 'BackendIMAP' with 15
    31/12/2017 15:32:13 [ 4260] [DEBUG] [<EMAIL>] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
    31/12/2017 15:32:13 [ 4260] [DEBUG] [<EMAIL>] BackendIMAP->close_connection(): disconnected from IMAP server
    

    The issue is related to out-of-memory issues. During the last three events instances of php5-fpm were killed using around 300000 rss with PIDs: 802, 15671, 15732.
    The last two segfaulted:

    kernel: [387753.727033] php5-fpm[15671]: segfault at 7ffe6f94efe8 ip 00007f01983f52a8 sp 00007ffe6f94ef90 error 6 in libcurl.so.4.3.0[7f01983d1000+64000]
    ...
    kernel: [387838.685031] php5-fpm[15732]: segfault at 7ffe6f94dfe0 ip 00007f01983f52ad sp 00007ffe6f94dfc0 error 6 in libcurl.so.4.3.0[7f01983d1000+64000]
    

    And the z-push log:

    01/01/2018 08:38:53 [  802] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:1265 stream_get_contents() expects parameter 1 to be resource, null given (2)
    01/01/2018 08:38:53 [  802] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:569 Undefined offset: 0 (8)
    01/01/2018 08:38:53 [  802] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:570 Undefined offset: 0 (8)
    01/01/2018 08:39:08 [15671] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:1265 stream_get_contents() expects parameter 1 to be resource, null given (2)
    01/01/2018 08:39:08 [15671] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:569 Undefined offset: 0 (8)
    01/01/2018 08:39:08 [15671] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:570 Undefined offset: 0 (8)
    01/01/2018 08:40:33 [15732] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:1265 stream_get_contents() expects parameter 1 to be resource, null given (2)
    01/01/2018 08:40:33 [15732] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:569 Undefined offset: 0 (8)
    01/01/2018 08:40:33 [15732] [WARN] [<EMAIL>] /data/www/roundcube/z-push/backend/carddav/carddav.php:570 Undefined offset: 0 (8)
    

    Running:
    PHP 5.5.9-1ubuntu4.22 (fpm-fcgi) (built: Aug 4 2017 19:44:16)
    Z-Push 2.3.8

    How to debug this further?


Log in to reply
 

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