Traceback in vif.py execv() arg 2 must contain only strings

[Serguei Bezverkhi]

While bringing up VM with the latest master (August 23,2016) I see this traceback and VM fails to launch.

Complete log is here: http://paste.openstack.org/show/562688/
nova.conf used is here: http://paste.openstack.org/show/562757/

The issue is 100% reproducible in my testbed.

2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [req-81060644-0dd7-453c-a68c-0d9cffe28fe7 3d1cd826f71a49cc81b33e85329f94b3 f738285a670c4be08d8a5e300aa25504 - - -] [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] Instance failed to spawn
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] Traceback (most recent call last):
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/manager.py", line 2075, in _build_resources
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] yield resources
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/compute/manager.py", line 1919, in _build_and_run_instance
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] block_device_info=block_device_info)
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2583, in spawn
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] post_xml_callback=gen_confdrive)
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4803, in _create_domain_and_network
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] self.plug_vifs(instance, network_info)
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 684, in plug_vifs
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] self.vif_driver.plug(instance, vif)
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 801, in plug
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] self._plug_os_vif(instance, vif_obj)
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] File "/var/lib/kolla/venv/lib/python2.7/site-packages/nova/virt/libvirt/vif.py", line 783, in _plug_os_vif
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] raise exception.NovaException(msg)
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219] NovaException: Failure running os_vif plugin plug method: Failed to plug VIF VIFBridge(active=False,address=fa:16:3e:c0:4a:fd,bridge_name='qbrb7b522a4-3f',has_traffic_filtering=True,id=b7b522a4-3faa-42ca-8e0f-d8c241432e1f,network=Network(f32fdde6-bb99-4981-926b-a7df30f0a612),plugin='ovs',port_profile=VIFPortProfileBase,preserve_on_delete=True,vif_name='tapb7b522a4-3f'). Got error: execv() arg 2 must contain only strings
2016-08-23 17:17:28.941 8808 ERROR nova.compute.manager [instance: 95f11702-9e64-445d-a3cd-2cde074a4219]

[Steven Dake (sdake)]

It is possible the deprecations are incorrect. Try the upgrade suggestions:

+++ b/releasenotes/notes/libvirt-uses-os-vif-plugins-31a0617de0c248b9.yaml
@@ -0,0 +1,35 @@
+---
+features:
+ - The Libvirt driver now uses os-vif plugins for
+ handling plug/unplug actions for the Linux Bridge
+ and OpenVSwitch VIF types. Each os-vif plugin will
+ have its own group in nova.conf for configuration
+ parameters it needs. These plugins will be installed
+ by default as part of the os-vif module installation
+ so no special action is required.
+upgrade:
+ - With the introduction of os-vif, some networking related
+ configuration options have moved, and users will need to update
+ their ``nova.conf``.
+
+ For OpenVSwitch users the following options have moved from
+ ``[DEFAULT]`` to ``[vif_plug_ovs]``
+
+ - network_device_mtu
+ - ovs_vsctl_timeout
+
+ For Linux Bridge users the following options have moved from
+ ``[DEFAULT]`` to ``[vif_plug_linux_bridge]``
+
+ - use_ipv6
+ - iptables_top_regex
+ - iptables_bottom_regex
+ - iptables_drop_action
+ - forward_bridge_interface
+ - vlan_interface
+ - flat_interface
+ - network_device_mtu
+
+ For backwards compatibility, and ease of upgrade, these options
+ will continue to work from ``[DEFAULT]`` during the Newton
+ release. However they will not in future releases.

[Steven Dake (sdake)]

Nova and Neutron work together in this part of the codebase to produce results. A link to your neutron.conf would be helpful as well.

[Serguei Bezverkhi (sbezverk)]

Here is neutron.conf: http://paste.openstack.org/show/562832/

These options are not used at all.
network_device_mtu
ovs_vsctl_timeout

[Serguei Bezverkhi (sbezverk)]

I added print for two variable which are passed to os_vif.plug function, please see output below.

    def _plug_os_vif(self, instance, vif):
    776 instance_info = os_vif_util.nova_to_osvif_instance(instance)
    777
    778 LOG.debug('************* instance=%(instance)s ************'
    779 '************* vif=%(vif)s instance info=%(instance_info) *************',
    780 {'instance': instance,
    781 'vif': vif, 'instance_info': instance_info})
    782 try:
    783 os_vif.plug(vif, instance_info)

!================================================================================================
/var/log/kolla/nova/nova-compute.log:2016-08-24 18:49:49.261 4205 DEBUG nova.virt.libvirt.vif [req-9d765dca-e0b0-477a-9906-0d5a74334d4e 3d1cd826f71a49cc81b33e85329f94b3 f738285a670c4be08d8a5e300aa25504 - - -] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='',created_at=2016-08-24T22:49:40Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='kube_vm_1',display_name='kube_vm_1',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(1),host='k8s-4.sbezverk.cisco.com',hostname='kube-vm-1',id=4,image_ref='1e48b8b8-7cd7-4bf7-9c70-643af57ae7ce',info_cache=InstanceInfoCache,instance_type_id=1,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='k8s-4.sbezverk.cisco.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=<?>,new_flavor=None,node='k8s-4.sbezverk.cisco.com',numa_topology=None,old_flavor=None,os_type=None,pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='f738285a670c4be08d8a5e300aa25504',ramdisk_id='',reservation_id='r-6hydn4us',root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={image_base_image_ref='1e48b8b8-7cd7-4bf7-9c70-643af57ae7ce',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0',network_allocated='True'},tags=<?>,task_state='spawning',terminated_at=None,updated_at=2016-08-24T22:49:46Z,user_data=None,user_id='3d1cd826f71a49cc81b33e85329f94b3',uuid=0f1208f4-d0e5-40e9-bb32-abee58496085,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif=VIF({'profile': {}, 'ovs_interfaceid': u'83ee19fc-f171-4cda-9a83-6232a6dcc505', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.57.85.13'})], 'version': 4, 'meta': {'dhcp_server': u'10.57.85.10'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': 'dns', 'address': u'205.151.222.250'})], 'routes': [], 'cidr': u'10.57.85.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.57.85.1'})})], 'meta': {'injected': False, 'tenant_id': u'f738285a670c4be08d8a5e300...

[John Garbutt (johngarbutt)]

Got some more logging here:
http://paste.openstack.org/show/563382/

By adding an extra LOG.exception in the code.

[John Garbutt (johngarbutt)]

So a side bug here, this drops the traceback, would be good to log that here:
https://git.openstack.org/cgit/openstack/nova/tree/nova/virt/libvirt/vif.py#n775

The exception seems to be coming out of here:
https://github.com/openstack/os-vif/blob/master/vif_plug_linux_bridge/linux_net.py#L97

or more likely this:
https://github.com/openstack/os-vif/blob/master/vif_plug_linux_bridge/linux_net.py#L126

[John Garbutt (johngarbutt)]

oh, wait it could be that this cmd is wrong here:
https://github.com/openstack/oslo.privsep/blob/master/oslo_privsep/daemon.py#L304

[John Garbutt (johngarbutt)]

hmm, although priv sep deamon is logging this:

['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'privsep-helper', '--config-file', '/nova/nova.conf', '--config-dir', ['/etc/nova'], '--privsep_context', 'vif_plug_ovs.privsep.vif_plug', '--privsep_sock_path', '/tmp/tmpI6Awof/privsep.sock']

That config-dir looks a bit suspect...

that comes from here:
https://github.com/openstack/oslo.privsep/blob/9bf606327d156de52c9418d5784cd7f29e243487/oslo_privsep/priv_context.py#L159

[John Garbutt (johngarbutt)]

so here is a working log from the gate:

2016-08-26 01:11:58.152 10783 INFO oslo.privsep.daemon [req-63ec8e65-4270-4294-84b2-e0dbedafa17d tempest-MigrationsAdminTest-1947500742 tempest-MigrationsAdminTest-1947500742] Running privsep helper: ['sudo', 'nova-rootwrap', '/etc/nova/rootwrap.conf', 'privsep-helper', '--config-file', '/etc/nova/nova.conf', '--privsep_context', 'os_brick.privileged.default', '--privsep_sock_path', '/tmp/tmpUMnE4F/privsep.sock']

[John Garbutt (johngarbutt)]

For reference I think this is where CONF.config-file and config-dir are coming from:
https://github.com/openstack/oslo.config/blob/bec8753196bf8c7079aed2b8c5fa6ba704a79710/oslo_config/cfg.py#L2152

[Serguei Bezverkhi (sbezverk)]

Testing without --config-dir.
Since we use no standard location of nova.conf, adding config-dir parameters pointing to the rest of configuration, seemed logical at that time.

[John Garbutt (johngarbutt)]

So sbezverk_ confirmed the issue was the --config-dir that priv-sep was passing to the worker. I am looking into a fix for that now.

[John Garbutt (johngarbutt)]

I just uploaded this patch:
https://review.openstack.org/361125

[Jesse Keating (jesse-keating)]

Added tag for newton back port, as this appears to be impacting newton installs. There has yet to be a release of oslo.privsep with this fix in it.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.privsep 1.14.0 release.

[Corey Bryant (corey.bryant)]

Ubuntu SRU details:

[Description]
See bug description.

[Test case]
The patch includes a test case.

[Regression Potential]
Minimal as the patch is cherry-picked from upstream stable/newton branch.

[Corey Bryant (corey.bryant)]

This has been uploaded to the yakkety review queue and is awaiting SRU team review.

[Brian Murray (brian-murray)]

Hello Serguei, or anyone else affected,

Accepted python-oslo.privsep into yakkety-proposed. The package will build now and be available at https://launchpad.net/ubuntu/+source/python-oslo.privsep/1.13.0-0ubuntu1.1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation on how to enable and use -proposed.Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Dr. Jens Harbott (j-harbott)]

Tested with python-oslo.privsep_1.13.0-0ubuntu1.1_all.deb, fix confirmed.

[Brian Murray (brian-murray)]

The verification of the Stable Release Update for python-oslo.privsep has completed successfully and the package has now been released to -updates. Subsequently, the Ubuntu Stable Release Updates Team is being unsubscribed and will not receive messages about this bug report. In the event that you encounter a regression using the package from -updates please report a new bug using ubuntu-bug and tag the bug report regression-update so we can easily find any regressions.

[Launchpad Janitor (janitor)]

This bug was fixed in the package python-oslo.privsep - 1.13.0-0ubuntu1.1

---------------
python-oslo.privsep (1.13.0-0ubuntu1.1) yakkety; urgency=medium

  * d/p/deal-with-conf-config-dir.patch: Cherry pick patch from upstream
    stable/newton branch to properly handle CONF.config_dir (LP: #1616240).

 -- Corey Bryant <email address hidden> Wed, 14 Dec 2016 07:50:45 -0500

[Ryan Beisner (1chb1n)]

This bug was fixed in the package python-oslo.privsep - 1.13.0-0ubuntu1.1~cloud0
---------------

 python-oslo.privsep (1.13.0-0ubuntu1.1~cloud0) xenial-newton; urgency=medium
 .
   * New update for the Ubuntu Cloud Archive.
 .
 python-oslo.privsep (1.13.0-0ubuntu1.1) yakkety; urgency=medium
 .
   * d/p/deal-with-conf-config-dir.patch: Cherry pick patch from upstream
     stable/newton branch to properly handle CONF.config_dir (LP: #1616240).

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.privsep 1.13.2 release.