Deadlock found when trying to get lock; try restarting transaction in LDAP app #6187
Comments
|
I digged into the code and already found the root cause of that issue. When executing the DAV request, nextcloud tries to verify username and password using the LDAP provider. This provider queries LDAP to retrieve username and password. Once retrieved, the gathered attributes are memorized and the lastrefresh time is memorized in the database. When running many requests this is not performant and also triggers above database issue. Overall, I think the whole behaviour should be checked. First, the lastRefreshed value might be better stored in a cache instead of the database. Second, the behavior does not respect the CacheLDAP timespan configuration value. This is set to, e.g., 600s, so I would expect a refresh the most every 10min as in the "update" method of User.php in the LDAP code. However, the code in "processAttributes" always refreshes, no matter whether 10min have passed. I wonder why the protective "if($this->needsRefresh())" is not used in the "processAttributes" method too. |
|
I'm seeing this without using LDAP. EDIT; not this specific error message though. But deadlock. |
|
Deadlocks might happen, most of the time when memory caching via PHP's memcache or redis is not configured correctly or under very high load. You could look up other issues on GitHub for hints how to resolve this. The issue I am reporting here is more a programm bug as it accesses the database with high frequencies for no obvious reasons from the LDAP module. |
|
This is how I managed to resolve this issue for both my Local Auth server and my LDAP servers Edit On all of the !== change them to != so it should look like this
Edit: Found this thread while I was trying to fix these issues so thought I'd post my findings. |
|
Maybe this could help? #7005 |
|
Duplicate #3453 |
|
This is not a duplicate and should not be closed. I have the correct isolation level set and the issue I am describing still happens. As explained in my report, it is a specific issue in the LDAP provider which causes tons of unnecessary DB requests where only a request should happen every 10 minutes. Hence, this issue should be reopened as it is not resolved. |
|
Well the message you posted above:
Is caused by a wrong transaction isolation level and unrelated to ldap, anyway |
|
It is related to LDAP as the UPDATE you see there is caused by the LDAP plugin and it writes the same data cell every few microseconds - which IMHO is the root cause of the issue. And let me cite from the Mysql docs: "For UPDATE or DELETE statements, InnoDB holds locks only for rows that it updates or deletes. Record locks for nonmatching rows are released after MySQL has evaluated the WHERE condition. This greatly reduces the probability of deadlocks, but they can still happen. " (cf. https://dev.mysql.com/doc/refman/5.7/en/innodb-transaction-isolation-levels.html) The issue here is that all these frequent UPDATEs lock exactly the same row (even they write the same attribute in that row). In sum, the raised the low likelyhood of deadlocks to a relevant one. |
|
I just cross-checked the issue: On the database I executed But still I get |
|
//edited the text --^ |
|
I tested the issue again with Nextcloud 13.0. It has dramatically decreased and is hard to trigger at all now due to the massive performance improvements in the LDAP connector. Once in a while it still happens, maybe when the server is under heavy load. But now it is at least on a very acceptable level. |
|
Same for file locking: #6899 |
|
just saw this issue also related to Deadlock. i made a commit for solution needs testing at #6160. |
skjnldsv
added
the
0. Needs triage
|
Fixed with #12411 I assume |
|
I set up Nextcloud (23) on a Fedora server with Mariadb and if a user uploads a lot of files at once it happens again. The uploads fail with 500 server error and there's this: I don't think that this is a configuration problem because I configured everything like I did on another server and there it worked (Nextcloud 22) except that I didn't use APCu I have APCu, redis file locking and redis distributed cache as following: Is the distributed redis cache the problem or is it a nextcloud problem? |
Steps to reproduce
Expected behaviour
Tell us what should happen
Server should work fine. Best would be to not run into the issue at all, hotfix would be to do what the error says and retry the transaction (maybe while issueing a warning).
Actual behaviour
Tell us what happens instead
You get an "internal server error"
Server log explains the cause is a database locking issue "An exception occurred while executing 'UPDATE
oc_preferencesSETconfigvalue= ? WHERE (userid= ?) AND (appid= ?) AND (configkey= ?)' with params [...]. Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction"General server configuration
Operating system: Linux nextcloud-225186920-qsznp 3.10.0-514.21.1.el7.x86_64 #1 SMP Thu May 25 17:04:51 UTC 2017 x86_64
Web server: Apache/2.4.10 (Debian) (apache2handler)
Database: mysql 10.1.25
PHP version: 7.1.8
PHP-modules loaded
Nextcloud configuration
Nextcloud version: 12.0.2 - 12.0.2.0
**Updated from an older Nextcloud/ownCloud or fresh install: Updated from 12.0
**Where did you install Nextcloud from: Offical docker image
**Are you using external storage, if yes which one: no
Are you using encryption: no
**Are you using an external user-backend, if yes which one: LDAP, using OpenLDAP - this is the root cause.
Signing status
Enabled apps
Disabled apps
Content of config/config.php
LDAP config
Client configuration
Browser: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:54.0) Gecko/20100101 Firefox/54.0
**Operating system: latest MacOS
Logs
Web server error log
Nextcloud log (data/nextcloud.log)
{"reqId":"o0nv7P3dGBdRoHu5kexs","level":3,"time":"2017-08-19T15:51:18+00:00","remoteAddr":"10.244.4.134","user":"--","app":"no app in context","method":"PROPFIND","url":"/remote.php/dav/principals/users/ae7066da-f4fb-1036-8cad-9b286aacc383/","message":"Exception: {"Exception":"Doctrine\\DBAL\\Exception\\DriverException","Message":"An exception occurred while executing 'UPDATE
oc_preferencesSETconfigvalue= ? WHERE (userid= ?) AND (appid= ?) AND (configkey= ?)' with params [1503157877, \"ae7066da-f4fb-1036-8cad-9b286aacc383\", \"user_ldap\", \"lastFeatureRefresh\"]:\n\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction","Code":0,"Trace":"#0 \/var\/www\/html\/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\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Connection.php(1015): Doctrine\\DBAL\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\DBAL\\Driver\\PDOMySql\\Driver), Object(Doctrine\\DBAL\\Driver\\PDOException), 'UPDATEoc_pref...', Array)\\n#2 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/DB\\\/Connection.php(213): Doctrine\\\\DBAL\\\\Connection->executeUpdate('UPDATEoc_pref...', Array, Array)\n#3 \/var\/www\/html\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php(208): OC\\DB\\Connection->executeUpdate('UPDATEoc_pref...', Array, Array)\\n#4 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/DB\\\/QueryBuilder\\\/QueryBuilder.php(213): Doctrine\\\\DBAL\\\\Query\\\\QueryBuilder->execute()\\n#5 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/AllConfig.php(232): OC\\\\DB\\\\QueryBuilder\\\\QueryBuilder->execute()\\n#6 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/User\\\/User.php(372): OC\\\\AllConfig->setUserValue('ae7066da-f4fb-1...', 'user_ldap', 'lastFeatureRefr...', 1503157877)\\n#7 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/User\\\/User.php(178): OCA\\\\User_LDAP\\\\User\\\\User->markRefreshTime()\\n#8 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/Access.php(835): OCA\\\\User_LDAP\\\\User\\\\User->processAttributes(Array)\\n#9 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/Access.php(807): OCA\\\\User_LDAP\\\\Access->batchApplyUserAttributes(Array)\\n#10 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/Access.php(780): OCA\\\\User_LDAP\\\\Access->fetchListOfUsers('(&(&(|(objectcl...', Array)\\n#11 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/User_LDAP.php(136): OCA\\\\User_LDAP\\\\Access->fetchUsersByLoginName('snowball', Array)\\n#12 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/User_LDAP.php(153): OCA\\\\User_LDAP\\\\User_LDAP->getLDAPUserByLoginName('snowball')\\n#13 [internal function]: OCA\\\\User_LDAP\\\\User_LDAP->checkPassword(*** sensitive parameters replaced ***)\\n#14 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/User_Proxy.php(98): call_user_func_array(Array, Array)\\n#15 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/Proxy.php(148): OCA\\\\User_LDAP\\\\User_Proxy->callOnLastSeenOn('snowball', 'checkPassword', Array, false)\\n#16 \\\/var\\\/www\\\/html\\\/apps\\\/user_ldap\\\/lib\\\/User_Proxy.php(186): OCA\\\\User_LDAP\\\\Proxy->handleRequest('snowball', 'checkPassword', Array)\\n#17 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/User\\\/Manager.php(215): OCA\\\\User_LDAP\\\\User_Proxy->checkPassword(*** sensitive parameters replaced ***)\\n#18 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/User\\\/Manager.php(192): OC\\\\User\\\\Manager->checkPasswordNoLogging('snowball', 'SHAUsiCEaDyneRt')\\n#19 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/User\\\/Session.php(541): OC\\\\User\\\\Manager->checkPassword(*** sensitive parameters replaced ***)\\n#20 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/User\\\/Session.php(326): OC\\\\User\\\\Session->loginWithPassword(*** sensitive parameters replaced ***)\\n#21 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/User\\\/Session.php(400): OC\\\\User\\\\Session->login(*** sensitive parameters replaced ***)\\n#22 \\\/var\\\/www\\\/html\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(129): OC\\\\User\\\\Session->logClientIn(*** sensitive parameters replaced ***)\\n#23 \\\/var\\\/www\\\/html\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Backend\\\/AbstractBasic.php(105): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->validateUserPass(*** sensitive parameters replaced ***)\\n#24 \\\/var\\\/www\\\/html\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(252): Sabre\\\\DAV\\\\Auth\\\\Backend\\\\AbstractBasic->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#25 \\\/var\\\/www\\\/html\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Auth.php(154): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->auth(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#26 \\\/var\\\/www\\\/html\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(201): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Auth->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#27 \\\/var\\\/www\\\/html\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(150): Sabre\\\\DAV\\\\Auth\\\\Plugin->check(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#28 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#29 \\\/var\\\/www\\\/html\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#30 \\\/var\\\/www\\\/html\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(466): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n#31 \\\/var\\\/www\\\/html\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#32 \\\/var\\\/www\\\/html\\\/apps\\\/dav\\\/lib\\\/Server.php(253): Sabre\\\\DAV\\\\Server->exec()\\n#33 \\\/var\\\/www\\\/html\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(33): OCA\\\\DAV\\\\Server->exec()\\n#34 \\\/var\\\/www\\\/html\\\/remote.php(162): require_once('\\\/var\\\/www\\\/html\\\/a...')\\n#35 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractMySQLDriver.php\",\"Line\":116}","userAgent":"Mac OS X\/10.12.6 (16G29) AddressBook\/1756.20","version":"12.0.2.0"} {"reqId":"o0nv7P3dGBdRoHu5kexs","level":4,"time":"2017-08-19T15:51:18+00:00","remoteAddr":"10.244.4.134","user":"--","app":"webdav","method":"PROPFIND","url":"\/remote.php\/dav\/principals\/users\/ae7066da-f4fb-1036-8cad-9b286aacc383\/","message":"Exception: {\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\ServiceUnavailable\",\"Message\":\"Doctrine\\\\DBAL\\\\Exception\\\\DriverException: An exception occurred while executing 'UPDATEoc_preferencesSETconfigvalue= ? WHERE (userid= ?) AND (appid= ?) AND (configkey` = ?)' with params [1503157877, \"ae7066da-f4fb-1036-8cad-9b286aacc383\", \"user_ldap\", \"lastFeatureRefresh\"]:\n\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction","Code":0,"Trace":"#0 \/var\/www\/html\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Plugin.php(201): OCA\\DAV\\Connector\\Sabre\\Auth->check(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n#1 \/var\/www\/html\/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\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n#4 \/var\/www\/html\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(466): Sabre\\Event\\EventEmitter->emit('beforeMethod', Array)\n#5 \/var\/www\/html\/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\/apps\/dav\/lib\/Server.php(253): Sabre\\DAV\\Server->exec()\n#7 \/var\/www\/html\/apps\/dav\/appinfo\/v2\/remote.php(33): OCA\\DAV\\Server->exec()\n#8 \/var\/www\/html\/remote.php(162): require_once('\/var\/www\/html\/a...')\n#9 {main}","File":"\/var\/www\/html\/apps\/dav\/lib\/Connector\/Sabre\/Auth.php","Line":162}","userAgent":"Mac OS X/10.12.6 (16G29) AddressBook/1756.20","version":"12.0.2.0"}Browser log
The text was updated successfully, but these errors were encountered: