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

TUS uploads might lead to data-loss in sharing conditions #4153

Closed
SwikritiT opened this issue Jul 11, 2022 · 33 comments
Closed

TUS uploads might lead to data-loss in sharing conditions #4153

SwikritiT opened this issue Jul 11, 2022 · 33 comments
Assignees
Labels
Priority:p2-high Escalation, on top of current planning, release blocker QA:team Type:Bug

Comments

@SwikritiT
Copy link
Contributor

Following scenario failed in nightly and needs further investigation https://drone.owncloud.com/owncloud/ocis/13277/49/6

 Scenario Outline: Overwrite file to a received share folder                                                                                   # /srv/app/testrunner/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature:75
    Given using <dav_version> DAV path                                                                                                          # FeatureContext::usingOldOrNewDavPath()
    And user "Alice" has created folder "/FOLDER"                                                                                               # FeatureContext::userHasCreatedFolder()
    And user "Alice" has uploaded file with content "original content" to "/FOLDER/textfile.txt"                                                # FeatureContext::userHasUploadedAFileWithContentTo()
    And user "Alice" has shared folder "/FOLDER" with user "Brian"                                                                              # FeatureContext::userHasSharedFileWithUserUsingTheSharingApi()
    And user "Brian" has accepted share "/FOLDER" offered by user "Alice"                                                                       # FeatureContext::userHasReactedToShareOfferedBy()
    When user "Brian" uploads file with content "overwritten content" to "/Shares/FOLDER/textfile.txt" using the TUS protocol on the WebDAV API # TUSContext::userUploadsAFileWithContentToUsingTus()
    Then the HTTP status code should be "200"                                                                                                   # FeatureContext::thenTheHTTPStatusCodeShouldBe()
    And as "Alice" file "/FOLDER/textfile.txt" should exist                                                                                     # FeatureContext::asFileOrFolderShouldExist()
    And the content of file "/FOLDER/textfile.txt" for user "Alice" should be "overwritten content"                                             # FeatureContext::contentOfFileForUserShouldBe()

    Examples:
      | dav_version |
      | old         |
      | new         |
        cURL error 52: Empty reply from server (see https://curl.haxx.se/libcurl/c/libcurl-errors.html) for https://ocis-server:9200/remote.php/dav/files/Alice/FOLDER/textfile.txt (GuzzleHttp\Exception\ConnectException)
      | spaces      |
        The downloaded content was expected to be 'overwritten content', but actually is 'original content'. HTTP status was 200
        Failed asserting that two strings are equal.
        --- Expected
        +++ Actual
        @@ @@
        -'overwritten content'
        +'original content'
@SwikritiT SwikritiT changed the title apiWebdavUploadTUS/uploadToShare.feature:75 failed in spaces in nightly apiWebdavUploadTUS/uploadToShare.feature:88 failed in spaces in nightly Jul 11, 2022
@SwikritiT
Copy link
Contributor Author

Tus upload related tests are failing in other merge PR as well seems like there's some problem
apiWebdavUploadTUS/uploadToShare.feature:329 : https://drone.owncloud.com/owncloud/ocis/13254/49/6

  Scenario Outline: Sharer uploads a file with checksum and as a sharee overwrites the shared file with new data and correct checksum                                                                                           # /srv/app/testrunner/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature:329
    Given using <dav_version> DAV path                                                                                                                                                                                          # FeatureContext::usingOldOrNewDavPath()
    And user "Alice" has created a new TUS resource on the WebDAV API with these headers:                                                                                                                                       # TUSContext::createNewTUSResource()
      | Upload-Length   | 16                        |
      | Upload-Metadata | filename dGV4dEZpbGUudHh0 |
    And user "Alice" has uploaded file with checksum "SHA1 c1dab0c0864b6ac9bdd3743a1408d679f1acd823" to the last created TUS Location with offset "0" and content "original content" using the TUS protocol on the WebDAV API   # TUSContext::userHasUploadedFileWithChecksum()
    And user "Alice" has shared file "/textFile.txt" with user "Brian"                                                                                                                                                          # FeatureContext::userHasSharedFileWithUserUsingTheSharingApi()
    And user "Brian" has accepted share "/textFile.txt" offered by user "Alice"                                                                                                                                                 # FeatureContext::userHasReactedToShareOfferedBy()
    When user "Brian" overwrites recently shared file with offset "0" and data "overwritten content" with checksum "SHA1 fe990d2686a0fc86004efc31f5bf2475a45d4905" using the TUS protocol on the WebDAV API with these headers: # TUSContext::userOverwritesFileWithChecksum()
      | Upload-Length   | 19                                    |
      | Upload-Metadata | filename L1NoYXJlcy90ZXh0RmlsZS50eHQ= |
    Then the HTTP status code should be "204"                                                                                                                                                                                   # FeatureContext::thenTheHTTPStatusCodeShouldBe()
    And the content of file "/textFile.txt" for user "Alice" should be "overwritten content"                                                                                                                                    # FeatureContext::contentOfFileForUserShouldBe()

    Examples:
      | dav_version |
      | old         |
      | new         |
        cURL error 52: Empty reply from server (see https://curl.haxx.se/libcurl/c/libcurl-errors.html) for https://ocis-server:9200/remote.php/dav/files/Alice/textFile.txt (GuzzleHttp\Exception\ConnectException)
      | spaces      |
        HTTP status code 412 is not the expected value 201
        Failed asserting that 412 matches expected 201.

@SwikritiT
Copy link
Contributor Author

@kiranparajuli589
Copy link
Contributor

@pascalwengerter
Copy link
Contributor

@SwikritiT
Copy link
Contributor Author

@SwikritiT SwikritiT self-assigned this Jul 11, 2022
@SwikritiT
Copy link
Contributor Author

SwikritiT commented Jul 11, 2022

The test fails for me locally every time in spaces because in this step

When user "Brian" uploads file with content "overwritten content" to "/Shares/FOLDER/textfile.txt" using the TUS protocol on the WebDAV API # TUSContext::userUploadsAFileWithContentToUsingTus()

the overwriting content is uploaded to Shares/... but there's no Shares in spaces and the tests use personal id for every spaces related operation as of now, which is also not correct. The assertion fails in the then step
And the content of file "/FOLDER/textfile.txt" for user "Alice" should be "overwritten content" .
It should actually fail in Then the HTTP status code should be "200". It gives me 412 when I try locally through curl. Has TUS protocol been implemented in spaces?

We need to decide if we want to do the same for #4154 other tests too?

cc @kiranparajuli589 @individual-it @phil-davis

@individual-it
Copy link
Member

I'm surprised that worked ever, tests that use sharing and spaces should not be in core but in ocis repo and work with the share space. So same as #4154

@SwikritiT
Copy link
Contributor Author

SwikritiT commented Jul 11, 2022

I'm surprised that worked ever, tests that use sharing and spaces should not be in core but in ocis repo and work with the share space. So same as #4154

The related tests for spaces are in the expected to fail file but the tests aren't exactly doing what they are supposed to do so idk how revelent it is to put them in expected to fail

- [apiWebdavUploadTUS/uploadToShare.feature:31](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L31)
- [apiWebdavUploadTUS/uploadToShare.feature:50](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L50)
- [apiWebdavUploadTUS/uploadToShare.feature:72](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L72)
- [apiWebdavUploadTUS/uploadToShare.feature:93](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L93)
- [apiWebdavUploadTUS/uploadToShare.feature:135](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L135)
- [apiWebdavUploadTUS/uploadToShare.feature:159](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L159)
- [apiWebdavUploadTUS/uploadToShare.feature:182](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L182)
- [apiWebdavUploadTUS/uploadToShare.feature:205](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L205)
- [apiWebdavUploadTUS/uploadToShare.feature:230](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L230)
- [apiWebdavUploadTUS/uploadToShare.feature:254](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L254)
- [apiWebdavUploadTUS/uploadToShare.feature:301](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L301)
- [apiWebdavUploadTUS/uploadToShare.feature:326](https://github.com/owncloud/core/blob/master/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature#L326)

The test is failing in new dav as well in CI which I cannot reproduce locally

@butonic
Copy link
Member

butonic commented Jul 12, 2022

ocis does show accepted shares in /webdav/Shares and /dav/files/{username}/Shares but accessing it like that is suboptimal. /dav/spaces/a0ca6a90-a365-4782-871e-d44447bbc668 is the direct share jail webdav path ...

@individual-it
Copy link
Member

@butonic with "suboptimal" you mean slow but still should work?

Tests using the share jail should be placed in ocis repo

@butonic
Copy link
Member

butonic commented Jul 12, 2022

correct, slow, but should work

@kiranparajuli589
Copy link
Contributor

failed on tests/acceptance/features/apiWebdavUploadTUS/uploadFile.feature:172 but with same error
https://drone.owncloud.com/owncloud/ocis/13350/51/8

@individual-it
Copy link
Member

ocis log output:

{"level":"error","service":"storage-users","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"error: not found: folder","status":{"code":6,"message":"path not found when initiating upload","trace":"00000000000000000000000000000000"},"time":"2022-07-12T07:21:38.719126126Z","message":"failed to initiate upload"}

{"level":"error","service":"storage-users","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"error: not found: folder","status":{"code":6,"message":"path not found when initiating upload","trace":"00000000000000000000000000000000"},"time":"2022-07-12T07:21:42.3804156Z","message":"failed to initiate upload"}

{"level":"error","service":"storage-users","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"error: not found: folder","status":{"code":6,"message":"path not found when initiating upload","trace":"00000000000000000000000000000000"},"time":"2022-07-12T07:21:46.193952293Z","message":"failed to initiate upload"}

@SwikritiT SwikritiT changed the title apiWebdavUploadTUS/uploadToShare.feature:88 failed in spaces in nightly apiWebdavUploadTUS/uploadToShare.feature related tests is failing intermittently in new dav Jul 13, 2022
@SwikritiT
Copy link
Contributor Author

SwikritiT commented Jul 13, 2022

I could reproduce the issue locally by running the curl commands involved in the tests in the loop. And seems like the overwritten content uploaded by the share receiver is not accessible by the sharer sometimes.

  1. Einstein creates a TUS resource
curl -k -X POST -u einstein:relativity https://host.docker.internal:9200/remote.php/dav/files/Einstein/ -H 'Tus-Resumable: 1.0.0' -H 'Upload-Length: 16' -H 'Upload-Metadata: filename dGV4dEZpbGUudHh0'
  1. Einstein uploads content to the resource through tus protocol
curl -k -X PATCH <https://<location-url-responded-by-post-req>> -u einstein:relativity -H 'Content-Type: application/offset+octet-stream' -H 'Tus-Resumable: 1.0.0' -H 'Upload-Offset: 0' -H'SHA1 c1dab0c0864b6ac9bdd3743a1408d679f1acd823' -d 'original content' -v
  1. Einstein shares the resource with Moss
curl -vk -X POST -u einstein:relativity https://host.docker.internal:9200/ocs/v1.php/apps/files_sharing/api/v1/shares -d 'path=textFile.txt' -d 'shareType=0' -d'permissions=31' -d'shareWith=moss'
  1. Moss accepts the request
curl -vk -X POST -u moss:vista https://host.docker.internal:9200/ocs/v1.php/apps/files_sharing/api/v1/shares/pending/${SHARE_ID}
  1. As moss upload the overwriting content over writing content through tus
curl -k -X POST -u moss:vista https://host.docker.internal:9200/remote.php/dav/files/moss -H 'Tus-Resumable: 1.0.0' -H 'Upload-Length: 19' -H 'Upload-Metadata: filename L1NoYXJlcy90ZXh0RmlsZS50eHQ='
curl -k -X PATCH <location-responded-by-POST> -u moss:vista -H 'Content-Type: application/offset+octet-stream' -H 'Tus-Resumable: 1.0.0' -H 'Upload-Offset: 0' -H'SHA1 fe990d2686a0fc86004efc31f5bf2475a45d4905' -d 'overwritten content' -v
response of patch
*   Trying 127.0.0.1:9200...
* TCP_NODELAY set
* Connected to host.docker.internal (127.0.0.1) port 9200 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_128_GCM_SHA256
* ALPN, server did not agree to a protocol
* Server certificate:
*  subject: O=Acme Corp; CN=OCIS
*  start date: Jul 13 11:26:08 2022 GMT
*  expire date: Jul 13 11:26:08 2023 GMT
*  issuer: O=Acme Corp; CN=OCIS
*  SSL certificate verify result: unable to get local issuer certificate (20), continuing anyway.
* Server auth using Basic with user 'moss'
> PATCH /data/eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJyZXZhIiwiZXhwIjoxNjU3Nzk4NDY3LCJpYXQiOjE2NTc3MTIwNjcsInRhcmdldCI6Imh0dHA6Ly9sb2NhbGhvc3Q6OTE1OC9kYXRhL3R1cy9kZWM3ZjRjMC1lY2ZkLTQ1ODQtOTZkNS1iZDBlMjk2YWQzYzAifQ.GZZ3ps_vJIxesSo5KNmRd0XJJPKgGvekc-u3sifAKo8 HTTP/1.1
> Host: host.docker.internal:9200
> Authorization: Basic bW9zczp2aXN0YQ==
> User-Agent: curl/7.68.0
> Accept: */*
> Content-Type: application/offset+octet-stream
> Tus-Resumable: 1.0.0
> Upload-Offset: 0
> Content-Length: 19
> 
* upload completely sent off: 19 out of 19 bytes
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* Mark bundle as not supporting multiuse
< HTTP/1.1 204 No Content
< Date: Wed, 13 Jul 2022 11:34:27 GMT
< Tus-Resumable: 1.0.0
< Upload-Offset: 19
< Vary: Origin
< X-Content-Type-Options: nosniff
< 
* Connection #0 to host host.docker.internal left intact
  1. As einstein get the content of the shared file
curl -k -X GET -u einstein:relativity https://host.docker.internal:9200/remote.php/dav/files/Einstein/textFile.txt

For this in some cases server replies with

% Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
curl: (52) Empty reply from server

ocis log

ocis_1             | 2022-07-13T11:39:13Z ERR error finishing copying data to response error="http: wrote more than the declared Content-Length" handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000
ocis_1             | 2022-07-13T11:39:13Z ERR content length vs transferred bytes mismatch content-length=19 handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000 transferred-bytes=0
ocis_1             | 2022-07-13T11:39:13Z ERR error finishing copying data to response error="http: wrote more than the declared Content-Length" handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000
ocis_1             | 2022-07-13T11:39:13Z ERR content length vs transferred bytes mismatch content-length=19 handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000 transferred-bytes=0
ocis_1             | 2022-07-13T11:39:13Z ERR error finishing copying data to response error="http: wrote more than the declared Content-Length" handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000
ocis_1             | 2022-07-13T11:39:13Z ERR content length vs transferred bytes mismatch content-length=19 handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000 transferred-bytes=0
ocis_1             | 2022-07-13T11:39:13Z ERR error finishing copying data to response error="http: wrote more than the declared Content-Length" handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000
ocis_1             | 2022-07-13T11:39:13Z ERR content length vs transferred bytes mismatch content-length=19 handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000 transferred-bytes=0
ocis_1             | 2022-07-13T11:39:13Z ERR error finishing copying data to response error="http: wrote more than the declared Content-Length" handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000
ocis_1             | 2022-07-13T11:39:13Z ERR content length vs transferred bytes mismatch content-length=19 handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000 transferred-bytes=0
ocis_1             | 2022-07-13T11:39:13Z ERR error finishing copying data to response error="http: wrote more than the declared Content-Length" handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000
ocis_1             | 2022-07-13T11:39:13Z ERR content length vs transferred bytes mismatch content-length=19 handler=get name=com.owncloud.web.ocdav path=/textFile.txt service=ocdav spaceid=1284d238-aa92-42ce-bdc4-0b0000009157$4c510ada-c86b-4815-8820-42cdf82c3d51 traceid=00000000000000000000000000000000 transferred-bytes=0

Upon accessing through UI the overwritten content is uploaded for the share-reciever Moss but for Einstein it gives a blank loading screen

tus.mp4

cc @individual-it @butonic

@individual-it individual-it changed the title apiWebdavUploadTUS/uploadToShare.feature related tests is failing intermittently in new dav TUS uploads might lead to data-loss in sharing conditions Jul 14, 2022
@individual-it
Copy link
Member

@butonic @micbar what to do with these tests? Skip them till the bug is fixed?

@micbar
Copy link
Contributor

micbar commented Jul 14, 2022

@butonic I really want to understand the underlying problem. Can you take a look?

@micbar micbar added the Priority:p2-high Escalation, on top of current planning, release blocker label Jul 14, 2022
@butonic
Copy link
Member

butonic commented Jul 14, 2022

👁️

@butonic butonic self-assigned this Jul 14, 2022
@micbar micbar added this to the 2.0.0 General Availability milestone Jul 14, 2022
@butonic
Copy link
Member

butonic commented Jul 14, 2022

weird ... I rebuild the steps in postman and let them run 100 times ... not a single error. maybe postman is toooo slow 🤔

@SwikritiT thx for the awesome detailed steps! Why are you sending a -H 'SHA1 fe990d2686a0fc86004efc31f5bf2475a45d4905' header? it does not contain a real header ... is there a typo? I'm not aware of a SHA1 header. Where did that come from?

Do you have a bash script I can use to try to reproduce this?

@butonic
Copy link
Member

butonic commented Jul 14, 2022

ok so the testsuite uses the checksum ... the header for that is OC-Checksum, but it is only read when doing a PUT upload. for tus the header should be Upload-Checksum: SHA1 fe990d2686a0fc86004efc31f5bf2475a45d4905. I'll add that to my postman test, maybe that triggers something...

@butonic
Copy link
Member

butonic commented Jul 14, 2022

after adding the Upload-Checksum: SHA1 fe990d2686a0fc86004efc31f5bf2475a45d4905 header the GET request fails .... pretty reliably ...

{"level":"error","service":"ocdav","name":"com.owncloud.web.ocdav","traceid":"00000000000000000000000000000000","path":"/users/4c510ada-c86b-4815-8820-42cdf82c3d51/textFile.txt","svc":"ocdav","handler":"get","content-length":19,"transferred-bytes":0,"time":"2022-07-14T16:41:38.300938824Z","message":"content length vs transferred bytes mismatch"}
{"level":"error","service":"ocdav","name":"com.owncloud.web.ocdav","traceid":"00000000000000000000000000000000","path":"/users/4c510ada-c86b-4815-8820-42cdf82c3d51/textFile.txt","svc":"ocdav","handler":"get","error":"http: wrote more than the declared Content-Length","time":"2022-07-14T16:41:38.398333979Z","message":"error finishing copying data to response"}

@butonic
Copy link
Member

butonic commented Jul 14, 2022

in the ocdav get.go we have:

	if info.Checksum != nil {
		w.Header().Set(net.HeaderOCChecksum, fmt.Sprintf("%s:%s", strings.ToUpper(string(storageprovider.GRPC2PKGXS(info.Checksum.Type))), info.Checksum.Sum))
	}
	var c int64
	if c, err = io.Copy(w, httpRes.Body); err != nil {
		log.Error().Err(err).Msg("error finishing copying data to response")
	}

when logging the error we have a maximally inconsistent state:

  1. info.Size is 16
  2. c is 0 the received body is actually empty
  3. httpRes.Header.Get(net.HeaderContentLength) is 19

something to dig into tomorrow ... might be a race where the download / get happens tooo quickly.

@butonic
Copy link
Member

butonic commented Jul 14, 2022

wat ... it no longer happens 🤯

@butonic
Copy link
Member

butonic commented Jul 14, 2022

ah, the last PATCH request was taking 164ms which seems to have prevented the glitch. aftor wiping .ocis (to get rid of ocd shares, which currently slow down the system significantly) the request took 64ms and now I am in the error case again.

@butonic
Copy link
Member

butonic commented Jul 14, 2022

so get.go first does a Stat, which returns size 16, the original size, then does an InitiateFileDownload, which returns a download url that carries the correct Content-Length 19 ... might be a cache invalidation problem ? ...

@SwikritiT
Copy link
Contributor Author

SwikritiT commented Jul 15, 2022

weird ... I rebuild the steps in postman and let them run 100 times ... not a single error. maybe postman is toooo slow thinking

@SwikritiT thx for the awesome detailed steps! Why are you sending a -H 'SHA1 fe990d2686a0fc86004efc31f5bf2475a45d4905' header? it does not contain a real header ... is there a typo? I'm not aware of a SHA1 header. Where did that come from?

Do you have a bash script I can use to try to reproduce this?

I had a script to reproduce it but seems like you've reproduced it already

@SwikritiT
Copy link
Contributor Author

SwikritiT commented Jul 15, 2022

TODO QA team after this issue is fixed || reva is bumped on ocis

@SwikritiT
Copy link
Contributor Author

Similar failure but not in sharing condition
Build: https://drone.owncloud.com/owncloud/ocis/13518/50/7

  Scenario Outline: upload a twice file in chunks with TUS and versions are available                                                      # /drone/src/oc10/testrunner/tests/acceptance/features/apiWebdavUploadTUS/uploadFile.feature:172
    Given using <dav_version> DAV path                                                                                                     # FeatureContext::usingOldOrNewDavPath()
    When user "Alice" uploads file with content "0123456789" in 10 chunks to "/myChunkedFile.txt" using the TUS protocol on the WebDAV API # TUSContext::userUploadsAFileWithContentInChunksUsingTus()
    And user "Alice" uploads file with content "01234" in 5 chunks to "/myChunkedFile.txt" using the TUS protocol on the WebDAV API        # TUSContext::userUploadsAFileWithContentInChunksUsingTus()
    Then the HTTP status code should be "200"                                                                                              # FeatureContext::thenTheHTTPStatusCodeShouldBe()
    And the version folder of file "/myChunkedFile.txt" for user "Alice" should contain "1" elements                                       # FilesVersionsContext::theVersionFolderOfFileShouldContainElements()
    And the content of file "/myChunkedFile.txt" for user "Alice" should be "01234"                                                        # FeatureContext::contentOfFileForUserShouldBe()

    Examples:
      | dav_version |
      | old         |
      | new         |
        cURL error 52: Empty reply from server (see https://curl.haxx.se/libcurl/c/libcurl-errors.html) for https://ocis-server:9200/remote.php/dav/files/Alice/myChunkedFile.txt (GuzzleHttp\Exception\ConnectException)
      | spaces      |

@butonic
Copy link
Member

butonic commented Jul 19, 2022

hm ... I cannot reproduce this ... this is my script:

#!/bin/bash

echo "initiating first upload"

location=$(curl --location --request POST 'https://cloud.ocis.test/remote.php/dav/files/admin' -k \
--header 'Tus-Resumable: 1.0.0' \
--header 'Upload-Length: 10' \
--header 'Upload-Metadata: filename bXlDaHVua2VkRmlsZS50eHQ=' \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' -I 2>|/dev/null | awk '/^location:/ { print $2 }' | sed -e 's/[[:cntrl:]]//') 

echo "uploading at $location"
for i in 0 1 2 3 4 5 6 7 8 9; do

curl --request PATCH ${location} -k \
--header 'Tus-Resumable: 1.0.0' \
--header 'Content-Type: application/offset+octet-stream' \
--header "Upload-Offset: $i" \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' \
--data-raw $i

done


echo "initiating second upload"

location=$(curl --location --request POST 'https://cloud.ocis.test/remote.php/dav/files/admin' -k \
--header 'Tus-Resumable: 1.0.0' \
--header 'Upload-Length: 5' \
--header 'Upload-Metadata: filename bXlDaHVua2VkRmlsZS50eHQ=' \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' -I 2>|/dev/null | awk '/^location:/ { print $2 }' | sed -e 's/[[:cntrl:]]//') 

echo "overwriting at $location"
for i in 0 1 2 3 4; do

curl --request PATCH ${location} -k \
--header 'Tus-Resumable: 1.0.0' \
--header 'Content-Type: application/offset+octet-stream' \
--header "Upload-Offset: $i" \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' \
--data-raw $i

done

echo 'looking up fileid'

fileid=$(curl --location --request PROPFIND 'https://cloud.ocis.test/remote.php/dav/files/admin/myChunkedFile.txt' -k \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' \
--header 'Content-Type: application/xml' \
--data-raw '<?xml version="1.0"?>
<d:propfind  xmlns:d="DAV:" xmlns:oc="http://owncloud.org/ns">
    <d:prop>
        <oc:fileid />
    </d:prop>
</d:propfind>' 2>|/dev/null | sed s@'.*.oc:fileid.\(.*\)..oc:fileid.*'@'\1'@)

echo 'fetching versions'

versions=$(curl --request PROPFIND "https://cloud.ocis.test/remote.php/dav/meta/${fileid}/v" -k \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' -s)

echo 'downloading'

content=$(curl --request GET "https://cloud.ocis.test/remote.php/dav/files/admin/myChunkedFile.txt" -k \
--header 'Authorization: Basic YWRtaW46YWRtaW4=' -s)

echo 'deleting'

curl --request DELETE "https://cloud.ocis.test/remote.php/dav/files/admin/myChunkedFile.txt" -k \
--header 'Authorization: Basic YWRtaW46YWRtaW4='

AFAICT curl does not get a reply for the download request ... maybe the ci run still has an ocis error in the logs 👀

@butonic
Copy link
Member

butonic commented Jul 19, 2022

The only place in the error level logs that actually has an error after the last chunk is uploaded looks like this:

[tusd] 2022/07/18 04:47:18 event="RequestIncoming" method="PATCH" path="/2cb1c7bd-d436-47a0-8b06-a0fbacf34d53" requestId="" 
[tusd] 2022/07/18 04:47:18 event="ChunkWriteStart" id="2cb1c7bd-d436-47a0-8b06-a0fbacf34d53" maxSize="1" offset="4" 
[tusd] 2022/07/18 04:47:18 event="ChunkWriteComplete" id="2cb1c7bd-d436-47a0-8b06-a0fbacf34d53" bytesWritten="1" 
[tusd] 2022/07/18 04:47:18 event="ResponseOutgoing" status="204" method="PATCH" path="/2cb1c7bd-d436-47a0-8b06-a0fbacf34d53" requestId="" 
{"level":"error","service":"storage-users","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"error: not found: folder","status":{"code":6,"message":"path not found when initiating upload","trace":"00000000000000000000000000000000"},"time":"2022-07-18T04:47:21.043460664Z","message":"failed to initiate upload"}
{"level":"error","service":"storage-users","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"error: not found: folder","status":{"code":6,"message":"path not found when initiating upload","trace":"00000000000000000000000000000000"},"time":"2022-07-18T04:47:24.743120436Z","message":"failed to initiate upload"}
{"level":"error","service":"storage-users","pkg":"rgrpc","traceid":"00000000000000000000000000000000","error":"error: not found: folder","status":{"code":6,"message":"path not found when initiating upload","trace":"00000000000000000000000000000000"},"time":"2022-07-18T04:47:28.71482827Z","message":"failed to initiate upload"}

but that would be a problem for the subsequest upload ... 🤔 and the path not found when initiating upload is only logged by the storageprovider whon the driver returns a not found error on InitiateUpload()

why is that line logged three times .... 🤔

@butonic
Copy link
Member

butonic commented Jul 19, 2022

hm also cannot reproduce against /dav/spaces

@butonic
Copy link
Member

butonic commented Jul 19, 2022

latest failure in https://drone.owncloud.com/owncloud/ocis/13609/51/7, apiWebdavUploadTUS/uploadToShare.feature:87, which is the original:

  Scenario Outline: Overwrite file to a received share folder                                                                                   # /drone/src/oc10/testrunner/tests/acceptance/features/apiWebdavUploadTUS/uploadToShare.feature:75
    Given using <dav_version> DAV path                                                                                                          # FeatureContext::usingOldOrNewDavPath()
    And user "Alice" has created folder "/FOLDER"                                                                                               # FeatureContext::userHasCreatedFolder()
    And user "Alice" has uploaded file with content "original content" to "/FOLDER/textfile.txt"                                                # FeatureContext::userHasUploadedAFileWithContentTo()
    And user "Alice" has shared folder "/FOLDER" with user "Brian"                                                                              # FeatureContext::userHasSharedFileWithUserUsingTheSharingApi()
    And user "Brian" has accepted share "/FOLDER" offered by user "Alice"                                                                       # FeatureContext::userHasReactedToShareOfferedBy()
    When user "Brian" uploads file with content "overwritten content" to "/Shares/FOLDER/textfile.txt" using the TUS protocol on the WebDAV API # TUSContext::userUploadsAFileWithContentToUsingTus()
    Then the HTTP status code should be "200"                                                                                                   # FeatureContext::thenTheHTTPStatusCodeShouldBe()
    And as "Alice" file "/FOLDER/textfile.txt" should exist                                                                                     # FeatureContext::asFileOrFolderShouldExist()
    And the content of file "/FOLDER/textfile.txt" for user "Alice" should be "overwritten content"                                             # FeatureContext::contentOfFileForUserShouldBe()

    Examples:
      | dav_version |
      | old         |
        cURL error 52: Empty reply from server (see https://curl.haxx.se/libcurl/c/libcurl-errors.html) for https://ocis-server:9200/remote.php/webdav/FOLDER/textfile.txt (GuzzleHttp\Exception\ConnectException)
      | new         |
      | spaces      |
        The downloaded content was expected to be 'overwritten content', but actually is 'original content'. HTTP status was 200
        Failed asserting that two strings are equal.
        --- Expected
        +++ Actual
        @@ @@
        -'overwritten content'
        +'original content'

@butonic
Copy link
Member

butonic commented Jul 19, 2022

ahhh the fix got only merged 35 min ago with #4181, reopen if it still occurrs

@butonic butonic closed this as completed Jul 19, 2022
@SwikritiT
Copy link
Contributor Author

TODO QA team after this issue is fixed || reva is bumped on ocis

I'll make a PR to unskip these tests

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Priority:p2-high Escalation, on top of current planning, release blocker QA:team Type:Bug
Projects
Archived in project
Development

No branches or pull requests

6 participants