yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1357476] Re: Timeout waiting for vif plugging callback for instance

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: jishnub <jbanerje@xxxxxxxxx>
Date: Tue, 09 Jun 2015 15:51:19 -0000
Reply-to: Bug 1357476 <1357476@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
I have hit this bug repeatedly on creating new instance on a compute-node on which already 4 instances exist.
Resource-wiseless than 10% of the hypervisor has been used by the existing instances.
Any new instance creation is failing at the same place as per the log trace.  I have attached the log for my instance named 'AGAIN'

Below is the log snippet:
=======================

2015-06-09 08:03:47.153 19692 WARNING nova.virt.libvirt.driver [-] Timeout waiting for vif plugging callback for instance b8c3a1dc-8780-4495-8a7e-3f03f14c8475
2015-06-09 08:03:47.363 19692 DEBUG nova.virt.libvirt.vif [-] 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=2015-06-09T14:58:40Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='AGAIN',display_name='AGAIN',ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,host='f3-compute-2.noiro.lab',hostname='again',id=77,image_ref='82cd7cee-ade0-43b2-94ac-b7cb8c0c941b',info_cache=InstanceInfoCache,instance_type_id=1,kernel_id='',key_data=None,key_name=None,launch_index=0,launched_at=None,launched_on='f3-compute-2.noiro.lab',locked=False,locked_by=None,memory_mb=4096,metadata={},node='f3-compute-2.noiro.lab',numa_topology=None,os_type=None,pci_devices=PciDeviceList,power_state=0,progress=0,project_id='26acdadf476e49e78172ef6f0595f9a1',ramdisk_id='',reservation_id='r-51nqu02g',root_device_name='/dev/vda',root_gb=40,scheduled_at=None,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={image_base_image_ref='82cd7cee-ade0-43b2-94ac-b7cb8c0c941b',image_container_format='bare',image_disk_format='qcow2',image_min_disk='40',image_min_ram='0',instance_type_ephemeral_gb='0',instance_type_flavorid='3',instance_type_id='1',instance_type_memory_mb='4096',instance_type_name='m1.medium',instance_type_root_gb='40',instance_type_rxtx_factor='1.0',instance_type_swap='0',instance_type_vcpu_weight=None,instance_type_vcpus='2',network_allocated='True'},task_state='spawning',terminated_at=None,updated_at=2015-06-09T14:58:44Z,user_data=None,user_id='3fd8184442334332be33cdfe5b57b1ae',uuid=b8c3a1dc-8780-4495-8a7e-3f03f14c8475,vcpus=2,vm_mode=None,vm_state='building') vif=VIF({'profile': {}, 'ovs_interfaceid': u'8d51f6bd-6a8b-43a0-9d86-b8384225eab5', 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'5.5.5.7'})], 'version': 4, 'meta': {'dhcp_server': u'5.5.5.3'}, 'dns': [], 'routes': [Route({'interface': None, 'cidr': u'5.5.5.0/24', 'meta': {}, 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'5.5.5.1'})})], 'cidr': u'5.5.5.0/28', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'5.5.5.1'})})], 'meta': {'injected': False, 'tenant_id': u'26acdadf476e49e78172ef6f0595f9a1'}, 'id': u'4659e62b-f4fd-43ac-b18a-5ef30fac028e', 'label': u'l2p_demo_same_ptg_l2p_l3p_bd'}), 'devname': u'tap8d51f6bd-6a', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': False, u'ovs_hybrid_plug': False}, 'address': u'fa:16:3e:61:6a:e8', 'active': False, 'type': u'ovs', 'id': u'8d51f6bd-6a8b-43a0-9d86-b8384225eab5', 'qbg_params': None}) unplug /usr/lib/python2.7/site-packages/nova/virt/libvirt/vif.py:688
2015-06-09 08:03:47.366 19692 DEBUG nova.virt.driver [-] Emitting event <LifecycleEvent: 1433862227.36, b8c3a1dc-8780-4495-8a7e-3f03f14c8475 => Stopped> emit_event /usr/lib/python2.7/site-packages/nova/virt/driver.py:1299
2015-06-09 08:03:47.366 19692 INFO nova.compute.manager [-] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] VM Stopped (Lifecycle Event)
2015-06-09 08:03:47.401 19692 DEBUG nova.compute.manager [-] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] Synchronizing instance power state after lifecycle event "Stopped"; current vm_state: building, current task_state: spawning, current DB power_state: 0, VM power_state: 4 handle_lifecycle_event /usr/lib/python2.7/site-packages/nova/compute/manager.py:1150
2015-06-09 08:03:47.405 19692 DEBUG nova.objects.instance [-] Lazy-loading `system_metadata' on Instance uuid b8c3a1dc-8780-4495-8a7e-3f03f14c8475 obj_load_attr /usr/lib/python2.7/site-packages/nova/objects/instance.py:579
2015-06-09 08:03:47.438 19692 INFO nova.compute.manager [-] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] During sync_power_state the instance has a pending task (spawning). Skip.
2015-06-09 08:03:47.444 19692 DEBUG nova.openstack.common.processutils [-] Running cmd (subprocess): mv /var/lib/nova/instances/b8c3a1dc-8780-4495-8a7e-3f03f14c8475 /var/lib/nova/instances/b8c3a1dc-8780-4495-8a7e-3f03f14c8475_del execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:161
2015-06-09 08:03:47.453 19692 DEBUG nova.openstack.common.processutils [-] Result was 0 execute /usr/lib/python2.7/site-packages/nova/openstack/common/processutils.py:195
2015-06-09 08:03:47.454 19692 INFO nova.virt.libvirt.driver [-] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] Deleting instance files /var/lib/nova/instances/b8c3a1dc-8780-4495-8a7e-3f03f14c8475_del
2015-06-09 08:03:47.454 19692 INFO nova.virt.libvirt.driver [-] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] Deletion of /var/lib/nova/instances/b8c3a1dc-8780-4495-8a7e-3f03f14c8475_del complete
2015-06-09 08:03:47.495 19692 ERROR nova.compute.manager [-] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] Instance failed to spawn
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] Traceback (most recent call last):
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2288, in _build_resources
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]     yield resources
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]   File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2158, in _build_and_run_instance
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]     block_device_info=block_device_info)
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 2635, in spawn
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]     block_device_info, disk_info=disk_info)
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]   File "/usr/lib/python2.7/site-packages/nova/virt/libvirt/driver.py", line 4579, in _create_domain_and_network
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]     raise exception.VirtualInterfaceCreateException()
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] VirtualInterfaceCreateException: Virtual Interface creation failed
2015-06-09 08:03:47.495 19692 TRACE nova.compute.manager [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475]
2015-06-09 08:03:47.496 19692 AUDIT nova.compute.manager [req-db08580d-efec-4377-baa5-e98e5868c055 None] [instance: b8c3a1dc-8780-4495-8a7e-3f03f14c8475] Terminating instance


** Changed in: nova
       Status: Invalid => New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1357476

Title:
  Timeout waiting for vif plugging callback for instance

Status in OpenStack Neutron (virtual network service):
  Invalid
Status in OpenStack Compute (Nova):
  New
Status in OpenStack Compute (nova) icehouse series:
  Invalid

Bug description:
  n-cpu times out while waiting for neutron.

  
  Logstash
  ========
  http://logstash.openstack.org/#eyJzZWFyY2giOiIgbWVzc2FnZTogXCJUaW1lb3V0IHdhaXRpbmcgZm9yIHZpZiBwbHVnZ2luZyBjYWxsYmFjayBmb3IgaW5zdGFuY2VcIiBBTkQgdGFnczpcInNjcmVlbi1uLWNwdS50eHRcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQwODEyMjI1NjY2NiwibW9kZSI6IiIsImFuYWx5emVfZmllbGQiOiIifQ==

  message: "Timeout waiting for vif plugging callback for instance" AND
  tags:"screen-n-cpu.txt"

  
  Logs
  ++++
  http://logs.openstack.org/09/108909/4/gate/check-tempest-dsvm-neutron-full/628138b/logs/screen-n-cpu.txt.gz#_2014-08-13_21_14_53_453

  2014-08-13 21:14:53.453 WARNING nova.virt.libvirt.driver [req-
  0974eac5-f261-472e-a2c3-f96514e4131c ServerActionsTestXML-650848250
  ServerActionsTestXML-1011304525] Timeout waiting for vif plugging
  callback for instance 794ceb8c-a08b-4b02-bdcb-4ad5632f7744

  2014-08-13 21:14:55.408 ERROR nova.compute.manager [req-0974eac5-f261-472e-a2c3-f96514e4131c ServerActionsTestXML-650848250 ServerActionsTestXML-1011304525] [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744] Setting instance vm_state to ERROR
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744] Traceback (most recent call last):
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]   File "/opt/stack/new/nova/nova/compute/manager.py", line 3714, in finish_resize
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]     disk_info, image)
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]   File "/opt/stack/new/nova/nova/compute/manager.py", line 3682, in _finish_resize
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]     old_instance_type, sys_meta)
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]   File "/opt/stack/new/nova/nova/compute/manager.py", line 3677, in _finish_resize
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]     block_device_info, power_on)
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]   File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 5302, in finish_migration
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]     block_device_info, power_on)
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]   File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3792, in _create_domain_and_network
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744]     raise exception.VirtualInterfaceCreateException()
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744] VirtualInterfaceCreateException: Virtual Interface creation failed
  2014-08-13 21:14:55.408 29002 TRACE nova.compute.manager [instance: 794ceb8c-a08b-4b02-bdcb-4ad5632f7744] 

  2014-08-13 21:14:56.138 ERROR oslo.messaging.rpc.dispatcher [req-0974eac5-f261-472e-a2c3-f96514e4131c ServerActionsTestXML-650848250 ServerActionsTestXML-1011304525] Exception during message handling: Virtual Interface creation failed
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 134, in _dispatch_and_reply
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     incoming.message))
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 177, in _dispatch
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     return self._do_dispatch(endpoint, method, ctxt, args)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/usr/local/lib/python2.7/dist-packages/oslo/messaging/rpc/dispatcher.py", line 123, in _do_dispatch
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     result = getattr(endpoint, method)(ctxt, **new_args)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/exception.py", line 88, in wrapped
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     payload)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/exception.py", line 71, in wrapped
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     return f(self, context, *args, **kw)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 292, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     pass
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 278, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 342, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 266, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     migration.instance_uuid, exc_info=True)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 253, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 320, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     kwargs['instance'], e, sys.exc_info())
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 308, in decorated_function
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     return function(self, context, *args, **kwargs)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 3726, in finish_resize
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     self._set_instance_error_state(context, instance)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 3714, in finish_resize
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     disk_info, image)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 3682, in _finish_resize
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     old_instance_type, sys_meta)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/openstack/common/excutils.py", line 82, in __exit__
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     six.reraise(self.type_, self.value, self.tb)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/compute/manager.py", line 3677, in _finish_resize
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 5302, in finish_migration
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     block_device_info, power_on)
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher   File "/opt/stack/new/nova/nova/virt/libvirt/driver.py", line 3792, in _create_domain_and_network
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher     raise exception.VirtualInterfaceCreateException()
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher VirtualInterfaceCreateException: Virtual Interface creation failed
  2014-08-13 21:14:56.138 29002 TRACE oslo.messaging.rpc.dispatcher

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1357476/+subscriptions
References

[Bug 1357476] [NEW] Timeout waiting for vif plugging callback for instance
From: Attila Fazekas, 2014-08-15