OpenStack Identity (keystone)

Keystone throws DBNonExistentTable

Bug #1891019 reported by Divya K Konoor
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
New
Undecided
Unassigned

Bug Description

Environment:

- Keystone runs as a process inside Apache Httpd on RHEL7.7 (OpenStack Stein) with one (default) process

I am using OpenStack Keystone Stein and run into the below error randomly, where Keystone public process(listening to 5000) is running inside Apache httpd. It is seen that in some cases when the httpd service is restarted, Keystone throws the below stacktrace (and is not functional after that). This problem is resolved with a restart of httpd service. This is seen soon after httpd is restarted and does not happen all the time. My environment has MariaDB backend (SELinux is in permissive). This problem is not limited to the assignment table and is seen across all other tables in Keystone. MariaDB service is functional (and has not been restarted) and all the tables are in place.

[Fri Aug 07 08:20:59.936087 2020] [:info] [pid 1420287] mod_wsgi (pid=1420287, process='keystone-public', application=''): Loading WSGI script '/usr/bin/keystone-wsgi-public'.
[Fri Aug 07 08:20:59.936089 2020] [:info] [pid 1420288] mod_wsgi (pid=1420288, process='keystone-admin', application=''): Loading WSGI script '/usr/bin/keystone-wsgi-admin'.
[Fri Aug 07 08:20:59.943431 2020] [ssl:info] [pid 1420290] [client 1.2.3.95:35762] AH01964: Connection to child 1 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:00.009317 2020] [ssl:info] [pid 1420291] [client 1.2.3.113:60132] AH01964: Connection to child 2 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:01.243594 2020] [ssl:info] [pid 1420289] [client 1.2.3.50:53996] AH01964: Connection to child 0 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:01.386329 2020] [ssl:info] [pid 1420293] [client x.x.x.x:38645] AH01964: Connection to child 4 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:01.824041 2020] [ssl:info] [pid 1420349] [client 1.2.3.101:42974] AH01964: Connection to child 5 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:02.949166 2020] [ssl:info] [pid 1420378] [client 1.2.3.50:54014] AH01964: Connection to child 9 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:02.949172 2020] [ssl:info] [pid 1420379] [client 1.2.3.80:46924] AH01964: Connection to child 10 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:03.286057 2020] [:info] [pid 1420287] mod_wsgi (pid=1420287): Create interpreter '1.2.3.50:5000|'.
[Fri Aug 07 08:21:03.287286 2020] [:info] [pid 1420287] [remote 1.2.3.95:156] mod_wsgi (pid=1420287, process='keystone-public', application='1.2.3.50:5000|'): Loading WSGI script '/usr/bin/keystone-wsgi-public'.
[Fri Aug 07 08:21:04.675059 2020] [ssl:info] [pid 1420436] [client 1.2.3.50:54032] AH01964: Connection to child 12 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:04.705975 2020] [ssl:info] [pid 1420437] [client 1.2.3.107:59554] AH01964: Connection to child 13 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:06.960940 2020] [ssl:info] [pid 1420438] [client 1.2.3.80:46970] AH01964: Connection to child 14 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:07.661670 2020] [ssl:info] [pid 1420349] [client 1.2.3.50:54124] AH01964: Connection to child 5 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:07.683383 2020] [ssl:info] [pid 1420292] [client x.x.x.x:30065] AH01964: Connection to child 3 established (server 1.2.3.50:5000)
[Fri Aug 07 08:21:08.442956 2020] [:error] [pid 1420287] [remote x.x.x.x:144] mod_wsgi (pid=1420287): Exception occurred processing WSGI script '/usr/bin/keystone-wsgi-public'.
[Fri Aug 07 08:21:08.443002 2020] [:error] [pid 1420287] [remote x.x.x.x:144] Traceback (most recent call last):
[Fri Aug 07 08:21:08.443017 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 2309, in __call__
[Fri Aug 07 08:21:08.443509 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.wsgi_app(environ, start_response)
[Fri Aug 07 08:21:08.443525 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/werkzeug/contrib/fixers.py", line 152, in __call__
[Fri Aug 07 08:21:08.443630 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.app(environ, start_response)
[Fri Aug 07 08:21:08.443644 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 129, in __call__
[Fri Aug 07 08:21:08.443746 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = self.call_func(req, *args, **kw)
[Fri Aug 07 08:21:08.443756 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 193, in call_func
[Fri Aug 07 08:21:08.443773 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.func(req, *args, **kwargs)
[Fri Aug 07 08:21:08.443781 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/oslo_middleware/base.py", line 131, in __call__
[Fri Aug 07 08:21:08.443844 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = req.get_response(self.application)
[Fri Aug 07 08:21:08.443859 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1314, in send
[Fri Aug 07 08:21:08.444194 2020] [:error] [pid 1420287] [remote x.x.x.x:144] application, catch_exc_info=False)
[Fri Aug 07 08:21:08.444203 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1278, in call_application
[Fri Aug 07 08:21:08.444220 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_iter = application(self.environ, start_response)
[Fri Aug 07 08:21:08.444229 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 143, in __call__
[Fri Aug 07 08:21:08.444245 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return resp(environ, start_response)
[Fri Aug 07 08:21:08.444253 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 129, in __call__
[Fri Aug 07 08:21:08.444268 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = self.call_func(req, *args, **kw)
[Fri Aug 07 08:21:08.444276 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 193, in call_func
[Fri Aug 07 08:21:08.444292 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.func(req, *args, **kwargs)
[Fri Aug 07 08:21:08.444300 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/oslo_middleware/base.py", line 131, in __call__
[Fri Aug 07 08:21:08.444315 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = req.get_response(self.application)
[Fri Aug 07 08:21:08.444323 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1314, in send
[Fri Aug 07 08:21:08.444338 2020] [:error] [pid 1420287] [remote x.x.x.x:144] application, catch_exc_info=False)
[Fri Aug 07 08:21:08.444346 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1278, in call_application
[Fri Aug 07 08:21:08.444361 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_iter = application(self.environ, start_response)
[Fri Aug 07 08:21:08.444370 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 129, in __call__
[Fri Aug 07 08:21:08.444385 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = self.call_func(req, *args, **kw)
[Fri Aug 07 08:21:08.444393 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 193, in call_func
[Fri Aug 07 08:21:08.444408 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.func(req, *args, **kwargs)
[Fri Aug 07 08:21:08.444416 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/osprofiler/web.py", line 112, in __call__
[Fri Aug 07 08:21:08.444476 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return request.get_response(self.application)
[Fri Aug 07 08:21:08.444485 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1314, in send
[Fri Aug 07 08:21:08.444501 2020] [:error] [pid 1420287] [remote x.x.x.x:144] application, catch_exc_info=False)
[Fri Aug 07 08:21:08.444509 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1278, in call_application
[Fri Aug 07 08:21:08.444524 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_iter = application(self.environ, start_response)
[Fri Aug 07 08:21:08.444533 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 129, in __call__
[Fri Aug 07 08:21:08.444547 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = self.call_func(req, *args, **kw)
[Fri Aug 07 08:21:08.444556 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 193, in call_func
[Fri Aug 07 08:21:08.444571 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.func(req, *args, **kwargs)
[Fri Aug 07 08:21:08.444587 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/oslo_middleware/request_id.py", line 58, in __call__
[Fri Aug 07 08:21:08.444636 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = req.get_response(self.application)
[Fri Aug 07 08:21:08.444645 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1314, in send
[Fri Aug 07 08:21:08.444660 2020] [:error] [pid 1420287] [remote x.x.x.x:144] application, catch_exc_info=False)
[Fri Aug 07 08:21:08.444669 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1278, in call_application
[Fri Aug 07 08:21:08.444684 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_iter = application(self.environ, start_response)
[Fri Aug 07 08:21:08.444698 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/server/flask/request_processing/middleware/url_normalize.py", line 38, in __call__
[Fri Aug 07 08:21:08.444750 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.app(environ, start_response)
[Fri Aug 07 08:21:08.444759 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 129, in __call__
[Fri Aug 07 08:21:08.444774 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = self.call_func(req, *args, **kw)
[Fri Aug 07 08:21:08.444783 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 193, in call_func
[Fri Aug 07 08:21:08.444797 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.func(req, *args, **kwargs)
[Fri Aug 07 08:21:08.444810 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py", line 333, in __call__
[Fri Aug 07 08:21:08.444828 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = req.get_response(self._app)
[Fri Aug 07 08:21:08.444836 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1314, in send
[Fri Aug 07 08:21:08.444851 2020] [:error] [pid 1420287] [remote x.x.x.x:144] application, catch_exc_info=False)
[Fri Aug 07 08:21:08.444859 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1278, in call_application
[Fri Aug 07 08:21:08.444874 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_iter = application(self.environ, start_response)
[Fri Aug 07 08:21:08.444883 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 129, in __call__
[Fri Aug 07 08:21:08.444897 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = self.call_func(req, *args, **kw)
[Fri Aug 07 08:21:08.444906 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/dec.py", line 193, in call_func
[Fri Aug 07 08:21:08.444920 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.func(req, *args, **kwargs)
[Fri Aug 07 08:21:08.444929 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/oslo_middleware/base.py", line 131, in __call__
[Fri Aug 07 08:21:08.444944 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = req.get_response(self.application)
[Fri Aug 07 08:21:08.444952 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1314, in send
[Fri Aug 07 08:21:08.444967 2020] [:error] [pid 1420287] [remote x.x.x.x:144] application, catch_exc_info=False)
[Fri Aug 07 08:21:08.444975 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/webob/request.py", line 1278, in call_application
[Fri Aug 07 08:21:08.444990 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_iter = application(self.environ, start_response)
[Fri Aug 07 08:21:08.444998 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/werkzeug/wsgi.py", line 826, in __call__
[Fri Aug 07 08:21:08.445279 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return app(environ, start_response)
[Fri Aug 07 08:21:08.445288 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 2295, in wsgi_app
[Fri Aug 07 08:21:08.445304 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = self.handle_exception(e)
[Fri Aug 07 08:21:08.445316 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445490 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445500 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445516 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445524 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445539 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445547 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445562 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445570 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445585 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445593 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445608 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445616 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445630 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445639 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445654 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445662 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445676 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445685 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445699 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445708 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445722 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445731 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445745 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445758 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445772 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445780 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445795 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445803 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445818 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445826 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445841 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445849 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445863 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445871 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445886 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445894 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445908 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445917 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445931 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445939 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445954 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445962 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445976 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.445984 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.445999 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446007 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446021 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446030 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446044 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446052 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446067 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446075 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446090 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446098 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446113 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446121 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446135 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446143 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446158 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446166 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 1741, in handle_exception
[Fri Aug 07 08:21:08.446181 2020] [:error] [pid 1420287] [remote x.x.x.x:144] reraise(exc_type, exc_value, tb)
[Fri Aug 07 08:21:08.446190 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 266, in error_router
[Fri Aug 07 08:21:08.446204 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.handle_error(e)
[Fri Aug 07 08:21:08.446212 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 2292, in wsgi_app
[Fri Aug 07 08:21:08.446227 2020] [:error] [pid 1420287] [remote x.x.x.x:144] response = self.full_dispatch_request()
[Fri Aug 07 08:21:08.446236 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 1815, in full_dispatch_request
[Fri Aug 07 08:21:08.446250 2020] [:error] [pid 1420287] [remote x.x.x.x:144] rv = self.handle_user_exception(e)
[Fri Aug 07 08:21:08.446259 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446273 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446282 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446296 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446304 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446318 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446327 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446341 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446349 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446363 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446372 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446386 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446395 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446409 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446417 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446432 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446440 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446454 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446463 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446477 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446485 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446500 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446508 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446522 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446531 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446545 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446553 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446568 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446576 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446590 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446599 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446613 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446621 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446636 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446644 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446658 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446667 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446681 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446689 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446704 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446712 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446727 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446735 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446749 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446757 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446772 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446780 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446795 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446803 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446817 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446826 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446840 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446848 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446863 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446871 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446885 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446893 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446908 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446916 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 269, in error_router
[Fri Aug 07 08:21:08.446930 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return original_handler(e)
[Fri Aug 07 08:21:08.446938 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 1718, in handle_user_exception
[Fri Aug 07 08:21:08.446953 2020] [:error] [pid 1420287] [remote x.x.x.x:144] reraise(exc_type, exc_value, tb)
[Fri Aug 07 08:21:08.446962 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 266, in error_router
[Fri Aug 07 08:21:08.446976 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.handle_error(e)
[Fri Aug 07 08:21:08.446984 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 1813, in full_dispatch_request
[Fri Aug 07 08:21:08.446999 2020] [:error] [pid 1420287] [remote x.x.x.x:144] rv = self.dispatch_request()
[Fri Aug 07 08:21:08.447007 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/app.py", line 1799, in dispatch_request
[Fri Aug 07 08:21:08.447022 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.view_functions[rule.endpoint](**req.view_args)
[Fri Aug 07 08:21:08.447031 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 458, in wrapper
[Fri Aug 07 08:21:08.447046 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = resource(*args, **kwargs)
[Fri Aug 07 08:21:08.447055 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask/views.py", line 88, in view
[Fri Aug 07 08:21:08.447119 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self.dispatch_request(*args, **kwargs)
[Fri Aug 07 08:21:08.447128 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/flask_restful/__init__.py", line 573, in dispatch_request
[Fri Aug 07 08:21:08.447144 2020] [:error] [pid 1420287] [remote x.x.x.x:144] resp = meth(*args, **kwargs)
[Fri Aug 07 08:21:08.447152 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/server/flask/common.py", line 1060, in wrapper
[Fri Aug 07 08:21:08.447392 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return f(*args, **kwargs)
[Fri Aug 07 08:21:08.447406 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/api/auth.py", line 312, in post
[Fri Aug 07 08:21:08.447551 2020] [:error] [pid 1420287] [remote x.x.x.x:144] token = authentication.authenticate_for_token(auth_data)
[Fri Aug 07 08:21:08.447561 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/api/_shared/authentication.py", line 229, in authenticate_for_token
[Fri Aug 07 08:21:08.447652 2020] [:error] [pid 1420287] [remote x.x.x.x:144] app_cred_id=app_cred_id, parent_audit_id=token_audit_id)
[Fri Aug 07 08:21:08.447662 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 116, in wrapped
[Fri Aug 07 08:21:08.447679 2020] [:error] [pid 1420287] [remote x.x.x.x:144] __ret_val = __f(*args, **kwargs)
[Fri Aug 07 08:21:08.447687 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/token/provider.py", line 252, in issue_token
[Fri Aug 07 08:21:08.447706 2020] [:error] [pid 1420287] [remote x.x.x.x:144] token.mint(token_id, issued_at)
[Fri Aug 07 08:21:08.447714 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/models/token_model.py", line 563, in mint
[Fri Aug 07 08:21:08.448498 2020] [:error] [pid 1420287] [remote x.x.x.x:144] self._validate_project_scope()
[Fri Aug 07 08:21:08.448508 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/models/token_model.py", line 512, in _validate_project_scope
[Fri Aug 07 08:21:08.448525 2020] [:error] [pid 1420287] [remote x.x.x.x:144] if self.project_scoped and not self.roles:
[Fri Aug 07 08:21:08.448533 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/models/token_model.py", line 438, in roles
[Fri Aug 07 08:21:08.448549 2020] [:error] [pid 1420287] [remote x.x.x.x:144] roles = self._get_project_roles()
[Fri Aug 07 08:21:08.448557 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/models/token_model.py", line 400, in _get_project_roles
[Fri Aug 07 08:21:08.448573 2020] [:error] [pid 1420287] [remote x.x.x.x:144] self.user_id, self.project_id
[Fri Aug 07 08:21:08.448581 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 116, in wrapped
[Fri Aug 07 08:21:08.448597 2020] [:error] [pid 1420287] [remote x.x.x.x:144] __ret_val = __f(*args, **kwargs)
[Fri Aug 07 08:21:08.448605 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1220, in decorate
[Fri Aug 07 08:21:08.449478 2020] [:error] [pid 1420287] [remote x.x.x.x:144] should_cache_fn)
[Fri Aug 07 08:21:08.449488 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 825, in get_or_create
[Fri Aug 07 08:21:08.449504 2020] [:error] [pid 1420287] [remote x.x.x.x:144] async_creator) as value:
[Fri Aug 07 08:21:08.449512 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 154, in __enter__
[Fri Aug 07 08:21:08.449967 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self._enter()
[Fri Aug 07 08:21:08.449977 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 94, in _enter
[Fri Aug 07 08:21:08.449995 2020] [:error] [pid 1420287] [remote x.x.x.x:144] generated = self._enter_create(createdtime)
[Fri Aug 07 08:21:08.450004 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/lock.py", line 145, in _enter_create
[Fri Aug 07 08:21:08.450020 2020] [:error] [pid 1420287] [remote x.x.x.x:144] created = self.creator()
[Fri Aug 07 08:21:08.450029 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 792, in gen_value
[Fri Aug 07 08:21:08.450046 2020] [:error] [pid 1420287] [remote x.x.x.x:144] created_value = creator()
[Fri Aug 07 08:21:08.450055 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/dogpile/cache/region.py", line 1216, in creator
[Fri Aug 07 08:21:08.450071 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return fn(*arg, **kw)
[Fri Aug 07 08:21:08.450080 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/assignment/core.py", line 128, in get_roles_for_user_and_project
[Fri Aug 07 08:21:08.450975 2020] [:error] [pid 1420287] [remote x.x.x.x:144] user_id=user_id, project_id=project_id, effective=True)
[Fri Aug 07 08:21:08.450985 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/common/manager.py", line 116, in wrapped
[Fri Aug 07 08:21:08.451001 2020] [:error] [pid 1420287] [remote x.x.x.x:144] __ret_val = __f(*args, **kwargs)
[Fri Aug 07 08:21:08.451009 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/assignment/core.py", line 999, in list_role_assignments
[Fri Aug 07 08:21:08.451025 2020] [:error] [pid 1420287] [remote x.x.x.x:144] strip_domain_roles)
[Fri Aug 07 08:21:08.451033 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/assignment/core.py", line 845, in _list_effective_role_assignments
[Fri Aug 07 08:21:08.451049 2020] [:error] [pid 1420287] [remote x.x.x.x:144] domain_id=domain_id, inherited=inherited)
[Fri Aug 07 08:21:08.451057 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/assignment/core.py", line 780, in list_role_assignments_for_actor
[Fri Aug 07 08:21:08.451072 2020] [:error] [pid 1420287] [remote x.x.x.x:144] group_ids=group_ids, inherited_to_projects=False)
[Fri Aug 07 08:21:08.451081 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib/python2.7/site-packages/keystone/assignment/backends/sql.py", line 248, in list_role_assignments
[Fri Aug 07 08:21:08.451599 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return [denormalize_role(ref) for ref in query.all()]
[Fri Aug 07 08:21:08.451609 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2925, in all
[Fri Aug 07 08:21:08.451632 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return list(self)
[Fri Aug 07 08:21:08.451641 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 3081, in __iter__
[Fri Aug 07 08:21:08.451656 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return self._execute_and_instances(context)
[Fri Aug 07 08:21:08.451665 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 3106, in _execute_and_instances
[Fri Aug 07 08:21:08.451683 2020] [:error] [pid 1420287] [remote x.x.x.x:144] result = conn.execute(querycontext.statement, self._params)
[Fri Aug 07 08:21:08.451691 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 980, in execute
[Fri Aug 07 08:21:08.451711 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return meth(self, multiparams, params)
[Fri Aug 07 08:21:08.451720 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 273, in _execute_on_connection
[Fri Aug 07 08:21:08.451736 2020] [:error] [pid 1420287] [remote x.x.x.x:144] return connection._execute_clauseelement(self, multiparams, params)
[Fri Aug 07 08:21:08.451745 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1099, in _execute_clauseelement
[Fri Aug 07 08:21:08.451762 2020] [:error] [pid 1420287] [remote x.x.x.x:144] distilled_params,
[Fri Aug 07 08:21:08.451771 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1240, in _execute_context
[Fri Aug 07 08:21:08.451786 2020] [:error] [pid 1420287] [remote x.x.x.x:144] e, statement, parameters, cursor, context
[Fri Aug 07 08:21:08.451795 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1456, in _handle_dbapi_exception
[Fri Aug 07 08:21:08.451810 2020] [:error] [pid 1420287] [remote x.x.x.x:144] util.raise_from_cause(newraise, exc_info)
[Fri Aug 07 08:21:08.451818 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 296, in raise_from_cause
[Fri Aug 07 08:21:08.451834 2020] [:error] [pid 1420287] [remote x.x.x.x:144] reraise(type(exception), exception, tb=exc_tb, cause=cause)
[Fri Aug 07 08:21:08.451843 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1236, in _execute_context
[Fri Aug 07 08:21:08.451858 2020] [:error] [pid 1420287] [remote x.x.x.x:144] cursor, statement, parameters, context
[Fri Aug 07 08:21:08.451866 2020] [:error] [pid 1420287] [remote x.x.x.x:144] File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 536, in do_execute
[Fri Aug 07 08:21:08.451882 2020] [:error] [pid 1420287] [remote x.x.x.x:144] cursor.execute(statement, parameters)
[Fri Aug 07 08:21:08.451923 2020] [:error] [pid 1420287] [remote x.x.x.x:144] DBNonExistentTable: (sqlite3.OperationalError) no such table: assignment [SQL: u'SELECT assignment.type AS assignment_type, assignment.actor_id AS assignment_actor_id, assignment.target_id AS assignment_target_id, assignment.role_id AS assignment_role_id, assignment.inherited AS assignment_inherited \\nFROM assignment \\nWHERE assignment.actor_id IN (?) AND assignment.target_id IN (?) AND assignment.type IN (?) AND assignment.inherited = 0'] [parameters: ('15c2fe91e053af57a997c568c117c908d59c138f996bdc19ae97e9f16df12345', '12345978536e45ab8a279e2b0fa4f947', 'UserProject')] (Background on this error at: http://sqlalche.me/e/e3q8)

Revision history for this message
Divya K Konoor (dikonoor) wrote :

Some additional piece of information is that this is observed only in cases where httpd service is restarted.. well not in all cases of restart.

Revision history for this message
Divya K Konoor (dikonoor) wrote :

I am wondering if either of the below is the cause:

1. the existing process has probably not let go of the connection (for some reason) and /or the new process did not get a handle to the connection- internally sqllite creates an empty in-memory database, which does not have any tables and that leads the second process into DBNonExistent errors. I see that these errors are thrown from the oslo_db/sqlalchemy layer and the error thrown from sqllite is no such table.

2. the first process still holds a handle to the connection; the second process gets another handle; the first process as it is dying closes the connection- the second process thinks it still has a live connection when it actually does not have. https://www.sqlite.org/howtocorrupt.html discusses about different possibility of how existence of multiple processes could lead to different issues.

Revision history for this message
Divya K Konoor (dikonoor) wrote :
Download full text (3.9 KiB)

Upon further analysis, it seems like the keystone /httpd logrotate is what is causing the httpd service to reload. Unlike what was though of earlier, the cause seems to be httpd reload instead of a restart. The log rotate files for keystone / httpd looks like the below:

https://access.redhat.com/solutions/2626601 (some related data)

# cat /etc/logrotate.d/openstack-keystone
/var/log/keystone/*.log {
    size 10M
    rotate 4
    missingok
    compress
postrotate
/bin/systemctl reload httpd.service > /dev/null 2>/dev/null || true >> reloads httpd service after logrotate
endscript
}

/var/log/keystone/*/*.log {
    size 10M
    rotate 4
    missingok
    compress
postrotate
/bin/systemctl reload httpd.service > /dev/null 2>/dev/null || true
endscript
}

# cat httpd
/var/log/httpd/*log {
    missingok
    notifempty
    sharedscripts
    delaycompress
    postrotate
        /bin/systemctl reload httpd.service > /dev/null 2>/dev/null || true
    endscript
}

httpd reload internally kills and starts the wsgidaemon processes running inside it. Keystone processes run as wsgi daemon processes in my environment. In a graceful restart of httpd, keystone processes stop gracefully and start properly. When keystone process starts, it gets a handle to mariadb based connection from /etc/keystone/keystone.conf via oslo.db / sqlalchemy. However, in cases where this problem is reported, a sqllite3 error is reported.

/etc/httpd/conf.d/keystone.conf:
Listen 5000
<VirtualHost *:5000>
   SSLEngine on
   SSLProtocol +TLSv1.2
.....
....
   WSGIDaemonProcess keystone-public user=keystone group=keystone display-name=keystone-public >> wsg daemon running inside httpd for keystone

[:error] [pid 1420287] [remote x.x.x.x:144] DBNonExistentTable: (sqlite3.OperationalError) no such table: assignment [SQL: u'SELECT assignment.type AS assignment_type, assignment.actor_id AS assignment_actor_id, assignment.target_id AS assignment_target_id, assignment.role_id AS assignment_role_id, assignment.inherited AS assignment_inherited \\nFROM assignment \\nWHERE assignment.actor_id IN (?) AND assignment.target_id IN (?) AND assignment.type IN (?) AND assignment.inherited = 0'] [parameters: ('15c2fe91e053af57a997c568c117c908d59c138f996bdc19ae97e9f16df12345', '12345978536e45ab8a279e2b0fa4f947', 'UserProject')] (Background on this error at: http://sqlalche.me/e/e3q8)

My guess is the problem here is that when httpd reload happens, the old keystone process is killed and within a span of 3-5 sec, the new process is spawn and in some very corner cases, the mariadb connection is still with the old process and the new process is unable to acquire it. In such cases, the new process falls back on the default sqllite in-memory keystone.db that does not have any tables. This leads to no such table errors when requests hit keystone process. >> https://github.com/openstack/keystone/blob/stable/stein/keystone/common/sql/core.py#L81

def initialize():
"""Initialize the module."""
db_options.set_defaults(
CONF,
connection="sqlite:///keystone.db")

From >> https://modwsgi.narkive.com/uBZgDFuy/apache-reload-kills-django-process-abruptly

When using daemon mode of mod_wsgi that is how it work...

Read more...

Revision history for this message
Divya K Konoor (dikonoor) wrote :

As a next step, running logrotate with the following configuration to see if this problem can still be reproduced:

cat /etc/logrotate.d/openstack-keystone
/var/log/keystone/*.log {
    size 32M
    rotate 4
    missingok
    compress
    copytruncate
}/var/log/keystone/*/*.log {
    size 32M
    rotate 4
    missingok
    compress
    copytruncate
}

Revision history for this message
Divya K Konoor (dikonoor) wrote :

It is found that when httpd reload is removed from the above, we don't run into this problem. This change merely removes running into this problem by avoiding it and does not solve the root problem.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.