remove_interface_router failing to delete port

[sajuptpm]

In multi-node contrail setup (3api, 3schema-trasformer, 3node cassandra, rabbitmq and zookeeper cluster), sometime "remove_router_interface" operation not cleaning the attribute "logical_router_back_refs" of VirtualMachineInterface object (port). Becacuse of that it failing to delete port.

contrail error log:
======
<pre>Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/vnc_openstack/neutron_plugin_interface.py", line 875, in plugin_del_router_interface
    subnet_id=subnet_id)
  File "/usr/lib/python2.7/dist-packages/vnc_openstack/neutron_plugin_db.py", line 3457, in remove_router_interface
    self.port_delete(port_id)
  File "/usr/lib/python2.7/dist-packages/vnc_openstack/neutron_plugin_db.py", line 3741, in port_delete <=======
    device_owner=constants.DEVICE_OWNER_ROUTER_INTF)
  File "/usr/lib/python2.7/dist-packages/vnc_openstack/neutron_plugin_db.py", line 254, in _raise_contrail_exception
    bottle.abort(400, json.dumps(exc_info))
  File "/usr/lib/python2.7/dist-packages/bottle.py", line 2310, in abort
    raise HTTPError(code, text)
HTTPError
</pre>
192.168.100.88 - - [2016-06-14 14:49:30] "POST /neutron/router HTTP/1.1" 400 249 0.780767

code
======
neutron_plug_in_db.py
def remove_router_interface(self, router_id, port_id=None, subnet_id=None):
    port_obj = self._virtual_machine_interface_read(port_id)
    router_obj.del_virtual_machine_interface(port_obj)
    self._vnc_lib.logical_router_update(router_obj)<===
    self.port_delete(port_id) <====

    def port_delete(self, port_id):
        if port_obj.get_logical_router_back_refs():
            self._raise_contrail_exception('L3PortInUse', port_id=port_id,
                device_owner=constants.DEVICE_OWNER_ROUTER_INTF)<====

[OpenContrail Admin (ci-admin-f)]

Review in progress for https://review.opencontrail.org/21223
Submitter: sajuptpm (<email address hidden>)

[sajuptpm (sajuptpm)]

I also tried to print port_obj.get_logical_router_back_refs() before and after the following two statements.

router_obj.del_virtual_machine_interface(port_obj)
self._vnc_lib.logical_router_update(router_obj)

Sometimes it print "None" after logical_router_update and sometimes like

[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-a69a87ac-03ab-4e97-b643-5f85298982c8'], u'href': u'http://127.0.0.1:9100/logical-router/a69a87ac-03ab-4e97-b643-5f85298982c8', u'attr': None, u'uuid': u'a69a87ac-03ab-4e97-b643-5f85298982c8'}]

[Sachin Bansal (sbansal)]

From the name of the router in the refs you printed, it looks like you created more than one logical router with the name 'default-logical-router' and might have linked both of them to this port. Could you print logical_router_back_refs before and after the deletion?

[sajuptpm (sajuptpm)]

Yes, In "def remove_router_interface", I have printed it before and after the statement "self._vnc_lib.logical_router_update(router_obj)"

I also printed it in "def port_delete(self, port_id)" method.

===remove_router_interface before=====port_id:5fe99d67-fc30-4803-a4e7-7bf65238a22b, logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-a69a87ac-03ab-4e97-b643-5f85298982c8'], u'href': u'http://127.0.0.1:9100/logical-router/a69a87ac-03ab-4e97-b643-5f85298982c8', u'attr': None, u'uuid': u'a69a87ac-03ab-4e97-b643-5f85298982c8'}]

===remove_router_interface after=====port_id:5fe99d67-fc30-4803-a4e7-7bf65238a22b, logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-a69a87ac-03ab-4e97-b643-5f85298982c8'], u'href': u'http://127.0.0.1:9100/logical-router/a69a87ac-03ab-4e97-b643-5f85298982c8', u'attr': None, u'uuid': u'a69a87ac-03ab-4e97-b643-5f85298982c8'}]

===in port_delete function=====port_id:5fe99d67-fc30-4803-a4e7-7bf65238a22b, logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-a69a87ac-03ab-4e97-b643-5f85298982c8'], u'href': u'http://127.0.0.1:9100/logical-router/a69a87ac-03ab-4e97-b643-5f85298982c8', u'attr': None, u'uuid': u'a69a87ac-03ab-4e97-b643-5f85298982c8'}]

[sajuptpm (sajuptpm)]

Sometime it print like this, I think this is the behavior we are expecting. right ?

===remove_router_interface before=====port_id:e71ddadf-27bd-4f88-ba33-6b2f1027e676, logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000012276693110', u'default-logical-router-bff5d7e9-d0e0-4d21-b916-3625e7e17104'], u'href': u'http://127.0.0.1:9100/logical-router/bff5d7e9-d0e0-4d21-b916-3625e7e17104', u'attr': None, u'uuid': u'bff5d7e9-d0e0-4d21-b916-3625e7e17104'}]

===remove_router_interface after=====port_id:e71ddadf-27bd-4f88-ba33-6b2f1027e676, logical_router_back_refs:None

===in port_delete function=====port_id:e71ddadf-27bd-4f88-ba33-6b2f1027e676, logical_router_back_refs:None

[Sachin Bansal (sbansal)]

Couple of more questions:
1. Are you providing subnet-id or port-id to router-interface-add command?
2. Is the router id same as what you see above in the logs?

[sajuptpm (sajuptpm)]

1) I am passing subnet-id
2) Log which i posted in the "Bug Description" is old. Today, I have reproduced that issue to print logical_router_back_refs of port.

[sajuptpm (sajuptpm)]

command which we running in stress test looks like

for router-id, subnet-id in xxxxx:
  neutron.remove_interface_router(router-id, subnet-id)

[Sachin Bansal (sbansal)]

Let me rephrase the question. Is the router id you pass to remove_interface_router, same as what you see in the logs in non-working case?

[sajuptpm (sajuptpm)]

yes, router id is same

[sajuptpm (sajuptpm)]

Now, I have printed router_id, router.get_virtual_machine_interface_refs, port_id and port.logical_router_back_refs before and after vnc_lib.logical_router_update statement.

This is non-working case

Example-1
##########
===before vnc_lib.logical_router_update=====router_id:bc61747a-4364-4606-a43c-11d643368b1f,
router.get_virtual_machine_interface_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'd476a060-0330-447e-aca3-eab7f1985ab7'], u'href': u'http://127.0.0.1:9100/virtual-machine-interface/d476a060-0330-447e-aca3-eab7f1985ab7', u'attr': None, u'uuid': u'd476a060-0330-447e-aca3-eab7f1985ab7'}],
port_id:d476a060-0330-447e-aca3-eab7f1985ab7,
port.logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-bc61747a-4364-4606-a43c-11d643368b1f'], u'href': u'http://127.0.0.1:9100/logical-router/bc61747a-4364-4606-a43c-11d643368b1f', u'attr': None, u'uuid': u'bc61747a-4364-4606-a43c-11d643368b1f'}]

===after vnc_lib.logical_router_update=====router_id:bc61747a-4364-4606-a43c-11d643368b1f,
router.get_virtual_machine_interface_refs:[],
port_id:d476a060-0330-447e-aca3-eab7f1985ab7,
port.logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-bc61747a-4364-4606-a43c-11d643368b1f'], u'href': u'http://127.0.0.1:9100/logical-router/bc61747a-4364-4606-a43c-11d643368b1f', u'attr': None, u'uuid': u'bc61747a-4364-4606-a43c-11d643368b1f'}]

===port_delete=====port_id:d476a060-0330-447e-aca3-eab7f1985ab7,
logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000478770600909-84cd8306-9959-4c7f-8e0b-084135aacf97', u'default-logical-router-bc61747a-4364-4606-a43c-11d643368b1f'], u'href': u'http://127.0.0.1:9100/logical-router/bc61747a-4364-4606-a43c-11d643368b1f', u'attr': None, u'uuid': u'bc61747a-4364-4606-a43c-11d643368b1f'}]

Example-2
##########
===before vnc_lib.logical_router_update=====router_id:7a4cfa6a-ede3-4ab3-972d-9eb06da04eb8,
router.get_virtual_machine_interface_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000012276693110', u'71ca40f0-546a-4dd1-86f2-33f22946f7dd'], u'href': u'http://127.0.0.1:9100/virtual-machine-interface/71ca40f0-546a-4dd1-86f2-33f22946f7dd', u'attr': None, u'uuid': u'71ca40f0-546a-4dd1-86f2-33f22946f7dd'}],
port_id:71ca40f0-546a-4dd1-86f2-33f22946f7dd,
port.logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000012276693110', u'default-logical-router'], u'href': u'http://127.0.0.1:9100/logical-router/7a4cfa6a-ede3-4ab3-972d-9eb06da04eb8', u'attr': None, u'uuid': u'7a4cfa6a-ede3-4ab3-972d-9eb06da04eb8'}]

===after vnc_lib.logical_router_update=====router_id:7a4cfa6a-ede3-4ab3-972d-9eb06da04eb8,
router.get_virtual_machine_interface_refs:[],
port_id:71ca40f0-546a-4dd1-86f2-33f22946f7dd,
port.logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000012276693110', u'default-logical-router'], u'href': u'http://127.0.0.1:9100/logical-router/7a4c...

[sajuptpm (sajuptpm)]

Example of working case.

===before vnc_lib.logical_router_update=====router_id:49b21a15-7bb5-46f0-a76a-84082e86f0f4,
router.get_virtual_machine_interface_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000012276693110', u'72b9d37e-0526-45e1-8757-9f12bc402d13'], u'href': u'http://127.0.0.1:9100/virtual-machine-interface/72b9d37e-0526-45e1-8757-9f12bc402d13', u'attr': None, u'uuid': u'72b9d37e-0526-45e1-8757-9f12bc402d13'}],
port_id:72b9d37e-0526-45e1-8757-9f12bc402d13,
port.logical_router_back_refs:[{u'to': [u'default-domain', u'Customer-00000000000000000000012276693110', u'default-logical-router-49b21a15-7bb5-46f0-a76a-84082e86f0f4'], u'href': u'http://127.0.0.1:9100/logical-router/49b21a15-7bb5-46f0-a76a-84082e86f0f4', u'attr': None, u'uuid': u'49b21a15-7bb5-46f0-a76a-84082e86f0f4'}]

===after vnc_lib.logical_router_update=====router_id:49b21a15-7bb5-46f0-a76a-84082e86f0f4,
router.get_virtual_machine_interface_refs:[],
port_id:72b9d37e-0526-45e1-8757-9f12bc402d13,
port.logical_router_back_refs:None

===port_delete=====port_id:72b9d37e-0526-45e1-8757-9f12bc402d13, logical_router_back_refs:None

[sajuptpm (sajuptpm)]

I am using following cassandra settings:
replication_factor = 3
rd_consistency = pycassa.cassandra.ttypes.ConsistencyLevel.QUORUM
wr_consistency = pycassa.cassandra.ttypes.ConsistencyLevel.QUORUM

is it ok ?
Should i do any cassandra tuning to get better read and write consistency ?

[Sachin Bansal (sbansal)]

cassandra setting look ok. Could you please also check if all 3 of your nodes are ntp synchronized? Without that, it is possible that cassandra can ignore the request to delete the ref.