Bug 1431026

Summary:

subnet-delete fails when more than one dhcp ports are available

Product:

Red Hat OpenStack

Reporter:

Mikel Olasagasti <molasaga>

Component:

openstack-neutron

Assignee:

anil venkata <vkommadi>

Status:

CLOSED ERRATA

QA Contact:

GenadiC <gcheresh>

Severity:

high

Docs Contact:

Priority:

high

Version:

8.0 (Liberty)

CC:

amuller, chrisw, fgarciad, ihrachys, ipetrova, kboumedh, molasaga, mschuppe, nyechiel, oblaut, pablo.iranzo, srevivo, vkommadi

Target Milestone:

async

Keywords:

Triaged, ZStream

Target Release:

8.0 (Liberty)

Flags:

mschuppe: needinfo+

Hardware:

x86_64

OS:

Linux

Whiteboard:

Fixed In Version:

openstack-neutron-7.2.0-9.el7ost

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Clones:

1436067 (view as bug list)

Environment:

Last Closed:

2017-06-20 12:57:04 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Bug Depends On:

Bug Blocks:

1381612, 1436067, 1436068, 1436071

Attachments:

Description	Flags
server.log with the traceback	none

Description Mikel Olasagasti 2017-03-10 08:39:11 UTC

Description of problem:

The issue seems to be that having 3 neutron nodes gives 3 DHCP agents in the subnet, with 3 ports. When performing subnet-delete just one port is removed and error is raised. The second time another port is deleted and the third time the last port is deleted and subnet can be removed.

Version-Release number of selected component (if applicable):

 ~/sosreport-Neutron2-20170309173403 > cat sos_commands/rpm/sh_-c_rpm_--nodigest_-qa_--qf_NAME_-_VERSION_-_RELEASE_._ARCH_INSTALLTIME_date_awk_-F_printf_-59s_s_n_1_2_sort_-f | grep -i neutro
openstack-neutron-7.2.0-5.el7ost.noarch                     Sat Mar  4 10:01:01 2017
openstack-neutron-common-7.2.0-5.el7ost.noarch              Sat Mar  4 10:00:59 2017
openstack-neutron-lbaas-7.2.0-1.el7ost.noarch               Sat Mar  4 10:01:35 2017
openstack-neutron-metering-agent-7.2.0-5.el7ost.noarch      Sat Mar  4 10:01:37 2017
openstack-neutron-ml2-7.2.0-5.el7ost.noarch                 Sat Mar  4 10:00:59 2017
openstack-neutron-openvswitch-7.2.0-5.el7ost.noarch         Sat Mar  4 10:01:35 2017
python-neutron-7.2.0-5.el7ost.noarch                        Sat Mar  4 10:00:54 2017
python-neutron-lbaas-7.2.0-1.el7ost.noarch                  Sat Mar  4 10:00:54 2017
python-neutronclient-3.1.0-2.el7ost.noarch                  Sat Mar  4 10:00:46 2017


How reproducible:

Always when more than one port is present


Steps to Reproduce:

[root@cfs3tnc01 ~(keystone_admin)]# neutron subnet-list | grep testrequests
| e5feca39-ad05-40a5-9ea6-7f1e096c66de | subnettestrequests              | 192.168.20.0/24  | {"start": "192.168.20.2", "end": "192.168.20.254"}   |

[root@cfs3tnc01 ~(keystone_admin)]# neutron port-list | grep e5feca39-ad05-40a5-9ea6-7f1e096c66de
| 74a7b23b-ae90-4357-a7fa-7910107c077d |                                      | fa:16:3e:51:e5:c7 | {"subnet_id": "e5feca39-ad05-40a5-9ea6-7f1e096c66de", "ip_address": "192.168.20.3"}   |
| e4ec53b6-e5ab-44c9-bb2b-3e70e21a71c8 |                                      | fa:16:3e:77:d3:ef | {"subnet_id": "e5feca39-ad05-40a5-9ea6-7f1e096c66de", "ip_address": "192.168.20.2"}   |
| f67e336e-0d3b-4cb9-924d-8bb0e4d11798 |                                      | fa:16:3e:9e:2d:5f | {"subnet_id": "e5feca39-ad05-40a5-9ea6-7f1e096c66de", "ip_address": "192.168.20.4"}   |


[root@cfs3tnc01 ~(keystone_admin)]# neutron subnet-delete subnettestrequests
Request Failed: internal server error while processing your request.

[root@cfs3tnc01 ~(keystone_admin)]# neutron port-list | grep e5feca39-ad05-40a5-9ea6-7f1e096c66de
| e4ec53b6-e5ab-44c9-bb2b-3e70e21a71c8 |                                      | fa:16:3e:77:d3:ef | {"subnet_id": "e5feca39-ad05-40a5-9ea6-7f1e096c66de", "ip_address": "192.168.20.2"}   |
| f67e336e-0d3b-4cb9-924d-8bb0e4d11798 |                                      | fa:16:3e:9e:2d:5f | {"subnet_id": "e5feca39-ad05-40a5-9ea6-7f1e096c66de", "ip_address": "192.168.20.4"}   |


[root@cfs3tnc01 ~(keystone_admin)]# neutron subnet-delete subnettestrequests
Request Failed: internal server error while processing your request.

[root@cfs3tnc01 ~(keystone_admin)]# neutron port-list | grep e5feca39-ad05-40a5-9ea6-7f1e096c66de
| f67e336e-0d3b-4cb9-924d-8bb0e4d11798 |                                      | fa:16:3e:9e:2d:5f | {"subnet_id": "e5feca39-ad05-40a5-9ea6-7f1e096c66de", "ip_address": "192.168.20.4"}   |

[root@cfs3tnc01 ~(keystone_admin)]# neutron subnet-list | grep subnettestrequests 
[root@cfs3tnc01 ~(keystone_admin)]#

Comment 3 Karim Boumedhel 2017-03-10 10:01:34 UTC

here a sample traceback of the issue:

2017-03-09 17:17:53.484 3432 DEBUG sqlalchemy.engine.base.Engine [req-bee66905-fe10-40a8-becc-cb8c62c534c2 b898d2d4bbd14552bd05efa6538cbf13 ddf408fec8f94c589369ac69a196508f - - -] Col ('ml2_network_segments_id', 'ml2_network_segments_network_id', 'ml2_network_segments_network_type', 'ml2_network_segments_physical_network', 'ml2_network_segments_segmentation_id', 'ml2_network_segments_is_dynamic', 'ml2_network_segments_segment_index') _init_metadata /usr/lib64/python2.7/site-packages/sqlalchemy/engine/result.py:527
2017-03-09 17:17:53.484 3432 DEBUG sqlalchemy.engine.base.Engine [req-bee66905-fe10-40a8-becc-cb8c62c534c2 b898d2d4bbd14552bd05efa6538cbf13 ddf408fec8f94c589369ac69a196508f - - -] Row ('4fb12cc5-6533-43e2-9cc9-7db6826345c6', 'b61d81d8-e11e-4ac3-8072-d5ba5eae55bc', 'opflex', 'physnet1', None, 0, 0L) process_rows /usr/lib64/python2.7/site-packages/sqlalchemy/engine/result.py:937
2017-03-09 17:17:53.484 3432 INFO sqlalchemy.engine.base.Engine [req-bee66905-fe10-40a8-becc-cb8c62c534c2 b898d2d4bbd14552bd05efa6538cbf13 ddf408fec8f94c589369ac69a196508f - - -] COMMIT
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource [req-bee66905-fe10-40a8-becc-cb8c62c534c2 b898d2d4bbd14552bd05efa6538cbf13 ddf408fec8f94c589369ac69a196508f - - -] delete failed
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource Traceback (most recent call last):
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/api/v2/resource.py", line 83, in resource
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     result = method(request=request, **args)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 532, in delete
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     return self._delete(request, id, **kwargs)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 146, in wrapper
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     ectxt.value = e.inner_exc
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 204, in __exit__
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     six.reraise(self.type_, self.value, self.tb)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 136, in wrapper
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     return f(*args, **kwargs)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 554, in _delete
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     obj_deleter(request.context, id, **kwargs)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 967, in delete_subnet
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     if a.port:
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/attributes.py", line 237, in __get__
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     return self.impl.get(instance_state(instance), dict_)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/attributes.py", line 578, in get
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     value = self.callable_(state, passive)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/strategies.py", line 502, in _load_for_state
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource     (orm_util.state_str(state), self.key)
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource DetachedInstanceError: Parent instance <IPAllocation at 0x5698c50> is not bound to a Session; lazy load operation of attribute 'port' cannot proceed
2017-03-09 17:17:53.493 3432 ERROR neutron.api.v2.resource
2017-03-09 17:17:53.494 3432 INFO neutron.wsgi [req-bee66905-fe10-40a8-becc-cb8c62c534c2 b898d2d4bbd14552bd05efa6538cbf13 ddf408fec8f94c589369ac69a196508f - - -] 15.17.174.51,10.48.4.18,10.48.40.11 - - [09/Mar/2017 17:17:53] "DELETE /v2.0/subnets/e635d618-46f5-43e7-a7bf-4832fb68916e.json HTTP/1.1" 500 359 0.304673

Comment 4 Karim Boumedhel 2017-03-10 10:07:47 UTC

Created attachment 1261879 [details]
server.log with the traceback

Comment 5 anil venkata 2017-03-13 13:18:19 UTC

This code is from OSP8 plugin.py

            with session.begin(subtransactions=True):
                record = self._get_subnet(context, id)
                subnet = self._make_subnet_dict(record, None, context=context)
                qry_allocated = (session.query(models_v2.IPAllocation).
                                 filter_by(subnet_id=id).
                                 join(models_v2.Port))
                is_auto_addr_subnet = ipv6_utils.is_auto_address_subnet(subnet)
                # Remove network owned ports, and delete IP allocations
                # for IPv6 addresses which were automatically generated
                # via SLAAC
                if is_auto_addr_subnet:
                    self._subnet_check_ip_allocations_internal_router_ports(
                            context, id)
                else:
                    qry_allocated = (
                        qry_allocated.filter(models_v2.Port.device_owner.
                        in_(db_base_plugin_v2.AUTO_DELETE_PORT_OWNERS)))
                allocated = set(qry_allocated.all())
                ...
                to_deallocate = allocated - deallocated
                ...
            for a in to_deallocate:
                deallocated.add(a)
                if a.port:


Here a.port is accessed outside of session and we are doing lazy binding, we don't have port in ipallocation object. That is why I think we are getting



2017-03-09 17:23:56.946 3432 INFO sqlalchemy.engine.base.Engine [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] COMMIT
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] delete failed
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource Traceback (most recent call last):
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/api/v2/resource.py", line 83, in resource
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     result = method(request=request, **args)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 532, in delete
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     return self._delete(request, id, **kwargs)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 146, in wrapper
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     ectxt.value = e.inner_exc
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/oslo_utils/excutils.py", line 204, in __exit__
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     six.reraise(self.type_, self.value, self.tb)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/oslo_db/api.py", line 136, in wrapper
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     return f(*args, **kwargs)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 554, in _delete
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     obj_deleter(request.context, id, **kwargs)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py", line 967, in delete_subnet
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     if a.port:
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/attributes.py", line 237, in __get__
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     return self.impl.get(instance_state(instance), dict_)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/attributes.py", line 578, in get
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     value = self.callable_(state, passive)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/strategies.py", line 502, in _load_for_state
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource     (orm_util.state_str(state), self.key)
2017-03-09 17:23:56.953 3432 ERROR neutron.api.v2.resource DetachedInstanceError: Parent instance <IPAllocation at 0x573f7d0> is not bound to a Session; lazy load operation of attribute 'port' cannot proceed


I think we should try without lazy bind and test.

Comment 6 Karim Boumedhel 2017-03-13 13:23:48 UTC

but then wouldnt anyone on liberty using more than one dhcp agent per network hit this issue?

Comment 7 anil venkata 2017-03-13 13:57:55 UTC

Port is not part of the query result, but still code is trying to access port from this query result


2017-03-09 17:23:56.818 3432 INFO sqlalchemy.engine.base.Engine [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] SELECT ipallocations.port_id AS ipallocations_port_id, ipallocations.ip_address AS ipallocations_ip_address, ipallocations.subnet_id AS ipallocations_subnet_id, ipallocations.network_id AS ipallocations_network_id 
FROM ipallocations INNER JOIN ports ON ports.id = ipallocations.port_id 
WHERE ipallocations.subnet_id = %s AND ports.device_owner IN (%s, %s)
2017-03-09 17:23:56.818 3432 INFO sqlalchemy.engine.base.Engine [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] ('eff90788-c270-44ac-a98d-3f22275945d2', 'network:dhcp', 'host-snat-pool-port-device-owner-internal-use')
2017-03-09 17:23:56.819 3432 DEBUG sqlalchemy.engine.base.Engine [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] Col ('ipallocations_port_id', 'ipallocations_ip_address', 'ipallocations_subnet_id', 'ipallocations_network_id') _init_metadata /usr/lib64/python2.7/site-packages/sqlalchemy/engine/result.py:527
2017-03-09 17:23:56.819 3432 DEBUG sqlalchemy.engine.base.Engine [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] Row ('70c7baf4-41c5-4040-a4c6-afd0fc736da9', '192.168.192.3', 'eff90788-c270-44ac-a98d-3f22275945d2', '811e950e-6a14-4ebf-82b0-2062187b8ce1') process_rows /usr/lib64/python2.7/site-packages/sqlalchemy/engine/result.py:937
2017-03-09 17:23:56.819 3432 DEBUG sqlalchemy.engine.base.Engine [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] Row ('7180f023-6dca-4c20-b508-8574c6ce1e2b', '192.168.192.4', 'eff90788-c270-44ac-a98d-3f22275945d2', '811e950e-6a14-4ebf-82b0-2062187b8ce1') process_rows /usr/lib64/python2.7/site-packages/sqlalchemy/engine/result.py:937
2017-03-09 17:23:56.820 3432 DEBUG neutron.plugins.ml2.plugin [req-8a9aabc4-f02a-4533-aa09-e853daf82579 5227a890398042c5b769cd1ed632ec76 e8ba07a25a7d43509b342265c7ac124b - - -] Ports to auto-deallocate: set([<neutron.db.models_v2.IPAllocation[object at 573f690] {port_id=u'7180f023-6dca-4c20-b508-8574c6ce1e2b', ip_address=u'192.168.192.4', subnet_id=u'eff90788-c270-44ac-a98d-3f22275945d2', network_id=u'811e950e-6a14-4ebf-82b0-2062187b8ce1'}>, <neutron.db.models_v2.IPAllocation[object at 573f7d0] {port_id=u'70c7baf4-41c5-4040-a4c6-afd0fc736da9', ip_address=u'192.168.192.3', subnet_id=u'eff90788-c270-44ac-a98d-3f22275945d2', network_id=u'811e950e-6a14-4ebf-82b0-2062187b8ce1'}>]) delete_subnet /usr/lib/python2.7/site-packages/neutron/plugins/ml2/plugin.py:903


I will test further and let you know

Comment 16 anil venkata 2017-03-20 13:02:11 UTC

@Pablo

I pushed a patch in u/s https://review.openstack.org/#/c/445996/ for this bug. Unfortunately some legacy bug is blocking this patch's review. Ihar is also actively reviewing it. We can provide the d/s patch and the build as soon as this u/s patch got merged. 

Thanks
Anil

Comment 17 Pablo Iranzo Gómez 2017-03-24 14:07:57 UTC

(In reply to anil venkata from comment #16)
> @Pablo
> 
> I pushed a patch in u/s https://review.openstack.org/#/c/445996/ for this
> bug. Unfortunately some legacy bug is blocking this patch's review. Ihar is
> also actively reviewing it. We can provide the d/s patch and the build as
> soon as this u/s patch got merged. 
> 
> Thanks
> Anil

Anil, It's already merged in upstream so green light for it :)

Comment 18 anil venkata 2017-03-27 05:17:48 UTC

Thanks Pablo.
I will provide build today.

Thanks
Anil

Comment 20 anil venkata 2017-03-28 11:36:02 UTC

Build openstack-neutron-7.2.0-6.el7ost released with the fix.

Thanks
Anil

Comment 39 GenadiC 2017-06-06 09:25:24 UTC

Verified in openstack-neutron-7.2.0-10.el7ost.noarch
Created a network and subnet on the host with 3 controllers, so 3 ports were created for that network
Removed the subnet without any exception when all 3 ports were removed automatically as expected

Comment 41 errata-xmlrpc 2017-06-20 12:57:04 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:1540