Intermittent "500 Internal Server Error" with Snap and DigitalOcean S3

[elsiehupp]

Nextcloud version: latest from snap
Operating system and version: Ubuntu 20.04.1 LTS DigitalOcean Droplet
Apache or nginx version: idk (latest from snap)
PHP version: 7.3.21 (latest from snap)

The issue you are facing: When accessing the web UI or syncing the desktop app, some portion of web requests or sync events result in a 500 internal server error, while others go through.

I should emphasize: I am using extremely close to a vanilla install of Nextcloud via Snap. The only configuration change I’ve made outside of the web GUI is setting up S3-style object storage in config.php.

Is this the first time you’ve seen this error? (Y/N): I’ve been seeing this since I started using Nextcloud a couple of days ago.

Steps to replicate it:

1. Load the website or sync the desktop app
2. Sometimes it works
3. Sometimes it doesn’t

The output of your Nextcloud log in Admin > Logging:

Doctrine\DBAL\DBALException: Failed to connect to the database: An exception occurred in driver: SQLSTATE[HY000] [2002] Connection refused

… (a ton of times)

Cannot modify header information - headers already sent by (output started at /snap/nextcloud/23171/htdocs/3rdparty/sabre/http/lib/Sapi.php:132) at /snap/nextcloud/23171/htdocs/apps/dav/lib/Connector/Sabre/File.php#683

… (a ton of times)

Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'SELECT `filecache`.`fileid`, `storage`, `path`, `path_hash`, `filecache`.`parent`, `name`, `mimetype`, `mimepart`, `size`, `mtime`, `storage_mtime`, `encrypted`, `etag`, `permissions`, `checksum`, `metadata_etag`, `creation_time`, `upload_time` FROM `oc_filecache` `filecache` LEFT JOIN `oc_filecache_extended` `fe` ON `filecache`.`fileid` = `fe`.`fileid` WHERE (`storage` = ?) AND (`path_hash` = ?)' with params [5, "1c9a1f36871f482d14da9061032b6b52"]: SQLSTATE[HY000]: General error: 2006 MySQL server has gone away

I have reams and reams and reams of error messages, but the first one is most common.

The output of your config.php file in /var/snap/nextcloud/23171/nextcloud/config/config.php:

<?php
$CONFIG = array (
  'apps_paths' => 
  array (
    0 => 
    array (
      'path' => '/snap/nextcloud/current/htdocs/apps',
      'url' => '/apps',
      'writable' => false,
    ),
    1 => 
    array (
      'path' => '/var/snap/nextcloud/current/nextcloud/extra-apps',
      'url' => '/extra-apps',
      'writable' => true,
    ),
  ),
  'supportedDatabases' => 
  array (
    0 => 'mysql',
  ),
  'memcache.locking' => '\\OC\\Memcache\\Redis',
  'memcache.local' => '\\OC\\Memcache\\Redis',
  'redis' => 
  array (
    'host' => '/tmp/sockets/redis.sock',
    'port' => 0,
  ),
  'passwordsalt' => [redacted],
  'secret' => [redacted],
  'trusted_domains' => 
  array (
    0 => 'localhost',
    1 => 'cloud.elsiehupp.com',
  ),
  'datadirectory' => '/var/snap/nextcloud/common/nextcloud/data',
  'dbtype' => 'mysql',
  'version' => '19.0.3.1',
  'overwrite.cli.url' => 'http://localhost',
  'dbname' => 'nextcloud',
  'dbhost' => 'localhost:/tmp/sockets/mysql.sock',
  'dbport' => '',
  'dbtableprefix' => 'oc_',
  'mysql.utf8mb4' => true,
  'dbuser' => 'nextcloud',
  'dbpassword' => [redacted]
  'installed' => true,
  'instanceid' => [redacted],
  'maintenance' => false,
  'objectstore' => 
  array (
    'class' => '\\OC\\Files\\ObjectStore\\S3',
    'arguments' => 
    array (
      'bucket' => 'cloud.elsiehupp',
      'key' => [redacted],
      'secret' => [redacted],
      'hostname' => 'nyc3.digitaloceanspaces.com',
      'region' => 'nyc3',
      'port' => 443,
      'use_ssl' => true,
      'use_path_style' => true,
    ),
  ),
);

Note that the only thing I’ve changed from the default is the trusted domains and the 'objectstore' => array (...) at the end.

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

Oct  1 18:22:48 cloud kernel: [533943.648004] [UFW BLOCK] IN=eth0 OUT= MAC=b2:79:f0:ff:44:a8:80:7f:f8:66:e8:30:08:00 SRC=185.202.2.72 DST=104.131.77.207 LEN=48 TOS=0x00 PREC=0x00 TTL=114 ID=22344 DF PROTO=TCP SPT=2918 DPT=3389 WINDOW=8192 RES=0x00 SYN URGP=0 
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: State 'stop-sigterm' timed out. Killing.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029093 (mysqld_safe) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029327 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029328 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029329 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029330 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029331 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029332 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029333 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029334 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029335 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029336 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029337 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029338 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029339 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029342 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029343 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029344 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029345 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029346 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029347 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029348 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029349 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029350 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029351 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029352 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029353 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029354 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Killing process 3029355 (mysqld) with signal SIGKILL.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Failed with result 'timeout'.
Oct  1 18:22:58 cloud systemd[1]: snap.nextcloud.mysql.service: Scheduled restart job, restart counter is at 7706.
Oct  1 18:22:58 cloud systemd[1]: Stopped Service for snap application nextcloud.mysql.
Oct  1 18:22:58 cloud systemd[1]: Started Service for snap application nextcloud.mysql.
Oct  1 18:22:58 cloud nextcloud.mysql[3029395]: 2020-10-01T18:22:58.907391Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
Oct  1 18:22:58 cloud nextcloud.mysql[3029395]: 2020-10-01T18:22:58.908116Z 0 [ERROR] --initialize specified but the data directory has files in it. Aborting.
Oct  1 18:22:58 cloud nextcloud.mysql[3029395]: 2020-10-01T18:22:58.908757Z 0 [ERROR] Aborting
Oct  1 18:22:58 cloud kernel: [533954.539112] audit: type=1400 audit(1601576578.923:16087): apparmor="DENIED" operation="exec" profile="snap.nextcloud.mysql" name="/bin/systemctl" pid=3029411 comm="mysql.server" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Oct  1 18:22:58 cloud nextcloud.mysql[3029397]: Starting MySQL
Oct  1 18:22:58 cloud nextcloud.mysql[3029397]:  *
Oct  1 18:22:58 cloud nextcloud.mysql[3029367]: Checking/upgrading mysql tables if necessary...
Oct  1 18:22:58 cloud nextcloud.mysql[3029422]: mysql_upgrade: Got error: 2002: Can't connect to local MySQL server through socket '/tmp/sockets/mysql.sock' (111) while connecting to the MySQL server
Oct  1 18:22:58 cloud nextcloud.mysql[3029422]: Upgrade process encountered error and will not continue.
Oct  1 18:22:59 cloud kernel: [533954.659614] audit: type=1400 audit(1601576579.043:16088): apparmor="DENIED" operation="exec" profile="snap.nextcloud.mysql" name="/bin/systemctl" pid=3029517 comm="mysql.server" requested_mask="x" denied_mask="x" fsuid=0 ouid=0
Oct  1 18:22:59 cloud nextcloud.mysql[3029437]:  * MySQL server process #3029327 is not running!
Oct  1 18:23:07 cloud kernel: [533963.286876] [UFW BLOCK] IN=eth0 OUT= MAC=b2:79:f0:ff:44:a8:80:7f:f8:66:e8:30:08:00 SRC=212.70.149.83 DST=104.131.77.207 LEN=60 TOS=0x00 PREC=0x00 TTL=56 ID=45315 DF PROTO=TCP SPT=33940 DPT=25 WINDOW=29200 RES=0x00 SYN URGP=0 

(The above is repeated over and over again.)

It certainly looks like the error has something to do with MySQL, but, again, this is basically a vanilla install from Snap.

[elsiehupp]

I should clarify that there is plenty of other stuff in the Nextcloud client logs. There’s just so much material that I don’t know what would be useful for me to share.

[Roenix]

Your problem looks a lot like what I’m experiencing, though I’m on a bare metal ubuntu server with the snap.

This is my post:

Repeated error DeadlockException and very slow sync

Nextcloud version: 19.0.3 (snap) Operating system and version: Ubuntu 18.04 (snap) Apache or nginx version: Apache 2.4.46 PHP version: 7.3.21 The issue you are facing: Repeated fatal errors in log when syncing large changes with many small files. Sync when moving a 1.3Gb folder with many small files takes more than a day. Nextcloud client on syncing desktop sometimes hangs. Restarting the server helps for a while. I am in doubt whether to report this to nextcloud or the nextcloud ubuntu s…

I’ve noticed I get a lot of these failures when I sync a CryFS encrypted folder, which tens of thousands of small files to be synced.

Another thing I’ve thought about is the fact that I bind mount a data partition under /var/snap/nextcloud/common/nextcloud/data

Hope your issues get fixed. Let me know if something works for you and if you recognize the issue correlates with very heavy syncs of lot’s of small files.

[elsiehupp]

I’m getting the 500 Internal Server Errors on all sorts of files, not just small ones, but I’m uploading tens or hundreds of thousands of files (eventually hundreds of gigabytes), and the repeated interruptions are slowing things down pretty dramatically. (I’m migrating from iCloud Drive because I just switched my second computer from Windows to Ubuntu, and Apple hasn’t seen fit to release a Linux client.)

[Roenix]

At the moment Nextcloud works fine for normal workloads again for me. But for migrating a lot of files I choose not to upload via the webclient or sync client, but put the files directly in the data directory on the server and then forced Nextcloud to reindex the files with the command:

sudo nextcloud.occ files:scan --all

See also:

Tutorial: How to migrate mass data to a new NextCloud server

Great post I have needed to do this with over 16gb of data a few times I never knew bout the console.php script to force a scan and update the database so I always spent a few days using the sync app for each user. In the owncloud days (and i think in the early nextcloud versions) you use to be able to just copy the data to the webroot data folder and it would just work but this option was removed a few years ago for reasons I never understood. Just an fyi rather than running ls to check the pr…

This worked for me, although I consider it a workaround, not a definitive solution to the errors.

[elsiehupp]

migrating a lot of files I choose not to upload via the webclient or sync client, but put the files directly in the data directory on the server and then forced Nextcloud to reindex the files

Unfortunately I can’t do this, as I am using off-site object storage, which isn’t directly exposed as a file system.

[elsiehupp]

Apparently this is, in fact, a bug related to MySQL that is unique to nextcloud-snap:

mysql: ensure mysqld responds before considering it up