ListAccount is forbidden randomly #820

dpakach · 2020-11-09T08:00:27Z

Sometimes the request to list the account gives a forbidden response after the user tries to list their own account

Note this issue only occurs randomly, not every time

❯ curl https://localhost:9200/ocs/v1.php/cloud/users/einstein -u einstein:relativity -k | xmllint --format -
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   296  100   296    0     0   4417      0 --:--:-- --:--:-- --:--:--  4417
<?xml version="1.0" encoding="UTF-8"?>
<ocs>
  <meta>
    <status>error</status>
    <statuscode>996</statuscode>
    <message>{"id":"com.owncloud.api.accounts","code":403,"detail":"no permission for ListAccounts","status":"Forbidden"}</message>
  </meta>
</ocs>

This issue gets fixed after restarting the server

❯ curl https://localhost:9200/ocs/v1.php/cloud/users/einstein -u einstein:relativity -k | xmllint --format -
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   538  100   538    0     0   1368      0 --:--:-- --:--:-- --:--:--  1365
<?xml version="1.0" encoding="UTF-8"?>
<ocs>
  <meta>
    <status>ok</status>
    <statuscode>100</statuscode>
    <message>OK</message>
  </meta>
  <data>
    <enabled>true</enabled>
    <id>4c510ada-c86b-4815-8820-42cdf82c3d51</id>
    <display-name>Albert Einstein</display-name>
    <displayname>Albert Einstein</displayname>
    <email>[email protected]</email>
    <quota>
      <free>2840756224000</free>
      <used>5059416668</used>
      <total>2845815640668</total>
      <relative>0.18</relative>
      <definition>default</definition>
    </quota>
    <uidnumber>20000</uidnumber>
    <gidnumber>30000</gidnumber>
  </data>
</ocs>

Server logs when failing

2020-11-09T13:41:32+05:45 WRN basic auth enabled, use only for testing or development service=proxy
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=de4e04e8664044e753bee810fc080393
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=36 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=291798 traceid=de4e04e8664044e753bee810fc080393 uri=/data/index.cs3/unique.github.com.owncloud.ocis.accounts.pkg.proto.v0.Account.OnPremisesSamAccountName/einstein url=/data/index.cs3/unique.github.com.owncloud.ocis.accounts.pkg.proto.v0.Account.OnPremisesSamAccountName/einstein
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=67f8e54f88924577399187af3c9395f0
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=584 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=245901 traceid=67f8e54f88924577399187af3c9395f0 uri=/data/accounts/4c510ada-c86b-4815-8820-42cdf82c3d51 url=/data/accounts/4c510ada-c86b-4815-8820-42cdf82c3d51
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=feb094445c9ecf0ad92fa9d0333a9a7b
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=584 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=177808 traceid=feb094445c9ecf0ad92fa9d0333a9a7b uri=/data/accounts/4c510ada-c86b-4815-8820-42cdf82c3d51 url=/data/accounts/4c510ada-c86b-4815-8820-42cdf82c3d51
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=4107ad4b69f385429b7001bd60b0bdf2
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=326 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=134727 traceid=4107ad4b69f385429b7001bd60b0bdf2 uri=/data/groups/509a9dcd-bb37-4f4f-a01a-19dca27d9cfa url=/data/groups/509a9dcd-bb37-4f4f-a01a-19dca27d9cfa
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=da7a9eaf3b178a1c7ad61e699322f175
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=198 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=130543 traceid=da7a9eaf3b178a1c7ad61e699322f175 uri=/data/groups/6040aa17-9c64-4fef-9bd0-77234d71bad0 url=/data/groups/6040aa17-9c64-4fef-9bd0-77234d71bad0
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=e3e779806cc68141507c2e6217ccc1cf
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=196 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=116235 traceid=e3e779806cc68141507c2e6217ccc1cf uri=/data/groups/dd58e5ec-842e-498b-8800-61f2ec6f911f url=/data/groups/dd58e5ec-842e-498b-8800-61f2ec6f911f
2020-11-09T13:41:32+05:45 INF access token is already provided pkg=rhttp service=storage traceid=c73f3a4da9404d323ec053e074343a19
2020-11-09T13:41:32+05:45 INF http end="09/Nov/2020:13:41:32 +0545" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=290 start="09/Nov/2020:13:41:32 +0545" status=200 time_ns=96626 traceid=c73f3a4da9404d323ec053e074343a19 uri=/data/groups/262982c1-2362-4afa-bfdf-8cbfef64a06e url=/data/groups/262982c1-2362-4afa-bfdf-8cbfef64a06e
2020-11-09T13:41:32+05:45 INF unary code=OK end="09/Nov/2020:13:41:32 +0545" from=tcp://127.0.0.1:51340 pkg=rgrpc service=storage start="09/Nov/2020:13:41:32 +0545" time_ns=92323 traceid=78ee20a0d00932bd65162c4b26f35a5f uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProvider user-agent=grpc-go/1.26.0
2020-11-09T13:41:32+05:45 INF unary code=OK end="09/Nov/2020:13:41:32 +0545" from=tcp://127.0.0.1:35158 pkg=rgrpc service=storage start="09/Nov/2020:13:41:32 +0545" time_ns=532972 traceid=78ee20a0d00932bd65162c4b26f35a5f uri=/cs3.storage.provider.v1beta1.ProviderAPI/CreateHome user-agent=grpc-go/1.26.0
2020-11-09T13:41:32+05:45 INF unary code=OK end="09/Nov/2020:13:41:32 +0545" from=tcp://127.0.0.1:51322 pkg=rgrpc service=storage start="09/Nov/2020:13:41:32 +0545" time_ns=1760565 traceid=78ee20a0d00932bd65162c4b26f35a5f uri=/cs3.gateway.v1beta1.GatewayAPI/CreateHome user-agent=grpc-go/1.26.0
2020-11-09T13:41:32+05:45 ERR could not get account for user error="{\"id\":\"com.owncloud.api.accounts\",\"code\":403,\"detail\":\"no permission for ListAccounts\",\"status\":\"Forbidden\"}" service=ocs userid=einstein

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

refs · 2020-11-09T08:37:15Z

In order to reproduce it correctly the proxy needs to have basic auth enabled. I was not able to reproduce it until I read the logs. Starting the server with the following command:

❯ PROXY_ENABLE_BASIC_AUTH=true OCIS_LOG_LEVEL=debug go run cmd/ocis/main.go server

Without PROXY_ENABLE_BASIC_AUTH set I just keep getting a 997 response back. So I'm guessing this is related to the basic auth + proxy combination. Will dig further into it.

butonic · 2020-11-09T08:39:05Z

correct. no permission for ListAccounts is a log line from the role / permissions checks that is now in effect.

refs · 2020-11-09T08:42:58Z

@dpakach is there any extra step you're doing? By running the curl command multiple times I am not able to reproduce it

dpakach · 2020-11-09T08:57:26Z

@refs We first noticed this issue when running in CI. like in
https://drone.owncloud.com/owncloud/ocis/1273/22/7
As you see all tests fail in some pipeline because of this. So rather than running curl multiple times, I think you should restart the server and try each time. When it's failing it fails every time.

I just ran ocis with
STORAGE_HOME_DRIVER=owncloud STORAGE_USERS_DRIVER=owncloud PROXY_ENABLE_BASIC_AUTH=true bin/ocis server
But it happens very rarely (like once every 20 times) but it's an annoying thing when running in CI.
Also I deleted the contents of /var/tmp/ocis-* every time but that may not be relevant here.

refs · 2020-11-09T10:07:05Z

So @butonic and I were able to reproduce it by doing:

start the server as: STORAGE_HOME_DRIVER=owncloud STORAGE_USERS_DRIVER=owncloud PROXY_ENABLE_BASIC_AUTH=true ./ocis server
requesting user Einstein should work at this point curl https://localhost:9200/ocs/v1.php/cloud/users/einstein -u einstein:relativity -k | xmllint --format -
remove the folder as: /var/tmp/ocis-* which only wipes the settings (which includes roles and permissions), but it does NOT wipe the account, which lives in /var/tmp/ocis/metadata/nodes
do the curl request from step 2 again
💥

We got to jump in the sprint planning and will continue afterwards.

dpakach · 2020-11-09T10:38:58Z

@refs, I did delete both /var/tmp/ocis and /var/tmp/ocis-* directories. Sorry, I should have made it clear in the first comment.

But since you reproduced it may be the real issue.

refs · 2020-11-09T10:43:51Z

ha, interesting. Do you happen to know in which step are the directories removed?

dpakach · 2020-11-09T10:49:58Z

@refs This is the exact steps I followed

Stop ocis if it is running
Delete the ocis generated directories

cd /var/tmp && rm -rf ocis-* reva .pman ocis

Run the ocis server

STORAGE_HOME_DRIVER=owncloud STORAGE_USERS_DRIVER=owncloud PROXY_ENABLE_BASIC_AUTH=true bin/ocis server

Check the issues with curl command
a. If the issue is reproduced - 👍
b. If the issue is not reproduced- Goto step 1

butonic · 2020-11-09T15:06:42Z

In Line 5284 of https://drone.owncloud.com/owncloud/ocis/1308/19/5 we have a winner ...

butonic · 2020-11-09T15:21:25Z

2020-11-09T13:24:54Z INF http end="09/Nov/2020:13:24:54 +0000" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=330 start="09/Nov/2020:13:24:54 +0000" status=200 time_ns=512671 traceid=192d4df331311711840b677e2c61c626 uri=/data/accounts/Alice url=/data/accounts/Alice
2020-11-09T13:24:54Z DBG Associated claims with uuid account={"accountEnabled":true,"displayName":"Alice Hansen","gidNumber":"3000","id":"Alice","mail":"[email protected]","onPremisesSamAccountName":"Alice","passwordProfile":{},"preferredName":"Alice","uidNumber":"40040"} claims={"iss":"https://ocis-server:9200"} service=proxy
2020-11-09T13:24:54Z INF access token is already provided pkg=rhttp service=storage traceid=1cc7f644ad4e9e3ccf7f7096f3302d1d
2020-11-09T13:24:54Z DBG http routing: head=data tail=/accounts/Alice svc=data pkg=rhttp service=storage
2020-11-09T13:24:54Z DBG NodeFromPath() fn=/accounts/Alice pkg=rhttp service=storage traceid=1cc7f644ad4e9e3ccf7f7096f3302d1d
2020-11-09T13:24:54Z DBG NodeFromPath() walk node={"Exists":true,"ID":"a83ecfb4-7780-44f3-8d85-755eff746b1e","Name":"accounts","ParentID":"root"} pkg=rhttp service=storage traceid=1cc7f644ad4e9e3ccf7f7096f3302d1d
2020-11-09T13:24:54Z DBG NodeFromPath() walk node={"Exists":true,"ID":"a0459aa5-679c-4153-a65d-b9e3d8af1adf","Name":"Alice","ParentID":"a83ecfb4-7780-44f3-8d85-755eff746b1e"} pkg=rhttp service=storage traceid=1cc7f644ad4e9e3ccf7f7096f3302d1d
2020-11-09T13:24:54Z DBG user is owner, returning owner permissions node={"Exists":true,"ID":"a0459aa5-679c-4153-a65d-b9e3d8af1adf","Name":"Alice","ParentID":"a83ecfb4-7780-44f3-8d85-755eff746b1e"} pkg=rhttp service=storage traceid=1cc7f644ad4e9e3ccf7f7096f3302d1d
2020-11-09T13:24:54Z INF http end="09/Nov/2020:13:24:54 +0000" host=127.0.0.1 method=GET pkg=rhttp proto=HTTP/1.1 service=storage size=330 start="09/Nov/2020:13:24:54 +0000" status=200 time_ns=426107 traceid=1cc7f644ad4e9e3ccf7f7096f3302d1d uri=/data/accounts/Alice url=/data/accounts/Alice
2020-11-09T13:24:54Z DBG skipping auth method=/cs3.gateway.v1beta1.GatewayAPI/CreateHome pkg=rgrpc service=storage traceid=aec5b6270a93e2a19cbf4466dc7f2b50
2020-11-09T13:24:54Z INF unary code=OK end="09/Nov/2020:13:24:54 +0000" from=tcp://127.0.0.1:53230 pkg=rgrpc service=storage start="09/Nov/2020:13:24:54 +0000" time_ns=180419 traceid=aec5b6270a93e2a19cbf4466dc7f2b50 uri=/cs3.storage.registry.v1beta1.RegistryAPI/GetStorageProvider user-agent=grpc-go/1.26.0
2020-11-09T13:24:54Z INF unary code=OK end="09/Nov/2020:13:24:54 +0000" from=tcp://127.0.0.1:59840 pkg=rgrpc service=storage start="09/Nov/2020:13:24:54 +0000" time_ns=628568 traceid=aec5b6270a93e2a19cbf4466dc7f2b50 uri=/cs3.storage.provider.v1beta1.ProviderAPI/CreateHome user-agent=grpc-go/1.26.0
2020-11-09T13:24:54Z INF unary code=OK end="09/Nov/2020:13:24:54 +0000" from=tcp://127.0.0.1:53098 pkg=rgrpc service=storage start="09/Nov/2020:13:24:54 +0000" time_ns=3511180 traceid=aec5b6270a93e2a19cbf4466dc7f2b50 uri=/cs3.gateway.v1beta1.GatewayAPI/CreateHome user-agent=grpc-go/1.26.0
2020-11-09T13:24:54Z DBG director found path=/ocs/v2.php/cloud/users/Alice policy=reva prefix=/ocs/v[12].php/cloud/(users?|groups) routeType=regex service=proxy
2020-11-09T13:24:54Z ERR could not get account for user error="{\"id\":\"com.owncloud.api.accounts\",\"code\":403,\"detail\":\"no permission for ListAccounts\",\"status\":\"Forbidden\"}" service=ocs userid=Alice
2020-11-09T13:24:54Z DBG  bytes=296 duration=4.548102 method=GET path=/ocs/v2.php/cloud/users/Alice proto=HTTP/1.1 request=2d786823-2e98-46c3-8d0f-f255c7503aa9 service=ocs status=500

🤔 The only suspicious thing I see is an account ID Alice with capital a... Just summons bad memories. Should work though...

refs · 2020-11-09T18:06:49Z

No I think we're good on that front, the users endpoint is case insensitive

refs · 2020-11-09T18:07:20Z

I was looking earlier to the usage of go-micro/metadata to store the roles @butonic

refs · 2020-11-09T18:24:20Z

next idea:

Hunt down the first occurrence of this issue on CI and read the diff

dpakach · 2020-11-10T06:29:37Z

@butonic @refs I ran git bisect and I think I found the commit that actually broke it
8e39d8b

hope this helps

refs · 2020-11-10T08:19:23Z

Thanks!

dpakach added the bug label Nov 9, 2020

dpakach mentioned this issue Nov 9, 2020

Acceptance tests are unreliable #819

Closed

exalate-issue-sync bot added p3-medium OCIS-Fastlane Planned outside of the sprint labels Nov 9, 2020

butonic mentioned this issue Nov 9, 2020

ci debug #825

Closed

exalate-issue-sync bot closed this as completed Nov 10, 2020

phil-davis mentioned this issue Nov 10, 2020

change hashing algorithm from SHA-512 to bcrypt #638

Merged

exalate-issue-sync bot added bug Type:Bug labels Jan 12, 2021

exalate-issue-sync bot added the bug label Mar 1, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ListAccount is forbidden randomly #820

ListAccount is forbidden randomly #820

dpakach commented Nov 9, 2020

refs commented Nov 9, 2020

butonic commented Nov 9, 2020

refs commented Nov 9, 2020

dpakach commented Nov 9, 2020

refs commented Nov 9, 2020 •

edited

Loading

dpakach commented Nov 9, 2020

refs commented Nov 9, 2020

dpakach commented Nov 9, 2020

butonic commented Nov 9, 2020

butonic commented Nov 9, 2020

refs commented Nov 9, 2020

refs commented Nov 9, 2020

refs commented Nov 9, 2020

dpakach commented Nov 10, 2020

refs commented Nov 10, 2020

ListAccount is forbidden randomly #820

ListAccount is forbidden randomly #820

Comments

dpakach commented Nov 9, 2020

refs commented Nov 9, 2020

butonic commented Nov 9, 2020

refs commented Nov 9, 2020

dpakach commented Nov 9, 2020

refs commented Nov 9, 2020 • edited Loading

dpakach commented Nov 9, 2020

refs commented Nov 9, 2020

dpakach commented Nov 9, 2020

butonic commented Nov 9, 2020

butonic commented Nov 9, 2020

refs commented Nov 9, 2020

refs commented Nov 9, 2020

refs commented Nov 9, 2020

dpakach commented Nov 10, 2020

refs commented Nov 10, 2020

refs commented Nov 9, 2020 •

edited

Loading