[QA] Upload to ocis-1.0.0-rc6 on eos fails #997

jnweiger · 2020-12-01T14:15:10Z

Deployed ocis-1.0.0-rc6 via hetzner-deploy/make_ocis_eos_compose_test.sh

Upload via web interface fails with

Upload via desktop client fails with
12/1/20 3:09:31 PM, stay_home_mainpost.de_Sven_Hoppe.jpg, testpilotcloud5,Server replied "500 Internal Server Error" to "POST https://168.119.152.147:9200/remote.php/dav/files/richard/" (skipped due to earlier error, trying again in 11 second(s))
12/1/20 3:08:01 PM, README.md, testpilotcloud3,Server replied "500 Internal Server Error" to "POST https://ocis-1-0-0-rc6-eos.jw-qa.owncloud.works:9200/remote.php/dav/files/einstein/"

serve rlog snippet:

ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:49076 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=57923752 traceid=68edb49df3f19b83ac8beaaca9513f65 uri=/cs3.storage.provider.v1beta1.ProviderAPI/CreateHome user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:48854 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=63892872 traceid=68edb49df3f19b83ac8beaaca9513f65 uri=/cs3.gateway.v1beta1.GatewayAPI/CreateHome user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z DBG director found path=/remote.php/dav/files/richard/ policy=reva prefix=/remote.php/ routeType=prefix service=proxy
ocis          | 2020-12-01T14:09:16Z INF access-log from=2.247.255.175:52087 method=POST path=/remote.php/dav/files/richard/ service=proxy
ocis          | 2020-12-01T14:09:16Z DBG access token is already provided pkg=rhttp service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG http routing: head= tail=/remote.php/dav/files/richard svc=root pkg=rhttp service=storage
ocis          | 2020-12-01T14:09:16Z DBG http routing head=remote.php pkg=rhttp service=storage tail=/dav/files/richard traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/Stat pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG gateway: split: parts[1]:stay_home_mainpost.de_Sven_Hoppe.jpg != shareFolder:Shares pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:48960 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=125611 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProvider user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z INF eos: get md for ref:path:"/stay_home_mainpost.de_Sven_Hoppe.jpg"  pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG eos: wrap external=/stay_home_mainpost.de_Sven_Hoppe.jpg internal=/eos/dockertest/reva/users/9/932b4540-8d16-481e-8ef4-588e4b6b151c/stay_home_mainpost.de_Sven_Hoppe.jpg pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z INF eos cmd args="[/usr/bin/eos -r 20002 30000 file info /eos/dockertest/reva/users/9/932b4540-8d16-481e-8ef4-588e4b6b151c/stay_home_mainpost.de_Sven_Hoppe.jpg -m --comment 9c1b21f12839b9f8a74e47c1b05fbc12]" env=[EOS_MGM_URL=root://mgm-master.testnet:1094] err="error: cannot stat '/eos/dockertest/reva/users/9/932b4540-8d16-481e-8ef4-588e4b6b151c/stay_home_mainpost.de_Sven_Hoppe.jpg'\n (errc=2) (No such file or directory)\n" exit=2 pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z WRN root/go/pkg/mod/github.com/cs3org/reva@v1.4.1-0.20201130061320-ac85e68e0600/internal/grpc/services/storageprovider/storageprovider.go:528 > path not found when stating pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:49076 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=33784355 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/cs3.storage.provider.v1beta1.ProviderAPI/Stat user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:48952 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=38915761 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/cs3.gateway.v1beta1.GatewayAPI/Stat user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z DBG skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/InitiateFileUpload pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:48960 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=118544 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProvider user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z INF file upload data-server=http://localhost:9155/data/simple/stay_home_mainpost.de_Sven_Hoppe.jpg fn=/home/stay_home_mainpost.de_Sven_Hoppe.jpg pkg=rgrpc service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12 xs="map[md5:100 unset:1000]"
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:49076 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=263930 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/cs3.storage.provider.v1beta1.ProviderAPI/InitiateFileUpload user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:16Z DBG unary code=OK end="01/Dec/2020:14:09:16 +0000" from=tcp://127.0.0.1:48952 pkg=rgrpc service=storage start="01/Dec/2020:14:09:16 +0000" time_ns=2340784 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/cs3.gateway.v1beta1.GatewayAPI/InitiateFileUpload user-agent=grpc-go/1.26.0
ocis          | 2020-12-01T14:09:17Z ERR error doing GET request to data service error="Patch \"\": unsupported protocol scheme \"\"" pkg=rhttp service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:17Z ERR http end="01/Dec/2020:14:09:17 +0000" host=127.0.0.1 method=POST pkg=rhttp proto=HTTP/1.1 service=storage size=0 start="01/Dec/2020:14:09:16 +0000" status=500 time_ns=790488105 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/remote.php/dav/files/richard/ url=/remote.php/dav/files/richard/
ocis          | 2020-12-01T14:09:23Z DBG cache hit for userinfo claims={"email":"richard@example.org","family_name":"richard","iss":"https://168.119.152.147:9200","name":"richard","preferred_username":"richard","sub":"AakjANunnz1vghDbXQZWiT2S6U6xDI7alM5IKAnQOZzVo8GkEqTiHoJlzQXFg45GtB1H0TD_KLJiDWDSkRMiOg@konnect"} service=proxy

The text was updated successfully, but these errors were encountered:

jnweiger · 2020-12-01T15:26:23Z

Also reproduced locally with

env OCIS_VERSION=v1.0.0-rc6 BRANCH=v1.0.0-rc6 EOS_OCIS_TAG=1.0.0-rc6 docker-compose -f docker-compose-eos-test.yml up -d

https://localhost:9200

ocis.logs.zip

butonic · 2020-12-01T18:26:31Z

The last lines show the problem:

ocis          | 2020-12-01T14:09:17Z ERR error doing GET request to data service error="Patch \"\": unsupported protocol scheme \"\"" pkg=rhttp service=storage traceid=9c1b21f12839b9f8a74e47c1b05fbc12
ocis          | 2020-12-01T14:09:17Z ERR http end="01/Dec/2020:14:09:17 +0000" host=127.0.0.1 method=POST pkg=rhttp proto=HTTP/1.1 service=storage size=0 start="01/Dec/2020:14:09:16 +0000" status=500 time_ns=790488105 traceid=9c1b21f12839b9f8a74e47c1b05fbc12 uri=/remote.php/dav/files/richard/ url=/remote.php/dav/files/richard/

The WRN in the middle can be ignored. There is always a stat request to check if the file exists because webdav requires different http response codes.

Need to dig into the unsupported protocol scheme error.

butonic · 2020-12-01T18:31:21Z

Hm, seems the data provider url is empty... Wtf... Likely a config issue... Need to check the env vars...

butonic · 2020-12-01T18:32:29Z

@jnweiger what is the content of hetzner-deploy/make_ocis_eos_compose_test.sh ... With credentials redacted?

butonic · 2020-12-01T19:41:34Z

the error doing GET request to data service log line originates in https://github.com/cs3org/reva/blob/b8759471f079f231c8a5a48797fdba771cd1729f/internal/http/services/owncloud/ocdav/tus.go#L221

It cannot be the one from the datagateway, because we would see a target log line from https://github.com/cs3org/reva/blob/86b255003b34533f99e34d5f765c6245b41526f0/internal/http/services/datagateway/datagateway.go#L219

so our ep uset to create the request in https://github.com/cs3org/reva/blob/b8759471f079f231c8a5a48797fdba771cd1729f/internal/http/services/owncloud/ocdav/tus.go#L203 is empty.

which brings me to this recently introduced for loop: https://github.com/cs3org/reva/blame/b8759471f079f231c8a5a48797fdba771cd1729f/internal/http/services/owncloud/ocdav/tus.go#L171-L177

which is part of a PR that refactors the upload: cs3org/reva#1321

@ishank011 something broke there

butonic · 2020-12-01T19:54:55Z

ok ... tus has been deliberately disabled for eos ... https://github.com/cs3org/reva/pull/1321/files#diff-360b3e8fed176d54eac93c1c3671153bb1516cb66b0debb4c2885c271e5296d9R78-R80

@ishank011 @labkode can you elaborate what is not working with tus? AFAICT we should be able to map the existing upload mechanisms to it. Data transfers package #1321 does not mention reasons. I found Enable different data transfer protocolos #1266, which talks about maturity. (TUS as a protocol is mature ... I was under the impression that we wanted to get rid of having to store chunks on the frontend servers before sending them to eos).

Maybe clarify in Review EOS TUS implementation and understand interplay with tusd lib interfaces #703

jnweiger · 2020-12-01T22:16:52Z

The capabilities contain
curl -k -u XXXXXX:XXXXXX 'https://localhost:9200/ocs/v1.php/cloud/capabilities?format=json' | jq | less

        "files": {
          "privateLinks": false,
          "bigfilechunking": false,
          "undelete": true,
          "versioning": true,
          "blacklisted_files": [],
          "tus_support": {
            "version": "1.0.0",
            "resumable": "1.0.0",
            "extension": "creation,creation-with-upload",
            "max_chunk_size": 0,
            "http_method_override": ""
          }
        },
        "dav": {
          "chunking": "",

Server started with

env STORAGE_FRONTEND_UPLOAD_DISABLE_TUS=true OCIS_VERSION=v1.0.0-rc6 BRANCH=v1.0.0-rc6 EOS_OCIS_TAG=1.0.0-rc6 docker-compose -f docker-compose-eos-test.yml up -d

has

        "files": {
          "privateLinks": false,
          "bigfilechunking": false,
          "undelete": true,
          "versioning": true,
          "blacklisted_files": [],
          "tus_support": {
            "version": "1.0.0",
            "resumable": "1.0.0",
            "extension": "creation,creation-with-upload",
            "max_chunk_size": 0,
            "http_method_override": ""
          }
        },
        "dav": {
          "chunking": "",

It does not seem to make a difference for me.

butonic · 2020-12-01T22:54:43Z

@jnweiger setting the env is not good enough. the STORAGE_FRONTEND_UPLOAD_DISABLE_TUS=true needs to either be set in the docker-compose-eos-test.yml under environment , in an env-file or you need to pass it as an -e option: https://docs.docker.com/compose/environment-variables/#set-environment-variables-with-docker-compose-run

jnweiger · 2020-12-01T23:15:46Z

I am trying to cover all of the known environmenty places. Except for -e -- that option only exists with docker run, not with docker-compose, afaik.

env | grep TUS
STORAGE_FRONTEND_UPLOAD_DISABLE_TUS=true
grep TUS .env
STORAGE_FRONTEND_UPLOAD_DISABLE_TUS=true
grep TUS config/eos-docker.env 
STORAGE_FRONTEND_UPLOAD_DISABLE_TUS=true
grep -B1 TUS docker-compose-eos-test.yml 
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"
--
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"
--
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"
--
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"
--
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"
--
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"
--
    environment:
      STORAGE_FRONTEND_UPLOAD_DISABLE_TUS: "true"

Anything else? It is insane already, but still has no effect.

ishank011 · 2020-12-02T08:31:33Z

@butonic @jnweiger for the reva version you're using, setting this env variable should be good enough. But in a recent commit cs3org/reva#1331, I modified the boolean capabilities parameter to a string one using which we can specify the chunking protocol https://github.com/cs3org/reva/blob/master/internal/http/services/owncloud/ocs/config/config.go#L32. The default value is tus and the other supported values are v1 and ng.

jnweiger · 2020-12-02T08:59:31Z

@butonic oops, are we using an old reva version?

jnweiger · 2020-12-04T17:20:15Z

Workaround: start the client with
export OWNCLOUD_NO_TUS=1

exalate-issue-sync · 2020-12-07T15:09:25Z

Michael Barz commented: We need to clarify TUS with EOS storage with @labkode

stale · 2021-03-30T18:05:47Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 10 days if no further activity occurs. Thank you for your contributions.

jnweiger assigned kulmann and butonic Dec 1, 2020

ishank011 mentioned this issue Dec 2, 2020

Review EOS TUS implementation and understand interplay with tusd lib interfaces cs3org/reva#703

Open

jnweiger mentioned this issue Dec 2, 2020

Cannot reliably determine ocis version #310

Closed

jnweiger mentioned this issue Dec 4, 2020

[QA] client should fallback to NG or V1, when TUS fails owncloud/client#8286

Closed

exalate-issue-sync bot added the p3-medium label Dec 7, 2020

refs added Interaction:Discussion Interaction:Needs-help Asking some hints to engineering when the issue can't be reproduced Category:Defect Existing functionality is not working as expected Topic:TUS labels Jan 13, 2021

settings bot removed the Topic:TUS label Jan 29, 2021

stale bot added the Status:Stale label Mar 30, 2021

settings bot removed the p3-medium label Apr 7, 2021

stale bot closed this as completed Apr 17, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[QA] Upload to ocis-1.0.0-rc6 on eos fails #997

[QA] Upload to ocis-1.0.0-rc6 on eos fails #997

jnweiger commented Dec 1, 2020 •

edited by butonic

jnweiger commented Dec 1, 2020 •

edited by refs

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

jnweiger commented Dec 1, 2020 •

edited

butonic commented Dec 1, 2020

jnweiger commented Dec 1, 2020 •

edited

ishank011 commented Dec 2, 2020

jnweiger commented Dec 2, 2020

jnweiger commented Dec 4, 2020 •

edited

exalate-issue-sync bot commented Dec 7, 2020

stale bot commented Mar 30, 2021

[QA] Upload to ocis-1.0.0-rc6 on eos fails #997

[QA] Upload to ocis-1.0.0-rc6 on eos fails #997

Comments

jnweiger commented Dec 1, 2020 • edited by butonic

jnweiger commented Dec 1, 2020 • edited by refs

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

butonic commented Dec 1, 2020

jnweiger commented Dec 1, 2020 • edited

butonic commented Dec 1, 2020

jnweiger commented Dec 1, 2020 • edited

ishank011 commented Dec 2, 2020

jnweiger commented Dec 2, 2020

jnweiger commented Dec 4, 2020 • edited

exalate-issue-sync bot commented Dec 7, 2020

stale bot commented Mar 30, 2021

jnweiger commented Dec 1, 2020 •

edited by butonic

jnweiger commented Dec 1, 2020 •

edited by refs

jnweiger commented Dec 1, 2020 •

edited

jnweiger commented Dec 1, 2020 •

edited

jnweiger commented Dec 4, 2020 •

edited