nova-lvm job failing with ArgsAlreadyParsedError (privsep)

[Matt Riedemann]

Seen here:

http://logs.openstack.org/43/619143/12/check/nova-lvm/786180c/logs/screen-n-cpu.txt.gz?level=TRACE#_Dec_12_12_35_39_607002

Dec 12 12:35:39.607002 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [None req-107a6ea1-f573-4c73-b191-2498e9d6d5ea tempest-AutoAllocateNetworkTest-1112737108 tempest-AutoAllocateNetworkTest-1112737108] [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] Instance failed to spawn: ArgsAlreadyParsedError: arguments already parsed
Dec 12 12:35:39.607240 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] Traceback (most recent call last):
Dec 12 12:35:39.607458 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/compute/manager.py", line 2361, in _build_resources
Dec 12 12:35:39.607676 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] yield resources
Dec 12 12:35:39.607886 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/compute/manager.py", line 2125, in _build_and_run_instance
Dec 12 12:35:39.608118 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] block_device_info=block_device_info)
Dec 12 12:35:39.608334 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3063, in spawn
Dec 12 12:35:39.608549 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] block_device_info=block_device_info)
Dec 12 12:35:39.608761 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3441, in _create_image
Dec 12 12:35:39.608975 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] fallback_from_host)
Dec 12 12:35:39.609190 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3532, in _create_and_inject_local_root
Dec 12 12:35:39.609415 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] instance, size, fallback_from_host)
Dec 12 12:35:39.609654 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 7830, in _try_fetch_image_cache
Dec 12 12:35:39.609878 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] trusted_certs=instance.trusted_certs)
Dec 12 12:35:39.610094 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/imagebackend.py", line 243, in cache
Dec 12 12:35:39.610310 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] *args, **kwargs)
Dec 12 12:35:39.610524 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/imagebackend.py", line 763, in create_image
Dec 12 12:35:39.610758 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] create_lvm_image(base, size)
Dec 12 12:35:39.610973 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py", line 328, in inner
Dec 12 12:35:39.611198 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] return f(*args, **kwargs)
Dec 12 12:35:39.611423 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/libvirt/imagebackend.py", line 731, in create_lvm_image
Dec 12 12:35:39.611639 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] run_as_root=True)
Dec 12 12:35:39.611852 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/images.py", line 117, in convert_image_unsafe
Dec 12 12:35:39.612060 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] _convert_image(source, dest, None, out_format, run_as_root)
Dec 12 12:35:39.612272 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/opt/stack/new/nova/nova/virt/images.py", line 128, in _convert_image
Dec 12 12:35:39.612506 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] source, dest, in_format, out_format, CONF.instances_path)
Dec 12 12:35:39.612745 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/priv_context.py", line 207, in _wrap
Dec 12 12:35:39.612960 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] return self.channel.remote_call(name, args, kwargs)
Dec 12 12:35:39.613174 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py", line 202, in remote_call
Dec 12 12:35:39.613393 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] raise exc_type(*result[2])
Dec 12 12:35:39.613616 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68] ArgsAlreadyParsedError: arguments already parsed
Dec 12 12:35:39.613830 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: d0a6774a-7b73-431b-8768-706e4e4fcc68]

The nova-lvm job is currently non-voting which is why no one probably noticed the regression.

https://github.com/openstack/nova/blob/c72dafad8011198b78fd906f2fc7d1126e3f79f3/.zuul.yaml#L115

[Matt Riedemann (mriedem)]

Maybe it's a bug in privsep:

Dec 12 12:35:44.260912 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [None req-3c3e5204-e1c4-416c-8391-62ba66af2285 tempest-AggregatesAdminTestJSON-1365895366 tempest-AggregatesAdminTestJSON-1365895366] [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] Instance failed to spawn: ImportError: cannot import name api
Dec 12 12:35:44.261208 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] Traceback (most recent call last):
Dec 12 12:35:44.261466 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] File "/opt/stack/new/nova/nova/compute/manager.py", line 2361, in _build_resources
Dec 12 12:35:44.261989 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] yield resources
Dec 12 12:35:44.262247 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] File "/opt/stack/new/nova/nova/compute/manager.py", line 2125, in _build_and_run_instance
Dec 12 12:35:44.262497 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] block_device_info=block_device_info)
Dec 12 12:35:44.262763 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3063, in spawn
Dec 12 12:35:44.263018 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] block_device_info=block_device_info)
Dec 12 12:35:44.263263 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3441, in _create_image
Dec 12 12:35:44.263529 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] fallback_from_host)
Dec 12 12:35:44.263793 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3532, in _create_and_inject_local_root
Dec 12 12:35:44.264040 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] instance, size, fallback_from_host)
Dec 12 12:35:44.264321 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 7830, in _try_fetch_image_cache
Dec 12 12:35:44.264748 ubuntu-xenial-rax-iad-0001148680 nova-compute[29772]: ERROR nova.compute.manager [instance: 32eb08fc-a2d2-4e20-b6e3-3fe606611d36] trusted_certs=instance.trusted_certs)
Dec 12 12:35:44.264995 ubuntu-xenial-rax-iad-000114...

[Matt Riedemann (mriedem)]

I don't know where "ImportError: cannot import name api" is coming from.

[Matt Riedemann (mriedem)]

Looks like maybe this started around Dec 8?

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22ImportError%3A%20cannot%20import%20name%20api%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=10d

[Matt Riedemann (mriedem)]

I wonder if it's something to do with this?

https://github.com/openstack/nova/commit/26521718bdba3bccbf6270e26b76754c26304658

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/628213

[Matt Riedemann (mriedem)]

Looks like there is a circular import:

http://logs.openstack.org/20/621920/2/check/barbican-simple-crypto-devstack-tempest/f013bd9/logs/screen-n-cpu.txt.gz#_Jan_03_17_17_25_525734

Jan 03 17:17:25.525734 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: DEBUG oslo.privsep.daemon [-] privsep: Exception during request[140640899997936]: arguments already parsed: cannot register CLI option {{(pid=1610) loop /usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py:449}}
Jan 03 17:17:25.526027 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: Traceback (most recent call last):
Jan 03 17:17:25.526264 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py", line 445, in loop
Jan 03 17:17:25.526486 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: reply = self._process_cmd(*msg)
Jan 03 17:17:25.526705 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/usr/local/lib/python2.7/dist-packages/oslo_privsep/daemon.py", line 422, in _process_cmd
Jan 03 17:17:25.526924 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: func = importutils.import_class(name)
Jan 03 17:17:25.527147 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/usr/local/lib/python2.7/dist-packages/oslo_utils/importutils.py", line 30, in import_class
Jan 03 17:17:25.527373 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: __import__(mod_str)
Jan 03 17:17:25.527587 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/opt/stack/new/nova/nova/privsep/qemu.py", line 22, in <module>
Jan 03 17:17:25.527812 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: import nova.privsep.utils
Jan 03 17:17:25.528027 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/opt/stack/new/nova/nova/privsep/utils.py", line 30, in <module>
Jan 03 17:17:25.528242 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: from nova import utils as nova_utils
Jan 03 17:17:25.528457 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/opt/stack/new/nova/nova/utils.py", line 53, in <module>
Jan 03 17:17:25.528673 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: import nova.conf
Jan 03 17:17:25.528889 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/opt/stack/new/nova/nova/conf/__init__.py", line 129, in <module>
Jan 03 17:17:25.529112 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: remote_debug.register_cli_opts(CONF)
Jan 03 17:17:25.529327 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/opt/stack/new/nova/nova/conf/remote_debug.py", line 66, in register_cli_opts
Jan 03 17:17:25.529543 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: conf.register_cli_opts(CLI_OPTS, group=debugger_group)
Jan 03 17:17:25.529760 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2041, in __inner
Jan 03 17:17:25.530011 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: result = f(self, *args, **kwargs)
Jan 03 17:17:25.530227 ubuntu-xenial-rax-ord-0001482694 nova-compute[1421]: File "/usr/local/lib/python2.7/dist-packages/oslo_config/cfg.py", line 2327, in regi...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/628302

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.openstack.org/628306

[OpenStack Infra (hudson-openstack)]

Change abandoned by Matt Riedemann (<email address hidden>) on branch: master
Review: https://review.openstack.org/628213
Reason: https://review.openstack.org/#/c/628302/ is hopefully the fix.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/628302
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=a371f11835e422c06be038d8ce79f38e8f64ab0d
Submitter: Zuul
Branch: master

commit a371f11835e422c06be038d8ce79f38e8f64ab0d
Author: Matt Riedemann <email address hidden>
Date: Thu Jan 3 16:12:56 2019 -0500

    Fix circular import in nova.privsep.utils

    Commit 26521718bdba3bccbf6270e26b76754c26304658 imported
    nova.utils into nova.privsep.utils which can cause
    an ImportError due to an ArgsAlreadyParseError because of
    nova.utils importing nova.conf which registers config options.

    For some obscure reason, this is only being noticed when using
    [libvirt]/image_type=lvm, so something in the libvirt lvm image
    backend using privsep is tickling this import error, but regardless
    the nova.privsep code should avoid importing stuff from the
    rest of nova, so this change simply adds a simple
    "generate_random_string" utility to nova.privsep.utils to
    avoid the import.

    Change-Id: I3799869fd4217d12b92d79e27484043ef5b8dc13
    Closes-Bug: #1808247

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/628306
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=f54b43c8b9a30948a270713e9503b54cc1bebc75
Submitter: Zuul
Branch: master

commit f54b43c8b9a30948a270713e9503b54cc1bebc75
Author: Matt Riedemann <email address hidden>
Date: Thu Jan 3 16:42:26 2019 -0500

    Run nova-lvm job on nova/privsep/* changes

    As seen from bug 1808247, there is something about
    the [libvirt]/image_type=lvm configuration that
    tickles privsep in ways that our normal integrated
    gate jobs don't, so this adds nova/privsep/* to the
    whitelist of files to trigger the nova-lvm job.

    Change-Id: I18f749e6089f776fcca386daea0e479b5382a44b
    Related-Bug: #1808247

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 19.0.0.0rc1 release candidate.