Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

423 Locked when upload a file after a disconnection #17254

Closed
javiergonzper opened this issue Jun 30, 2015 · 25 comments
Closed

423 Locked when upload a file after a disconnection #17254

javiergonzper opened this issue Jun 30, 2015 · 25 comments

Comments

@javiergonzper
Copy link

Server version:

    {"installed":true,"maintenance":false,"version":"8.1.0.7","versionstring":"8.1 RC1","edition":""}

Steps:
1- Upload a file with curl
curl -X PUT -v --progress-bar -u user:pass "http://SERVER/remote.php/webdav/file.MOV" -F myfile=@"/Users/Javi/file.MOV"
2- Remove the connection (disconnect ethernet cable) and wait untile time out of curl.
3- Connect again the computer
4- Upload the same file with curl

Current behavior:
Once the file finish the upload we receive a 423 response and the file not appear in the list of files:
< HTTP/1.1 423 Locked

Expected behavior:
File should be upload

It works fine with the Files_Locking App enable or disable. It does not work when the transactional File Locking is active.

Logs:

Exception: {"Message":"HTTP\/1.1 423 \"file.MOV\" is locked","Code":0,"Trace":"
#0 \/opt\/owncloud\/lib\/private\/connector\/sabre\/directory.php(111): OC\\Connector\\Sabre\\File->put(Resource id #28)\n
#1 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(1053): OC\\Connector\\Sabre\\Directory->createFile('file.MOV', Resource id #28)\n
#2 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/CorePlugin.php(513): Sabre\\DAV\\Server->createFile('file.MOV', Resource id #28, NULL)\n
#3 [internal function]: Sabre\\DAV\\CorePlugin->httpPut(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n
#4 \/opt\/owncloud\/3rdparty\/sabre\/event\/lib\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\n
#5 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(469): Sabre\\Event\\EventEmitter->emit('method:PUT', Array)\n
#6 \/opt\/owncloud\/3rdparty\/sabre\/dav\/lib\/DAV\/Server.php(254): Sabre\\DAV\\Server->invokeMethod(Object(Sabre\\HTTP\\Request), Object(Sabre\\HTTP\\Response))\n
#7 \/opt\/owncloud\/apps\/files\/appinfo\/remote.php(83): Sabre\\DAV\\Server->exec()\n
#8 \/opt\/owncloud\/remote.php(84): require_once('\/opt\/owncloud\/a...')\n#9 {main}","File":"\/opt\/owncloud\/lib\/private\/connector\/sabre\/file.php","Line":198}
@DeepDiver1975 DeepDiver1975 added this to the 8.1-current milestone Jun 30, 2015
@DeepDiver1975
Copy link
Member

same scenario as with owncloud-archive/files_locking#39

@DeepDiver1975
Copy link
Member

Is there a shutdown handler on php side missing? @icewind1991

@javiergonzper
Copy link
Author

Sorry @DeepDiver1975 @icewind1991
It works fine with the Files_Locking App enable or disable. It does not work when the transactional File Locking is active.

@DeepDiver1975
Copy link
Member

It works fine with the Files_Locking App enable or disable. It does not work when the transactional File Locking is active.

owncloud-archive/files_locking#39 is telling a different story - please keep in mind that encryption being enabled or disabled has an impact.

@javiergonzper
Copy link
Author

@DeepDiver1975 encryption is disabled. If you want I can check it with encryption enabled

@PVince81
Copy link
Contributor

It works fine with the Files_Locking App enable or disable. It does not work when the transactional File Locking is active.

Are you sure ? In the original post you said you disabled "Files_Locking" and it worked fine.
Now you are saying disabling Transactional locking to make it work.

The former would match owncloud-archive/files_locking#39

@rperezb
Copy link

rperezb commented Jun 30, 2015

@PVince81 sorry for the confusion.
Yes, this bug is related to the transactional_file locking, with it is enable it leads to this behavior.

We though that it could be related to the fact of having enable the files_locking, disable it, nothing changes, it still fails.

@PVince81
Copy link
Contributor

Thanks.

I cannot explain this issue.
Normally I'd expect Apache to keep the PHP request running even if the connection was closed.

Because there are shutdown handlers that automatically unlock files at the end of a request.

Now maybe that PHP request is also running into a timeout situation, in which case there is no wait to automatically unlock files, because the request is killed. No further code can be executed. The solution for this would be to have a TTL for locks: #16966

@PVince81
Copy link
Contributor

Hmm if the file list is not browseable then it's an additional issue. In general a lock shouldn't block that.

@PVince81
Copy link
Contributor

@javiergonzper if I understand well the folder is still browseable here, is that correct ? (in the other ticket it isn't)

@PVince81
Copy link
Contributor

@javiergonzper you're on Apache, right ? Do you use php-fpm ?

@PVince81
Copy link
Contributor

@icewind1991 and I did some tests on Apache and nginx + php-fpm and saw that even if the connection is lost, the PHP request continues running.

So for now the only explanation would be that the PHP request runs for so long that it reaches PHP timeout.

@PVince81
Copy link
Contributor

I cannot reproduce this issue.

I tried monitoring with redis-cli, type monitor.

When the transfer starts, I see:

1435680490.667382 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.670019 [0 127.0.0.1:57475] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.670089 [0 127.0.0.1:57475] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.670193 [0 127.0.0.1:57475] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.670254 [0 127.0.0.1:57475] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.670360 [0 127.0.0.1:57475] "UNWATCH"
1435680490.676345 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.676715 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.677713 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.677982 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.686812 [0 127.0.0.1:57475] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.686920 [0 127.0.0.1:57475] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.687067 [0 127.0.0.1:57475] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.687205 [0 127.0.0.1:57475] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.687353 [0 127.0.0.1:57475] "UNWATCH"
1435680490.695016 [0 127.0.0.1:57475] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.695143 [0 127.0.0.1:57475] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.695271 [0 127.0.0.1:57475] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.695430 [0 127.0.0.1:57475] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.695544 [0 127.0.0.1:57475] "UNWATCH"
1435680490.712253 [0 127.0.0.1:57475] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.712340 [0 127.0.0.1:57475] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.712422 [0 127.0.0.1:57475] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.712492 [0 127.0.0.1:57475] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680490.712560 [0 127.0.0.1:57475] "UNWATCH"
1435680490.712858 [0 127.0.0.1:57475] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.712926 [0 127.0.0.1:57475] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.712999 [0 127.0.0.1:57475] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.713061 [0 127.0.0.1:57475] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.713120 [0 127.0.0.1:57475] "UNWATCH"
1435680490.717830 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/570083c83ca8f9fffd22dd3da4e9d31c"
1435680490.718171 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680490.718476 [0 127.0.0.1:57475] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"

After I disconnect the VM's network, after a second or so I see:

1435680506.872874 [0 127.0.0.1:57471] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680506.872989 [0 127.0.0.1:57471] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680506.873107 [0 127.0.0.1:57471] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680506.873182 [0 127.0.0.1:57471] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680506.873246 [0 127.0.0.1:57471] "UNWATCH"
1435680506.873338 [0 127.0.0.1:57471] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680506.873456 [0 127.0.0.1:57471] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680506.873592 [0 127.0.0.1:57471] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680506.873652 [0 127.0.0.1:57471] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/28a23ef7d2b67cd904d21af0e32e9aad"
1435680506.873713 [0 127.0.0.1:57471] "UNWATCH"
1435680506.873807 [0 127.0.0.1:57471] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/570083c83ca8f9fffd22dd3da4e9d31c"
1435680506.873860 [0 127.0.0.1:57471] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/570083c83ca8f9fffd22dd3da4e9d31c"
1435680506.873938 [0 127.0.0.1:57471] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/570083c83ca8f9fffd22dd3da4e9d31c"
1435680506.873995 [0 127.0.0.1:57471] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/570083c83ca8f9fffd22dd3da4e9d31c"
1435680506.874051 [0 127.0.0.1:57471] "UNWATCH"
1435680517.521291 [0 127.0.0.1:57479] "INCR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680517.523871 [0 127.0.0.1:57479] "EXISTS" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680517.523959 [0 127.0.0.1:57479] "DECR" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680517.524045 [0 127.0.0.1:57479] "WATCH" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680517.524130 [0 127.0.0.1:57479] "GET" "cc729126482099a8571d51be5c15b233/lockfiles/2a2694688f159d7d04bd51bd0534851f"
1435680517.524204 [0 127.0.0.1:57479] "UNWATCH"

And if I restart the transfer, it works.

Could be a difference in setup/environment ?

I have this:

  • openSUSE Factory
  • apache2-2.4.12-7.1.x86_64 with mod_php
  • php5-5.6.9-1.1.x86_64

@icewind1991
Copy link
Contributor

According to the comments on https://secure.php.net/manual/en/function.register-shutdown-function.php the shutdown function should work correctly if we hit the max execution time

@ghost ghost modified the milestones: 8.1.1-next-maintenance, 8.1-current Jun 30, 2015
@ghost
Copy link

ghost commented Jun 30, 2015

Moving to 8.1.1, not enough information to stop RC

@ghost ghost closed this as completed Jun 30, 2015
@ghost ghost reopened this Jun 30, 2015
@javiergonzper
Copy link
Author

@PVince81 our enviroment is:
owncloud-8.1.0RC1.tar.bz2
ubuntu_lamp_redis:late
Server version: {"installed":true,"maintenance":false,"version":"8.1.0.7","versionstring":"8.1 RC1","edition":""}

If you want I can provide you an account and also an access by ssh

@PVince81
Copy link
Contributor

PVince81 commented Jul 1, 2015

Is it the old RC1 from two weeks ago ?

@icewind1991 and I tested on master which is more recent.

If you still see this issue in RC2 we'll need ssh credentials.

@javiergonzper
Copy link
Author

Ok, I will check it on RC2 👍

@javiergonzper
Copy link
Author

@PVince81 on RC2 it works... but I created this bug to simulate other bug that we have on the iOS App that still happening... funny.

@MorrisJobke MorrisJobke modified the milestones: 8.1-current, 8.1.1-next-maintenance Jul 2, 2015
@nasli
Copy link

nasli commented Jul 26, 2016

Happens again within 9.1.0.15
1.Upload a file inside a folder "/a" and while it is uploading network connection lost
2.Network connection back
3.Try to upload again same file
4.Try to delete the folder "/a"

Current behavior:
3 . It is not possible to upload the file, file error locked 423, Logs CURL:

< HTTP/1.1 423 Locked
< Date: Tue, 26 Jul 2016 17:00:41 GMT
< Server: Apache/2.4.7 (Ubuntu)
< X-Powered-By: PHP/5.5.9-1ubuntu4.13
...
<?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>"a/file.MOV" is locked</s:message>
</d:error>

4 . It is not possible to delete the folder

@PVince81
Copy link
Contributor

PVince81 commented Aug 8, 2016

Yes, if there is a disconnection it is likely that the PHP process got killed and could not clear the lock.
The file will auto-unlock after an hour when the TTL is reached.

This is a known issue. I hope we'll find a good solution one day...

@PVince81
Copy link
Contributor

PVince81 commented Aug 8, 2016

@rperezb why was this tagged as regression ? In which version did it work in the past ? (it might have worked in very old OC that had no locking)

@PVince81 PVince81 modified the milestones: 9.1.2, 9.1.1 Sep 21, 2016
@PVince81 PVince81 modified the milestones: 9.1.3, 9.1.2 Oct 20, 2016
@PVince81 PVince81 modified the milestones: 9.1.4, 9.1.3 Nov 30, 2016
@PVince81
Copy link
Contributor

PVince81 commented Dec 7, 2016

This PR might fix it #26775 as it will prevent the PHP request to be killed and let it do its cleanup.

@PVince81
Copy link
Contributor

PVince81 commented Feb 6, 2017

Please try again with 9.1.4 or 9.0.8 where the locks should be freed properly upon disconnection

@lock
Copy link

lock bot commented Aug 3, 2019

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@lock lock bot locked as resolved and limited conversation to collaborators Aug 3, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

8 participants