"AttributeError: 'Enforcer' object has no attribute '_warning_emitted'" when keystone API run with > 1 wsgi threads

[melanie witt]

Seeing this in the gate while testing a change that sets wsgi threads to 16 in the wsgi config [1]:

[uwsgi]
threads = 16

In keystone, we get "ERROR keystone AttributeError: 'Enforcer' object has no attribute '_warning_emitted'" and a 500 error returned from the API. The problem seems to be around the global policy enforcer object code [2]:

    @property
    def _enforcer(self):
        # The raw oslo-policy enforcer object
        if self.__ENFORCER is None:
            self.__ENFORCER = common_policy.Enforcer(CONF)
            # NOTE(cmurphy) when running in the keystone server, suppress
            # deprecation warnings for individual policy rules. Instead, we log
            # a single notification at enforcement time indicating the
            # oslo.policy tools the operator can use to detect and resolve
            # deprecated policies. If there is no request context here, that
            # means external tooling such as the oslo.policy tools are running
            # this code, in which case we do want the full deprecation warnings
            # emitted for individual polcy rules.
            if flask.has_request_context():
                self.__ENFORCER.suppress_deprecation_warnings = True
            # NOTE(cmurphy) Tests may explicitly disable these warnings to
            # prevent an explosion of test logs
            if self.suppress_deprecation_warnings:
                self.__ENFORCER.suppress_deprecation_warnings = True
            self.register_rules(self.__ENFORCER)
            self.__ENFORCER._warning_emitted = False
        return self.__ENFORCER

With multiple wsgi threads, it can get into a state where self.__ENFORCER._warning_emitted has not been set before it is accessed [3]:

        def _emit_warning():
            if not self._enforcer._warning_emitted: <============== AttributeError
                LOG.warning("Deprecated policy rules found. Use "
                            "oslopolicy-policy-generator and "
                            "oslopolicy-policy-upgrade to detect and resolve "
                            "deprecated policies in your configuration.")
                self._enforcer._warning_emitted = True

Full traceback from an example job run [4]:

Aug 22 01:06:34.637238 np0035008942 <email address hidden>[47694]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-e7086405-d9ba-468e-abac-85609696331d None admin] RBAC: Authorizing `identity:create_domain()` {{(pid=47694) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:449}}
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: CRITICAL keystone [None req-e7086405-d9ba-468e-abac-85609696331d None admin] Unhandled error: AttributeError: 'Enforcer' object has no attribute '_warning_emitted'
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone Traceback (most recent call last):
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 2551, in __call__
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone return self.wsgi_app(environ, start_response)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/werkzeug/middleware/proxy_fix.py", line 187, in __call__
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone return self.app(environ, start_response)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone resp = self.call_func(req, *args, **kw)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone return self.func(req, *args, **kwargs)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/base.py", line 124, in __call__
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone response = req.get_response(self.application)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone status, headers, app_iter = self.call_application(
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone app_iter = application(self.environ, start_response)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 143, in __call__
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone return resp(environ, start_response)
Aug 22 01:06:34.671985 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone resp = self.call_func(req, *args, **kw)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone return self.func(req, *args, **kwargs)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/base.py", line 124, in __call__
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone response = req.get_response(self.application)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone status, headers, app_iter = self.call_application(
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone app_iter = application(self.environ, start_response)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone resp = self.call_func(req, *args, **kw)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone return self.func(req, *args, **kwargs)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/osprofiler/web.py", line 111, in __call__
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone return request.get_response(self.application)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone status, headers, app_iter = self.call_application(
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone app_iter = application(self.environ, start_response)
Aug 22 01:06:34.675440 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone resp = self.call_func(req, *args, **kw)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone return self.func(req, *args, **kwargs)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/request_id.py", line 58, in __call__
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone response = req.get_response(self.application)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone status, headers, app_iter = self.call_application(
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone app_iter = application(self.environ, start_response)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/keystone/keystone/server/flask/request_processing/middleware/url_normalize.py", line 38, in __call__
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone return self.app(environ, start_response)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone resp = self.call_func(req, *args, **kw)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone return self.func(req, *args, **kwargs)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/keystonemiddleware/auth_token/__init__.py", line 340, in __call__
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone response = req.get_response(self._app)
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Aug 22 01:06:34.678696 np0035008942 <email address hidden>[47694]: ERROR keystone status, headers, app_iter = self.call_application(
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone app_iter = application(self.environ, start_response)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/werkzeug/middleware/dispatcher.py", line 78, in __call__
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone return app(environ, start_response)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 2531, in wsgi_app
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone response = self.handle_exception(e)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 271, in error_router
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone return original_handler(e)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 271, in error_router
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone return original_handler(e)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 271, in error_router
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone return original_handler(e)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone [Previous line repeated 28 more times]
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 2528, in wsgi_app
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone response = self.full_dispatch_request()
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1825, in full_dispatch_request
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone rv = self.handle_user_exception(e)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 271, in error_router
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone return original_handler(e)
Aug 22 01:06:34.681823 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 271, in error_router
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone return original_handler(e)
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 271, in error_router
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone return original_handler(e)
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone [Previous line repeated 28 more times]
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1823, in full_dispatch_request
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone rv = self.dispatch_request()
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/app.py", line 1799, in dispatch_request
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 467, in wrapper
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone resp = resource(*args, **kwargs)
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask/views.py", line 107, in view
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone return current_app.ensure_sync(self.dispatch_request)(**kwargs)
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/data/venv/lib/python3.10/site-packages/flask_restful/__init__.py", line 582, in dispatch_request
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone resp = meth(*args, **kwargs)
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/keystone/keystone/api/domains.py", line 113, in post
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone ENFORCER.enforce_call(action='identity:create_domain')
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 455, in enforce_call
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone enforcer_obj._enforce(
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 127, in _enforce
Aug 22 01:06:34.685577 np0035008942 <email address hidden>[47694]: ERROR keystone self._check_deprecated_rule(action)
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 96, in _check_deprecated_rule
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: ERROR keystone _emit_warning()
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: ERROR keystone File "/opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py", line 82, in _emit_warning
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: ERROR keystone if not self._enforcer._warning_emitted:
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: ERROR keystone AttributeError: 'Enforcer' object has no attribute '_warning_emitted'
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: ERROR keystone
Aug 22 01:06:34.689279 np0035008942 <email address hidden>[47694]: [pid: 47694|app: 0|req: 2/15] 10.209.128.207 () {68 vars in 1290 bytes} [Tue Aug 22 01:06:34 2023] POST /identity/v3/domains => generated 0 bytes in 533 msecs (HTTP/1.1 500) 0 headers in 0 bytes (0 switches on core 1)

[1] https://review.opendev.org/c/openstack/devstack/+/891214
[2] https://github.com/openstack/keystone/blob/349706a/keystone/common/rbac_enforcer/enforcer.py#L136-L157
[3] https://github.com/openstack/keystone/blob/349706a/keystone/common/rbac_enforcer/enforcer.py#L82
[4] https://zuul.opendev.org/t/openstack/build/af86792d15284fbd9db06cf5e5954fb4/log/controller/logs/screen-keystone.txt#1318