Upload into a moved folder fails (at least on ocis.owncloud.works)

[kulmann]

Upload into a moved folder fails

Steps to reproduce:

1: create folder /test
2: create folder /test-moved
3: move folder /test-moved into /test, so that its path is /test/test-moved
4: navigate into /test/test-moved
5: upload a file (tus) - upload fails with error message File upload failed… tus: unexpected response while creating upload, originated from request (response code: 500, response text: )

Then:
6: create folder /test/test-created
7: navigate into /test/test-created
8: upload a file (tus) - upload succeeds.

Server logs:

2020-11-27T13:45:12Z DBG gateway: split: parts[1]:Serman != shareFolder:Shares pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG unary code=OK end="27/Nov/2020:13:45:12 +0000" from=tcp://127.0.0.1:57262 pkg=rgrpc service=storage start="27/Nov/2020:13:45:12 +0000" time_ns=152192 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProvider user-agent=grpc-go/1.26.0
2020-11-27T13:45:12Z DBG NodeFromPath() fn=/Serman/foo/demo-key-mail-works.png pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() walk node={"Exists":true,"ID":"da3fc2e5-0453-40d1-b190-18fb385d77f5","Name":"Serman","ParentID":"d94c9d94-a68f-4da0-8d86-162d19f6b2c0"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() walk node={"Exists":true,"ID":"c3e05899-e798-4edd-93bf-03189afa67be","Name":"foo","ParentID":"da3fc2e5-0453-40d1-b190-18fb385d77f5"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() walk node={"Exists":false,"ID":"","Name":"demo-key-mail-works.png","ParentID":"c3e05899-e798-4edd-93bf-03189afa67be"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z WRN srv/app/pkg/mod/github.com/cs3org/[email protected]/internal/grpc/services/storageprovider/storageprovider.go:528 > path not found when stating pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG unary code=OK end="27/Nov/2020:13:45:12 +0000" from=tcp://127.0.0.1:44946 pkg=rgrpc service=storage start="27/Nov/2020:13:45:12 +0000" time_ns=626771 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/cs3.storage.provider.v1beta1.ProviderAPI/Stat user-agent=grpc-go/1.26.0
2020-11-27T13:45:12Z DBG unary code=OK end="27/Nov/2020:13:45:12 +0000" from=tcp://127.0.0.1:57272 pkg=rgrpc service=storage start="27/Nov/2020:13:45:12 +0000" time_ns=3093147 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/cs3.gateway.v1beta1.GatewayAPI/Stat user-agent=grpc-go/1.26.0
2020-11-27T13:45:12Z DBG skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/InitiateFileUpload pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG unary code=OK end="27/Nov/2020:13:45:12 +0000" from=tcp://127.0.0.1:57262 pkg=rgrpc service=storage start="27/Nov/2020:13:45:12 +0000" time_ns=138674 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProvider user-agent=grpc-go/1.26.0
2020-11-27T13:45:12Z DBG NodeFromPath() fn=/Serman/foo/demo-key-mail-works.png pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() walk node={"Exists":true,"ID":"da3fc2e5-0453-40d1-b190-18fb385d77f5","Name":"Serman","ParentID":"d94c9d94-a68f-4da0-8d86-162d19f6b2c0"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() walk node={"Exists":true,"ID":"c3e05899-e798-4edd-93bf-03189afa67be","Name":"foo","ParentID":"da3fc2e5-0453-40d1-b190-18fb385d77f5"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() walk node={"Exists":false,"ID":"","Name":"demo-key-mail-works.png","ParentID":"c3e05899-e798-4edd-93bf-03189afa67be"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG ocisfs: resolved filename info={"ID":"","IsFinal":false,"IsPartial":false,"MetaData":{"dir":"foo","filename":"demo-key-mail-works.png","mtime":"1605150372.581"},"Offset":0,"PartialUploads":null,"Size":79162,"SizeIsDeferred":false,"Storage":null} metadata={"mtime":"1605150372.581"} node={"Exists":false,"ID":"","Name":"demo-key-mail-works.png","ParentID":"c3e05899-e798-4edd-93bf-03189afa67be"} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG ocisfs: NewUpload info={"ID":"","IsFinal":false,"IsPartial":false,"MetaData":{"dir":"foo","filename":"demo-key-mail-works.png","mtime":"1605150372.581"},"Offset":0,"PartialUploads":null,"Size":79162,"SizeIsDeferred":false,"Storage":null} pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG NodeFromPath() fn=foo/demo-key-mail-works.png pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z ERR srv/app/pkg/mod/github.com/cs3org/[email protected]/internal/grpc/services/storageprovider/storageprovider.go:331 > error getting upload id: path:"/home/Serman/foo/demo-key-mail-works.png"  error="ocisfs: error wrapping filename: error: not found: foo" pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG unary code=OK end="27/Nov/2020:13:45:12 +0000" from=tcp://127.0.0.1:44946 pkg=rgrpc service=storage start="27/Nov/2020:13:45:12 +0000" time_ns=1177151 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/cs3.storage.provider.v1beta1.ProviderAPI/InitiateFileUpload user-agent=grpc-go/1.26.0
2020-11-27T13:45:12Z ERR srv/app/pkg/mod/github.com/cs3org/[email protected]/internal/grpc/services/gateway/storageprovider.go:634 > error initiating upload error="gateway: grpc failed with code CODE_INTERNAL" pkg=rgrpc service=storage traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z DBG unary code=OK end="27/Nov/2020:13:45:12 +0000" from=tcp://127.0.0.1:57272 pkg=rgrpc service=storage start="27/Nov/2020:13:45:12 +0000" time_ns=2813423 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/cs3.gateway.v1beta1.GatewayAPI/InitiateFileUpload user-agent=grpc-go/1.26.0
2020-11-27T13:45:12Z ERR grpc initiate file upload request failed path=/home/Serman/foo/demo-key-mail-works.png pkg=rhttp service=storage status={"code":15,"message":"error initiating upload","trace":"73951531a8563b6aebdc09eda37b1d22"} traceid=73951531a8563b6aebdc09eda37b1d22
2020-11-27T13:45:12Z ERR http end="27/Nov/2020:13:45:12 +0000" host=127.0.0.1 method=POST pkg=rhttp proto=HTTP/1.1 service=storage size=0 start="27/Nov/2020:13:45:12 +0000" status=500 time_ns=7934567 traceid=73951531a8563b6aebdc09eda37b1d22 uri=/remote.php/dav/files/einstein/Serman/foo url=/remote.php/dav/files/einstein/Serman/foo

[jnweiger]

Reproduced with Android app 2.15.3

[jnweiger]

desktop client 2.7.1 stops all sync down activity, due to this:

11-27 15:04:43:157 [ info sync.httplogger ]:    "34fa263b-9887-4cac-bbc0-060e2d44927c: Response: PROPFIND 207 https://ocis.owncloud.works/remote.php/webdav/Serman/foo Header: { Access-Control-Allow-Origin: *, Access-Control-Expose-Headers: Tus-Resumable, Tus-Version, Tus-Extension, Content-Length: 1580, Content-Security-Policy: default-src 'none';, Content-Type: application/xml; charset=utf-8, Date: Fri, 27 Nov 2020 14:04:43 GMT, Dav: 1, 3, extended-mkcol, Tus-Extension: creation,creation-with-upload, Tus-Resumable: 1.0.0, Tus-Version: 1.0.0, Vary: Origin, X-Content-Type-Options: nosniff, X-Download-Options: noopen, X-Frame-Options: SAMEORIGIN, X-Permitted-Cross-Domain-Policies: none, X-Robots-Tag: none, X-Xss-Protection: 1; mode=block, } Data: [<?xml version=\"1.0\" encoding=\"utf-8\"?><d:multistatus xmlns:d=\"DAV:\" xmlns:s=\"http://sabredav.org/ns\" xmlns:oc=\"http://owncloud.org/ns\"><d:response><d:href>/remote.php/webdav/Serman/foo/</d:href><d:propstat><d:prop><d:resourcetype><d:collection/></d:resourcetype><d:getlastmodified>Wed, 25 Nov 2020 20:44:12 +0000</d:getlastmodified><d:getetag>\"4ff20cf04e7622206374a4b394db761e\"</d:getetag><oc:id>MTI4NGQyMzgtYWE5Mi00MmNlLWJkYzQtMGIwMDAwMDA5MTU3OmMzZTA1ODk5LWU3OTgtNGVkZC05M2JmLTAzMTg5YWZhNjdiZQ==</oc:id><oc:permissions>WCKDNVR</oc:permissions></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><d:getcontentlength></d:getcontentlength><oc:downloadURL></oc:downloadURL><oc:dDC></oc:dDC><oc:checksums></oc:checksums><oc:share-types></oc:share-types></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response><d:response><d:href>/remote.php/webdav/foo/New%20file.txt</d:href><d:propstat><d:prop><d:resourcetype></d:resourcetype><d:getlastmodified>Wed, 25 Nov 2020 20:44:12 +0000</d:getlastmodified><d:getcontentlength>0</d:getcontentlength><d:getetag>\"9cb22f9fd74ef5e3176c6fd058dbd799\"</d:getetag><oc:id>MTI4NGQyMzgtYWE5Mi00MmNlLWJkYzQtMGIwMDAwMDA5MTU3OjFmMDQ5YTg2LTA2ZjUtNDhlNi1hZTYyLTUxMTAxYmQ2YjNkZQ==</oc:id><oc:permissions>WCKDNVR</oc:permissions></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat><d:propstat><d:prop><oc:downloadURL></oc:downloadURL><oc:dDC></oc:dDC><oc:checksums></oc:checksums><oc:share-types></oc:share-types></d:prop><d:status>HTTP/1.1 404 Not Found</d:status></d:propstat></d:response></d:multistatus>]"
11-27 15:04:43:157 [ info sync.networkjob.lscol ]:      LSCOL of QUrl("https://ocis.owncloud.works/remote.php/webdav/Serman/foo") FINISHED WITH STATUS "OK"
11-27 15:04:43:157 [ warning sync.networkjob.lscol ]:   Invalid href "/remote.php/webdav/foo/New file.txt" expected starting with "/remote.php/webdav/Serman/foo"
11-27 15:04:43:157 [ warning sync.discovery ]:  LSCOL job error "Unknown error" 207 QNetworkReply::NoError
11-27 15:04:43:157 [ warning sync.discovery ]:  Server error in directory "Serman/foo" 207

[refs]

so it looks like the following holds with the ocis storage:

1. remove all files for the sake of sanity
2. create /A folder
3. create /B folder
4. move /B into /A
5. print /A/B extended attributes

expected: /A/B user.ocis.parentid attribute is updated to reflect the new parent
actual: /A/B user.ocis.parentid is not updated and instead points to the root folder (the initial parent).

This can be seen in this screenshot

[jnweiger]

Cannot reproduce on ocis-1.0.0-rc5 on eos.

connect desktop client-2.7.1 as user einstein, wait until initial sync finishes.
From within the sync folder do:

 2091  mkdir foo bar
 2092  cp ~/Pictures/testpics_3/CHANGELOG.md foo
 2093  cp ~/Pictures/testpics_3/chart.svg bar
 2094  mkdir killer
 2095  mv bar killer
 2096  cp ~/Pictures/testpics_3/inksc.png killer/bar/

Syncs just fine. No errors!
(ignore my previous ramblings, that was a broken server suffering from earlier destructive tests)

[kulmann]

So, we found out that newNode.ID is empty here:
https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/tree.go#L177

and because of that the extended attributes are not written to the correct node, but to the nodes root folder of the ocis fs.

Trying to read the node after the os.Rename operation results in a weird node, having var as name, though. Might come from some intermediate state of the rename operation? Have to debug further.

[butonic]

As you may have seen there are two codepaths in the ocis move(). The first is for renaming a file in the same folder. The second one is for moving a node to a new parent and optionally changing the name at the same time.

[butonic]

The target node in that case is the result of the lookup in https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/ocis.go#L342

Even if the target path does not exist the call returns a note struct that should be filled with the correct parent I'd.

[butonic]

NodeFromResourco might take a path or an id reference. Let me check what ocs sends...

[kulmann]

The target node in that case is the result of the lookup in https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/ocis.go#L342

Even if the target path does not exist the call returns a note struct that should be filled with the correct parent I'd.

Yep, took us way too long but we arrived there as well. The issue is that we need a valid ID to build the target path for where we want to write the extended attributes. While the parentid indeed exists and is valid, the ID is empty because the node didn't exist when we read it.

[butonic]

The ocs move checks if the destination exists. If not it checks if the parent exists. And it will always use a path based reference: https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/internal/http/services/owncloud/ocdav/move.go#L181

[butonic]

Ok so NodeFromPath uses Walk with() from a node: https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/lookup.go#L63

[butonic]

Actually walkPath is implemented in lookup.go https://github.com/cs3org/reva/blob/4a9be347ac29706e429d47525815e638f9770f29/pkg/storage/fs/ocis/lookup.go#L126 😞 needs cleanup ... as I said the Interface is not yet done ...

[butonic]

Anyway ... The code finally relies on a nodes Child() to return a node https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/node.go#L199

[butonic]

Child() creates a new node struct and sets the parentID to the parent nodes ID property. https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/node.go#L202

AFAICT the target does not exist so the new child node has no ID set. Which is what I would expect.

[butonic]

The code in move should handle that case correctly, because it needs to reuse the node I'd from the source...

[butonic]

@kulmann ok that is why https://github.com/cs3org/reva/blob/e4fc511d5fac467cd1425077eb676c5af7f20441/pkg/storage/fs/ocis/tree.go#L177 has no ID. We need to copy it from the src node. That should do the trick. Need to take care of the kids now...

[individual-it]

related to #719 ?