Lots of SABRE errors, NC to slow to use

[/details]

Nextcloud version (eg, 20.0.5): 23.0.0 RC3 and 22.2.2
Operating system and version (eg, Ubuntu 20.04): Ubuntu 20 LTS
Apache or nginx version (eg, Apache 2.4.25): nginx latest
PHP version (eg, 7.4): 7.4

The issue you are facing:

My NC instance has been incredibly slow for about a week now. First I thought it had something to do with the host. Load average was above 3 sometimes. I did some troubleshooting and disabled THP. Dunno if that was the only thing, but the load average is now at ~0.1 again. Performance is still so slow that my NC is not usable anymore.

I even upgraded to 23, to see if that fixed anything: same as on 22.

As far as I know I did not change anything on my server to cause this. (3 core, 4GB, 2 users)

Is this the first time you’ve seen this error? (Y/N): yes

Steps to replicate it: dunno

The output of your Nextcloud log in Admin > Logging:

Error	no app in context	Sabre\DAV\Exception\BadRequest: Expected filesize of 5994903 bytes but read (from Nextcloud client) and wrote (to Nextcloud storage) 229376 bytes. Could either be a network problem on the sending side or a problem writing to the storage on the server side.

    /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php - line 155:

    OCA\DAV\Connector\Sabre\File->put()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 1098:

    OCA\DAV\Connector\Sabre\Directory->createFile()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 504:

    Sabre\DAV\Server->createFile()

    /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php - line 89:

    Sabre\DAV\CorePlugin->httpPut()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 472:

    Sabre\DAV\Server->emit()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 253:

    Sabre\DAV\Server->invokeMethod()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 321:

    Sabre\DAV\Server->start()

    /var/www/nextcloud/apps/dav/appinfo/v1/webdav.php - line 83:

    Sabre\DAV\Server->exec()

    /var/www/nextcloud/remote.php - line 166:

    require_once("/var/www/ne ... p")

AND

Warning	no app in context	External storage not available: Sabre\HTTP\ClientException: Failed to connect to 145.132.12.252 port 8443: Connection timed out

AND

Fatal	webdav	Sabre\VObject\ParseException: This parser only supports VCARD and VCALENDAR files

    /var/www/nextcloud/3rdparty/sabre/vobject/lib/Parser/MimeDir.php - line 90:

    Sabre\VObject\Parser\MimeDir->parseDocument()

    /var/www/nextcloud/3rdparty/sabre/vobject/lib/Reader.php - line 47:

    Sabre\VObject\Parser\MimeDir->parse()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/CardDAV/Plugin.php - line 808:

    Sabre\VObject\Reader::read()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/CardDAV/Plugin.php - line 244:

    Sabre\CardDAV\Plugin->convertVCard()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/CardDAV/Plugin.php - line 189:

    Sabre\CardDAV\Plugin->addressbookMultiGetReport()

    /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php - line 89:

    Sabre\CardDAV\Plugin->report()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 685:

    Sabre\DAV\Server->emit()

    /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php - line 89:

    Sabre\DAV\CorePlugin->httpReport()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 472:

    Sabre\DAV\Server->emit()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 253:

    Sabre\DAV\Server->invokeMethod()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 321:

    Sabre\DAV\Server->start()

    /var/www/nextcloud/apps/dav/lib/Server.php - line 339:

    Sabre\DAV\Server->exec()

    /var/www/nextcloud/apps/dav/appinfo/v2/remote.php - line 35:

    OCA\DAV\Server->exec()

    /var/www/nextcloud/remote.php - line 166:

    require_once("/var/www/ne ... p")

AND

Fatal	webdav	Sabre\VObject\ParseException: This parser only supports VCARD and VCALENDAR files

    /var/www/nextcloud/3rdparty/sabre/vobject/lib/Parser/MimeDir.php - line 90:

    Sabre\VObject\Parser\MimeDir->parseDocument()

    /var/www/nextcloud/3rdparty/sabre/vobject/lib/Reader.php - line 47:

    Sabre\VObject\Parser\MimeDir->parse()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/CardDAV/Plugin.php - line 808:

    Sabre\VObject\Reader::read()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/CardDAV/Plugin.php - line 244:

    Sabre\CardDAV\Plugin->convertVCard()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/CardDAV/Plugin.php - line 189:

    Sabre\CardDAV\Plugin->addressbookMultiGetReport()

    /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php - line 89:

    Sabre\CardDAV\Plugin->report()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 685:

    Sabre\DAV\Server->emit()

    /var/www/nextcloud/3rdparty/sabre/event/lib/WildcardEmitterTrait.php - line 89:

    Sabre\DAV\CorePlugin->httpReport()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 472:

    Sabre\DAV\Server->emit()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 253:

    Sabre\DAV\Server->invokeMethod()

    /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 321:

    Sabre\DAV\Server->start()

    /var/www/nextcloud/apps/dav/lib/Server.php - line 339:

    Sabre\DAV\Server->exec()

    /var/www/nextcloud/apps/dav/appinfo/v2/remote.php - line 35:

    OCA\DAV\Server->exec()

    /var/www/nextcloud/remote.php - line 166:

    require_once("/var/www/ne ... p")

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

<?php
$CONFIG = array (
  'blacklisted_files' =>

  array (
    0 => '.htaccess',
    1 => 'Thumbs.db',
    2 => 'thumbs.db',
  ),
  'instanceid' => 'xxx',
  'passwordsalt' => 'xxx',
  'secret' => 'xxx',
  'trusted_domains' =>
  array (
    0 => 'redacted.redacted',
  ),
  'datadirectory' => '/var/nc_data/',
  'overwrite.cli.url' => 'https://redacted.redacted',
  'dbtype' => 'pgsql',
  'version' => '23.0.0.9',
  'dbname' => 'nextcloud',
  'dbhost' => '127.0.0.1',
  'dbport' => '',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'REDACT',
  'dbpassword' => 'REDACT',
  'installed' => true,
  'enable_previews' => true,
  'filesystem_check_changes' => 0,
  'filelocking.enabled' => 'true',
  'htaccess.RewriteBase' => '/',
  'memcache.local' => '\\OC\\Memcache\\APCu',
  'preview_max_x' => 1024,
  'preview_max_y' => 768,
  'preview_max_scale_factor' => 1,
  'mail_from_address' => 'nextcloud',
  'mail_smtpmode' => 'smtp',
  'mail_smtpauthtype' => 'LOGIN',
  'mail_domain' => 'redacted',
  'maintenance' => false,
  'default_phone_region' => 'NL',
  'theme' => '',
  'loglevel' => 0,
  'mail_smtpsecure' => 'ssl',
  'mail_smtpauth' => 1,
  'mail_smtphost' => 'REDACT',
  'mail_smtpport' => '465',
  'mail_smtpname' => 'mark@redacted',
  'mail_smtppassword' => 'REDACT',
  'twofactor_enforced' => 'true',
  'twofactor_enforced_groups' =>
  array (
  ),
  'twofactor_enforced_excluded_groups' =>
  array (
  ),
  'mail_sendmailmode' => 'smtp',
  'app_install_overwrite' =>
  array (
    0 => 'calendar',
    1 => 'tasks',
    2 => 'radio',
    3 => 'occweb',
    4 => 'dicomviewer',
    5 => 'spreed',
    6 => 'passman',
    7 => 'social',
    8 => 'bruteforcesettings',
    9 => 'metadata',
    10 => 'rainloop',
  ),
  'updater.release.channel' => 'stable',
);


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


2021/12/01 00:01:59 [error] 599#599: *39318 open() "/usr/share/nginx/html/api/public/info" failed (2: No such file or directory), client: 23.183.81.102, server: redacted, request: "GET https://api.yagoal.co/api/public/info HTTP/1.1", host: "api.yagoal.co", referrer: "https://api.yagoal.co"
2021/12/01 00:06:15 [error] 599#599: *40405 open() "/usr/share/nginx/html/config/getuser" failed (2: No such file or directory), client: 198.98.49.124, server: redacted, request: "GET /config/getuser?index=0 HTTP/1.1", host: "redacted:80"
2021/12/01 00:14:00 [error] 599#599: *43006 open() "/usr/share/nginx/html/echo.php" failed (2: No such file or directory), client: 5.188.210.227, server: redacted, request: "GET http://5.188.210.227/echo.php HTTP/1.1", host: "5.188.210.227", referrer: "https://www.google.com/"

I used to use an external ical (or caldav) calendar for holidays and such. That no longer exists, I am not sure if I removed that link at some point. It does not show in my calender (when I am able to open it) app in any case.

I am going to take a look at that api.yagoal.co: I think that might be a hacking attempt?

Nextcloud error log:

2021/11/30 00:12:59 [error] 599#599: *33526 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 192.168.1.1, server: redacted, request: "PROPFIND /remote.php/dav/files/redacted//Redacted/IMG20210815113719.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock", host: "redacted"
2021/11/30 02:13:06 [error] 599#599: *34941 upstream timed out (110: Connection timed out) while sending request to upstream, client: 192.168.1.1, server: redacted, request: "PUT /remote.php/webdav/Foto%27s/21-08-05%2021-01-02%203016.jpg HTTP/2.0", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock", host: "redacted"
2021/11/30 02:13:59 [warn] 599#599: *34968 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/1/01/0000000011 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-05%2022-07-46%203017.mp4 HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 02:14:20 [warn] 599#599: *34978 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/2/01/0000000012 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-06%2018-34-37%203026.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 02:15:03 [warn] 599#599: *34968 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/3/01/0000000013 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-07%2012-13-14%203047.mov HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 02:23:40 [warn] 599#599: *35128 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/4/01/0000000014 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-07%2011-56-59%203045.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:06:35 [warn] 599#599: *35528 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/5/01/0000000015 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-07%2018-37-01%203064.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:06:46 [warn] 599#599: *35527 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/6/01/0000000016 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-07%2018-36-35%203062.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:06:58 [warn] 599#599: *35533 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/7/01/0000000017 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-07%2019-21-47%203065.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:07:09 [warn] 599#599: *35460 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/8/01/0000000018 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-07%2019-21-57%203066.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:20:49 [error] 599#599: *35769 upstream timed out (110: Connection timed out) while sending request to upstream, client: 192.168.1.1, server: redacted, request: "PUT /remote.php/webdav/Foto%27s/21-08-08%2008-01-30%203076.jpg HTTP/2.0", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock", host: "redacted"
2021/11/30 03:25:59 [error] 599#599: *35841 upstream timed out (110: Connection timed out) while sending request to upstream, client: 192.168.1.1, server: redacted, request: "PUT /remote.php/webdav/Foto%27s/21-08-08%2012-05-46%203085.jpg HTTP/2.0", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock", host: "redacted"
2021/11/30 03:26:50 [warn] 599#599: *35867 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/9/01/0000000019 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-08%2011-34-59%203081.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:27:20 [warn] 599#599: *35857 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/0/02/0000000020 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-08%2011-35-06%203082.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:28:35 [warn] 599#599: *35861 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/1/02/0000000021 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-08%2011-35-22%203083.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:38:47 [warn] 599#599: *35900 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/2/02/0000000022 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-08%2012-38-59%203091.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:39:03 [warn] 599#599: *35968 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/3/02/0000000023 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-08%2012-39-33%203094.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"
2021/11/30 03:39:19 [warn] 599#599: *35967 an upstream response is buffered to a temporary file /var/lib/nginx/fastcgi/4/02/0000000024 while reading upstream, client: 192.168.1.1, server: redacted, request: "GET /remote.php/dav/files/redacted/Redacted/21-08-08%2012-39-35%203095.jpg HTTP/1.1", upstream: "fastcgi://unix:/run/php/php7.4-fpm.sock:", host: "redacted"

Any thoughts as where I would have to start troubleshooting this?

Did you check what program/service is causing it, e.g. with htop or top?
I would also monitor Network activity if you are simply bombed with dummy requests.

As far as I could tell php-fpm was using most cpu. But that was still not nearly 100%. I am beginning to wonder if slow external storage could be the problem?

Also I am wondering if there is a way to check which contact (vcard) is corrupt? The contacts page does not seem to want to load at all most of the time now. And when it does I get “contact not found” whenever I click a contact. Syncing still seems to work though…

Since this week I see CPU loads of 100% sometimes on my NAS. Seems to be whenever Nextcloud is accessing files. Never had a load of more than 25% before last week.

I have all my files stored there and make them available via external storages via Nextcloud.

As I know, Contacts are saved in DB e.g. in oc_addressbooks, not on a storage at all.

I think so too. So I am thinking of two separate issues.

One: slow storage (is this the cause, or a result?)
Two: some kind of corruption in my address book or a single vcard…

Sure, if storage slow it could cause a lot of issues.

I believe you are using Contact App? Check with a Developer Tools - Network of your browser if requests are passing trough quick enough.
To check is REPORT to /remote.php/dav/addressbooks/users/USER/contacts/. Its delivers overview of all contacts and should be fast.

Then you can click on any contact it will retrieve data of it as PROPFIND to /remote.php/dav/addressbooks/users/USER/contacts/<uuid>.vcf (please ignore 404 on ...photo not all contact having them):

IDK how many contacts do you have, but if you click all of them you can may be find one that fails.

Alright, found out what was causing the terrible (non-existent) performance: Camera RAW Previews .

What happened: we where cleaning up pictures, moving them from “live” storage to SMB mounted External storage. When NC detected the new files on external storage the Camera RAW Previews app was generating previews for all the files (not just raw?) and overloading the NAS.

After removing Camera RAW Previews app my NAS load dropped back to 1%.

Still getting errors from the contacts app. I am also noticing that the avatars/pictures are not showing and are being generated every time I open the contacts app. Will look in to that when I have the time.

1 Like

Oh, thats cool! I have had similar issue with Recognize App, but it utilized Network a lot and didn’t hit my CPU limits: