Intermittent deadlock in database access, causes client sync issues

[GreenArchon]

Steps to reproduce

I have no idea (but it didn't happen before oc9->nc11 upgrade)

Expected behaviour

Syncing should work without errors

Actual behaviour

Client (and maybe web interface?) PROPFIND/GET/PUT/DELETE requests are answered with 503 ~0.2% of the time, causing intermittent sync errors on client. Server log says Sabre\DAV\Exception\ServiceUnavailable: HTTP/1.1 503 Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE oc_mounts [...] : SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction.
(see logs for more details)

Server configuration

Operating system: Centos 7

Web server: Apache 2.4.18
Database: Mysql

PHP version: 5.6

Nextcloud version: 11.0.1

Updated from an older Nextcloud/ownCloud or fresh install: updated from OC 9 (and 8.2, 8.1, 7 previously)

Where did you install Nextcloud from: nextcloud.com

List of activated apps:

App list

- activity: 2.4.1 - announcementcenter: 3.0.0 - contacts: 1.5.2 - dav: 1.1.1 - direct_menu: 0.10.0 - federatedfilesharing: 1.1.1 - files: 1.6.1 - files_pdfviewer: 1.0.1 - files_sharing: 1.1.1 - files_texteditor: 2.2 - files_trashbin: 1.1.0 - files_versions: 1.4.0 - files_videoplayer: 1.0.0 - firstrunwizard: 2.0 - gallery: 16.0.0 - logreader: 2.0.0 - lookup_server_connector: 1.0.0 - nextant: 1.0.3 - notifications: 1.0.1 - provisioning_api: 1.1.0 - serverinfo: 1.1.1 - sharebymail: 1.0.1 - survey_client: 0.1.5 - templateeditor: 0.2 - theming: 1.1.1 - twofactor_backupcodes: 1.0.0 - user_ldap: 1.1.1 - workflowengine: 1.1.1

The content of config/config.php:

Config report

{ "system": { "instanceid": "tell me if you need it", "passwordsalt": "***REMOVED SENSITIVE VALUE***", "secret": "***REMOVED SENSITIVE VALUE***", "trusted_domains": [ "localhost", "mydomain.com", "www.mydomain.com" ], "datadirectory": "\/srv\/data", "overwrite.cli.url": "https:\/\/mydomain.com\/owncloud", "dbtype": "mysql", "version": "11.0.1.2", "dbname": "owncloud", "dbhost": "localhost", "dbtableprefix": "oc_", "dbuser": "***REMOVED SENSITIVE VALUE***", "dbpassword": "***REMOVED SENSITIVE VALUE***", "logtimezone": "UTC", "installed": true, "mail_from_address": "owncloud", "mail_smtpmode": "php", "mail_domain": "mydomain.com", "loglevel": 2, "ldapIgnoreNamingRules": false, "memcache.local": "\\OC\\Memcache\\APCu", "maintenance": false, "theme": "", "trashbin_retention_obligation": "auto", "versions_retention_obligation": "auto", "updatechecker": false, "activity_expire_days": 240, "ldapProviderFactory": "\\OCA\\User_LDAP\\LDAPProviderFactory" } }

Are you using external storage, if yes which one: no (local only)

Are you using encryption: no

Are you using an external user-backend, if yes which one: LDAP (OpenLDAP)

Client configuration

Browser: Owncloud client (up to date, hasn't changed since upgrading)

Operating system: Depends on user

Logs

Web server error log

ssl_access_log, sample GET failure

[...]
a.b.c.d - - [09/Feb/2017:19:44:10 -0500] "GET /owncloud/remote.php/webdav/CAD%20Design/A16-H17%20-%20Payload/Section%20FP/Senseur%20FP/93330A282_ALUM%20FEM%20THRDED%20ROUND%20STANDOFF.CATPart HTTP/1.1" 200 854042
a.b.c.d - - [09/Feb/2017:19:44:13 -0500] "GET /owncloud/remote.php/webdav/CAD%20Design/A16-H17%20-%20Payload/Section%20FP/Senseur%20FP/93330A282_ALUM%20FEM%20THRDED%20ROUND%20STANDOFF.STEP HTTP/1.1" 503 652
a.b.c.d - - [09/Feb/2017:19:44:14 -0500] "GET /owncloud/remote.php/webdav/CAD%20Design/A16-H17%20-%20Payload/Section%20FP/Senseur%20FP/Ceramic%20plate.CATPart HTTP/1.1" 200 351393
[...]

ssl_access_log, sample PROPFIND failure

e.f.g.h - - [10/Feb/2017:12:46:09 -0500] "PROPFIND /owncloud/remote.php/webdav/PCB%20Design HTTP/1.1" 207 411406
e.f.g.h - - [10/Feb/2017:12:46:11 -0500] "PROPFIND /owncloud/remote.php/webdav/Analysis HTTP/1.1" 503 655
e.f.g.h - - [10/Feb/2017:12:46:11 -0500] "PROPFIND /owncloud/remote.php/webdav/PCB%20Design%20-%20Lib HTTP/1.1" 207 421

Nextcloud log (data/nextcloud.log)

Note: I can produce more on demand, my log is full of these.

Human readable sample

Sabre\DAV\Exception\ServiceUnavailable: HTTP/1.1 503 Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE oc_mounts SET storage_id = ?, mount_point = ?, mount_id = ? WHERE (user_id = ?) AND (root_id = ?)' with params ["3", "/13903c04-bd16-1034-8677-eb3b17aab112/files/Photos - Archiving/", null, "13903c04-bd16-1034-8677-eb3b17aab112", 18]: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction

/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php - line 202: OCA\DAV\Connector\Sabre\Auth->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php - line 150: Sabre\DAV\Auth\Plugin->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
[internal function] Sabre\DAV\Auth\Plugin->beforeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php - line 105: call_user_func_array(Array, Array)
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 466: Sabre\Event\EventEmitter->emit('beforeMethod', Array)
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 254: Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/apps/dav/appinfo/v1/webdav.php - line 60: Sabre\DAV\Server->exec()
/var/www/html/owncloud/remote.php - line 165: require_once('/var/www/html/o...')
{main}

Doctrine\DBAL\Exception\DriverException: An exception occurred while executing 'UPDATE oc_mounts SET storage_id = ?, mount_point = ?, mount_id = ? WHERE (user_id = ?) AND (root_id = ?)' with params ["3", "/13903c04-bd16-1034-8677-eb3b17aab112/files/Photos - Archiving/", null, "13903c04-bd16-1034-8677-eb3b17aab112", 18]: SQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction

/var/www/html/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php - line 128: Doctrine\DBAL\Driver\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\DBAL\Driver\PDOException))
/var/www/html/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php - line 996: Doctrine\DBAL\DBALException driverExceptionDuringQuery(Object(Doctrine\DBAL\Driver\PDOMySql\Driver), Object(Doctrine\DBAL\Driver\PDOException), 'UPDATE `oc_moun...', Array)
/var/www/html/owncloud/lib/private/DB/Connection.php - line 215: Doctrine\DBAL\Connection->executeUpdate('UPDATE `oc_moun...', Array, Array)
/var/www/html/owncloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php - line 208: OC\DB\Connection->executeUpdate('UPDATE `*PREFIX...', Array, Array)
/var/www/html/owncloud/lib/private/DB/QueryBuilder/QueryBuilder.php - line 177: Doctrine\DBAL\Query\QueryBuilder->execute()
/var/www/html/owncloud/lib/private/Files/Config/UserMountCache.php - line 182: OC\DB\QueryBuilder\QueryBuilder->execute()
/var/www/html/owncloud/lib/private/Files/Config/UserMountCache.php - line 129: OC\Files\Config\UserMountCache->updateCachedMount(Object(OC\Files\Config\LazyStorageMountInfo))
/var/www/html/owncloud/lib/private/Files/Config/MountProviderCollection.php - line 134: OC\Files\Config\UserMountCache->registerMounts(Object(OC\User\User), Array)
/var/www/html/owncloud/lib/private/Files/Filesystem.php - line 449: OC\Files\Config\MountProviderCollection->registerMounts(Object(OC\User\User), Array)
/var/www/html/owncloud/lib/private/Files/Filesystem.php - line 375: OC\Files\Filesystem initMountPoints('13903c04-bd16-1...')
/var/www/html/owncloud/lib/private/legacy/util.php - line 235: OC\Files\Filesystem init('13903c04-bd16-1...', '/13903c04-bd16-...')
/var/www/html/owncloud/apps/dav/lib/Connector/Sabre/Auth.php - line 124: OC_Util setupFS('13903c04-bd16-1...')
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Auth/Backend/AbstractBasic.php - line 105: OCA\DAV\Connector\Sabre\Auth->validateUserPass(*** sensitive parameters replaced ***)
/var/www/html/owncloud/apps/dav/lib/Connector/Sabre/Auth.php - line 252: Sabre\DAV\Auth\Backend\AbstractBasic->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/apps/dav/lib/Connector/Sabre/Auth.php - line 155: OCA\DAV\Connector\Sabre\Auth->auth(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php - line 202: OCA\DAV\Connector\Sabre\Auth->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Auth/Plugin.php - line 150: Sabre\DAV\Auth\Plugin->check(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
[internal function] Sabre\DAV\Auth\Plugin->beforeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/3rdparty/sabre/event/lib/EventEmitterTrait.php - line 105: call_user_func_array(Array, Array)
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 466: Sabre\Event\EventEmitter->emit('beforeMethod', Array)
/var/www/html/owncloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 254: Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response))
/var/www/html/owncloud/apps/dav/appinfo/v1/webdav.php - line 60: Sabre\DAV\Server->exec()
/var/www/html/owncloud/remote.php - line 165: require_once('/var/www/html/o...')

Nextcloud log

{"reqId":"WJ4k7tUxgP8XhQPJqVGrgwAAABE","remoteAddr":"w.x.y.z","app":"no app in context","message":"Exception: {"Exception":"Doctrine\\DBAL\\Exception\\DriverException","Message":"An exception occurred while executing 'UPDATE oc_mounts SET storage_id = ?, mount_point = ?, mount_id = ? WHERE (user_id = ?) AND (root_id = ?)' with params [\"3\", \"\\\/492c4a6c-b9d1-1034-9dd1-7b768ca242da\\\/files\\\/Photos - Archiving\\\/\", null, \"492c4a6c-b9d1-1034-9dd1-7b768ca242da\", 18]:\n\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction","Code":0,"Trace":"#0 \/var\/www\/html\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/DBALException.php(128): Doctrine\\DBAL\\Driver\\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\\DBAL\\Driver\\PDOException))\n#1 \/var\/www\/html\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php(996): Doctrine\\DBAL\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\DBAL\\Driver\\PDOMySql\\Driver), Object(Doctrine\\DBAL\\Driver\\PDOException), 'UPDATE oc_moun...', Array)\\n#2 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/DB\\\/Connection.php(215): Doctrine\\\\DBAL\\\\Connection->executeUpdate('UPDATE oc_moun...', Array, Array)\n#3 \/var\/www\/html\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php(208): OC\\DB\\Connection->executeUpdate('UPDATE *PREFIX...', Array, Array)\\n#4 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/DB\\\/QueryBuilder\\\/QueryBuilder.php(177): Doctrine\\\\DBAL\\\\Query\\\\QueryBuilder->execute()\\n#5 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Config\\\/UserMountCache.php(182): OC\\\\DB\\\\QueryBuilder\\\\QueryBuilder->execute()\\n#6 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Config\\\/UserMountCache.php(129): OC\\\\Files\\\\Config\\\\UserMountCache->updateCachedMount(Object(OC\\\\Files\\\\Config\\\\LazyStorageMountInfo))\\n#7 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Config\\\/MountProviderCollection.php(134): OC\\\\Files\\\\Config\\\\UserMountCache->registerMounts(Object(OC\\\\User\\\\User), Array)\\n#8 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Filesystem.php(449): OC\\\\Files\\\\Config\\\\MountProviderCollection->registerMounts(Object(OC\\\\User\\\\User), Array)\\n#9 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/Files\\\/Filesystem.php(375): OC\\\\Files\\\\Filesystem::initMountPoints('492c4a6c-b9d1-1...')\\n#10 \\\/var\\\/www\\\/html\\\/owncloud\\\/lib\\\/private\\\/legacy\\\/util.php(235): OC\\\\Files\\\\Filesystem::init('492c4a6c-b9d1-1...', '\\\/492c4a6c-b9d1-...')\\n#11 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(124): OC_Util::setupFS('492c4a6c-b9d1-1...')\\n#12 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Backend\\\/AbstractBasic.php(105): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->validateUserPass(*** sensitive parameters replaced ***)\\n#13 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(252): Sabre\\\\DAV\\\\Auth\\\\Backend\\\\AbstractBasic->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#14 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(155): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->auth(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#15 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(202): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#16 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(150): Sabre\\\\DAV\\\\Auth\\\\Plugin->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#17 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#18 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#19 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(466): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#20 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#21 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(60): Sabre\\\\DAV\\\\Server->exec()\\n#22 \\\/var\\\/www\\\/html\\\/owncloud\\\/remote.php(165): require_once('\\\/var\\\/www\\\/html\\\/o...')\\n#23 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractMySQLDriver.php\",\"Line\":116}","level":3,"time":"2017-02-10T20:39:21+00:00","method":"GET","url":"\/owncloud\/remote.php\/webdav\/Management%20-%20Finances\/2016-2017\/Factures\/Air%20Liquide\/AIR_LIQUIDE_20170131.pdf","user":"492c4a6c-b9d1-1034-9dd1-7b768ca242da","version":"11.0.1.2"} {"reqId":"WJ4k7tUxgP8XhQPJqVGrgwAAABE","remoteAddr":"w.x.y.z","app":"webdav","message":"Exception: {\"Message\":\"HTTP\\\/1.1 503 Doctrine\\\\DBAL\\\\Exception\\\\DriverException: An exception occurred while executing 'UPDATE oc_mountsSETstorage_id= ?,mount_point= ?,mount_id = ? WHERE (user_id = ?) AND (root_id= ?)' with params [\\\"3\\\", \\\"\\\\\\\/492c4a6c-b9d1-1034-9dd1-7b768ca242da\\\\\\\/files\\\\\\\/Photos - Archiving\\\\\\\/\\\", null, \\\"492c4a6c-b9d1-1034-9dd1-7b768ca242da\\\", 18]:\\n\\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\ServiceUnavailable\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(202): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#1 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(150): Sabre\\\\DAV\\\\Auth\\\\Plugin->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#2 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#3 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#4 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(466): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#5 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/webdav.php(60): Sabre\\\\DAV\\\\Server->exec()\\n#7 \\\/var\\\/www\\\/html\\\/owncloud\\\/remote.php(165): require_once('\\\/var\\\/www\\\/html\\\/o...')\\n#8 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php\",\"Line\":163,\"User\":\"492c4a6c-b9d1-1034-9dd1-7b768ca242da\"}","level":4,"time":"2017-02-10T20:39:21+00:00","method":"GET","url":"\/owncloud\/remote.php\/webdav\/Management%20-%20Finances\/2016-2017\/Factures\/Air%20Liquide\/AIR_LIQUIDE_20170131.pdf","user":"492c4a6c-b9d1-1034-9dd1-7b768ca242da","version":"11.0.1.2"} {"reqId":"WJ4lSVOZ-y2wmm5mlYoQqgAAAB4","remoteAddr":"w.x.y.z","app":"no app in context","message":"Exception: {\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException\",\"Message\":\"An exception occurred while executing 'UPDATEoc_mountsSETstorage_id= ?,mount_point= ?,mount_id = ? WHERE (user_id = ?) AND (root_id= ?)' with params [\\\"3\\\", \\\"\\\\\\\/492c4a6c-b9d1-1034-9dd1-7b768ca242da\\\\\\\/files\\\\\\\/Graphism - Utilitaire\\\\\\\/\\\", null, \\\"492c4a6c-b9d1-1034-9dd1-7b768ca242da\\\", 40]:\\n\\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/DBALException.php(128): Doctrine\\\\DBAL\\\\Driver\\\\AbstractMySQLDriver->convertException('An exception oc...', Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException))\\n#1 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Connection.php(996): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOMySql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'UPDATEoc_moun...', Array)\n#2 \/var\/www\/html\/owncloud\/lib\/private\/DB\/Connection.php(215): Doctrine\\DBAL\\Connection->executeUpdate('UPDATE oc_moun...', Array, Array)\\n#3 \\\/var\\\/www\\\/html\\\/owncloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Query\\\/QueryBuilder.php(208): OC\\\\DB\\\\Connection->executeUpdate('UPDATE PREFIX...', Array, Array)\n#4 \/var\/www\/html\/owncloud\/lib\/private\/DB\/QueryBuilder\/QueryBuilder.php(177): Doctrine\\DBAL\\Query\\QueryBuilder->execute()\n#5 \/var\/www\/html\/owncloud\/lib\/private\/Files\/Config\/UserMountCache.php(182): OC\\DB\\QueryBuilder\\QueryBuilder->execute()\n#6 \/var\/www\/html\/owncloud\/lib\/private\/Files\/Config\/UserMountCache.php(129): OC\\Files\\Config\\UserMountCache->updateCachedMount(Object(OC\\Files\\Config\\LazyStorageMountInfo))\n#7 \/var\/www\/html\/owncloud\/lib\/private\/Files\/Config\/MountProviderCollection.php(134): OC\\Files\\Config\\UserMountCache->registerMounts(Object(OC\\User\\User), Array)\n#8 \/var\/www\/html\/owncloud\/lib\/private\/Files\/Filesystem.php(449): OC\\Files\\Config\\MountProviderCollection->registerMounts(Object(OC\\User\\User), Array)\n#9 \/var\/www\/html\/owncloud\/lib\/private\/Files\/Filesystem.php(375): OC\\Files\\Filesystem::initMountPoints('492c4a6c-b9d1-1...')\n#10 \/var\/www\/html\/owncloud\/lib\/private\/legacy\/util.php(235): OC\\Files\\Filesystem::init('492c4a6c-b9d1-1...', '\/492c4a6c-b9d1-...')\n#11 \/var\/www\/html\/owncloud\/apps\/dav\/lib\/Connector\/Sabre\/Auth.php(124): OC_Util::setupFS('492c4a6c-b9d1-1...')\n#12 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Backend\/AbstractBasic.php(105): OCA\\DAV\\Connector\\Sabre\\Auth->validateUserPass(** sensitive parameters replaced ***)\n#13 \/var\/www\/html\/owncloud\/apps\/dav\/lib\/Connector\/Sabre\/Auth.php(252): Sabre\\DAV\\Auth\\Backend\\AbstractBasic->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#14 \/var\/www\/html\/owncloud\/apps\/dav\/lib\/Connector\/Sabre\/Auth.php(155): OCA\\DAV\\Connector\\Sabre\\Auth->auth(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#15 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Plugin.php(202): OCA\\DAV\\Connector\\Sabre\\Auth->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#16 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Plugin.php(150): Sabre\\DAV\\Auth\\Plugin->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#17 [internal function]: Sabre\\DAV\\Auth\\Plugin->beforeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#18 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#19 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(466): Sabre\\Event\\EventEmitter->emit('beforeMethod', Array)\n#20 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#21 \/var\/www\/html\/owncloud\/apps\/dav\/appinfo\/v1\/webdav.php(60): Sabre\\DAV\\Server->exec()\n#22 \/var\/www\/html\/owncloud\/remote.php(165): require_once('\/var\/www\/html\/o...')\n#23 {main}","File":"\/var\/www\/html\/owncloud\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Driver\/AbstractMySQLDriver.php","Line":116}","level":3,"time":"2017-02-10T20:40:42+00:00","method":"PROPFIND","url":"/owncloud/remote.php/webdav/Management%20-%20Commandites","user":"492c4a6c-b9d1-1034-9dd1-7b768ca242da","version":"11.0.1.2"}
{"reqId":"WJ4lSVOZ-y2wmm5mlYoQqgAAAB4","remoteAddr":"w.x.y.z","app":"webdav","message":"Exception: {"Message":"HTTP\/1.1 503 Doctrine\\DBAL\\Exception\\DriverException: An exception occurred while executing 'UPDATE oc_mounts SET storage_id = ?, mount_point = ?, mount_id = ? WHERE (user_id = ?) AND (root_id = ?)' with params [\"3\", \"\\\/492c4a6c-b9d1-1034-9dd1-7b768ca242da\\\/files\\\/Graphism - Utilitaire\\\/\", null, \"492c4a6c-b9d1-1034-9dd1-7b768ca242da\", 40]:\n\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction","Exception":"Sabre\\DAV\\Exception\\ServiceUnavailable","Code":0,"Trace":"#0 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Plugin.php(202): OCA\\DAV\\Connector\\Sabre\\Auth->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#1 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Plugin.php(150): Sabre\\DAV\\Auth\\Plugin->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#2 [internal function]: Sabre\\DAV\\Auth\\Plugin->beforeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#3 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#4 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(466): Sabre\\Event\\EventEmitter->emit('beforeMethod', Array)\n#5 \/var\/www\/html\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#6 \/var\/www\/html\/owncloud\/apps\/dav\/appinfo\/v1\/webdav.php(60): Sabre\\DAV\\Server->exec()\n#7 \/var\/www\/html\/owncloud\/remote.php(165): require_once('\/var\/www\/html\/o...')\n#8 {main}","File":"\/var\/www\/html\/owncloud\/apps\/dav\/lib\/Connector\/Sabre\/Auth.php","Line":163,"User":"492c4a6c-b9d1-1034-9dd1-7b768ca242da"}","level":4,"time":"2017-02-10T20:40:42+00:00","method":"PROPFIND","url":"/owncloud/remote.php/webdav/Management%20-%20Commandites","user":"492c4a6c-b9d1-1034-9dd1-7b768ca242da","version":"11.0.1.2"}

Statistics

Note that each log shown previously isn't directly related (ie. I took them randomly in each files). However:

Fun stats

ssl_access_log rotated 5 days ago:

cat ssl_access_log | grep webdav | grep "HTTP/1.1" 503 " | wc -l
2230
cat ssl_access_log | grep webdav | grep "HTTP/1.1" 503 " | grep PROPFIND | wc -l
2099
cat ssl_access_log | grep webdav | grep "HTTP/1.1" 503 " | grep GET | wc -l
111
cat ssl_access_log | grep webdav | grep "HTTP/1.1" 503 " | grep PUT | wc -l
10
cat ssl_access_log | grep webdav | grep "HTTP/1.1" 503 " | grep DELETE | wc -l
9
nextcloud.log, not rotated since upgrade (Dec 23rd):
cat nextcloud.log | grep Deadlock | wc -l
28133

Thanks in advance for any input.

[nickvergessen]

I think you are using a wrong transaction isolation level:
https://docs.nextcloud.com/server/11/admin_manual/configuration_database/linux_database_configuration.html#mysql-mariadb-with-binary-logging-enabled

[GreenArchon]

I doubt it's the cause of the issue, however, having spend Sunday afternoon tweaking performance settings (ie. setting up redis for file locks and figuring out #3461) I can't reproduce anymore. While it doesn't necessarily mean that everything is the best in the best of all possible worlds (hack fixing #3461 did reduce my database io load by ~90%) and I'll continue to monitor logs in the following days, I'll close for now and reopen if it happens again.

[chaos-prevails]

Hi GreenArchon,
I think I suffer from the same issue. Transaction level and binlog format are correctly, but I still have up and then deadlocks and also reguarly some files get locked (and are constantly updated by clients while they don't touch those files).

could you explain me your redis-tweaking or post here your redis nextcloud configuration?

thanks!

[GreenArchon]

@chaos-prevails Do you have mounts shared between users? In my case I'm pretty sure the whole thing was caused by #3461 (which is fixed in #3588 and will be in nc 11.0.3) - or at least, if it didn't solve the problem it made it so unfrequent it doesn't happen anymore (since oc_mounts updates went down from ~100/second to pretty much 0 in ever, so there's no need for locking that table/row).

[chaos-prevails]

Hi GreenArchon,

thanks. No, everybody has his/her own (veracrypt) container mounted where the NC synced folder is. But no shared mount between users.
It is "only" executable files like exe, dll, js, etc which are constantly updated and re-downloaded. I thought about virus scanners on the clients constantly touching the files but the files themselves don't change (I don't see any differences in the versioning). I have to look into the issue further.

Tim