yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1571666] [NEW] [Pluggable IPAM] Original exception is replaced on rollback failure

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Pavel Bondar <pbondar@xxxxxxxxxxxx>
Date: Mon, 18 Apr 2016 13:48:54 -0000
Reply-to: Bug 1571666 <1571666@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

During concurent allocation/deallocation/update multiple ips in ipam_pluggable_backend deadlock  can be raised [1]. It causes rollback actions to be performed in [2], but because of raising deadlock exception database is not in operatable state unless full transaction restart. So it cause rollback action to fail and raise another exception 'InternalError'.
As a result original exception DeadLock was replaced with InternalError and db_retry wrapper does not restart transaction in this case.

Resulting exception as seen in logs[3]:

2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters [req-15281429-cfa8-4b9f-a904-0105fc947933 admin -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_3 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_3']
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     context)
2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)
2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_3 does not exist')
2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters 
2016-04-13 12:15:04.687 18294 DEBUG oslo_messaging._drivers.amqpdriver [req-56495b4e-29c9-4360-8609-f5b3ded6ed8f - -] sending reply msg_id: ee2f4dd536fb48e79bee32a668e3cc1d reply queue: reply_d2a1789c66c141888838b059e322350c time elapsed: 0.006736069s _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:74
/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py:68: SAWarning: An exception has occurred during handling of a previous exception.  The previous exception is:
 <class 'oslo_db.exception.DBDeadlock'> (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'INSERT INTO ipamallocations (ip_address, status, ipam_subnet_id) VALUES (%(ip_address)s, %(status)s, %(ipam_subnet_id)s)'] [parameters: {'status': 'ALLOCATED', 'ip_address': u'2001:db8::4e', 'ipam_subnet_id': u'1c084441-cec0-4865-848a-a75f01711e36'}]

  "is:\n %s %s\n" % (self._exc_info[0], self._exc_info[1]))
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters [req-15281429-cfa8-4b9f-a904-0105fc947933 admin -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_3 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_3']
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     context)
2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)
2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_3 does not exist')
2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters 


[1] https://github.com/openstack/neutron/blob/2a305c563073a3066aac3f07aab3c895ec2cd2fb/neutron/db/ipam_pluggable_backend.py#L59
[2] https://github.com/openstack/neutron/blob/2a305c563073a3066aac3f07aab3c895ec2cd2fb/neutron/db/ipam_pluggable_backend.py#L69
[3] http://logs.openstack.org/23/181023/64/check/gate-tempest-dsvm-neutron-dvr/f503538/logs/screen-q-svc.txt.gz#_2016-04-13_12_15_04_685

** Affects: neutron
     Importance: Undecided
     Assignee: Pavel Bondar (pasha117)
         Status: New


** Tags: l3-ipam-dhcp

** Changed in: neutron
     Assignee: (unassigned) => Pavel Bondar (pasha117)

** Tags added: l3-ipam-dhcp

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

Title:
  [Pluggable IPAM] Original exception is replaced on rollback failure

Status in neutron:
  New

Bug description:
  During concurent allocation/deallocation/update multiple ips in ipam_pluggable_backend deadlock  can be raised [1]. It causes rollback actions to be performed in [2], but because of raising deadlock exception database is not in operatable state unless full transaction restart. So it cause rollback action to fail and raise another exception 'InternalError'.
  As a result original exception DeadLock was replaced with InternalError and db_retry wrapper does not restart transaction in this case.

  Resulting exception as seen in logs[3]:

  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters [req-15281429-cfa8-4b9f-a904-0105fc947933 admin -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_3 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_3']
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
  2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     context)
  2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
  2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)
  2016-04-13 12:15:04.685 18292 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-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_3 does not exist')
  2016-04-13 12:15:04.685 18292 ERROR oslo_db.sqlalchemy.exc_filters 
  2016-04-13 12:15:04.687 18294 DEBUG oslo_messaging._drivers.amqpdriver [req-56495b4e-29c9-4360-8609-f5b3ded6ed8f - -] sending reply msg_id: ee2f4dd536fb48e79bee32a668e3cc1d reply queue: reply_d2a1789c66c141888838b059e322350c time elapsed: 0.006736069s _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:74
  /usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py:68: SAWarning: An exception has occurred during handling of a previous exception.  The previous exception is:
   <class 'oslo_db.exception.DBDeadlock'> (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'INSERT INTO ipamallocations (ip_address, status, ipam_subnet_id) VALUES (%(ip_address)s, %(status)s, %(ipam_subnet_id)s)'] [parameters: {'status': 'ALLOCATED', 'ip_address': u'2001:db8::4e', 'ipam_subnet_id': u'1c084441-cec0-4865-848a-a75f01711e36'}]

    "is:\n %s %s\n" % (self._exc_info[0], self._exc_info[1]))
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters [req-15281429-cfa8-4b9f-a904-0105fc947933 admin -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_3 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_3']
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
  2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     context)
  2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 158, in execute
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 308, in _query
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 820, in query
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
  2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1285, in read
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 966, in _read_packet
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 394, in check_error
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
  2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     _check_mysql_exception(errinfo)
  2016-04-13 12:15:04.688 18292 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-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters     raise InternalError(errno, errorvalue)
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_3 does not exist')
  2016-04-13 12:15:04.688 18292 ERROR oslo_db.sqlalchemy.exc_filters 

  
  [1] https://github.com/openstack/neutron/blob/2a305c563073a3066aac3f07aab3c895ec2cd2fb/neutron/db/ipam_pluggable_backend.py#L59
  [2] https://github.com/openstack/neutron/blob/2a305c563073a3066aac3f07aab3c895ec2cd2fb/neutron/db/ipam_pluggable_backend.py#L69
  [3] http://logs.openstack.org/23/181023/64/check/gate-tempest-dsvm-neutron-dvr/f503538/logs/screen-q-svc.txt.gz#_2016-04-13_12_15_04_685

To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1571666/+subscriptions
Follow ups

[Bug 1571666] Re: [Pluggable IPAM] Original exception is replaced on rollback failure
From: OpenStack Infra, 2016-06-22