PHP Fatal error: Uncaught PDOException: Deadlock detected

[mfr00t]

Server configuration

OS: Debian 9
Nextcloud Version: 15(0.7)
PHP Version: 7.2 (fpm)
Database: Postgresql 9.6
Webserver: Apache
Single-User system

Steps to reproduce

not known

fpm and postgres logs getting spammed with these entries:

Logs

fpm_nextcloud.log:

PHP Fatal error:  Uncaught PDOException: SQLSTATE[40P01]: Deadlock detected: 7 ERROR:  deadlock detected
DETAIL:  Process 14896 waits for ShareLock on transaction 1930337; blocked by process 14897.
Process 14897 waits for ShareLock on transaction 1930336; blocked by process 14896.
HINT:  See server log for query details.
CONTEXT:  while rechecking updated tuple (12,138) in relation "oc_file_locks" in /opt/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:105
Stack trace:
#0 /opt/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php(105): PDOStatement->execute(NULL)
#1 /opt/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(1006): Doctrine\DBAL\Driver\PDOStatement->execute()
#2 /opt/nextcloud/lib/private/DB/Connection.php(216): Doctrine\DBAL\Connection->executeUpdate('UPDATE "oc_file...', Array, Array)
#3 /opt/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php(208): OC\DB\Connection->executeUpdate('UPDATE "oc_file...', Array, Array)
#4 /opt/next in /opt/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractPostgreSQLDriver.php on line 92

postgresql-9.6-main.log:

2019-04-11 05:15:18 GMT ERROR:  duplicate key value violates unique constraint "lock_key_index"
2019-04-11 05:15:18 GMT DETAIL:  Key (key)=(files/7d79c31537be24aadcda7fa480987df4) already exists.
2019-04-11 05:15:18 GMT STATEMENT:  INSERT INTO "oc_file_locks" ("key", "lock", "ttl") VALUES($1, $2, $3)
2019-04-11 05:15:18 GMT ERROR:  duplicate key value violates unique constraint "lock_key_index"
2019-04-11 05:15:18 GMT DETAIL:  Key (key)=(files/abfe242a994b591cb4dee19585031873) already exists.
2019-04-11 05:15:18 GMT STATEMENT:  INSERT INTO "oc_file_locks" ("key", "lock", "ttl") VALUES($1, $2, $3)

[jknockaert]

I have a similar deadlock occurring (using nextcloud 16.0.3). It happens when uploading a file over webdav. Nginx returns a 423 http status code. At the postgres level a lot is happening; it basically starts with multiple:

ERROR:  duplicate key value violates unique constraint "oc_credentials_pkey"
DETAIL:  Key ("user", identifier)=(jknockaert, password::logincredentials/credentials) already exists.
STATEMENT:  INSERT INTO "oc_credentials" ("user", "identifier", "credentials") VALUES($1, $2, $3)

and then deadlocks get detected, like this one:

ERROR:  deadlock detected
DETAIL:  Process 13718 waits for ShareLock on transaction 17507889; blocked by process 13720.
HINT:  See server log for query details.
CONTEXT:  while rechecking updated tuple (0,91) in relation "oc_file_locks"
STATEMENT:  UPDATE "oc_file_locks" SET "lock" = "lock" - '1' WHERE ("key" IN ($1, $2, $3, $4)) AND ("lock" > 0)

As the client keeps reiterating it's http put request, after a short while the postgres server hits its maximum number of connections:

FATAL:  remaining connection slots are reserved for non-replication superuser connections
FATAL:  sorry, too many clients already

which is pretty ridiculous, provided this is a single nextcloud user setup (with a max of 200 connections on the postgres backend).
This is the full nextcloud log:

Doctrine\DBAL\Exception\DeadlockException: An exception occurred while executing 'UPDATE "oc_file_locks" SET "lock" = "lock" + 1, "ttl" = ? WHERE "key" = ? AND "lock" >= 0' with params [1564417365, "files\/e7e0bbf21169ed1673f5ddf8ed7ebb89"]:

SQLSTATE[40P01]: Deadlock detected: 7 ERROR: deadlock detected
DETAIL: Process 13976 waits for ExclusiveLock on tuple (6,56) of relation 16847 of database 16389; blocked by process 13956. 
Process 13956 waits for ShareLock on transaction 17508673; blocked by process 13908.
Process 13908 waits for ShareLock on transaction 17508707; blocked by process 13910.
Process 13910 waits for ExclusiveLock on tuple (6,56) of relation 16847 of database 16389; blocked by process 13976.
HINT: See server log for query details.

 0. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php - line 184:
    Doctrine\DBAL\Driver\AbstractPostgreSQLDriver->convertException("An exceptio ... .", Doctrine\DBA ... ]})

 1. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php - line 158:
    Doctrine\DBAL\DBALException::wrapException(Doctrine\DBA ... {}, Doctrine\DBA ... ]}, "An exceptio ... .")

 2. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php - line 1088:
    Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Doctrine\DBA ... {}, Doctrine\DBA ... ]}, "UPDATE \"oc ... 0", { 1: 1564417 ... "})

 3. /var/www/nextcloud/lib/private/DB/Connection.php - line 216:
    Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc ... 0", [ 1564417365 ... "], [])

 4. /var/www/nextcloud/lib/private/Lock/DBLockingProvider.php - line 189:
    OC\DB\Connection->executeUpdate("UPDATE \"oc ... 0", [ 1564417365 ... "])

 5. /var/www/nextcloud/lib/private/Files/Storage/Common.php - line 715:
    OC\Lock\DBLockingProvider->acquireLock("files/e7e0b ... 9", 1)

 6. /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php - line 593:
    OC\Files\Storage\Common->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 7. /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php - line 593:
    OC\Files\Storage\Wrapper\Wrapper->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 8. /var/www/nextcloud/lib/private/Files/View.php - line 1940:
    OC\Files\Storage\Wrapper\Wrapper->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 9. /var/www/nextcloud/lib/private/Files/View.php - line 2054:
    OC\Files\View->lockPath("/Backups", 1)

10. /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Node.php - line 378:
    OC\Files\View->lockFile("/Backups/Si ... p", 1)

11. /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php - line 153:
    OCA\DAV\Connector\Sabre\Node->acquireLock(1)

12. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 1096:
    OCA\DAV\Connector\Sabre\Directory->createFile("signal-2019 ... p", null)

13. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 525:
    Sabre\DAV\Server->createFile("files/jknoc ... p", null, null)

14. <<closure>>
    Sabre\DAV\CorePlugin->httpPut(Sabre\HTTP\R ... "}, Sabre\HTTP\Response {})

15. /var/www/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php - line 105:
    call_user_func_array([ Sabre\DAV\ ... "], [ Sabre\HTTP ... }])

16. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 479:
    Sabre\Event\EventEmitter->emit("method:PUT", [ Sabre\HTTP ... }])

17. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 254:
    Sabre\DAV\Server->invokeMethod(Sabre\HTTP\R ... "}, Sabre\HTTP\Response {})

18. /var/www/nextcloud/apps/dav/lib/Server.php - line 316:
    Sabre\DAV\Server->exec()

19. /var/www/nextcloud/apps/dav/appinfo/v2/remote.php - line 35:
    OCA\DAV\Server->exec()

20. /var/www/nextcloud/remote.php - line 163:
    require_once("/var/www/ne ... p")

Cased by Doctrine\DBAL\Driver\PDOException: 

SQLSTATE[40P01]: Deadlock detected: 7 
ERROR: deadlock detected 
DETAIL: Process 13976 waits for ExclusiveLock on tuple (6,56) of relation 16847 of database 16389; blocked by process 13956.
Process 13956 waits for ShareLock on transaction 17508673; blocked by process 13908.
Process 13908 waits for ShareLock on transaction 17508707; blocked by process 13910.
Process 13910 waits for ExclusiveLock on tuple (6,56) of relation 16847 of database 16389; blocked by process 13976.
HINT: See server log for query details.

 0. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php - line 1081:
    Doctrine\DBAL\Driver\PDOStatement->execute([ 1564417365 ... "])

 1. /var/www/nextcloud/lib/private/DB/Connection.php - line 216:
    Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc ... 0", [ 1564417365 ... "], [])

 2. /var/www/nextcloud/lib/private/Lock/DBLockingProvider.php - line 189:
    OC\DB\Connection->executeUpdate("UPDATE \"oc ... 0", [ 1564417365 ... "])

 3. /var/www/nextcloud/lib/private/Files/Storage/Common.php - line 715:
    OC\Lock\DBLockingProvider->acquireLock("files/e7e0b ... 9", 1)

 4. /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php - line 593:
    OC\Files\Storage\Common->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 5. /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php - line 593:
    OC\Files\Storage\Wrapper\Wrapper->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 6. /var/www/nextcloud/lib/private/Files/View.php - line 1940:
    OC\Files\Storage\Wrapper\Wrapper->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 7. /var/www/nextcloud/lib/private/Files/View.php - line 2054:
    OC\Files\View->lockPath("/Backups", 1)

 8. /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Node.php - line 378:
    OC\Files\View->lockFile("/Backups/Si ... p", 1)

 9. /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php - line 153:
    OCA\DAV\Connector\Sabre\Node->acquireLock(1)

10. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 1096:
    OCA\DAV\Connector\Sabre\Directory->createFile("signal-2019 ... p", null)

11. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 525:
    Sabre\DAV\Server->createFile("files/jknoc ... p", null, null)

12. <<closure>>
    Sabre\DAV\CorePlugin->httpPut(Sabre\HTTP\R ... "}, Sabre\HTTP\Response {})

13. /var/www/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php - line 105:
    call_user_func_array([ Sabre\DAV\ ... "], [ Sabre\HTTP ... }])

14. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 479:
    Sabre\Event\EventEmitter->emit("method:PUT", [ Sabre\HTTP ... }])

15. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 254:
    Sabre\DAV\Server->invokeMethod(Sabre\HTTP\R ... "}, Sabre\HTTP\Response {})

16. /var/www/nextcloud/apps/dav/lib/Server.php - line 316:
    Sabre\DAV\Server->exec()

17. /var/www/nextcloud/apps/dav/appinfo/v2/remote.php - line 35:
    OCA\DAV\Server->exec()

18. /var/www/nextcloud/remote.php - line 163:
    require_once("/var/www/ne ... p")

Cased by PDOException:

SQLSTATE[40P01]: Deadlock detected: 7 
ERROR: deadlock detected 
DETAIL: Process 13976 waits for ExclusiveLock on tuple (6,56) of relation 16847 of database 16389; blocked by process 13956.
Process 13956 waits for ShareLock on transaction 17508673; blocked by process 13908.
Process 13908 waits for ShareLock on transaction 17508707; blocked by process 13910.
Process 13910 waits for ExclusiveLock on tuple (6,56) of relation 16847 of database 16389; blocked by process 13976.
HINT: See server log for query details.

 0. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php - line 141:
    PDOStatement->execute([ 1564417365 ... "])

 1. /var/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php - line 1081:
    Doctrine\DBAL\Driver\PDOStatement->execute([ 1564417365 ... "])

 2. /var/www/nextcloud/lib/private/DB/Connection.php - line 216:
    Doctrine\DBAL\Connection->executeUpdate("UPDATE \"oc ... 0", [ 1564417365 ... "], [])

 3. /var/www/nextcloud/lib/private/Lock/DBLockingProvider.php - line 189:
    OC\DB\Connection->executeUpdate("UPDATE \"oc ... 0", [ 1564417365 ... "])

 4. /var/www/nextcloud/lib/private/Files/Storage/Common.php - line 715:
    OC\Lock\DBLockingProvider->acquireLock("files/e7e0b ... 9", 1)

 5. /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php - line 593:
    OC\Files\Storage\Common->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 6. /var/www/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php - line 593:
    OC\Files\Storage\Wrapper\Wrapper->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 7. /var/www/nextcloud/lib/private/Files/View.php - line 1940:
    OC\Files\Storage\Wrapper\Wrapper->acquireLock("files/Backups", 1, OC\Lock\DBLockingProvider {})

 8. /var/www/nextcloud/lib/private/Files/View.php - line 2054:
    OC\Files\View->lockPath("/Backups", 1)

 9. /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Node.php - line 378:
    OC\Files\View->lockFile("/Backups/Si ... p", 1)

10. /var/www/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php - line 153:
    OCA\DAV\Connector\Sabre\Node->acquireLock(1)

11. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 1096:
    OCA\DAV\Connector\Sabre\Directory->createFile("signal-2019 ... p", null)

12. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 525:
    Sabre\DAV\Server->createFile("files/jknoc ... p", null, null)

13. <<closure>>
    Sabre\DAV\CorePlugin->httpPut(Sabre\HTTP\R ... "}, Sabre\HTTP\Response {})

14. /var/www/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php - line 105:
    call_user_func_array([ Sabre\DAV\ ... "], [ Sabre\HTTP ... }])

15. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 479:
    Sabre\Event\EventEmitter->emit("method:PUT", [ Sabre\HTTP ... }])

16. /var/www/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 254:
    Sabre\DAV\Server->invokeMethod(Sabre\HTTP\R ... "}, Sabre\HTTP\Response {})

17. /var/www/nextcloud/apps/dav/lib/Server.php - line 316:
    Sabre\DAV\Server->exec()

18. /var/www/nextcloud/apps/dav/appinfo/v2/remote.php - line 35:
    OCA\DAV\Server->exec()

19. /var/www/nextcloud/remote.php - line 163:
    require_once("/var/www/ne ... p")

[jknockaert]

Likely I was seeing #11136.

[kesselb]

@mfr00t @jknockaert would you mind to edit your post and add the issue template?

To reproduce such issues its required to setup a similar environment (webserver, active apps, configuration, etc.). A workaround for you could be to disable filelocking or use redis as locking provider.

STATEMENT: UPDATE "oc_file_locks" SET "lock" = "lock" - '1' WHERE ("key" IN ($1, $2, $3, $4)) AND ("lock" > 0)

server/lib/private/Lock/DBLockingProvider.php

Lines 309 to 312 in f5c0ea8

	$query = $builder->update('file_locks')
	->set('lock', $builder->func()->subtract('lock', $builder->expr()->literal(1)))
	->where($builder->expr()->in('key', $builder->createNamedParameter($chunk, IQueryBuilder::PARAM_STR_ARRAY)))
	->andWhere($builder->expr()->gt('lock', new Literal(0)));

The query looks related to the cleanup logs logic. This is tricky because the action / task is done and the final step is to delete our locks (on files in nextcloud) and run into a deadlock while trying to change the db values (because the db entry related to the file lock is locked by another process).

Index: lib/private/Lock/DBLockingProvider.php
IDEA additional info:
Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP
<+>UTF-8
===================================================================
--- lib/private/Lock/DBLockingProvider.php	(revision 7b8ddd7e958bfbf7dbddf38aca2c789310e3d1a4)
+++ lib/private/Lock/DBLockingProvider.php	(date 1565639171793)
@@ -301,14 +301,12 @@
 			return $this->sharedLocks[$path];
 		});
 
-		$chunkedPaths = array_chunk($lockedPaths, 100);
-
-		foreach ($chunkedPaths as $chunk) {
-			$builder = $this->connection->getQueryBuilder();
+		$builder = $this->connection->getQueryBuilder();
 
+		foreach($lockedPaths as $lockedPath) {
 			$query = $builder->update('file_locks')
 				->set('lock', $builder->func()->subtract('lock', $builder->expr()->literal(1)))
-				->where($builder->expr()->in('key', $builder->createNamedParameter($chunk, IQueryBuilder::PARAM_STR_ARRAY)))
+				->where($builder->expr()->eq('key', $builder->createNamedParameter($lockedPath, IQueryBuilder::PARAM_STR)))
 				->andWhere($builder->expr()->gt('lock', new Literal(0)));
 
 			$query->execute();

Could you try the above patch? I wonder if the unlocking would be more stable (but slower in situations with many locked files) when updating each lock for itself instead of changing multiple locks with one update.

[jknockaert]

@kesselb I already moved to using Redis and am having the issue (which likely was #11136) far less often now. There's still something happening when I opened a folder with many thousands of files, but I am not sure if that was really a bug or (more likely) resources being oversollicited.

This issue has been automatically marked as stale because it has not had recent activity and seems to be missing some essential information. It will be closed if no further activity occurs. Thank you for your contributions.

[kesselb]

Hey @mfr00t 🏓

[yanosz]

Got some deadlocks:

OS: Debian
Database: postgres 11.5-1+deb10u1
Nextloud: 16.0.3
Client (Linux): Version 2.5.1git.

Steps to reproduce on my server

1. Create a new User
2. Assign it to an existing group having a share (about 116 files)
3. Start sync using desktop client without logging to the webui before

[Thu Oct 03 16:05:52.717041 2019] [php7:error] [pid 1153] [client 172.16.3.1:55162] PHP Fatal error: Uncaught PDOException: SQLSTATE[40P01]: Deadlock detected: 7 ERROR: deadlock detected\nDETAIL: Process 1914 waits for ShareLock on transaction 36709; blocked by process 1913.\nProcess 1913 waits for ShareLock on transaction 36711; blocked by process 1914.\nHINT: See server log for query details.\nCONTEXT: while locking tuple (1,128) in relation "oc_file_locks" in /var/www/html/nc/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php:141\nStack trace:\n#0 /var/www/html/nc/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/PDOStatement.php(141): PDOStatement->execute(NULL)\n#1 /var/www/html/nc/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Connection.php(1079): Doctrine\DBAL\Driver\PDOStatement->execute()\n#2 /var/www/html/nc/lib/private/DB/Connection.php(216): Doctrine\DBAL\Connection->executeUpdate('UPDATE "oc_file...', Array, Array)\n#3 /var/www/html/nc/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Query/QueryBuilder.php(222): OC\DB\Connection->executeUpdate('UPDATE "oc_file...', Array, Array)\n#4 /var/www/html/nc/li in /var/www/html/nc/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Driver/AbstractPostgreSQLDriver.php on line 55

The number of deadlocks varies from time to time, but some are there.