Server: Continuous HTTP error 412 on PUT requests to the address book

[CamZie]

Steps to reproduce

1. use Mac OS X 10.13 as the client for the Contacts app (AddressBook/1806)
2. Synchronise your Contacts with the Nextcloud contacts app

Expected behaviour

No 412 HTTP error should appear and the load on the server should not go higher.

Actual behaviour

Continuous HTTP 412 PUT response for an address book (see below "Web-server access log"), which causes a high load on the database and takes up more server resource than it should.

We also noticed the errors in the nextcloud.log (see below "Nextcloud log"), which appears every 30 seconds. We are not sure if this is related to the 412 PUT responses.

I have opened this issue first on nextcloud/contacts, which is already discussed and debugged: https://github.com/nextcloud/contacts/issues/434

Server configuration

Operating system: Debian 9.1 (stretch)

Web server: Nginx 1.10.3

Database: MySQL 5.8

PHP version: 7

Nextcloud version: 12.0.2

Contacts version: 2.0.1

Updated from an older Nextcloud or fresh install: Updated from Nextcloud version 12

Signing status:

No errors have been found.

List of activated apps:

Enabled:
  - activity: 2.5.2
  - admin_audit: 1.2.0
  - calendar: 1.5.6
  - comments: 1.2.0
  - contacts: 2.0.1
  - dav: 1.3.0
  - encryption: 1.6.0
  - federatedfilesharing: 1.2.0
  - federation: 1.2.0
  - files: 1.7.2
  - files_pdfviewer: 1.1.1
  - files_sharing: 1.4.0
  - files_texteditor: 2.4.1
  - files_trashbin: 1.2.0
  - files_videoplayer: 1.1.0
  - gallery: 17.0.0
  - logreader: 2.0.0
  - lookup_server_connector: 1.0.0
  - nextcloud_announcements: 1.1
  - notes: 2.3.1
  - notifications: 2.0.0
  - oauth2: 1.0.5
  - password_policy: 1.2.2
  - provisioning_api: 1.2.0
  - serverinfo: 1.2.0
  - sharebymail: 1.2.0
  - survey_client: 1.0.0
  - systemtags: 1.2.0
  - tasks: 0.9.5
  - twofactor_backupcodes: 1.1.1
  - updatenotification: 1.2.0
  - workflowengine: 1.2.0

Nextcloud configuration:

{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "dbtype": "mysql",
        "version": "12.0.2.0",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "localhost",
        "dbtableprefix": "oc_",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "installed": true,
        "forcessl": true,
        "theme": "***REMOVED SENSITIVE VALUE***",
        "enable_previews": true,
        "enable_avatars": false,
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "smtp",
        "log_authfailip": true,
        "loglevel": 2,
        "maintenance": false,
        "customclient_desktop": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "***REMOVED SENSITIVE VALUE***"
        ],
        "share_folder": "\/Shared",
        "overwritewebroot": "\/",
        "overwriteprotocol": "https",
        "secret": "***REMOVED SENSITIVE VALUE***",
        "singleuser": false,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "trashbin_retention_obligation": "auto,30",
        "activity_expire_days": 14,
        "logtimezone": "Europe\/Zurich",
        "log_type": "errorlog",
        "skeletondirectory": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/***REMOVED SENSITIVE VALUE***"
    }
}

Are you using encryption: yes

Client configuration

Operating system: Mac OS X/10.13.1

CardDAV-clients: Apple contacts

Logs

Web server access log

***REMOVED SENSITIVE VALUE*** - ***REMOVED SENSITIVE VALUE*** [13/Nov/2017:10:36:30 +0100] "PUT /remote.php/carddav/addressbooks/***REMOVED SENSITIVE VALUE***/Contacts/a3ab6572-e87f-4796-9e5f-2fec6bc8876e.vcf HTTP/1.1" 412 332 "-" "Mac OS X/10.13.1 (17B48) AddressBook/1806"
***REMOVED SENSITIVE VALUE*** - ***REMOVED SENSITIVE VALUE*** [13/Nov/2017:10:36:30 +0100] "PUT /remote.php/carddav/addressbooks/***REMOVED SENSITIVE VALUE***/Contacts/aa162dfd-a56d-4184-8f73-9bca641965a9.vcf HTTP/1.1" 412 332 "-" "Mac OS X/10.13.1 (17B48) AddressBook/1806"
***REMOVED SENSITIVE VALUE*** - ***REMOVED SENSITIVE VALUE*** [13/Nov/2017:10:36:30 +0100] "PUT /remote.php/carddav/addressbooks/***REMOVED SENSITIVE VALUE***/Contacts/29c6c947-f1a7-42e4-a655-2ba42e30b999.vcf HTTP/1.1" 412 332 "-" "Mac OS X/10.13.1 (17B48) AddressBook/1806"

Nextcloud log (data/nextcloud.log)

2017/11/13 10:35:33 [error] 497#497: *2192260 FastCGI sent in stderr: "PHP message: [owncloud][carddav][4] Exception: {"Exception":"Sabre\\DAV\\Exception\\InvalidSyncToken","Message":"Invalid or unknown sync token","Code":0,"Trace":"#0 \/var\/www\/nextcloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Sync\/Plugin.php(65): Sabre\\DAV\\Sync\\Plugin->syncCollection('addressbooks\/st...', Object(Sabre\\DAV\\Xml\\Request\\SyncCollectionReport))\n#1 [internal function]: Sabre\\DAV\\Sync\\Plugin->Sabre\\DAV\\Sync\\{closure}('{DAV:}sync-coll...', Object(Sabre\\DAV\\Xml\\Request\\SyncCollectionReport), 'addressbooks\/st...')\n#2 \/var\/www\/nextcloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Object(Closure), Array)\n#3 \/var\/www\/nextcloud\/3rdparty\/sabre\/dav\/lib\/DAV\/CorePlugin.php(718): Sabre\\Event\\EventEmitter->emit('report', Array)\n#4 [internal function]: Sabre\\DAV\\CorePlugin->httpReport(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#5 \/var\/www\/nextcloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func" while reading response header from upstream, client: ***REMOVED SENSITIVE VALUE***, server: ***REMOVED SENSITIVE VALUE***, request: "REPORT /remote.php/carddav/addressbooks/***REMOVED SENSITIVE VALUE***/Contacts/ HTTP/1.1", upstream: "fastcgi://unix:/var/run/php-fpm.sock:", host: "***REMOVED SENSITIVE VALUE***"

Browser log

nothing relevant

[MorrisJobke]

It looks like the authentication token is not valid anymore: Invalid or unknown sync token

[hostingnuggets]

@MorrisJobke do you think Apple has messed up their Contacts app since Mac OS 10.13? With Mac OS X/10.13.2 (17C88) AddressBook/1808.6 I still see the same behaviour (non-stop PUT requests generating 412 errors and high load on the server side). As with the time more and more people are upgrading to 10.13 I can see more and more load due to more such PUT requests.

[MorrisJobke]

cc @georgehrke is this the same as #7519? @hostingnuggets Maybe try https://github.com/nextcloud/server/issues/7519#issuecomment-360936289 for the CardDAV setup?

[georgehrke]

cc @georgehrke is this the same as #7519?

Not exactly, because that bug didnt even allow you add the CalDAV/CardDAV account.
Nonetheless the workaround could help here too.

[georgehrke]

"macOS address book" spamming the server with requests is probably a result of the Sabre\\DAV\\Exception\\InvalidSyncToken exception.
The client thinks that changes previously made were not saved properly, so it tries to save them again.

Now the question is, why does the InvalidSyncToken exception occur. Would be very helpful to get a capture of the REPORT request sent by the client.

[Rello]

same for me on 10.13.3

as a result, Mac OS tries to push the change every 30 seconds again and again.

the error is also reflected in the nginx error log
FastCGI sent in stderr: "Primary script unknown" while reading response header from upstream, client: 91.64.56.111, server: webserver, request: "REPORT /owncloud/remote.php/dav/addressbooks/users/***/contacts/ HTTP/1.1", upstream: "fastcgi://unix:/var/run/php/php7.0-fpm.sock:", host: "***"

@georgehrke how to get a capture of the REPORT? wireshark, or what do you mean?

[Rello]

one additional finding: the Session-Folder of php is flooded with a session-file for every single request (Pfofind, put, report, options, ...).
could this be a hint? it seems to loose the session in between a roundtrip?

exception thrown is this one
https://github.com/nextcloud/3rdparty/blob/e42a129bf8c10cf9e519cc9e4a0e6978bbcd7e59/sabre/dav/lib/DAV/Sync/Plugin.php#L123

[Rello]

one more comment here:

I removed the CalDav Account and recreated it in macOS. then the error is gone. so it might have been some hick-up?

the only issue I had: I needed to add a Caldav-Manual with the long url as server address:
https://***/nextcloud/remote.php/dav/addressbooks/users/***/
despite having all the .well-known redirects setup, it never worked for me with the direct url

[ppaeps]

The .well-known redirects always worked for me provided that I also set up a redirect from port 8443 to port 443.

I think the way forward is to try to capture a REPORT in tcpdump. This is a bit frustrating on my setup because everything is under TLS. If someone has a non-TLS setup, that may be easier.

[m3nu]

I can confirm this. macOS works when port 8443 is set up, but doesn't update contacts when it's not set up.

[georgehrke]

@m3nu Does it work for you if you set it up like described in https://github.com/nextcloud/server/issues/7519#issuecomment-360936289?

(without port 8443)

[hostingnuggets]

@ppaeps could you show us an excerpt of your nginx/apache config where you have set up this port 8443 to port 443 redirection? or is this documented somewhere in the official Nextcloud docs?

[ppaeps]

@hostingnuggets I simply have the packet filter rewrite packets for port 8443 to port 443 so I don't have to do anything in the nginx configuration. I use pf on FreeBSD. I'm sure you can do this on other operating systems too. From my /etc/pf.conf:

rdr pass on $internet proto tcp from any to $nextcloud port 8443 -> $nextcloud port 443

I don't know if this is in the Nextcloud documentation. This has been in my configuration since before I used Nextcloud (or ownCloud). It may have come from other CalDAV documentation from the mists of time.

[hostingnuggets]

@ppaeps thanks for the example, we also use pf on our firewall so I added the redirection but I must say that this does not change anything to the problem of having continuous 412 PUT requests from people using the MacOS addressbook. So the problem still persists...

[hostingnuggets]

Any progress on this issue anyone?

[georgehrke]

As i said earlier, no one of us can reproduce it and we need the Capture (Wireshark / Charles) of the communication that happens there. (Some couple of requests including the REPORT and PUT) Otherwise I can’t fix this.

[hostingnuggets]

@georgehrke so if I understand you correctly, you are saying here that you have setup a test environment replicating the same server configuration as mentioned by @CamZie and you tested it with the same Mac OS X Contacts app version and for you it works without any problems?

[ppaeps]

@georgehrke I have a packet capture of a lot of traffic from my personal server. Not a test system, so I'm reluctant to upload it somewhere. Some snippets that may help follow:

09:58:41.784439 AF IPv4 (2), length 1313: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 1309, bad cksum 0 (->bbb6)!)
    172.16.17.2.http > 172.16.17.2.31053: Flags [P.], cksum 0x7f34 (incorrect -> 0x68de), seq 1:1258, ack 16333, win 1276, options [nop,nop,TS val 1913846334 ecr 1159124493], length 1257: HTTP, length: 1257
        HTTP/1.1 412 Precondition failed
        Server: nginx/1.12.2
        Date: Thu, 15 Mar 2018 09:58:41 GMT
        Content-Type: application/xml; charset=utf-8
        Connection: close
        X-Powered-By: PHP/7.0.27
        Expires: Thu, 19 Nov 1981 08:52:00 GMT
        Cache-Control: no-store, no-cache, must-revalidate
        Pragma: no-cache
        Set-Cookie: oc_sessionPassphrase=elided; path=/cloud; secure; HttpOnly
        X-Frame-Options: SAMEORIGIN
        Set-Cookie: nc_sameSiteCookielax=true; path=/cloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=lax
        Set-Cookie: nc_sameSiteCookiestrict=true; path=/cloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=strict
        Content-Security-Policy: default-src 'none';
        Set-Cookie: elided; path=/cloud; secure; HttpOnly
        ETag: "7ce146967cea902cfe6af78a351759f0"

        <?xml version="1.0" encoding="utf-8"?>
        <d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
          <s:exception>Sabre\DAV\Exception\PreconditionFailed</s:exception>
          <s:message>An If-Match header was specified, but none of the specified the ETags matched.</s:message>
          <s:header>If-Match</s:header>
        </d:error>

This is what a REPORT looks like:

09:58:42.137762 AF IPv4 (2), length 772: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 768, bad ck
sum 0 (->bdd3)!)
    172.16.17.2.31059 > 172.16.17.2.http: Flags [P.], cksum 0x7d17 (incorrect -> 0x39ba), seq 1:717, ack 1, win 1276, op
tions [nop,nop,TS val 1159124912 ecr 3713529066], length 716: HTTP, length: 716
        REPORT /remote.php/dav/addressbooks/users/elided/contacts/ HTTP/1.0
        X-Forwarded-Proto: https
        X-Real-IP: elided
        X-Forwarded-For: elided
        Host: 172.16.17.2
        Connection: close
        Content-Length: 236
        Accept: */*
        Brief: t
        Authorization: Basic elided
        Accept-Language: en-gb
        Accept-Encoding: br, gzip, deflate
        Content-Type: text/xml
        Depth: 1
        User-Agent: Mac OS X/10.13.3 (17D102) AddressBook/1808.6
        Prefer: return=minimal

        <?xml version="1.0" encoding="UTF-8"?>
        <A:sync-collection xmlns:A="DAV:">
          <A:sync-token>82ef57b0-bcad-4d57-809a-d5c78c10c639</A:sync-token>
          <A:sync-level>1</A:sync-level>
          <A:prop>
            <A:getetag/>
          </A:prop>
        </A:sync-collection>

The REPORT is followed by 401 Unauthorized. Which is odd since it has an Authorization: header. The 401 is:

09:58:42.150059 AF IPv4 (2), length 1415: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 1411, bad cksum 0 (->bb50)!)
    172.16.17.2.http > 172.16.17.2.31057: Flags [P.], cksum 0x7f9a (incorrect -> 0xb61b), seq 1:1360, ack 543, win 1276, options [nop,nop,TS val 3987188303 ecr 1159124903], length 1359: HTTP, length: 1359
        HTTP/1.1 401 Unauthorized
        Server: nginx/1.12.2
        Date: Thu, 15 Mar 2018 09:58:42 GMT
        Content-Type: application/xml; charset=utf-8
        Connection: close
        X-Powered-By: PHP/7.0.27
        Set-Cookie: elided; path=/cloud; secure; HttpOnly
        Expires: Thu, 19 Nov 1981 08:52:00 GMT
        Cache-Control: no-store, no-cache, must-revalidate
        Pragma: no-cache
        Set-Cookie: oc_sessionPassphrase=elided; path=/cloud; secure; HttpOnly
        X-Frame-Options: SAMEORIGIN
        Set-Cookie: nc_sameSiteCookielax=true; path=/cloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=lax
        Set-Cookie: nc_sameSiteCookiestrict=true; path=/cloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=strict
        Content-Security-Policy: default-src 'none';
        WWW-Authenticate: Basic realm="Nextcloud"

        <?xml version="1.0" encoding="utf-8"?>
        <d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
          <s:exception>Sabre\DAV\Exception\NotAuthenticated</s:exception>
          <s:message>No 'Authorization: Basic' header found. Either the client didn't send one, or the server is misconfigured, No 'Authorization: Bearer' header found. Either the client didn't send one, or the server is mis-configured</s:message>
        </d:error>

It's then immediately followed by 403 Forbidden:

09:58:42.191579 AF IPv4 (2), length 1324: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto TCP (6), length 1320, bad
cksum 0 (->bbab)!)
    172.16.17.2.http > 172.16.17.2.31059: Flags [P.], cksum 0x7f3f (incorrect -> 0x19cd), seq 1:1269, ack 717, win 1276,
 options [nop,nop,TS val 3713529120 ecr 1159124912], length 1268: HTTP, length: 1268
        HTTP/1.1 403 Forbidden
        Server: nginx/1.12.2
        Date: Thu, 15 Mar 2018 09:58:42 GMT
        Content-Type: text/html; charset=UTF-8
        Connection: close
        Vary: Accept-Encoding
        X-Powered-By: PHP/7.0.27
        Set-Cookie: elided; path=/cloud; secure; HttpOnly
        Expires: Thu, 19 Nov 1981 08:52:00 GMT
        Cache-Control: no-store, no-cache, must-revalidate
        Pragma: no-cache
        Set-Cookie: oc_sessionPassphrase=elided; path=/cloud; secure; HttpOnly
        Content-Security-Policy: default-src 'self'; script-src 'self' 'unsafe-eval' 'nonce-elided'; style-src 'self' 'unsafe-inline'; frame-src *; img-src * data: blob:; font-src 'self' data:; media-src *; connect-src *; object-src 'none'; base-uri 'self';
        X-Frame-Options: SAMEORIGIN
        Set-Cookie: nc_sameSiteCookielax=true; path=/cloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=lax
        Set-Cookie: nc_sameSiteCookiestrict=true; path=/cloud; httponly;secure; expires=Fri, 31-Dec-2100 23:59:59 GMT; SameSite=strict
        Location: elided

It looks like the If-Match and ETags are an immediate problem. I'm not sure where the 401/403 come from. I could email you the packet capture but maybe you could tell me what else I could look for?

[ppaeps]

Could this be slightly related to #6657?

I tried setting gzip off in my nginx configurations to try to get the ETag headers to go away but that does not appear to make any difference as far as I can tell.

I don't actually understand how DAV works so I'll let someone with actual clue comment before I poke at my setup enough to break it. ;)

[hostingnuggets]

A short update to mention that this problem still occurs with the latest Mac OS X and AddressBook/Contact app. That would be this specific user agent:

Mac OS X/10.13.4 (17E199) AddressBook/1808.7

[ppaeps]

@georgehrke : was that packet capture helpful at all? The problem still exists with 13.0.1. I'm happy to help debug further or test patches. Thanks.

[RandieM]

I can also confirm this behaviour with High Sierra. For each new contact on the Mac address book, I get several PUT requests with status code 412 and finally a REPORT with 403. I also get 401 responses on OPTIONS and PROPFIND.

[RandieM]

Any updates on this?

[Rello]

Hello,
any news on this - in my opinion pretty crucial - issue?
Isn´t this one of the core features of NC?

I am really suffering. New additions seem to be added on my side, but no updates anymore. nextcloud.log is flooded...

[andreaspollak]

I can also confirm this problem, while testing nextcloud 13.04.
My problems gone, after following configuration changes (nginx).

Configuration used:
https://www.fox1.de/2017/03/15/nextcloud-ispconfig3-debian3-nginx/ (german)

changed from
fastcgi_intercept_errors on;
to
fastcgi_intercept_errors off;

nginx log:
...
"REPORT /remote.php/dav/addressbooks/users/testuser/contacts/ HTTP/1.1" 207 285 "-" "Mac OS X/10.13.5 (17F77) AddressBook/1808.7"
...

I've changed multiple contacts on multiple devices and it's working now as expected!

[ppaeps]

@andreaspollak I can confirm that setting fastcgi_intercept_errors off also appears to make the problem go away on my setup.

Thank you for figuring this out!

[ppaeps]

I spent a little more time on this, and it turns out that removing the error_page directives from nginx also makes the problem go away. Since the error_page templates no longer exist and configuring them breaks things, maybe the documentation should be fixed?

[hostingnuggets]

@ppaeps where do you see the error_page nginx config parameter I can't find it anywhere in the official doc (https://docs.nextcloud.com/server/13/admin_manual/installation/nginx.html) ?

For me turning fastcgi_intercept_errors to off unfortunately does not make the 412 errors disappear. It does not change anything.

[ppaeps]

I suspect the documentation has been updated a while back (possibly when the templates went away). I did not check the commit logs.

On my setup, setting fastcgi_intercept_errors back to on, and removing the error_page directives made the problem of 412 errors go away. Setting fastcgi_intercept_errors to off also made it go away, but I'm not sure what other consequences that may have.

[RandieM]

The fastcgi_intercept_errors "trick" unfortunately did no help me either.

@ppaeps, FYI the web server-related documentation was updated shortly after this conversation: https://github.com/nextcloud/server/issues/3307. It never became clear to me what these error lines were really doing and if it was actually a good idea to yank them from the configuration.

So in the past, there were error pages for 403 and 404 status codes in the NGINX configuration, but I do not recall anything related to 412, so I am also having trouble understanding how these lines would be relevant to this.

[skjnldsv]

Can you all make sure your settings screen looks like this?
This is a working instance.

[MorrisJobke]

As there is no report since a while and we can't reproduce the issue I will close this ticket. If this is still happening please feel free to reopen.

[tscheiby]

To me it turned out to be an nginx config error: i had custom 403 and 401 Pages defined in the server section of my NC config.

Seen backwards the problem expresses like this:

• 10.13 client sends one or multiple puts with wrong (outdated) etags to update Contact entries. This happens because initially it tries to update etags with a sync-collection request that has failed so there are no updates. The if-match fails correctly, Precondition fails.

• Before a sync-collection request is successful it needs a valid sync token and the request to get a sync token leads to a 403 if outdated, or better the error tells it the tokin is invalid and it would have to be renewed.

• If nginx intercepts with a custom page the client won't continue to get a sync token, the response does not contain valid xml

• next the client then tries to put the changed objects anyways but the etags are wrong, server rejects.

Here the process is described in detail.

So to sum it up the error happens indirect, seeminly not related but indeed happens because of intercepted 403 responses by nginx.