an object is deleted twice that causes object not found

[Li Ma]

May 18 19:39:51.678170 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb [-] 'NoneType' object has no attribute 'emit_deleted'
May 18 19:39:51.678589 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb Traceback (most recent call last):
May 18 19:39:51.678922 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb File "/opt/stack/new/dragonflow/dragonflow/db/api_nb.py", line 250, in _read_db_changes_from_queue
May 18 19:39:51.679213 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb value)
May 18 19:39:51.679519 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb File "/opt/stack/new/dragonflow/dragonflow/db/api_nb.py", line 282, in apply_db_change
May 18 19:39:51.679792 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb self.controller.delete_by_id(model_class, key)
May 18 19:39:51.680085 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb File "/opt/stack/new/dragonflow/dragonflow/controller/df_local_controller.py", line 591, in delete_by_id
May 18 19:39:51.680342 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb return handler(model(id=obj_id))
May 18 19:39:51.680595 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb File "/opt/stack/new/dragonflow/dragonflow/controller/df_local_controller.py", line 545, in delete_model_object
May 18 19:39:51.680860 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb obj.emit_deleted()
May 18 19:39:51.681125 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb AttributeError: 'NoneType' object has no attribute 'emit_deleted'
May 18 19:39:51.681409 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: ERROR dragonflow.db.api_nb

[Li Ma (nick-ma-z)]

May 18 19:39:51.674157 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: DEBUG dragonflow.db.api_nb [-] Pushing Update to Queue: Action:delete, Table:lrouter, Key:2770eb89-d914-4696-a789-162bd0e2da57 Value:2770eb89-d914-4696-a789-162bd0e2da57 Topic:D {{(pid=22868) db_change_callback /opt/stack/new/dragonflow/dragonflow/db/api_nb.py:228}}
May 18 19:39:51.674634 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: DEBUG dragonflow.db.api_nb [-] Event update: Action:delete, Table:lrouter, Key:2770eb89-d914-4696-a789-162bd0e2da57 Value:2770eb89-d914-4696-a789-162bd0e2da57 Topic:D {{(pid=22868) _read_db_changes_from_queue /opt/stack/new/dragonflow/dragonflow/db/api_nb.py:237}}
May 18 19:39:51.675958 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: DEBUG dragonflow.db.model_framework [-] router_deleted from dragonflow.controller.l3_app_base gets deleted event of LogicalRouter(id=u'2770eb89-d914-4696-a789-162bd0e2da57', name=u'myrouter1', ports=[], routes=[], topic=u'82a854baf9df41bb817b88b67ec69ee2', unique_key=18, version=6). {{(pid=22868) _emit /opt/stack/new/dragonflow/dragonflow/db/model_framework.py:107}}
May 18 19:39:51.676869 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: DEBUG dragonflow.db.api_nb [-] Pushing Update to Queue: Action:delete, Table:lrouter, Key:2770eb89-d914-4696-a789-162bd0e2da57 Value:2770eb89-d914-4696-a789-162bd0e2da57 Topic:D {{(pid=22868) db_change_callback /opt/stack/new/dragonflow/dragonflow/db/api_nb.py:228}}
May 18 19:39:51.677186 ubuntu-xenial-ovh-gra1-8884370 df-local-controller[22868]: DEBUG dragonflow.db.api_nb [-] Event update: Action:delete, Table:lrouter, Key:2770eb89-d914-4696-a789-162bd0e2da57 Value:2770eb89-d914-4696-a789-162bd0e2da57 Topic:D {{(pid=22868) _read_db_changes_from_queue /opt/stack/new/dragonflow/dragonflow/db/api_nb.py:237}}

The router is deleted twice that causes object is not found.

[Omer Anson (omer-anson)]

From looking at the logs, I see to repeated deletes: lport and lrouter. I think they come from the topology model.

When the OVS port is removed, the matching lport is removed as well. If that was the last lport belonging to the tenant/topic, then the matching lrouter is removed as well.

I think fix 466149 ( https://review.openstack.org/#/c/466149/2 ) can close this bug. The behaviour is as expected - topology removes objects before they are removed from DB. When DB removes them, then they already appear deleted. Since it is done at the same time, the topic isn't yet removed from the subscriber and we see both deletes (both from topology and from server). I don't think this race condition can happen in the other direction - since then we have to delete the last object and create one at the same time. If this appears, we could just add a lock to topology (But I still don't think it's needed now).

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/466149
Committed: https://git.openstack.org/cgit/openstack/dragonflow/commit/?id=54822b1a47a7aee2a5be6cc154573bef6036ce3d
Submitter: Jenkins
Branch: master

commit 54822b1a47a7aee2a5be6cc154573bef6036ce3d
Author: Li Ma <email address hidden>
Date: Fri May 19 10:06:19 2017 +0800

    Check if the object has been deleted

    When calling db_store2.get_one(), it should check
    if this method returns None which means the object
    cannot be found.

    This logic has been implemented in other methods
    except this one.

    The root cause of deleting one object twice needs
    further investigation.

    Change-Id: Icbe320170751e5771ca1426d10abfe3ae6cf8846
    Closes-Bug: #1691904