Skip to content

Deadlock found when trying to get lock; try restarting transaction in LDAP app #6187

New issue
New issue
Closed
Closed
Deadlock found when trying to get lock; try restarting transaction in LDAP app#6187
Labels
0. Needs triagePending check for reproducibility or if it fits our roadmapbugfeature: ldap
@snowball77

Description

@snowball77
snowball77
opened on Aug 19, 2017

Steps to reproduce

  1. Install nextcloud, LDAP and a DAV app like calendar
  2. Run a huge amount of DAV operations like in a calendar synchronization

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_preferences SET configvalue = ? 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 
 - Core
 - date
 - libxml
 - openssl
 - pcre
 - sqlite3
 - zlib
 - ctype
 - curl
 - dom
 - fileinfo
 - filter
 - ftp
 - hash
 - iconv
 - json
 - mbstring
 - SPL
 - PDO
 - session
 - posix
 - Reflection
 - standard
 - SimpleXML
 - pdo_sqlite
 - Phar
 - tokenizer
 - xml
 - xmlreader
 - xmlwriter
 - mysqlnd
 - apache2handler
 - apcu
 - exif
 - gd
 - intl
 - ldap
 - mcrypt
 - memcached
 - mysqli
 - pcntl
 - pdo_mysql
 - pdo_pgsql
 - pgsql
 - redis
 - zip
 - Zend OPcache

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 
 - activity: 2.5.2
 - bruteforcesettings: 1.0.2
 - calendar: 1.5.3
 - comments: 1.2.0
 - contacts: 1.5.3
 - dav: 1.3.0
 - federatedfilesharing: 1.2.0
 - federation: 1.2.0
 - files: 1.7.2
 - files_pdfviewer: 1.1.1
 - files_sharing: 1.4.0
 - files_texteditor: 2.4.1
 - files_trashbin: 1.2.0
 - files_versions: 1.5.0
 - files_videoplayer: 1.1.0
 - firstrunwizard: 2.1
 - gallery: 17.0.0
 - issuetemplate: 0.2.2
 - logreader: 2.0.0
 - lookup_server_connector: 1.0.0
 - nextcloud_announcements: 1.1
 - notifications: 2.0.0
 - oauth2: 1.0.5
 - password_policy: 1.2.2
 - provisioning_api: 1.2.0
 - serverinfo: 1.2.0
 - sharebymail: 1.2.0
 - survey_client: 1.0.0
 - systemtags: 1.2.0
 - theming: 1.3.0
 - twofactor_backupcodes: 1.1.1
 - updatenotification: 1.2.0
 - user_ldap: 1.2.1
 - workflowengine: 1.2.0
Disabled apps 
 - admin_audit
 - encryption
 - files_external
 - user_external
Content of config/config.php 
{
    "apps_paths": [
        {
            "path": "\/var\/www\/html\/apps",
            "url": "\/apps",
            "writable": false
        },
        {
            "path": "\/var\/www\/html\/custom_apps",
            "url": "\/custom_apps",
            "writable": true
        }
    ],
    "instanceid": "oco6psmk02yu",
    "passwordsalt": "***REMOVED SENSITIVE VALUE***",
    "secret": "***REMOVED SENSITIVE VALUE***",
    "trusted_domains": [
        "storage.rss.iste.uni-stuttgart.de",
        "nextcloud.default.svc.cluster.local"
    ],
    "datadirectory": "\/var\/www\/html\/data",
    "overwrite.cli.url": "https:\/\/storage.rss.iste.uni-stuttgart.de",
    "dbtype": "mysql",
    "version": "12.0.2.0",
    "dbname": "nextcloud",
    "dbhost": "pxc-cluster.default.svc.cluster.local",
    "dbport": "",
    "dbtableprefix": "oc_",
    "dbuser": "***REMOVED SENSITIVE VALUE***",
    "dbpassword": "***REMOVED SENSITIVE VALUE***",
    "installed": true,
    "ldapIgnoreNamingRules": false,
    "ldapProviderFactory": "\\OCA\\User_LDAP\\LDAPProviderFactory",
    "mail_smtpmode": "smtp",
    "mail_smtpauthtype": "LOGIN",
    "mail_domain": "rss.iste.uni-stuttgart.de",
    "mail_smtphost": "mailgw.informatik.uni-stuttgart.de",
    "mail_smtpport": "465",
    "mail_smtpdebug": true,
    "mail_smtpsecure": "ssl",
    "mail_smtpauth": 1,
    "mail_smtpname": "***REMOVED SENSITIVE VALUE***",
    "mail_smtppassword": "***REMOVED SENSITIVE VALUE***",
    "memcache.local": "\\OC\\Memcache\\APCu",
    "filelocking.enabled": true,
    "memcache.locking": "\\OC\\Memcache\\Redis",
    "redis": {
        "host": "redis.default.svc.cluster.local",
        "port": 6379,
        "timeout": 0,
        "password": "***REMOVED SENSITIVE VALUE***"
    },
    "mail_from_address": "nextcloud-noreply",
    "theme": "",
    "loglevel": 2,
    "maintenance": false,
    "updater.secret": "***REMOVED SENSITIVE VALUE***"
}
LDAP config 
With access to your command line run e.g.:
sudo -u www-data php occ ldap:show-config
from within your Nextcloud installation folder

Without access to your command line download the data/owncloud.db to your local
computer or access your SQL server remotely and run the select query:
SELECT * FROM `oc_appconfig` WHERE `appid` = 'user_ldap';

Eventually replace sensitive data as the name/IP-address of your LDAP server or groups.

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 
Insert your webserver log here
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_preferences SET configvalue = ? 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), 'UPDATE oc_pref...', Array)\\n#2 \\\/var\\\/www\\\/html\\\/lib\\\/private\\\/DB\\\/Connection.php(213): Doctrine\\\\DBAL\\\\Connection->executeUpdate('UPDATE oc_pref...', Array, Array)\n#3 \/var\/www\/html\/3rdparty\/doctrine\/dbal\/lib\/Doctrine\/DBAL\/Query\/QueryBuilder.php(208): OC\\DB\\Connection->executeUpdate('UPDATE oc_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 '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\/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 
Insert your browser log here, this could for example include:

a) The javascript console log
b) The network log
c) ...

Metadata

Metadata

Assignees

No one assigned

    Labels

    0. Needs triagePending check for reproducibility or if it fits our roadmapbugfeature: ldap

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions