search

nextcloud / server

☁️ Nextcloud server, a safe home for all your data
https://nextcloud.com
GNU Affero General Public License v3.0
27.27k stars 4.05k forks source link

Race condition with locks in database - unique constraint violation on oc_file_locks #9305

Closed jirutka closed 5 years ago

jirutka commented 6 years ago

Steps to reproduce

  1. Share a folder.
  2. Login and logout.
  3. Click on the “share” button to share the folder.

However, the problem does not always occur! It seems that it depends on actual load or something.

Expected behaviour

The details sidebar should slide out and user should be able to share the folder.

Actual behaviour

The details sidebar slides out, but freeze with spinners spinning forever. Nextcloud logs exception:

An exception occurred while executing 'INSERT INTO "oc_file_locks" ("key","lock","ttl") SELECT ?,?,? FROM "oc_file_locks" WHERE "key" = ? HAVING COUNT(*) = 0
SQLSTATE[23505]: Unique violation: 7 ERROR:  duplicate key value violates unique constraint "lock_key_index"
DETAIL:  Key (key)=(files/737d52477f1fb583a5bfe5eb33e820da) already exists.

When user reloads the page and try it again, then it suddenly works.

Please examine Nextcloud, web server and browser logs below.

Server configuration

Operating system: Linux

Web server: nginx

Database: PostgreSQL 9.6

PHP version: 7.1.16

Nextcloud version: 12.0.6

Updated from an older Nextcloud/ownCloud or fresh install: updates

Where did you install Nextcloud from: Alpine Linux package

List of activated apps:

App list ``` Enabled: - activity: 2.5.2 - dav: 1.3.1 - federatedfilesharing: 1.2.0 - files: 1.7.2 - files_sharing: 1.4.0 - files_trashbin: 1.2.0 - provisioning_api: 1.2.0 - theming: 1.3.0 - user_ldap: 1.2.1 ```

Nextcloud configuration:

Config report ```json { "system": { "datadirectory": "\/var\/lib\/nextcloud\/data", "logfile": "\/var\/log\/nextcloud\/nextcloud.log", "apps_paths": [ { "path": "\/usr\/share\/webapps\/nextcloud\/apps", "url": "\/apps", "writable": false }, { "path": "\/var\/lib\/nextcloud\/apps", "url": "\/apps-appstore", "writable": true } ], "updatechecker": false, "check_for_working_htaccess": false, "appstoreenabled": false, "memcache.local": "\\OC\\Memcache\\APCu", "instanceid": "******", "passwordsalt": "******", "secret": "******", "trusted_domains": [ "******" ], "overwrite.cli.url": "https:\/\/******", "dbtype": "pgsql", "version": "12.0.6.1", "dbname": "nextcloud", "dbhost": "postgresql", "dbport": "", "dbtableprefix": "oc_", "dbuser": "******", "dbpassword": "******", "installed": true, "ldapIgnoreNamingRules": false, "ldapProviderFactory": "\\OCA\\User_LDAP\\LDAPProviderFactory", "mail_smtpmode": "smtp", "mail_smtpauthtype": "LOGIN", "mail_smtpsecure": "tls", "mail_from_address": "no-reply", "mail_domain": "******", "mail_smtpauth": 1, "mail_smtphost": "******", "mail_smtpport": "587", "mail_smtpname": "******", "mail_smtppassword": "******", "skeletondirectory": "", "theme": "", "loglevel": 2, "maintenance": false } } ```

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

LDAP configuration (delete this part if not used)

LDAP config ``` +-------------------------------+---------------------------------------------+ | Configuration | s02 | +-------------------------------+---------------------------------------------+ | hasMemberOfFilterSupport | | | hasPagedResultSupport | | | homeFolderNamingRule | | | lastJpegPhotoLookup | 0 | | ldapAgentName | | | ldapAgentPassword | *** | | ldapAttributesForGroupSearch | | | ldapAttributesForUserSearch | uid;cn;preferredEmail | | ldapBackupHost | | | ldapBackupPort | | | ldapBase | dc=****** | | ldapBaseGroups | ou=group,****** | | ldapBaseUsers | ou=people,****** | | ldapCacheTTL | 600 | | ldapConfigurationActive | 1 | | ldapDefaultPPolicyDN | | | ldapDynamicGroupMemberURL | | | ldapEmailAttribute | preferredEmail | | ldapExperiencedAdmin | 0 | | ldapExpertUUIDGroupAttr | cn | | ldapExpertUUIDUserAttr | uid | | ldapExpertUsernameAttr | uid | | ldapGidNumber | gidNumber | | ldapGroupDisplayName | cn | | ldapGroupFilter | (&(|(objectclass=groupOfNames))) | | ldapGroupFilterGroups | | | ldapGroupFilterMode | 0 | | ldapGroupFilterObjectclass | groupOfNames | | ldapGroupMemberAssocAttr | member | | ldapHost | ldap | | ldapIgnoreNamingRules | | | ldapLoginFilter | (&(|(objectclass=inetOrgPerson))(uid=%uid)) | | ldapLoginFilterAttributes | | | ldapLoginFilterEmail | 0 | | ldapLoginFilterMode | 0 | | ldapLoginFilterUsername | 1 | | ldapNestedGroups | 0 | | ldapOverrideMainServer | | | ldapPagingSize | 500 | | ldapPort | 389 | | ldapQuotaAttribute | | | ldapQuotaDefault | | | ldapTLS | 0 | | ldapUserDisplayName | cn | | ldapUserDisplayName2 | | | ldapUserFilter | (|(objectclass=inetOrgPerson)) | | ldapUserFilterGroups | | | ldapUserFilterMode | 1 | | ldapUserFilterObjectclass | inetOrgPerson | | ldapUuidGroupAttribute | auto | | ldapUuidUserAttribute | auto | | turnOffCertCheck | 0 | | turnOnPasswordChange | 0 | | useMemberOfToDetectMembership | 1 | +-------------------------------+---------------------------------------------+ ```

Client configuration

Browser: various (Firefox, Safari, Chrome, …)

Operating system: various (Linux, macOS, Windows)

Logs

Web server error log

Web server error log **The first try to open Details sidebar (unsuccessful):** ``` ***.***.***.*** - - [18/Apr/2018:16:50:28 +0200] "GET /ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&shared_with_me=true HTTP/1.1" 404 31 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36" "***.***.***.***" ***.***.***.*** - - [18/Apr/2018:16:50:28 +0200] "GET /ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&reshares=true HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36" "***.***.***.***" ``` **The second try to open Details sidebar (successful):** ``` ***.***.***.*** - - [18/Apr/2018:16:53:10 +0200] "GET /ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&reshares=true HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36" "***.***.***.***" ***.***.***.*** - - [18/Apr/2018:16:53:10 +0200] "GET /ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&shared_with_me=true HTTP/1.1" 200 74 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36" "***.***.***.***" ```

Nextcloud log (data/nextcloud.log)

Nextcloud log ```json { "reqId":"YOsVCMaJtv7lPX2MX9Uz", "level":3, "time":"2018-04-18T14:50:28+00:00", "remoteAddr":"********", "user":"*******", "app":"no app in context", "method":"GET", "url":"\/ocs\/v2.php\/apps\/files_sharing\/api\/v1\/shares?format=json&path=%2FDocuments&shared_with_me=true", "message":"Exception: {\"Exception\":\"Doctrine\\\\DBAL\\\\Exception\\\\UniqueConstraintViolationException\",\"Message\":\"An exception occurred while executing 'INSERT INTO \\\"oc_file_locks\\\" (\\\"key\\\",\\\"lock\\\",\\\"ttl\\\") SELECT ?,?,? FROM \\\"oc_file_locks\\\" WHERE \\\"key\\\" = ? HAVING COUNT(*) = 0' with params [\\\"files\\\\\\\/737d52477f1fb583a5bfe5eb33e820da\\\", 1, 1524066628, \\\"files\\\\\\\/737d52477f1fb583a5bfe5eb33e820da\\\"]:\\n\\nSQLSTATE[23505]: Unique violation: 7 ERROR: duplicate key value violates unique constraint \\\"lock_key_index\\\"\\nDETAIL: Key (key)=(files\\\/737d52477f1fb583a5bfe5eb33e820da) already exists.\",\"Code\":0,\"Trace\":\"#0 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/DBALException.php(128): Doctrine\\\\DBAL\\\\Driver\\\\AbstractPostgreSQLDriver->convertException('An exception oc...', Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException))\\n#1 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Connection.php(1015): Doctrine\\\\DBAL\\\\DBALException::driverExceptionDuringQuery(Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOPgSql\\\\Driver), Object(Doctrine\\\\DBAL\\\\Driver\\\\PDOException), 'INSERT INTO \\\"oc...', Array)\\n#2 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/DB\\\/Connection.php(213): Doctrine\\\\DBAL\\\\Connection->executeUpdate('INSERT INTO \\\"oc...', Array, Array)\\n#3 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/DB\\\/Adapter.php(114): OC\\\\DB\\\\Connection->executeUpdate('INSERT INTO \\\"oc...', Array)\\n#4 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/DB\\\/Connection.php(251): OC\\\\DB\\\\Adapter->insertIfNotExist('*PREFIX*file_lo...', Array, Array)\\n#5 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Lock\\\/DBLockingProvider.php(118): OC\\\\DB\\\\Connection->insertIfNotExist('*PREFIX*file_lo...', Array, Array)\\n#6 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Lock\\\/DBLockingProvider.php(163): OC\\\\Lock\\\\DBLockingProvider->initLockField('files\\\/737d52477...', 1)\\n#7 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Common.php(704): OC\\\\Lock\\\\DBLockingProvider->acquireLock('files\\\/737d52477...', 1)\\n#8 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/View.php(1931): OC\\\\Files\\\\Storage\\\\Common->acquireLock('files\\\/Documents', 1, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#9 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/View.php(2041): OC\\\\Files\\\\View->lockPath('\\\/*******\\\/files\\\/...', 1, false)\\n#10 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Node\\\/Node.php(360): OC\\\\Files\\\\View->lockFile('\\\/*******\\\/files\\\/...', 1)\\n#11 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/apps\\\/files_sharing\\\/lib\\\/Controller\\\/ShareAPIController.php(928): OC\\\\Files\\\\Node\\\\Node->lock(1)\\n#12 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/apps\\\/files_sharing\\\/lib\\\/Controller\\\/ShareAPIController.php(589): OCA\\\\Files_Sharing\\\\Controller\\\\ShareAPIController->lock(Object(OC\\\\Files\\\\Node\\\\Folder))\\n#13 [internal function]: OCA\\\\Files_Sharing\\\\Controller\\\\ShareAPIController->getShares('true', 'false', 'false', Object(OC\\\\Files\\\\Node\\\\Folder), 'false')\\n#14 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/Http\\\/Dispatcher.php(160): call_user_func_array(Array, Array)\\n#15 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/Http\\\/Dispatcher.php(90): OC\\\\AppFramework\\\\Http\\\\Dispatcher->executeController(Object(OCA\\\\Files_Sharing\\\\Controller\\\\ShareAPIController), 'getShares')\\n#16 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/App.php(114): OC\\\\AppFramework\\\\Http\\\\Dispatcher->dispatch(Object(OCA\\\\Files_Sharing\\\\Controller\\\\ShareAPIController), 'getShares')\\n#17 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/AppFramework\\\/Routing\\\/RouteActionHandler.php(47): OC\\\\AppFramework\\\\App::main('OCA\\\\\\\\Files_Shari...', 'getShares', Object(OC\\\\AppFramework\\\\DependencyInjection\\\\DIContainer), Array)\\n#18 [internal function]: OC\\\\AppFramework\\\\Routing\\\\RouteActionHandler->__invoke(Array)\\n#19 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/lib\\\/private\\\/Route\\\/Router.php(299): call_user_func(Object(OC\\\\AppFramework\\\\Routing\\\\RouteActionHandler), Array)\\n#20 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/ocs\\\/v1.php(78): OC\\\\Route\\\\Router->match('\\\/ocsapp\\\/apps\\\/fi...')\\n#21 \\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/ocs\\\/v2.php(23): require_once('\\\/usr\\\/share\\\/weba...')\\n#22 {main}\",\"File\":\"\\\/usr\\\/share\\\/webapps\\\/nextcloud\\\/3rdparty\\\/doctrine\\\/dbal\\\/lib\\\/Doctrine\\\/DBAL\\\/Driver\\\/AbstractPostgreSQLDriver.php\",\"Line\":63}", "userAgent":"Mozilla\/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/65.0.3325.181 Safari\/537.36", "version":"12.0.6.1" } ```

Browser log

Browser log **The first XHR request sent after click on share button:** ``` Request URL: https://******/ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&reshares=true Request Method: GET Status Code: 200 Request Headers accept: */* accept-encoding: gzip, deflate, br accept-language: en-GB,en;q=0.9,en-US;q=0.8,cs;q=0.7,de;q=0.6 cache-control: no-cache cookie: __Host-nc_sameSiteCookielax=true; __Host-nc_sameSiteCookiestrict=true; oc_sessionPassphrase=61jEvo******jy8C0UUw7dXwh%2B3z4ZfYnNIj8eML******FiA7Z5EfS1%2B2rmcAs04B******MO%2BaTTeC%2Bpcmb******UYAymYQZ%2BMOjmBxzC8sa******PcLxLMC8fXjTT; ocidyqaqrsqc=pecphph******tk1v7ksue0vdq ocs-apirequest: true pragma: no-cache requesttoken: GdG/H2qRtwea******7QklYrnfujhQoSVENErnvrHKY=:a4XYLFK******46+Fvm33ThC+LeI7n5+NRtwyzyGcMM= user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36 x-requested-with: XMLHttpRequest Response Headers: cache-control: no-cache, no-store, must-revalidate content-length: 74 content-security-policy: default-src 'none';base-uri 'none';manifest-src 'self' content-type: application/json; charset=utf-8 date: Wed, 18 Apr 2018 14:50:28 GMT expires: Thu, 19 Nov 1981 08:52:00 GMT pragma: no-cache server: nginx status: 200 strict-transport-security: max-age=315360000 x-content-type-options: nosniff x-download-options: noopen x-frame-options: SAMEORIGIN x-permitted-cross-domain-policies: none x-powered-by: PHP/7.1.16 x-robots-tag: none x-xss-protection: 1; mode=block ``` **The second XHR request sent after click on share button:** ``` Request URL: https://******/ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&shared_with_me=true Request Method: GET Status Code: 404 Request Headers accept: */* accept-encoding: gzip, deflate, br accept-language: en-GB,en;q=0.9,en-US;q=0.8,cs;q=0.7,de;q=0.6 cache-control: no-cache cookie: __Host-nc_sameSiteCookielax=true; __Host-nc_sameSiteCookiestrict=true; oc_sessionPassphrase=61jEvo******jy8C0UUw7dXwh%2B3z4ZfYnNIj8eML******FiA7Z5EfS1%2B2rmcAs04B******MO%2BaTTeC%2Bpcmb******UYAymYQZ%2BMOjmBxzC8sa******PcLxLMC8fXjTT; ocidyqaqrsqc=pecphph******tk1v7ksue0vdq ocs-apirequest: true pragma: no-cache requesttoken: GdG/H2qRtwea******7QklYrnfujhQoSVENErnvrHKY=:a4XYLFK******46+Fvm33ThC+LeI7n5+NRtwyzyGcMM= user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36 x-requested-with: XMLHttpRequest Response Headers cache-control: no-store, no-cache, must-revalidate content-encoding: gzip content-security-policy: default-src 'self'; script-src 'self' 'unsafe-eval' 'nonce-elhQQmd******VM2bmE0b3hreDJRR0VXRFVzS1RWT******6b1FSVGtmVT06dnllbXM4akVpT1hqMGZkR2pYc1JEdzkvYU******YURjM0FIeEVNKy9aQT0='; style-src 'self' 'unsafe-inline'; frame-src *; img-src * data: blob:; font-src 'self' data:; media-src *; connect-src *; object-src 'none'; base-uri 'self'; content-type: text/html; charset=UTF-8 date: Wed, 18 Apr 2018 14:50:28 GMT expires: Thu, 19 Nov 1981 08:52:00 GMT location: https://******/apps/files/ pragma: no-cache server: nginx status: 404 vary: Accept-Encoding x-frame-options: SAMEORIGIN x-powered-by: PHP/7.1.16 ```` After reload, the first request for `reshares=true` looks the same. **The second XHR request sent _after reload_ and click on share button again:** ``` Request URL: https://******/ocs/v2.php/apps/files_sharing/api/v1/shares?format=json&path=%2FDocuments&shared_with_me=true Request Method: GET Status Code: 200 Request Headers accept: */* accept-encoding: gzip, deflate, br accept-language: en-GB,en;q=0.9,en-US;q=0.8,cs;q=0.7,de;q=0.6 cache-control: no-cache cookie: __Host-nc_sameSiteCookielax=true; __Host-nc_sameSiteCookiestrict=true; oc_sessionPassphrase=61jEvo******jy8C0UUw7dXwh%2B3z4ZfYnNIj8eML******FiA7Z5EfS1%2B2rmcAs04B******MO%2BaTTeC%2Bpcmb******UYAymYQZ%2BMOjmBxzC8sa******PcLxLMC8fXjTT; ocidyqaqrsqc=pecphph******tk1v7ksue0vdq ocs-apirequest: true pragma: no-cache requesttoken: G940EhC55iOt******4CAYOozjlXeQ+3c8QAVeCYXz3Q=:aYpTISi******6RRMLfnL4Ra6xn1KJmwkFghHWF6oxE= user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/65.0.3325.181 Safari/537.36 x-requested-with: XMLHttpRequest Response Headers cache-control: no-cache, no-store, must-revalidate content-length: 74 content-security-policy: default-src 'none';base-uri 'none';manifest-src 'self' content-type: application/json; charset=utf-8 date: Wed, 18 Apr 2018 14:53:10 GMT expires: Thu, 19 Nov 1981 08:52:00 GMT pragma: no-cache server: nginx status: 200 strict-transport-security: max-age=315360000 x-content-type-options: nosniff x-download-options: noopen x-frame-options: SAMEORIGIN x-permitted-cross-domain-policies: none x-powered-by: PHP/7.1.16 x-robots-tag: none x-xss-protection: 1; mode=block ```
OneOfOne commented 6 years ago

bump

benediktg commented 6 years ago

Current Nextcloud version is 13.0.2 – does your issue still occur with NC13?

jirutka commented 6 years ago

does your issue still occur with NC13?

Yes, it does.

OneOfOne commented 6 years ago

Yes, I had to move to mariadb.

benediktg commented 6 years ago

But I also have PostgreSQL and cannot reproduce it. 😉

jirutka commented 6 years ago

@benedikt Do you use LDAP? Do you have Nextcloud behind a web proxy? Is the Nextcloud under some load (few users using it concurrently)? This is apparently some race condition, so hard to reproduce in testing environment.

OneOfOne commented 6 years ago

@benediktg it's extremely hard to reliably reproduce, however I had it happen with 2 tabs + the android client running in the same time.

Using redis fixes it so it is definitely a race issue with *SQL.

benediktg commented 6 years ago

Using redis fixes it so it is definitely a race issue with *SQL.

Ah, I also have redis (for transactional file locking).

Do you use LDAP? Do you have Nextcloud behind a web proxy? Is the Nextcloud under some load (few users using it concurrently)?

no; php-fpm behind nginx here; usually I use it alone.

MorrisJobke commented 6 years ago

In more recent versions (13.0.4 and 12.0.9) we reduced drastically the amount of lock statements which should avoid most of the problems in here.

Maybe also this one here is related: #8239

MorrisJobke commented 6 years ago

Crossposting from #8239:

Is it possible to get a file locking debug log? There is a config switch that - once set - will log all locking attempts. Maybe we can pinpoint then the actual problem. Would one of you so kind to provide this log as we are unable to reproduce the issue on our side.

You maybe want to combine this filelocking.debug flag with the log.condition option to only log it for one user.

Thanks in advance.

Temtaime commented 6 years ago

@MorrisJobke the problem persists in 13.0.4

matt-horwood-mayden commented 6 years ago

@MorrisJobke I have the same issue on 13.0.4

Operating system: Linux

Web server: nginx

Database: MySQL 5.5.60

PHP version: 7.0.27

Nextcloud version: 13.0.4

MySQL Log

LATEST DETECTED DEADLOCK
------------------------
180705 15:56:58
*** (1) TRANSACTION:
TRANSACTION 1344059, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 8 lock struct(s), heap size 1024, 11 row lock(s), undo log entries 5
MySQL thread id 1094, OS thread handle 0x470ff450, query id 70579 192.168.49.203 oc_admin Updating
UPDATE `oc_file_locks` SET `lock` = `lock` -1 WHERE (`key` IN ('files/c0ecd6ca2172b9551e6d4d252d2eac26', 'files/48247726ea4e98e85ca0b7803f73ea27', 'files/22056201cbd111db6f441791fd69d2aa', 'files/ca11a1257d59bf594663aa454d934412', 'files/e9bea7fe5757761fc0868dcd73a1ee96', 'files/770014c2bba5284a1de2bc35ce1055c5', 'files/47ca3494e45001090659586b929b7631', 'files/e97e5387112b19df8f8d39e82d68fbc5', 'files/0a1d368ddd09601e558bc998ac44ef5b', 'files/1aa175c2e547e2fbae4b382bfec39072', 'files/12357cc463150eccca3e4586a339d9f2')) AND (`lock` > 0)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 435 page no 134 n bits 336 index `lock_key_index` of table `horwood_nextcloud`.`oc_file_locks` trx id 1344059 lock_mode X locks rec but not gap waiting
Record lock, heap no 103 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 30; hex 66696c65732f343832343737323665613465393865383563613062373830; asc files/48247726ea4e98e85ca0b780; (total 38 bytes);
 1: len 8; hex 0000000000004a0f; asc       J ;;

Nextcloud Log:

{"reqId":"WMLIa75snwLlfuS9pbRh","level":0,"time":"2018-07-05 14:56:58","remoteAddr":"x.x.x.x","user":"matt","app":"core","method":"GET","url":"\/css\/core\/89a5-fd1c-jquery-ui-fixes.css","message":"Exception while scanning file \"appdata_oc0xc6xq5cff\/theming\": An exception occurred while executing 'UPDATE `oc_file_locks` SET `lock` = `lock` + 1, `ttl` = ? WHERE `key` = ? AND `lock` >= 0' with params [1530806218, \"files\\\/22056201cbd111db6f441791fd69d2aa\"]:\n\nSQLSTATE[40001]: Serialization failure: 1213 Deadlock found when trying to get lock; try restarting transaction","userAgent":"Mozilla\/5.0 (Macintosh; Intel Mac OS X 10_13_5) AppleWebKit\/537.36 (KHTML, like Gecko) Chrome\/66.0.3359.170 Safari\/537.36 OPR\/53.0.2907.99","version":"13.0.4.0"}
MorrisJobke commented 6 years ago

UPDATE oc_file_locks SET lock = lock -1

This looks like it could be fixed by #10116. That one avoids, that more locks are freed than there are (the lock is usually the count of existing locks and -1 doesn't make sense.

matt-horwood-mayden commented 6 years ago

Could we get a bug fix out soon?

MorrisJobke commented 6 years ago

Could we get a bug fix out soon?

Plan is to backport it, but testing from your side may help to know if this is a fix for your problem or if we still need to check for further places as well.

matt-horwood-mayden commented 6 years ago

Just had a proper look at pull request #10116 and that wont help me, I dont use memcache for locking.

MorrisJobke commented 6 years ago

Okay. Then we should check for the same in the DB provider.

matt-horwood-mayden commented 6 years ago

Just in case it helps with debug

Nextcloud configuration:

Config report ``` { "system": { "instanceid": "***REMOVED SENSITIVE VALUE***", "passwordsalt": "***REMOVED SENSITIVE VALUE***", "secret": "***REMOVED SENSITIVE VALUE***", "trusted_domains": [ "owncloud.horwood.biz", "212.159.117.222", "192.168.49.203" ], "datadirectory": "***REMOVED SENSITIVE VALUE***", "overwrite.cli.url": "https:\/\/owncloud.horwood.biz", "dbtype": "mysql", "version": "13.0.4.0", "dbname": "***REMOVED SENSITIVE VALUE***", "dbhost": "***REMOVED SENSITIVE VALUE***", "dbtableprefix": "oc_", "dbuser": "***REMOVED SENSITIVE VALUE***", "dbpassword": "***REMOVED SENSITIVE VALUE***", "logtimezone": "UTC", "logfile": "\/var\/data\/owncloud\/owncloud.log", "logdateformat": "Y-m-d H:i:s", "installed": true, "mail_smtpmode": "smtp", "mail_from_address": "***REMOVED SENSITIVE VALUE***", "mail_domain": "***REMOVED SENSITIVE VALUE***", "mail_smtphost": "***REMOVED SENSITIVE VALUE***", "mail_smtpport": "25", "theme": "", "filelocking.enabled": "true", "memcache.local": "\\OC\\Memcache\\APCu", "redis": { "host": "***REMOVED SENSITIVE VALUE***", "port": 6379, "timeout": 0 }, "asset-pipeline.enabled": false, "filesystem_check_changes": "0", "trashbin_retention_obligation": "auto", "preview_max_scale_factor": 1, "preview_max_x": 1024, "preview_max_y": 1024, "maintenance": false, "loglevel": 0, "htaccess.RewriteBase": "\/", "has_internet_connection": true, "data-fingerprint": "a40dea991a946a4d82e4a3702c8f1fcc", "updater.secret": "***REMOVED SENSITIVE VALUE***", "log_rotate_size": 52428800, "tempdirectory": "\/mnt\/pendrive\/nc_temp" } } ```
obel1x commented 5 years ago

Does the Protocoll shows references to Adapter.php LINE 115 like: /srv/www/htdocs/owncloud/lib/private/DB/Adapter.php - line 115: OC\DB\Connection->executeUpdate("INSERT INTO ... 0", [ "10","11", ... "]) in relation to the Deadlock?

If so - maybe you want to check my solution in #6160 for testing - i think the problem is in general using update and select together on one table which should work, but sometimes doesn't (at least for me). Regards, Daniel

MorrisJobke commented 5 years ago

Fix is in #12366

MorrisJobke commented 5 years ago

Fix is in #12366

Was superseded due to feedback by #12371

rcdailey commented 5 years ago

So until I upgrade to Nextcloud 15 which has this fix, what are the consequences of this error on version 14? Will the desktop client on Windows eventually be able to upload those files? Or is this dangerous, because some files do not get synced?

MorrisJobke commented 5 years ago

So until I upgrade to Nextcloud 15 which has this fix, what are the consequences of this error on version 14? Will the desktop client on Windows eventually be able to upload those files? Or is this dangerous, because some files do not get synced?

We try to backport fixes for this as well to stable14.

MorrisJobke commented 5 years ago

We try to backport fixes for this as well to stable14.

See #12413 for the fix to this issue (it fixes the race condition with the unique constraint violation and the deadlock)

covici commented 5 years ago

I am getting this error under 15.0.7 when I share a link, or disable the sharing of the link. I am using linux, postgresql 10.8 and apache 2.4.39. I did not get this in 13.0.5 but I got it in 14.0.12. I am using gentoo. How would I use redis to get around this?

covici commented 5 years ago

I can reproduce this every time, so its not a race condition, or at least not that I could figure out.

MorrisJobke commented 5 years ago

@covici Mind to open a new ticket about this and link to this one here?

m-0-r-t commented 4 years ago

I had the same problem in production today, I just restarted redis container.

Snazzie commented 2 years ago

Hit this problem during upgrade docker container from 23-24.... now stuck on update screen