yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1856312] [NEW] RuntimeError during calling log_opts_values

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: norman shen <1856312@xxxxxxxxxxxxxxxxxx>
Date: Fri, 13 Dec 2019 12:40:21 -0000
Reply-to: Bug 1856312 <1856312@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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.

** Affects: nova
     Importance: Undecided
         Status: New

-- 
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):
  New

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
Follow ups

[Bug 1856312] Re: RuntimeError during calling log_opts_values
From: OpenStack Infra, 2019-12-17
[Bug 1856312] Re: RuntimeError during calling log_opts_values
From: Matt Riedemann, 2019-12-13
[Bug 1856312] Re: RuntimeError during calling log_opts_values
From: Matt Riedemann, 2019-12-13