usual events are logged with level Error

[Boris Bobrov]

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 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application Traceback (most recent call last):
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application rv = self.dispatch_request()
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application resp = resource(*args, **kwargs)
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return current_app.ensure_sync(self.dispatch_request)(**kwargs)
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application resp = meth(*args, **kwargs)
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return self._get_role(role_id)
Dec 07 01:52:24.990962 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application ENFORCER.enforce_call(action='identity:get_role')
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application policy_dict.update(cls._extract_member_target_data(
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application member_name: func(flask.request.view_args[key])
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application __ret_val = __f(*args, **kwargs)
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return caller(func, *(extras + args), **kw)
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return self.get_or_create(
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application with Lock(
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return self._enter()
Dec 07 01:52:24.991525 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application generated = self._enter_create(value, createdtime)
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return self.creator()
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application created_value = creator(
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application return self.driver.get_role(role_id)
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR tracebackkeystone.server.flask.application return self._get_role(session, role_id).to_dict()
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[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 <email address hidden>[51936]: ERROR keystone.server.flask.application raise exception.RoleNotFound(role_id=role_id)
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[51936]: ERROR keystone.server.flask.application keystone.exception.RoleNotFound: Could not find role: admin.
Dec 07 01:52:24.992011 np0035966603 <email address hidden>[51936]: ERROR keystone.server.flask.application

[Boris Bobrov (bbobrov)]

I am not sure what would be the correct way to fix this.

Option 1: revert https://review.opendev.org/c/openstack/keystone/+/834181, change from warning to info for certain events (for example, for all NotFound). This is an easy and quick option. But for me it feels like we are swiping the issue under the rug.

Option 2: catch all those exceptions in keystone code, reraise Unauthorized based on them, or returning a proper response. This feels like a cleaner solution to me. But it feels like boiling an ocean: there are 321 errors in the tempest log alone, and i have a feeling that tempest is not covering 100% of our API, especially all the negative response codes.

I guess a mix of both 1 and 2 should be done?

[Sven Kieske (s-kieske)]

afaik there are some actual bugs hidden in above Trace. let me fill a bug separately for them and link here.

[Sven Kieske (s-kieske)]

I'll write a detailed bugreport later(maybe I need time until monday) for now you can read my downstream findings here if you want:

https://github.com/osism/issues/issues/907