Interrupted upload results in lock on unrelated folders

[davivel]

Steps to reproduce

With curl:

1. curl -v -X PUT -u [user]:[pass] -H "OC-Chunked:1" "http://[server]/remote.php/webdav/Photos/file.mp4-chunking-7860-2-0" -F myfile=@"[localPath]\file.mp4"
2. Interrupt abruptly the transference - (unplug the Ethernet cable, turn off the WiFi adapter...)
3. Wait for curl aborts the connection
4. Enable again the network access
5. curl -v -u [user]:[pass] -X PROPFIND -H "Content-Type: text/xml" -d "<?xml version='1.0' encoding='UTF-8'?><D:propfind xmlns:D='DAV:'><D:prop><D:resourcetype/><D:getlastmodified/><size xmlns='http://owncloud.org/ns'/><D:creationdate/><id xmlns='http://owncloud.org/ns'/><D:getcontentlength/><D:displayname/><D:getetag/><permissions xmlns='http://owncloud.org/ns'/><D:getcontenttype/></D:prop></D:propfind>" http://[server]/remote.php/webdav/
6. curl -v -u [user]:[pass] -X PROPFIND -H "Content-Type: text/xml" -d "<?xml version='1.0' encoding='UTF-8'?><D:propfind xmlns:D='DAV:'><D:prop><D:resourcetype/><D:getlastmodified/><size xmlns='http://owncloud.org/ns'/><D:creationdate/><id xmlns='http://owncloud.org/ns'/><D:getcontentlength/><D:displayname/><D:getetag/><permissions xmlns='http://owncloud.org/ns'/><D:getcontenttype/></D:prop></D:propfind>" http://[server]/remote.php/webdav/Documents

   Expected behaviour

Both (5) and (6) should return the list of files in folders "/" (5) and "/Documents/" (6). Please, notice that the file in (1) was uploading to "/Photos/"

Actual behaviour

Both (5) and (6) finish with error 500 and next response: <d:error xmlns:d="DAV:" xmlns:s="http://sabredav.org/ns"> <s:exception>OCP\Files\LockNotAcquiredException</s:exception> <s:message>Could not obtain lock type 1 on "/opt/owncloud/data/admin/cache/file.mp4-chunking-7860-0.y9A4yfbYqmIyat4w.part".</s:message> </d:error>

Server configuration

Operating system: Ubuntu 14.04

Web server: Apache/2.4.7

Database: MySQL

PHP version: 5.5.9

ownCloud version: (see ownCloud admin page) 8.1.0.7 (nightly generated 30/06/2015)

Updated from an older ownCloud or fresh install: Fresh

List of activated apps: Activity 2.0.0 Deleted files 0.6.2 File Locking First Run Wizard 1.1 Mail Template Editor 0.1 PDF Viewer 0.7 Pictures 0.6.0 Provisioning API 0.2 Share Files 0.6.1 Text Editor 0.4 Updater 0.5 Versions 1.0.5 Video Viewer 0.1.3

No matter if transactional file locking is enabled or not.

The bug does not happen with File Locking app disabled.

The content of config/config.php: Unknown

Are you using external storage, if yes which one: local/smb/sftp/... Not sure

Are you using encryption: yes/no No

Are you using an external user-backend, if yes which one: LDAP/ActiveDirectory/Webdav/... No

Logs

Web server error log

ownCloud log (data/owncloud.log)

Exception: {"Message":"Could not obtain lock type 1 on \"\/opt\/owncloud\/data\/admin\/cache\/file.mp4-chunking-7860-0.y9A4yfbYqmIyat4w.part\".","Code":0,"Trace":"#0 \/opt\/owncloud\/apps\/files_locking\/lib\/lockingwrapper.php(45): OCA\\Files_Locking\\Lock->addLock(1, Resource id #30)\n
#1 \/opt\/owncloud\/apps\/files_locking\/lib\/lockingwrapper.php(172): OCA\\Files_Locking\\LockingWrapper->getLock('cache\/file.mp4-...', 1, Resource id #30)\n
#2 \/opt\/owncloud\/lib\/private\/files\/storage\/wrapper\/encryption.php(609): OCA\\Files_Locking\\LockingWrapper->fopen('cache\/file.mp4-...', 'r')\n
#3 \/opt\/owncloud\/lib\/private\/files\/storage\/wrapper\/encryption.php(629): OC\\Files\\Storage\\Wrapper\\Encryption->getHeader('cache\/file.mp4-...')\n
#4 \/opt\/owncloud\/lib\/private\/files\/storage\/wrapper\/encryption.php(215): OC\\Files\\Storage\\Wrapper\\Encryption->getEncryptionModule('cache\/file.mp4-...')\n
#5 [internal function]: OC\\Files\\Storage\\Wrapper\\Encryption->unlink('cache\/file.mp4-...')\n
#6 \/opt\/owncloud\/apps\/files_trashbin\/lib\/storage.php(116): call_user_func_array(Array, Array)\n
#7 \/opt\/owncloud\/apps\/files_trashbin\/lib\/storage.php(89): OCA\\Files_Trashbin\\Storage->doDelete('cache\/file.mp4-...', 'unlink')\n
#8 \/opt\/owncloud\/lib\/private\/files\/view.php(1006): OCA\\Files_Trashbin\\Storage->unlink('cache\/file.mp4-...')\n
#9 \/opt\/owncloud\/lib\/private\/files\/view.php(598): OC\\Files\\View->basicOperation('unlink', '\/file.mp4-chunk...', Array)\n
#10 \/opt\/owncloud\/lib\/private\/cache\/file.php(187): OC\\Files\\View->unlink('\/file.mp4-chunk...')\n
#11 \/opt\/owncloud\/lib\/base.php(734): OC\\Cache\\File->gc()\n
#12 [internal function]: OC::{closure}(Object(OC\\User\\User), 'Password')\n
#13 \/opt\/owncloud\/lib\/private\/hooks\/emittertrait.php(99): call_user_func_array(Object(Closure), Array)\n
#14 \/opt\/owncloud\/lib\/private\/hooks\/publicemitter.php(32): OC\\Hooks\\BasicEmitter->emit('\\OC\\User', 'postLogin', Array)\n
#15 \/opt\/owncloud\/lib\/private\/user\/session.php(223): OC\\Hooks\\PublicEmitter->emit('\\OC\\User', 'postLogin', Array)\n
#16 \/opt\/owncloud\/lib\/private\/user.php(241): OC\\User\\Session->login('admin', 'Password')\n
#17 \/opt\/owncloud\/lib\/private\/connector\/sabre\/auth.php(71): OC_User::login('admin', 'Password')\n
#18 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Backend\/AbstractBasic.php(74): OC\\Connector\\Sabre\\Auth->validateUserPass('admin', 'Password')\n
#19 \/opt\/owncloud\/lib\/private\/connector\/sabre\/auth.php(135): Sabre\\DAV\\Auth\\Backend\\AbstractBasic->authenticate(Object(OC\\Connector\\Sabre\\Server), 'ownCloud')\n
#20 \/opt\/owncloud\/lib\/private\/connector\/sabre\/auth.php(115): OC\\Connector\\Sabre\\Auth->auth(Object(OC\\Connector\\Sabre\\Server), 'ownCloud')\n
#21 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Auth\/Plugin.php(118): OC\\Connector\\Sabre\\Auth->authenticate(Object(OC\\Connector\\Sabre\\Server), 'ownCloud')\n
#22 [internal function]: Sabre\\DAV\\Auth\\Plugin->beforeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n
#23 \/opt\/owncloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n
#24 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(456): Sabre\\Event\\EventEmitter->emit('beforeMethod', Array)\n
#25 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n
#26 \/opt\/owncloud\/apps\/files\/appinfo\/remote.php(83): Sabre\\DAV\\Server->exec()\n
#27 \/opt\/owncloud\/remote.php(84): require_once('\/opt\/owncloud\/a...')\n
#28 {main}","File":"\/opt\/owncloud\/apps\/files_locking\/lib\/lock.php","Line":257}

EXTRA: relevant for mobile in cases of lost connectivity. Android client:

1. Upload a file bigger than 1MB (chunked mode) to "/Photos/"
2. Turn off the network access while the file is uploading (simulate lost conectivity)
3. The upload fails; tap on the notification bar to access the folder where the upload was in progress.
4. Turn on notification
5. Browse to root folder (is not refreshed)
6. Browse to "/Documents/" folder (not refreshed; if never browsed into before, appears as an empty folder, although it's not).

The client can't refresh anymore until the lock is released by the server (some minutes later).

cc: @DeepDiver1975 , @PVince81

[davivel]

From owncloud/core#17236.

[PVince81]

Thanks

[PVince81]

Do you mind checking if this also happens on the latest OC 7 and OC 8.0.x ?

[PVince81]

to confirm that this is not a regression.

[davivel]

I will.

[davivel]

8.0.5 beta is NOT failing.

[PVince81]

Thanks.

Hmm, there were still a few commits since: https://github.com/owncloud/files_locking/compare/master...stable8

But could also be due to changes in core code.

[PVince81]

Aha, so it's related to encryption ? Because a lot of encryption has changed in core.

Do you see the issue when encryption is disabled ?

[PVince81]

@schiesbn see item number 3 in the stack trace. I thought encryption wouldn't work on the cache folder ?

[davivel]

No, encryption appears in the admin panel as disabled.

[davivel]

I noticed a warning in the failing instance (8.1.0) about memcache not being enabled.

The instance not failing (8.0.5) has no warning.

[PVince81]

Ok. The reason why we see the encryption wrapper is because it's always there in 8.1 even when encryption is disabled, this is expected.

Now maybe the code path is slightly different as in 8.0.5 and makes it run into the locking situation.

Ideal would be that the locks are properly cleant up after abort.

[schiessle]

The encryption wrapper gets called for all files because you never know what future encryption modules want to encrypt. But the current encryption module will not touch the files: https://github.com/owncloud/core/blob/master/apps/encryption/lib/crypto/encryption.php#L341

[PVince81]

Okay, so I got told that:

• there is a stray lock on a sibling which isn't supposed to happen
• it was about chunk upload

If the file list cannot be shown then it's quite bad.

[PVince81]

I wonder if this is loosely related to the callback wrappers issue, just a wild guess: https://github.com/owncloud/core/pull/17256

I'll first try and reproduce this issue

[PVince81]

Re-read the report.

It is indeed very strange that step 5 and step 6 even bother about the cache folder. They shouldn't do anything with it.

[PVince81]

No need to wait for timeout: after unplugging the cable, you can kill curl and wait a bit, then replug.

I saw a chunk file in the "cache" folder.

[PVince81]

and while the chunk file was there, the locking error appears on PROPFIND. After one minute or so, the chunk file disappeared automatically, possibly cleant up by the PHP process. And the lock error disappeared too.

So now to find out why a simple PROPFIND has anything to do with the cache file.

[PVince81]

Aha, a stack trace in the log for the PROPFIND!

{"reqId":"0zrI6P5GaxRUg9fZ7Pnm","remoteAddr":"192.168.177.186","app":"webdav","message":"Exception: {\"Message\":\"Could not obtain lock type 1 on \\\"\\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/data\\\/root\\\/cache\\\/data1.dat-chunking-7860-0.EpCAd4qjbmvq7TBu.part\\\".\",\"Code\":0,\"Trace\":\"
#0 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps3\\\/files_locking\\\/lib\\\/lockingwrapper.php(45): OCA\\\\Files_Locking\\\\Lock->addLock(1, Resource id #296)\\n
#1 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps3\\\/files_locking\\\/lib\\\/lockingwrapper.php(172): OCA\\\\Files_Locking\\\\LockingWrapper->getLock('cache\\\/data1.dat...', 1, Resource id #296)\\n
#2 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/encryption.php(622): OCA\\\\Files_Locking\\\\LockingWrapper->fopen('cache\\\/data1.dat...', 'r')\\n
#3 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/encryption.php(642): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Encryption->getHeader('cache\\\/data1.dat...')\\n
#4 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/files\\\/storage\\\/wrapper\\\/encryption.php(218): OC\\\\Files\\\\Storage\\\\Wrapper\\\\Encryption->getEncryptionModule('cache\\\/data1.dat...')\\n
#5 [internal function]: OC\\\\Files\\\\Storage\\\\Wrapper\\\\Encryption->unlink('cache\\\/data1.dat...')\\n
#6 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files_trashbin\\\/lib\\\/storage.php(116): call_user_func_array(Array, Array)\\n
#7 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files_trashbin\\\/lib\\\/storage.php(89): OCA\\\\Files_Trashbin\\\\Storage->doDelete('cache\\\/data1.dat...', 'unlink')\\n
#8 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(1003): OCA\\\\Files_Trashbin\\\\Storage->unlink('cache\\\/data1.dat...')\\n
#9 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/files\\\/view.php(597): OC\\\\Files\\\\View->basicOperation('unlink', '\\\/data1.dat-chun...', Array)\\n
#10 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/cache\\\/file.php(182): OC\\\\Files\\\\View->unlink('\\\/data1.dat-chun...')\\n
#11 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/base.php(734): OC\\\\Cache\\\\File->gc()\\n
#12 [internal function]: OC::{closure}(Object(OC\\\\User\\\\User), 'admin')\\n
#13 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/hooks\\\/emittertrait.php(98): call_user_func_array(Object(Closure), Array)\\n
#14 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/hooks\\\/publicemitter.php(32): OC\\\\Hooks\\\\BasicEmitter->emit('\\\\\\\\OC\\\\\\\\User', 'postLogin', Array)\\n
#15 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/user\\\/session.php(223): OC\\\\Hooks\\\\PublicEmitter->emit('\\\\\\\\OC\\\\\\\\User', 'postLogin', Array)\\n
#16 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/user.php(242): OC\\\\User\\\\Session->login('root', 'admin')\\n
#17 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/auth.php(71): OC_User::login('root', 'admin')\\n
#18 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Backend\\\/AbstractBasic.php(74): OC\\\\Connector\\\\Sabre\\\\Auth->validateUserPass('root', 'admin')\\n
#19 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/auth.php(135): Sabre\\\\DAV\\\\Auth\\\\Backend\\\\AbstractBasic->authenticate(Object(OC\\\\Connector\\\\Sabre\\\\Server), 'ownCloud')\\n
#20 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/lib\\\/private\\\/connector\\\/sabre\\\/auth.php(115): OC\\\\Connector\\\\Sabre\\\\Auth->auth(Object(OC\\\\Connector\\\\Sabre\\\\Server), 'ownCloud')\\n
#21 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Auth\\\/Plugin.php(118): OC\\\\Connector\\\\Sabre\\\\Auth->authenticate(Object(OC\\\\Connector\\\\Sabre\\\\Server), 'ownCloud')\\n
#22 [internal function]: Sabre\\\\DAV\\\\Auth\\\\Plugin->beforeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n
#23 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n
#24 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(456): Sabre\\\\Event\\\\EventEmitter->emit('beforeMethod', Array)\\n
#25 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/3rdparty\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n
#26 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps\\\/files\\\/appinfo\\\/remote.php(83): Sabre\\\\DAV\\\\Server->exec()\\n
#27 \\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/remote.php(83): require_once('\\\/srv\\\/www\\\/htdocs...')\\n
#28 {main}\",\"File\":\"\\\/srv\\\/www\\\/htdocs\\\/owncloud\\\/apps3\\\/files_locking\\\/lib\\\/lock.php\",\"Line\":257}","level":4,"time":"2015-06-30T14:38:02+00:00","method":"PROPFIND","url":"\/owncloud\/remote.php\/webdav\/test"}

[PVince81]

Of course!

The login hook is triggered, and the login hook usually triggers cleanup of chunks. But since the chunk is still locked, it cannot clean it up yet...

I'll prepare a PR to ignore locked chunks...

[PVince81]

We ought to move this cleanup to a cron job in the future. https://github.com/owncloud/core/issues/14646

[PVince81]

Now I'm also wondering why is it trying to clear that chunk that early ? It's supposed to let them live a few hours or so.

[davivel]

I'll prepare a PR to ignore locked chunks...

:+1: