rootwrap daemon with libvirt/xen not working

[Thomas Bechtold]

Using:
- SLE12SP1
- xen 4.7
- nova 13.1.2.dev68 (stable-mitaka tarball)

When configuring nova-compute to use the rootwrap daemon and using Xen with libvirt as hypervisor I get the following error when booting a VM:

2016-10-12 15:54:34.216 17936 INFO nova.compute.claims [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Claim successful
2016-10-12 15:54:34.458 17936 INFO nova.virt.osinfo [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] Cannot load Libosinfo: (No module named Libosinfo)
2016-10-12 15:54:34.479 17936 WARNING oslo_config.cfg [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] Option "username" from group "neutron" is deprecated. Use option "user-name" from group "neutron".
2016-10-12 15:54:34.751 17936 INFO nova.virt.libvirt.driver [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Creating image
2016-10-12 15:54:34.758 17936 INFO nova.utils [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] Executing RootwrapDaemonHelper.execute cmd=[u'touch -c /var/lib/nova/instances/_base/309100c6d00d13edba007a0dde00e9889ce0410a'] kwargs=[{'run_as_root': True}]
2016-10-12 15:54:34.795 17936 INFO oslo_rootwrap.client [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] Spawned new rootwrap daemon process with pid=17984
2016-10-12 15:54:36.060 17936 INFO nova.utils [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] Executing RootwrapDaemonHelper.execute cmd=[u'xend status'] kwargs=[{'run_as_root': True}]
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Instance failed to spawn
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Traceback (most recent call last):
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2218, in _build_resources
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] yield resources
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2064, in _build_and_run_instance
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] block_device_info=block_device_info)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2790, in spawn
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] write_to_disk=True)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4746, in _get_guest_xml
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] context)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4605, in _get_guest_config
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] flavor, guest.os_type)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3640, in _get_guest_storage_config
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] inst_type)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 3593, in _get_guest_disk_config
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] self._host.get_version())
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/imagebackend.py", line 176, in libvirt_info
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] self.is_block_dev)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/utils.py", line 133, in pick_disk_driver_name
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] run_as_root=True, check_exit_code=True)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/utils.py", line 56, in execute
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] return utils.execute(*args, **kwargs)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/utils.py", line 386, in execute
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] *cmd, **kwargs)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/nova/utils.py", line 336, in execute
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] cmd, process_input)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib/python2.7/site-packages/oslo_rootwrap/client.py", line 135, in execute
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] res = proxy.run_one_command(cmd, stdin)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "<string>", line 2, in run_one_command
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] File "/usr/lib64/python2.7/multiprocessing/managers.py", line 774, in _callmethod
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] raise convert_to_error(kind, result)
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] RemoteError:
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] ---------------------------------------------------------------------------
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Unserializable message: ('#ERROR', FilterMatchNotExecutable())
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] ---------------------------------------------------------------------------
2016-10-12 15:54:36.062 17936 ERROR nova.compute.manager [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5]
2016-10-12 15:54:36.067 17936 INFO nova.compute.manager [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Terminating instance
2016-10-12 15:54:36.074 17936 INFO nova.virt.libvirt.driver [-] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] During wait destroy, instance disappeared.
2016-10-12 15:54:36.126 17936 INFO nova.virt.libvirt.driver [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Deleting instance files /var/lib/nova/instances/98dbdd8b-ae17-4861-bffe-cc48042f93e5_del
2016-10-12 15:54:36.189 17936 INFO nova.virt.libvirt.driver [req-5f1c8974-b449-41fa-806b-73f705ed1634 47640c082746419f87ae498f7bdab44e 08f3d1224d1845cda767a2193594c3d7 - - -] [instance: 98dbdd8b-ae17-4861-bffe-cc48042f93e5] Deletion of /var/lib/nova/instances/98dbdd8b-ae17-4861-bffe-cc48042f93e5_del complete

[Matt Riedemann (mriedem)]

Looks like it's trying to call the xend executable here:

http://git.openstack.org/cgit/openstack/nova/tree/nova/virt/libvirt/utils.py?h=13.1.2#n129

The xend rootwrap filter is here:

http://git.openstack.org/cgit/openstack/nova/tree/etc/nova/rootwrap.d/compute.filters?h=13.1.2#n248

Do you have that in the compute.filters on your compute node where this fails?

[Thomas Bechtold (toabctl)]

@Matt: Yes. The filters file is there:

$ grep xend /etc/nova/rootwrap.d/compute.filters
# nova/virt/libvirt/utils.py: 'xend', 'status'
xend: CommandFilter, xend, root

[Thomas Bechtold (toabctl)]

Looks like this is a oslo.rootwrap bug and executing an unknown command is not tested in the testsuite.

[OpenStack Infra (hudson-openstack)]

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

[Thomas Bechtold (toabctl)]

@Matt: the review from comment#4 is the reproducer.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/385785
Committed: https://git.openstack.org/cgit/openstack/oslo.rootwrap/commit/?id=16c22e9b1a83c1fa27c1fac071f9c41c5822e019
Submitter: Jenkins
Branch: master

commit 16c22e9b1a83c1fa27c1fac071f9c41c5822e019
Author: Thomas Bechtold <email address hidden>
Date: Thu Oct 13 08:32:08 2016 +0200

    Fix running unknown commands in daemon mode

    Running a unknown command (which is mentioned in the filter
    but not available on the filesystem) leads currently to an exception.
    Make sure that the return codes for both, daemon and non-daemon mode
    are equal when running the same command.
    Also add functional tests for this case.

    Change-Id: I20004c3c370d004b5b76f4c8f8ab167d0949fabf
    Closes-Bug: #1632768

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/newton
Review: https://review.openstack.org/388773

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/388773
Committed: https://git.openstack.org/cgit/openstack/oslo.rootwrap/commit/?id=36e9592359f70c720d93b460d33ea136d3945996
Submitter: Jenkins
Branch: stable/newton

commit 36e9592359f70c720d93b460d33ea136d3945996
Author: Thomas Bechtold <email address hidden>
Date: Thu Oct 13 08:32:08 2016 +0200

    Fix running unknown commands in daemon mode

    Running a unknown command (which is mentioned in the filter
    but not available on the filesystem) leads currently to an exception.
    Make sure that the return codes for both, daemon and non-daemon mode
    are equal when running the same command.
    Also add functional tests for this case.

    Change-Id: I20004c3c370d004b5b76f4c8f8ab167d0949fabf
    Closes-Bug: #1632768
    (cherry picked from commit 16c22e9b1a83c1fa27c1fac071f9c41c5822e019)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.rootwrap 5.1.1 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.rootwrap 5.3.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.rootwrap 5.1.1 release.

[Sean Dague (sdague)]

Automatically discovered version mitaka in description. If this is incorrect, please update the description to include 'nova version: ...'