yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1265081] Re: nicira: db integrity error during port deletion

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Thierry Carrez <thierry.carrez+lp@xxxxxxxxx>
Date: Wed, 22 Jan 2014 15:15:18 -0000
Reply-to: Bug 1265081 <1265081@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: neutron
       Status: Fix Committed => Fix Released

** Changed in: neutron
    Milestone: None => icehouse-2

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1265081

Title:
  nicira: db integrity error during port deletion

Status in OpenStack Neutron (virtual network service):
  Fix Released

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1265081/+subscriptions
References

[Bug 1265081] [NEW] nicira: db integrity error during port deletion
From: Armando Migliaccio, 2013-12-30