Timeout waiting for vif plugging callback for instance

have you set up:
notify_nova_on_port_data_changes = True
notify_nova_on_port_status_changes = True

in neutron.conf?

Marking as incomplete until gongysh's question is answered

It is the default and the configured value.

notify_nova_on_port_data_changes = True
notify_nova_on_port_status_changes = True

http://logs.openstack.org/09/108909/4/gate/check-tempest-dsvm-neutron-full/628138b/logs/etc/neutron/neutron.conf.txt.gz

We are already aware of this race in the neutron full job.
We did not see this bug and reported a different one: bug 1357599

I will dig a bit more into it before declaring it a dupe... it won't be the first time a failure shows multiple root causes.

one possible reason is that applying iptables time took lots of time due to lots of VMs on compute nodes, if so, this patch should can help, see https://review.openstack.org/#/c/115719/
so it looks maybe this is a duplicate issue with https://bugs.launchpad.net/neutron/+bug/1352826

marked as critical because 40 hits in elastic-recheck in 24 hours

Reviewed: https://review.openstack.org/120842
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=9e856922e33b2e7d1c51098454ac85591a90df4f
Submitter: Jenkins
Branch: master

commit 9e856922e33b2e7d1c51098454ac85591a90df4f
Author: Dan Smith <email address hidden>
Date: Thu Sep 11 10:10:58 2014 -0700

    Improve logging of external events on the compute node

    We don't log every event we receive on the compute node, which could
    allow some to slip through and look like they were never received. This
    patch makes sure to debug log each one so we at least know that it made
    it from API to compute.

    Change-Id: I817248ea8167be21c55fecad3a39cb45b027596c
    Related-bug: #1357476

Unless someone is actively working on this, we need to untarget it from rc1.

0 hits in 7 days:

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

We should probably untarget from rc1.

I'm hitting this on my devstack all-in-one node using neutron. I've done some debugging and looks like a timing issue whereupon nova is "missing" the notification regarding the vif plug completion... Here's some notes on the flow.

------

FLOW (durung boot instance):
- nova.compute.manager.ComputeManager._allocate_network() which returns an async wrapper instance of: network_model.NetworkInfoAsyncWrapper

- shortly thereafter neutron finishes plugging the network info and will send AMQP notification.. e.g.:
2014-09-29 08:43:48.130 DEBUG neutron.context [req-881fbe63-8722-4ce0-a068-5c3880db8294 None None] Arguments dropped when creating context
: {u'project_name': None, u'tenant': None} from (pid=5674) __init__ /opt/stack/neutron/neutron/context.py:83
2014-09-29 08:43:48.650 DEBUG neutron.notifiers.nova [-] Sending events: [{'status': 'completed', 'tag': u'7ffbe55f-f1bd-4742-8ed9-9b238c456555', 'name': 'network-vif-plugged', 'server_uuid': u'd9574d53-12b3-4a4c-b308-3dd522dffdee'}] from (pid=5674) send_events /opt/stack/neutron/neutron/notifiers/nova.py:220
2014-09-29 08:43:48.827 DEBUG urllib3.connectionpool [-] "POST /v2/5c2ed97c153f4e02988214fe2a25e753/os-server-external-events HTTP/1.1" 200 183 from (pid=5674) _make_request /usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:415
2014-09-29 08:43:48.828 INFO neutron.notifiers.nova [-] Nova event response: {u'status': u'completed', u'tag': u'7ffbe55f-f1bd-4742-8ed9-9b238c456555', u'name': u'network-vif-plugged', u'server_uuid': u'd9574d53-12b3-4a4c-b308-3dd522dffdee', u'code': 200}

- nova.compute.manager.ComputeManager calls driver.spawn() ... note the neutron vif completed notification is already done at this point.
here's a sample of network_info which is passed into the driver.spawn()... notice its not active:
[VIF({"profile": {}, "ovs_interfaceid": "491f5df8-277d-4163-917f-2eba8b25ff36", "network": Network({"bridge": "br-int", "subnets": [Subnet({"ips": [FixedIP({"meta": {}, "version": 4, "type": "fixed", "floating_ips": [], "address": "10.0.0.2"})], "version": 4, "meta": {"dhcp_server": "10.0.0.3"}, "dns": [], "routes": [], "cidr": "10.0.0.0/24", "gateway": IP({"meta": {}, "version": 4, "type": "gateway", "address": "10.0.0.1"})})], "meta": {"injected": False, "tenant_id": "15045704e84f4fb9be69a4aabc10905d"}, "id": "92aabdcd-4a9d-45ba-96d0-cd6b9c314434", "label": "private"}), "devname": "tap491f5df8-27", "vnic_type": "normal", "qbh_params": None, "meta": {}, "details": {"port_filter": True, "ovs_hybrid_plug": True}, "address": "fa:16:3e:92:e4:f7", "active": False, "type": "ovs", "id": "491f5df8-277d-4163-917f-2eba8b25ff36", "qbg_params": None})]

- spawn() calls _create_domain_and_network()

- _create_domain_and_network() calls _get_neutron_events()

- _get_neutron_events() returns indicating the driver needs to wait for the network-vif-plugged notification. however as mentioned
above this has already been sent so we timeout.
------

I'm looking into a fix even though this one is assigned to Oleg as it's blocking me.... Note in my scenario I'm passing in a preallocated neutron port on the nova boot call.

btw -- I am aware this issue can be worked around via CONF.vif_plugging_is_fatal

here's 1 fix that works, but didn't have time to do more than a simpel verify w/it..

in the libvirt.driver.LibvirtDriver._create_domain_and_network() change the following snip from:

        if (self._conn_supports_start_paused and
            utils.is_neutron() and not
            vifs_already_plugged and power_on and timeout):
            events = self._get_neutron_events(network_info)
        else:
            events = []

to:

        if (self._conn_supports_start_paused and
            utils.is_neutron() and not
            vifs_already_plugged and power_on and timeout
            and not instance.system_metadata['network_allocated']):
            events = self._get_neutron_events(network_info)
        else:
            events = []

This works because the async network allocation callback populates the instance.system_metadata['network_allocated'] value.

Note #12 above is just a "hint" as I have to run for the day... If we used system_metadata as in the approach above it obviously lacks additional synchronization with neutron event waiting and async callback update of the metadata itself.

@boden, can you please describe how are you reproducing the issue on devstack?
I am able to reproduce by launching 50-60 instances at the same time, but this may be another issue however.

Regarding your fix: indeed, async network allocation callback sets the instance.system_metadata['network_allocated'] to True but this happens right after Neutron creates port and sends the result to Nova. VIF plugging is another async operation however. So with your fix Nova just doesn't wait for vif plugging event from neutron which is identical to setting vif_plugging_is_fatal = False.

@Oleg -- I'm using the master stream with a devstack all-in-one configuration (neutron networking); the error occurs with every server boot.

As it turns out, my devstack setup accidentally had nova cells enabled which as a result was using some of the cells_api integration (e.g. ComputeRPCAPIRedirect for the compute rpcapi). Once I disabled cells I'm no longer hitting the error discussed in this bug.

is this really critical in neutron? no hits in logstash last 7 days [1]

I think the underlying fix in nova @ [2] squashed this one. the Latest repro from Boden R turned out to be a false positive.

[1] http://logstash.openstack.org/#eyJzZWFyY2giOiIgbWVzc2FnZTogXCJUaW1lb3V0IHdhaXRpbmcgZm9yIHZpZiBwbHVnZ2luZyBjYWxsYmFjayBmb3IgaW5zdGFuY2VcIiIsImZpZWxkcyI6W10sIm9mZnNldCI6MCwidGltZWZyYW1lIjoiNjA0ODAwIiwiZ3JhcGhtb2RlIjoiY291bnQiLCJ0aW1lIjp7InVzZXJfaW50ZXJ2YWwiOjB9LCJzdGFtcCI6MTQxMzM2ODgwNTg3OSwibW9kZSI6IiIsImFuYWx5emVfZmllbGQiOiIifQ==

[2] https://review.openstack.org/#/c/116354/

This might be fixed, no hits in 10 days.

Since we haven't seen this in 10 days, closing the bug. If this is seen again feel free to re-open.

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'po...

Forgot to mention that this bug prevails in Stable-Juno

Does this happen in master? originally this was filed for logs we saw in CI jobs.

Yes.. this juno off the Master

May I know why the bug state is in Incomplete?

I have provided all the necessary logs which I have captured in invoking two different VMs and two different time instances.

Please provide the analysis of the logs if they have been already triaged.

[Expired for OpenStack Compute (nova) because there has been no activity for 60 days.]