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.8How to debug this further?