← Back to team overview

yahoo-eng-team team mailing list archive

  1. yahoo-eng-team team
  2. Mailing list archive
  3. Message #23358

[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

  Thread Previous • Date Previous • • Thread Next 
Public bug reported:

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

** Affects: neutron
     Importance: Undecided
         Status: New


** Tags: l3-dvr-backlog

** Attachment added: "Lockwait-timeout.txt"
   https://bugs.launchpad.net/bugs/1377241/+attachment/4223688/+files/Lockwait-timeout.txt

-- 
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:
  OperationalError:  Lock wait timeout exceeded seen occasionally when
  we run a script to clean all networks, ports and routers. This is seen
  with DVR

Status in OpenStack Neutron (virtual network service):
  New

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

Follow ups

References

  Thread Previous • Date Previous • • Thread Next