Out of memory while uploading small files, seemingly caused by runaway SQL queries

Nextcloud version: 20.0.8
Operating system and version: CentOS 8.3.2011
Apache or nginx version: Apache HTTPD 2.4.37
PHP version: PHP-FPM 7.4.16

File uploads are failing since the upgrade to 20.0.8. The actual upload part works fine, but when it gets to assembling chunks, the php-fpm process suddenly eats an entire CPU and PostgreSQL eats another one. NextCloud seems to be sending the same query 55450 (!) times during file processing. PHP goes out of memory, eating a whopping 4GB when uploading a 30MB file. This seems to make very little sense.

I can reproduce this during every single file upload.

Unsure whether the upgrade to 20.0.8 caused this, or whether it was the upgrade to PHP 7.4.16, as these were executed on the same day.

PostgreSQL is logging gigabytes of SQL queries every hour. Which is insane, given that this is an instance with a handful of users and less than 10k files. Update statements to oc_filecache are repeated tens of thousands of times per file upload.

Here are couple of interesting logs:

Error log:

[26-Mar-2021 17:52:26 UTC] PHP Fatal error:  Allowed memory size of 4294967296 bytes exhausted (tried to allocate 12288 bytes) in /var/www/html/nextcloud/lib/private/Files/Storage/Wrapper/Encryption.php on line 862

Stack trace from PHP-FPM slow log:

[26-Mar-2021 17:56:16]  [pool www] pid 54155
script_filename = /var/www/html/nextcloud/remote.php
[0x00007fefba640920] execute() /var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:127
[0x00007fefba6408a0] execute() /var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php:906
[0x00007fefba6407b0] executeQuery() /var/www/html/nextcloud/lib/private/DB/Connection.php:202
[0x00007fefba640710] executeQuery() /var/www/html/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php:206
[0x00007fefba6406a0] execute() /var/www/html/nextcloud/lib/private/DB/QueryBuilder/QueryBuilder.php:217
[0x00007fefba6405e0] execute() /var/www/html/nextcloud/lib/private/Files/Cache/Cache.php:154
[0x00007fefba640530] get() /var/www/html/nextcloud/lib/private/Files/Cache/HomeCache.php:85
[0x00007fefba6404a0] get() /var/www/html/nextcloud/lib/private/Files/Storage/Wrapper/Encryption.php:145
[0x00007fefba6403f0] filesize() /var/www/html/nextcloud/lib/private/Files/Storage/Wrapper/Encryption.php:409
[0x00007fefba640230] fopen() /var/www/html/nextcloud/lib/private/Files/Storage/LocalTempFileTrait.php:66
[0x00007fefba640160] toTmpFile() /var/www/html/nextcloud/lib/private/Files/Storage/LocalTempFileTrait.php:49
[0x00007fefba6400e0] getCachedFile() /var/www/html/nextcloud/lib/private/Files/Storage/Wrapper/Encryption.php:789
[0x00007fefba640060] getLocalFile() /var/www/html/nextcloud/apps/workflowengine/lib/Check/FileMimeType.php:126
[0x00007fefba63ffb0] getActualValue() /var/www/html/nextcloud/apps/workflowengine/lib/Check/FileMimeType.php:104
[0x00007fefba63ff00] executeCheck() /var/www/html/nextcloud/apps/workflowengine/lib/Service/RuleMatcher.php:241
[0x00007fefba63fe20] check() /var/www/html/nextcloud/apps/workflowengine/lib/Service/RuleMatcher.php:176
[0x00007fefba63fc90] getMatchingOperations() /var/www/html/nextcloud/apps/workflowengine/lib/Service/RuleMatcher.php:124
[0x00007fefba63fc20] getFlows() /var/www/html/nextcloud/apps/files_automatedtagging/lib/Operation.php:98
[0x00007fefba63fb50] checkOperations() /var/www/html/nextcloud/apps/files_automatedtagging/lib/Listener/CacheListener.php:41
[0x00007fefba63fae0] handle() /var/www/html/nextcloud/lib/private/EventDispatcher/ServiceEventListener.php:76

SQL Query which is executed 55450 times (first line is the query, the second line are the prepared statement parameters). Note that the parameters are identical all 55450 times.

LOG:  execute <unnamed>: UPDATE "oc_filecache" SET "storage" = $1, "path_hash" = $2, "path" = $3, "parent" = $4, "name" = $5, "mimepart" = $6, "mimetype" = $7, "size" = $8, "mtime" = $9, "storage_mtime" = $10, "encrypted" = $11, "etag" = $12, "permissions" = $13, "checksum" = $14 WHERE ("fileid" = $15) AND ((("storage" <> $16) OR ("storage" IS NULL)) OR (("path_hash" <> $17) OR ("path_hash" IS NULL)) OR (("path" <> $18) OR ("path" IS NULL)) OR (("parent" <> $19) OR ("parent" IS NULL)) OR (("name" <> $20) OR ("name" IS NULL)) OR (("mimepart" <> $21) OR ("mimepart" IS NULL)) OR (("mimetype" <> $22) OR ("mimetype" IS NULL)) OR (("size" <> $23) OR ("size" IS NULL)) OR (("mtime" <> $24) OR ("mtime" IS NULL)) OR (("storage_mtime" <> $25) OR ("storage_mtime" IS NULL)) OR (("encrypted" <> $26) OR ("encrypted" IS NULL)) OR (("etag" <> $27) OR ("etag" IS NULL)) OR (("permissions" <> $28) OR ("permissions" IS NULL)) OR (("checksum" <> $29) OR ("checksum" IS NULL)))


DETAIL:  parameters: $1 = '3', $2 = '26a4ebc5bf91bea525a4dc5431c8efca', $3 = 'files/filename_censored.pdf', $4 = '377', $5 = 'filename_censored.pdf', $6 = '3', $7 = '9', $8 = '39324209', $9 = '1616781365', $10 = '1616781365', $11 = '1', $12 = 'ddfae1507a42adc530a49e0f0662dd1e', $13 = '27', $14 = '', $15 = '27582', $16 = '3', $17 = '26a4ebc5bf91bea525a4dc5431c8efca', $18 = 'files/filename_censored.pdf', $19 = '377', $20 = 'filename_censored.pdf', $21 = '3', $22 = '9', $23 = '39324209', $24 = '1616781365', $25 = '1616781365', $26 = '1', $27 = 'ddfae1507a42adc530a49e0f0662dd1e', $28 = '27', $29 = ''

Config (censored and smtp information removed)

<?php
$CONFIG = array (
  'instanceid' => 'FOO',
  'passwordsalt' => 'FOO',
  'secret' => 'FOO',
  'trusted_domains' => 
  array (
    0 => 'foo.example.com',
  ),
  'datadirectory' => '/var/www/html/nextcloud/data',
  'dbtype' => 'pgsql',
  'version' => '20.0.8.1',
  'dbname' => 'nextcloud',
  'dbhost' => '127.0.0.1',
  'dbport' => '',
  'dbtableprefix' => 'oc_',
  'dbuser' => 'nextcloud',
  'dbpassword' => 'FOO',
  'installed' => true,
  'overwrite.cli.url' => 'https://foo.example.com',
  'overwriteprotocol' => 'https',
  'overwritehost' => 'foo.example.com',
  'htaccess.RewriteBase' => '/',
  'enable_previews' => false,
  'ldapIgnoreNamingRules' => false,
  'ldapProviderFactory' => 'OCA\\User_LDAP\\LDAPProviderFactory',
  'skeletondirectory' => '',
  'loglevel' => 2,
  'log.condition' => 
  array (
    'apps' => 
    array (
      0 => 'admin_audit',
    ),
  ),
  'maintenance' => false,
  'theme' => '',
  'encryption.legacy_format_support' => true,
  'encryption.key_storage_migrated' => false,
);

There is nothing of note in the Apache logs.

This seems to be caused by a bug in the Automated Tagging plugin, debug logging shows that this gets caught in an infinite loop of trying to apply the tagging rules. Removing all Automated Tagging rules “fixes” the problem.

1 Like