Double release of memcache locks causes PUT requests to fail

[jvsalo]

Steps to reproduce

Set up a Nextcloud instance using Redis.

Then, create a large number of new, small files and attempt to sync them with the Desktop Client, eg.:

for i in $(seq 1000); do touch $i; done

Expected behaviour

Files are synced without problem.

Actual behaviour

Occasionally, syncing a file fails as such (as seen from Desktop Client Activity tab):

Server replied "423 Locked" to "PUT https://nextcloud.example.com/remote.php/dav/files/.../test/94349" ("test" is locked)

I'm able to consistently reproduce this in our production setup, but not on a VM that's running on my laptop. Probably latency and other matters change the outcome of a race condition. In my tests, often 1-10 requests fail out of 1000. Desktop Client will re-attempt the sync afterwards that normally fixes the issue.

Below are some selected logs taken with

'loglevel' => 0,
'filelocking.debug' => true,
'debug' => true,

The lock named files/test is acquired only once, but released twice:

Typical trace of a successful PUT request

{"reqId":"rLSyz4oCzb8Bc2DofduX","level":0,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"no app in context","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"Deprecated event type for OCA\\User_LDAP\\User\\User::postLDAPBackendAdded: null","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":0,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"PHP","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"Calling the \"Symfony\\Component\\EventDispatcher\\EventDispatcherInterface::dispatch()\" method with the event name as the first argument is deprecated since Symfony 4.3, pass it as the second argument and provide the event object as the first argument instead. at /opt/censored/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php#58","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":3,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"nextcloud_announcements","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":{"Exception":"RuntimeException","Message":"App class OCA\\NextcloudAnnouncements\\AppInfo\\Application is not setup via query() but directly","Code":0,"Trace":[{"file":"/opt/censored/nextcloud/apps/nextcloud_announcements/lib/AppInfo/Application.php","line":34,"function":"__construct","class":"OCP\\AppFramework\\App","type":"->","args":["nextcloud_announcements"]},{"file":"/opt/censored/nextcloud/apps/nextcloud_announcements/appinfo/app.php","line":24,"function":"__construct","class":"OCA\\NextcloudAnnouncements\\AppInfo\\Application","type":"->","args":[]},{"file":"/opt/censored/nextcloud/lib/private/legacy/app.php","line":266,"args":["/opt/censored/nextcloud/apps/nextcloud_announcements/appinfo/app.php"],"function":"require_once"},{"file":"/opt/censored/nextcloud/lib/private/legacy/app.php","line":155,"function":"requireAppFile","class":"OC_App","type":"::","args":["nextcloud_announcements"]},{"file":"/opt/censored/nextcloud/lib/private/legacy/app.php","line":128,"function":"loadApp","class":"OC_App","type":"::","args":["nextcloud_announcements"]},{"file":"/opt/censored/nextcloud/remote.php","line":150,"function":"loadApps","class":"OC_App","type":"::","args":[["filesystem","logging"]]}],"File":"/opt/censored/nextcloud/lib/public/AppFramework/App.php","Line":80,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"acquire shared lock on \"files/test/95285\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"acquire shared lock on \"files/test\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"acquire exclusive lock on \"files/userdir/files/test/95285.upload.part\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"acquire shared lock on \"files/userdir\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"acquire shared lock on \"files/userdir/files\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"acquire shared lock on \"files/userdir/files/test\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"change lock on \"files/test/95285\" to exclusive on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"change lock on \"files/test/95285\" to shared on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release exclusive lock on \"files/userdir/files/test/95285.upload.part\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/userdir\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/userdir/files\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/userdir/files/test\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/test/95285\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/test\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/test/95285\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"rLSyz4oCzb8Bc2DofduX","level":1,"time":"2020-05-23T22:42:15+00:00","remoteAddr":"IP_CENSORED","user":"userdir","app":"locking","method":"PUT","url":"/remote.php/dav/files/userdir/test/95285","message":"release shared lock on \"files/test\" on storage \"home::userdir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}

It is released once here:

 nextcloud/lib/private/Lock/MemcacheLockingProvider.php:releaseLock() <-
 nextcloud/lib/private/Files/Storage/Common.php:779 <-
 nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php:604 <-
 nextcloud/lib/private/Files/View.php:2034 <-
 nextcloud/lib/private/Files/View.php:2090 <-
 nextcloud/apps/dav/lib/Connector/Sabre/Node.php:395 <-
 nextcloud/apps/dav/lib/Connector/Sabre/Directory.php:159 <-
 nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:1096 <-
 nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php:525 <-
 : <-
 nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php:105 <-
 nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:479 <-
 nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:254 <-
 nextcloud/apps/dav/lib/Server.php:319 <-
 nextcloud/apps/dav/appinfo/v2/remote.php:35 <-
 nextcloud/remote.php:165

and then again here:

nextcloud/lib/private/Lock/MemcacheLockingProvider.php:releaseLock() <-
nextcloud/lib/private/Files/Storage/Common.php:779 <-
nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php:604 <-
nextcloud/lib/private/Files/View.php:2034 <-
nextcloud/lib/private/Files/View.php:2090 <-
nextcloud/apps/dav/lib/Connector/Sabre/Node.php:395 <-
nextcloud/apps/dav/lib/Connector/Sabre/LockPlugin.php:82 <-
: <-
nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php:105 <-
nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:492 <-
nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php:254 <-
nextcloud/apps/dav/lib/Server.php:319 <-
nextcloud/apps/dav/appinfo/v2/remote.php:35 <-
nextcloud/remote.php:165

I'm seeing that LockPlugin never acquires the lock, but it still releases it.

The mechanism at

server/lib/private/Lock/MemcacheLockingProvider.php

Line 108 in 5e35594

// if we somehow release more locks then exists, reset the lock

sometimes works around this issue, but there is a race condition. Sometimes the lock value is -1 when another request increments it at

server/lib/private/Lock/MemcacheLockingProvider.php

Line 78 in 5e35594

if (!$this->memcache->inc($path)) {

which is then considered a failure because return value 0 is interpreted as false.

Then this is what you get, and the request ends up in 423

{"reqId":"PwRb6pUZ88QcQh9friFs","level":0,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"no app in context","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":"Deprecated event type for OCA\\User_LDAP\\User\\User::postLDAPBackendAdded: null","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"PwRb6pUZ88QcQh9friFs","level":0,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"PHP","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":"Calling the \"Symfony\\Component\\EventDispatcher\\EventDispatcherInterface::dispatch()\" method with the event name as the first argument is deprecated since Symfony 4.3, pass it as the second argument and provide the event object as the first argument instead. at /opt/censored/nextcloud/3rdparty/symfony/event-dispatcher/EventDispatcher.php#58","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"PwRb6pUZ88QcQh9friFs","level":3,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"nextcloud_announcements","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":{"Exception":"RuntimeException","Message":"App class OCA\\NextcloudAnnouncements\\AppInfo\\Application is not setup via query() but directly","Code":0,"Trace":[{"file":"/opt/censored/nextcloud/apps/nextcloud_announcements/lib/AppInfo/Application.php","line":34,"function":"__construct","class":"OCP\\AppFramework\\App","type":"->","args":["nextcloud_announcements"]},{"file":"/opt/censored/nextcloud/apps/nextcloud_announcements/appinfo/app.php","line":24,"function":"__construct","class":"OCA\\NextcloudAnnouncements\\AppInfo\\Application","type":"->","args":[]},{"file":"/opt/censored/nextcloud/lib/private/legacy/app.php","line":266,"args":["/opt/censored/nextcloud/apps/nextcloud_announcements/appinfo/app.php"],"function":"require_once"},{"file":"/opt/censored/nextcloud/lib/private/legacy/app.php","line":155,"function":"requireAppFile","class":"OC_App","type":"::","args":["nextcloud_announcements"]},{"file":"/opt/censored/nextcloud/lib/private/legacy/app.php","line":128,"function":"loadApp","class":"OC_App","type":"::","args":["nextcloud_announcements"]},{"file":"/opt/censored/nextcloud/remote.php","line":150,"function":"loadApps","class":"OC_App","type":"::","args":[["filesystem","logging"]]}],"File":"/opt/censored/nextcloud/lib/public/AppFramework/App.php","Line":80,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"PwRb6pUZ88QcQh9friFs","level":1,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"locking","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":"acquire shared lock on \"files/test/96088\" on storage \"home::homedir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"PwRb6pUZ88QcQh9friFs","level":1,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"locking","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":"acquire shared lock on \"files/test\" on storage \"home::homedir\"","userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"PwRb6pUZ88QcQh9friFs","level":1,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"no app in context","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":{"Exception":"OCP\\Lock\\LockedException","Message":"\"files/3f64760bdb34017831c4432f0ef3ab18\" is locked, existing lock on file: none","Code":0,"Trace":[{"file":"/opt/censored/nextcloud/lib/private/Files/Storage/Common.php","line":747,"function":"acquireLock","class":"OC\\Lock\\MemcacheLockingProvider","type":"->","args":["files/3f64760bdb34017831c4432f0ef3ab18",1]},{"file":"/opt/censored/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php","line":593,"function":"acquireLock","class":"OC\\Files\\Storage\\Common","type":"->","args":["files/test",1,{"__class__":"OC\\Lock\\MemcacheLockingProvider"}]},{"file":"/opt/censored/nextcloud/lib/private/Files/View.php","line":1947,"function":"acquireLock","class":"OC\\Files\\Storage\\Wrapper\\Wrapper","type":"->","args":["files/test",1,{"__class__":"OC\\Lock\\MemcacheLockingProvider"}]},{"file":"/opt/censored/nextcloud/lib/private/Files/View.php","line":2063,"function":"lockPath","class":"OC\\Files\\View","type":"->","args":["/test",1]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Node.php","line":388,"function":"lockFile","class":"OC\\Files\\View","type":"->","args":["/test/96088",1]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","line":153,"function":"acquireLock","class":"OCA\\DAV\\Connector\\Sabre\\Node","type":"->","args":[1]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1096,"function":"createFile","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->","args":["96088",null]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":525,"function":"createFile","class":"Sabre\\DAV\\Server","type":"->","args":["files/homedir/test/96088",null,null]},{"function":"httpPut","class":"Sabre\\DAV\\CorePlugin","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[[{"__class__":"Sabre\\DAV\\CorePlugin"},"httpPut"],[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":479,"function":"emit","class":"Sabre\\Event\\EventEmitter","type":"->","args":["method:PUT",[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Server.php","line":319,"function":"exec","class":"Sabre\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/remote.php","line":165,"args":["/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/opt/censored/nextcloud/lib/private/Lock/MemcacheLockingProvider.php","Line":78,"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}
{"reqId":"PwRb6pUZ88QcQh9friFs","level":0,"time":"2020-05-23T23:12:00+00:00","remoteAddr":"IP_CENSORED","user":"homedir","app":"webdav","method":"PUT","url":"/remote.php/dav/files/homedir/test/96088","message":{"Exception":"OCA\\DAV\\Connector\\Sabre\\Exception\\FileLocked","Message":"\"test\" is locked","Code":0,"Trace":[{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1096,"function":"createFile","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->","args":["96088",null]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":525,"function":"createFile","class":"Sabre\\DAV\\Server","type":"->","args":["files/homedi/test/96088",null,null]},{"function":"httpPut","class":"Sabre\\DAV\\CorePlugin","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[[{"__class__":"Sabre\\DAV\\CorePlugin"},"httpPut"],[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":479,"function":"emit","class":"Sabre\\Event\\EventEmitter","type":"->","args":["method:PUT",[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Server.php","line":319,"function":"exec","class":"Sabre\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/remote.php","line":165,"args":["/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","Line":168,"Previous":{"Exception":"OCP\\Lock\\LockedException","Message":"\"test\" is locked","Code":0,"Trace":[{"file":"/opt/censored/nextcloud/lib/private/Files/View.php","line":2063,"function":"lockPath","class":"OC\\Files\\View","type":"->","args":["/test",1]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Node.php","line":388,"function":"lockFile","class":"OC\\Files\\View","type":"->","args":["/test/96088",1]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","line":153,"function":"acquireLock","class":"OCA\\DAV\\Connector\\Sabre\\Node","type":"->","args":[1]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1096,"function":"createFile","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->","args":["96088",null]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":525,"function":"createFile","class":"Sabre\\DAV\\Server","type":"->","args":["files/homedir/test/96088",null,null]},{"function":"httpPut","class":"Sabre\\DAV\\CorePlugin","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[[{"__class__":"Sabre\\DAV\\CorePlugin"},"httpPut"],[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":479,"function":"emit","class":"Sabre\\Event\\EventEmitter","type":"->","args":["method:PUT",[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Server.php","line":319,"function":"exec","class":"Sabre\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/remote.php","line":165,"args":["/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/opt/censored/nextcloud/lib/private/Files/View.php","Line":1952,"Previous":{"Exception":"OCP\\Lock\\LockedException","Message":"\"files/3f64760bdb34017831c4432f0ef3ab18\" is locked, existing lock on file: none","Code":0,"Trace":[{"file":"/opt/censored/nextcloud/lib/private/Files/Storage/Common.php","line":747,"function":"acquireLock","class":"OC\\Lock\\MemcacheLockingProvider","type":"->","args":["files/3f64760bdb34017831c4432f0ef3ab18",1]},{"file":"/opt/censored/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php","line":593,"function":"acquireLock","class":"OC\\Files\\Storage\\Common","type":"->","args":["files/test",1,{"__class__":"OC\\Lock\\MemcacheLockingProvider"}]},{"file":"/opt/censored/nextcloud/lib/private/Files/View.php","line":1947,"function":"acquireLock","class":"OC\\Files\\Storage\\Wrapper\\Wrapper","type":"->","args":["files/test",1,{"__class__":"OC\\Lock\\MemcacheLockingProvider"}]},{"file":"/opt/censored/nextcloud/lib/private/Files/View.php","line":2063,"function":"lockPath","class":"OC\\Files\\View","type":"->","args":["/test",1]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Node.php","line":388,"function":"lockFile","class":"OC\\Files\\View","type":"->","args":["/test/96088",1]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php","line":153,"function":"acquireLock","class":"OCA\\DAV\\Connector\\Sabre\\Node","type":"->","args":[1]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":1096,"function":"createFile","class":"OCA\\DAV\\Connector\\Sabre\\Directory","type":"->","args":["96088",null]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php","line":525,"function":"createFile","class":"Sabre\\DAV\\Server","type":"->","args":["files/homedir/test/96088",null,null]},{"function":"httpPut","class":"Sabre\\DAV\\CorePlugin","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php","line":105,"function":"call_user_func_array","args":[[{"__class__":"Sabre\\DAV\\CorePlugin"},"httpPut"],[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":479,"function":"emit","class":"Sabre\\Event\\EventEmitter","type":"->","args":["method:PUT",[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]]},{"file":"/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php","line":254,"function":"invokeMethod","class":"Sabre\\DAV\\Server","type":"->","args":[{"absoluteUrl":"https://example.com/remote.php/dav/files/homedir/test/96088","__class__":"Sabre\\HTTP\\Request"},{"__class__":"Sabre\\HTTP\\Response"}]},{"file":"/opt/censored/nextcloud/apps/dav/lib/Server.php","line":319,"function":"exec","class":"Sabre\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php","line":35,"function":"exec","class":"OCA\\DAV\\Server","type":"->","args":[]},{"file":"/opt/censored/nextcloud/remote.php","line":165,"args":["/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php"],"function":"require_once"}],"File":"/opt/censored/nextcloud/lib/private/Lock/MemcacheLockingProvider.php","Line":78}},"CustomMessage":"--"},"userAgent":"Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)","version":"18.0.4.2"}

Here is a pretty-print of the exception log line:

{
 "app": "no app in context",
 "level": 1,
 "message": {
 "Code": 0,
 "CustomMessage": "--",
 "Exception": "OCP\\Lock\\LockedException",
 "File": "/opt/censored/nextcloud/lib/private/Lock/MemcacheLockingProvider.php",
 "Line": 78,
 "Message": "\"files/3f64760bdb34017831c4432f0ef3ab18\" is locked, existing lock on file: none",
 "Trace": [
 {
 "args": [
 "files/3f64760bdb34017831c4432f0ef3ab18",
 1
 ],
 "class": "OC\\Lock\\MemcacheLockingProvider",
 "file": "/opt/censored/nextcloud/lib/private/Files/Storage/Common.php",
 "function": "acquireLock",
 "line": 747,
 "type": "->"
 },
 {
 "args": [
 "files/test",
 1,
 {
 "__class__": "OC\\Lock\\MemcacheLockingProvider"
 }
 ],
 "class": "OC\\Files\\Storage\\Common",
 "file": "/opt/censored/nextcloud/lib/private/Files/Storage/Wrapper/Wrapper.php",
 "function": "acquireLock",
 "line": 593,
 "type": "->"
 },
 {
 "args": [
 "files/test",
 1,
 {
 "__class__": "OC\\Lock\\MemcacheLockingProvider"
 }
 ],
 "class": "OC\\Files\\Storage\\Wrapper\\Wrapper",
 "file": "/opt/censored/nextcloud/lib/private/Files/View.php",
 "function": "acquireLock",
 "line": 1947,
 "type": "->"
 },
 {
 "args": [
 "/test",
 1
 ],
 "class": "OC\\Files\\View",
 "file": "/opt/censored/nextcloud/lib/private/Files/View.php",
 "function": "lockPath",
 "line": 2063,
 "type": "->"
 },
 {
 "args": [
 "/test/96088",
 1
 ],
 "class": "OC\\Files\\View",
 "file": "/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Node.php",
 "function": "lockFile",
 "line": 388,
 "type": "->"
 },
 {
 "args": [
 1
 ],
 "class": "OCA\\DAV\\Connector\\Sabre\\Node",
 "file": "/opt/censored/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php",
 "function": "acquireLock",
 "line": 153,
 "type": "->"
 },
 {
 "args": [
 "96088",
 null
 ],
 "class": "OCA\\DAV\\Connector\\Sabre\\Directory",
 "file": "/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php",
 "function": "createFile",
 "line": 1096,
 "type": "->"
 },
 {
 "args": [
 "files/homedir/test/96088",
 null,
 null
 ],
 "class": "Sabre\\DAV\\Server",
 "file": "/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php",
 "function": "createFile",
 "line": 525,
 "type": "->"
 },
 {
 "args": [
 {
 "__class__": "Sabre\\HTTP\\Request",
 "absoluteUrl": "https://example.com/remote.php/dav/files/homedir/test/96088"
 },
 {
 "__class__": "Sabre\\HTTP\\Response"
 }
 ],
 "class": "Sabre\\DAV\\CorePlugin",
 "function": "httpPut",
 "type": "->"
 },
 {
 "args": [
 [
 {
 "__class__": "Sabre\\DAV\\CorePlugin"
 },
 "httpPut"
 ],
 [
 {
 "__class__": "Sabre\\HTTP\\Request",
 "absoluteUrl": "https://example.com/remote.php/dav/files/homedir/test/96088"
 },
 {
 "__class__": "Sabre\\HTTP\\Response"
 }
 ]
 ],
 "file": "/opt/censored/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php",
 "function": "call_user_func_array",
 "line": 105
 },
 {
 "args": [
 "method:PUT",
 [
 {
 "__class__": "Sabre\\HTTP\\Request",
 "absoluteUrl": "https://example.com/remote.php/dav/files/homedir/test/96088"
 },
 {
 "__class__": "Sabre\\HTTP\\Response"
 }
 ]
 ],
 "class": "Sabre\\Event\\EventEmitter",
 "file": "/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php",
 "function": "emit",
 "line": 479,
 "type": "->"
 },
 {
 "args": [
 {
 "__class__": "Sabre\\HTTP\\Request",
 "absoluteUrl": "https://example.com/remote.php/dav/files/homedir/test/96088"
 },
 {
 "__class__": "Sabre\\HTTP\\Response"
 }
 ],
 "class": "Sabre\\DAV\\Server",
 "file": "/opt/censored/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php",
 "function": "invokeMethod",
 "line": 254,
 "type": "->"
 },
 {
 "args": [],
 "class": "Sabre\\DAV\\Server",
 "file": "/opt/censored/nextcloud/apps/dav/lib/Server.php",
 "function": "exec",
 "line": 319,
 "type": "->"
 },
 {
 "args": [],
 "class": "OCA\\DAV\\Server",
 "file": "/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php",
 "function": "exec",
 "line": 35,
 "type": "->"
 },
 {
 "args": [
 "/opt/censored/nextcloud/apps/dav/appinfo/v2/remote.php"
 ],
 "file": "/opt/censored/nextcloud/remote.php",
 "function": "require_once",
 "line": 165
 }
 ]
 },
 "method": "PUT",
 "remoteAddr": "IP_CENSORED",
 "reqId": "PwRb6pUZ88QcQh9friFs",
 "time": "2020-05-23T23:12:00+00:00",
 "url": "/remote.php/dav/files/homedir/test/96088",
 "user": "homedir",
 "userAgent": "Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)",
 "version": "18.0.4.2"
}

The is locked part of the message is not true, as the value is actually 0 (it was incremented from -1). Also, the message existing lock on file: none generated at

server/lib/private/Lock/MemcacheLockingProvider.php

Line 143 in 5e35594

return 'none';

doesn't mean that the lock is not found, but that the value happens to be 0 at the time of printing.

Server configuration

Operating system:
Debian GNU/Linux 10 (buster)

Web server:
apache2 2.4.38-3+deb10u3

Database:
mariadb 1:10.3.22-0+deb10u1

PHP version:
7.3.14-1~deb10u1

Nextcloud version:
18.0.4

Updated from an older Nextcloud/ownCloud or fresh install:
Updated from NC 17

Where did you install Nextcloud from:
nextcloud.com tarball

Signing status:

Signing status

No errors have been found.

List of activated apps:

App list

Enabled:
 - accessibility: 1.4.0
 - activity: 2.11.0
 - bruteforcesettings: 1.6.0
 - cloud_federation_api: 1.1.0
 - comments: 1.8.0
 - dav: 1.14.0
 - federatedfilesharing: 1.8.0
 - files: 1.13.1
 - files_pdfviewer: 1.7.0
 - files_rightclick: 0.15.2
 - files_sharing: 1.10.1
 - files_trashbin: 1.8.0
 - files_versions: 1.11.0
 - files_videoplayer: 1.7.0
 - impersonate: 1.5.1
 - logreader: 2.3.0
 - lookup_server_connector: 1.6.0
 - nextcloud_announcements: 1.7.0
 - notifications: 2.6.0
 - oauth2: 1.6.0
 - password_policy: 1.8.0
 - photos: 1.0.0
 - privacy: 1.2.0
 - provisioning_api: 1.8.0
 - recommendations: 0.6.0
 - serverinfo: 1.8.0
 - settings: 1.0.0
 - sharebymail: 1.8.0
 - support: 1.1.0
 - survey_client: 1.6.0
 - systemtags: 1.8.0
 - text: 2.0.0
 - theming: 1.9.0
 - twofactor_backupcodes: 1.7.0
 - updatenotification: 1.8.0
 - user_ldap: 1.8.0
 - viewer: 1.2.0
 - workflowengine: 2.0.0
Disabled:
 - admin_audit
 - encryption
 - federation
 - files_external
 - firstrunwizard

Nextcloud configuration:

Config report

{
 "system": {
 "instanceid": "***REMOVED SENSITIVE VALUE***",
 "passwordsalt": "***REMOVED SENSITIVE VALUE***",
 "secret": "***REMOVED SENSITIVE VALUE***",
 "trusted_domains": [
 "***REMOVED SENSITIVE VALUE***"
 ],
 "datadirectory": "***REMOVED SENSITIVE VALUE***",
 "dbtype": "mysql",
 "version": "18.0.4.2",
 "overwrite.cli.url": "https:\/\/***REMOVED SENSITIVE VALUE***",
 "dbname": "***REMOVED SENSITIVE VALUE***",
 "dbhost": "***REMOVED SENSITIVE VALUE***",
 "dbport": "",
 "dbtableprefix": "oc_",
 "mysql.utf8mb4": true,
 "dbuser": "***REMOVED SENSITIVE VALUE***",
 "dbpassword": "***REMOVED SENSITIVE VALUE***",
 "installed": true,
 "ldapIgnoreNamingRules": false,
 "ldapProviderFactory": "OCA\\User_LDAP\\LDAPProviderFactory",
 "maintenance": false,
 "memcache.local": "\\OC\\Memcache\\APCu",
 "memcache.distributed": "\\OC\\Memcache\\Redis",
 "memcache.locking": "\\OC\\Memcache\\Redis",
 "redis": {
 "host": "***REMOVED SENSITIVE VALUE***",
 "port": 0,
 "dbindex": 0,
 "timeout": 1.5
 },
 "lost_password_link": "disabled",
 "loglevel": 2,
 "mail_from_address": "***REMOVED SENSITIVE VALUE***",
 "mail_smtpmode": "smtp",
 "mail_sendmailmode": "smtp",
 "mail_domain": "***REMOVED SENSITIVE VALUE***",
 "mail_smtphost": "***REMOVED SENSITIVE VALUE***",
 "updater.secret": "***REMOVED SENSITIVE VALUE***",
 "theme": ""
 }
}

Are you using external storage, if yes which one: Local ZFS storage

Are you using encryption: No

Are you using an external user-backend, if yes which one: OpenLDAP

LDAP configuration (delete this part if not used)

LDAP config

+-------------------------------+-------------------------------------------------------------+
| Configuration | s01 |
+-------------------------------+-------------------------------------------------------------+
| hasMemberOfFilterSupport | |
| homeFolderNamingRule | |
| lastJpegPhotoLookup | 0 |
| ldapAgentName | cn=nextcloud,***REMOVED SENSITIVE VALUE*** |
| ldapAgentPassword | *** |
| ldapAttributesForGroupSearch | |
| ldapAttributesForUserSearch | |
| ldapBackupHost | |
| ldapBackupPort | |
| ldapBase | ***REMOVED SENSITIVE VALUE*** |
| ldapBaseGroups | ou=groups,***REMOVED SENSITIVE VALUE*** |
| ldapBaseUsers | ou=people,***REMOVED SENSITIVE VALUE*** |
| ldapCacheTTL | 600 |
| ldapConfigurationActive | 1 |
| ldapDefaultPPolicyDN | |
| ldapDynamicGroupMemberURL | |
| ldapEmailAttribute | mail |
| ldapExperiencedAdmin | 1 |
| ldapExpertUUIDGroupAttr | |
| ldapExpertUUIDUserAttr | |
| ldapExpertUsernameAttr | |
| ldapExtStorageHomeAttribute | |
| ldapGidNumber | gidNumber |
| ldapGroupDisplayName | cn |
| ldapGroupFilter | (&(objectClass=posixGroup)(|***REMOVED SENSITIVE VALUE***) |
| ldapGroupFilterGroups | |
| ldapGroupFilterMode | 0 |
| ldapGroupFilterObjectclass | |
| ldapGroupMemberAssocAttr | memberUid |
| ldapHost | ldaps://ldap.***REMOVED SENSITIVE VALUE*** |
| ldapIgnoreNamingRules | |
| ldapLoginFilter | (&(|(objectclass=inetOrgPerson))(uid=%uid)) |
| ldapLoginFilterAttributes | |
| ldapLoginFilterEmail | 0 |
| ldapLoginFilterMode | 0 |
| ldapLoginFilterUsername | 1 |
| ldapNestedGroups | 0 |
| ldapOverrideMainServer | |
| ldapPagingSize | 500 |
| ldapPort | 636 |
| ldapQuotaAttribute | |
| ldapQuotaDefault | |
| ldapTLS | 0 |
| ldapUserAvatarRule | default |
| ldapUserDisplayName | cn |
| ldapUserDisplayName2 | |
| ldapUserFilter | (|(objectclass=inetOrgPerson)) |
| ldapUserFilterGroups | |
| ldapUserFilterMode | 0 |
| ldapUserFilterObjectclass | inetOrgPerson |
| ldapUuidGroupAttribute | auto |
| ldapUuidUserAttribute | auto |
| turnOffCertCheck | 0 |
| turnOnPasswordChange | 0 |
| useMemberOfToDetectMembership | 1 |
+-------------------------------+-------------------------------------------------------------+

Client configuration

Operating system:
Ubuntu 18.04.4 LTS

Desktop client:
Nextcloud version 2.6.4git

Logs

Web server error log

Web server error log

*snip* - jvsalo [23/May/2020:23:59:46 +0300] "PUT /remote.php/dav/files/***REMOVED SENSITIVE VALUE***/test/83518 HTTP/1.1" 423 894 "-" "Mozilla/5.0 (Linux) mirall/2.6.4git (Nextcloud)"