Webdav COPY issues with Depth 0

[PVince81]

From litmus test

Steps

1. Create a folder "ccsrc"
2. Upload a file "ccsrc/foo"
3. Do a Webdav shallow copy:

curl -D - -X COPY -H "Depth: 0" -H "Destination: http://localhost:9140/remote.php/webdav/litmus/ccdest" -H "$OCIS_AUTH" -k http://localhost:9140/remote.php/webdav/litmus/ccsrc

Expected result

Success error code.
Since this is a shallow copy, no contents of the folders must be copied (no recursion), see https://tools.ietf.org/html/rfc4918#section-9.8.3

Actual result

HTTP/1.1 500 Internal Server Error
Access-Control-Allow-Origin: *
Vary: Origin
X-Access-Token: REMOVED
Date: Tue, 05 May 2020 13:15:23 GMT
Content-Length: 0

The target folder was created though and no contents was copied over.
However it seems the logic is attempting to copy the contents even though it shouldn't, the fact that the final outcome is correct is only due to the error that happened.

Logs

Reva-frontend

WRN core access token not set pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
DBG error retrieving credentials error="no basic auth provided" pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
DBG credentials obtained from credential strategy: &{Type:bearer ClientID: ClientSecret:eyJhbGciOiJQUzI1NiIsImtpZCI6IiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJwaG9lbml4IiwiZXhwIjoxNTg4Njg1MDYyLCJqdGkiOiJ6UEhPaWdUbGlYWmtkVHlfN1VJaV8tcDk1WEtERkpRNiIsImlhdCI6MTU4ODY4NDQ2MiwiaXNzIjoiaHR0cHM6Ly9sb2NhbGhvc3Q6OTIwMCIsInN1YiI6Ilh0U2lfbWl5V1NCLXBrdkdueFBvQzVBNGZsaWgwVUNMZ3ZVN2NMd2ptakNLWDdGWW4ySFdrNnJSQ0V1eTJHNXFBeV95TVFjX0ZLOWFORmhVTXJYMnBRQGtvbm5lY3QiLCJrYy5pc0FjY2Vzc1Rva2VuIjp0cnVlLCJrYy5hdXRob3JpemVkU2NvcGVzIjpbIm9wZW5pZCIsInByb2ZpbGUiLCJlbWFpbCJdLCJrYy5pZGVudGl0eSI6eyJrYy5pLmRuIjoiRWluc3RlaW4iLCJrYy5pLmlkIjoiY249ZWluc3RlaW4sb3U9dXNlcnMsZGM9ZXhhbXBsZSxkYz1vcmciLCJrYy5pLnVuIjoiZWluc3RlaW4ifSwia2MucHJvdmlkZXIiOiJpZGVudGlmaWVyLWxkYXAifQ.FHny3RhPiySaYuvtenket6r3KRBaQ19IajmE2e3V1zuKeBKvZkgmPEVJyh06Rz8GCj_9SpKsPa987f7kRgVJj7sX4ZoaFeQ9Red_6oIQzwTM7HVGnFmXPvHjnC6xMI_Nmu0qQsVzaO99j8sIf0uWeJHsKEovs2BdsPWxUjM62lFLhqsjBS9DEZgsQMPXTSRt-10fp5q7cJ6y0HnFCW_5GA1DFgmhPNP9Nuu3rRfhVnhyNrsZlg9E4XYCyD4mYrO47jQ3ru_uT2pM9sUcOmAF_7g_Y41VS4v0J81bXeMbjHobK6IDllW_x0wNdwyIVkdHO9U5SeQCBdx4FuP0yI2DVA} pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
DBG AuthenticateRequest: type:"bearer" client_secret:"eyJhbGciOiJQUzI1NiIsImtpZCI6IiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJwaG9lbml4IiwiZXhwIjoxNTg4Njg1MDYyLCJqdGkiOiJ6UEhPaWdUbGlYWmtkVHlfN1VJaV8tcDk1WEtERkpRNiIsImlhdCI6MTU4ODY4NDQ2MiwiaXNzIjoiaHR0cHM6Ly9sb2NhbGhvc3Q6OTIwMCIsInN1YiI6Ilh0U2lfbWl5V1NCLXBrdkdueFBvQzVBNGZsaWgwVUNMZ3ZVN2NMd2ptakNLWDdGWW4ySFdrNnJSQ0V1eTJHNXFBeV95TVFjX0ZLOWFORmhVTXJYMnBRQGtvbm5lY3QiLCJrYy5pc0FjY2Vzc1Rva2VuIjp0cnVlLCJrYy5hdXRob3JpemVkU2NvcGVzIjpbIm9wZW5pZCIsInByb2ZpbGUiLCJlbWFpbCJdLCJrYy5pZGVudGl0eSI6eyJrYy5pLmRuIjoiRWluc3RlaW4iLCJrYy5pLmlkIjoiY249ZWluc3RlaW4sb3U9dXNlcnMsZGM9ZXhhbXBsZSxkYz1vcmciLCJrYy5pLnVuIjoiZWluc3RlaW4ifSwia2MucHJvdmlkZXIiOiJpZGVudGlmaWVyLWxkYXAifQ.FHny3RhPiySaYuvtenket6r3KRBaQ19IajmE2e3V1zuKeBKvZkgmPEVJyh06Rz8GCj_9SpKsPa987f7kRgVJj7sX4ZoaFeQ9Red_6oIQzwTM7HVGnFmXPvHjnC6xMI_Nmu0qQsVzaO99j8sIf0uWeJHsKEovs2BdsPWxUjM62lFLhqsjBS9DEZgsQMPXTSRt-10fp5q7cJ6y0HnFCW_5GA1DFgmhPNP9Nuu3rRfhVnhyNrsZlg9E4XYCyD4mYrO47jQ3ru_uT2pM9sUcOmAF_7g_Y41VS4v0J81bXeMbjHobK6IDllW_x0wNdwyIVkdHO9U5SeQCBdx4FuP0yI2DVA"  against localhost:9142 pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
INF core access token generated pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
DBG http routing: head= tail=/remote.php/webdav/litmus/ccsrc svc=root pkg=rhttp service=reva
DBG http routing head=remote.php pkg=rhttp service=reva tail=/webdav/litmus/ccsrc traceid=900b7eaa62ae443ecb4f7d71d682bbca
INF copy destination=http://localhost:9140/remote.php/webdav/litmus/ccdest overwrite= pkg=rhttp service=reva source=/home/litmus/ccsrc traceid=900b7eaa62ae443ecb4f7d71d682bbca
INF copy base-uri=/remote.php/webdav pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca url-path=/remote.php/webdav/litmus/ccdest
DBG descending dst=/home/litmus/ccdest pkg=rhttp service=reva src=/home/litmus/ccsrc traceid=900b7eaa62ae443ecb4f7d71d682bbca
DBG descending dst=/home/litmus/ccdest/foo pkg=rhttp service=reva src=/home/litmus/ccsrc/foo traceid=900b7eaa62ae443ecb4f7d71d682bbca
ERR error descending directory error="status code 200" pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
ERR http end="05/May/2020:15:15:23 +0200" host=127.0.0.1 method=COPY pkg=rhttp proto=HTTP/1.1 service=reva size=0 start="05/May/2020:15:15:22 +0200" status=500 time_ns=73014758 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/remote.php/webdav/litmus/ccsrc url=/remote.php/webdav/litmus/ccsrc
WRN core access token not set pkg=rhttp service=reva traceid=6de68adba6a0e3beccc3aa3c4882f79d
DBG error retrieving credentials error="no basic auth provided" pkg=rhttp service=reva traceid=6de68adba6a0e3beccc3aa3c4882f79d
DBG credentials obtained from credential strategy: &{Type:bearer ClientID: ClientSecret:eyJhbGciOiJQUzI1NiIsImtpZCI6IiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJwaG9lbml4IiwiZXhwIjoxNTg4Njg1MDYyLCJqdGkiOiJ6UEhPaWdUbGlYWmtkVHlfN1VJaV8tcDk1WEtERkpRNiIsImlhdCI6MTU4ODY4NDQ2MiwiaXNzIjoiaHR0cHM6Ly9sb2NhbGhvc3Q6OTIwMCIsInN1YiI6Ilh0U2lfbWl5V1NCLXBrdkdueFBvQzVBNGZsaWgwVUNMZ3ZVN2NMd2ptakNLWDdGWW4ySFdrNnJSQ0V1eTJHNXFBeV95TVFjX0ZLOWFORmhVTXJYMnBRQGtvbm5lY3QiLCJrYy5pc0FjY2Vzc1Rva2VuIjp0cnVlLCJrYy5hdXRob3JpemVkU2NvcGVzIjpbIm9wZW5pZCIsInByb2ZpbGUiLCJlbWFpbCJdLCJrYy5pZGVudGl0eSI6eyJrYy5pLmRuIjoiRWluc3RlaW4iLCJrYy5pLmlkIjoiY249ZWluc3RlaW4sb3U9dXNlcnMsZGM9ZXhhbXBsZSxkYz1vcmciLCJrYy5pLnVuIjoiZWluc3RlaW4ifSwia2MucHJvdmlkZXIiOiJpZGVudGlmaWVyLWxkYXAifQ.FHny3RhPiySaYuvtenket6r3KRBaQ19IajmE2e3V1zuKeBKvZkgmPEVJyh06Rz8GCj_9SpKsPa987f7kRgVJj7sX4ZoaFeQ9Red_6oIQzwTM7HVGnFmXPvHjnC6xMI_Nmu0qQsVzaO99j8sIf0uWeJHsKEovs2BdsPWxUjM62lFLhqsjBS9DEZgsQMPXTSRt-10fp5q7cJ6y0HnFCW_5GA1DFgmhPNP9Nuu3rRfhVnhyNrsZlg9E4XYCyD4mYrO47jQ3ru_uT2pM9sUcOmAF_7g_Y41VS4v0J81bXeMbjHobK6IDllW_x0wNdwyIVkdHO9U5SeQCBdx4FuP0yI2DVA} pkg=rhttp service=reva traceid=6de68adba6a0e3beccc3aa3c4882f79d
DBG AuthenticateRequest: type:"bearer" client_secret:"eyJhbGciOiJQUzI1NiIsImtpZCI6IiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJwaG9lbml4IiwiZXhwIjoxNTg4Njg1MDYyLCJqdGkiOiJ6UEhPaWdUbGlYWmtkVHlfN1VJaV8tcDk1WEtERkpRNiIsImlhdCI6MTU4ODY4NDQ2MiwiaXNzIjoiaHR0cHM6Ly9sb2NhbGhvc3Q6OTIwMCIsInN1YiI6Ilh0U2lfbWl5V1NCLXBrdkdueFBvQzVBNGZsaWgwVUNMZ3ZVN2NMd2ptakNLWDdGWW4ySFdrNnJSQ0V1eTJHNXFBeV95TVFjX0ZLOWFORmhVTXJYMnBRQGtvbm5lY3QiLCJrYy5pc0FjY2Vzc1Rva2VuIjp0cnVlLCJrYy5hdXRob3JpemVkU2NvcGVzIjpbIm9wZW5pZCIsInByb2ZpbGUiLCJlbWFpbCJdLCJrYy5pZGVudGl0eSI6eyJrYy5pLmRuIjoiRWluc3RlaW4iLCJrYy5pLmlkIjoiY249ZWluc3RlaW4sb3U9dXNlcnMsZGM9ZXhhbXBsZSxkYz1vcmciLCJrYy5pLnVuIjoiZWluc3RlaW4ifSwia2MucHJvdmlkZXIiOiJpZGVudGlmaWVyLWxkYXAifQ.FHny3RhPiySaYuvtenket6r3KRBaQ19IajmE2e3V1zuKeBKvZkgmPEVJyh06Rz8GCj_9SpKsPa987f7kRgVJj7sX4ZoaFeQ9Red_6oIQzwTM7HVGnFmXPvHjnC6xMI_Nmu0qQsVzaO99j8sIf0uWeJHsKEovs2BdsPWxUjM62lFLhqsjBS9DEZgsQMPXTSRt-10fp5q7cJ6y0HnFCW_5GA1DFgmhPNP9Nuu3rRfhVnhyNrsZlg9E4XYCyD4mYrO47jQ3ru_uT2pM9sUcOmAF_7g_Y41VS4v0J81bXeMbjHobK6IDllW_x0wNdwyIVkdHO9U5SeQCBdx4FuP0yI2DVA"  against localhost:9142 pkg=rhttp service=reva traceid=6de68adba6a0e3beccc3aa3c4882f79d
INF core access token generated pkg=rhttp service=reva traceid=6de68adba6a0e3beccc3aa3c4882f79d

Reva-storage-home

2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=871236 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/CreateHome user-agent=grpc-go/1.26.0
2020-05-05T15:15:22+02:00 DBG ocfs: unwrap: internal=/var/tmp/reva/data/einstein/files/litmus/ccsrc external=/litmus/ccsrc pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=1838982 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/Stat user-agent=grpc-go/1.26.0
2020-05-05T15:15:22+02:00 DBG ocfs: unwrap: internal=/var/tmp/reva/data/einstein/files/litmus/ccdest external=/litmus/ccdest pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 WRN home/vincent/Private/Work/workspace/reva/internal/grpc/services/storageprovider/storageprovider.go:449 > file not found pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=1751867 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/Stat user-agent=grpc-go/1.26.0
2020-05-05T15:15:22+02:00 DBG ocfs: unwrap: internal=/var/tmp/reva/data/einstein/files/litmus external=/litmus pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=2252965 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/Stat user-agent=grpc-go/1.26.0
2020-05-05T15:15:22+02:00 DBG propagating change i=1 leafPath=/var/tmp/reva/data/einstein/files/litmus/ccdest parts=["","litmus","ccdest"] pkg=rgrpc root=/var/tmp/reva/data/einstein/files service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 DBG propagating change i=2 leafPath=/var/tmp/reva/data/einstein/files/litmus/ccdest parts=["","litmus","ccdest"] pkg=rgrpc root=/var/tmp/reva/data/einstein/files/litmus service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=1770984 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/CreateContainer user-agent=grpc-go/1.26.0
2020-05-05T15:15:22+02:00 DBG ocfs: unwrap: internal=/var/tmp/reva/data/einstein/files/litmus/ccsrc/foo external=/litmus/ccsrc/foo pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=1870209 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/ListContainer user-agent=grpc-go/1.26.0
2020-05-05T15:15:22+02:00 INF file download data-server=http://localhost:9156/data/litmus/ccsrc/foo fn=/home/litmus/ccsrc/foo pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:22+02:00 INF unary code=OK end="05/May/2020:15:15:22 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:22 +0200" time_ns=476044 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/InitiateFileDownload user-agent=grpc-go/1.26.0
2020-05-05T15:15:23+02:00 DBG ocfs: unwrap: internal=/var/tmp/reva/data/einstein/files/litmus/ccdest/foo external=/litmus/ccdest/foo pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:23+02:00 DBG ocfs: NewUpload info={"ID":"","IsFinal":false,"IsPartial":false,"MetaData":{"dir":"/litmus/ccdest","filename":"foo"},"Offset":0,"PartialUploads":null,"Size":0,"SizeIsDeferred":false,"Storage":null} pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:23+02:00 DBG ocfs: resolved filename info={"ID":"","IsFinal":false,"IsPartial":false,"MetaData":{"dir":"/litmus/ccdest","filename":"foo"},"Offset":0,"PartialUploads":null,"Size":0,"SizeIsDeferred":false,"Storage":null} pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:23+02:00 INF file upload data-server=http://localhost:9156/data/234825db-2f06-4c15-af0a-eb302bdf196e fn=/home/litmus/ccdest/foo pkg=rgrpc service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca xs="map[md5:100 unset:1000]"
2020-05-05T15:15:23+02:00 INF unary code=OK end="05/May/2020:15:15:23 +0200" from=tcp://127.0.0.1:33180 pkg=rgrpc service=reva start="05/May/2020:15:15:23 +0200" time_ns=2715366 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/cs3.storage.provider.v1beta1.ProviderAPI/InitiateFileUpload user-agent=grpc-go/1.26.0

Reva-storage-home-data

2020-05-05T15:15:23+02:00 INF access token is already provided pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:23+02:00 DBG http routing: head=data tail=/litmus/ccsrc/foo svc=data pkg=rhttp service=reva
[tusd] 2020/05/05 15:15:23 event="RequestIncoming" method="GET" path="/litmus/ccsrc/foo" requestId="" 
2020-05-05T15:15:23+02:00 INF tusd routing: path=/litmus/ccsrc/foo pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:23+02:00 INF http end="05/May/2020:15:15:23 +0200" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=reva size=375 start="05/May/2020:15:15:23 +0200" status=200 time_ns=1295781 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/data/litmus/ccsrc/foo url=/data/litmus/ccsrc/foo
2020-05-05T15:15:23+02:00 INF access token is already provided pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca
2020-05-05T15:15:23+02:00 DBG http routing: head=data tail=/234825db-2f06-4c15-af0a-eb302bdf196e svc=data pkg=rhttp service=reva
[tusd] 2020/05/05 15:15:23 event="RequestIncoming" method="PUT" path="/234825db-2f06-4c15-af0a-eb302bdf196e" requestId="" 
[tusd] 2020/05/05 15:15:23 event="ResponseOutgoing" status="412" method="PUT" path="/234825db-2f06-4c15-af0a-eb302bdf196e" error="unsupported version" requestId="" 
2020-05-05T15:15:23+02:00 WRN http end="05/May/2020:15:15:23 +0200" host=127.0.0.1 method=PUT pkg=rhttp proto=HTTP/1.1 service=reva size=20 start="05/May/2020:15:15:23 +0200" status=412 time_ns=674724 traceid=900b7eaa62ae443ecb4f7d71d682bbca uri=/data/234825db-2f06-4c15-af0a-eb302bdf196e url=/data/234825db-2f06-4c15-af0a-eb302bdf196e

[PVince81]

somehow it seems to be unhappy about success:

ERR error descending directory error="status code 200" pkg=rhttp service=reva traceid=900b7eaa62ae443ecb4f7d71d682bbca

looking at the storage log above it seems that it's initiating a download of the file "foo" and then uploads it to the destination. But in the end the file is not there, so likely the upload did not finish

[PVince81]

I've added the log for the storage-home-data service, apparently TUS was not happy for that last upload:

[tusd] 2020/05/05 15:15:23 event="ResponseOutgoing" status="412" method="PUT" path="/234825db-2f06-4c15-af0a-eb302bdf196e" error="unsupported version" requestId="" 

Strange thing that it's a "PUT" method which I don't see anywhere in the protocol description.
It should have been a "POST".

[PVince81]

error descending directory error="status code 200" is because the status for the wrong request is returned: https://github.com/cs3org/reva/blob/master/internal/http/services/owncloud/ocdav/copy.go#L274 should be httpRes.StatusCode not httpDownloadRes.StatusCode

so indeed there is an underlying error...

[PVince81]

PR here to fix Depth 0 case: cs3org/reva#714

Apparently the code was not reading the depth value.
So merging that PR would make Litmus happy, for the depth 0 case.
However, the COPY with infinity is still broken as the call is forcing a PUT request but the handler is expecting TUS, so we need to TUSify copy.go.

[PVince81]

raised #173 for the COPY+TUS issue