Attribute Error found with router_interface_delete

[Swaminathan Vasudevan]

This may be related to the DB lockwait timeout issue seen in the neutron with DVR.
The error occurs when trying to query the ports in the "delete_csnat_router_interface".

This is from the recent change in the router and port relationship.

2014-10-14 15:54:02.332 ERROR neutron.api.v2.resource [req-5508a216-08e5-4dc4-8ed5-9ebe79b1f7aa admin 065018a159504b6189562b5ff29463d0] remove_router_interface failed
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource Traceback (most recent call last):
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/api/v2/resource.py", line 87, in resource
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource result = method(request=request, **args)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/api/v2/base.py", line 200, in _handle_action
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return getattr(self._plugin, name)(*arg_list, **kwargs)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 260, in remove_router_interface
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource context.elevated(), router, subnet_id=subnet_id)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 590, in delete_csnat_router_interface_ports
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource filters={'id': ports}
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1463, in get_ports
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource page_reverse=page_reverse)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1449, in _get_ports_query
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource query = self._apply_filters_to_query(query, Port, filters)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/common_db_mixin.py", line 132, in _apply_filters_to_query
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource query = query.filter(column.in_(value))
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 404, in in_
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return self.operate(in_op, other)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/attributes.py", line 252, in operate
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return op(self.comparator, *other, **kwargs)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 694, in in_op
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return a.in_(b)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 404, in in_
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return self.operate(in_op, other)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/properties.py", line 212, in operate
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return op(self.__clause_element__(), *other, **kwargs)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 694, in in_op
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return a.in_(b)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 404, in in_
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return self.operate(in_op, other)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/expression.py", line 2311, in operate
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return op(self.comparator, *other, **kwargs)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 694, in in_op
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return a.in_(b)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/operators.py", line 404, in in_
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return self.operate(in_op, other)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/expression.py", line 1994, in operate
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource return o[0](self, self.expr, op, *(other + o[1:]), **kwargs)
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/expression.py", line 2113, in _in_impl
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource for o in seq_or_selectable:
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 584, in <genexpr>
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource rp.port.id for rp in
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource AttributeError: 'NoneType' object has no attribute 'id'
2014-10-14 15:54:02.332 TRACE neutron.api.v2.resource

[Kevin Benton (kevinbenton)]

Swami, I'm interested in helping get to the bottom of these. Can I take this bug or have you already started on it?

[Armando Migliaccio (armando-migliaccio)]

The change you're referring to is:

https://review.openstack.org/#/c/127017/5/neutron/db/l3_dvr_db.py

Is there any chance you identified under which circumstances this recurs?

Logstash doesn't catch anything:

http://logstash.openstack.org/#eyJzZWFyY2giOiIgbWVzc2FnZTpcImluIGRlbGV0ZV9jc25hdF9yb3V0ZXJfaW50ZXJmYWNlX3BvcnRzXCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MTMzMzUxMjA1NTl9

So the might not expose ourselves to this race with Tempest.

[OpenStack Infra (hudson-openstack)]

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

[Kevin Benton (kevinbenton)]

This can happen with his script that deletes interfaces in a very fast manner. Some of the interfaces are removed from the router before the csnat delete method is called but after get_router is called.

[Kevin Benton (kevinbenton)]

Swami, you should play the lottery. The window for this to hit is really narrow. :-)

Between when the generator expression is defined and when get_ports iterates through it.

[Swaminathan Vasudevan (swaminathan-vasudevan)]

@Kevin, with your latest patch for the lockwait timeout, I was still able to see this "Attribute Error".
See the attached log file for more information.

Again this error is seen, when _delete_current_gw_port tries to call delete_csnat_router_interface.

neutron router-interface-delete af919504-e919-4dab-91d4-b4857399bdde 8fdc39a7-85b9-4242-aaa4-5addc5fc40ed
delete inter sub 08cddafc-74e4-4733-a8ae-52701a992c08
neutron router-interface-delete af919504-e919-4dab-91d4-b4857399bdde 08cddafc-74e4-4733-a8ae-52701a992c08
delete inter sub 05eafc0a-cebe-43a1-99e9-8728c6aa5e52
neutron router-interface-delete af919504-e919-4dab-91d4-b4857399bdde 05eafc0a-cebe-43a1-99e9-8728c6aa5e52
neutron router-gateway-clear af919504-e919-4dab-91d4-b4857399bdde
+--------------------------------------+------+-------------------+------------------------------------------------------------------------------------+
| id | name | mac_address | fixed_ips |
+--------------------------------------+------+-------------------+------------------------------------------------------------------------------------+
| 3398637f-dbd8-474c-b83d-72108d330634 | | fa:16:3e:a8:fe:05 | {"subnet_id": "8fdc39a7-85b9-4242-aaa4-5addc5fc40ed", "ip_address": "152.2.0.1"} |
| 3ac80d7b-eb12-4a9a-9d36-8ad47e5049b2 | | fa:16:3e:08:f4:4d | {"subnet_id": "8fdc39a7-85b9-4242-aaa4-5addc5fc40ed", "ip_address": "152.2.0.12"} |
| 4f0bab7b-42f9-44e4-a29c-81c60a6d6f88 | | fa:16:3e:4b:58:af | {"subnet_id": "08cddafc-74e4-4733-a8ae-52701a992c08", "ip_address": "152.1.0.3"} |
| 882acfa8-1cc9-44aa-b3fa-b3b538096149 | | fa:16:3e:6f:4f:eb | {"subnet_id": "08cddafc-74e4-4733-a8ae-52701a992c08", "ip_address": "152.1.0.1"} |
| c8e7c4e3-2836-4ae7-9b6b-15bd9a5d0855 | | fa:16:3e:43:df:1c | {"subnet_id": "05eafc0a-cebe-43a1-99e9-8728c6aa5e52", "ip_address": "151.0.0.3"} |
| d1a9c4b5-7041-4b37-997a-14c9dcc6246c | | fa:16:3e:56:a6:63 | {"subnet_id": "05eafc0a-cebe-43a1-99e9-8728c6aa5e52", "ip_address": "151.0.0.1"} |
| efd59c72-8140-4a29-a856-d45b853b814f | | fa:16:3e:ac:84:bd | {"subnet_id": "bf02b6a2-607d-499e-8e8c-8499269e2578", "ip_address": "153.1.1.100"} |
+--------------------------------------+------+-------------------+------------------------------------------------------------------------------------+
Request Failed: internal server error while processing your request.
Removed interface from router af919504-e919-4dab-91d4-b4857399bdde.
Removed interface from router af919504-e919-4dab-91d4-b4857399bdde.
Removed gateway from router af919504-e919-4dab-91d4-b4857399bdde
neutron router-delete af919504-e919-4dab-91d4-b4857399bdde

On the console I see "Request Failed: internal server error while processing your request."

[Kevin Benton (kevinbenton)]

Swami, are you sure you were running with patch https://review.openstack.org/#/c/128803/2 ?

[Swaminathan Vasudevan (swaminathan-vasudevan)]

Kevin, no I was not running the test with the patch #128803.
I only had the patch #128855.

I will include this, I might have missed this patch.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/128803
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=c858b8438939c7e36d0ceced0c0dd6eadc6f5b66
Submitter: Jenkins
Branch: master

commit c858b8438939c7e36d0ceced0c0dd6eadc6f5b66
Author: Kevin Benton <email address hidden>
Date: Wed Oct 15 18:03:37 2014 -0700

    Guard against concurrent port removal in DVR

    The delete_csnat_router_interface_ports method constructs
    a generator expression to retrieve the ports attached
    to a router. If a concurrent process manages to delete
    one of the ports referenced in the generator from the DB
    after it is constructed (but before iteration), some of the
    ports will be None objects on iteration.

    This patch verifies that the port db object is there
    before trying to extract the ID from it.

    More details:

    This is because the query expression[1] is evaluated immediately
    at the time the generator is defined. If there are ports in the
    DB at the time of this evaluation, RouterPort objects will be
    prepared to be iterated over. However, before the iteration over the
    generator happens, something else may delete the port from the DB.
    If that happens, when the iteration starts and the 'port' attribute
    is accessed on the router port, a SELECT statement will be issued to
    the DB to get that port[2] and it will return None.

    1. router.attached_ports.filter_by(port_type=DEVICE_OWNER_DVR_SNAT)
    2. The RouterPorts table's relationship to the Ports table is using
       the default 'select' lazy loading.

    Closes-Bug: #1381263
    Change-Id: Ia371545d641aaa1cbaa0fd10cd233250ec5769e5