[FOLIO-2839] folio-ansible okapi-secure role fails with Okapi 4.2.0 Created: 16/Oct/20 Updated: 19/Oct/20 Resolved: 19/Oct/20 |
|
| Status: | Closed |
| Project: | FOLIO |
| Components: | None |
| Affects versions: | None |
| Fix versions: | None |
| Type: | Bug | Priority: | TBD |
| Reporter: | John Malconian | Assignee: | John Malconian |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original estimate: | Not Specified | ||
| Environment: |
Snapshot reference builds w/Okapi 4.2.0, mod-users:17.3.0-SNAPSHOT.152, mod-login:7.2.0-SNAPSHOT.86, mod-authtoken:2.7.0-SNAPSHOT.78 |
||
| Attachments: |
|
||||||||
| Issue links: |
|
||||||||
| Sprint: | DevOps: Sprint 99 | ||||||||
| Development Team: | FOLIO DevOps | ||||||||
| Description |
|
folio-testing/snapshot reference builds fails getting supertenant token. This task occurs in the folio-ansible role, okapi-secure - https://github.com/folio-org/folio-ansible/tree/master/roles/okapi-secure - This role occurs towards the end of the playbook post module deployment and tenant configuration. Only reproducible when running Okapi 4.2.0. |
| Comments |
| Comment by John Malconian [ 16/Oct/20 ] |
|
The following Ansible task which attempts to get the supertenant token fails: - name: login to supertenant
uri:
url: "{{ okapi_login_url }}/authn/login"
method: POST
headers:
X-Okapi-Tenant: "supertenant"
Accept: application/json
body_format: json
body: "{'username': '{{ superuser_username }}', 'password': '{{ superuser_password }}' }"
status_code: 201, 404
register: login_result
listen: supertenant login
This is functionally equivalent to: curl -w '\n' -X POST -d '{"username": "superadmin", "password": "$PASSWORD" }' -H 'X-Okapi-Tenant: supertenant' -H 'Accept: application/json' -H 'Content-Type: application/json' https://$OKAPI_URL/authn/login
The following is the log output from Okapi: 2020-10-16T17:02:46,700 INFO ProxyContext 366088/authn REQ 10.36.1.228:46466 supertenant POST /authn/login mod-login-7.2.0-SNAPSHOT.86
2020-10-16T17:02:46,705 INFO ProxyContext 165346/users REQ 172.17.0.12:40196 supertenant GET /users mod-users-17.3.0-SNAPSHOT.152
2020-10-16T17:02:46,708 INFO DockerModuleHandle mod-users-17.3.0-SNAPSHOT.152 Oct 16, 2020 5:02:46 PM org.folio.cql2pgjson.CQL2PgJSON loadDbSchema
2020-10-16T17:02:46,708 INFO DockerModuleHandle mod-users-17.3.0-SNAPSHOT.152 INFO: loadDbSchema: Loaded templates/db_scripts/schema.json OK
2020-10-16T17:02:46,708 INFO DockerModuleHandle mod-users-17.3.0-SNAPSHOT.152 17:02:46 INFO CQLWrapper CQL >>> SQL: username==super_admin >>>WHERE lower(f_unaccent(users.jsonb->>'username')) LIKE lower(f_unaccent('super\_admin')) LIMIT 10 OFFSET 0
2020-10-16T17:02:46,717 INFO ProxyContext 165346/users RES 200 11171us mod-users-17.3.0-SNAPSHOT.152 http://10.36.1.228:9134/users?query=username==super_admin
2020-10-1:02:46,720 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:02:46:719 INFO CQLWrapper [] CRITERION >>> SQL: WHERE (jsonb->>'userId') = 'bddd70cd-036b-5456-976e-01ee5e84a05f' >>>WHERE (jsonb->>'userId') = 'bddd70cd-036b-5456-976e-01ee5e84a05f'
2020-10-16T17:02:46,725 INFO ProxyContext 431440/token REQ 172.17.0.12:40196 supertenant POST /token mod-authtoken-2.7.0-SNAPSHOT.78
2020-10-16T17:02:46,726 INFO ProxyContext 287966/refreshtoken REQ 172.17.0.12:40192 supertenant POST /refreshtoken mod-authtoken-2.7.0-SNAPSHOT.78
2020-10-16T17:02:46,729 INFO ProxyContext 431440/token RES 403 4019us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/token
2020-10-16T17:02:46,730 INFO ProxyContext 287966/refreshtoken RES 403 4042us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/refreshtoken
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 Oct 16, 2020 5:02:46 PM mod-auth-authtoken-module
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 SEVERE: Expected tenant: supertenant, got tenant: diku
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 Oct 16, 2020 5:02:46 PM mod-auth-authtoken-module
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 SEVERE: Invalid token for access
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 Oct 16, 2020 5:02:46 PM mod-auth-authtoken-module
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 SEVERE: Expected tenant: supertenant, got tenant: diku
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 Oct 16, 2020 5:02:46 PM mod-auth-authtoken-module
2020-10-16T17:02:46,731 INFO DockerModuleHandle mod-authtoken-2.7.0-SNAPSHOT.78 SEVERE: Invalid token for access
2020-10-16T17:02:46,733 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:02:46:732 ERROR LoginAPI [] Error fetching token: Got response 403 fetching token
2020-10-16T17:02:46,733 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:02:46:733 INFO LogUtil [reqId=366088/authn] org.folio.rest.RestVerticle start invoking postAuthnLogin
2020-10-16T17:02:46,733 INFO ProxyContext 366088/authn RES 500 33064us mod-login-7.2.0-SNAPSHOT.86 http://10.36.1.228:9141/authn/login
2020-10-16T17:02:46,734 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:02:46:733 INFO LogUtil [reqId=366088/authn] null POST /authn/login null HTTP_1_1 500 53 30 tid=supertenant Internal Server Error
|
| Comment by John Malconian [ 16/Oct/20 ] |
|
Subsequently, running the command succeeds: root@ip-10-36-1-228:/var/log/folio/okapi# curl -w '\n' -X POST -d '{"username": "super_admin", "password": "admin" }' -H 'X-Okapi-Tenant: supertenant' -H 'Accept: application/json' -H 'Content-Type: application/json' http://10.36.1.228:9130/authn/login -D -
HTTP/1.1 201 Created
vary: origin
X-Okapi-Trace: POST mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/authn/login : 202 1805us
Content-Type: application/json
x-okapi-token: eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJzdXBlcl9hZG1pbiIsInVzZXJfaWQiOiJiZGRkNzBjZC0wMzZiLTU0NTYtOTc2ZS0wMWVlNWU4NGEwNWYiLCJpYXQiOjE2MDI4NzA2OTQsInRlbmFudCI6InN1cGVydGVuYW50In0.p9-3_KhMKUOvE_RMTCAT1mFS7Z0hhj0pwzFuOgDwt7U
refreshtoken: eyJlbmMiOiJBMjU2R0NNIiwiYWxnIjoiZGlyIn0..oSPkSYoHLBMk6Vof.jjIzWAuOnHF7wIEA9Tx19e8xsJWxbSyKO-n41kFfhCeLuRtQ6USXnsxF7P2zlj6jMiuPPm188uWIL8p6Y_UxVXUUyVhOPXc2dI1I1H3oZHydiIuvvhPyNtEss--PXZLiyez9xAXKEo1k0ENKDbspYoPl23c52b147o-IrwnTsS1sZacZUZbNT_EdKLW15mwSVX3Gz7LrW36jCzvjlmG0JYSm79lDmufREOCuun9u8TJUSxShfa-TV6xBUZmGQ4CSbE9sdzWwVa0U1AyCFjJbR8YgpW0._GiyeCiyNfoeQPOFRtMi6Q
transfer-encoding: chunked
X-Okapi-Trace: POST mod-login-7.2.0-SNAPSHOT.86 http://10.36.1.228:9141/authn/login : 201 45513us
{
"username" : "super_admin",
"password" : "admin"
}
Corresponding log entries:
2020-10-16T17:36:45,568 INFO ProxyContext 865290/authn REQ 10.36.1.228:46974 supertenant POST /authn/login mod-authtoken-2.7.0-SNAPSHOT.78 mod-login-7.2.0-SNAPSHOT.86
2020-10-16T17:36:45,570 INFO ProxyContext 865290/authn RES 202 2162us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/authn/login
2020-10-16T17:36:45,576 INFO ProxyContext 625467/users REQ 172.17.0.12:41120 supertenant GET /users mod-authtoken-2.7.0-SNAPSHOT.78 mod-users-17.3.0-SNAPSHOT.152
2020-10-16T17:36:45,579 INFO ProxyContext 625467/users RES 202 2076us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/users?query=username==super_admin
2020-10-16T17:36:45,583 INFO DockerModuleHandle mod-users-17.3.0-SNAPSHOT.152 Oct 16, 2020 5:36:45 PM org.folio.cql2pgjson.CQL2PgJSON loadDbSchema
2020-10-16T17:36:45,583 INFO DockerModuleHandle mod-users-17.3.0-SNAPSHOT.152 INFO: loadDbSchema: Loaded templates/db_scripts/schema.json OK
2020-10-16T17:36:45,585 INFO DockerModuleHandle mod-users-17.3.0-SNAPSHOT.152 17:36:45 INFO CQLWrapper CQL >>> SQL: username==super_admin >>>WHERE lower(f_unaccent(users.jsonb->>'username')) LIKE lower(f_unaccent('super\_admin')) LIMIT 10 OFFSET 0
2020-10-16T17:36:45,588 INFO ProxyContext 625467/users RES 200 9325us mod-users-17.3.0-SNAPSHOT.152 http://10.36.1.228:9134/users?query=username==super_admin
2020-10-16T17:36:45,595 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:36:45:593 INFO CQLWrapper [] CRITERION >>> SQL: WHERE (jsonb->>'userId') = 'bddd70cd-036b-5456-976e-01ee5e84a05f' >>>WHERE (jsonb->>'userId') = 'bddd70cd-036b-5456-976e-01ee5e84a05f'
2020-10-16T17:36:45,598 INFO ProxyContext 664634/token REQ 172.17.0.12:41120 supertenant POST /token mod-authtoken-2.7.0-SNAPSHOT.78 mod-authtoken-2.7.0-SNAPSHOT.78
2020-10-16T17:36:45,599 INFO ProxyContext 631439/refreshtoken REQ 172.17.0.12:41124 supertenant POST /refreshtoken mod-authtoken-2.7.0-SNAPSHOT.78 mod-authtoken-2.7.0-SNAPSHOT.78
2020-10-16T17:36:45,601 INFO ProxyContext 664634/token RES 202 1998us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/token
2020-10-16T17:36:45,602 INFO ProxyContext 664634/token RES 201 1476us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/token
2020-10-16T17:36:45,603 INFO ProxyContext 631439/refreshtoken RES 202 3383us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/refreshtoken
2020-10-16T17:36:45,605 INFO ProxyContext 631439/refreshtoken RES 201 1885us mod-authtoken-2.7.0-SNAPSHOT.78 http://10.36.1.228:9152/refreshtoken
2020-10-16T17:36:45,607 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:36:45:606 INFO CQLWrapper [] CRITERION >>> SQL: WHERE (jsonb->>'userId') = 'bddd70cd-036b-5456-976e-01ee5e84a05f' >>>WHERE (jsonb->>'userId') = 'bddd70cd-036b-5456-976e-01ee5e84a05f'
2020-10-16T17:36:45,609 INFO ProxyContext 632744/configurations RES 404 - okapi No suitable module found for path /configurations/entries for tenant supertenant
2020-10-16T17:36:45,610 ERROR HttpResponse HTTP response code=404 msg=No suitable module found for path /configurations/entries for tenant supertenant
2020-10-16T17:36:45,612 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:36:45:611 INFO LogStorageServiceImpl [] Logging settings are disabled
2020-10-16T17:36:45,613 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:36:45:613 INFO LogUtil [reqId=865290/authn] org.folio.rest.RestVerticle start invoking postAuthnLogin
2020-10-16T17:36:45,614 INFO ProxyContext 865290/authn RES 201 43616us mod-login-7.2.0-SNAPSHOT.86 http://10.36.1.228:9141/authn/login
2020-10-16T17:36:45,615 INFO DockerModuleHandle mod-login-7.2.0-SNAPSHOT.86 16 Oct 2020 17:36:45:614 INFO LogUtil [reqId=865290/authn] 10.36.1.228:43236 POST /authn/login null HTTP_1_1 201 56 40 tid=supertenant Created
|
| Comment by Craig McNally [ 16/Oct/20 ] |
|
John Malconian it's strange that mod-authtoken appears to think that the tenant is diku... |
| Comment by John Malconian [ 16/Oct/20 ] |
|
Right. And getting the supertenant token succeeds after the build has failed in my last comment above. I wonder if a cache has expired by this point. |
| Comment by Craig McNally [ 16/Oct/20 ] |
|
is it possible to try this with -Dtoken_cache_ttl_ms=0 ? |
| Comment by Craig McNally [ 16/Oct/20 ] |
|
Also, enabling debug logging in OKAPI might help as well |
| Comment by John Malconian [ 16/Oct/20 ] |
|
No build errors when starting Okapi with '-Dtoken_cache_ttl_ms=0'. supertenant token fetched successfully. For the next build, I will disable '-Dtoken_cache_ttl_ms=0' and increase log level to 'DEBUG'. |
| Comment by Craig McNally [ 16/Oct/20 ] |
|
yeah that pretty much proves it's an issue with the token cache... I think I know what it is, but I'm having a hard time reproducing this in unit tests. The debug logs will be helpful. Thanks John Malconian |
| Comment by John Malconian [ 16/Oct/20 ] |
|
Removed option '-Dtoken_cache_ttl_ms=0' and build fails again fetching supertenant token. Full Okapi debug log file attached to this issue. |
| Comment by Craig McNally [ 16/Oct/20 ] |
|
OK, so it's what I suspected, I have a fix - just need to figure out why I can't reproduce this in unit tests. Here's the smoking gun:
2020-10-16T19:52:45,759 DEBUG TokenCache Cache Hit: POST|/authn/login|null -> eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiJVTkRFRklORURfVVNFUl9fMTAuMzYuMS4xMTo0MTMwOF9fMjAyMC0xMC0xNlQxOTo1MDoyMC4zNzYrMDAwMCIsIm1vZHVsZSI6Im1vZC1sb2dpbi03LjIuMC1TTkFQU0hPVC44NiIsImV4dHJhX3Blcm1pc3Npb25zIjpbIlNZUyNtb2QtbG9naW4tNy4yLjAtU05BUFNIT1QuODYjXC9hdXRoblwvbG9naW4jW1BPU1RdIl0sInRlbmFudCI6ImRpa3UifQ.bEuxT9idhyVgg6mTkyaFFMZ2Mwf64tfOC2aq3wYGcAc
instead of explicitly incorporating things like tenant and userId into the cache key we use the entire token in the request as part of the cache key since it includes this information. In doing so, we need to ensure that we don't allow cache keys w/ token=null. See
|
| Comment by Craig McNally [ 19/Oct/20 ] |
|
John Malconian OKAPI version 4.2.1 was released this morning w/ a fix for
|
| Comment by John Malconian [ 19/Oct/20 ] |
|
I've verified that this is resolved in Okapi 4.2.1. Will unpin Okapi in reference builds. |