nicira: db integrity error during port deletion

[Armando Migliaccio]

This is a stacktrace experienced during a test on trunk:

2013-12-30 13:42:39.606 29118 DEBUG routes.middleware [-] Matched DELETE /ports/a42a9719-8416-4c44-a4f3-b3861648281f __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:100
2013-12-30 13:42:39.606 29118 DEBUG routes.middleware [-] Route path: '/ports/{id}{.format}', defaults: {'action': u'delete', 'controller': <wsgify at 72315472 wrapping <function resource at 0x44f2500>>} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-12-30 13:42:39.606 29118 DEBUG routes.middleware [-] Match dict: {'action': u'delete', 'controller': <wsgify at 72315472 wrapping <function resource at 0x44f2500>>, 'id': u'a42a9719-8416-4c44-a4f3-b3861648281f', 'format': None} __call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:103
2013-12-30 13:42:39.606 29118 DEBUG neutron.openstack.common.rpc.amqp [req-d8b115ac-38c3-4690-b670-7c81a9d9ca15 663434b6088b4984991d07a858d6f6bc 4a9f94ca2c674047b8e86fae8eefc9a4] Sending port.delete.start on notifications.info notify /opt/stack/neutron/neutron/openstack/common/rpc/amqp.py:598
2013-12-30 13:42:39.607 29118 DEBUG neutron.openstack.common.rpc.amqp [req-d8b115ac-38c3-4690-b670-7c81a9d9ca15 663434b6088b4984991d07a858d6f6bc 4a9f94ca2c674047b8e86fae8eefc9a4] UNIQUE_ID is 3f460839b3144eaa911c04de8725eb06. _add_unique_id /opt/stack/neutron/neutron/openstack/common/rpc/amqp.py:339
2013-12-30 13:42:39.610 29118 DEBUG neutron.plugins.nicira.api_client.client [-] [3681] Acquired connection https://192.168.1.8:443. 9 connection(s) available. acquire_connection /opt/stack/neutron/neutron/plugins/nicira/api_client/client.py:134
2013-12-30 13:42:39.611 29118 DEBUG neutron.plugins.nicira.api_client.request [-] [3681] Issuing - request POST https://192.168.1.8:443//ws.v1/lswitch/6d795954-a836-47f2-b2e3-2438e0da7f80/lport _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:99
2013-12-30 13:42:39.611 29118 DEBUG neutron.plugins.nicira.api_client.request [-] Setting X-Nvp-Wait-For-Config-Generation request header: '96230' _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:124
2013-12-30 13:42:39.647 29118 DEBUG neutron.plugins.nicira.nvplib [req-d8b115ac-38c3-4690-b670-7c81a9d9ca15 663434b6088b4984991d07a858d6f6bc 4a9f94ca2c674047b8e86fae8eefc9a4] Looking for port with q_port_id tag 'a42a9719-8416-4c44-a4f3-b3861648281f' on: '6d795954-a836-47f2-b2e3-2438e0da7f80' get_port_by_neutron_tag /opt/stack/neutron/neutron/plugins/nicira/nvplib.py:743
2013-12-30 13:42:39.648 29118 DEBUG neutron.plugins.nicira.api_client.client [-] [3682] Acquired connection https://192.168.1.8:443. 8 connection(s) available. acquire_connection /opt/stack/neutron/neutron/plugins/nicira/api_client/client.py:134
2013-12-30 13:42:39.648 29118 DEBUG neutron.plugins.nicira.api_client.request [-] [3682] Issuing - request GET https://192.168.1.8:443//ws.v1/lswitch/6d795954-a836-47f2-b2e3-2438e0da7f80/lport?fields=uuid&tag_scope=q_port_id&tag=a42a9719-8416-4c44-a4f3-b3861648281f _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:99
2013-12-30 13:42:39.648 29118 DEBUG neutron.plugins.nicira.api_client.request [-] Setting X-Nvp-Wait-For-Config-Generation request header: '96230' _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:124
2013-12-30 13:42:39.670 29118 DEBUG neutron.openstack.common.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_context_request_id': u'req-0f858449-8d08-4c71-af5c-3fa7b4470f20', u'_context_tenant_name': None, u'_context_project_name': None, u'_context_read_deleted': u'no', u'args': {u'agent_state': {u'agent_state': {u'topic': u'dhcp_agent', u'binary': u'neutron-dhcp-agent', u'host': u'cidevstack', u'agent_type': u'DHCP agent', u'configurations': {u'subnets': 3, u'use_namespaces': True, u'dhcp_lease_duration': 86400, u'dhcp_driver': u'neutron.agent.linux.dhcp.Dnsmasq', u'networks': 3, u'ports': 5}}}, u'time': u'2013-12-30T21:42:39.665454'}, u'_context_tenant': None, u'method': u'report_state', u'_unique_id': u'49ca1db3e75247e594c8c4005b4b262a', u'_context_timestamp': u'2013-12-30 21:42:39.665074', u'_context_is_admin': True, u'version': u'1.0', u'_context_project_id': None, u'_context_tenant_id': None, u'_context_user': None, u'_context_user_id': None, u'namespace': None, u'_context_user_name': None} _safe_log /opt/stack/neutron/neutron/openstack/common/rpc/common.py:276
2013-12-30 13:42:39.670 29118 DEBUG neutron.openstack.common.rpc.amqp [-] unpacked context: {'project_name': None, 'user_id': None, 'roles': [u'admin'], 'tenant_id': None, 'request_id': u'req-0f858449-8d08-4c71-af5c-3fa7b4470f20', 'is_admin': True, 'tenant': None, 'timestamp': u'2013-12-30 21:42:39.665074', 'tenant_name': None, 'project_id': None, 'user_name': None, 'read_deleted': u'no', 'user': None} _safe_log /opt/stack/neutron/neutron/openstack/common/rpc/common.py:276
2013-12-30 13:42:39.671 29118 DEBUG neutron.context [req-0f858449-8d08-4c71-af5c-3fa7b4470f20 None None] Arguments dropped when creating context: {'project_name': None, 'tenant': None} __init__ /opt/stack/neutron/neutron/context.py:84
2013-12-30 13:42:39.681 29118 DEBUG neutron.plugins.nicira.api_client.request [-] [3681] Completed request 'POST https://192.168.1.8:443//ws.v1/lswitch/6d795954-a836-47f2-b2e3-2438e0da7f80/lport': 201 (0.07 seconds) _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:141
2013-12-30 13:42:39.682 29118 DEBUG neutron.plugins.nicira.api_client.request [-] Reading X-Nvp-config-Generation response header: '96231' _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:146
2013-12-30 13:42:39.682 29118 DEBUG neutron.plugins.nicira.api_client.client [-] [3681] Released connection https://192.168.1.8:443. 9 connection(s) available. release_connection /opt/stack/neutron/neutron/plugins/nicira/api_client/client.py:189
2013-12-30 13:42:39.684 29118 DEBUG neutron.plugins.nicira.api_client.request [-] [3682] Completed request 'GET https://192.168.1.8:443//ws.v1/lswitch/6d795954-a836-47f2-b2e3-2438e0da7f80/lport?fields=uuid&tag_scope=q_port_id&tag=a42a9719-8416-4c44-a4f3-b3861648281f': 200 (0.04 seconds) _issue_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request.py:141
2013-12-30 13:42:39.684 29118 DEBUG neutron.plugins.nicira.api_client.client [-] [3682] Released connection https://192.168.1.8:443. 10 connection(s) available. release_connection /opt/stack/neutron/neutron/plugins/nicira/api_client/client.py:189
2013-12-30 13:42:39.685 29118 DEBUG neutron.plugins.nicira.api_client.request_eventlet [-] [3681] Completed request 'POST /ws.v1/lswitch/6d795954-a836-47f2-b2e3-2438e0da7f80/lport': 201 _handle_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request_eventlet.py:156
2013-12-30 13:42:39.685 29118 DEBUG neutron.plugins.nicira.api_client.request_eventlet [-] [3682] Completed request 'GET /ws.v1/lswitch/6d795954-a836-47f2-b2e3-2438e0da7f80/lport?fields=uuid&tag_scope=q_port_id&tag=a42a9719-8416-4c44-a4f3-b3861648281f': 200 _handle_request /opt/stack/neutron/neutron/plugins/nicira/api_client/request_eventlet.py:156
2013-12-30 13:42:39.686 29118 DEBUG neutron.plugins.nicira.nvplib [-] Created logical port d612afd7-339d-4f25-97d2-e6f6c966551e on logical switch 6d795954-a836-47f2-b2e3-2438e0da7f80 create_lport /opt/stack/neutron/neutron/plugins/nicira/nvplib.py:856
2013-12-30 13:42:39.696 29118 ERROR neutron.api.v2.resource [-] delete failed
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource Traceback (most recent call last):
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/api/v2/resource.py", line 84, in resource
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource result = method(request=request, **args)
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/api/v2/base.py", line 438, in delete
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource obj_deleter(request.context, id, **kwargs)
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/plugins/nicira/NeutronPlugin.py", line 1342, in delete_port
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource port_delete_func(context, neutron_db_port)
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/plugins/nicira/NeutronPlugin.py", line 498, in _nvp_delete_port
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource port_data)
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/plugins/nicira/NeutronPlugin.py", line 750, in _nvp_get_port_id
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource nvp_port['uuid'])
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/plugins/nicira/dbexts/nicira_db.py", line 54, in add_neutron_nvp_port_mapping
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource return mapping
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 456, in __exit__
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource self.commit()
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 368, in commit
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource self._prepare_impl()
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 347, in _prepare_impl
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource self.session.flush()
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/openstack/common/db/sqlalchemy/session.py", line 541, in _wrap
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource _raise_if_duplicate_entry_error(e, get_engine().name)
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource File "/opt/stack/neutron/neutron/openstack/common/db/sqlalchemy/session.py", line 492, in _raise_if_duplicate_entry_error
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource raise exception.DBDuplicateEntry(columns, integrity_error)
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource DBDuplicateEntry: (IntegrityError) (1062, "Duplicate entry 'a42a9719-8416-4c44-a4f3-b3861648281f' for key 'PRIMARY'") 'INSERT INTO quantum_nvp_port_mapping (quantum_id, nvp_id) VALUES (%s, %s)' ('a42a9719-8416-4c44-a4f3-b3861648281f', 'd612afd7-339d-4f25-97d2-e6f6c966551e')
2013-12-30 13:42:39.696 29118 TRACE neutron.api.v2.resource
2013-12-30 13:42:39.700 29118 INFO neutron.wsgi [-] 127.0.0.1 - - [30/Dec/2013 13:42:39] "DELETE //v2.0/ports/a42a9719-8416-4c44-a4f3-b3861648281f HTTP/1.1" 500 249 0.097381

It is unclear what the root cause is at the moment.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit de4b5a2bba57cbd5294fb6f9527d64b8eeddf901
Author: armando-migliaccio <email address hidden>
Date: Tue Dec 31 05:51:43 2013 -0800

    nicira: fix db integrity error during port deletion

    Due to the fact that plugin port operations are not
    transactional (as they involve non synchronized DB
    and Controller operations), concurrent (interleaved)
    port requests may accidentally cause the insertion
    of the mapping entry (neutron-port-id, nvp-port-id)
    more than once. In case this occurs, it's safe to
    expect the failure and continue the normal process
    of the operation being requested.

    Closes-bug: #1265081

    Change-Id: Ifcf5b453fa08145df844c2de3cbb08bf2f4baa59