Comment 8 for bug 1372049

Revision history for this message
Yair Fried (yfried) wrote :

Well, all I've been able to find, so far, is that it seems like nova-compute is ignoring neutron port-notifications:

taking 2 instances
f41ec90c-6d10-4ee5-be7f-96590ec7c8c1 - ERROR - VirtualInterfaceCreateException: Virtual Interface creation failed
be60b489-07d3-4ec1-a6e7-79b459d631c5 - ACTIVE

server be60b489-07d3-4ec1-a6e7-79b459d631c5 Neutron sends port notifications:
[yfried-mobl-rh ~/workspace/Hosts/scale_debug] # grep -rn be60b489-07d3-4ec1-a6e7-79b459d631c5 | grep notifiers
var/log/neutron/server.log:9482:2014-09-21 11:32:02.358 57216 DEBUG neutron.notifiers.nova [-] Sending events: [{'status': 'completed', 'tag': u'7c3b3872-f711-43a4-a566-669c640c99f4', 'name': 'network-vif-plugged', 'server_uuid': u'0d3be93b-73d3-4995-913c-03a4b80ad37e'}, {'status': 'completed', 'tag': u'a09f7486-aae6-4b0b-b298-9e0f80b46278', 'name': 'network-vif-plugged', 'server_uuid': u'be60b489-07d3-4ec1-a6e7-79b459d631c5'}, {'status': 'completed', 'tag': u'ff2bb3bb-bcbd-4bc8-80b4-5c91841048c0', 'name': 'network-vif-plugged', 'server_uuid': u'547d6f97-31db-4718-afb3-4b6123d71076'}, {'status': 'completed', 'tag': u'549de3d5-2b8f-4822-9912-15730b03234f', 'name': 'network-vif-plugged', 'server_uuid': u'a431c16f-bf1e-424c-88f9-b0ba2a683f99'}, {'status': 'completed', 'tag': u'820d8afc-4d74-4f19-a7a5-8c58cd41e898', 'name': 'network-vif-plugged', 'server_uuid': u'2b7256a8-c04a-42cf-9c19-5836b585c0f5'}] send_events /usr/lib/python2.7/site-packages/neutron/notifiers/nova.py:218
var/log/neutron/server.log:9507:2014-09-21 11:32:03.618 57216 INFO neutron.notifiers.nova [-] Nova event response: {u'status': u'completed', u'tag': u'a09f7486-aae6-4b0b-b298-9e0f80b46278', u'name': u'network-vif-plugged', u'server_uuid': u'be60b489-07d3-4ec1-a6e7-79b459d631c5', u'code': 200}

Nova receives notifications:
[yfried-mobl-rh ~/workspace/Hosts/scale_debug] # grep -rn be60b489-07d3-4ec1-a6e7-79b459d631c5 var/log/nova | grep "event network-vif-plugged"
var/log/nova/nova-api.log:3059:2014-09-21 11:32:03.486 57411 AUDIT nova.api.openstack.compute.contrib.server_external_events [req-50beaf5f-5db9-4fd3-b1fd-26b5a7d39b11 940afd62ccde4376915abee8356a28d9 9426944e683b41d5aa4d7f8e298fd4d8] Creating event network-vif-plugged:a09f7486-aae6-4b0b-b298-9e0f80b46278 for instance be60b489-07d3-4ec1-a6e7-79b459d631c5
var/log/nova/nova-compute.log:8370:2014-09-21 11:31:46.012 57535 DEBUG nova.compute.manager [req-10ffb1e2-6592-492f-b465-00a0658a6251 16480061596d47ea819c7def6d7eef1f 3957117d021244b5badcacb08cdc83e2] [instance: be60b489-07d3-4ec1-a6e7-79b459d631c5] Preparing to wait for external event network-vif-plugged-a09f7486-aae6-4b0b-b298-9e0f80b46278 prepare_for_instance_event /usr/lib/python2.7/site-packages/nova/compute/manager.py:447
var/log/nova/nova-compute.log:14539:2014-09-21 11:36:24.837 57535 DEBUG nova.compute.manager [req-50beaf5f-5db9-4fd3-b1fd-26b5a7d39b11 940afd62ccde4376915abee8356a28d9 9426944e683b41d5aa4d7f8e298fd4d8] [instance: be60b489-07d3-4ec1-a6e7-79b459d631c5] Processing event network-vif-plugged-a09f7486-aae6-4b0b-b298-9e0f80b46278 _process_instance_event /usr/lib/python2.7/site-packages/nova/compute/manager.py:5665

But on server f41ec90c-6d10-4ee5-be7f-96590ec7c8c1:
Neutron sends port notification:
[yfried-mobl-rh ~/workspace/Hosts/scale_debug] # grep -rn f41ec90c-6d10-4ee5-be7f-96590ec7c8c1 | grep notifiers
var/log/neutron/server.log:3785:2014-09-21 11:31:27.143 57216 DEBUG neutron.notifiers.nova [req-059e9a9d-b943-4497-a9e6-6fbeb4d16472 None] Sending events: [{'status': 'completed', 'tag': u'ca09537e-3cb8-4c81-a2ca-db8ac1f9e95b', 'name': 'network-vif-plugged', 'server_uuid': u'f41ec90c-6d10-4ee5-be7f-96590ec7c8c1'}] send_events /usr/lib/python2.7/site-packages/neutron/notifiers/nova.py:218
var/log/neutron/server.log:4873:2014-09-21 11:31:29.468 57216 INFO neutron.notifiers.nova [req-17ea7119-3a5f-4d38-a878-ec0b6b6985a5 None] Nova event response: {u'status': u'completed', u'tag': u'ca09537e-3cb8-4c81-a2ca-db8ac1f9e95b', u'name': u'network-vif-plugged', u'server_uuid': u'f41ec90c-6d10-4ee5-be7f-96590ec7c8c1', u'code': 200}

And nova responds:
[yfried-mobl-rh ~/workspace/Hosts/scale_debug] # grep -rn f41ec90c-6d10-4ee5-be7f-96590ec7c8c1 var/log/nova | grep "event network-vif-plugged"
var/log/nova/nova-api.log:2924:2014-09-21 11:31:29.435 57407 AUDIT nova.api.openstack.compute.contrib.server_external_events [req-bed8b911-3b41-4788-beb7-93738dd15697 940afd62ccde4376915abee8356a28d9 9426944e683b41d5aa4d7f8e298fd4d8] Creating event network-vif-plugged:ca09537e-3cb8-4c81-a2ca-db8ac1f9e95b for instance f41ec90c-6d10-4ee5-be7f-96590ec7c8c1
var/log/nova/nova-compute.log:1715:2014-09-21 11:31:22.024 57535 DEBUG nova.compute.manager [req-10ffb1e2-6592-492f-b465-00a0658a6251 16480061596d47ea819c7def6d7eef1f 3957117d021244b5badcacb08cdc83e2] [instance: f41ec90c-6d10-4ee5-be7f-96590ec7c8c1] Preparing to wait for external event network-vif-plugged-ca09537e-3cb8-4c81-a2ca-db8ac1f9e95b prepare_for_instance_event /usr/lib/python2.7/site-packages/nova/compute/manager.py:447
var/log/nova/nova-compute.log:14428:2014-09-21 11:36:24.692 57535 DEBUG nova.compute.manager [req-bed8b911-3b41-4788-beb7-93738dd15697 940afd62ccde4376915abee8356a28d9 9426944e683b41d5aa4d7f8e298fd4d8] [instance: f41ec90c-6d10-4ee5-be7f-96590ec7c8c1] Processing event network-vif-plugged-ca09537e-3cb8-4c81-a2ca-db8ac1f9e95b _process_instance_event /usr/lib/python2.7/site-packages/nova/compute/manager.py:5665

But still compute agent times out (after 5min set in conf):
[yfried-mobl-rh ~/workspace/Hosts/scale_debug] # grep -rn f41ec90c-6d10-4ee5-be7f-96590ec7c8c1 | grep WARN
var/log/nova/nova-compute.log:14360:2014-09-21 11:36:23.690 57535 WARNING nova.virt.libvirt.driver [req-10ffb1e2-6592-492f-b465-00a0658a6251 16480061596d47ea819c7def6d7eef1f 3957117d021244b5badcacb08cdc83e2] Timeout waiting for vif plugging callback for instance f41ec90c-6d10-4ee5-be7f-96590ec7c8c1