DAVdroid fails to sync contacts due to 504

hook · June 20, 2018, 12:38pm

Nextcloud version (eg, 12.0.2): 13.0.4.0
Debian GNU/Linux 9.4 (stretch) (Armbian version)
Apache or nginx version (eg, Apache 2.4.25): Nginx 1.10.3
PHP version (eg, 7.1): 7.0.27

The issue you are facing:

Since I imported a few hundred contacts into Nextcloud (previously exported from my old ownCloud), DAVdroid throws a 504 error when it tries to sync contacts.

It worked fine before that with about half as many contacts. Calendars also seem to work fine still.

Is this the first time you’ve seen this error? (Y/N): Yes, but since then it’s repeating on every(?) contacts sync.

Steps to replicate it:

Have some contacts already – about 300-400 sounds about right
Import some more contacts – about 300-400 sounds about right
Wait for DAVdroid to try any sync the contacts ↦ error

The output of your Nextcloud log in Admin > Logging:

I see nothing directly applicable, but there’s a tonne of these:

|Info|cli|Memcache \OC\Memcache\APCu not available for distributed cache|2018-06-20T14:33:53+0200|
|---|---|---|---|
|Info|cli|Memcache \OC\Memcache\APCu not available for local cache|2018-06-20T14:33:53+0200|
|Info|cli|Memcache \OC\Memcache\APCu not available for distributed cache|2018-06-20T14:33:18+0200|
|Info|cli|Memcache \OC\Memcache\APCu not available for local cache|2018-06-20T14:33:18+0200|
|Info|cli|Memcache \OC\Memcache\APCu not available for distributed cache|2018-06-20T14:33:12+0200|
|Info|cli|Memcache \OC\Memcache\APCu not available for local cache|2018-06-20T14:33:12+0200|
|Info|cli|Memcache \OC\Memcache\APCu not available for distributed cache|2018-06-20T14:33:02+0200|
|Info|cli|Memcache \OC\Memcache\APCu not available for local cache|2018-06-20T14:33:02+0200|

The output of your config.php file in /path/to/nextcloud (make sure you remove any identifiable information!):

<?php
$CONFIG = array (
  'instanceid' => '###REDACTED###',
  'passwordsalt' => '###REDACTED###',
  'secret' => '###REDACTED###,
  'trusted_domains' =>
  array (
    0 => 'thatfunkyplace.wheremymonkeyis.at',
    1 => 'explorethe7seas.wheremymonkeyis.at',
  ),
  'datadirectory' => '/srv/nextcloud_data',
  'overwrite.cli.url' => 'http://localhost',
  'dbtype' => 'pgsql',
  'version' => '13.0.2.1',                                                                                                                      [20/953]
  'dbname' => 'nextcloud',
  'dbhost' => 'localhost',
  'dbport' => '5432',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'www-data',
  'dbpassword' => ''###REDACTED###',
  'logtimezone' => 'Europe/Ljubljana',
  'installed' => true,
  'memcache.local' => '\OC\Memcache\APCu',
#  'memcache.local' => '\OC\Memcache\Redis',
#  'redis' => array (
#   'host' => '/var/run/redis/redis.sock',
#   'port' => 0,
#   ),
#  'memcache.locking' => '\OC\Memcache\Redis',
  'maintenance' => false,
  'enabledPreviewProviders' =>
  array (
    0 => 'OC\Preview\Image',
    1 => 'OC\Preview\MP3',
    2 => 'OC\Preview\TXT',
    3 => 'OC\Preview\MarkDown',
    4 => 'OC\Preview\Epub',
    5 => 'OC\Preview\PDF',
  ),
  'theme' => '',
  'loglevel' => 0,
  'mail_domain' => ''###REDACTED###',
  'mail_smtpmode' => 'smtp',
  'mail_smtpauthtype' => 'LOGIN',
  'mail_smtpsecure' => 'ssl',
  'mail_from_address' => ''###REDACTED###',
  'mail_smtpauth' => 1,
  'mail_smtphost' => ''###REDACTED###',
  'mail_smtpport' => '465',
  'mail_smtpname' => ''###REDACTED###',
  'mail_smtppassword' => ''###REDACTED###',
  'updater.release.channel' => 'stable',
);

The output of your Apache/nginx/system log in /var/log/nginx/error.log:

2018/06/20 14:33:21 [error] 10397#10397: *93470 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.88.1, server: thatfunkyplace.wheremymonkeyis.at, request: "REPORT /remote.php/dav/addressbooks/users/hook/contacts/ HTTP/2.0", upstream: "fastcgi://unix:/run/php/php7.0-fpm.sock", host: "thatfunkyplace.wheremymonkeyis.at"

Error report from DAVdroid:

--- BEGIN DEBUG INFO ---
Account name: Stiki (matija@suklje.name ew)
Authority: com.android.contacts

HTTP REQUEST:
Request{method=REPORT, url=https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/addressbooks/users/hook/contacts/, tag=null}
<?xml version='1.0' encoding='UTF-8' ?><CARD:addressbook-multiget xmlns="DAV:" xmlns:CARD="urn:ietf:params:xml:ns:carddav"><prop><getcontenttype /><getetag /><CARD:address-data content-type="text/vcard" version="4.0" /></prop><href>/remote.php/dav/addressbooks/users/hook/contacts/fb6e605c-fa1e-4cc8-ac02-a78ca826dc96.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/b8664e98-6a4c-47f1-b0b7-027c2cf76ce2.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/a3264179-4193-4dec-bc28-e6eae10c562c.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/4f7035c2-919d-4201-95c3-fdd645e8fb08.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/9142346a-9d20-4d58-991b-6f2761dfb7bc.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/d61f45ca-a294-427b-8b22-0c9eaf8f42a9.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/f16f7802-d414-4e50-9b98-b22be0c45e08.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/a0895fb6-253c-4e18-bc3c-d83fd4a4eab8.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/f33c1fac-bdeb-4758-99f9-362639b6a0be.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/04ca8fee-cd5f-4b13-84c1-5898bf0ae05f.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/ce567751-21ff-4eda-9ae5-0a242e22721d.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/9cd8f3d3-eeea-468a-9e13-d6ce539784f2.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/6e96da8f-7abf-4d20-8eb4-e9f3b02a309e.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/6f024e12-3627-4e38-a0e6-5f9775f57a8b.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/be06360d-79c6-4a4a-8182-7db145b56587.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/556e93a9-e379-4603-a168-7aaf14aabe3a.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/c70d2fef-ec29-41dc-a0d4-7acd20bb43dc.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/32222299-2faf-48d0-983f-5e39203308ca.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/4a75c169-4259-4a98-b3ae-f2e9b53091ab.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/b33f836f-e377-4688-899e-9cf946bfa32c.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/c582b4d9-653f-402c-a021-3c2d31493c50.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/1bf7cd6a-7696-4916-b0a4-ef2eb5371d69.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/58ec739d-463c-49db-9787-f235dd67e7b0.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/25f2d7c7-2704-4ed2-84f0-4dc26ac57334.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/fa4be977-e79e-421e-acde-21bd91d877e9.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/c5abe150-4132-4d53-bdde-f81a089296f5.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/e95c066c-b42e-4fc1-91dc-c5483791e69a.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/b9b76e4c-56f6-4b9d-a517-6541ed619d9f.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/6dfcab3c-3351-4a00-bd48-a6139ed8d43d.vcf</href><href>/remote.php/dav/addressbooks/users/hook/contacts/46cb9a99-092b-4162-8a10-98a67b59fc31.vcf</href></CARD:addressbook-multiget>

HTTP RESPONSE:
Response{protocol=h2, code=504, message=, url=https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/addressbooks/users/hook/contacts/}
<html>
<head><title>504 Gateway Time-out</title></head>
<body bgcolor="white">
<center><h1>504 Gateway Time-out</h1></center>
<hr><center>nginx/1.10.3</center>
</body>
</html>



REMOTE RESOURCE:
https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/addressbooks/users/hook/contacts/

EXCEPTION:
at.bitfire.dav4android.exception.HttpException: HTTP 504 
	at at.bitfire.dav4android.DavResource.checkStatus(DavResource.kt:355)
	at at.bitfire.dav4android.DavResource.checkStatus(DavResource.kt:323)
	at at.bitfire.dav4android.DavAddressBook.multiget(DavAddressBook.kt:113)
	at at.bitfire.davdroid.syncadapter.ContactsSyncManager$processRemoteChanges$3.invoke(ContactsSyncManager.kt:340)
	at at.bitfire.davdroid.syncadapter.ContactsSyncManager$processRemoteChanges$3.invoke(ContactsSyncManager.kt:76)
	at at.bitfire.davdroid.syncadapter.BaseDavSyncManager.useRemote(BaseDavSyncManager.kt:303)
	at at.bitfire.davdroid.syncadapter.BaseDavSyncManager.useRemoteCollection(BaseDavSyncManager.kt:316)
	at at.bitfire.davdroid.syncadapter.ContactsSyncManager.processRemoteChanges(ContactsSyncManager.kt:339)
	at at.bitfire.davdroid.syncadapter.SyncManager.performSync(SyncManager.kt:174)
	at at.bitfire.davdroid.syncadapter.ContactsSyncAdapterService$ContactsSyncAdapter.sync(ContactsSyncAdapterService.kt:65)
	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:84)
	at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:272)

SOFTWARE INFORMATION
Package: at.bitfire.davdroid
Version: 1.11.4.1-ose (231) from 13. jun. 2018
Installed from: com.google.android.packageinstaller
JB Workaround installed: no

CONNECTIVITY (at the moment)
Active connection: WiFi, CONNECTED

CONFIGURATION
Power saving disabled: yes
android.permission.READ_CONTACTS permission: granted
android.permission.WRITE_CONTACTS permission: granted
android.permission.READ_CALENDAR permission: granted
android.permission.WRITE_CALENDAR permission: granted
org.dmfs.permission.READ_TASKS permission: denied
org.dmfs.permission.WRITE_TASKS permission: denied
System-wide synchronization: automatically
Account: matija@suklje.name
  Address book sync. interval: 240 min
  Calendar     sync. interval: 240 min
  OpenTasks    sync. interval: —
  WiFi only: false
  [CardDAV] Contact group method: CATEGORIES
  [CalDAV] Time range (past days): 90
           Manage calendar colors: true
Address book account: Stiki (matija@suklje.name ew)
  Main account: Account {name=matija@suklje.name, type=bitfire.at.davdroid}
  URL: https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/addressbooks/users/hook/contacts/
  Sync automatically: true

SQLITE DUMP
android_metadata
	|  locale |
	|  sl_SI |
----------
services
	|  _id | accountName | service | principal |
	|  1 | matija@suklje.name | carddav | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/principals/users/hook/ |
	|  2 | matija@suklje.name | caldav | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/principals/users/hook/ |
----------
sqlite_sequence
	|  name | seq |
	|  services | 2 |
	|  homesets | 8 |
	|  collections | 18 |
----------
homesets
	|  _id | serviceID | url |
	|  7 | 2 | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/calendars/hook/ |
	|  8 | 1 | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/addressbooks/users/hook/ |
----------
collections
	|  _id | serviceID | type | url | readOnly | forceReadOnly | displayName | description | color | timezone | supportsVEVENT | supportsVTODO | source | sync |
	|  14 | 2 | WEBCAL | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/calendars/hook/88282260liferaycom/ | 0 | 0 | Služba | <null> | -8853644 | <null> | 1 | 0 | https://calendar.google.com/calendar/ical/88282260@liferay.com/public/basic.ics | 0 |
	|  15 | 2 | CALENDAR | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/calendars/hook/contact_birthdays/ | 1 | 0 | Rojstni dnevi kontaktov | <null> | -54 | <null> | 1 | 0 | <null> | 0 |
	|  16 | 2 | CALENDAR | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/calendars/hook/dogodki/ | 0 | 0 | Dogodki | <null> | -1608502 | <null> | 1 | 1 | <null> | 1 |
	|  17 | 2 | CALENDAR | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/calendars/hook/personal/ | 0 | 0 | Osebno | <null> | -1579148 | <null> | 1 | 1 | <null> | 1 |
	|  18 | 1 | ADDRESS_BOOK | https://thatfunkyplace.wheremymonkeyis.at/remote.php/dav/addressbooks/users/hook/contacts/ | 0 | 0 | Stiki | <null> | <null> | <null> | 0 | 0 | <null> | 1 |
----------

SYSTEM INFORMATION
Android version: 8.0.0 (50.1.A.5.59)
Device: Sony H4113 (H4113)

--- END DEBUG INFO ---

Sanook · June 20, 2018, 9:52pm

You need to install ACPu first
https://docs.nextcloud.com/server/13/admin_manual/configuration_server/caching_configuration.html?highlight=apcu

hook · June 21, 2018, 5:04am

I do have it installed:

php-apcu/stable,now 5.1.8+4.0.11-1 armhf [installed]
  APC User Cache for PHP

Since this is a small ARM-powered server for just me and my family, I’m followed the recommendation to just have local caching here:
https://docs.nextcloud.com/server/13/admin_manual/configuration_server/caching_configuration.html?highlight=apcu#recommendations-based-on-type-of-deployment

Which is odd, because it seems the NextcloudPi uses Redis instead. So I’m a bit torn between what to use.

Ultimately, you think caching would prevent the 504?

Sanook · June 21, 2018, 6:45am

No, not really

Is HTTP/2.0 supported by DAVdroid?
The official sync client is not as far as i know.

hook · June 21, 2018, 7:12am

Bah, thought as much. Would still be good to fix eventually. No idea what’s wrong with the caching

I think so. It didn’t cause 504 before I uploaded the other contacts and it still syncs the calendars just fine.

In any case, AFAIK I have both HTTP2 and oldskool HTTPS in Nginx:

server {
    listen 80;
    server_name thatfunkyplace.wheremymonkeyis.at;
    # enforce https
    return 301 https://$server_name$request_uri;
}

server {
    listen 443 ssl http2;
    server_name thatfunkyplace.wheremymonkeyis.at;

    # SSL
    include includes/letsencrypt.conf;

hook · June 28, 2018, 7:15am

I have since set the update interval on DAVdroid to once a day for contacts, leaving the calendars to once every few hours. I hope(d) to avoid both syncing together that way.

After testing for a few days, the bug persists though.

Any ideas? It is highly annoying that you would get a 504 for what is essentially a vCard that is just 5 MiB big.

Hevii_Guy · June 29, 2018, 9:14pm

I am relieved that I’m not the only one suffering from this problem!

When syncing to my two Android devices, Caldav syncs with no problem yet Carddav always times out.

On the other hand, syncing contacts and calendar events between my Macbook and Nextcloud (residing on a Linux closet-server) does so without any apparent problems.

Bernie_O · June 29, 2018, 10:13pm

Have you tried to increase the values of the timeout directives in nginx and php-fpm? For what time are they configured?

These are ini php.ini
default_socket_timeout and max_execution_time

and in your nginx configuration:
fastcgi_read_timeout

hook · July 1, 2018, 1:50pm

Thank you @Bernie_O, that makes a lot of sense.

Here is what I have there:

max_execution_time = 30
default_socket_timeout = 60

There is none declared. Which block should it be in to be effective in this case?

hook · July 1, 2018, 5:11pm

I have bumped all three to 360s and on the manual sync it seems to have worked. I’ll wait for a few days to see if this did it for the regular auto update and report here.

Thanks

Addendum

To clarify @Bernie_O ’s suggestion, what solved it for me is that I edited the following two files:

In /etc/php/7.0/fpm/php.ini these two settings already existed in separate places, but I increased the value to 360 seconds (i.e. 6 minutes):

default_socket_timeout = 360
max_execution_time = 360

In my Nginx settings (e.g. /etc/nginx/sites-available/nextcloud.conf) I added fastcgi_read_timeout to the following block – note that the commented out ellipsis is here to show there are a lot of lines in that block that I omitted and anything above the # […] is just to help you find the block in question.

location ~ ^/(?:index|remote|public|cron|core/ajax/update|status|ocs/v[12]|updater/.+|ocs-provider/.+)\.php(?:$|/) {
    fastcgi_split_path_info ^(.+\.php)(/.*)$;
    include fastcgi_params;
# […]
    fastcgi_read_timeout 360s;
}

Bernie_O · July 1, 2018, 5:57pm

Sounds good so far. Let’s keep our fingers crossed that the timeouts are gone.

Looks like that info message is complaining about missing APCu for cli. Did you enable APCu also for the command line interface?

hook · July 2, 2018, 4:55am

Looks like that info message is complaining about missing APCu for cli. Did
you enable APCu also for the command line interface?

No, but I nowhere saw in the documentation that I should. I’ll try it out
right now.

I’m a bit sceptical though, as the PHP documentation says the following about it:

apc.enable_cli integer

Mostly for testing and debugging. Setting this enables APC for the CLI version of PHP. Under normal circumstances, it is not ideal to create, populate and destroy the APC cache on every CLI request, but for various test scenarios it is useful to be able to enable APC for the CLI version of PHP easily.

hook · July 2, 2018, 5:33am

@Bernie_O, I have set the following:

apc.enable_cli=1

in /etc/php/7.0/fpm/php.iniand restarted PHP.

The same error persists in Nextcloud logs.

Upon further research, it seems those settings fit somewhere else.

I found this a tad confusing, as on first glance the PHP documentation seemed to indicate it goes into php.ini, but then I followed the instructions in this post NC13: "Memcache \\OC\\Memcache\\APCu not available for local cache" and appended the cli setting instead to /etc/php/7.0/mods-available/apcu.ini.

And now the annoying APCu CLI info entries into the log are gone. Yay! \o/

Bernie_O · July 2, 2018, 6:47am

In some use cases enabling apc for cli does make sense. Due to my lack of knowledge about Nextclouds source code I do not now though whether that applies for Nextcloud.

Strangely enough I don‘t have these error messages without apc being enabled for cli (EDIT: I am using Nextcloud 13.0.4).

hook · July 2, 2018, 6:51am

I suppose it depends on whether or not you use a part (or app) of Nextcloud that calls APC in the CLI as well. Thanks for your help

~~I’ll wait another day to see if the original issue is fixed now. And if so, mark the thread as solved.~~I haven’t seen this issue resurrect in over two weeks, so I consider it solved.