yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1953555] [NEW] keystone ldap request not sending out promptly during stack creation

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Johnny Yang <1953555@xxxxxxxxxxxxxxxxxx>
Date: Tue, 07 Dec 2021 22:59:31 -0000
Reply-to: Bug 1953555 <1953555@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
Public bug reported:

We are deploying openstack victoria using kolla ansible tool into our baremetal/VM based clusters. After installation, when we creates user heat stacks from kolla_toolbox, every time we are failed with example error message as 
=====
(kolla-toolbox)[root@kolla-controller2 /]# openstack stack create --wait --parameter project=new-test.cedev17.d103.eng.pdx.wd -t /opt/heat_templates/templates/monitoring_role_assignment.yaml monitoring_role_assignment
2021-10-26 21:33:29Z [monitoring_role_assignment]: CREATE_IN_PROGRESS  Stack CREATE started
2021-10-26 21:33:29Z [monitoring_role_assignment.name_translation]: CREATE_IN_PROGRESS  state changed
2021-10-26 21:33:29Z [monitoring_role_assignment.name_translation]: CREATE_COMPLETE  state changed
2021-10-26 21:33:29Z [monitoring_role_assignment]: CREATE_FAILED  No user with a name or ID of 'wpc-monitoring-dev' exists.

 Stack monitoring_role_assignment CREATE_FAILED
======
wpc-monitoring-dev is one user in our dev env.
indeed, we have checked ldap server side that user "wpc-monitoring-dev" existed in ldap db.
===
(kolla-toolbox)[root@s-mxq0400p0d /]# openstack user list --domain wday | grep wpc-monitoring-dev
| 9182fdc1858c5dd5568186ca93c41ea403f24058568dfe2aa67c5e7528d5ddc4 | wpc-monitoring-dev
===

What we found out in the keystone log:
====
2021-10-21 21:39:47.387 55 WARNING keystone.server.flask.application [req-f8564b31-11cb-4bba-bda3-78160f92d21e d9ab538e492e40c8853d7741d74d57ea 73b5eb12562c458e963fd7a9223d5a4a - default default] Could not find role: admin.: keystone.exception.RoleNotFound: Could not find role: admin.
2021-10-21 21:39:49.112 52 WARNING keystone.server.flask.application [req-7d729047-1ae4-4a62-8b31-ec7c59530595 d9ab538e492e40c8853d7741d74d57ea 73b5eb12562c458e963fd7a9223d5a4a - default default] Could not find user: wpc-monitoring-dev.: keystone.exception.UserNotFound: Could not find user: wpc-monitoring-dev.
====

what we observed:
=====
1. if we tapping on our outgoing networking interface such as eth0, we did not find any ldap query packets sent out to ldap server when this stack creation error happens. on the other hand, if stack creation success, there are a few ldap query and response packet going thorough the interface eth0.
2. if we restart all keystone containers once after initial kolla installation, then stack creation will work successfully as normal and there is no error in creating heat stacks.
====

some additional lgos we observed, not sure if it is completely related:
====

2021-10-25 17:31:59.375 47 DEBUG passlib.handlers.bcrypt [req-70fb1480-4a60-4461-a700-f83a5614e679 - - - - -] 'bcrypt' backend lacks $2$ support, enabling workaround _finalize_backend_mixin /var/lib/kolla/venv/lib/python3.6/site-packages/passlib/handlers/bcrypt.py:382
2021-10-25 17:31:59.663 47 DEBUG keystone.auth.core [req-70fb1480-4a60-4461-a700-f83a5614e679 - - - - -] MFA Rules not processed for user `c146b2b4e81d4028b51f22a9c5e58eed`. Rule list: `[]` (Enabled: `True`). check_auth_methods_against_rules /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/auth/core.py:442
2021-10-25 17:32:00.086 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-ed6c6a80-2dc1-44bc-88f1-b63f5d2c4ac5 - - - - -] Authenticating user token process_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:407
2021-10-25 17:32:00.096 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-ed6c6a80-2dc1-44bc-88f1-b63f5d2c4ac5 - - - - -] Validating token access rules against request validate_allowed_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:545
2021-10-25 17:32:00.160 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: auth_context: {'token': <TokenModel (audit_id=V6nY5pWbRxGmAeJEEgpdXw, audit_chain_id=['V6nY5pWbRxGmAeJEEgpdXw']) at 0x7f366a1b2358>, 'domain_id': None, 'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_name': None, 'group_ids': [], 'user_id': '4ad279fe187042999b413328ee4cd0bd', 'user_domain_id': 'default', 'system_scope': None, 'project_id': '2b6837214bd1499a9ff472e55c639283', 'project_domain_id': 'default', 'roles': ['member', 'heat_stack_owner', 'reader', 'admin'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} fill_context /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/middleware/auth_context.py:478
2021-10-25 17:32:00.161 53 DEBUG keystone.server.flask.request_processing.req_logging [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
2021-10-25 17:32:00.161 53 DEBUG keystone.server.flask.request_processing.req_logging [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
2021-10-25 17:32:00.162 53 DEBUG keystone.server.flask.request_processing.req_logging [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] PATH_INFO: `/v3/domains/wday` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29
2021-10-25 17:32:00.171 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorizing `identity:get_domain(domain_id=wday)` enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:442
2021-10-25 17:32:00.184 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorization granted enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:449
2021-10-25 17:32:00.196 53 WARNING keystone.server.flask.application [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] Could not find domain: wday.: keystone.exception.DomainNotFound: Could not find domain: wday.
2021-10-25 17:32:00.414 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-3f6a94a8-0a08-4e4e-9133-c94f36082e92 - - - - -] Authenticating user token process_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:407
2021-10-25 17:32:00.426 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-3f6a94a8-0a08-4e4e-9133-c94f36082e92 - - - - -] Validating token access rules against request validate_allowed_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:545
2021-10-25 17:32:00.433 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: auth_context: {'token': <TokenModel (audit_id=V6nY5pWbRxGmAeJEEgpdXw, audit_chain_id=['V6nY5pWbRxGmAeJEEgpdXw']) at 0x7f3669ebf630>, 'domain_id': None, 'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_name': None, 'group_ids': [], 'user_id': '4ad279fe187042999b413328ee4cd0bd', 'user_domain_id': 'default', 'system_scope': None, 'project_id': '2b6837214bd1499a9ff472e55c639283', 'project_domain_id': 'default', 'roles': ['member', 'heat_stack_owner', 'admin', 'reader'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} fill_context /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/middleware/auth_context.py:478
2021-10-25 17:32:00.434 53 DEBUG keystone.server.flask.request_processing.req_logging [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
2021-10-25 17:32:00.434 53 DEBUG keystone.server.flask.request_processing.req_logging [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
2021-10-25 17:32:00.435 53 DEBUG keystone.server.flask.request_processing.req_logging [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] PATH_INFO: `/v3/users` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29
2021-10-25 17:32:00.435 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Adding query filter params (domain_id=bd9bb1b991894ee498a489ae06e61e89, name=wpc-monitoring-dev) _extract_filter_values /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:161
2021-10-25 17:32:00.436 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorizing `identity:list_users()` enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:442
2021-10-25 17:32:00.447 53 WARNING py.warnings [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_policy/policy.py:1022: UserWarning: Policy identity:list_users failed scope check. The token used to make the request was project scoped but the policy requires ['system', 'domain'] scope. This behavior may change in the future where using the intended scope is required
  warnings.warn(msg)

2021-10-25 17:32:00.448 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorization granted enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:449
=======


2021-10-25 17:32:00.258 52 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-f2d776b4-5f7b-4aea-ab47-878080af2046 - - - - -] Authenticating user token process_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:407
2021-10-25 17:32:00.296 52 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-f2d776b4-5f7b-4aea-ab47-878080af2046 - - - - -] Validating token access rules against request validate_allowed_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:545
2021-10-25 17:32:00.305 52 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: auth_context: {'token': <TokenModel (audit_id=V6nY5pWbRxGmAeJEEgpdXw, audit_chain_id=['V6nY5pWbRxGmAeJEEgpdXw']) at 0x7fb4a8d905f8>, 'domain_id': None, 'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_name': None, 'group_ids': [], 'user_id': '4ad279fe187042999b413328ee4cd0bd', 'user_domain_id': 'default', 'system_scope': None, 'project_id': '2b6837214bd1499a9ff472e55c639283', 'project_domain_id': 'default', 'roles': ['admin', 'member', 'reader', 'heat_stack_owner'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} fill_context /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/middleware/auth_context.py:478
2021-10-25 17:32:00.306 52 DEBUG keystone.server.flask.request_processing.req_logging [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
2021-10-25 17:32:00.307 52 DEBUG keystone.server.flask.request_processing.req_logging [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
2021-10-25 17:32:00.307 52 DEBUG keystone.server.flask.request_processing.req_logging [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] PATH_INFO: `/v3/users/wpc-monitoring-dev` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29
2021-10-25 17:32:00.361 52 DEBUG keystone.common.rbac_enforcer.enforcer [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorizing `identity:get_user(user_id=wpc-monitoring-dev)` enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:442
2021-10-25 17:32:00.374 52 DEBUG keystone.common.rbac_enforcer.enforcer [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorization granted enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:449
2021-10-25 17:32:00.404 52 WARNING keystone.server.flask.application [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] Could not find user: wpc-monitoring-dev.: keystone.exception.UserNotFound: Could not find user: wpc-monitoring-dev.
2021-10-25 17:32:17.914 46 DEBUG keystone.server.flask.request_processing.req_logging [req-b066e3c7-cee6-4c3c-bdb9-08c353bdabb6 - - - - -] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
2021-10-25 17:32:17.915 46 DEBUG keystone.server.flask.request_processing.req_logging [req-b066e3c7-cee6-4c3c-bdb9-08c353bdabb6 - - - - -] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
2021-10-25 17:32:17.915 46 DEBUG keystone.server.flask.request_processing.req_logging [req-b066e3c7-cee6-4c3c-bdb9-08c353bdabb6 - - - - -] PATH_INFO: `/` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29


=====

** Affects: keystone
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Identity (keystone).
https://bugs.launchpad.net/bugs/1953555

Title:
  keystone ldap request not sending out promptly during stack creation

Status in OpenStack Identity (keystone):
  New

Bug description:
  We are deploying openstack victoria using kolla ansible tool into our baremetal/VM based clusters. After installation, when we creates user heat stacks from kolla_toolbox, every time we are failed with example error message as 
  =====
  (kolla-toolbox)[root@kolla-controller2 /]# openstack stack create --wait --parameter project=new-test.cedev17.d103.eng.pdx.wd -t /opt/heat_templates/templates/monitoring_role_assignment.yaml monitoring_role_assignment
  2021-10-26 21:33:29Z [monitoring_role_assignment]: CREATE_IN_PROGRESS  Stack CREATE started
  2021-10-26 21:33:29Z [monitoring_role_assignment.name_translation]: CREATE_IN_PROGRESS  state changed
  2021-10-26 21:33:29Z [monitoring_role_assignment.name_translation]: CREATE_COMPLETE  state changed
  2021-10-26 21:33:29Z [monitoring_role_assignment]: CREATE_FAILED  No user with a name or ID of 'wpc-monitoring-dev' exists.

   Stack monitoring_role_assignment CREATE_FAILED
  ======
  wpc-monitoring-dev is one user in our dev env.
  indeed, we have checked ldap server side that user "wpc-monitoring-dev" existed in ldap db.
  ===
  (kolla-toolbox)[root@s-mxq0400p0d /]# openstack user list --domain wday | grep wpc-monitoring-dev
  | 9182fdc1858c5dd5568186ca93c41ea403f24058568dfe2aa67c5e7528d5ddc4 | wpc-monitoring-dev
  ===

  What we found out in the keystone log:
  ====
  2021-10-21 21:39:47.387 55 WARNING keystone.server.flask.application [req-f8564b31-11cb-4bba-bda3-78160f92d21e d9ab538e492e40c8853d7741d74d57ea 73b5eb12562c458e963fd7a9223d5a4a - default default] Could not find role: admin.: keystone.exception.RoleNotFound: Could not find role: admin.
  2021-10-21 21:39:49.112 52 WARNING keystone.server.flask.application [req-7d729047-1ae4-4a62-8b31-ec7c59530595 d9ab538e492e40c8853d7741d74d57ea 73b5eb12562c458e963fd7a9223d5a4a - default default] Could not find user: wpc-monitoring-dev.: keystone.exception.UserNotFound: Could not find user: wpc-monitoring-dev.
  ====

  what we observed:
  =====
  1. if we tapping on our outgoing networking interface such as eth0, we did not find any ldap query packets sent out to ldap server when this stack creation error happens. on the other hand, if stack creation success, there are a few ldap query and response packet going thorough the interface eth0.
  2. if we restart all keystone containers once after initial kolla installation, then stack creation will work successfully as normal and there is no error in creating heat stacks.
  ====

  some additional lgos we observed, not sure if it is completely related:
  ====

  2021-10-25 17:31:59.375 47 DEBUG passlib.handlers.bcrypt [req-70fb1480-4a60-4461-a700-f83a5614e679 - - - - -] 'bcrypt' backend lacks $2$ support, enabling workaround _finalize_backend_mixin /var/lib/kolla/venv/lib/python3.6/site-packages/passlib/handlers/bcrypt.py:382
  2021-10-25 17:31:59.663 47 DEBUG keystone.auth.core [req-70fb1480-4a60-4461-a700-f83a5614e679 - - - - -] MFA Rules not processed for user `c146b2b4e81d4028b51f22a9c5e58eed`. Rule list: `[]` (Enabled: `True`). check_auth_methods_against_rules /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/auth/core.py:442
  2021-10-25 17:32:00.086 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-ed6c6a80-2dc1-44bc-88f1-b63f5d2c4ac5 - - - - -] Authenticating user token process_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:407
  2021-10-25 17:32:00.096 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-ed6c6a80-2dc1-44bc-88f1-b63f5d2c4ac5 - - - - -] Validating token access rules against request validate_allowed_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:545
  2021-10-25 17:32:00.160 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: auth_context: {'token': <TokenModel (audit_id=V6nY5pWbRxGmAeJEEgpdXw, audit_chain_id=['V6nY5pWbRxGmAeJEEgpdXw']) at 0x7f366a1b2358>, 'domain_id': None, 'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_name': None, 'group_ids': [], 'user_id': '4ad279fe187042999b413328ee4cd0bd', 'user_domain_id': 'default', 'system_scope': None, 'project_id': '2b6837214bd1499a9ff472e55c639283', 'project_domain_id': 'default', 'roles': ['member', 'heat_stack_owner', 'reader', 'admin'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} fill_context /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/middleware/auth_context.py:478
  2021-10-25 17:32:00.161 53 DEBUG keystone.server.flask.request_processing.req_logging [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
  2021-10-25 17:32:00.161 53 DEBUG keystone.server.flask.request_processing.req_logging [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
  2021-10-25 17:32:00.162 53 DEBUG keystone.server.flask.request_processing.req_logging [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] PATH_INFO: `/v3/domains/wday` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29
  2021-10-25 17:32:00.171 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorizing `identity:get_domain(domain_id=wday)` enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:442
  2021-10-25 17:32:00.184 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorization granted enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:449
  2021-10-25 17:32:00.196 53 WARNING keystone.server.flask.application [req-b1bf6546-5b6d-43e1-831f-f105c353d705 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] Could not find domain: wday.: keystone.exception.DomainNotFound: Could not find domain: wday.
  2021-10-25 17:32:00.414 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-3f6a94a8-0a08-4e4e-9133-c94f36082e92 - - - - -] Authenticating user token process_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:407
  2021-10-25 17:32:00.426 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-3f6a94a8-0a08-4e4e-9133-c94f36082e92 - - - - -] Validating token access rules against request validate_allowed_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:545
  2021-10-25 17:32:00.433 53 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: auth_context: {'token': <TokenModel (audit_id=V6nY5pWbRxGmAeJEEgpdXw, audit_chain_id=['V6nY5pWbRxGmAeJEEgpdXw']) at 0x7f3669ebf630>, 'domain_id': None, 'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_name': None, 'group_ids': [], 'user_id': '4ad279fe187042999b413328ee4cd0bd', 'user_domain_id': 'default', 'system_scope': None, 'project_id': '2b6837214bd1499a9ff472e55c639283', 'project_domain_id': 'default', 'roles': ['member', 'heat_stack_owner', 'admin', 'reader'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} fill_context /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/middleware/auth_context.py:478
  2021-10-25 17:32:00.434 53 DEBUG keystone.server.flask.request_processing.req_logging [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
  2021-10-25 17:32:00.434 53 DEBUG keystone.server.flask.request_processing.req_logging [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
  2021-10-25 17:32:00.435 53 DEBUG keystone.server.flask.request_processing.req_logging [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] PATH_INFO: `/v3/users` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29
  2021-10-25 17:32:00.435 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Adding query filter params (domain_id=bd9bb1b991894ee498a489ae06e61e89, name=wpc-monitoring-dev) _extract_filter_values /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:161
  2021-10-25 17:32:00.436 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorizing `identity:list_users()` enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:442
  2021-10-25 17:32:00.447 53 WARNING py.warnings [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_policy/policy.py:1022: UserWarning: Policy identity:list_users failed scope check. The token used to make the request was project scoped but the policy requires ['system', 'domain'] scope. This behavior may change in the future where using the intended scope is required
    warnings.warn(msg)

  2021-10-25 17:32:00.448 53 DEBUG keystone.common.rbac_enforcer.enforcer [req-17e5f1e3-7b9f-4b8c-8b72-4761b13b451c 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorization granted enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:449
  =======


  2021-10-25 17:32:00.258 52 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-f2d776b4-5f7b-4aea-ab47-878080af2046 - - - - -] Authenticating user token process_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:407
  2021-10-25 17:32:00.296 52 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-f2d776b4-5f7b-4aea-ab47-878080af2046 - - - - -] Validating token access rules against request validate_allowed_request /var/lib/kolla/venv/lib/python3.6/site-packages/keystonemiddleware/auth_token/__init__.py:545
  2021-10-25 17:32:00.305 52 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: auth_context: {'token': <TokenModel (audit_id=V6nY5pWbRxGmAeJEEgpdXw, audit_chain_id=['V6nY5pWbRxGmAeJEEgpdXw']) at 0x7fb4a8d905f8>, 'domain_id': None, 'trust_id': None, 'trustor_id': None, 'trustee_id': None, 'domain_name': None, 'group_ids': [], 'user_id': '4ad279fe187042999b413328ee4cd0bd', 'user_domain_id': 'default', 'system_scope': None, 'project_id': '2b6837214bd1499a9ff472e55c639283', 'project_domain_id': 'default', 'roles': ['admin', 'member', 'reader', 'heat_stack_owner'], 'is_admin_project': True, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_id': None, 'service_project_domain_id': None, 'service_roles': []} fill_context /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/middleware/auth_context.py:478
  2021-10-25 17:32:00.306 52 DEBUG keystone.server.flask.request_processing.req_logging [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
  2021-10-25 17:32:00.307 52 DEBUG keystone.server.flask.request_processing.req_logging [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
  2021-10-25 17:32:00.307 52 DEBUG keystone.server.flask.request_processing.req_logging [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] PATH_INFO: `/v3/users/wpc-monitoring-dev` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29
  2021-10-25 17:32:00.361 52 DEBUG keystone.common.rbac_enforcer.enforcer [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorizing `identity:get_user(user_id=wpc-monitoring-dev)` enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:442
  2021-10-25 17:32:00.374 52 DEBUG keystone.common.rbac_enforcer.enforcer [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] RBAC: Authorization granted enforce_call /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/common/rbac_enforcer/enforcer.py:449
  2021-10-25 17:32:00.404 52 WARNING keystone.server.flask.application [req-df8800e1-78e6-4ae5-a20a-5aed5a3f1989 4ad279fe187042999b413328ee4cd0bd 2b6837214bd1499a9ff472e55c639283 - default default] Could not find user: wpc-monitoring-dev.: keystone.exception.UserNotFound: Could not find user: wpc-monitoring-dev.
  2021-10-25 17:32:17.914 46 DEBUG keystone.server.flask.request_processing.req_logging [req-b066e3c7-cee6-4c3c-bdb9-08c353bdabb6 - - - - -] REQUEST_METHOD: `GET` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:27
  2021-10-25 17:32:17.915 46 DEBUG keystone.server.flask.request_processing.req_logging [req-b066e3c7-cee6-4c3c-bdb9-08c353bdabb6 - - - - -] SCRIPT_NAME: `` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:28
  2021-10-25 17:32:17.915 46 DEBUG keystone.server.flask.request_processing.req_logging [req-b066e3c7-cee6-4c3c-bdb9-08c353bdabb6 - - - - -] PATH_INFO: `/` log_request_info /var/lib/kolla/venv/lib/python3.6/site-packages/keystone/server/flask/request_processing/req_logging.py:29

  
  =====

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1953555/+subscriptions