search

cs3org / reva

WebDAV/gRPC/HTTP high performance server to link high level clients to storage backends
https://reva.link
Apache License 2.0
170 stars 113 forks source link

"error forwarding invite" error on accepting invitation request. #2948

Open shokri-navid opened 2 years ago

shokri-navid commented 2 years ago

I am using Owncloud Sciencemesh to share storage with other Owncloud users. generating the invitation token and authorization process works perfectly on the sender party side but in the acceptor party side when I try to accept the invitation I am getting these two errors:

2022-06-10 06:59:43.973 ERR ../../reva/internal/http/services/ocmd/reqres.go:62 > grpc forward invite request failed error="error forwarding invite" pid=6 pkg=rhttp traceid=3c12c8cda3f3b58c7a5fe6c8fe014db0 2022-06-10 06:59:43.974 ERR ../../reva/internal/http/interceptors/log/log.go:112 > http end="10/Jun/2022:06:59:43 +0000" host=172.18.0.7 method=POST pid=6 pkg=rhttp proto=HTTP/2.0 size=79 start="10/Jun/2022:06:59:43 +0000" status=500 time_ns=105106001 traceid=3c12c8cda3f3b58c7a5fe6c8fe014db0 uri=/ocm/invites/forward url=/ocm/invites/forward

michielbdejong commented 2 years ago

If you see that error on your revaoc2.docker then there is probably a more informative error message on your revaoc1.docker (for instance, maybe the user was already added, or the token is invalid).

shokri-navid commented 2 years ago

I insert whole reva logs of invitation acceptor (marie) party:

2022-06-10 10:54:44.136 WRN ../../reva/internal/http/interceptors/auth/auth.go:205 > core access token not set pid=7 pkg=rhttp traceid=cff79cef436cea177f2da589b0af3480

2022-06-10 10:54:44.136 DBG ../../reva/internal/http/interceptors/auth/auth.go:218 > credentials obtained from credential strategy: type: basic, client_id: marie pid=7 pkg=rhttp traceid=cff79cef436cea177f2da589b0af3480

2022-06-10 10:54:44.137 DBG ../../reva/internal/http/interceptors/auth/auth.go:244 > AuthenticateRequest: type: basic, client_id: marie against revaoc2.docker:19000 pid=7 pkg=rhttp traceid=cff79cef436cea177f2da589b0af3480

2022-06-10 10:54:44.138 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/Authenticate pid=7 pkg=rgrpc traceid=9c4034e67389b248f5c2a9ff4a091c2b

2022-06-10 10:54:44.139 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.auth.registry.v1beta1.RegistryAPI/GetAuthProviders pid=7 pkg=rgrpc traceid=433f113ea47cbc79e34d011900aa90bb

2022-06-10 10:54:44.139 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:50012 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=350635 traceid=433f113ea47cbc79e34d011900aa90bb uri=/cs3.auth.registry.v1beta1.RegistryAPI/GetAuthProviders user-agent=grpc-go/1.45.0

2022-06-10 10:54:44.14 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.auth.provider.v1beta1.ProviderAPI/Authenticate pid=7 pkg=rgrpc traceid=3014c59d630ec1671b1e7250a3ceea98

2022-06-10 10:54:44.14 INF ../../reva/pkg/auth/manager/nextcloud/nextcloud.go:170 > Authenticate marie {"clientID":"marie","clientSecret":"OcU1kTJgiyBjTGM3eKpvjEcyxxFvgqOX"} pid=7 pkg=rgrpc traceid=3014c59d630ec1671b1e7250a3ceea98

2022-06-10 10:54:44.14 INF ../../reva/pkg/auth/manager/nextcloud/nextcloud.go:124 > am.do https://oc2.docker/index.php/apps/sciencemesh/~marie/api/auth/Authenticate {"clientID":"marie","clientSecret":"OcU1kTJgiyBjTGM3eKpvjEcyxxFvgqOX"} shared-secret-2 pid=7 pkg=rgrpc traceid=3014c59d630ec1671b1e7250a3ceea98

2022-06-10 10:54:44.239 INF ../../reva/pkg/auth/manager/nextcloud/nextcloud.go:143 > am.do response 200 {"user":{"id":{"idp":"https:\/\/revaoc2.docker\/","opaque_id":"marie"},"display_name":"marie","email":null,"type":1},"scopes":{"user":{"resource":{"decoder":"json","value":"eyJyZXNvdXJjZV9pZCI6eyJzdG9yYWdlX2lkIjoic3RvcmFnZS1pZCIsIm9wYXF1ZV9pZCI6Im9wYXF1ZS1pZCJ9LCJwYXRoIjoic29tZS9maWxlL3BhdGgudHh0In0="},"role":1}}} pid=7 pkg=rgrpc traceid=3014c59d630ec1671b1e7250a3ceea98

2022-06-10 10:54:44.24 INF ../../reva/internal/grpc/services/authprovider/authprovider.go:141 > user idp:"https://revaoc2.docker/" opaque_id:"marie" authenticated pid=7 pkg=rgrpc traceid=3014c59d630ec1671b1e7250a3ceea98 2022-06-10 10:54:44.24 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:50014 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=100111717 traceid=3014c59d630ec1671b1e7250a3ceea98 uri=/cs3.auth.provider.v1beta1.ProviderAPI/Authenticate user-agent=grpc-go/1.45.0

2022-06-10 10:54:44.242 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:50020 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=264030 traceid=b3fa0ee66056a39ae9ab11cf4aec48c2 uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProviders user-agent=grpc-go/1.45.0

2022-06-10 10:54:44.245 INF ../../reva/pkg/storage/fs/nextcloud/nextcloud.go:212 > nc.do req https://oc2.docker/index.php/apps/sciencemesh/~marie/api/storage/CreateStorageSpace {"opaque":{"map":{"space_id":{"decoder":"plain","value":"bWFyaWU="}}},"owner":{"id":{"idp":"https://revaoc2.docker/","opaque_id":"marie"},"display_name":"marie"},"type":"personal","name":"marie"} pid=7 pkg=rgrpc traceid=67779cf733744c95633353589fb636a9

2022-06-10 10:54:44.308 INF ../../reva/pkg/storage/fs/nextcloud/nextcloud.go:231 > nc.do res https://oc2.docker/index.php/apps/sciencemesh/~marie/api/storage/CreateStorageSpace {"status":{"code":1,"trace":"00000000000000000000000000000000"},"storage_space":{"opaque":{"map":{"bar":{"value":"c2FtYQ=="},"foo":{"value":"c2FtYQ=="}}},"id":{"opaque_id":"some-opaque-storage-space-id"},"owner":{"id":{"idp":"some-idp","opaque_id":"some-opaque-user-id","type":1}},"root":{"storage_id":"some-storage-id","opaque_id":"some-opaque-root-id"},"name":"My Storage Space","quota":{"quota_max_bytes":456,"quota_max_files":123},"space_type":"home","mtime":{"seconds":1234567890}}} pid=7 pkg=rgrpc traceid=67779cf733744c95633353589fb636a9

2022-06-10 10:54:44.31 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:50022 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=64649537 traceid=67779cf733744c95633353589fb636a9 uri=/cs3.storage.provider.v1beta1.ProviderAPI/CreateStorageSpace user-agent=grpc-go/1.45.0

2022-06-10 10:54:44.31 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:49622 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=172365022 traceid=9c4034e67389b248f5c2a9ff4a091c2b uri=/cs3.gateway.v1beta1.GatewayAPI/Authenticate user-agent=grpc-go/1.45.0

2022-06-10 10:54:44.31 INF ../../reva/internal/http/interceptors/auth/auth.go:258 > core access token generated pid=7 pkg=rhttp traceid=cff79cef436cea177f2da589b0af3480 2022-06-10 10:54:44.311 DBG ../../reva/pkg/rhttp/rhttp.go:242 > http routing: head=ocm tail=/invites/forward svc=ocm pid=7 pkg=rhttp

2022-06-10 10:54:44.311 DBG ../../reva/internal/http/services/ocmd/ocmd.go:113 > http routing head=invites pid=7 pkg=rhttp tail=/forward traceid=cff79cef436cea177f2da589b0af3480

2022-06-10 10:54:44.311 DBG ../../reva/internal/http/services/ocmd/invites.go:61 > http routing head=forward pid=7 pkg=rhttp tail=/ traceid=cff79cef436cea177f2da589b0af3480

2022-06-10 10:54:44.311 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/GetInfoByDomain pid=7 pkg=rgrpc traceid=78ff201701034f5a2b9523d69e1b1e65

2022-06-10 10:54:44.313 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:50026 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=483560 traceid=516709f347772251c8170da883bc28d0 uri=/cs3.ocm.provider.v1beta1.ProviderAPI/GetInfoByDomain user-agent=

2022-06-10 10:54:44.313 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:49622 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=1765266 traceid=78ff201701034f5a2b9523d69e1b1e65 uri=/cs3.gateway.v1beta1.GatewayAPI/GetInfoByDomain user-agent=

2022-06-10 10:54:44.32 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/ForwardInvite pid=7 pkg=rgrpc traceid=1dfd2f083741e9cb425ff603eb28282b

2022-06-10 10:54:44.337 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:50028 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=15862991 traceid=773001e296c0254064790820b1b15668 uri=/cs3.ocm.invite.v1beta1.InviteAPI/ForwardInvite user-agent=

2022-06-10 10:54:44.337 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="10/Jun/2022:10:54:44 +0000" from=tcp://127.0.0.1:49622 pid=7 pkg=rgrpc start="10/Jun/2022:10:54:44 +0000" time_ns=17304271 traceid=1dfd2f083741e9cb425ff603eb28282b uri=/cs3.gateway.v1beta1.GatewayAPI/ForwardInvite user-agent=

2022-06-10 10:54:44.338 ERR ../../reva/internal/http/services/ocmd/reqres.go:62 > grpc forward invite request failed error="error forwarding invite" pid=7 pkg=rhttp traceid=cff79cef436cea177f2da589b0af3480

2022-06-10 10:54:44.338 ERR ../../reva/internal/http/interceptors/log/log.go:112 > http end="10/Jun/2022:10:54:44 +0000" host=172.20.0.6 method=POST pid=7 pkg=rhttp proto=HTTP/2.0 size=79 start="10/Jun/2022:10:54:44 +0000" status=500 time_ns=201352241 traceid=cff79cef436cea177f2da589b0af3480 uri=/ocm/invites/forward url=/ocm/invites/forward

and this is invitation sender (einstein) reva log:

2022-06-14 08:11:02.548 INF ../../reva/internal/http/interceptors/auth/auth.go:172 > skipping auth check for: /ocm/invites/accept pid=7 pkg=rhttp traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.548 WRN ../../reva/internal/http/interceptors/auth/auth.go:205 > core access token not set pid=7 pkg=rhttp traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.548 DBG ../../reva/internal/http/interceptors/auth/auth.go:214 > error retrieving credentials error="no basic auth provided" pid=7 pkg=rhttp traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.548 DBG ../../reva/internal/http/interceptors/auth/auth.go:214 > error retrieving credentials error="no bearer auth provided" pid=7 pkg=rhttp traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.548 INF ../../reva/internal/http/interceptors/providerauthorizer/providerauthorizer.go:83 > skipping provider authorizer check for: /ocm/invites/accept pid=7 pkg=rhttp traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.549 DBG ../../reva/pkg/rhttp/rhttp.go:242 > http routing: head=ocm tail=/invites/accept svc=ocm pid=7 pkg=rhttp 2022-06-14 08:11:02.549 DBG ../../reva/internal/http/services/ocmd/ocmd.go:113 > http routing head=invites pid=7 pkg=rhttp tail=/accept traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.549 DBG ../../reva/internal/http/services/ocmd/invites.go:61 > http routing head=accept pid=7 pkg=rhttp tail=/ traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.55 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/IsProviderAllowed pid=7 pkg=rgrpc traceid=b93f5d21c4975a67ac99801e4e4596b4 2022-06-14 08:11:02.551 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.ocm.provider.v1beta1.ProviderAPI/IsProviderAllowed pid=7 pkg=rgrpc traceid=2ab68eddc3b1a41887d18c57f67bd726 2022-06-14 08:11:02.552 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="14/Jun/2022:08:11:02 +0000" from=tcp://127.0.0.1:41824 pid=7 pkg=rgrpc start="14/Jun/2022:08:11:02 +0000" time_ns=1171574 traceid=2ab68eddc3b1a41887d18c57f67bd726 uri=/cs3.ocm.provider.v1beta1.ProviderAPI/IsProviderAllowed user-agent=grpc-go/1.45.0 2022-06-14 08:11:02.553 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="14/Jun/2022:08:11:02 +0000" from=tcp://127.0.0.1:41388 pid=7 pkg=rgrpc start="14/Jun/2022:08:11:02 +0000" time_ns=3382556 traceid=b93f5d21c4975a67ac99801e4e4596b4 uri=/cs3.gateway.v1beta1.GatewayAPI/IsProviderAllowed user-agent=grpc-go/1.45.0 2022-06-14 08:11:02.555 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/AcceptInvite pid=7 pkg=rgrpc traceid=ad46a595b97b3910b62d9d158add20e5 2022-06-14 08:11:02.556 DBG ../../reva/internal/grpc/interceptors/auth/auth.go:96 > skipping auth method=/cs3.ocm.invite.v1beta1.InviteAPI/AcceptInvite pid=7 pkg=rgrpc traceid=3bfa4fcd7e6e4b0d0b0da7cb3b550fa2 2022-06-14 08:11:02.557 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="14/Jun/2022:08:11:02 +0000" from=tcp://127.0.0.1:41768 pid=7 pkg=rgrpc start="14/Jun/2022:08:11:02 +0000" time_ns=1028608 traceid=3bfa4fcd7e6e4b0d0b0da7cb3b550fa2 uri=/cs3.ocm.invite.v1beta1.InviteAPI/AcceptInvite user-agent=grpc-go/1.45.0 2022-06-14 08:11:02.558 DBG ../../reva/internal/grpc/interceptors/log/log.go:66 > unary code=OK end="14/Jun/2022:08:11:02 +0000" from=tcp://127.0.0.1:41388 pid=7 pkg=rgrpc start="14/Jun/2022:08:11:02 +0000" time_ns=3195079 traceid=ad46a595b97b3910b62d9d158add20e5 uri=/cs3.gateway.v1beta1.GatewayAPI/AcceptInvite user-agent=grpc-go/1.45.0 2022-06-14 08:11:02.56 ERR ../../reva/internal/http/services/ocmd/reqres.go:62 > grpc accept invite request failed error="error accepting invite" pid=7 pkg=rhttp traceid=8f7b11600ef6bc0388ba3cb613b68f4a 2022-06-14 08:11:02.56 ERR ../../reva/internal/http/interceptors/log/log.go:112 > http end="14/Jun/2022:08:11:02 +0000" host=172.18.0.8 method=POST pid=7 pkg=rhttp proto=HTTP/2.0 size=78 start="14/Jun/2022:08:11:02 +0000" status=500 time_ns=12112157 traceid=8f7b11600ef6bc0388ba3cb613b68f4a uri=/ocm/invites/accept url=/ocm/invites/accept

michielbdejong commented 2 years ago

That still looks like the logs of revaoc2.docker (start-to-Revaoc in https://github.com/cs3org/ocm-test-suite/tree/main/scripts), not revaoc1.docker (start-from-Revaoc there)?

  1. First, oc2.docker makes the /ocm/invites/forward call to revaoc2.docker, and then
  2. revaoc2.docker makes the /ocm/invites/accept call to revaoc1.docker.

I think the error is probably happening during that second step.

michielbdejong commented 2 years ago

Thanks for adding the revaoc1.docker logs! Indeed, there is a matching "error accepting invite" error there but unfortunately it doesn't provide a lot of detail. I'll try to reproduce this issue.

michielbdejong commented 2 years ago

I couldn't reproduce the error on ocmhost.pondersource.com - there I see

2022-06-14 08:36:55.966 INF ../../reva/internal/http/services/ocmd/invites.go:201 > Invite forwarded to: revaoc1.docker pid=6 pkg=rhttp traceid=db436690a13c96f3821be31988f0f4e6

let's look at it together in a screensharing session!