yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1673429] [NEW] nova removes ports not owned by "compute" in deallocate_for_instance

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Vladyslav Drok <vdrok@xxxxxxxxxxxx>
Date: Thu, 16 Mar 2017 11:27:42 -0000
Reply-to: Bug 1673429 <1673429@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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

** Affects: nova
     Importance: Undecided
         Status: New


** Tags: ironic

** Tags added: ironic

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1673429

Title:
  nova removes ports not owned by "compute" in deallocate_for_instance

Status in OpenStack Compute (nova):
  New

Bug description:
  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

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1673429/+subscriptions