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

[jirutka]

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

{
    "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

{
  "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]

bump

[benediktg]

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

[jirutka]

does your issue still occur with NC13?

Yes, it does.

[OneOfOne]

Yes, I had to move to mariadb.

[benediktg]

But I also have PostgreSQL and cannot reproduce it. 😉

[jirutka]

@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]

@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]

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.