yahoo-eng-team team mailing list archive

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

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1571666@xxxxxxxxxxxxxxxxxx>
Date: Wed, 22 Jun 2016 19:08:32 -0000
Reply-to: Bug 1571666 <1571666@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Reviewed:  https://review.openstack.org/332098
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=1d8eabaff1cff9efbc122b68a54b94745e001cd6
Submitter: Jenkins
Branch:    master

commit 1d8eabaff1cff9efbc122b68a54b94745e001cd6
Author: Pavel Bondar <pbondar@xxxxxxxxxxxx>
Date:   Tue Jun 21 14:34:57 2016 +0300

    Do not rewrite original exception for IPAM part 2
    
    If subnet allocation fails on _save_subnet stage, then rollback mechnism
    is executed. Currently if exception is raised on rollback stage it
    replaces original exception. But original exception is needed by
    retry wrappers to work properly also it is more informative for user.
    
    Using _safe_rollback method to prevent replacing original exception with
    one from rollback stage.
    
    Closes-Bug: #1571666
    Change-Id: I388272820451bb117281948fef0000bb46a951d4


** 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/1571666

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

Status in neutron:
  Fix Released

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
References

[Bug 1571666] [NEW] [Pluggable IPAM] Original exception is replaced on rollback failure
From: Pavel Bondar, 2016-04-18