Reviewed: https://review.opendev.org/698954
Committed:
https://git.openstack.org/cgit/openstack/oslo.config/commit/?id=e3e2ba55eeeb86a9bc0624bb2592e46583e839e7
Submitter: Zuul
Branch: master
commit e3e2ba55eeeb86a9bc0624bb2592e46583e839e7
Author: Stephen Finucane <sfinu...@redhat.com>
Date: Fri Dec 13 16:18:33 2019 +0000
Ensure option groups don't change during logging
oslo.config allows us to configure groups and options dynamically. This
can cause a race with our logging as we attempt to iterate through
option groups that are changing under our feet. This wouldn't be a huge
issue, since these are just logs are we can always log again, if needed,
but we store groups in a dictionary and Python doesn't like us changing
the size of a dict it's iterating through:
RuntimeError: dictionary changed size during iteration
Given that we're only reading through this option group and don't need
to worry about a group _disappearing_, the solution is pretty simple:
create a copy of our option group names ahead of time so we don't need
to worry about new ones coming and messing things up.
No tests are included since this is a race and the only way I see to
reproduce this would involve lots of ugly threading.
Change-Id: Id3b28465d645a24f0fcebff2dd68a9bd30e21594
Signed-off-by: Stephen Finucane <sfinu...@redhat.com>
Closes-Bug: #1856312
** Changed in: oslo.config
Status: In Progress => Fix Released
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1856312
Title:
RuntimeError during calling log_opts_values
Status in OpenStack Compute (nova):
Invalid
Status in oslo.config:
Fix Released
Bug description:
During starting up nova-compute service, we are hit by the following
error message
+ sed -i s/HOST_IP// /tmp/logging-nova-compute.conf
+ exec nova-compute --config-file /etc/nova/nova.conf --config-file
/tmp/pod-shared/nova-console.conf --config-file
/tmp/pod-shared/nova-libvirt.conf --config-file
/tmp/pod-shared/nova-hypervisor.conf --log-config-append
/tmp/logging-nova-compute.conf
2019-12-13 06:53:09.556 29036 WARNING oslo_config.cfg [-] Deprecated: Option
"use_neutron" from group "DEFAULT" is deprecated for removal (
nova-network is deprecated, as are any related configuration options.
). Its value may be silently ignored in the future.
2019-12-13 06:53:12.000 29036 INFO nova.compute.rpcapi
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Automatically selected
compute RPC version 5.0 from minimum service version 35
2019-12-13 06:53:12.000 29036 INFO nova.compute.rpcapi
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Automatically selected
compute RPC version 5.0 from minimum service version 35
2019-12-13 06:53:12.029 29036 INFO nova.virt.driver
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Loading compute driver
'libvirt.LibvirtDriver'
2019-12-13 06:53:12.029 29036 INFO nova.virt.driver
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Loading compute driver
'libvirt.LibvirtDriver'
2019-12-13 06:53:22.064 29036 WARNING oslo_config.cfg
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Deprecated: Option
"firewall_driver" from group "DEFAULT" is deprecated for removal (
nova-network is deprecated, as are any related configuration options.
). Its value may be silently ignored in the future.
2019-12-13 06:53:22.192 29036 WARNING os_brick.initiator.connectors.remotefs
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Connection details not
present. RemoteFsClient may not initialize properly.
2019-12-13 06:53:22.409 29036 WARNING oslo_config.cfg
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Deprecated: Option
"linuxnet_interface_driver" from group "DEFAULT" is deprecated for removal (
nova-network is deprecated, as are any related configuration options.
). Its value may be silently ignored in the future.
2019-12-13 06:53:22.414 29036 WARNING oslo_config.cfg
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Deprecated: Option
"metadata_port" from group "DEFAULT" is deprecated for removal (
nova-network is deprecated, as are any related configuration options.
). Its value may be silently ignored in the future.
2019-12-13 06:53:22.440 29036 INFO nova.service [-] Starting compute node
(version 18.0.0)
2019-12-13 06:53:22.570 29036 WARNING oslo_config.cfg
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Deprecated: Option
"api_endpoint" from group "ironic" is deprecated for removal (Endpoint lookup
uses the service catalog via common keystoneauth1 Adapter configuration
options. In the current release, api_endpoint will override this behavior, but
will be ignored and/or removed in a future release. To achieve the same result,
use the endpoint_override option instead.). Its value may be silently ignored
in the future.
2019-12-13 06:53:22.440 29036 INFO nova.service [-] Starting compute node
(version 18.0.0)
2019-12-13 06:53:22.594 29036 WARNING oslo_config.cfg
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Deprecated: Option
"api_endpoint" from group "ironic" is deprecated. Use option
"endpoint-override" from group "ironic".
2019-12-13 06:53:22.911 29036 CRITICAL nova
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Unhandled error:
RuntimeError: dictionary changed size during iteration
2019-12-13 06:53:22.911 29036 ERROR nova Traceback (most recent call last):
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/bin/nova-compute", line 8, in <module>
2019-12-13 06:53:22.911 29036 ERROR nova sys.exit(main())
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/nova/inspur/cmd/compute.py",
line 71, in main
2019-12-13 06:53:22.911 29036 ERROR nova service.wait()
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/nova/service.py", line
460, in wait
2019-12-13 06:53:22.911 29036 ERROR nova _launcher.wait()
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/oslo_service/service.py",
line 392, in wait
2019-12-13 06:53:22.911 29036 ERROR nova status, signo =
self._wait_for_exit_or_signal()
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/oslo_service/service.py",
line 367, in _wait_for_exit_or_signal
2019-12-13 06:53:22.911 29036 ERROR nova self.conf.log_opt_values(LOG,
logging.DEBUG)
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/oslo_config/cfg.py", line
2579, in log_opt_values
2019-12-13 06:53:22.911 29036 ERROR nova for group_name in self._groups:
2019-12-13 06:53:22.911 29036 ERROR nova RuntimeError: dictionary changed
size during iteration
2019-12-13 06:53:22.911 29036 ERROR nova
2019-12-13 06:53:22.911 29036 CRITICAL nova
[req-eec76cc3-35a9-4d1d-bb91-4c484f6ef855 - - - - -] Unhandled error:
RuntimeError: dictionary changed size during iteration
2019-12-13 06:53:22.911 29036 ERROR nova Traceback (most recent call last):
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/bin/nova-compute", line 8, in <module>
2019-12-13 06:53:22.911 29036 ERROR nova sys.exit(main())
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/nova/inspur/cmd/compute.py",
line 71, in main
2019-12-13 06:53:22.911 29036 ERROR nova service.wait()
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/nova/service.py", line
460, in wait
2019-12-13 06:53:22.911 29036 ERROR nova _launcher.wait()
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/oslo_service/service.py",
line 392, in wait
2019-12-13 06:53:22.911 29036 ERROR nova status, signo =
self._wait_for_exit_or_signal()
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/oslo_service/service.py",
line 367, in _wait_for_exit_or_signal
2019-12-13 06:53:22.911 29036 ERROR nova self.conf.log_opt_values(LOG,
logging.DEBUG)
2019-12-13 06:53:22.911 29036 ERROR nova File
"/var/lib/openstack/local/lib/python2.7/site-packages/oslo_config/cfg.py", line
2579, in log_opt_values
2019-12-13 06:53:22.911 29036 ERROR nova for group_name in self._groups:
2019-12-13 06:53:22.911 29036 ERROR nova RuntimeError: dictionary
changed size during iteration
Looks like cfg._groups is changing while iterating through dictionary
object.
After some debugging, I believe the problem is introduced by this
commit https://review.opendev.org/#/c/564440/ where a new group is
registered by `register_dynamic_opts`. This situation seems rare
enough and I am suspecting we are caught because server's load is very
high. But still, I think it's good to have a better way to lock the
object.
Currently the workaround is to disable `log_options`, and I think the
default value should also be False as well.
To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1856312/+subscriptions
--
Mailing list: https://launchpad.net/~yahoo-eng-team
Post to : yahoo-eng-team@lists.launchpad.net
Unsubscribe : https://launchpad.net/~yahoo-eng-team
More help : https://help.launchpad.net/ListHelp
