unplugging vif ERROR in n-cpu log after successful tempest neutron run

[David Kranz]

Happens a lot. For example: http://logs.openstack.org/50/51750/8/check/check-tempest-devstack-vm-neutron/7b73c73/logs/screen-n-cpu.txt.gz

2013-10-22 20:29:59.161 3294 ERROR nova.virt.libvirt.driver [-] [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] During wait destroy, instance disappeared.
2013-10-22 20:29:59.163 DEBUG nova.virt.libvirt.vif [req-b59c1299-a2d5-4ad0-a798-e2d6c57734ce demo demo] vif_type=ovs instance={'vm_state': u'building', 'availability_zone': None, 'terminated_at': None, 'ephemeral_gb': 0, 'instance_type_id': 6, 'user_data': None, 'cleaned': False, 'vm_mode': None, 'deleted_at': None, 'reservation_id': u'r-5n6tip35', 'id': 18, 'disable_terminate': False, 'display_name': u'Server 88a265da-046a-4fc4-b812-59164e7e35c0', 'uuid': '88a265da-046a-4fc4-b812-59164e7e35c0', 'default_swap_device': None, 'hostname': u'server-88a265da-046a-4fc4-b812-59164e7e35c0', 'launched_on': u'devstack-precise-hpcloud-az3-598823', 'display_description': u'', 'key_data': None, 'kernel_id': u'1b2d8a22-2d48-4240-9987-e27de5999746', 'power_state': 0, 'default_ephemeral_device': None, 'progress': 0, 'project_id': u'd66f874bdc1e49a2adedb607234b2f99', 'launched_at': None, 'config_drive': u'', 'node': u'devstack-precise-hpcloud-az3-598823', 'ramdisk_id': u'8243eabc-098b-44cc-8629-73102741d145', 'access_ip_v6': None, 'access_ip_v4': None, 'deleted': False, 'key_name': None, 'updated_at': datetime.datetime(2013, 10, 22, 20, 29, 57, tzinfo=<iso8601.iso8601.Utc object at 0x2b0cf50>), 'host': u'devstack-precise-hpcloud-az3-598823', 'architecture': u'x86_64', 'user_id': u'ebc6b389f1044bed9ebfdc9ef111d268', 'system_metadata': {u'image_architecture': u'x86_64', u'instance_type_memory_mb': u'64', u'instance_type_swap': u'0', u'instance_type_vcpu_weight': None, u'instance_type_root_gb': u'0', u'instance_type_id': u'6', u'image_image_state': u'available', u'instance_type_name': u'm1.nano', u'image_image_location': u's3bucket--tempest-1023546658/cirros-0.3.1-x86_64-blank.img.manifest.xml', u'instance_type_ephemeral_gb': u'0', u'instance_type_rxtx_factor': u'1.0', u'image_disk_format': u'ami', u'instance_type_flavorid': u'42', u'image_container_format': u'ami', u'instance_type_vcpus': u'1', u'image_min_ram': u'0', u'image_min_disk': u'0', u'image_base_image_ref': u'7979e34a-8f16-4d0b-8d6f-4b521d832aee'}, 'task_state': u'deleting', 'shutdown_terminate': False, 'cell_name': None, 'root_gb': 0, 'locked': False, 'name': 'instance-00000012', 'created_at': datetime.datetime(2013, 10, 22, 20, 29, 55, tzinfo=<iso8601.iso8601.Utc object at 0x2b0cf50>), 'locked_by': None, 'launch_index': 0, 'metadata': {}, 'memory_mb': 64, 'vcpus': 1, 'image_ref': u'7979e34a-8f16-4d0b-8d6f-4b521d832aee', 'root_device_name': u'/dev/vda', 'auto_disk_config': False, 'os_type': None, 'scheduled_at': datetime.datetime(2013, 10, 22, 20, 29, 55, tzinfo=<iso8601.iso8601.Utc object at 0x2b0cf50>)} vif=VIF({'ovs_interfaceid': u'725ac9ef-5f13-4eb3-b00b-0bbf1aad3809', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.1.0.5'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.3'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})})], 'meta': {'injected': False, 'tenant_id': u'd66f874bdc1e49a2adedb607234b2f99'}, 'id': u'2b5cb11b-edf9-4e26-a068-bd820c95e106', 'label': u'private'}), 'devname': u'tap725ac9ef-5f', 'qbh_params': None, 'meta': {}, 'address': u'fa:16:3e:31:dd:da', 'type': u'ovs', 'id': u'725ac9ef-5f13-4eb3-b00b-0bbf1aad3809', 'qbg_params': None}) unplug /opt/stack/new/nova/nova/virt/libvirt/vif.py:755
2013-10-22 20:29:59.164 DEBUG nova.openstack.common.processutils [req-b59c1299-a2d5-4ad0-a798-e2d6c57734ce demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr725ac9ef-5f qvb725ac9ef-5f execute /opt/stack/new/nova/nova/openstack/common/processutils.py:147
2013-10-22 20:29:59.178 DEBUG nova.openstack.common.processutils [req-7e492c69-7a37-438e-9918-f3932e88c617 demo demo] Result was 1 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:172
2013-10-22 20:29:59.179 DEBUG nova.openstack.common.processutils [req-7e492c69-7a37-438e-9918-f3932e88c617 demo demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link show dev qvod0a9091e-91 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:147
2013-10-22 20:29:59.301 DEBUG nova.openstack.common.processutils [req-b59c1299-a2d5-4ad0-a798-e2d6c57734ce demo demo] Result was 1 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:172
2013-10-22 20:29:59.302 ERROR nova.virt.libvirt.vif [req-b59c1299-a2d5-4ad0-a798-e2d6c57734ce demo demo] [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] Failed while unplugging vif
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] Traceback (most recent call last):
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] File "/opt/stack/new/nova/nova/virt/libvirt/vif.py", line 636, in unplug_ovs_hybrid
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] utils.execute('brctl', 'delif', br_name, v1_name, run_as_root=True)
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] File "/opt/stack/new/nova/nova/utils.py", line 174, in execute
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] return processutils.execute(*cmd, **kwargs)
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] File "/opt/stack/new/nova/nova/openstack/common/processutils.py", line 178, in execute
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] cmd=' '.join(cmd))
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] ProcessExecutionError: Unexpected error while running command.
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] Command: sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr725ac9ef-5f qvb725ac9ef-5f
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] Exit code: 1
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] Stdout: ''
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0] Stderr: 'interface qvb725ac9ef-5f does not exist!\n'
2013-10-22 20:29:59.302 3294 TRACE nova.virt.libvirt.vif [instance: 88a265da-046a-4fc4-b812-59164e7e35c0]
2

[Davanum Srinivas (DIMS) (dims-v)]

Taking this example:
logs.openstack.org/92/54092/1/gate/gate-tempest-devstack-vm-neutron-pg-isolated/d7ae6d4/logs/screen-n-cpu.txt.gz

we see the following problem:
2013-10-30 22:01:46.059 DEBUG nova.openstack.common.processutils [req-624df130-b4cd-4e2e-bd9a-cfcbe0b502a8 ServerActionsTestXML-tempest-1320742179-user ServerActionsTestXML-tempest-1320742179-tenant] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbrf4e6ce85-9f qvbf4e6ce85-9f execute /opt/stack/new/nova/nova/openstack/common/processutils.py:147
2013-10-30 22:01:46.122 DEBUG nova.openstack.common.processutils [req-624df130-b4cd-4e2e-bd9a-cfcbe0b502a8 ServerActionsTestXML-tempest-1320742179-user ServerActionsTestXML-tempest-1320742179-tenant] Result was 1 execute /opt/stack/new/nova/nova/openstack/common/processutils.py:172
2013-10-30 22:01:46.123 ERROR nova.virt.libvirt.vif [req-624df130-b4cd-4e2e-bd9a-cfcbe0b502a8 ServerActionsTestXML-tempest-1320742179-user ServerActionsTestXML-tempest-1320742179-tenant] [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] Failed while unplugging vif
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] Traceback (most recent call last):
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] File "/opt/stack/new/nova/nova/virt/libvirt/vif.py", line 636, in unplug_ovs_hybrid
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] utils.execute('brctl', 'delif', br_name, v1_name, run_as_root=True)
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] File "/opt/stack/new/nova/nova/utils.py", line 174, in execute
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] return processutils.execute(*cmd, **kwargs)
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] File "/opt/stack/new/nova/nova/openstack/common/processutils.py", line 178, in execute
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] cmd=' '.join(cmd))
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] ProcessExecutionError: Unexpected error while running command.
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] Command: sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbrf4e6ce85-9f qvbf4e6ce85-9f
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] Exit code: 1
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] Stdout: ''
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f] Stderr: 'interface qvbf4e6ce85-9f does not exist!\n'
2013-10-30 22:01:46.123 2087 TRACE nova.virt.libvirt.vif [instance: d39887ee-f76f-4682-b51a-06dcd3a6ea4f]

If you grep for req-624df130-b4cd-4e2e-bd9a-cfcbe0b502a8 you can see that it...

[Davanum Srinivas (DIMS) (dims-v)]

https://review.openstack.org/#/c/54658/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/54658
Committed: http://github.com/openstack/nova/commit/0a84a7fb24a4605f0da863407512612651890003
Submitter: Jenkins
Branch: master

commit 0a84a7fb24a4605f0da863407512612651890003
Author: Davanum Srinivas <email address hidden>
Date: Wed Oct 30 22:17:55 2013 -0400

    Issue brctl/delif only if the bridge exists

    Add a check for existence of the bridge before we try cleaning
    up as we see a lot of spurious exceptions in the logs especially
    when rebuild_instance is in progress and terminate_instance is
    issued

    Closes-Bug: #1243488

    Change-Id: Ib0e2e4d9506e3a8f63201d28a3fc2c910c77d3bd