[FOLIO-1312] Intermittant ansible deployment errors during PRs Created: 26/Jun/18  Updated: 12/Nov/18  Resolved: 22/Aug/18

Status: Closed
Project: FOLIO
Components: None
Affects versions: None
Fix versions: None

Type: Bug Priority: P3
Reporter: John Malconian Assignee: John Malconian
Resolution: Done Votes: 0
Labels: ci, sprint41, sprint42, sprint43, sprint44, sprint45
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original estimate: Not Specified

Attachments: File okapi.log-pr_72_18.gz    
Issue links:
Blocks
blocks FOLIO-1043 integrate ui-testing with PR Closed
is blocked by MODAT-29 concurrency issue with tenant Closed
Relates
relates to MODAT-27 Add creation timestamp to token on cr... Closed
Sprint:

 Description   

The following auth error occurs every so often while loading sample circulation data for a tenant during PR regression testing initialization:

ASK [folio-ansible/roles/mod-circulation-data : Load loan policies] ***********
changed: [localhost] => (item=/home/jenkins/workspace/folio-org/ui-users/PR-413/folio-infrastructure/CI/ansible/folio-ansible/roles/mod-circulation-data/files/loan-policies/one-hour.json)
failed: [localhost] (item=/home/jenkins/workspace/folio-org/ui-users/PR-413/folio-infrastructure/CI/ansible/folio-ansible/roles/mod-circulation-data/files/loan-policies/rolling.json) =>

{"changed": false, "connection": "close", "content": "Access requires permission: circulation-storage.loan-policies.item.post", "item": "/home/jenkins/workspace/folio-org/ui-users/PR-413/folio-infrastructure/CI/ansible/folio-ansible/roles/mod-circulation-data/files/loan-policies/rolling.json", "msg": "Status code was 403 and not [201, 422, 500]: HTTP Error 403: Forbidden", "redirected": false, "status": 403, "transfer_encoding": "chunked", "url": "http://folio-snapshot-stable.aws.indexdata.com:9130/loan-policy-storage/loan-policies", "x_okapi_trace": "POST mod-authtoken-1.4.1-SNAPSHOT.21 http://10.36.1.145:9135/loan-policy-storage/loan-policies : 403 19950us"}

to retry, use: --limit @/home/jenkins/workspace/folio-org/ui-users/PR-413/folio-infrastructure/CI/ansible/folioci-pr.retry



 Comments   
Comment by John Malconian [ 26/Jun/18 ]

Example occurances:

Failure - https://jenkins-aws.indexdata.com/job/folio-org/job/ui-users/view/change-requests/job/PR-413/8/console

Comment by John Malconian [ 26/Jun/18 ]

Subsequent success - https://jenkins-aws.indexdata.com/job/folio-org/job/ui-users/view/change-requests/job/PR-413/9/

Comment by John Malconian [ 26/Jun/18 ]

It appears the permission is added to the tenant admin user here on PR-413 Build 8:

changed: [localhost] => (item=

{u'dummy': False, u'permissionName': u'circulation-storage.all', u'displayName': u'Circulation storage module - all permissions', u'description': u'Entire set of permissions needed to use the circulation storage module', u'tags': [], u'childOf': [], u'visible': False, u'subPermissions': [u'circulation-storage.loans.collection.get', u'circulation-storage.loans.item.get', u'circulation-storage.loans.item.post', u'circulation-storage.loans.item.put', u'circulation-storage.loans.item.delete', u'circulation-storage.loans.collection.delete', u'circulation-storage.loans-history.collection.get', u'circulation-storage.loan-rules.get', u'circulation-storage.loan-rules.put', u'circulation-storage.loan-policies.collection.get', u'circulation-storage.loan-policies.item.get', u'circulation-storage.loan-policies.item.post', u'circulation-storage.loan-policies.item.put', u'circulation-storage.loan-policies.item.delete', u'circulation-storage.loan-policies.collection.delete', u'circulation-storage.requests.collection.get', u'circulation-storage.requests.item.get', u'circulation-storage.requests.item.post', u'circulation-storage.requests.item.put', u'circulation-storage.requests.item.delete', u'circulation-storage.requests.collection.delete', u'circulation-storage.fixed-due-date-schedules.collection.delete', u'circulation-storage.fixed-due-date-schedules.item.delete', u'circulation-storage.fixed-due-date-schedules.item.put', u'circulation-storage.fixed-due-date-schedules.item.post', u'circulation-storage.fixed-due-date-schedules.item.get', u'circulation-storage.fixed-due-date-schedules.collection.get', u'circulation-storage.staff-slips.item.delete', u'circulation-storage.staff-slips.collection.delete', u'circulation-storage.staff-slips.collection.get', u'circulation-storage.staff-slips.item.post', u'circulation-storage.staff-slips.item.put', u'circulation-storage.staff-slips.item.get'], u'mutable': False, u'id': u'a9e33958-888c-40ff-bb81-793649b6965b', u'grantedTo': []}

)

And here on PR-413 Build 9:

changed: [localhost] => (item=

{u'dummy': False, u'permissionName': u'circulation-storage.all', u'displayName': u'Circulation storage module - all permissions', u'description': u'Entire set of permissions needed to use the circulation storage module', u'tags': [], u'childOf': [], u'visible': False, u'subPermissions': [u'circulation-storage.loans.collection.get', u'circulation-storage.loans.item.get', u'circulation-storage.loans.item.post', u'circulation-storage.loans.item.put', u'circulation-storage.loans.item.delete', u'circulation-storage.loans.collection.delete', u'circulation-storage.loans-history.collection.get', u'circulation-storage.loan-rules.get', u'circulation-storage.loan-rules.put', u'circulation-storage.loan-policies.collection.get', u'circulation-storage.loan-policies.item.get', u'circulation-storage.loan-policies.item.post', u'circulation-storage.loan-policies.item.put', u'circulation-storage.loan-policies.item.delete', u'circulation-storage.loan-policies.collection.delete', u'circulation-storage.requests.collection.get', u'circulation-storage.requests.item.get', u'circulation-storage.requests.item.post', u'circulation-storage.requests.item.put', u'circulation-storage.requests.item.delete', u'circulation-storage.requests.collection.delete', u'circulation-storage.fixed-due-date-schedules.collection.delete', u'circulation-storage.fixed-due-date-schedules.item.delete', u'circulation-storage.fixed-due-date-schedules.item.put', u'circulation-storage.fixed-due-date-schedules.item.post', u'circulation-storage.fixed-due-date-schedules.item.get', u'circulation-storage.fixed-due-date-schedules.collection.get', u'circulation-storage.staff-slips.item.delete', u'circulation-storage.staff-slips.collection.delete', u'circulation-storage.staff-slips.collection.get', u'circulation-storage.staff-slips.item.post', u'circulation-storage.staff-slips.item.put', u'circulation-storage.staff-slips.item.get'], u'mutable': False, u'id': u'2f2048b5-1438-43b5-85aa-6bdf56ab63fa', u'grantedTo': []}

)

Comment by John Malconian [ 26/Jun/18 ]

Permissions for pr_413_8_admin:

[malc@ip-10-36-20-124 scripts]$ curl -s -D - -X POST -d '

{ "username": "pr_413_8_admin", "password": "admin"}

' -H 'X-Okapi-Tenant: pr_413_8' -H 'Accept: application/json, text/plain' -H 'Content-Type: application/json' http://folio-snapshot-stable.aws.indexdata.com:9130/bl-users/login
HTTP/1.1 201 Created
X-Okapi-Trace: POST mod-authtoken-1.4.1-SNAPSHOT.21 http://10.36.1.145:9135/bl-users/login : 202 871us
Content-Type: application/json
x-okapi-token: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJwcl80MTNfOF9hZG1pbiIsInVzZXJfaWQiOiIzZTBhYmY5ZC1jNmExLTQ0MDMtYjNjNS00MjQ2ZDExODk4ZGUiLCJ0ZW5hbnQiOiJwcl80MTNfOCJ9.vgGfVY43rPpbQ4pIvcOB6ICwmCloQ04RsI5F-IRZYT08S_stf5Sv7PChGVhzL3XDw27OhbiOfloi59aJQZwCLA
host: folio-snapshot-stable.aws.indexdata.com:9130
user-agent: curl/7.53.1
x-okapi-tenant: pr_413_8
accept: application/json, text/plain
x-okapi-request-id: 803481/bl-users
x-okapi-url: http://10.36.1.145:9130
x-okapi-permissions: []
X-Okapi-Trace: POST mod-users-bl-3.0.0-SNAPSHOT.17 http://10.36.1.145:9134/bl-users/login : 201 59073us
Transfer-Encoding: chunked

{
"user" : {
"username" : "pr_413_8_admin",
"id" : "3e0abf9d-c6a1-4403-b3c5-4246d11898de",
"active" : true,
"proxyFor" : [ ],
"personal" :

{ "lastName" : "ADMINISTRATOR", "firstName" : "pr_413_8", "email" : "admin@pr_413_8.example.org", "addresses" : [ ] }

},
"permissions" :

{ "id" : "e1b32f6b-2393-4655-851a-13a614c3c2da", "userId" : "3e0abf9d-c6a1-4403-b3c5-4246d11898de", "permissions" : [ "perms.all", "ui-checkin.all", "ui-checkout.all", "settings.checkout.enabled", "ui-circulation.settings.fixed-due-date-schedules", "settings.developer.enabled", "settings.loan-policies.all", "settings.loan-rules.all", "module.developer.enabled", "ui-inventory.all-permissions.TEMPORARY", "ui-inventory.settings.materialtypes", "ui-inventory.settings.loantypes", "ui-inventory.settings.instance-formats", "module.organization.enabled", "ui-organization.settings.key-bindings", "ui-organization.settings.locale", "ui-organization.settings.plugins", "ui-inventory.settings.instance-types", "ui-inventory.settings.contributor-types", "ui-organization.settings.location", "ui-organization.settings.sso", "circulation.all", "ui-requests.all", "module.search.enabled", "circulation-storage.all", "configuration.all", "inventory.all", "login-saml.all", "ui-users.editperms", "inventory-storage.all", "notify.all", "users.all", "okapi.proxy.pull.modules.post", "okapi.all", "ui-users.create", "module.notes.enabled", "ui-users.editproxies", "ui-users.editpermsets", "settings.usergroups.all", "login.all", "users-bl.all", "stripes-util-notes.all", "stripes-util-notes.edit", "stripes-util-notes.create", "stripes-util-notes.delete", "settings.addresstypes.all" ] }

,
"proxiesFor" : [ ]
}

Permissions for pr_413_9_admin:

[malc@ip-10-36-20-124 scripts]$ curl -s -D - -XPOST -d '

{ "username": "pr_413_9_admin", "password": "admin"}

' -H 'X-Okapi-Tenant: pr_413_9' -H 'Accept: application/json, text/plain' -H 'Content-Type: application/json' http://folio-snapshot-stable.aws.indexdata.com:9130/bl-users/login
HTTP/1.1 201 Created
X-Okapi-Trace: POST mod-authtoken-1.4.1-SNAPSHOT.21 http://10.36.1.145:9135/bl-users/login : 202 795us
Content-Type: application/json
x-okapi-token: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJwcl80MTNfOV9hZG1pbiIsInVzZXJfaWQiOiJhNTVjNjdiZC1mODIxLTQ0OGQtYjM1OS0wNDhlNjZmOTBkOTciLCJ0ZW5hbnQiOiJwcl80MTNfOSJ9.zeg0CW89Bmyg4PvEnwYIyk7IDFRbtrRrultw1uKOCNxUVlQukzXSYQdIckaBKORoGx_EqxEtleW1W_zGgxLAjQ
host: folio-snapshot-stable.aws.indexdata.com:9130
user-agent: curl/7.53.1
x-okapi-tenant: pr_413_9
accept: application/json, text/plain
x-okapi-request-id: 710602/bl-users
x-okapi-url: http://10.36.1.145:9130
x-okapi-permissions: []
X-Okapi-Trace: POST mod-users-bl-3.0.0-SNAPSHOT.17 http://10.36.1.145:9134/bl-users/login : 201 61576us
Transfer-Encoding: chunked

{
"user" : {
"username" : "pr_413_9_admin",
"id" : "a55c67bd-f821-448d-b359-048e66f90d97",
"active" : true,
"proxyFor" : [ ],
"personal" :

{ "lastName" : "ADMINISTRATOR", "firstName" : "pr_413_9", "email" : "admin@pr_413_9.example.org", "addresses" : [ ] }

},
"permissions" :

{ "id" : "1797943f-0899-4e6f-9f38-76a3379924b1", "userId" : "a55c67bd-f821-448d-b359-048e66f90d97", "permissions" : [ "perms.all", "ui-checkin.all", "ui-checkout.all", "settings.checkout.enabled", "settings.loan-rules.all", "settings.loan-policies.all", "module.developer.enabled", "ui-inventory.settings.instance-types", "ui-inventory.all-permissions.TEMPORARY", "ui-circulation.settings.fixed-due-date-schedules", "settings.developer.enabled", "ui-inventory.settings.contributor-types", "ui-inventory.settings.loantypes", "module.organization.enabled", "module.search.enabled", "ui-inventory.settings.materialtypes", "ui-inventory.settings.instance-formats", "ui-organization.settings.key-bindings", "ui-organization.settings.locale", "ui-organization.settings.plugins", "ui-organization.settings.sso", "ui-requests.all", "circulation-storage.all", "ui-organization.settings.location", "circulation.all", "inventory.all", "configuration.all", "ui-users.editperms", "inventory-storage.all", "users.all", "okapi.proxy.pull.modules.post", "login-saml.all", "okapi.all", "notify.all", "settings.addresstypes.all", "login.all", "module.notes.enabled", "settings.usergroups.all", "users-bl.all", "stripes-util-notes.all", "stripes-util-notes.edit", "stripes-util-notes.create", "stripes-util-notes.delete", "ui-users.create", "ui-users.editproxies", "ui-users.editpermsets" ] }

,
"proxiesFor" : [ ]
}

Comment by John Malconian [ 26/Jun/18 ]

Both tenant admin users have 'circulation-storage.all' defined which I assume includes 'circulation-storage.loan-policies.item.post'

Comment by John Malconian [ 26/Jun/18 ]

The task that loads the loan policies looks like this:

  • name: Load loan policies
    uri:
    url: "{{ okapi_url }}/loan-policy-storage/loan-policies"
    method: POST
    body_format: json
    headers:
    Authtoken-Refresh-Cache: "true"
    X-Okapi-Tenant: "{{ tenant }}"
    Accept: application/json
    X-Okapi-Token: "{{ tenant_admin_login.x_okapi_token | default('token') }}"
    body: "{{ lookup('file', item) }}"
    status_code: 201, 422, 500
    register: load_loanp
    changed_when: load_loanp.status == 201
    with_fileglob:
  • loan-policies/*.json

I wonder if the header 'Authtoken-Refresh-Cache: "true"' may have something to do with this.

Comment by John Malconian [ 26/Jun/18 ]

the permission 'circulation-storage.all' is created and granted to the tenant admin user minutes prior to when this request is made and approximately a few seconds after the tenant admin user is granted the x_okapi_token that is used in the request.

Comment by John Malconian [ 10/Jul/18 ]

I believe this might be resolved by MODAT-27 Closed but I will it open for a little longer to see if the issue manifests itself again.

Comment by John Malconian [ 18/Jul/18 ]

Haven't seen problem since MODAT-27 Closed has been resolved. Closing issue.

Comment by John Malconian [ 19/Jul/18 ]

Re-opening this issue. New instance of failure detected.

https://jenkins-aws.indexdata.com/job/folio-org/job/ui-checkout/job/PR-158/2/console

Comment by John Malconian [ 19/Jul/18 ]

I thought maybe the admin user became 'inactive' maybe, but that does not appear to be the case:

[malc@ip-10-36-20-124 scripts]$ curl -H "x-okapi-token: $OKAPI_TOKEN" -H "x-okapi-tenant: pr_158_2" -H "Content-Type: application/json" $

{OKAPI_URL}

/users
{
"users" : [ {
"username" : "pr_158_2_admin",
"id" : "8965408e-13df-59b1-b927-f7324aa5771a",
"active" : true,
"proxyFor" : [ ],
"personal" :

{ "lastName" : "pr_158_2", "firstName" : "Admin", "email" : "admin@example.org", "addresses" : [ ] }

} ],
"totalRecords" : 1,
"resultInfo" :

{ "totalRecords" : 1, "facets" : [ ], "diagnostics" : [ ] }
Comment by John Malconian [ 19/Jul/18 ]

Log snippet:

2018-07-19 16:42:35,777 INFO  DockerModuleHandle   mod-permissions-5.2.5-SNAPSHOT.22 16:42:35 INFO  PermsAPI             Calling getExpandedPermissionsSequential with permissionList: inventory-storage.location-units.campuses.item.get, inventory-storage.location-units.campuses.item.post, inventory-storage.location-units.campuses.item.put, inventory-storage.location-units.campuses.item.delete, inventory-storage.location-units.libraries.collection.get, inventory-storage.location-units.libraries.item.get, inventory-storage.location-units.libraries.item.post, inventory-storage.location-units.libraries.item.put, inventory-storage.location-units.libraries.item.delete, inventory-storage.locations.collection.get, inventory-storage.locations.item.get, inventory-storage.locations.item.post, inventory-storage.locations.item.put, inventory-storage.locations.item.delete, inventory-storage.identifier-types.collection.get
2018-07-19 16:42:35,780 INFO  ProxyContext         954162/classification-types REQ 10.36.20.139:36938 pr_158_2 POST /classification-types mod-authtoken-1.4.1-SNAPSHOT.21 mod-inventory-storage-12.1.0-SNAPSHOT.128
2018-07-19 16:42:35,781 WARN  ProxyService         relayToResponse XXX Returning direct response 403
2018-07-19 16:42:35,781 INFO  ProxyContext         954162/classification-types RES 403 617us mod-authtoken-1.4.1-SNAPSHOT.21 http://10.36.1.64:9135/classification-types
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 getUserAndExpandedPermissions, userid=8965408e-13df-59b1-b927-f7324aa5771apermissions=[]
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 completing future with user permissions=[], expanded permissions=[]
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 Jul 19, 2018 4:42:35 PM mod-auth-authtoken-module
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 INFO: Retrieving permissions for userid 8965408e-13df-59b1-b927-f7324aa5771a and expanding permissions for []
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 Jul 19, 2018 4:42:35 PM mod-auth-authtoken-module
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 INFO: Retrieving permissions for userid 8965408e-13df-59b1-b927-f7324aa5771a, and expanded permissions for []
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 Jul 19, 2018 4:42:35 PM mod-auth-authtoken-module
2018-07-19 16:42:35,784 INFO  DockerModuleHandle   mod-authtoken-1.4.1-SNAPSHOT.21 SEVERE: [](user permissions) nor [](module permissions) do not contain inventory-storage.classification-types.item.post
Comment by John Malconian [ 19/Jul/18 ]

Permissions for user pr_158_2_admin:

ubuntu@ip-10-36-1-64:~$ curl -s -D - -X POST -d '{ "username": "pr_158_2_admin", "password": "admin"}' -H 'X-Okapi-Tenant: pr_158_2' -H 'Accept: application/json, text/plain' -H 'Content-Type: application/json' http://folio-snapshot-stable.aws.indexdata.com:9130/bl-users/login
HTTP/1.1 201 Created
X-Okapi-Trace: POST mod-authtoken-1.4.1-SNAPSHOT.21 http://10.36.1.64:9135/bl-users/login : 202 854us
Content-Type: application/json
x-okapi-token: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJwcl8xNThfMl9hZG1pbiIsInVzZXJfaWQiOiI4OTY1NDA4ZS0xM2RmLTU5YjEtYjkyNy1mNzMyNGFhNTc3MWEiLCJ0ZW5hbnQiOiJwcl8xNThfMiJ9.gKQ3UyFROWL5A8A4RaYD3f4Jm7l8Z2JJCGmuECTfVtqUoC-sRRl_Jg25KCO4O-xAY7ijZ2fuq8_KhWaCIkRULg
host: folio-snapshot-stable.aws.indexdata.com:9130
user-agent: curl/7.47.0
x-okapi-tenant: pr_158_2
accept: application/json, text/plain
x-okapi-request-id: 150912/bl-users
x-okapi-url: http://10.36.1.64:9130
x-okapi-permissions: []
X-Okapi-Trace: POST mod-users-bl-3.0.0-SNAPSHOT.17 http://10.36.1.64:9134/bl-users/login : 201 60350us
Transfer-Encoding: chunked

{
  "user" : {
    "username" : "pr_158_2_admin",
    "id" : "8965408e-13df-59b1-b927-f7324aa5771a",
    "active" : true,
    "proxyFor" : [ ],
    "personal" : {
      "lastName" : "pr_158_2",
      "firstName" : "Admin",
      "email" : "admin@example.org",
      "addresses" : [ ]
    }
  },
  "permissions" : {
    "id" : "de79044f-f0a5-524c-8e01-0c7eaf9e8018",
    "userId" : "8965408e-13df-59b1-b927-f7324aa5771a",
    "permissions" : [ "perms.all", "login.all", "users.all", "ui-checkin.all", "ui-checkout.all", "settings.checkout.enabled", "settings.loan-policies.all", "ui-circulation.settings.fixed-due-date-schedules", "module.developer.enabled", "ui-inventory.settings.contributor-types", "settings.loan-rules.all", "ui-inventory.settings.materialtypes", "ui-inventory.settings.loantypes", "ui-circulation.settings.cancellation-reasons", "ui-inventory.settings.instance-formats", "settings.developer.enabled", "ui-inventory.settings.instance-types", "module.organization.enabled", "ui-requests.all", "ui-inventory.all-permissions.TEMPORARY", "module.search.enabled", "circulation-storage.all", "ui-organization.settings.key-bindings", "ui-organization.settings.locale", "ui-organization.settings.plugins", "ui-organization.settings.sso", "okapi.proxy.pull.modules.post", "okapi.all", "inventory.all", "ui-organization.settings.location", "circulation.all", "configuration.all", "notify.all", "settings.enabled", "inventory-storage.all", "login-saml.all", "users-bl.all", "stripes-util-notes.all", "stripes-util-notes.edit", "module.notes.enabled", "stripes-util-notes.create", "stripes-util-notes.delete" ]
  },
  "proxiesFor" : [ ]
Comment by John Malconian [ 19/Jul/18 ]

Kurt Nordstrom suggested setting the header 'Authtoken-Refresh-Cache: true' in the data loading requests. Updated folio-ansible/roles/module-sample-data/tasks/load-data.yml.

Will also attempt to see if I can set something up that runs in a loop in an attempt to duplicate the error.

Comment by John Malconian [ 20/Jul/18 ]

Looks like adding Authtoken-Refresh-Cache: true has exacerbated the issue. There were at least a half dozen failures overnight. Here are a few examples:

https://jenkins-aws.indexdata.com/job/folio-org/job/ui-users/job/PR-429/7/console
https://jenkins-aws.indexdata.com/job/folio-org/job/ui-users/job/PR-433/6/console
https://jenkins-aws.indexdata.com/job/folio-org/job/ui-checkout/job/PR-151/12/console

Comment by Kurt Nordstrom [ 20/Jul/18 ]

Well, crap, that's not how it was supposed to work!

Will investigate and let you know what I find.

Comment by John Malconian [ 24/Jul/18 ]

I ran a loop that created tenants. enabled modules, assigned permissions, and loaded sample data exactly how jenkins is configured and am unable to reproduce a single failure. About 50 tenants created. I'm going to continue to see if I can generate an error, but have a feeling that I won't. That's making this issue all the more perplexing. Something environmental? Will look into other approaches.

Comment by John Malconian [ 24/Jul/18 ]

Ran another loop of 40 tenants. No errors.

Comment by John Malconian [ 31/Jul/18 ]

Most recent PR failure due to this issue:

https://jenkins-aws.indexdata.com/job/folio-org/job/ui-users/job/PR-413/21/

TASK [folio-ansible/roles/module-sample-data : Load module data to /loan-policy-storage/loan-policies] ***
failed: [localhost] (item=/tmp/ansible.K4GiNK/mod-circulation-storage/reference-data/loan-policy-storage/loan-policies/one-hour.json) =>

{"changed": false, "connection": "close", "content": "Access requires permission: circulation-storage.loan-policies.item.post", "data_file": "/tmp/ansible.K4GiNK/mod-circulation-storage/reference-data/loan-policy-storage/loan-policies/one-hour.json", "msg": "Status code was 403 and not [201, 500]: HTTP Error 403: Forbidden", "redirected": false, "status": 403, "transfer_encoding": "chunked", "url": "http://folio-snapshot-stable.aws.indexdata.com:9130/loan-policy-storage/loan-policies", "x_okapi_trace": "POST mod-authtoken-1.5.1-SNAPSHOT.24 http://10.36.1.143:9135/loan-policy-storage/loan-policies : 403 27874us"}

failed: [localhost] (item=/tmp/ansible.K4GiNK/mod-circulation-storage/reference-data/loan-policy-storage/loan-policies/rolling.json) =>

{"changed": false, "connection": "close", "content": "Access requires permission: circulation-storage.loan-policies.item.post", "data_file": "/tmp/ansible.K4GiNK/mod-circulation-storage/reference-data/loan-policy-storage/loan-policies/rolling.json", "msg": "Status code was 403 and not [201, 500]: HTTP Error 403: Forbidden", "redirected": false, "status": 403, "transfer_encoding": "chunked", "url": "http://folio-snapshot-stable.aws.indexdata.com:9130/loan-policy-storage/loan-policies", "x_okapi_trace": "POST mod-authtoken-1.5.1-SNAPSHOT.24 http://10.36.1.143:9135/loan-policy-storage/loan-policies : 403 870us"}

I've re-added 'Authtoken-Refresh-Cache: "true" header to Ansible module-sample-data role. Hoping for different result after Kurt's bugfix here: https://github.com/folio-org/mod-authtoken/commit/79eea50d23a7f441eac220b79fba089bcf4ea844

Comment by John Malconian [ 01/Aug/18 ]

Another error here this morning after enabling 'Authtoken-Refresh-Cache: "true":

https://jenkins-aws.indexdata.com/job/folio-org/job/ui-organization/job/PR-72/18/console

failed: [localhost] (item=/tmp/ansible.aojbH0/mod-inventory-storage/reference-data/contributor-types/Degreegrantinginstitution.json) =>

{"changed": false, "connection": "close", "content": "Access requires permission: inventory-storage.contributor-types.item.post", "data_file": "/tmp/ansible.aojbH0/mod-inventory-storage/reference-data/contributor-types/Degreegrantinginstitution.json", "msg": "Status code was 403 and not [201, 400]: HTTP Error 403: Forbidden", "redirected": false, "status": 403, "transfer_encoding": "chunked", "url": "http://folio-snapshot-stable.aws.indexdata.com:9130/contributor-types", "x_okapi_trace": "POST mod-authtoken-1.5.1-SNAPSHOT.24 http://10.36.1.143:9135/contributor-types : 403 16360us"}
Comment by John Malconian [ 01/Aug/18 ]

I think the issue here is that there is a tenant admin user and tenant mismatch occurring.

This build - https://jenkins-aws.indexdata.com/job/folio-org/job/ui-organization/view/change-requests/job/PR-72/18/ - which creates tenant 'pr_72_18' with a tenant admin user called 'pr_72_18_admin' and this build -
https://jenkins-aws.indexdata.com/job/folio-org/job/ui-organization/view/change-requests/job/PR-99/6/ - which creates tenant, 'pr_99_6' with a tenant admin user called 'pr_99_6_admin' were triggered at the same time and pretty much ran in parallel.

Here are the attributes of the 'pr_72_18_admin' user:

ubuntu@ip-10-36-1-143:~$ curl -s -D - -X POST -d '{ "username": "pr_72_18_admin", "password": "admin"}' -H 'X-Okapi-Tenant: pr_72_18' -H 'Accept: application/json, text/plain' -H 'Content-Type: application/json' http://folio-snapshot-stable.aws.indexdata.com:9130/bl-users/login
HTTP/1.1 201 Created
X-Okapi-Trace: POST mod-authtoken-1.5.1-SNAPSHOT.24 http://10.36.1.143:9135/bl-users/login : 202 612us
Content-Type: application/json
x-okapi-token: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJwcl83Ml8xOF9hZG1pbiIsInVzZXJfaWQiOiIyM2NmMTM3YS1mNzkxLTUwNjYtOWE0Ny0wYmEwYzk3OGJhYzQiLCJ0ZW5hbnQiOiJwcl83Ml8xOCIsImlhdCI6MTUzMzEzNzM1OH0.HRwAsqc8jSZt01Nqqe0V00pTWyNkczEcYTalvM0Zx3oAVJO3vwY0T3XUD-EDHZDmCNp_vMnK2d2gyO8BpEHJGw
host: folio-snapshot-stable.aws.indexdata.com:9130
user-agent: curl/7.47.0
x-okapi-tenant: pr_72_18
accept: application/json, text/plain
x-okapi-request-id: 354913/bl-users
x-okapi-url: http://10.36.1.143:9130
x-okapi-permissions: []
X-Okapi-Trace: POST mod-users-bl-3.0.0-SNAPSHOT.19 http://10.36.1.143:9134/bl-users/login : 201 63516us
Transfer-Encoding: chunked

{
  "user" : {
    "username" : "pr_72_18_admin",
    "id" : "23cf137a-f791-5066-9a47-0ba0c978bac4",
    "active" : true,
    "proxyFor" : [ ],
    "personal" : {
      "lastName" : "pr_72_18",
      "firstName" : "Admin",
      "email" : "admin@example.org",
      "addresses" : [ ]
    }
  },
  "permissions" : {
    "id" : "305e8b1c-659a-595a-9718-ebba56792100",
    "userId" : "23cf137a-f791-5066-9a47-0ba0c978bac4",
    "permissions" : [ "perms.all", "login.all", "users.all", "ui-checkin.all", "ui-checkout.all", "settings.checkout.enabled", "settings.loan-policies.all", "ui-circulation.settings.fixed-due-date-schedules", "ui-circulation.settings.cancellation-reasons", "module.organization.enabled", "module.search.enabled", "settings.loan-rules.all", "module.developer.enabled", "ui-inventory.settings.instance-types", "settings.developer.enabled", "ui-inventory.settings.instance-formats", "ui-organization.settings.location", "ui-inventory.all-permissions.TEMPORARY", "ui-inventory.settings.materialtypes", "ui-inventory.settings.loantypes", "ui-organization.settings.key-bindings", "ui-organization.settings.locale", "ui-organization.settings.plugins", "ui-organization.settings.sso", "ui-inventory.settings.contributor-types", "circulation.all", "ui-requests.all", "circulation-storage.all", "inventory.all", "configuration.all", "login-saml.all", "okapi.proxy.pull.modules.post", "okapi.all", "notify.all", "inventory-storage.all", "ui-users.create", "settings.comments.all", "settings.feefines.all", "module.notes.enabled", "tags.all", "settings.refunds.all", "users-bl.all", "stripes-util-notes.all", "module.tags.enabled", "settings.usergroups.all", "stripes-util-notes.edit", "stripes-util-notes.create", "stripes-util-notes.delete", "settings.tags.enabled", "settings.waives.all", "settings.accounts.all", "settings.transfers.all", "feesfines.all", "ui-users.editperms", "ui-users.editproxies", "settings.owners.all", "settings.feefineactions.all", "settings.transfertypes.all", "ui-users.editpermsets", "settings.payments.all", "settings.addresstypes.all" ]
  },
  "proxiesFor" : [ ]
}

Here are the attributes of the pr_99_6_admin user:

ubuntu@ip-10-36-1-143:~$ curl -s -D - -X POST -d '{ "username": "pr_99_6_admin", "password": "admin"}' -H 'X-Okapi-Tenant: pr_99_6' -H 'Accept: application/json, text/plain' -H 'Content-Type: application/json' http://folio-snapshot-stable.aws.indexdata.com:9130/bl-users/login
HTTP/1.1 201 Created
X-Okapi-Trace: POST mod-authtoken-1.5.1-SNAPSHOT.24 http://10.36.1.143:9135/bl-users/login : 202 730us
Content-Type: application/json
x-okapi-token: eyJhbGciOiJIUzUxMiJ9.eyJzdWIiOiJwcl85OV82X2FkbWluIiwidXNlcl9pZCI6ImJlNDVkNDFkLTAwYmItNWEwMC1iMTg5LWYyMDliZTEyMzM0YSIsInRlbmFudCI6InByXzk5XzYiLCJpYXQiOjE1MzMxMzc3NDF9.j1WCtmbpmdC154AlUGl4dQVd4dIaLegN4EbIwCf0qDE4ygVceh936Ju92S6YplHC7HR-LCWzvY925P31Swe8Ig
host: folio-snapshot-stable.aws.indexdata.com:9130
user-agent: curl/7.47.0
x-okapi-tenant: pr_99_6
accept: application/json, text/plain
x-okapi-request-id: 850488/bl-users
x-okapi-url: http://10.36.1.143:9130
x-okapi-permissions: []
X-Okapi-Trace: POST mod-users-bl-3.0.0-SNAPSHOT.19 http://10.36.1.143:9134/bl-users/login : 201 70740us
Transfer-Encoding: chunked

{
  "user" : {
    "username" : "pr_99_6_admin",
    "id" : "be45d41d-00bb-5a00-b189-f209be12334a",
    "active" : true,
    "proxyFor" : [ ],
    "personal" : {
      "lastName" : "pr_99_6",
      "firstName" : "Admin",
      "email" : "admin@example.org",
      "addresses" : [ ]
    }
  },
  "permissions" : {
    "id" : "fa2fb195-de51-5b4e-935b-2b420de46db0",
    "userId" : "be45d41d-00bb-5a00-b189-f209be12334a",
    "permissions" : [ "perms.all", "login.all", "users.all", "ui-checkin.all", "ui-checkout.all", "settings.checkout.enabled", "settings.loan-policies.all", "ui-circulation.settings.cancellation-reasons", "module.developer.enabled", "ui-inventory.settings.loantypes", "settings.loan-rules.all", "settings.developer.enabled", "inventory.all", "ui-circulation.settings.fixed-due-date-schedules", "ui-inventory.all-permissions.TEMPORARY", "ui-inventory.settings.materialtypes", "ui-inventory.settings.instance-formats", "module.organization.enabled", "ui-inventory.settings.instance-types", "ui-inventory.settings.contributor-types", "ui-organization.settings.key-bindings", "ui-organization.settings.locale", "ui-organization.settings.plugins", "ui-organization.settings.sso", "ui-organization.settings.location", "ui-requests.all", "module.search.enabled", "circulation.all", "configuration.all", "circulation-storage.all", "okapi.all", "module.notes.enabled", "module.tags.enabled", "login-saml.all", "notify.all", "inventory-storage.all", "okapi.proxy.pull.modules.post", "feesfines.all", "settings.tags.enabled", "ui-users.create", "settings.feefines.all", "settings.payments.all", "users-bl.all", "stripes-util-notes.all", "stripes-util-notes.edit", "stripes-util-notes.create", "stripes-util-notes.delete", "tags.all", "settings.comments.all", "settings.feefineactions.all", "ui-users.editperms", "ui-users.editproxies", "settings.owners.all", "settings.refunds.all", "settings.waives.all", "settings.accounts.all", "settings.usergroups.all", "settings.transfers.all", "settings.transfertypes.all", "settings.addresstypes.all", "ui-users.editpermsets" ]
  },
  "proxiesFor" : [ ]
}

Here is the okapi log where the error occurred:

2018-08-01 11:26:41,331 INFO  DockerModuleHandle   mod-permissions-5.3.0-SNAPSHOT.25 11:26:41 INFO  LogUtil              org.folio.rest.RestVerticle start  invoking getPermsUsersByIdPermissions
2018-08-01 11:26:41,331 INFO  DockerModuleHandle   mod-permissions-5.3.0-SNAPSHOT.25 11:26:41 INFO  LogUtil              10.36.1.143:37756 GET /perms/users/305e8b1c-659a-595a-9718-ebba56792100/permissions expanded=true HTTP_1_1 404 56 1 tid=pr_99_6 Not Found
2018-08-01 11:26:41,331 WARN  ProxyService         relayToResponse XXX Returning direct response 403
2018-08-01 11:26:41,331 INFO  ProxyContext         001166/contributor-types RES 403 16365us mod-authtoken-1.5.1-SNAPSHOT.24 http://10.36.1.143:9135/contributor-types
2018-08-01 11:26:41,331 INFO  DockerModuleHandle   mod-authtoken-1.5.1-SNAPSHOT.24 Aug 01, 2018 11:26:41 AM mod-auth-authtoken-module
2018-08-01 11:26:41,331 INFO  DockerModuleHandle   mod-authtoken-1.5.1-SNAPSHOT.24 SEVERE: [](user permissions) nor [](module permissions) do not contain inventory-storage.contributor-types.item.post
2018-08-01 11:26:41,331 INFO  DockerModuleHandle   mod-authtoken-1.5.1-SNAPSHOT.24 completing future with user permissions=[], expanded permissions=[]

Note the following line in particular:

10.36.1.143:37756 GET /perms/users/305e8b1c-659a-595a-9718-ebba56792100/permissions expanded=true HTTP_1_1 404 56 1 tid=pr_99_6 Not Found

In the above line, the tenant admin's permissions id is '305e8b1c-659a-595a-9718-ebba56792100'. This is the permissions id for the tenant admin user 'pr_72_18_admin'. However, also note that the 'tid' logged in pr_99_6. This tenant user and the tenant do not match.

Comment by John Malconian [ 01/Aug/18 ]

I guess the question is what is causing this mismatch. Something environmental on the Jenkins side that is passing the wrong tenant in a header or is this a bug in okapi or one of the modules.

Comment by John Malconian [ 01/Aug/18 ]

attached okapi log file that contains the error for tenant, pr_72_18.

Comment by John Malconian [ 02/Aug/18 ]

I'm able to duplicate this problem rather easily outside of Jenkins by creating two tenants and bootstrapping tenant data almost simultaneously. So its not a CI issue.

Comment by Adam Dickmeiss [ 02/Aug/18 ]

Excellent. Then we can try this locally.. Please supply the produce/script ..

Comment by John Malconian [ 02/Aug/18 ]

Adam Dickmeiss I'll attempt to package something up you can run easily. The data loading is via ansible.

Comment by John Malconian [ 02/Aug/18 ]

Adam Dickmeiss I've cobbled together some bash scripts so that you do not have to deal with setting up an Ansible environment. I was able to replicate the issue on the first try with these scripts.

Steps to run:

  • make sure you have 'curl' and 'jq' installed.
  • clone https://github.com/folio-org/folio-infrastructure
  • cd folio-infrastructure/CI/scripts
  • take a look at the modules listed in the file 'tenant_module_list'. Make sure you have Okapi and those modules deployed already. Update the file if the versions of the modules listed differ slightly from the modules you have deployed.
  • take a look at bootstrapTenant.sh and update 'okapiUrl' and the Postgres env info accordingly.
  • run './bootstrapTenant.sh tenant1 > tenant1.log 2>&1 &'
  • and then run another instance immediately afterward, './bootstrapTenant.sh tenant2 > tenant2.log 2>&1 &', so that the two are running somewhat in parallel.
  • grep for the string 'Access requires permission' in both tenant logs when the scripts are complete. This indicates there was a permissions problem as reported above. Check the okapi logs for additional details.
Comment by Jakub Skoczen [ 06/Aug/18 ]

Heikki Levanto or Kurt Nordstrom would it make sense for one of you to look into it while Adam is away?

Comment by Heikki Levanto [ 07/Aug/18 ]

I can take a look

Comment by Heikki Levanto [ 07/Aug/18 ]

I tried to reproduce this locally. Run into small problems with the maze of small scripts, and assumptions about database setups, so never got to the point where it would load the reference data. Now I need to move on to other things.

Comment by Jakub Skoczen [ 08/Aug/18 ]

Adam Dickmeiss can you look into this first thing after you get back? Thanks!

Comment by Adam Dickmeiss [ 09/Aug/18 ]

From code inspection, I think the problem is in mod-authtoken. It has a class, ModulePermissionsSource, which is created once (for all tenants) and it has a member (tenant) which will be inconsistent whenever requests is made to handleAuthorize. I'll try to fix and make a PR.

Comment by Adam Dickmeiss [ 09/Aug/18 ]

Made a pull request: See MODAT-29 Closed

Comment by Adam Dickmeiss [ 10/Aug/18 ]

John Malconian .. When convenient, please check if the issue goes away with mod-authtoken from master.

Comment by Jakub Skoczen [ 15/Aug/18 ]

John Malconian what's the latest status here?

Comment by John Malconian [ 15/Aug/18 ]

I still need to verify if this is fixed.

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