Reviewed: https://review.openstack.org/309067 Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=310074b2d457a6de2fdf141d4ede6b6044efc002 Submitter: Jenkins Branch: master
commit 310074b2d457a6de2fdf141d4ede6b6044efc002 Author: Pavel Bondar <pbon...@infoblox.com> Date: Thu Apr 21 17:31:13 2016 +0300 Check if pool update is needed in reference driver Commit 6ed8f45fdf529bacae32b074844aa1320b005b51 had some negative impact on concurrent ip allocations. To make ipam driver aware of subnet updates (mostly for thirdparty drivers) ipam driver is always called with allocation pools even if pools are not changed. Current way of handling that event is deleting old pools and creating new pools. But on scale it may cause issues, because of this: - deleting allocation pools removes availability ranges by foreign key; - any ip allocation modifies availability range; These events concurently modify availability range records causing deadlocks. This fix prevents deleting and recreating pools and availability ranges in cases where allocation pools are not changed. So it eliminates negative impact on concurency added by always calling ipam driver on subnet update. This fix aims to provide backportable solution to be used with 6ed8f45fdf529bacae32b074844aa1320b005b51. Complete solution that eliminates concurrent modifications in availability range table is expected to be devivered with ticket #1543094, but it will not be backportable because of the scope of the change. Change-Id: I29e03a79c34b150a822697f7b556ed168a57c064 Related-Bug: #1534625 Closes-Bug: #1572474 ** Changed in: neutron Status: In Progress => Fix Released -- You received this bug notification because you are a member of Yahoo! Engineering Team, which is subscribed to neutron. https://bugs.launchpad.net/bugs/1572474 Title: [Pluggable IPAM] Deadlock on simultaneous update subnet and ip allocation from subnet Status in neutron: Fix Released Bug description: Observed in logs 'Lock wait timeout exceeded; try restarting transaction' [1], when two requests are concurently executed in neutron: - request A calls update subnet req-5f9fc363-4b22-48e0-97e2-504aa7c3dda3 - request B calls create port on the same subnet req-ccd11684-ad2b-4937-a3c1-dc46aaa36b2d As a result both requests failed. Request A tries to delete 'ipamallocationpools' for subnet_id and it effectivelly removes 'ipamavailabilityranges' by foreign key. Request B allocates ip and modifies av_range record in 'ipamavailabilityranges'. So looks like collision caused by concurent access to 'ipamavailabilityranges' table. [1] http://logs.openstack.org/23/181023/68/check/gate-tempest-dsvm- neutron-full/a9180e0/logs/screen-q-svc.txt.gz#_2016-04-19_15_43_05_837 StackTrace with both requests failed: 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters [req-5f9fc363-4b22-48e0-97e2-504aa7c3dda3 tempest-NetworksIpV6Test-714183411 -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'DELETE FROM ipamallocationpools WHERE ipamallocationpools.ipam_subnet_id = %(ipam_subnet_id_1)s'] [parameters: {u'ipam_subnet_id_1': u'0b896671-8cc2-4e08-bbfe-05655e6c479c'}] 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last): 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters context) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1002, in _read_query_result 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters result.read() 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet() 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error() 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters _check_mysql_exception(errinfo) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters raise InternalError(errno, errorvalue) 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1205, u'Lock wait timeout exceeded; try restarting transaction') 2016-04-19 15:43:05.837 17992 ERROR oslo_db.sqlalchemy.exc_filters 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource [req-5f9fc363-4b22-48e0-97e2-504aa7c3dda3 tempest-NetworksIpV6Test-714183411 -] update failed 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource Traceback (most recent call last): 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/resource.py", line 84, in resource 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource result = method(request=request, **args) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 579, in update 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource return self._update(request, id, body, **kwargs) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 148, in wrapper 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource ectxt.value = e.inner_exc 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__ 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource self.force_reraise() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource six.reraise(self.type_, self.value, self.tb) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/oslo_db/api.py", line 138, in wrapper 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource return f(*args, **kwargs) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/api/v2/base.py", line 624, in _update 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource obj = obj_updater(request.context, id, **kwargs) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py", line 912, in update_subnet 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource context, id, subnet) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 764, in update_subnet 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource db_pools) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/ipam_pluggable_backend.py", line 381, in update_db_subnet 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource self._ipam_update_allocation_pools(context, ipam_driver, subnet_copy) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/db/ipam_pluggable_backend.py", line 159, in _ipam_update_allocation_pools 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource ipam_driver.update_subnet(subnet_request) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/ipam/drivers/neutrondb_ipam/driver.py", line 440, in update_subnet 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource subnet.update_allocation_pools(subnet_request.allocation_pools, cidr) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/ipam/drivers/neutrondb_ipam/driver.py", line 377, in update_allocation_pools 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource self.subnet_manager.delete_allocation_pools(session) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/opt/stack/new/neutron/neutron/ipam/drivers/neutrondb_ipam/db_api.py", line 99, in delete_allocation_pools 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource ipam_subnet_id=self._ipam_subnet_id).delete() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 3048, in delete 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource delete_op.exec_() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 1127, in exec_ 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource self._do_exec() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 1311, in _do_exec 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource mapper=self.mapper) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1034, in execute 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource bind, close_with_result=True).execute(clause, params or {}) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 914, in execute 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource return meth(self, multiparams, params) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource return connection._execute_clauseelement(self, multiparams, params) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource compiled_sql, distilled_params 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource context) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource util.raise_from_cause(newraise, exc_info) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource reraise(type(exception), exception, tb=exc_tb, cause=cause) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource context) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource cursor.execute(statement, parameters) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource result = self._query(query) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource conn.query(q) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource self._affected_rows = self._read_query_result(unbuffered=unbuffered) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1002, in _read_query_result 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource result.read() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource first_packet = self.connection._read_packet() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource packet.check_error() 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource err.raise_mysql_exception(self._data) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource _check_mysql_exception(errinfo) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource raise InternalError(errno, errorvalue) 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource DBError: (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'DELETE FROM ipamallocationpools WHERE ipamallocationpools.ipam_subnet_id = %(ipam_subnet_id_1)s'] [parameters: {u'ipam_subnet_id_1': u'0b896671-8cc2-4e08-bbfe-05655e6c479c'}] 2016-04-19 15:43:05.847 17992 ERROR neutron.api.v2.resource 2016-04-19 15:43:05.863 17992 INFO neutron.wsgi [req-5f9fc363-4b22-48e0-97e2-504aa7c3dda3 tempest-NetworksIpV6Test-714183411 -] 127.0.0.1 - - [19/Apr/2016 15:43:05] "PUT /v2.0/subnets/f5613ce4-2fd8-4ab7-a87e-558b1b1b7bc2 HTTP/1.1" 500 363 51.651743 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters [req-ccd11684-ad2b-4937-a3c1-dc46aaa36b2d - -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1205, u'Lock wait timeout exceeded; try restarting transaction') [SQL: u'INSERT INTO ipallocations (port_id, ip_address, subnet_id, network_id) VALUES (%(port_id)s, %(ip_address)s, %(subnet_id)s, %(network_id)s)'] [parameters: {'subnet_id': u'f5613ce4-2fd8-4ab7-a87e-558b1b1b7bc2', 'network_id': u'33d94f9c-e24b-448f-900c-0249fbd6c96d', 'port_id': 'b81c0244-1eb9-4716-b85f-253deed19b19', 'ip_address': u'2003::3'}] 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last): 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters context) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1002, in _read_query_result 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters result.read() 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet() 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error() 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in raise_mysql_exception 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters _check_mysql_exception(errinfo) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 115, in _check_mysql_exception 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters raise InternalError(errno, errorvalue) 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1205, u'Lock wait timeout exceeded; try restarting transaction') 2016-04-19 15:43:05.862 17994 ERROR oslo_db.sqlalchemy.exc_filters To manage notifications about this bug go to: https://bugs.launchpad.net/neutron/+bug/1572474/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp