Core: 423 locked when retrying uploads with new endpoint

[davigonz]

As you already know, we are currently replacing the network library in the Android app and I just noticed a strange behaviour when retrying an upload.

Steps to reproduce

1. Upload a file with curl
   curl -X PUT -u user:password "url:port/remote.php/dav/files/user/video.mp4" -F myfile=@"./video.mp4" -v --progress-bar
2. Disconnect internet connection.
3. Wait for the curl timeout.
4. Reconnect internet.
5. Use the curl command in step 1 to upload the same file.

Current behaviour

423 locked error

<?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>"video.mp4" is locked</s:message>
</d:error>

Expected behaviour

The upload is properly performed and the file is created in server receiving 204 No Content code.

Server configuration

Web server: Apache 2.4.18

Database: MySQL

PHP version: php7.0.28

ownCloud version: 10.0.7 (stable)

Logs

ownCloud log (data/owncloud.log)

{"reqId":"dSk3WydM0XfTycCUycx7","level":4,"time":"2018-06-20T10:59:19+00:00","remoteAddr":"85.57.168.79","user":"admin","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/admin\/video.mp4","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 17252447 got 3191060\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\BadRequest\",\"Code\":0,\"Trace\":\"#0 \\\/opt\\\/owncloud\\\/lib\\\/public\\\/Events\\\/EventEmitterTrait.php(50): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->OCA\\\\DAV\\\\Connector\\\\Sabre\\\\{closure}()\\n#1 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(269): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->emittingCall(Object(Closure), Array, 'file', 'create')\\n#2 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(171): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #66)\\n#3 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1095): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('video.mp4', Resource id #66)\\n#4 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(525): Sabre\\\\DAV\\\\Server->createFile('files\\\/admin\\\/vid...', Resource id #66, NULL)\\n#5 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#7 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#8 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(263): Sabre\\\\DAV\\\\Server->exec()\\n#10 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#11 \\\/opt\\\/owncloud\\\/remote.php(165): require_once('\\\/opt\\\/owncloud\\\/a...')\\n#12 {main}\",\"File\":\"\\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":180,\"User\":\"admin\"}"}
{"reqId":"HQVdQLMVf4rO9dMDPY3p","level":2,"time":"2018-06-20T11:10:33+00:00","remoteAddr":"85.57.168.79","user":"admin","app":"dav","method":"DELETE","url":"\/remote.php\/webdav\/video.mp4","message":"Could not get node for path: \"video.mp4\" : File with name video.mp4 could not be located"}
{"reqId":"fK3LvWrIpvAJ83GlbEzd","level":2,"time":"2018-06-20T11:11:04+00:00","remoteAddr":"85.57.168.79","user":"admin","app":"dav","method":"DELETE","url":"\/remote.php\/webdav\/video.mp4","message":"Could not get node for path: \"video.mp4\" : File with name video.mp4 could not be located"}
{"reqId":"HTfrALeh25DulLfhGh27","level":4,"time":"2018-06-20T11:12:16+00:00","remoteAddr":"85.57.168.79","user":"admin","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/admin\/video.mp4","message":"Exception: {\"Message\":\"HTTP\\\/1.1 423 \\\"video.mp4\\\" is locked\",\"Exception\":\"OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Exception\\\\FileLocked\",\"Code\":0,\"Trace\":\"#0 \\\/opt\\\/owncloud\\\/lib\\\/public\\\/Events\\\/EventEmitterTrait.php(50): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->OCA\\\\DAV\\\\Connector\\\\Sabre\\\\{closure}()\\n#1 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(269): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->emittingCall(Object(Closure), Array, 'file', 'create')\\n#2 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(171): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #66)\\n#3 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1095): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('video.mp4', Resource id #66)\\n#4 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(525): Sabre\\\\DAV\\\\Server->createFile('files\\\/admin\\\/vid...', Resource id #66, NULL)\\n#5 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#7 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#8 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(263): Sabre\\\\DAV\\\\Server->exec()\\n#10 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#11 \\\/opt\\\/owncloud\\\/remote.php(165): require_once('\\\/opt\\\/owncloud\\\/a...')\\n#12 {main}\",\"File\":\"\\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":205,\"User\":\"admin\"}"}
{"reqId":"e1h8lkdlhtKkm4klyEe3","level":4,"time":"2018-06-20T11:16:13+00:00","remoteAddr":"85.57.168.79","user":"admin","app":"webdav","method":"PUT","url":"\/remote.php\/dav\/files\/admin\/video.mp4","message":"Exception: {\"Message\":\"HTTP\\\/1.1 400 expected filesize 57231427 got 15852171\",\"Exception\":\"Sabre\\\\DAV\\\\Exception\\\\BadRequest\",\"Code\":0,\"Trace\":\"#0 \\\/opt\\\/owncloud\\\/lib\\\/public\\\/Events\\\/EventEmitterTrait.php(50): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->OCA\\\\DAV\\\\Connector\\\\Sabre\\\\{closure}()\\n#1 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php(269): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->emittingCall(Object(Closure), Array, 'file', 'create')\\n#2 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/Directory.php(171): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\File->put(Resource id #66)\\n#3 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(1095): OCA\\\\DAV\\\\Connector\\\\Sabre\\\\Directory->createFile('video.mp4', Resource id #66)\\n#4 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/CorePlugin.php(525): Sabre\\\\DAV\\\\Server->createFile('files\\\/admin\\\/vid...', Resource id #66, NULL)\\n#5 [internal function]: Sabre\\\\DAV\\\\CorePlugin->httpPut(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#6 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/event\\\/lib\\\/EventEmitterTrait.php(105): call_user_func_array(Array, Array)\\n#7 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(479): Sabre\\\\Event\\\\EventEmitter->emit('method:PUT', Array)\\n#8 \\\/opt\\\/owncloud\\\/lib\\\/composer\\\/sabre\\\/dav\\\/lib\\\/DAV\\\/Server.php(254): Sabre\\\\DAV\\\\Server->invokeMethod(Object(Sabre\\\\HTTP\\\\Request), Object(Sabre\\\\HTTP\\\\Response))\\n#9 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Server.php(263): Sabre\\\\DAV\\\\Server->exec()\\n#10 \\\/opt\\\/owncloud\\\/apps\\\/dav\\\/appinfo\\\/v2\\\/remote.php(31): OCA\\\\DAV\\\\Server->exec()\\n#11 \\\/opt\\\/owncloud\\\/remote.php(165): require_once('\\\/opt\\\/owncloud\\\/a...')\\n#12 {main}\",\"File\":\"\\\/opt\\\/owncloud\\\/apps\\\/dav\\\/lib\\\/Connector\\\/Sabre\\\/File.php\",\"Line\":180,\"User\":\"admin\"}"}

Related issues (old endpoint)

https://github.com/owncloud/core/issues/17254
https://github.com/owncloudarchive/files_locking/issues/39

[ownclouders]

GitMate.io thinks possibly related issues are https://github.com/owncloud/core/issues/17016 (Retry lock acquiring after delay), https://github.com/owncloud/core/issues/17254 (423 Locked when upload a file after a disconnection), https://github.com/owncloud/core/issues/1088 (IE8 New and Upload have no border), https://github.com/owncloud/core/pull/30776 (Retry on stalled upload), and https://github.com/owncloud/core/issues/17236 (Interrupted upload results in lock on unrelated folders).

[DeepDiver1975]

do you have any server side logs?

generally speaking: in exceptional cases stray locks can remain. They will be cleaned after the timeout expires.

[davigonz]

do you have any server side logs?

Yes, just updated my first comment with some server logs.

Like to add this behaviour wasn't present when retrying uploads with the old endpoint.

They will be cleaned after the timeout expires

How long is that timeout?

[PVince81]

@davigonz did you interrupt the curl command and let it run while disconnecting ?

Maybe curl kept the connection open ? Wireshark or netstat might be able to tell.

The timeout is one hour. If using DB locking you need to run cron to get the locks cleant.

[PVince81]

You can also try to observe the locking table during each step by doing select * from oc_file_locks where lock <> 0 and see if there's anything there during these times.

[davigonz]

@PVince81

did you interrupt the curl command and let it run while disconnecting?

No, I disconnect internet, wait a bit for the curl timeout and after that I retry the upload.

Maybe curl kept the connection open?

Don't think so due to my answer to the previous question. Besides, the error also appears when using OkHttp in the app and the first call to upload the file is closed after losing the internet connection.

The timeout is one hour. If using DB locking you need to run cron to get the locks cleant.

In my opinion, the files should be properly unlocked upon disconnection, as we did to fix https://github.com/owncloud/core/issues/17254#issuecomment-277644412.

[PVince81]

Hmm, and you're also using mod_php for the deployment ? AFAIK PHP will run all cleanup and shutdown routines after a connection was closed, which will liberate the locks.

[davigonz]

Hmm, and you're also using mod_php for the deployment ?

I've tested it in demo.owncloud.org and in a docker container running locally and is reproducible in both cases. Besides, I executed the command apache2ctl -M | sort within the local docker to see the apache modules installed and php7_module is there.

Any other idea?

[guruz]

I've seen this FileLocked in some bug reports in desktop but it didn't come up much. (I don't know about old vs new endpoint)
https://github.com/owncloud/client/search?q=FileLocked&type=Issues

I'd assume the PHP process of the first upload is still running, that's why you see an issue? (I dont know how server side works)

[michaelstingl]

@davigonz Tiny file? No chunking?

[michaelstingl]

@davigonz no problem with old endpoint?

[guruz]

Do the old and new endpoint differ with regards to lock cleanup?
Is there a lock cleanup in the PHP shutdown handler?

[davigonz]

Tiny file? No chunking?

The issue is also reproducible with no chunking, using a couple of megabytes file.

no problem with old endpoint?

No, upload retries work as expected with the old endpoint.

I've seen this FileLocked in some bug reports in desktop but it didn't come up much. (I don't know about old vs new endpoint)

Thanks @guruz for the link, I would say that https://github.com/owncloud/client/issues/4874 is similar to what I describe here.

Do the old and new endpoint differ with regards to lock cleanup?
Is there a lock cleanup in the PHP shutdown handler?

+1 , think the problem is related to those questions.

[guruz]

Looks like it is always registered?
https://github.com/owncloud/core/blob/v10.0.7/lib/base.php#L678

https://github.com/owncloud/core/blob/0d64f54a91a84fa7eea99971c2763f376031146b/lib/base.php#L685

[PVince81]

There is a lock cleanup when using $view->fopen() here https://github.com/owncloud/core/blob/v10.0.8/lib/private/Files/View.php#L1214

[PVince81]

the above waits for "fclose()", hmm... so if fclose is not called it won't unlock.

I'd expect PHP's GC to call fclose here when aborting the connection.

Maybe the new endpoint uses a different approach and not fopen ?

[DeepDiver1975]

the above waits for "fclose()", hmm... so if fclose is not called it won't unlock.

I'd expect PHP's GC to call fclose here when aborting the connection.

Maybe the new endpoint uses a different approach and not fopen ?

even if fclose is not called and the file is not unlocked - the releaseAll() call in the shutdown function will clean it up ....

[DeepDiver1975]

I did reproduce this in local setup with apache on one machine and curl on another.

The php process on the server will remain in wait state for quite a few minutes waiting for data to be pushed from the client to the server.
After this period of time the requests terminates and cleans the remaining locks.

I bet there is some config value within apache to determine this time out value ...

@davigonz what are your experianced time frames the lock is removed? THX

[davigonz]

what are your experianced time frames the lock is removed? THX

I waited for a couple of minutes and the files kept locked, maybe need to wait a bit more. I will test it a again and give you more precise numbers.

[PVince81]

sounds like potential FAQ documentation: "file is locked, what should I do"

[davigonz]

what are your experianced time frames the lock is removed? THX

@DeepDiver1975 @PVince81

Using https://demo.owncloud.org/ as server and taking into account different time frames from the moment in which Wi-Fi was turned off while performing a file upload till the moment to perform the first retry.

• 1 minute: file still blocked.
• 2 minutes: file still blocked.
• 3 minutes: file still blocked.
• 4 minutes: file still blocked
• 5 minutes: file unblocked, retry works.

I bet there is some config value within apache to determine this time out value ...

So 5 minutes is the timeout value.

More than one year ago, this PR was merged to fix a similar problem, have you checked if is something we are doing there but not in the new endpoint?

[DeepDiver1975]

The PR addresses v1 and V2 of the dav endpoints.
There is nothing else we can do .... 5 minutes seem reasonable to me.
If not one needs to tweak the PHP/Apache settings.

Lets close this issue.

[davigonz]

The PR addresses v1 and V2 of the dav endpoints.
There is nothing else we can do .... 5 minutes seem reasonable to me.

But that PR was meant to tell PHP to continue working even when the connection was closed so that resources get freed properly in that moment, not after 5 minutes, so that solution is not working for this case.

[DeepDiver1975]

The problem is the detection that the connection is dead. When reading from a connection you cannot detect if the connection is dead or not. You can only detect this when you write to a connection.

So in the scenario above you need to wait for data to arrive and when no data is received for a given timeframe -> abort.

ignore_user_abort is necessary to let the process continue and finish what ever is necessary even if the connection dies.

[michaelstingl]

@DeepDiver1975 What's the recommended strategy for clients to deal with this situation?

[DeepDiver1975]

Is there any need for special handling? My expectation is that after a 423 the operation is retried after some time .... hmmm ....

[davigonz]

Well, I've been testing this the most part of the day with the latest commit in our new network library branch and is working properly at the moment but the error is still reproducible via curl, so we will keep working on uploads retry and give you more information if the error reappears while using the app, thanks for your help.

[guruz]

@DeepDiver1975 I don't understand your reasoning. @davigonz says it's is different for old endpoint vs new endpoint. So there must be a regression somewhere?

[DeepDiver1975]

@davigonz says it's is different for old endpoint vs new endpoint. So there must be a regression somewhere?

this is not the case from my understaning.

@davigonz can you please reevaluate? THX

[guruz]

@DeepDiver1975 FYI https://github.com/owncloud/core/issues/31843#issuecomment-403456348

no problem with old endpoint?

No, upload retries work as expected with the old endpoint.

But maybe @davigonz can clarify

[davigonz]

says it's is different for old endpoint vs new endpoint. So there must be a regression somewhere?

That is what I saw when I opened this issue, but after testing it several times, there's no deterministic behaviour, yesterday I got a 423 locked error when using the old endpoint as well.

[guruz]

I think I'm able to reproduce this on demo.owncloud.com (old endpoint) just by re-uploading the same file again and again. WITHOUT killing the connection. Not 100% confident yet.
I also commented on https://github.com/owncloud/core/issues/17016#issuecomment-493871705

[cdamken]

That is what I saw when I opened this issue, but after testing it several times, there's no deterministic behaviour, yesterday I got a 423 locked error when using the old endpoint as well.

@micbar This looks like the problem with Redis, probably that will be the solution

[cdamken]

@micbar can you explain which was the problem you solved?

[cdamken]

After talking with @davigonz I see this test was not tested with redis.