search

nextcloud / server

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

OCA\DAV\Connector\Sabre\Exception\FileLocked - Redis race condition #9001

Closed asengineeringsupport closed 1 year ago

asengineeringsupport commented 6 years ago

Steps to reproduce

  1. Install and configure Redis
  2. Upload a bigger file for longer than 1 hour.

Expected behaviour

When the upload finishes (monitoring the last seconds) the file should appear on filesystem and in webinterface.

Actual behaviour

The last Bytes are transmitting and then appears the "locked" message in Webbrower. The message OCA\DAV\Connector\Sabre\Exception\FileLocked will be logged in Adminpage. It happens when somebody uses a not so fast Internetconnection and is uploading for longer than one hour (f.e. 3GB, over 5 MBit/s, over 70-80 minutes), but somebody who is able to upload 4.5 GB in 12 minutes has success.

Server configuration

Operating system: Ubuntu 16.04.4 LTS

Web server: apache2 (2.4.18-2ubuntu3.5)

Database:

PHP version: php7.0 7.0.28-0ubuntu0.16.04.1 [1.290 B]

Nextcloud version: 12.0.3, 12.0.6 (actually), 13.0.0

Updated from an older Nextcloud/ownCloud or fresh install: First 12.0.3 than updated over Adminpage.

Where did you install Nextcloud from: Ubuntu repository

Signing status:

Signing status ``` Fatal webdav OCA\DAV\Connector\Sabre\Exception\FileLocked: "xxxx_GmbH/to_xxx_xxx/Autocad 2010.nrg" is locked0./var/www/html/nextcloud/apps/dav/lib/Connector/Sabre/Directory.php - line 151: OCA\DAV\Connector\Sabre\File->put(Resource id #20) 1./var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 1096: OCA\DAV\Connector\Sabre\Directory->createFile('Autocad 2010.nr...', Resource id #20) 2./var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/CorePlugin.php - line 525: Sabre\DAV\Server->createFile('xxxx_GmbH/to_xx...', Resource id #20, NULL) 3.[internal function] Sabre\DAV\CorePlugin->httpPut(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response)) 4./var/www/html/nextcloud/3rdparty/sabre/event/lib/EventEmitterTrait.php - line 105: call_user_func_array(Array, Array) 5./var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 479: Sabre\Event\EventEmitter->emit('method PUT', Array) 6./var/www/html/nextcloud/3rdparty/sabre/dav/lib/DAV/Server.php - line 254: Sabre\DAV\Server->invokeMethod(Object(Sabre\HTTP\Request), Object(Sabre\HTTP\Response)) 7./var/www/html/nextcloud/apps/dav/appinfo/v1/webdav.php - line 76: Sabre\DAV\Server->exec() 8./var/www/html/nextcloud/remote.php - line 164: require_once('/var/www/html/n...') 9.{main} ```

List of activated apps:

App list ``` Enabled: - activity: 2.5.2 - admin_audit: 1.2.0 - bruteforcesettings: 1.0.3 - checksum: 0.3.5 - comments: 1.2.0 - dav: 1.3.1 - federatedfilesharing: 1.2.0 - federation: 1.2.0 - files: 1.7.2 - files_accesscontrol: 1.2.5 - 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 - groupfolders: 1.2.0 - 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 - quota_warning: 1.1.1 - 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: - encryption - files_external - user_external ```

Nextcloud configuration:

Config report ``` 'xxxxxxxxxxxx', 'passwordsalt' => 'xxxxxxxxxxxxxxx', 'secret' => 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx', 'trusted_domains' => array ( 0 => '192.168.10.33', 1 => 'cloud.xxxxxx.de', ), 'datadirectory' => '/store/nextcloud-data', 'overwrite.cli.url' => 'http://192.168.10.33/nextcloud', 'dbtype' => 'mysql', 'version' => '12.0.6.1', 'dbname' => 'nextcloud', 'dbhost' => 'localhost', 'dbport' => '', 'dbtableprefix' => 'oc_', 'dbuser' => 'xxxxxxxxxxx', 'dbpassword' => 'xxxxxxxxxxx', 'installed' => true, 'filelocking.enabled' => true, 'memcache.distributed' => '\\OC\\Memcache\\Redis', 'memcache.local' => '\\OC\\Memcache\\Redis', 'memcache.locking' => '\\OC\\Memcache\\Redis', 'redis' => array ( 'host' => 'localhost', 'port' => 6379, ), 'mail_from_address' => 'xxxxxxx', 'mail_smtpmode' => 'smtp', 'mail_smtpauthtype' => 'LOGIN', 'mail_domain' => xxxxxxxxxxx.de', 'mail_smtphost' => xxxxxxxxxx.xxx.local', 'mail_smtpport' => '25', 'updater.release.channel' => 'stable', 'maintenance' => false, 'ldapIgnoreNamingRules' => false, 'ldapProviderFactory' => '\\OCA\\User_LDAP\\LDAPProviderFactory', 'updater.secret' => 'xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx' 'theme' => '', 'loglevel' => 2, ); ```

Are you using external storage, if yes which one: Yes, SMB.

Are you using encryption: No internal/build-in. Only encrypted filesystem on Ubuntu-erver himself and Bitlocker on Fileserver.

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

Client configuration

Browser: Internet Explorer 11, Firefox 59.0.2

Operating system: Windows 7 Professional x64

Logs

Web server error log

Web server error log ``` [Mon Mar 26 06:25:02.314662 2018] [mpm_prefork:notice] [pid 21244] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Mon Mar 26 06:25:02.314757 2018] [core:notice] [pid 21244] AH00094: Command line: '/usr/sbin/apache2' [Mon Mar 26 14:01:03.162471 2018] [mpm_prefork:notice] [pid 21244] AH00171: Graceful restart requested, doing restart AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 127.0.1.1. Set the 'ServerName' directive globally to suppress this message [Mon Mar 26 14:01:03.218000 2018] [mpm_prefork:notice] [pid 21244] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Mon Mar 26 14:01:03.218012 2018] [core:notice] [pid 21244] AH00094: Command line: '/usr/sbin/apache2' [Mon Mar 26 21:25:11.241890 2018] [mpm_prefork:notice] [pid 21244] AH00169: caught SIGTERM, shutting down [Mon Mar 26 21:25:12.308033 2018] [mpm_prefork:notice] [pid 46408] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Mon Mar 26 21:25:12.308074 2018] [core:notice] [pid 46408] AH00094: Command line: '/usr/sbin/apache2' [Mon Mar 26 21:25:53.944791 2018] [mpm_prefork:notice] [pid 46408] AH00169: caught SIGTERM, shutting down [Mon Mar 26 21:26:27.243619 2018] [mpm_prefork:notice] [pid 1409] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Mon Mar 26 21:26:27.245690 2018] [core:notice] [pid 1409] AH00094: Command line: '/usr/sbin/apache2' [Mon Mar 26 21:33:40.697760 2018] [mpm_prefork:notice] [pid 1409] AH00169: caught SIGTERM, shutting down [Mon Mar 26 21:33:41.764078 2018] [mpm_prefork:notice] [pid 2270] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Mon Mar 26 21:33:41.764121 2018] [core:notice] [pid 2270] AH00094: Command line: '/usr/sbin/apache2' [Mon Mar 26 23:00:18.538636 2018] [mpm_prefork:notice] [pid 2270] AH00169: caught SIGTERM, shutting down [Mon Mar 26 23:00:19.857040 2018] [mpm_prefork:notice] [pid 2815] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Mon Mar 26 23:00:19.857088 2018] [core:notice] [pid 2815] AH00094: Command line: '/usr/sbin/apache2' [Tue Mar 27 02:01:03.232558 2018] [mpm_prefork:notice] [pid 2815] AH00171: Graceful restart requested, doing restart AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 127.0.1.1. Set the 'ServerName' directive globally to suppress this message [Tue Mar 27 02:01:03.297159 2018] [mpm_prefork:notice] [pid 2815] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Tue Mar 27 02:01:03.297171 2018] [core:notice] [pid 2815] AH00094: Command line: '/usr/sbin/apache2' [Tue Mar 27 06:25:02.552259 2018] [mpm_prefork:notice] [pid 2815] AH00171: Graceful restart requested, doing restart AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 127.0.1.1. Set the 'ServerName' directive globally to suppress this message [Tue Mar 27 06:25:02.590111 2018] [mpm_prefork:notice] [pid 2815] AH00163: Apache/2.4.18 (Ubuntu) OpenSSL/1.0.2g configured -- resuming normal operations [Tue Mar 27 06:25:02.590120 2018] [core:notice] [pid 2815] AH00094: Command line: '/usr/sbin/apache2' [Tue Mar 27 06:25:02.827004 2018] [mpm_prefork:notice] [pid 2815] AH00171: Graceful restart requested, doing restart AH00558: apache2: Could not reliably determine the server's fully qualified domain name, using 127.0.1.1. Set the 'ServerName' directive globally to suppress this message ```

Nextcloud log (data/nextcloud.log)

Nextcloud log ``` Don't know where to fing the nextcloud.log. /var/www/html/nextcloud/data/nextcloud.log is empty. ```
BurtGummer commented 6 years ago

I have the same problem with 2 servers on Debian 9.

arduino43 commented 6 years ago

Exact same problem here as well.

ZoeED commented 6 years ago

I have had the same problem as well. We have remote offices uploading over 5mbps lines and after several attempts to upload 1/2GB files we had to give up.

We have stopped using NextCloud and will have to wait until this is fixed.

Proton23 commented 6 years ago

Same here. I can synchronise folders with a file > 3GB without a problem, but if I try to sync a folder which contains 2 files of that size it takes more than hour with my connection and than I get the exact behaviour as described above. max_execution_time set to 10800 but without any changes.

leog23 commented 6 years ago

Same problem. Large files over a slow link cause file locking - the same upload over a fast network will successfully upload.

I would love a fix for this.

krocheck commented 6 years ago

We have started experiencing this more than in the past ... I can't prove correlation to the upgrade from 12 to 13, but that's what it feels like.

BurtGummer commented 6 years ago

Hello,

one more example. As described here

https://docs.nextcloud.com/server/12/user_manual/files/access_webdav.html#accessing-files-using-curl

i use curl to upload a 4,4GB file. The first from a Hetzner root-server with 100MB/s connection:

root@Server ~ # time curl -u MY-USER:aaaaa-bbbbb-ccccc-ddddd-eeeee -T KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso https://example.org/cloud/remote.php/dav/files/MY-USER/nichtDownload/upload/

real    2m16,990s
user    0m6,608s
sys     0m4,644s
root@Server ~ # ls -alh KNO*
-rw-r--r-- 1 root root 4,4G Apr  3 13:48 KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso
root@Server ~ #

The second with a 2MB/s upload cable-connection: 

root@nas:~$ time curl -u MY-USER:aaaaa-bbbbb-ccccc-ddddd-eeeee -T KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso https://example.org/cloud/remote.php/dav/files/MY-USER/nichtDownload/upload/
<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>OCA\DAV\Connector\Sabre\Exception\FileLocked</s:exception>
  <s:message>"nichtDownload/upload/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso" is locked</s:message>
</d:error>

real    298m56,539s
user    1m44,292s
sys     1m11,464s
root@nas:~$ ls -alh KNO*
-rw-rw-rw- 1 root root 4,4G Apr  3 14:18 KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso
root@nas:~$

The complete error from nextcloud.log:

{"reqId":"o31GrPOYQkX8ApRievH2","level":3,"time":"2018-04-12T10:51:50+00:00","remoteAddr":"89.xxx.xxx.xxx","user":"MY-USER","app":"no app in context","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/MY-USER\/nichtDownload\/upload\/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso","message":"Exception: {\"Exception\":\"OCP\\\\Lock\\\\LockedException\",\"Message\":\"\\\"files\\\/6875118f810d0d4a272d4e6b662cba2e\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Common.php(773): OC\\\\Lock\\\\MemcacheLockingProvider->changeLock('files\\\/6875118f8...', 2)\\n#1 \\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Common->changeLock('files\\\/nichtDown...', 2, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#2 \\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/nichtDown...', 2, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#3 \\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/View.php(1967): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/nichtDown...', 2, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#4 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Node.php(356): OC\\\\Files\\\\View->changeLock('\\\/nichtDownload\\\/...', 2)\\n#5 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(196): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Node->changeLock(2)\\n#6 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1130): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #9)\\n#7 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->updateFile('files\\\/MY-USER\\\/ni...', Resource id #9, NULL)\\n#8 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#10 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#11 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#12 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Server.php(283): Sabre\\\\DAV\\\\Server->exec()\\n#13 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(35): OCA\\\\DAV\\\\Server->exec()\\n#14 \\\/var\\\/www\\\/html\\\/nextcloud\\\/remote.php(164): require_once('\\\/var\\\/www\\\/html\\\/n...')\\n#15 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Lock\\\/MemcacheLockingProvider.php\",\"Line\":122}","userAgent":"curl\/7.52.1","version":"13.0.1.1"}
{"reqId":"o31GrPOYQkX8ApRievH2","level":4,"time":"2018-04-12T10:51:50+00:00","remoteAddr":"89.xxx.xxx.xxx","user":"MY-USER","app":"webdav","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/MY-USER\/nichtDownload\/upload\/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso","message":"Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Message\":\"\\\"nichtDownload\\\/upload\\\/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1130): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #9)\\n#1 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(513): Sabre\\\\DAV\\\\Server->updateFile('files\\\/MY-USER\\\/ni...', Resource id #9, NULL)\\n#2 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#3 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#4 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#5 \\\/var\\\/www\\\/html\\\/nextcloud\\\/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\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Server.php(283): Sabre\\\\DAV\\\\Server->exec()\\n#7 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(35): OCA\\\\DAV\\\\Server->exec()\\n#8 \\\/var\\\/www\\\/html\\\/nextcloud\\\/remote.php(164): require_once('\\\/var\\\/www\\\/html\\\/n...')\\n#9 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":201}","userAgent":"curl\/7.52.1","version":"13.0.1.1"}

My config:

root@Server /var/www/html/nextcloud # sudo -u www-data php occ config:list system
{
    "system": {
        "instanceid": "***REMOVED SENSITIVE VALUE***",
        "passwordsalt": "***REMOVED SENSITIVE VALUE***",
        "trusted_domains": [
            "oc.example.org",
            "example.org"
        ],
        "datadirectory": "***REMOVED SENSITIVE VALUE***",
        "overwrite.cli.url": "https:\/\/example.org\/cloud",
        "dbtype": "mysql",
        "version": "13.0.1.1",
        "installed": true,
        "theme": "",
        "maintenance": false,
        "secret": "***REMOVED SENSITIVE VALUE***",
        "mail_from_address": "***REMOVED SENSITIVE VALUE***",
        "mail_smtpmode": "php",
        "mail_domain": "***REMOVED SENSITIVE VALUE***",
        "loglevel": 2,
        "trashbin_retention_obligation": "auto",
        "updatechecker": true,
        "htaccess.RewriteBase": "\/cloud",
        "dbname": "***REMOVED SENSITIVE VALUE***",
        "dbhost": "***REMOVED SENSITIVE VALUE***",
        "dbuser": "***REMOVED SENSITIVE VALUE***",
        "filelocking.debug": true,
        "dbpassword": "***REMOVED SENSITIVE VALUE***",
        "updater.release.channel": "stable",
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 6379,
            "timeout": 0
        }
    }
}
root@Server /var/www/html/nextcloud #

If any informations missing, please ask.

I hope, someone can help. This problem is so frustrating.

leog23 commented 6 years ago

It is very frustrating...

asengineeringsupport commented 6 years ago

Same issue after manual 13.0.1 upgrade.

BurtGummer commented 6 years ago

Because of this problem I had to install vsftpd today :-( (and I thought with nextcloud I'd never have to do that again). And because this report is almost a month old, here is another example, this time with "'loglevel' => 0,":

root@server /var/www/html/nextcloud/data/MY-USER/files/nichtDownload/upload # ls -alh
insgesamt 4,4G
drwxr-x---  3 www-data www-data 4,0K Apr 24 06:14 .
drwxr-xr-x 17 www-data www-data 4,0K Mär 28 11:38 ..
-rw-r--r--  1 www-data www-data 4,4G Apr 24 11:12 KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso.ocTransferId1472831112.part
root@server /var/www/html/nextcloud/data/MY-USER/files/nichtDownload/upload #

some seconds later:

root@nas:~$ time curl -u MY-USER:aaaaa-bbbbb-cccccc-dddd -T KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso https://example.org/cloud/remote.php/dav/files/MY-USER/nichtDownload/upload/
<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>OCA\DAV\Connector\Sabre\Exception\FileLocked</s:exception>
  <s:message>"nichtDownload/upload/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso" is locked</s:message>
</d:error>

real    299m30,041s
user    1m44,700s
sys     1m8,352s
root@nas:~$

And the nextcloud.log:

{"reqId":"eBRCIZL7yZJstOPj8Qxn","level":1,"time":"2018-04-24T09:13:04+00:00","remoteAddr":"xx.xxx.xxx.140","user":"MY-USER","app":"locking","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/MY-USER\/nichtDownload\/upload\/KN
OPPIX_V7.7.1DVD-2016-10-22-DE.iso","message":"release shared lock on \"files\/nichtDownload\/upload\" on storage \"home::MY-USER\"","userAgent":"curl\/7.52.1","version":"13.0.1.1"}
{"reqId":"eBRCIZL7yZJstOPj8Qxn","level":1,"time":"2018-04-24T09:13:04+00:00","remoteAddr":"xx.xxx.xxx.140","user":"MY-USER","app":"locking","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/MY-USER\/nichtDownload\/upload\/KN
OPPIX_V7.7.1DVD-2016-10-22-DE.iso","message":"change lock on \"files\/nichtDownload\/upload\/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso\" to exclusive on storage \"home::MY-USER\"","userAgent":"curl\/7.52.1","version":"13.0.1.1"}
{"reqId":"eBRCIZL7yZJstOPj8Qxn","level":3,"time":"2018-04-24T09:13:04+00:00","remoteAddr":"xx.xxx.xxx.140","user":"MY-USER","app":"no app in context","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/MY-USER\/nichtDownload\/
upload\/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso","message":"Exception: {\"Exception\":\"OCP\\\\Lock\\\\LockedException\",\"Message\":\"\\\"files\\\/6875118f810d0d4a272d4e6b662cba2e\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/var\
\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Common.php(773): OC\\\\Lock\\\\MemcacheLockingProvider->changeLock('files\\\/6875118f8...', 2)\\n#1 \\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/F
iles\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Common->changeLock('files\\\/nichtDown...', 2, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#2 \\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\
\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/nichtDown...', 2, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#3 \\\/var\\\/www\\\/html\\\/nextcloud\\\
/lib\\\/private\\\/Files\\\/View.php(1967): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/nichtDown...', 2, Object(OC\\\\Lock\\\\MemcacheLockingProvider))\\n#4 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\
/dav\\\/lib\\\/Connector\\\/Sabre\\\/Node.php(356): OC\\\\Files\\\\View->changeLock('\\\/nichtDownload\\\/...', 2)\\n#5 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(196): OCA\\\\DA
V\\\\Connector\\\\Sabre\\\\Node->changeLock(2)\\n#6 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(151): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #9)\\n#7 \\\/v
ar\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1096): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('KNOPPIX_V7.7.1D...', Resource id #9)\\n#8 \\\/var\\\/www\\\/html\\\/nextcl
oud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(525): Sabre\\\\DAV\\\\Server->createFile('files\\\/MY-USER\\\/ni...', Resource id #9, NULL)\\n#9 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sab
re\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#10 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#11 \\\/var\\\/www\\\
/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#12 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/S
erver.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#13 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Server.php(283): Sabre\\\\DAV\\\\Serve
r->exec()\\n#14 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(35): OCA\\\\DAV\\\\Server->exec()\\n#15 \\\/var\\\/www\\\/html\\\/nextcloud\\\/remote.php(164): require_once('\\\/var\\\/www\\\/h
tml\\\/n...')\\n#16 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/nextcloud\\\/lib\\\/private\\\/Lock\\\/MemcacheLockingProvider.php\",\"Line\":122}","userAgent":"curl\/7.52.1","version":"13.0.1.1"}
{"reqId":"eBRCIZL7yZJstOPj8Qxn","level":4,"time":"2018-04-24T09:13:04+00:00","remoteAddr":"xx.xxx.xxx.140","user":"MY-USER","app":"webdav","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/MY-USER\/nichtDownload\/upload\/KNO
PPIX_V7.7.1DVD-2016-10-22-DE.iso","message":"Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Message\":\"\\\"nichtDownload\\\/upload\\\/KNOPPIX_V7.7.1DVD-2016-10-22-DE.iso\\\" is lock
ed\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(151): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #9)\\n#1 \\\/var\\\/www\\\/html\\\/
nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1096): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('KNOPPIX_V7.7.1D...', Resource id #9)\\n#2 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sa
bre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(525): Sabre\\\\DAV\\\\Server->createFile('files\\\/MY-USER\\\/ni...', Resource id #9, NULL)\\n#3 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request
), Object(Sabre\\\\HTTP\\\\Response))\\n#4 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#5 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3
rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#6 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\
\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#7 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Server.php(283): Sabre\\\\DAV\\\\Server->exec()\\n#8 \\\/var\\\
/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(35): OCA\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/html\\\/nextcloud\\\/remote.php(164): require_once('\\\/var\\\/www\\\/html\\\/n...')\\n#10 {main}\
",\"File\":\"\\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":201}","userAgent":"curl\/7.52.1","version":"13.0.1.1"}
arduino43 commented 6 years ago

I've tried 12-13 and all the same as above.

mnajamudinridha commented 6 years ago

me too :D

BurtGummer commented 6 years ago

I remove this options from my config:

  'memcache.locking' => '\\OC\\Memcache\\Redis',
  'redis' =>
  array (
    'host' => 'localhost',
    'port' => 6379,
    'timeout' => 0.0,
  ),

upload a file again and it is the same problem. So redis should not be the cause.

Are there any ideas I could still test?

jonesints commented 6 years ago

Is this a duplicate of #8239 ? there seems to be quite a few affected by this just searching on google. best workarounds imply disabling file locking altogether.

BurtGummer commented 6 years ago

'filelocking.enabled' => false,

is not a solution.

zetric commented 6 years ago

Issue still existing in 13.0.2.

'filelocking.enabled' => false, is not a solution.

:+1:

arduino43 commented 6 years ago

For me, the problem also occurs during large file uploads.

Uploading +40GB virtual disk files always fails, despite a 40-60Mbps throughput. This worked fine in v12.

BurtGummer commented 6 years ago

Sorry ... @MorrisJobke any idea how to solv this problem?

zetric commented 6 years ago

Some additional infos from my side.

For testing, I set 'filelocking.enabled' to false and copied a whole folder to the remote location (I use the german "Magentacloud"). This lead to other errors: image

So I wanted to verify that the issue is not situated at the storage provider. I set up an Ubuntu VM in Azure and mounted my target WebDav directory directly as file system via davfs (mount -t davfs ...).

Then I copied (cp -rv) many files within many folders to the remote location and back (I used the nextcloud source folder :wink: ) -> worked well, I achieved about 5-10 files/second; no errors I also tried it with some larger files and an 1.8 GB ubuntu ISO image. -> copied with about 7 MByte/s; no errors.

So for me it seems to be an issue in the "Sabre" library itself. And disabeling file locking is (for me) also not working.

If I can help out with testing, just let me know.

EDIT: Same in 13.0.3. A colleague in my company told me that he made the same experience in another use case (not nextcloud). There the cause was situated in the frequency the files were pushed to the remote. The client pushed the files to fast for the server. This may be also the cause here, as larger files that take more time to transmit were no problem here while high amount of small files lead to the above error messages.

vpecinka commented 6 years ago

Same problem, came with 13.0.4, swift primary storage, Redis used for filelocking and memory cache as well.

BurtGummer commented 6 years ago

Yes, the problem still exists (have the same version). I have the impression that a lot of new stuff is being developed in nextcloud, but the known bugs are not being fixed.

MorrisJobke commented 6 years ago

@BurtGummer @vpecinka Does it happen reliably for you or only from time to time?

MorrisJobke commented 6 years ago

cc @icewind1991

MorrisJobke commented 6 years ago

And if so: could you enable the locking debug log in the config.php? See config.sample.php for the description.

BurtGummer commented 6 years ago

Hey @MorrisJobke thank you very much for your response.

Yes, the problem happens reliably every time, the upload connection is slow and the file is big. In https://github.com/nextcloud/server/issues/9001#issuecomment-380775689 i had

'filelocking.debug' => true,

filelocking.debug was enabled all the time, I forgot to disable this option.

BurtGummer commented 6 years ago

@zetric https://github.com/nextcloud/server/issues/9001#issuecomment-395954722

This may be also the cause here, as larger files that take more time to transmit were no problem here while high amount of small files lead to the above error messages.

no, thats wrong. please read my tests, i upload one file with 4,4GB and the error occurs. Until now, I have some smaller files with a bigger total size not uploaded, but i'll try it.

arduino43 commented 6 years ago

This does happen reliably for me as well.

Not sure if this is too vague to be useful, but I've found anything below 2mbit/s for files 2.5GB or more will fail 100% of the time.

asengineeringsupport commented 6 years ago

I've tested it from several different locations with different upload speeds, from 2 till 100 MBit/s. Internet connections with better performance are able to upload bigger files. The file size does not matter, more the consequence.

I can upload 18GB big files, when its fast enough (internal network). In my test it seems that all uploads fail, when upload time is longer than one hour. The upload goes till 99 percent and at the 100 percent mark the file locking issue appears.

MorrisJobke commented 6 years ago

I can upload 18GB big files, when its fast enough (internal network). In my test it seems that all uploads fail, when upload time is longer than one hour. The upload goes till 99 percent and at the 100 percent mark the file locking issue appears.

Then it all makes a bit more sense: The locks time out after 1 hour. :/

@icewind1991 We need a way to refresh them during the upload. Anything we can do here?

MorrisJobke commented 6 years ago

With #10116 we try to fix some cases where more locks are freed than we got. It's possible that it fixes the issue in here.

Schmuuu commented 6 years ago

Hi,

I ran into such an issue yesterday. After another user was complaining about failing uploads (and then switched over to dropbox again :( ) I tried uploading files myself. When the upload actually finished and the complete file was uploaded, renaming the file failed, because it was locked.

ll files/public-test/
-rw-r-----  1 http http 8.2G Jul 12 14:18 'Showreel(1).mkv.ocTransferId1432038356.part'
-rw-r-----  1 http http 452K Jul 11 16:38  Nextcloud.mp4
-rw-r-----  1 http http 4.4G Jul 12 11:36  Showreel.mkv

As a result, the file doesn't appear in the Nextcloud web gui. Can you give me an advice please, how I can rename or delete the file safely? I mean, I obviously can rename and delete via SSH, I know, but I don't want to have an inconsistency between file system and NC database. That's why I'm asking.

Here are the two log entries:

{"reqId":"cZdLk6rld1ccITPuLoqC","level":3,"time":"2018-07-12T14:18:01+02:00","remoteAddr":"IP-ADDRESS","user":"--","app":"no app in context","method":"PUT","url":"\/public.php\/webdav\/Showreel.mkv","message":"Exception: {\"Exception\":\"OCP\\\\Lock\\\\LockedException\",\"Message\":\"\\\"files\\\/519524f8b4ef81acfa28f0bb037fab08\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Common.php(773): OC\\\\Lock\\\\DBLockingProvider->changeLock('files\\\/519524f8b...', 2)\\n#1 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Common->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#2 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#3 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#4 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#5 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#6 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/Storage\\\/Wrapper\\\/Wrapper.php(614): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#7 \\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Files\\\/View.php(1965): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Wrapper->changeLock('files\\\/public-te...', 2, Object(OC\\\\Lock\\\\DBLockingProvider))\\n#8 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Node.php(356): OC\\\\Files\\\\View->changeLock('\\\/Showreel.mkv', 2)\\n#9 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(196): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Node->changeLock(2)\\n#10 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(156): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #15)\\n#11 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1096): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('Showreel.mkv', Resource id #15)\\n#12 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(529): Sabre\\\\DAV\\\\Server->createFile('Showreel.mkv', Resource id #15, NULL)\\n#13 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#14 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#15 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#16 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#17 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/publicwebdav.php(107): Sabre\\\\DAV\\\\Server->exec()\\n#18 \\\/var\\\/www\\\/nextcloud\\\/public.php(79): require_once('\\\/var\\\/www\\\/nextcl...')\\n#19 {main}\",\"File\":\"\\\/var\\\/www\\\/nextcloud\\\/lib\\\/private\\\/Lock\\\/DBLockingProvider.php\",\"Line\":234}","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:61.0) Gecko\/20100101 Firefox\/61.0","version":"13.0.4.0"}
{"reqId":"cZdLk6rld1ccITPuLoqC","level":4,"time":"2018-07-12T14:18:01+02:00","remoteAddr":"IP-ADDRESS","user":"--","app":"webdav","method":"PUT","url":"\/public.php\/webdav\/Showreel.mkv","message":"Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Message\":\"\\\"public-test\\\/Showreel.mkv\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(156): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #15)\\n#1 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1096): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('Showreel.mkv', Resource id #15)\\n#2 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(529): Sabre\\\\DAV\\\\Server->createFile('Showreel.mkv', Resource id #15, NULL)\\n#3 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#4 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#5 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#6 \\\/var\\\/www\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#7 \\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v1\\\/publicwebdav.php(107): Sabre\\\\DAV\\\\Server->exec()\\n#8 \\\/var\\\/www\\\/nextcloud\\\/public.php(79): require_once('\\\/var\\\/www\\\/nextcl...')\\n#9 {main}\",\"File\":\"\\\/var\\\/www\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":201}","userAgent":"Mozilla\/5.0 (Windows NT 10.0; Win64; x64; rv:61.0) Gecko\/20100101 Firefox\/61.0","version":"13.0.4.0"}

I applied the above mentioned fix 6 days ago already. So it doesn't work for me.

I'm running: NC 13.0.4 Redis 4.0.10 Locking settings from the config:

        "filelocking.enabled": true,
        "memcache.local": "\\OC\\Memcache\\APCu",
        "memcache.locking": "\\OC\\Memcache\\Redis",
        "redis": {
            "host": "***REMOVED SENSITIVE VALUE***",
            "port": 0,
            "timeout": 0,
            "dbindex": 0,
            "password": "***REMOVED SENSITIVE VALUE***"
        },

Help is highly appreciated. More and more users stop using the NC server, due to locking issues since NC 13.0.4 and fall back to dropbox stating, that dropbox simply works -.-'

linucksrox commented 6 years ago

I have had success using the method I described in the other Github issue that is basically a duplicate of this issue: https://github.com/nextcloud/server/issues/8239#issuecomment-398105379 Just remove the locked files from Redis and you should be able to proceed with renaming the file.

MorrisJobke commented 6 years ago

Can you give me an advice please, how I can rename or delete the file safely? I mean, I obviously can rename and delete via SSH, I know, but I don't want to have an inconsistency between file system and NC database. That's why I'm asking.

Run occ files:scan for that user/path and it should be fine again. Then at worst you need to wait 1 hour until the lock expired.

BurtGummer commented 6 years ago

First test with 13.0.5 didn't work:

root@nas:~$ time curl -u USER:xxxxx-xxxxx-xxxxx-xxxxx-xxxxx -T debian-8.7.1-amd64-DVD-2.iso https://example.org/cloud/remote.php/dav/files/USER/nichtDownload/upload/
<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>OCA\DAV\Connector\Sabre\Exception\FileLocked</s:exception>
  <s:message>"nichtDownload/upload/debian-8.7.1-amd64-DVD-2.iso" is locked</s:message>
</d:error>

real    286m30,730s
user    1m27,972s
sys     0m58,888s
root@nas:~$

And again:

root@sa /var/www/html/nextcloud # ls -alh /var/www/html/nextcloud/data/USER/files/nichtDownload/upload/debian-8.7.1-amd64-DVD-2.iso.ocTransferId1727695603.part
-rw-r----- 1 www-data www-data 4,1G Jul 24 15:00 /var/www/html/nextcloud/data/USER/files/nichtDownload/upload/debian-8.7.1-amd64-DVD-2.iso.ocTransferId1727695603.part
root@sa /var/www/html/nextcloud #

The file was automatically deleted after uploading. Interesting is the time from the error in the nextcloud.log:

{"reqId":"czeTb0L4KvpxOI4wzxf3","level":4,"time":"2018-07-24T13:05:42+00:00","remoteAddr":"89.xxx.xxx.xxx","user":"USER","app":"webdav","method":"PUT","url":"\/cloud\/remote.php\/dav\/files\/USER\/nichtDownload\/upload\/debian-8.7.1-amd64-DVD-2.iso","message":"Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Message\":\"\\\"nichtDownload\\\/upload\\\/debian-8.7.1-amd64-DVD-2.iso\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(156): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #12)\\n#1 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1096): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('debian-8.7.1-am...', Resource id #12)\\n#2 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(529): Sabre\\\\DAV\\\\Server->createFile('files\\\/USER\\\/ni...', Resource id #12, NULL)\\n#3 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#4 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#5 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#6 \\\/var\\\/www\\\/html\\\/nextcloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#7 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Server.php(287): Sabre\\\\DAV\\\\Server->exec()\\n#8 \\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(35): OCA\\\\DAV\\\\Server->exec()\\n#9 \\\/var\\\/www\\\/html\\\/nextcloud\\\/remote.php(164): require_once('\\\/var\\\/www\\\/html\\\/n...')\\n#10 {main}\",\"File\":\"\\\/var\\\/www\\\/html\\\/nextcloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":212}","userAgent":"curl\/7.52.1","version":"13.0.5.2"}

because the upload was locked after 15:00, but the error is from 13:05? (date/time from the server is correct)

samtygier commented 6 years ago

I can still trigger this in 13.0.5.2 (snap version). I am testing with several thousand small files.

{"reqId":"0Dj7eVp4enqgfKoPA2AN","level":2,"time":"2018-08-11T20:40:46+00:00","remoteAddr":"192.168.1.1","user":"--","app":"core","method":"GET","url":"\/ind
ex.php\/204","message":"Login failed: 'Bart' (Remote IP: '192.168.1.1')","userAgent":"Mozilla\/5.0 (Android) ownCloud-android\/3.2.1","version":"13.0.5.2"}
{"reqId":"MnZxvfywAhFcKnL8OU1Y","level":4,"time":"2018-08-11T20:46:03+00:00","remoteAddr":"192.168.1.1","user":"x61","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/x61\/files_test\/mt\/eckztljp","message":"Exception: {\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Message\":\"\\\"files_test\\\" is locked\",\"Code\":0,\"Trace\":\"#0 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1096): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('eckztljp', Resource id #21)\\n#1 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(529): Sabre\\\\DAV\\\\Server->createFile('files\\\/x61\\\/files...', Resource id #21, NULL)\\n#2 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#3 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#4 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#5 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/apps\\\/dav\\\/lib\\\/Server.php(287): Sabre\\\\DAV\\\\Server->exec()\\n#7 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(35): OCA\\\\DAV\\\\Server->exec()\\n#8 \\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/remote.php(164): require_once('\\\/snap\\\/nextcloud...')\\n#9 {main}\",\"File\":\"\\\/snap\\\/nextcloud\\\/8267\\\/htdocs\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php\",\"Line\":168}","userAgent":"Mozilla\/5.0 (Linux) mirall\/2.3.3 (Nextcloud)","version":"13.0.5.2"}

and at the client end

||mt/eckztljp|INST_NEW|Up|1534019725||11790||3|Error transferring https://xxxx.ddns.net/remote.php/dav/files/x61/files_test/mt/eckztljp - server replied: Locked ("files_test" is locked)|423|0|0|||INST_NONE|

In this case the files did make it onto the server, but I am worried that there is a relation to nextcloud/desktop/issues/506

sooslaca commented 6 years ago

+1 here

With slow upload same happens. When upload is quick no issues.

My log contains:

Error | no app in context | OCP\Lock\LockedException: "files/334bb07d03dc1abaafe783db82c18398" is locked, existing lock on file: none
-- | -- | --

Right after that:

Fatal | webdav | OCA\DAV\Connector\Sabre\Exception\FileLocked: "<<filename_and_url_here>>" is locked
-- | -- | --
bobblkabb commented 6 years ago

Same here (13.0.6 on Ubuntu 18.04). 2.7GB over 1Mbit connection was locked after 6-7 hours. Probably just before the end.

BurtGummer commented 6 years ago

I uploaded a 1,7GB file in the browser to a Nextcloud link that was enabled for editing (I did this in another browser where I was logged in to Nextcloud). So I didn't have to enter a user/password to upload the file. Nevertheless, the upload broke off again when the upload was finished. So it should have nothing to do with whether you are logged in as a user or not.

BurtGummer commented 6 years ago

My first test with 14.0.2 - so far successful!

I have upload 2 files, one with 1,4G and one with 1,7G, time was longer as one hour with 2mb/s cable connection. I try more uploads now.

Interesting: there is no more .part-file in the upload directory from nextcloud?

Proton23 commented 6 years ago

Thank you for this Information, I'm very happy to hear that. I will test it within the next days and give feedback on this.

BurtGummer commented 6 years ago

Noo, glad too early:

root@nas:~$ time curl -u USER:xxxxxxxxxxxx -T debian-8.7.1-amd64-DVD-2.iso https://example.org/cloud/remote.php/dav/files/USER/nichtDownload/TestUploadFett/
<?xml version="1.0" encoding="utf-8"?>
<d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns">
  <s:exception>OCA\DAV\Connector\Sabre\Exception\FileLocked</s:exception>
  <s:message>"nichtDownload/TestUploadFett/debian-8.7.1-amd64-DVD-2.iso" is locked</s:message>
</d:error>

real    289m53,312s
user    1m37,040s
sys     1m3,880s
root@nas:~$

sorry... :-(

BurtGummer commented 6 years ago

I'd like to give a (known) developer from Nextcloud root access to my private root server running Nextcloud in the current version 14, where the problem has existed for years. Maybe this way a developer can find out where the problem is and find a solution? a spark of hope...

tfvlrue commented 6 years ago

I can confirm that this is also happening on my Nextcloud 14 instance. It seems that if the upload over WebDAV takes longer than an hour, the transferred file disappears from the server and it logs two errors like:

Fatal webdav OCA\DAV\Connector\Sabre\Exception\FileLocked: "xxx" is locked Error no app in context OCP\Lock\LockedException: "files/9f6f03d7935642c2bad854c2d45a890d" is locked

I am using APCu for caching and have not explicitly configured memcache.locking 'memcache.local' => '\OC\Memcache\APCu',

Has anyone found a workaround for this? Let me know if there is any more information I can provide. This is 100% reproducible for me. Thanks.

ErAzOr2k commented 5 years ago

issue still persists in Nextcloud 15.0.2 :/

ErAzOr2k commented 5 years ago

this issue is not redis related. It's file locking in general.

I setup a new nextcloud installation without redis and file lock enabled. Issue is still the same --> upload longer than 1 hour leads to 0kb file.

With file lock disabled everything is fine.

BurtGummer commented 5 years ago

This bug is a endless story... :-( should have the label "High"...

icewind1991 commented 5 years ago

Please see if https://github.com/nextcloud/server/pull/13739 fixes the issue for you

arduino43 commented 5 years ago

Still an issue. This should be marked as high - we stopped using NextCloud in production because of this issue.

MorrisJobke commented 5 years ago

Still an issue. This should be marked as high - we stopped using NextCloud in production because of this issue.

Did you tested the PR from @icewind1991? Did you also waited long enough so that the locks are not there from before the patch was applied. The locks have a TTL of 1 hour. So either clear them (with the risk of running into a concurrent request) or wait for at least 1 hour.

BurtGummer commented 5 years ago

I have to wait until the next version 15.0.3 because I don't know how to apply the patch. I can hardly wait.