[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: File okapi-4.2.0-debug.log.gz    
Issue links:
Relates
relates to OKAPI-921 Don't use tokenCache when no token is... Closed
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...
SEVERE: Expected tenant: supertenant, got tenant: diku
Based on the ansible task above I don't see how/why that would be.

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 OKAPI-921 Closed

Comment by Craig McNally [ 19/Oct/20 ]

John Malconian OKAPI version 4.2.1 was released this morning w/ a fix for OKAPI-921 Closed . Please give that a try when you get a chance. Thanks!

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.

Generated at Thu Feb 08 23:23:37 UTC 2024 using Jira 1001.0.0-SNAPSHOT#100246-sha1:7a5c50119eb0633d306e14180817ddef5e80c75d.