Seen here:
http://logs.openstack.org/46/623246/3/check/nova-multiattach/efa830b/logs/screen-n-cpu.txt.gz?#_Dec_12_00_01_13_179474
Dec 12 00:01:13.179474 ubuntu-xenial-inap-mtl01-0001136812 nova-compute[29399]: WARNING nova.virt.libvirt.driver [None req-f43f3c35-dc0b-4aa4-bfd0-4046045b315e tempest-TaggedBootDevicesTest-250467933 tempest-TaggedBootDevicesTest-250467933] [instance: 18e5987e-a535-4044-84aa-dd8f023cedcc] Timeout waiting for [('network-vif-plugged', u'472ab433-bc18-41b5-85ae-009611117b70'), ('network-vif-plugged', u'6b476c8d-35b5-4380-a4c0-9e691f568ff5'), ('network-vif-plugged', u'8c3289ef-07aa-4048-8df1-979c2d8af07b'), ('network-vif-plugged', u'5a8d8e13-3dba-4b64-a17d-67724ef420ce'), ('network-vif-plugged', u'727b1a5d-e704-4185-9765-97c8ffb4f559'), ('network-vif-plugged', u'45563a2d-cd6c-4fe3-b5a9-74699bea3737'), ('network-vif-plugged', u'bc284b29-921e-495c-ad53-6f5fe9df6cd8')] for instance with vm_state building and task_state spawning.: Timeout: 300 seconds
I've seen this in a couple of failures and each time the only port of the 7 that we don't get the network-vif-plugged event for is the first one, in this case 472ab433-bc18-41b5-85ae-009611117b70.
The 472ab433-bc18-41b5-85ae-009611117b70 vif is plugged in nova-compute here:
Dec 11 23:56:11.855811 ubuntu-xenial-inap-mtl01-0001136812 nova-compute[29399]: INFO os_vif [None req-f43f3c35-dc0b-4aa4-bfd0-4046045b315e tempest-TaggedBootDevicesTest-250467933 tempest-TaggedBootDevicesTest-250467933] Successfully plugged vif VIFOpenVSwitch(active=False,address=fa:16:3e:fb:dd:9f,bridge_name='br-int',has_traffic_filtering=True,id=472ab433-bc18-41b5-85ae-009611117b70,network=Network(4988ef3d-6a8f-477f-b0a2-298c33019494),plugin='ovs',port_profile=VIFPortProfileOpenVSwitch,preserve_on_delete=False,vif_name='tap472ab433-bc')
Interestingly, right before that in the neutron server logs I see a network-changed event for that port:
Dec 11 23:55:46.981194 ubuntu-xenial-inap-mtl01-0001136812 neutron-server[20899]: DEBUG neutron.notifiers.nova [-] Sending events: [{'tag': u'472ab433-bc18-41b5-85ae-009611117b70', 'name': 'network-changed', 'server_uuid': u'18e5987e-a535-4044-84aa-dd8f023cedcc'}] {{(pid=21001) send_events /opt/stack/new/neutron/neutron/notifiers/nova.py:245}}
It looks like that is due to the port binding, from the neutron agent logs:
Dec 11 23:55:46.383255 ubuntu-xenial-inap-mtl01-0001136812 neutron-openvswitch-agent[21879]: DEBUG neutron.agent.resource_cache [None req-8081683c-7287-4e57-936f-3376788aec97 service neutron] Resource Port 472ab433-bc18-41b5-85ae-009611117b70 updated (revision_number 1->2). Old fields: {'device_owner': u'', 'bindings': [PortBinding(host='',port_id=472ab433-bc18-41b5-85ae-009611117b70,profile={},status='ACTIVE',vif_details=None,vif_type='unbound',vnic_type='normal')]} New fields: {'device_owner': u'compute:nova', 'bindings': [PortBinding(host='ubuntu-xenial-inap-mtl01-0001136812',port_id=472ab433-bc18-41b5-85ae-009611117b70,profile={},status='ACTIVE',vif_details=None,vif_type='unbound',vnic_type='normal')]} {{(pid=21879) record_resource_update /opt/stack/new/neutron/neutron/agent/resource_cache.py:186}}
Then in the neutron agent I see this:
Dec 11 23:56:12.724830 ubuntu-xenial-inap-mtl01-0001136812 neutron-openvswitch-agent[21879]: DEBUG neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-cc26f856-2521-411e-ae10-34ad96b7c665 None None] Processing port: 472ab433-bc18-41b5-85ae-009611117b70 {{(pid=21879) treat_devices_added_or_updated /opt/stack/new/neutron/neutron/plugins/ml2/drivers/openvswitch/agent/ovs_neutron_agent.py:1605}}
Dec 11 23:56:12.725010 ubuntu-xenial-inap-mtl01-0001136812 neutron-openvswitch-agent[21879]: INFO neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-cc26f856-2521-411e-ae10-34ad96b7c665 None None] Port 472ab433-bc18-41b5-85ae-009611117b70 was not found on the integration bridge and will therefore not be processed
Is that a problem which might cause the network-vif-plugged event to not be sent?
And then I see this:
Dec 11 23:56:14.095895 ubuntu-xenial-inap-mtl01-0001136812 neutron-openvswitch-agent[21879]: INFO neutron.plugins.ml2.drivers.openvswitch.agent.ovs_neutron_agent [None req-cc26f856-2521-411e-ae10-34ad96b7c665 None None] Ports set([u'472ab433-bc18-41b5-85ae-009611117b70', u'bc284b29-921e-495c-ad53-6f5fe9df6cd8', u'45563a2d-cd6c-4fe3-b5a9-74699bea3737', u'6b476c8d-35b5-4380-a4c0-9e691f568ff5', u'8c3289ef-07aa-4048-8df1-979c2d8af07b', u'5a8d8e13-3dba-4b64-a17d-67724ef420ce', u'727b1a5d-e704-4185-9765-97c8ffb4f559']) skipped, changing status to down
http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22tempest-TaggedBootDevicesTest%5C%22%20AND%20message%3A%5C%22Timeout%20waiting%20for%20%5B('network-vif-plugged'%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22&from=7d
4 hits in 7 days, check and gate, all failures.
so just loking at the logs around when processing of the port was skipped in the neutron agent we see
that the vms tap interface tap472ab433-bc corresponding to port 472ab433- bc18-41b5- 85ae-009611117b 70 logs.openstack. org/46/ 623246/ 3/check/ nova-multiattac h/efa830b/ logs/screen- q-agt.txt. gz#_Dec_ 11_23_56_ 12_715432
is present in the db list at http://
Dec 11 23:56:12.715432 ubuntu- xenial- inap-mtl01- 0001136812 neutron- openvswitch- agent[21879] : DEBUG ovsdbapp. backend. ovs_idl. transaction [-] Running txn n=1 command(idx=0): DbListCommand( if_exists= True, records= [u'tap6b476c8d- 35', u'tap459d08b5-8c', u'tapc4cbed6d-26', u'int-br-ex', u'tap9596db0a-58', u'tapd2e38552-81', u'qr-6ffb4153-0f', u'qg-89b08004-24', u'tap467f555d-fd', u'tap45563a2d-cd', u'qg-88ca1551-8f', u'tap5a8d8e13-3d', u'qr-35a687f0-fb', u'qg-c992632f-da', u'tapf2f4235b-c3', u'tap727b1a5d-e7', u'qg-a51133f8-41', u'tapd883b80b-39', u'tap8c3289ef-07', u'qr-c64db2ce-aa', u'tapb734a414-18', u'tapbc284b29-92', u'qr-3a500395-7f', u'patch-tun', u'tap472ab433-bc'], table=Interface, columns=['name', 'external_ids', 'ofport'], row=False) {{(pid=21879) do_commit /usr/local/ lib/python2. 7/dist- packages/ ovsdbapp/ backend/ ovs_idl/ transaction. py:84}}
then there is a warningn
ubuntu- xenial- inap-mtl01- 0001136812 neutron- openvswitch- agent[21879] : WARNING neutron. agent.common. ovs_lib [None req-cc26f856- 2521-411e- ae10-34ad96b7c6 65 None None] ofport: [] for VIF: 472ab433- bc18-41b5- 85ae-009611117b 70 is not a positive integer: OVSFWTagNotFound: Cannot get tag for port tap5b6aa631-3b from its other_config: {}
and then the message saying the port was not found
Dec 11 23:56:12.725010 ubuntu- xenial- inap-mtl01- 0001136812 neutron- openvswitch- agent[21879] : INFO neutron. plugins. ml2.drivers. openvswitch. agent.ovs_ neutron_ agent [None req-cc26f856- 2521-411e- ae10-34ad96b7c6 65 None None] Port 472ab433- bc18-41b5- 85ae-009611117b 70 was not found on the integration bridge and will therefore not be processed
now the stagege thing about the warining is that the tap listed is wrong.
the warning states "OVSFWTagNotFound: Cannot get tag for port tap5b6aa631-3b from its other_config: {}" however the tap should be tap472ab433-bc