Public bug reported: Some time ago https://review.opendev.org/c/openstack/keystone/+/834181 got merged. It exposed an issue: keystone does not catch many exceptions. It leads to keystone logging every small event using logging.exception() method, which prints a traceback and logs it with an ERROR level. For example, it does it for RoleNotFound, or DomainNotFound.
Steps to reproduce: 1. Deploy keystone 2. Do curl /v3/domains/nonexistingdomain Expected: keystone treats this as a minor event, logging an INFO message Observed: keystone logs the full traceback, see below For example, taken from a tempest run https://ed33be9e77348e089777-ffccc72cd1a336bccef8b981ce42be9d.ssl.cf2.rackcdn.com/902705/5/check/tempest-full-py3/66ebb81/controller/logs/index.html, screen-keystone.txt: Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application [None req-9ab3573a-c69c-4518-a1e6-7ae735470dae None admin] Could not find role: admin.: keystone.exception.RoleNotFound: Could not find role: admin. Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application Traceback (most recent call last): Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1823, in full_dispatch_request Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application rv = self.dispatch_request() Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1799, in dispatch_request Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 489, in wrapper Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application resp = resource(*args, **kwargs) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/views.py", line 107, in view Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return current_app.ensure_sync(self.dispatch_request)(**kwargs) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 604, in dispatch_request Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application resp = meth(*args, **kwargs) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/api/roles.py", line 50, in get Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self._get_role(role_id) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/api/roles.py", line 70, in _get_role Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application ENFORCER.enforce_call(action='identity:get_role') Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 402, in enforce_call Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application policy_dict.update(cls._extract_member_target_data( Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 234, in _extract_member_target_data Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application member_name: func(flask.request.view_args[key]) Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/common/manager.py", line 110, in wrapped Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application __ret_val = __f(*args, **kwargs) Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/decorator.py", line 232, in fun Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return caller(func, *(extras + args), **kw) Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/cache/region.py", line 1594, in get_or_create_for_user_func Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.get_or_create( Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/cache/region.py", line 1054, in get_or_create Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application with Lock( Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/lock.py", line 185, in __enter__ Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self._enter() Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/lock.py", line 94, in _enter Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application generated = self._enter_create(value, createdtime) Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/lock.py", line 178, in _enter_create Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.creator() Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/cache/region.py", line 1007, in gen_value Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application created_value = creator( Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/assignment/core.py", line 1276, in get_role Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.driver.get_role(role_id) Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/assignment/role_backends/sql.py", line 70, in get_role Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR tracebackkeystone.server.flask.application return self._get_role(session, role_id).to_dict() Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/assignment/role_backends/sql.py", line 65, in _get_role Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application raise exception.RoleNotFound(role_id=role_id) Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application keystone.exception.RoleNotFound: Could not find role: admin. Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application ** 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/2045995 Title: usual events are logged with level Error Status in OpenStack Identity (keystone): New Bug description: Some time ago https://review.opendev.org/c/openstack/keystone/+/834181 got merged. It exposed an issue: keystone does not catch many exceptions. It leads to keystone logging every small event using logging.exception() method, which prints a traceback and logs it with an ERROR level. For example, it does it for RoleNotFound, or DomainNotFound. Steps to reproduce: 1. Deploy keystone 2. Do curl /v3/domains/nonexistingdomain Expected: keystone treats this as a minor event, logging an INFO message Observed: keystone logs the full traceback, see below For example, taken from a tempest run https://ed33be9e77348e089777-ffccc72cd1a336bccef8b981ce42be9d.ssl.cf2.rackcdn.com/902705/5/check/tempest-full-py3/66ebb81/controller/logs/index.html, screen-keystone.txt: Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application [None req-9ab3573a-c69c-4518-a1e6-7ae735470dae None admin] Could not find role: admin.: keystone.exception.RoleNotFound: Could not find role: admin. Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application Traceback (most recent call last): Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1823, in full_dispatch_request Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application rv = self.dispatch_request() Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1799, in dispatch_request Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 489, in wrapper Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application resp = resource(*args, **kwargs) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/views.py", line 107, in view Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return current_app.ensure_sync(self.dispatch_request)(**kwargs) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 604, in dispatch_request Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application resp = meth(*args, **kwargs) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/api/roles.py", line 50, in get Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self._get_role(role_id) Dec 07 01:52:24.990962 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/api/roles.py", line 70, in _get_role Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application ENFORCER.enforce_call(action='identity:get_role') Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 402, in enforce_call Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application policy_dict.update(cls._extract_member_target_data( Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 234, in _extract_member_target_data Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application member_name: func(flask.request.view_args[key]) Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/common/manager.py", line 110, in wrapped Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application __ret_val = __f(*args, **kwargs) Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/decorator.py", line 232, in fun Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return caller(func, *(extras + args), **kw) Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/cache/region.py", line 1594, in get_or_create_for_user_func Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.get_or_create( Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/cache/region.py", line 1054, in get_or_create Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application with Lock( Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/lock.py", line 185, in __enter__ Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self._enter() Dec 07 01:52:24.991525 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/lock.py", line 94, in _enter Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application generated = self._enter_create(value, createdtime) Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/lock.py", line 178, in _enter_create Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.creator() Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/data/venv/lib/python3.10/site-packages/dogpile/cache/region.py", line 1007, in gen_value Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application created_value = creator( Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/assignment/core.py", line 1276, in get_role Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application return self.driver.get_role(role_id) Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/assignment/role_backends/sql.py", line 70, in get_role Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR tracebackkeystone.server.flask.application return self._get_role(session, role_id).to_dict() Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application File "/opt/stack/keystone/keystone/assignment/role_backends/sql.py", line 65, in _get_role Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application raise exception.RoleNotFound(role_id=role_id) Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application keystone.exception.RoleNotFound: Could not find role: admin. Dec 07 01:52:24.992011 np0035966603 devstack@keystone.service[51936]: ERROR keystone.server.flask.application To manage notifications about this bug go to: https://bugs.launchpad.net/keystone/+bug/2045995/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
