1651554 – [OSP13] placement API fail to start if nova-manage api_db sync not finished

Bug 1651554 - [OSP13] placement API fail to start if nova-manage api_db sync not finished

Summary: [OSP13] placement API fail to start if nova-manage api_db sync not finished

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	openstack-tripleo-heat-templates
Sub Component:
Version:	13.0 (Queens)
Hardware:	x86_64
OS:	Linux
Priority:	medium
Severity:	high
Target Milestone:	z5
Target Release:	13.0 (Queens)
Assignee:	Martin Schuppert
QA Contact:	Gurenko Alex
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2018-11-20 10:35 UTC by Martin Schuppert
Modified:	2019-09-09 16:47 UTC (History)
CC List:	18 users (show)
Fixed In Version:	openstack-tripleo-heat-templates-8.0.7-26.el7ost
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:	1636399
Environment:
Last Closed:	2019-03-14 13:54:52 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Priority	Status	Summary	Last Updated
Launchpad	1784155	None	None	None	2018-11-20 10:35:44 UTC
OpenStack gerrit	623227	None	MERGED	Change step to start nova placement and make compute wait for it	2020-09-19 07:32:29 UTC
OpenStack gerrit	623228	None	MERGED	nova_compute fails to start in tls-everywhere configuration	2020-09-19 07:32:29 UTC
Red Hat Product Errata	RHBA-2019:0448	None	None	None	2019-03-14 13:55:01 UTC

Description Martin Schuppert 2018-11-20 10:35:45 UTC

+++ This bug was initially created as a clone of Bug #1636399 +++

Using this bug to track the deployment race aspect of this issue.


+++ This bug was initially created as a clone of Bug #1630069 +++

Unable to launch instance after deployment.
Gets stuck in BUILD. 
nova-compute shows:
ResourceProviderSyncFailed: Failed to synchronize the placement service with resource provider information supplied by the compute host.

Environment:
openstack-nova-common-18.0.1-0.20180830232802.43f6f74.el7ost.noarch
python2-novaclient-11.0.0-0.20180809174649.f1005ce.el7ost.noarch
openstack-nova-migration-18.0.1-0.20180830232802.43f6f74.el7ost.noarch
puppet-nova-13.3.1-0.20180831195236.ce0efbe.el7ost.noarch
python-nova-18.0.1-0.20180830232802.43f6f74.el7ost.noarch
openstack-nova-compute-18.0.1-0.20180830232802.43f6f74.el7ost.noarch
openstack-tripleo-heat-templates-9.0.0-0.20180831204457.17bb71e.0rc1.el7ost
instack-undercloud-9.3.1-0.20180831000258.e464799.el7ost.noarch

Steps to reproduce:

Deployed OC on BM setup.
Try to launch an instance.

Result:
The instance gets stuck:
(overcloud) [stack@undercloud ~]$ openstack server list
+--------------------------------------+--------------+--------+----------+--------+---------+
| ID                                   | Name         | Status | Networks | Image  | Flavor  |
+--------------------------------------+--------------+--------+----------+--------+---------+
| ecf1d7c4-8b03-4528-96b5-ddc3a21b2558 | after_deploy | BUILD  |          | cirros | m1.tiny |
+--------------------------------------+--------------+--------+----------+--------+---------+



<h1>Internal Server Error</h1>
<p>The server encountered an internal error or
misconfiguration and was unable to complete
your request.</p>
<p>Please contact the server administrator at 
 [no address given] to inform them of the time this error occurred,
 and the actions you performed just before this error.</p>
<p>More information about this error may be available
in the server error log.</p>
</body></html>
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager [req-268c54e7-9f4f-459f-84f1-5c1f3ab41746 - - - - -] Error updating resources for node overcloud-compute-0.localdomain.: ResourceProvider
SyncFailed: Failed to synchronize the placement service with resource provider information supplied by the compute host.
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager Traceback (most recent call last):
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 7722, in _update_available_resource_for_node
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     rt.update_available_resource(context, nodename)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py", line 703, in update_available_resource
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     self._update_available_resource(context, resources)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 274, in inner
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     return f(*args, **kwargs)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py", line 726, in _update_available_resource
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     self._init_compute_node(context, resources)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py", line 593, in _init_compute_node
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     self._update(context, cn)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/retrying.py", line 68, in wrapped_f
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     return Retrying(*dargs, **dkw).call(f, *args, **kw)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/retrying.py", line 223, in call
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     return attempt.get(self._wrap_exception)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/retrying.py", line 261, in get
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     six.reraise(self.value[0], self.value[1], self.value[2])
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/retrying.py", line 217, in call
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     attempt = Attempt(fn(*args, **kwargs), attempt_number, False)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py", line 938, in _update
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     self._update_to_placement(context, compute_node)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/compute/resource_tracker.py", line 907, in _update_to_placement
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     reportclient.update_from_provider_tree(context, prov_tree)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/scheduler/client/__init__.py", line 37, in __run_method
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     return getattr(self.instance, __name)(*args, **kwargs)
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager   File "/usr/lib/python2.7/site-packages/nova/scheduler/client/report.py", line 1535, in update_from_provider_tree
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager     raise exception.ResourceProviderSyncFailed()
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager ResourceProviderSyncFailed: Failed to synchronize the placement service with resource provider information supplied by the compute host.
2018-09-17 19:47:18.271 1 ERROR nova.compute.manager 



Repeating error in /var/log/containers/httpd/nova-placement/placement_wsgi_error.log on controllers:
[Mon Sep 17 19:37:25.276009 2018] [:error] [pid 16] [remote 10.19.94.28:80] mod_wsgi (pid=16): Exception occurred processing WSGI script '/var/www/cgi-bin/nova/nova-placement-api'.
[Mon Sep 17 19:37:25.276033 2018] [:error] [pid 16] [remote 10.19.94.28:80] Traceback (most recent call last):
[Mon Sep 17 19:37:25.276055 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/var/www/cgi-bin/nova/nova-placement-api", line 54, in <module>
[Mon Sep 17 19:37:25.276092 2018] [:error] [pid 16] [remote 10.19.94.28:80]     application = init_application()
[Mon Sep 17 19:37:25.276105 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/wsgi.py", line 102, in init_application
[Mon Sep 17 19:37:25.276132 2018] [:error] [pid 16] [remote 10.19.94.28:80]     _parse_args([], default_config_files=[conffile])
[Mon Sep 17 19:37:25.276144 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/wsgi.py", line 62, in _parse_args
[Mon Sep 17 19:37:25.276164 2018] [:error] [pid 16] [remote 10.19.94.28:80]     logging.register_options(conf.CONF)
[Mon Sep 17 19:37:25.276174 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/oslo_log/log.py", line 250, in register_options
[Mon Sep 17 19:37:25.276195 2018] [:error] [pid 16] [remote 10.19.94.28:80]     conf.register_cli_opts(_options.common_cli_opts)
[Mon Sep 17 19:37:25.276209 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2501, in __inner
[Mon Sep 17 19:37:25.276927 2018] [:error] [pid 16] [remote 10.19.94.28:80]     result = f(self, *args, **kwargs)
[Mon Sep 17 19:37:25.276949 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2783, in register_cli_opts
[Mon Sep 17 19:37:25.276974 2018] [:error] [pid 16] [remote 10.19.94.28:80]     self.register_cli_opt(opt, group, clear_cache=False)
[Mon Sep 17 19:37:25.276985 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2505, in __inner
[Mon Sep 17 19:37:25.277004 2018] [:error] [pid 16] [remote 10.19.94.28:80]     return f(self, *args, **kwargs)
[Mon Sep 17 19:37:25.277014 2018] [:error] [pid 16] [remote 10.19.94.28:80]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2775, in register_cli_opt
[Mon Sep 17 19:37:25.277032 2018] [:error] [pid 16] [remote 10.19.94.28:80]     raise ArgsAlreadyParsedError("cannot register CLI option")
[Mon Sep 17 19:37:25.277057 2018] [:error] [pid 16] [remote 10.19.94.28:80] ArgsAlreadyParsedError: arguments already parsed: cannot register CLI option
[Mon Sep 17 19:38:55.686870 2018] [:error] [pid 19] [remote 10.19.94.28:88] mod_wsgi (pid=19): Target WSGI script '/var/www/cgi-bin/nova/nova-placement-api' cannot be loaded as Python module.


--- Additional comment from Lee Yarwood on 2018-09-18 11:02:43 EDT ---

Looks like some kind of DB sync race with the initial start of the service on controller-1 :

sosreport-overcloud-controller-1-20180917224003/var/log/containers/httpd/nova-placement/placement_wsgi_error.log

   1 [Mon Sep 17 19:32:12.265597 2018] [:error] [pid 19] [remote 10.19.94.28:0] mod_wsgi (pid=19): Target WSGI script '/var/www/cgi-bin/nova/nova-placement-api' cannot be loaded as Python module.
   2 [Mon Sep 17 19:32:12.265662 2018] [:error] [pid 19] [remote 10.19.94.28:0] mod_wsgi (pid=19): Exception occurred processing WSGI script '/var/www/cgi-bin/nova/nova-placement-api'.
   3 [Mon Sep 17 19:32:12.265693 2018] [:error] [pid 19] [remote 10.19.94.28:0] Traceback (most recent call last):
   4 [Mon Sep 17 19:32:12.265713 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/var/www/cgi-bin/nova/nova-placement-api", line 54, in <module>
   5 [Mon Sep 17 19:32:12.265748 2018] [:error] [pid 19] [remote 10.19.94.28:0]     application = init_application()
   6 [Mon Sep 17 19:32:12.265761 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/wsgi.py", line 115, in init_application
   7 [Mon Sep 17 19:32:12.265788 2018] [:error] [pid 19] [remote 10.19.94.28:0]     return deploy.loadapp(conf.CONF)
   8 [Mon Sep 17 19:32:12.265799 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/deploy.py", line 119, in loadapp
   9 [Mon Sep 17 19:32:12.265919 2018] [:error] [pid 19] [remote 10.19.94.28:0]     update_database()
  10 [Mon Sep 17 19:32:12.265934 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/deploy.py", line 99, in update_database
  11 [Mon Sep 17 19:32:12.265961 2018] [:error] [pid 19] [remote 10.19.94.28:0]     resource_provider.ensure_trait_sync(ctx)
  12 [Mon Sep 17 19:32:12.265973 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/objects/resource_provider.py", line 146, in ensure_trait_sync
  13 [Mon Sep 17 19:32:12.266915 2018] [:error] [pid 19] [remote 10.19.94.28:0]     _trait_sync(ctx)
  14 [Mon Sep 17 19:32:12.266936 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 154, in wrapper
  15 [Mon Sep 17 19:32:12.267076 2018] [:error] [pid 19] [remote 10.19.94.28:0]     ectxt.value = e.inner_exc
  16 [Mon Sep 17 19:32:12.267090 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 220, in __exit__
  17 [Mon Sep 17 19:32:12.267219 2018] [:error] [pid 19] [remote 10.19.94.28:0]     self.force_reraise()
  18 [Mon Sep 17 19:32:12.267234 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
  19 [Mon Sep 17 19:32:12.267256 2018] [:error] [pid 19] [remote 10.19.94.28:0]     six.reraise(self.type_, self.value, self.tb)
  20 [Mon Sep 17 19:32:12.267266 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 142, in wrapper
  21 [Mon Sep 17 19:32:12.267284 2018] [:error] [pid 19] [remote 10.19.94.28:0]     return f(*args, **kwargs)
  22 [Mon Sep 17 19:32:12.267295 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 993, in wrapper
  23 [Mon Sep 17 19:32:12.267615 2018] [:error] [pid 19] [remote 10.19.94.28:0]     return fn(*args, **kwargs)
  24 [Mon Sep 17 19:32:12.267635 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/objects/resource_provider.py", line 102, in _trait_sync
  25 [Mon Sep 17 19:32:12.267661 2018] [:error] [pid 19] [remote 10.19.94.28:0]     res = ctx.session.execute(sel).fetchall()
  26 [Mon Sep 17 19:32:12.267675 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 1176, in execute
  27 [Mon Sep 17 19:32:12.268321 2018] [:error] [pid 19] [remote 10.19.94.28:0]     bind, close_with_result=True).execute(clause, params or {})
  28 [Mon Sep 17 19:32:12.268336 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 948, in execute
  29 [Mon Sep 17 19:32:12.268823 2018] [:error] [pid 19] [remote 10.19.94.28:0]     return meth(self, multiparams, params)
  30 [Mon Sep 17 19:32:12.268851 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
  31 [Mon Sep 17 19:32:12.269668 2018] [:error] [pid 19] [remote 10.19.94.28:0]     return connection._execute_clauseelement(self, multiparams, params)
  32 [Mon Sep 17 19:32:12.269688 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
  33 [Mon Sep 17 19:32:12.269712 2018] [:error] [pid 19] [remote 10.19.94.28:0]     compiled_sql, distilled_params
  34 [Mon Sep 17 19:32:12.269724 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
  35 [Mon Sep 17 19:32:12.269743 2018] [:error] [pid 19] [remote 10.19.94.28:0]     context)
  36 [Mon Sep 17 19:32:12.269753 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
  37 [Mon Sep 17 19:32:12.269772 2018] [:error] [pid 19] [remote 10.19.94.28:0]     util.raise_from_cause(newraise, exc_info)
  38 [Mon Sep 17 19:32:12.269783 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
  39 [Mon Sep 17 19:32:12.269884 2018] [:error] [pid 19] [remote 10.19.94.28:0]     reraise(type(exception), exception, tb=exc_tb, cause=cause)
  40 [Mon Sep 17 19:32:12.269898 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
  41 [Mon Sep 17 19:32:12.269920 2018] [:error] [pid 19] [remote 10.19.94.28:0]     context)
  42 [Mon Sep 17 19:32:12.269934 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
  43 [Mon Sep 17 19:32:12.270234 2018] [:error] [pid 19] [remote 10.19.94.28:0]     cursor.execute(statement, parameters)
  44 [Mon Sep 17 19:32:12.270248 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
  45 [Mon Sep 17 19:32:12.270396 2018] [:error] [pid 19] [remote 10.19.94.28:0]     result = self._query(query)
  46 [Mon Sep 17 19:32:12.270410 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
  47 [Mon Sep 17 19:32:12.270431 2018] [:error] [pid 19] [remote 10.19.94.28:0]     conn.query(q)
  48 [Mon Sep 17 19:32:12.270442 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
  49 [Mon Sep 17 19:32:12.270808 2018] [:error] [pid 19] [remote 10.19.94.28:0]     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  50 [Mon Sep 17 19:32:12.270828 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
  51 [Mon Sep 17 19:32:12.270851 2018] [:error] [pid 19] [remote 10.19.94.28:0]     result.read()
  52 [Mon Sep 17 19:32:12.270866 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
  53 [Mon Sep 17 19:32:12.270886 2018] [:error] [pid 19] [remote 10.19.94.28:0]     first_packet = self.connection._read_packet()
  54 [Mon Sep 17 19:32:12.270897 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1014, in _read_packet
  55 [Mon Sep 17 19:32:12.270916 2018] [:error] [pid 19] [remote 10.19.94.28:0]     packet.check_error()
  56 [Mon Sep 17 19:32:12.270927 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
  57 [Mon Sep 17 19:32:12.270945 2018] [:error] [pid 19] [remote 10.19.94.28:0]     err.raise_mysql_exception(self._data)
  58 [Mon Sep 17 19:32:12.270956 2018] [:error] [pid 19] [remote 10.19.94.28:0]   File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
  59 [Mon Sep 17 19:32:12.271049 2018] [:error] [pid 19] [remote 10.19.94.28:0]     raise errorclass(errno, errval)
  60 [Mon Sep 17 19:32:12.271112 2018] [:error] [pid 19] [remote 10.19.94.28:0] ProgrammingError: (pymysql.err.ProgrammingError) (1146, u"Table 'nova_placement.traits' doesn't exist") [SQL: u'SELECT traits.name \\nFROM traits'] (Background on this error at: http://sqlalche.me/e/f405)
[..]
 121 [Mon Sep 17 19:34:20.002384 2018] [:error] [pid 19] [remote 10.19.94.28:88] mod_wsgi (pid=19): Target WSGI script '/var/www/cgi-bin/nova/nova-placement-api' cannot be loaded as Python module.
 122 [Mon Sep 17 19:34:20.002432 2018] [:error] [pid 19] [remote 10.19.94.28:88] mod_wsgi (pid=19): Exception occurred processing WSGI script '/var/www/cgi-bin/nova/nova-placement-api'.
 123 [Mon Sep 17 19:34:20.002475 2018] [:error] [pid 19] [remote 10.19.94.28:88] Traceback (most recent call last):
 124 [Mon Sep 17 19:34:20.002518 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/var/www/cgi-bin/nova/nova-placement-api", line 54, in <module>
 125 [Mon Sep 17 19:34:20.002587 2018] [:error] [pid 19] [remote 10.19.94.28:88]     application = init_application()
 126 [Mon Sep 17 19:34:20.002632 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/wsgi.py", line 102, in init_application
 127 [Mon Sep 17 19:34:20.002702 2018] [:error] [pid 19] [remote 10.19.94.28:88]     _parse_args([], default_config_files=[conffile])
 128 [Mon Sep 17 19:34:20.002728 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/nova/api/openstack/placement/wsgi.py", line 62, in _parse_args
 129 [Mon Sep 17 19:34:20.002771 2018] [:error] [pid 19] [remote 10.19.94.28:88]     logging.register_options(conf.CONF)
 130 [Mon Sep 17 19:34:20.002795 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/oslo_log/log.py", line 250, in register_options
 131 [Mon Sep 17 19:34:20.002838 2018] [:error] [pid 19] [remote 10.19.94.28:88]     conf.register_cli_opts(_options.common_cli_opts)
 132 [Mon Sep 17 19:34:20.002866 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2501, in __inner
 133 [Mon Sep 17 19:34:20.004316 2018] [:error] [pid 19] [remote 10.19.94.28:88]     result = f(self, *args, **kwargs)
 134 [Mon Sep 17 19:34:20.004362 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2783, in register_cli_opts
 135 [Mon Sep 17 19:34:20.004414 2018] [:error] [pid 19] [remote 10.19.94.28:88]     self.register_cli_opt(opt, group, clear_cache=False)
 136 [Mon Sep 17 19:34:20.004438 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2505, in __inner
 137 [Mon Sep 17 19:34:20.004477 2018] [:error] [pid 19] [remote 10.19.94.28:88]     return f(self, *args, **kwargs)
 138 [Mon Sep 17 19:34:20.004500 2018] [:error] [pid 19] [remote 10.19.94.28:88]   File "/usr/lib/python2.7/site-packages/oslo_config/cfg.py", line 2775, in register_cli_opt
 139 [Mon Sep 17 19:34:20.004539 2018] [:error] [pid 19] [remote 10.19.94.28:88]     raise ArgsAlreadyParsedError("cannot register CLI option")
 140 [Mon Sep 17 19:34:20.004587 2018] [:error] [pid 19] [remote 10.19.94.28:88] ArgsAlreadyParsedError: arguments already parsed: cannot register CLI option
 141 [Mon Sep 17 19:37:25.275976 2018] [:error] [pid 16] [remote 10.19.94.28:80] mod_wsgi (pid=16): Target WSGI script '/var/www/cgi-bin/nova/nova-placement-api' cannot be loaded as Python module.

--- Additional comment from Martin Schuppert on 2018-10-25 14:23:22 EDT ---

With the fix during overcloud deploy we could see on ctrl1 + 2 where the db_sync is not running something like:

[root@controller-1 ~]# grep  INFO:nova_wait_for_db_sync /var/log/messages                                                                                                                                                                                                                 
Oct 25 13:32:48 controller-1 journal: INFO:nova_wait_for_db_sync:Nova API DB sync not yet finished. Migrationnumber DB/files (0/61)
Oct 25 13:32:58 controller-1 journal: INFO:nova_wait_for_db_sync:Nova API DB sync not yet finished. Migrationnumber DB/files (13/61)
Oct 25 13:33:08 controller-1 journal: INFO:nova_wait_for_db_sync:Nova API DB sync finished. Migration number 61

[root@controller-2 ~]# grep  INFO:nova_wait_for_db_sync /var/log/messages
Oct 25 13:32:50 controller-2 journal: INFO:nova_wait_for_db_sync:Nova API DB sync not yet finished. Migrationnumber DB/files (0/61)
Oct 25 13:33:00 controller-2 journal: INFO:nova_wait_for_db_sync:Nova API DB sync not yet finished. Migrationnumber DB/files (35/61)
Oct 25 13:33:10 controller-2 journal: INFO:nova_wait_for_db_sync:Nova API DB sync finished. Migration number 61


This BZ tracks the backport to OSP13

Comment 2 Martin Schuppert 2018-12-03 13:34:34 UTC

New approach to fix this issue in OSP14 1652287 . This BZ is to track the backport for this BZ, not the original way.

Comment 21 errata-xmlrpc 2019-03-14 13:54:52 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2019:0448

Note You need to log in before you can comment on or make changes to this bug.