nova removes ports not owned by "compute" in deallocate_for_instance

[Vladyslav Drok]

Hit this on ocata when aborting a deployment through nova (nova boot, then nova delete while instance is still in BUILD), using ironic virt driver. Relevant bits of n-cpu log:

2017-03-16 10:06:16.780 ERROR nova.compute.manager [req-37b74c46-5553-484b-b397-6efbede9d962 admin admin] [instance: 888b7c5a-6f7d-400d-a61f
-f367441e7a91] Build of instance 888b7c5a-6f7d-400d-a61f-f367441e7a91 aborted: Instance 888b7c5a-6f7d-400d-a61f-f367441e7a91 provisioning wa
s aborted
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] Traceback (most recent call last):
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/opt/stack/nova/nova/compute/man
ager.py", line 1780, in _do_build_and_run_instance
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] filter_properties)
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/opt/stack/nova/nova/compute/man
ager.py", line 1961, in _build_and_run_instance
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] phase=fields.NotificationPhase.ERROR
, exception=e)
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/usr/local/lib/python2.7/dist-pa
ckages/oslo_utils/excutils.py", line 220, in __exit__
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] self.force_reraise()
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/usr/local/lib/python2.7/dist-pa
ckages/oslo_utils/excutils.py", line 196, in force_reraise
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] six.reraise(self.type_, self.value,
self.tb)
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/opt/stack/nova/nova/compute/man
ager.py", line 1933, in _build_and_run_instance
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] instance=instance)
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/usr/lib/python2.7/contextlib.py
", line 35, in __exit__
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] self.gen.throw(type, value, tracebac
k)
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] File "/opt/stack/nova/nova/compute/manager.py", line 2152, in _build_resources
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] reason=six.text_type(exc))
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] BuildAbortException: Build of instance 888b7c5a-6f7d-400d-a61f-f367441e7a91 aborted: Instance 888b7c5a-6f7d-400d-a61f-f367441e7a91 provisioning was aborted
2017-03-16 10:06:16.780 TRACE nova.compute.manager [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91]
2017-03-16 10:06:16.781 DEBUG nova.compute.manager [req-37b74c46-5553-484b-b397-6efbede9d962 admin admin] [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] Deallocating network for instance from (pid=25464) _deallocate_network /opt/stack/nova/nova/compute/manager.py:1661
2017-03-16 10:06:16.781 DEBUG nova.network.neutronv2.api [req-37b74c46-5553-484b-b397-6efbede9d962 admin admin] [instance: 888b7c5a-6f7d-400d-a61f-f367441e7a91] deallocate_for_instance() from (pid=25464) deallocate_for_instance /opt/stack/nova/nova/network/neutronv2/api.py:1156
2017-03-16 10:06:16.901 DEBUG neutronclient.v2_0.client [req-37b74c46-5553-484b-b397-6efbede9d962 admin admin] GET call to neutron for http://192.168.122.22:9696/v2.0/ports.json?device_id=888b7c5a-6f7d-400d-a61f-f367441e7a91 used request id req-be903c33-c4da-433a-8e52-9bd5d14ed018 from (pid=25464) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
2017-03-16 10:06:17.587 DEBUG neutronclient.v2_0.client [req-37b74c46-5553-484b-b397-6efbede9d962 admin admin] DELETE call to neutron for http://192.168.122.22:9696/v2.0/ports/1dee64d3-4e81-4ce5-b428-ab90700051dd.json used request id req-a5d90558-2b04-46fa-833e-d65446146a16 from (pid=25464) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128
2017-03-16 10:06:19.055 DEBUG oslo_service.periodic_task [req-f990991a-f1ee-4e3e-a1e6-82a33df8f6d3 None None] Running periodic task ComputeManager._heal_instance_info_cache from (pid=25464) run_periodic_tasks /usr/local/lib/python2.7/dist-packages/oslo_service/periodic_task.py:215
2017-03-16 10:06:19.055 DEBUG nova.compute.manager [req-f990991a-f1ee-4e3e-a1e6-82a33df8f6d3 None None] Starting heal instance info cache from (pid=25464) _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5851
2017-03-16 10:06:19.056 DEBUG nova.compute.manager [req-f990991a-f1ee-4e3e-a1e6-82a33df8f6d3 None None] Rebuilding the list of instances to heal from (pid=25464) _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5855
2017-03-16 10:06:19.057 DEBUG oslo_messaging._drivers.amqpdriver [req-f990991a-f1ee-4e3e-a1e6-82a33df8f6d3 None None] CALL msg_id: 99a597d83cf54335a9d71edbdc6da979 exchange 'nova' topic 'conductor' from (pid=25464) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:442
2017-03-16 10:06:19.070 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: 99a597d83cf54335a9d71edbdc6da979 from (pid=25464) __call__ /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:299
2017-03-16 10:06:19.071 DEBUG nova.compute.manager [req-f990991a-f1ee-4e3e-a1e6-82a33df8f6d3 None None] Didn't find any instances for network info cache update. from (pid=25464) _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5927
2017-03-16 10:06:19.534 DEBUG oslo_messaging._drivers.amqpdriver [-] CALL msg_id: a99d550a6c02409ea18eeab85d8f0e57 exchange 'nova' topic 'conductor' from (pid=25464) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:442
2017-03-16 10:06:19.554 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: a99d550a6c02409ea18eeab85d8f0e57 from (pid=25464) __call__ /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:299
2017-03-16 10:06:22.746 DEBUG neutronclient.v2_0.client [req-37b74c46-5553-484b-b397-6efbede9d962 admin admin] DELETE call to neutron for http://192.168.122.22:9696/v2.0/ports/c643c888-52e2-4df9-b222-eb7e4c90f8df.json used request id req-cfe45eb1-ddec-421a-b675-4031bb941746 from (pid=25464) _append_request_id /usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py:128

The only filter nova applies is device_id filter, and it ignores the device_owner value. This causes the deletion of both 1dee64d3-4e81-4ce5-b428-ab90700051dd, which is a tenant port, and c643c888-52e2-4df9-b222-eb7e4c90f8df, which is provisioning port. A pieces of q-svc.log:

2017-03-16 10:06:17.653 DEBUG neutron.plugins.ml2.plugin [req-cfe45eb1-ddec-421a-b675-4031bb941746 admin admin] Deleting port c643c888-52e2-
4df9-b222-eb7e4c90f8df from (pid=27713) _pre_delete_port /opt/stack/neutron/neutron/plugins/ml2/plugin.py:1576
2017-03-16 10:06:17.654 DEBUG neutron.callbacks.manager [req-cfe45eb1-ddec-421a-b675-4031bb941746 admin admin] Notify callbacks [('neutron.d
b.l3_db._prevent_l3_port_delete_callback-8784608762101', <function _prevent_l3_port_delete_callback at 0x7fd537c18f50>)] for port, before_de
lete from (pid=27713) _notify_loop /opt/stack/neutron/neutron/callbacks/manager.py:142
2017-03-16 10:06:17.771 DEBUG neutron.plugins.ml2.db [req-cfe45eb1-ddec-421a-b675-4031bb941746 admin admin] For port c643c888-52e2-4df9-b222
-eb7e4c90f8df, host 88f150ce-20c1-4ba9-992d-73a6c4118a52, got binding levels [<neutron.plugins.ml2.models.PortBindingLevel[object at 7fd5366
41c90] {port_id=u'c643c888-52e2-4df9-b222-eb7e4c90f8df', host=u'88f150ce-20c1-4ba9-992d-73a6c4118a52', level=0, driver=u'genericswitch', seg
ment_id=u'ef37742a-ad89-4431-960b-9d2d1d7ab3a9'}>] from (pid=27713) get_binding_levels /opt/stack/neutron/neutron/plugins/ml2/db.py:97
2017-03-16 10:06:17.785 DEBUG neutron.plugins.ml2.plugin [req-cfe45eb1-ddec-421a-b675-4031bb941746 admin admin] Calling delete_port for c643
c888-52e2-4df9-b222-eb7e4c90f8df owned by baremetal:none from (pid=27713) delete_port /opt/stack/neutron/neutron/plugins/ml2/plugin.py:1634

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/473873

[Sean Dague (sdague)]

Automatically discovered version ocata in description. If this is incorrect, please update the description to include 'nova version: ...'

[Mark Goddard (mgoddard)]

This fix should not be merged until ironic bug https://bugs.launchpad.net/ironic/+bug/1732412 has been resolved. Turns out ironic is not very diligent in cleaning up provisioning ports, and until now this has been masked by nova cleaning up after it.

[Mark Goddard (mgoddard)]

The above fix in ironic was released in ironic 10.0.0. The fix for this issue in nova can now be unblocked.