yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1377241] Re: Lock wait timeout on delete port for DVR

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Thierry Carrez <thierry.carrez+lp@xxxxxxxxx>
Date: Thu, 18 Dec 2014 14:26:33 -0000
Reply-to: Bug 1377241 <1377241@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
** Changed in: neutron
       Status: Fix Committed => Fix Released

** Changed in: neutron
    Milestone: None => kilo-1

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

Title:
  Lock wait timeout on delete port for DVR

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

Bug description:
  We run a script to configure networks, VMs, Routers and assigin floatingIP to the VM.
  After it is created, then we run a script to clean all ports, networks, routers and gateway and FIP.

  The issue is seen when there is a back to back call to router-
  interface-delete and router-gateway-clear.

  There are three calls to router-interface-delete and the fourth call
  to router-gateway-clear.

  At this time there is a db lock obtained for port delete and when the
  other delete comes in, it timeout.

  
  2014-10-03 09:28:39.587 DEBUG neutron.openstack.common.lockutils [req-a89ee05c-d8b2-438a-a707-699f450d3c41 admin d3bb4e1791814b809672385bc8252688] Got semaphore "db-access" from (pid=25888) lock /opt/stack/neutron/neutron/openstack/common/lockutils.py:168
  2014-10-03 09:29:30.777 INFO neutron.wsgi [-] (25888) accepted ('192.168.15.144', 54899)
  2014-10-03 09:29:30.778 INFO neutron.wsgi [-] (25888) accepted ('192.168.15.144', 54900)
  2014-10-03 09:29:30.778 INFO neutron.wsgi [-] (25888) accepted ('192.168.15.144', 54901)
  2014-10-03 09:29:30.778 INFO neutron.wsgi [-] (25888) accepted ('192.168.15.144', 54902)
  2014-10-03 09:29:30.780 ERROR neutron.api.v2.resource [req-a89ee05c-d8b2-438a-a707-699f450d3c41 admin d3bb4e1791814b809672385bc8252688] remove_router_interface failed
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource Traceback (most recent call last):
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/opt/stack/neutron/neutron/api/v2/resource.py", line 87, in resource
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     result = method(request=request, **args)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/opt/stack/neutron/neutron/api/v2/base.py", line 200, in _handle_action
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     return getattr(self._plugin, name)(*arg_list, **kwargs)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 247, in remove_router_interface
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     context.elevated(), router, subnet_id=subnet_id)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/opt/stack/neutron/neutron/db/l3_dvr_db.py", line 557, in delete_csnat_router_interface_ports
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     l3_port_check=False)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/opt/stack/neutron/neutron/plugins/ml2/plugin.py", line 983, in delete_port
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     port_db, binding = db.get_locked_port_and_binding(session, id)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/opt/stack/neutron/neutron/plugins/ml2/db.py", line 135, in get_locked_port_and_binding
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     with_lockmode('update').
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2310, in one
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     ret = list(self)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2353, in __iter__
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     return self._execute_and_instances(context)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2368, in _execute_and_instances
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     result = conn.execute(querycontext.statement, self._params)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     params)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 761, in _execute_clauseelement
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     compiled_sql, distilled_params
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     context)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/compat/handle_error.py", line 125, in _handle_dbapi_exception
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     six.reraise(type(newraise), newraise, sys.exc_info()[2])
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/compat/handle_error.py", line 102, in _handle_dbapi_exception
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     per_fn = fn(ctx)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/exc_filters.py", line 323, in handler
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     context.is_disconnect)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource   File "/usr/local/lib/python2.7/dist-packages/oslo/db/sqlalchemy/exc_filters.py", line 254, in _raise_operational_errors_directly_filter
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource     raise operational_error
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource OperationalError: (OperationalError) (1205, 'Lock wait timeout exceeded; try restarting transaction') 'SELECT ports.tenant_id AS ports_tenant_id, ports.id AS ports_id, ports.name AS ports_name, ports.network_id AS ports_network_id, ports.mac_address AS ports_mac_address, ports.admin_state_up AS ports_admin_state_up, ports.status AS ports_status, ports.device_id AS ports_device_id, ports.device_owner AS ports_device_owner \nFROM ports \nWHERE ports.id = %s FOR UPDATE' ('bec69266-227d-4482-a346-ef47dd3a7a78',)
  2014-10-03 09:29:30.780 TRACE neutron.api.v2.resource

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

[Bug 1377241] [NEW] OperationalError: Lock wait timeout exceeded seen occasionally when we run a script to clean all networks, ports and routers. This is seen with DVR
From: Swaminathan Vasudevan, 2014-10-03