yahoo-eng-team team mailing list archive

Thread
Date
[Bug 2045995] [NEW] usual events are logged with level Error

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Boris Bobrov <2045995@xxxxxxxxxxxxxxxxxx>
Date: Fri, 08 Dec 2023 17:59:49 -0000
Reply-to: Bug 2045995 <2045995@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
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