User endpoint doesn't answer the first time it's queried

[michaelstingl]

Describe the bug

Looks like the desktop client can't query the user endpoint (/ocs/v2.php/cloud/user?format=json) when the user was never logged in before.

Steps to reproduce

Steps to reproduce the behavior:

1. Install 3.0 pre-release desktop client (ownCloud-3.0.0-daily20220920.8579.pkg)
2. Add new account with ocis.ocis-keycloak.latest.owncloud.works
3. Login Keycloak with einstein:relativity or other demo user after nightly reset of the instance

Expected behavior

Desktop sync client need to query user endpoint directly after it got the access_token from the IdP.

Actual behavior

Desktop sync client can't query user information.

Only after triggering "Reopen Browser", the next attempt works:

Setup

ocis.ocis-keycloak.latest.owncloud.works

Additional context

Registration ✅

09-19 14:50:59:884 [ info sync.httplogger ]:	"89cd6f6f-a77f-45c6-86d2-a49fdf9edb93:
 Request: POST https://keycloak.ocis-keycloak.latest.owncloud.works/auth/realms/oCIS/clients-registrations/openid-connect
 Header: { Content-Type: application/json, User-Agent: Mozilla/5.0 (Macintosh) mirall/3.0.0.8569-daily20220919 (ownCloud, osx-21.6.0 ClientArchitecture: x86_64 OsArchitecture: x86_64), Accept: */*, X-Request-ID: 89cd6f6f-a77f-45c6-86d2-a49fdf9edb93, Original-Request-ID: 89cd6f6f-a77f-45c6-86d2-a49fdf9edb93, Content-Length: 193, }
 Data: [{\n    \"application_type\": \"native\",\n    \"client_name\": \"ownCloud 3.0.0.8569\",\n    \"redirect_uris\": [\n        \"http://127.0.0.1\"\n    ],\n    \"token_endpoint_auth_method\": \"client_secret_basic\"\n}\n]"

09-19 14:51:00:421 [ info sync.httplogger ]:	"89cd6f6f-a77f-45c6-86d2-a49fdf9edb93:
 Response: POST 201 () https://keycloak.ocis-keycloak.latest.owncloud.works/auth/realms/oCIS/clients-registrations/openid-connect
 Header: { Content-Length: 1397, Content-Type: application/json, Date: Mon, 19 Sep 2022 21:51:00 GMT, Location: https://keycloak.ocis-keycloak.latest.owncloud.works/auth/realms/oCIS/clients-registrations/openid-connect/658835f7-4792-4ae6-8484-01d65136aecb, Referrer-Policy: no-referrer, Strict-Transport-Security: max-age=31536000; includeSubDomains, X-Content-Type-Options: nosniff, X-Frame-Options: SAMEORIGIN, X-Xss-Protection: 1; mode=block, }
 Data: [{\"redirect_uris\":[\"http://127.0.0.1\"],\"token_endpoint_auth_method\":\"client_secret_basic\",\"grant_types\":[\"authorization_code\",\"refresh_token\"],\"response_types\":[\"code\",\"none\"],\"client_id\":\"658835f7-4792-4ae6-8484-01d65136aecb\",\"client_secret\":\"5gk9FdrfliEGKV4kE6F5oyDqKzregFBC\",\"client_name\":\"ownCloud 3.0.0.8569\",\"scope\":\"address phone offline_access microprofile-jwt\",\"subject_type\":\"public\",\"request_uris\":[],\"tls_client_certificate_bound_access_tokens\":false,\"client_id_issued_at\":1663624260,\"client_secret_expires_at\":0,\"registration_client_uri\":\"https://keycloak.ocis-keycloak.latest.owncloud.works/auth/realms/oCIS/clients-registrations/openid-connect/658835f7-4792-4ae6-8484-01d65136aecb\",\"registration_access_token\":\"eyJhbGciOiJIUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJmMTg4OTgzOS1mZGIxLTRjM2EtOThiNi0xMzMwNWYxYjBmNzQifQ.eyJleHAiOjAsImlhdCI6MTY2MzYyNDI2MCwianRpIjoiNTRhZjExMjMtMzlmOS00NDk2LWFmOGMtZDdmNTI0NTZiMWIwIiwiaXNzIjoiaHR0cHM6Ly9rZXljbG9hay5vY2lzLWtleWNsb2FrLmxhdGVzdC5vd25jbG91ZC53b3Jrcy9hdXRoL3JlYWxtcy9vQ0lTIiwiYXVkIjoiaHR0cHM6Ly9rZXljbG9hay5vY2lzLWtleWNsb2FrLmxhdGVzdC5vd25jbG91ZC53b3Jrcy9hdXRoL3JlYWxtcy9vQ0lTIiwidHlwIjoiUmVnaXN0cmF0aW9uQWNjZXNzVG9rZW4iLCJyZWdpc3RyYXRpb25fYXV0aCI6ImFub255bW91cyJ9.Ek1OlUSesHZZqohm_lf1th1tgd1de49ClkWe4EmjJ-k\",\"backchannel_logout_session_required\":false,\"require_pushed_authorization_requests\":false,\"frontchannel_logout_session_required\":false}]"

Token ✅

09-19 14:51:43:030 [ info sync.httplogger ]:	"d454f0e7-f8af-409a-bdfb-5521d6d47a82:
 Request: POST https://keycloak.ocis-keycloak.latest.owncloud.works/auth/realms/oCIS/protocol/openid-connect/token
 Header: { Authorization: Basic [redacted], Content-Type: application/x-www-form-urlencoded; charset=UTF-8, User-Agent: Mozilla/5.0 (Macintosh) mirall/3.0.0.8569-daily20220919 (ownCloud, osx-21.6.0 ClientArchitecture: x86_64 OsArchitecture: x86_64), Accept: */*, X-Request-ID: d454f0e7-f8af-409a-bdfb-5521d6d47a82, Original-Request-ID: d454f0e7-f8af-409a-bdfb-5521d6d47a82, Content-Length: 466, }
 Data: [client_id=658835f7-4792-4ae6-8484-01d65136aecb&client_secret=5gk9FdrfliEGKV4kE6F5oyDqKzregFBC&scope=openid%20offline_access%20email%20profile&grant_type=authorization_code&code=66148514-6400-463d-9509-705f8734be25.e3d6f1d0-3b92-4b63-be7a-54af734c5a93.658835f7-4792-4ae6-8484-01d65136aecb&redirect_uri=http://127.0.0.1:49153&code_verifier=7NwyiPzWexPhGPJuz6AoAzBvSzn8JiteQ6DvBY-IzKyHrbl04z0G9uzZ5zRrFrG3INOa8V-IhfbgamxMjwP1gi1m0s1wOvTKTLmD9aW4xDibF24G93UUiFnSXWq-vhmn]"

09-19 14:51:43:477 [ info sync.httplogger ]:	"d454f0e7-f8af-409a-bdfb-5521d6d47a82:
 Response: POST 200 () https://keycloak.ocis-keycloak.latest.owncloud.works/auth/realms/oCIS/protocol/openid-connect/token
 Header: { Cache-Control: no-store, Content-Length: 3671, Content-Type: application/json, Date: Mon, 19 Sep 2022 21:51:43 GMT, Pragma: no-cache, Referrer-Policy: no-referrer, Strict-Transport-Security: max-age=31536000; includeSubDomains, X-Content-Type-Options: nosniff, X-Frame-Options: SAMEORIGIN, X-Xss-Protection: 1; mode=block, }
 Data: [{\"access_token\":\"eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJneHJad2xqNGdEdWpLb3JhYlFRa0V0QTIycDhZemdlVzlqcUdkVGs5Z1hZIn0.eyJleHAiOjE2NjM2MjQ2MDMsImlhdCI6MTY2MzYyNDMwMywiYXV0aF90aW1lIjoxNjYzNjI0Mjk4LCJqdGkiOiJlNjUyYzk4MC01MzZiLTQ3OTgtYjI2NS00YTUwMmNhZmVmNWIiLCJpc3MiOiJodHRwczovL2tleWNsb2FrLm9jaXMta2V5Y2xvYWsubGF0ZXN0Lm93bmNsb3VkLndvcmtzL2F1dGgvcmVhbG1zL29DSVMiLCJzdWIiOiIwYTlmNDM0Yy00ODY0LTQ5Y2YtYWMxNS00NmVkMGY0OWQ1OWIiLCJ0eXAiOiJCZWFyZXIiLCJhenAiOiI2NTg4MzVmNy00NzkyLTRhZTYtODQ4NC0wMWQ2NTEzNmFlY2IiLCJzZXNzaW9uX3N0YXRlIjoiZTNkNmYxZDAtM2I5Mi00YjYzLWJlN2EtNTRhZjczNGM1YTkzIiwiYWNyIjoiMSIsImFsbG93ZWQtb3JpZ2lucyI6WyJodHRwOi8vMTI3LjAuMC4xIl0sInJlYWxtX2FjY2VzcyI6eyJyb2xlcyI6WyJvZmZsaW5lX2FjY2VzcyJdfSwic2NvcGUiOiJvcGVuaWQgZW1haWwgb2ZmbGluZV9hY2Nlc3MgcHJvZmlsZSIsInNpZCI6ImUzZDZmMWQwLTNiOTItNGI2My1iZTdhLTU0YWY3MzRjNWE5MyIsImVtYWlsX3ZlcmlmaWVkIjp0cnVlLCJuYW1lIjoiQWxiZXJ0IEVpbnN0ZWluIiwicHJlZmVycmVkX3VzZXJuYW1lIjoiZWluc3RlaW4iLCJnaXZlbl9uYW1lIjoiQWxiZXJ0IiwiZmFtaWx5X25hbWUiOiJFaW5zdGVpbiIsImVtYWlsIjoiZWluc3RlaW5AZXhhbXBsZS5vcmcifQ.GbaOvpAPhOgaEgmeiNxjz4HjEyXCpA-bZYaywQEGciClDsOCKgEdybaKZ89GmiK2TNnRfJKrvCx3eITDaxyoFWzwi9_EHwlWnIWRs_N1c1dz7gGguU5x5EOQNn_VXauH8GRgHPHwNYdwKcgOKzBD0avwJ5cpeFeJZuu5TLY7Ig3Fz5GbUmeUBOkpzE_SvKAJquIXa-nGbYZ8sm7R8ydLgkQG9Uazhjxht1nVWXqd7euAYrfxjYin1Ocm1lA5qZAW4JleRNdlCcTAwU9hXxD1EYsfzc_aeO-G1ndCQXntVDgDuhUUdH2hMNX8DQg6rd8xKIp9YYMu6Qg8Pl4u-UdO7g\",\"expires_in\":300,\"refresh_expires_in\":0,\"refresh_token\":\"eyJhbGciOiJIUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJmMTg4OTgzOS1mZGIxLTRjM2EtOThiNi0xMzMwNWYxYjBmNzQifQ.eyJpYXQiOjE2NjM2MjQzMDMsImp0aSI6ImJiNDJiMDRjLTkxN2EtNDcyYS04ODZmLThiOTUzZWEwZTIwOSIsImlzcyI6Imh0dHBzOi8va2V5Y2xvYWsub2Npcy1rZXljbG9hay5sYXRlc3Qub3duY2xvdWQud29ya3MvYXV0aC9yZWFsbXMvb0NJUyIsImF1ZCI6Imh0dHBzOi8va2V5Y2xvYWsub2Npcy1rZXljbG9hay5sYXRlc3Qub3duY2xvdWQud29ya3MvYXV0aC9yZWFsbXMvb0NJUyIsInN1YiI6IjBhOWY0MzRjLTQ4NjQtNDljZi1hYzE1LTQ2ZWQwZjQ5ZDU5YiIsInR5cCI6Ik9mZmxpbmUiLCJhenAiOiI2NTg4MzVmNy00NzkyLTRhZTYtODQ4NC0wMWQ2NTEzNmFlY2IiLCJzZXNzaW9uX3N0YXRlIjoiZTNkNmYxZDAtM2I5Mi00YjYzLWJlN2EtNTRhZjczNGM1YTkzIiwic2NvcGUiOiJvcGVuaWQgZW1haWwgb2ZmbGluZV9hY2Nlc3MgcHJvZmlsZSIsInNpZCI6ImUzZDZmMWQwLTNiOTItNGI2My1iZTdhLTU0YWY3MzRjNWE5MyJ9.vKrDSp_tzge_Ig6jMfIh6HuLWJ3jsTX0Rfafy3Km0UE\",\"token_type\":\"Bearer\",\"id_token\":\"eyJhbGciOiJSUzI1NiIsInR5cCIgOiAiSldUIiwia2lkIiA6ICJneHJad2xqNGdEdWpLb3JhYlFRa0V0QTIycDhZemdlVzlqcUdkVGs5Z1hZIn0.eyJleHAiOjE2NjM2MjQ2MDMsImlhdCI6MTY2MzYyNDMwMywiYXV0aF90aW1lIjoxNjYzNjI0Mjk4LCJqdGkiOiIwYzAwMzY0ZS01ODFkLTQ4MjQtOTQxYy0wYTE5ZTg5NGMxYTkiLCJpc3MiOiJodHRwczovL2tleWNsb2FrLm9jaXMta2V5Y2xvYWsubGF0ZXN0Lm93bmNsb3VkLndvcmtzL2F1dGgvcmVhbG1zL29DSVMiLCJhdWQiOiI2NTg4MzVmNy00NzkyLTRhZTYtODQ4NC0wMWQ2NTEzNmFlY2IiLCJzdWIiOiIwYTlmNDM0Yy00ODY0LTQ5Y2YtYWMxNS00NmVkMGY0OWQ1OWIiLCJ0eXAiOiJJRCIsImF6cCI6IjY1ODgzNWY3LTQ3OTItNGFlNi04NDg0LTAxZDY1MTM2YWVjYiIsInNlc3Npb25fc3RhdGUiOiJlM2Q2ZjFkMC0zYjkyLTRiNjMtYmU3YS01NGFmNzM0YzVhOTMiLCJhdF9oYXNoIjoiQlVaeHl0MVhqclV2Q2JFRGVkN1hndyIsImFjciI6IjEiLCJzaWQiOiJlM2Q2ZjFkMC0zYjkyLTRiNjMtYmU3YS01NGFmNzM0YzVhOTMiLCJlbWFpbF92ZXJpZmllZCI6dHJ1ZSwibmFtZSI6IkFsYmVydCBFaW5zdGVpbiIsInByZWZlcnJlZF91c2VybmFtZSI6ImVpbnN0ZWluIiwiZ2l2ZW5fbmFtZSI6IkFsYmVydCIsImZhbWlseV9uYW1lIjoiRWluc3RlaW4iLCJlbWFpbCI6ImVpbnN0ZWluQGV4YW1wbGUub3JnIn0.WTz0ARjvZn_Qq-b6DmSsKExkP_-8sD-Fl44foWwmB_58XfCsGGrjToY-cR3vnCzjB1aEGHb9XZeMGovn0HL5KEWA2WCTE4vLA7Orniok2PPhOUrftPjyjuTQzsgrT9vQV8N2RRzfOrPJZALLWYwyilHCva7YExtfq2ZPNB0Igg0TJ3vH4NMh1tA-E6L6AJmHc4R0QbFF0dAKy9hL1hKV6TqFi_ZiXfrT_3Vkf-hjjJpwrGVSQOr44jYhHRFNN9lmJ_zt8CkQfeo1W6JWJYpO-fTJN9Q_9ODDaR7yZiCSVlSUrFcyUwpV5yS5mec4Oq9Ai0I7L5gRfYYdy_d3DHgFqA\",\"not-before-policy\":0,\"session_state\":\"e3d6f1d0-3b92-4b63-be7a-54af734c5a93\",\"scope\":\"openid email offline_access profile\"}]"

User endpoint 💥

09-19 14:51:43:480 [ info sync.httplogger ]:	"14381b44-e581-40a2-9dfa-7d4436bc1cbe:
 Request: GET https://ocis.ocis-keycloak.latest.owncloud.works/ocs/v2.php/cloud/user?format=json
 Header: { Authorization: Bearer [redacted], OCS-APIREQUEST: true, User-Agent: Mozilla/5.0 (Macintosh) mirall/3.0.0.8569-daily20220919 (ownCloud, osx-21.6.0 ClientArchitecture: x86_64 OsArchitecture: x86_64), Accept: */*, X-Request-ID: 14381b44-e581-40a2-9dfa-7d4436bc1cbe, Original-Request-ID: 14381b44-e581-40a2-9dfa-7d4436bc1cbe, }
 Data: []"

09-19 14:51:44:519 [ info sync.httplogger ]:	"14381b44-e581-40a2-9dfa-7d4436bc1cbe:
 Response: GET 401 (Error: Host requires authentication,) https://ocis.ocis-keycloak.latest.owncloud.works/ocs/v2.php/cloud/user?format=json
 Header: { Content-Length: 0, Date: Mon, 19 Sep 2022 21:51:44 GMT, }
 Data: []"

@wkloucek @C0rby I just told you…

/cc @TheOneRing @fmoc

[micbar]

Desktop sync client need to query user endpoint directly after it got the access_token from the IdP.

That is the issue here. The autoprovisioning of the user happens later in the ocis proxy after successful login.

@rhafer any ideas?

[rhafer]

That is the issue here. The autoprovisioning of the user happens later in the ocis proxy after successful login.

As the ocs/v2.php/cloud/user endpoint requires an authenticated user, the autoprovisioning should have happened before request hits the ocs service. I am stlll trying to figure out what's going wrong here.

[rhafer]

After autoprovisioning a user, we did not properly request a reva token for that user. Which made the ocs service (auth interceptro in frontend) try to get a token via the auth-bearer service. That service however is currently not able to map the token correctly to a reva user (at least not in a way compatible with how the proxy is doing it). It will throw the 401 you're seeing above.

Fix is on it's way.

This however also raises the question why we're currently running the auth-bearer service at all. AFAICs it can't really work for us currently. And in all cases apart from autoprovisioning the proxy is requesting the reva-token via the auth-machine service.

[rhafer]

This however also raises the question why we're currently running the auth-bearer service at all.

I've created #4692 to tackle that separately.