Unable to « acquire » an existing organization in DC from the portal

[bobeal]

Hi,

From the portal, when I want to create an organization that already exists in the Datacore, I get a 403 Forbidden error.

Here are the logs :

| DEBUG| 17:07:04.203 | kernelLogging.logRequestTimings - GET Request to https://data.ozwillo.com/dc/r/orgfr:Organisation_0/FR/testImport10/1 took 38 ms
| DEBUG| 17:07:04.575 | org.oasis_eu.spring.datacore.impl.DatacoreClientImpl - Setting rights to Resource: URI String is https://data.ozwillo.com/dc/r/orgfr:Organisation_0/FR/testImport10/1
| DEBUG| 17:07:04.580 | kernelLogging.logRequestTimings - PUT Request to https://data.ozwillo.com/dc/r/orgfr:Organisation_0/FR/testImport10/1 took 4 ms
| INFO | 17:07:04.682 | org.oasis_eu.portal.services.dc.organization.DCOrganizationService - Searching resource in DC using parameters : testImport10, http://data.ozwillo.com/dc/type/geocofr:Pays_0/FR and org:Organization_0
| DEBUG| 17:07:04.683 | org.oasis_eu.spring.datacore.impl.DatacoreClientImpl - Fetching limited Resources: URI String is https://data.ozwillo.com/dc/type/org:Organization_0?start=0&limit=1&org:regNumber=testImport10&adrpost:country=http://data.ozwillo.com/dc/type/geocofr:Pays_0/FR
| DEBUG| 17:07:04.688 | kernelLogging.logRequestTimings - GET Request to https://data.ozwillo.com/dc/type/org:Organization_0?start=0&limit=1&org:regNumber=testImport10&adrpost:country=http://data.ozwillo.com/dc/type/geocofr:Pays_0/FR took 5 ms
| DEBUG| 17:07:04.757 | org.oasis_eu.portal.services.dc.organization.DCOrganizationService - Fetched 1 resources in 75 ms
| DEBUG| 17:07:04.757 | org.oasis_eu.portal.services.dc.organization.DCOrganizationService - It exists, and there are no previous updates. Merging it from form fields, and doing a datacoreClient.updateResource()
| DEBUG| 17:07:04.757 | org.oasis_eu.spring.datacore.impl.DatacoreClientImpl - Updating Resource: URI String is https://data.ozwillo.com/dc/type/orgfr:Organisation_0/FR/testImport10
| DEBUG| 17:07:04.764 | kernelLogging.logRequestTimings - PUT Request to https://data.ozwillo.com/dc/type/orgfr:Organisation_0/FR/testImport10 took 6 ms
| INFO | 17:07:04.811 | kernelLogging.logFullErrorResponses - Full response body: Access is denied (as c410d537-56fd-4db0-8cd1-fb730c68cf10).
| WARN | 17:07:04.811 | org.oasis_eu.spring.util.KernelLoggingInterceptor - PUT request to https://data.ozwillo.com/dc/type/orgfr:Organisation_0/FR/testImport10 resulted in 403 Forbidden
| INFO | 17:07:04.811 | org.oasis_eu.spring.util.KernelLoggingInterceptor - Request headers: 
Content-Type:   [application/json]
X-Datacore-Project: [org]
Content-Length: [1292]
Authorization:  [Bearer eyJpZCI6IjhkMzBjY2RmLTU5NDYtNGFkYS04NzYzLTk4NGRhMDYyYjA1Ny9KWW04WV9wR3ZHaUhVQ2hsZlNtLXJRIiwiaWF0IjoxNDUzMTMxNzg1Njk5LCJleHAiOjE0NTMxMzUzODU2OTl9]

| INFO | 17:07:04.811 | org.oasis_eu.spring.util.KernelLoggingInterceptor - Request body: {"@id":"http://data.ozwillo.com/dc/type/orgfr:Organisation_0/FR/testImport10","o:version":2,"org:displayAltName":[{"@value":"Test Import 11 – Lyon, France","@language":"fr"},{"@value":"","@language":"it"},{"@value":"","@language":"bg"},{"@value":"","@language":"tr"},{"@value":"","@language":"es"}],"adrpost:streetAndNumber":"rue test","org:country":"http://data.ozwillo.com/dc/type/geocofr:Pays_0/FR","org:altName":[{"@language":"en","@value":""}],"org:regNumber":"testImport10","@type":["orgfr:Organisation_0","org:Organization_0","odisp:Displayable_0","relt:Target_0","adrpost:Postal_0","orgpu:PublicOrg_0"],"org:legalName":[{"@language":"en","@value":"Test Import 11"}],"org:status":"Inactive","odisp:name":[{"@language":"en","@value":"Test Import 11,Lyon (69000), France - France"}],"adrpost:postCode":"69001","adrpost:postName":"http://data.ozwillo.com/dc/type/geocifr:Commune_0/FR/FR-69/Lyon","org:activity":"http://data.ozwillo.com/dc/type/orgactfr:Activit%C3%A9NAF2008_0/FR/01.11Z","org:sector":"Private","adrpost:country":"http://data.ozwillo.com/dc/type/geocofr:Pays_0/FR","org:displayName":[{"@value":"Test Import 11 – Lyon, France","@language":"fr"},{"@value":"","@language":"it"},{"@value":"","@language":"bg"},{"@value":"","@language":"tr"},{"@value":"","@language":"es"}]}
| WARN | 17:07:04.811 | org.springframework.web.client.RestTemplate - PUT request for "https://data.ozwillo.com/dc/type/orgfr:Organisation_0/FR/testImport10" resulted in 403 (Forbidden); invoking error handler
| ERROR| 17:07:04.840 | org.oasis_eu.spring.datacore.impl.DatacoreClientImpl - Error caught while querying data core
org.springframework.web.client.HttpClientErrorException: 403 Forbidden
    at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:91) ~[spring-web-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
    at org.springframework.web.client.RestTemplate.handleResponseError(RestTemplate.java:588) ~[spring-web-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
    at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:546) ~[spring-web-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
    at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:517) ~[spring-web-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
    at org.springframework.web.client.RestTemplate.put(RestTemplate.java:393) ~[spring-web-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
    at org.oasis_eu.spring.datacore.impl.DatacoreClientImpl.updateResource(DatacoreClientImpl.java:210) ~[ozwillo-java-spring-integration-1.22-SNAPSHOT.jar!/:na]
    at org.oasis_eu.portal.services.dc.organization.DCOrganizationService.create(DCOrganizationService.java:176) [ozwillo-portal-front-1.39.jar!/:na]
    at org.oasis_eu.portal.services.dc.organization.DCOrganizationService.update(DCOrganizationService.java:198) [ozwillo-portal-front-1.39.jar!/:na]
    at org.oasis_eu.portal.services.dc.organization.OrganizationService.update(OrganizationService.java:155) [ozwillo-portal-front-1.39.jar!/:na]
    at org.oasis_eu.portal.front.my.network.NetworkAJAXServices.updateDCOrganization(NetworkAJAXServices.java:146) [ozwillo-portal-front-1.39.jar!/:na]

[mdutoo]

Did you use a token that was already known by the Datacore (ex. already clicked on an (dc) org info in the portal since logging in) ? Then it seems it could it be #124. So please try again (after the 5 minutes delay).

If it's not, we'll have to debug the Datacore. If it is, read on.

Indeed, according to those logs - and it's pretty obvious from the code (https://github.com/ozwillo/ozwillo-portal/blob/master/portal-parent/ozwillo-portal-front/src/main/java/org/oasis_eu/portal/services/dc/organization/OrganizationService.java#L155), the portal : creates the missing Kernel org, adds it to permissions of the existing DC org using the admin refresh token and rights, then attempts (and fails) to further update the DC org using the REGULAR user token, ALL IN THE SAME OPERATION. Since the Datacore caches token info for 5 minutes, token info won't bear the new org id in its sub_group field, which is what the Datacore looks at when checking rights. So relogging (and getting a new token with said kernel org id) should solve it.

Now, why wasn't this case encountered before ? Merely because the usual case of a portal user that wants to "acquire" his (dc) organization is a user that HASN'T ANY org yet. Which is the case for agrilocal providers. (or maybe I'm forgetting something here... anybody ?)

So THIS PROBLEM SHOULDN'T BE ENCOUNTERED BY NORMAL USERS.

Beyond, solutions (if it is DC#124):

• ideally / long term, the Kernel should dispatch notification of membership changes of tokens, so that the Datacore can listen to it and remove those tokens from its 5 minutes cache.
• or the Portal could auto-relog without the user noticing it, therefore getting a new, uncached token, maybe using token refresh capabilities. @tbroyer would it be possible ?
• the portal could do this "save org info" operation (https://github.com/ozwillo/ozwillo-portal/blob/master/portal-parent/ozwillo-portal-front/src/main/java/org/oasis_eu/portal/services/dc/organization/OrganizationService.java#L155) also using the admin refresh token and rights when it has just created a kernel org (and therefore knows it would fail), or even to solve it all, when created for less than 5-10 minutes (by comparing dc org createdAt vs current time).

And workarounds:

• the portal could say "Please relog or wait 5 minutes" when it gets such 403 Forbidden (https://github.com/ozwillo/ozwillo-portal/blob/master/portal-parent/ozwillo-portal-front/src/main/java/org/oasis_eu/portal/services/dc/organization/OrganizationService.java#L155) after creating a new kernel org
• lower the Datacore cache TTL. However, it won't fully solve the problem unless it is short enough to negate any caching benefits. Because if the Datacore doesn't cache tokens, not only will mass import be 10x slower, but there will be one Kernel request for each Datacore request, meaning 10-1000x more requests to the Kernel and 100-500ms more to each portal request, therefore trouncing user experience.

[tbroyer]

Maybe the Portal could somehow ask the DC to evict the token from its cache? Or the DC could possibly refresh its token introspection data automatically when a token is used as at a resource whose rights have been updated recently and the presented token didn't match (i.e. if token doesn't match, then if rights have been updated recently, then refresh token introspection data and check token access rights again)

Re. obtaining a new token, indeed it's possible: just redirect to the authorization endpoint at the Kernel. If you do that though, you should (probably) revoke the previous token (to limit the number of active tokens).

Or we could make it possible for the Portal to ask for a new token "based on" the current token (and possibly with restricted scopes – datacore only in our case), either by issuing a refresh_token in all cases (i.e. even when not asking for the offline_access scope; the refresh_token in this case would typically have the same expiration as the access_token, contrary to a refresh_token issued for offline_access); or by implementing https://tools.ietf.org/html/draft-ietf-oauth-token-exchange (a bit too early though IMO).
This, IMO, should be a last resort if the first 3 proposals above (explicit eviction from DC cache driven by the Portal, automatic refresh of token introspection data under certain circumstances on the DC side, or redirect to the authorization endpoint) can't be implemented. I'd rather wait for the "OAuth Token Exchange" spec to mature and stabilize before implementing it.

[bobeal]

It seems it could it be #124. So please try again (after the 5 minutes delay).

Tested it, same result.

[mdutoo]

I've just reproduced the bug myself. BUT when trying to save org info again 5 minutes later, it succeeded. So it really seems it is #124.

(I guess I wasn't clear when asking you to try again : it was "try again saving this org" and not "tray again acquiring another org". Am I right ?)

But I was wrong when saying that it shouldn't happen in the common case. Now that the portal looks for dc orgs in the Datacore before creating them, it always happens, because this first lookup request makes the Datacore cache token infos that are about to be obsoleted by "acquiring" the found org.

[bobeal]

(I guess I wasn't clear when asking you to try again : it was "try again saving this org" and not "tray again acquiring another org". Am I right ?)

Yes, that's what I understood.

But I was wrong when saying that it shouldn't happen in the common case. Now that the portal looks for dc orgs in the Datacore before creating them, it always happens, because this first lookup request makes the Datacore cache token infos that are about to be obsoleted by "acquiring" the found org.

And I made my yesterday evening test from the portal. That's why I still had the problem.

[schambon]

NB - reproduced & tested fix in dev environment