Public bug reported:
If mysql triggers a deadlock error while in a nested transaction, the
savepoint can be lost, which will cause a DBError from sqlalchemy that
looks like the following:
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
[req-287a245f-f5da-4126-9625-148e889b3443 tempest-NetworksTestDHCPv6-2134889417
-] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305,
u'SAVEPOINT sa_savepoint_1 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT
sa_savepoint_1']
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters Traceback
(most recent call last):
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139,
in _execute_context
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters context)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line
450, in do_execute
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
cursor.execute(statement, parameters)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 161, in
execute
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters result =
self._query(query)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 317, in _query
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
conn.query(q)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 835, in
query
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1019, in
_read_query_result
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
result.read()
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1302, in
read
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
first_packet = self.connection._read_packet()
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 981, in
_read_packet
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
packet.check_error()
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 393, in
check_error
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
err.raise_mysql_exception(self._data)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in
raise_mysql_exception
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
_check_mysql_exception(errinfo)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 115, in
_check_mysql_exception
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters raise
InternalError(errno, errorvalue)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
InternalError: (1305, u'SAVEPOINT sa_savepoint_1 does not exist')
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
/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 ipallocations (port_id, ip_address, subnet_id, network_id) VALUES
(%(port_id)s, %(ip_address)s, %(subnet_id)s, %(network_id)s)'] [parameters:
{'network_id': u'bab3d364-8fff-43dd-ac4b-28baf51060e2', 'subnet_id':
'0e4d20e8-9f7a-420c-947c-913e8fca99b1', 'port_id':
u'856f7fe5-65b4-45f3-a3ea-e99bc2e9c1cb', 'ip_address':
'2003::f816:3eff:fe5b:1efb'}]
This is a known issue with how mysql handles the savepoints on errors:
https://bitbucket.org/zzzeek/sqlalchemy/issues/2696/misleading-exception-triggered-on
So we need to look for this particular exception in our retry wrapper since the
real cause is likely a deadlock error.
** Affects: neutron
Importance: Undecided
Assignee: Kevin Benton (kevinbenton)
Status: New
** Changed in: neutron
Assignee: (unassigned) => Kevin Benton (kevinbenton)
--
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to neutron.
https://bugs.launchpad.net/bugs/1590298
Title:
DB retry wrapper needs to look for savepoint errors
Status in neutron:
New
Bug description:
If mysql triggers a deadlock error while in a nested transaction, the
savepoint can be lost, which will cause a DBError from sqlalchemy that
looks like the following:
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
[req-287a245f-f5da-4126-9625-148e889b3443 tempest-NetworksTestDHCPv6-2134889417
-] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305,
u'SAVEPOINT sa_savepoint_1 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT
sa_savepoint_1']
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters Traceback
(most recent call last):
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1139,
in _execute_context
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
context)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line
450, in do_execute
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
cursor.execute(statement, parameters)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 161, in
execute
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters result
= self._query(query)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/cursors.py", line 317, in _query
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
conn.query(q)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 835, in
query
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1019, in
_read_query_result
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
result.read()
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 1302, in
read
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
first_packet = self.connection._read_packet()
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 981, in
_read_packet
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
packet.check_error()
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/connections.py", line 393, in
check_error
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
err.raise_mysql_exception(self._data)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 120, in
raise_mysql_exception
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
_check_mysql_exception(errinfo)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters File
"/usr/local/lib/python2.7/dist-packages/pymysql/err.py", line 115, in
_check_mysql_exception
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters raise
InternalError(errno, errorvalue)
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
InternalError: (1305, u'SAVEPOINT sa_savepoint_1 does not exist')
2016-06-08 05:15:22.609 18530 ERROR oslo_db.sqlalchemy.exc_filters
/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 ipallocations (port_id, ip_address, subnet_id, network_id) VALUES
(%(port_id)s, %(ip_address)s, %(subnet_id)s, %(network_id)s)'] [parameters:
{'network_id': u'bab3d364-8fff-43dd-ac4b-28baf51060e2', 'subnet_id':
'0e4d20e8-9f7a-420c-947c-913e8fca99b1', 'port_id':
u'856f7fe5-65b4-45f3-a3ea-e99bc2e9c1cb', 'ip_address':
'2003::f816:3eff:fe5b:1efb'}]
This is a known issue with how mysql handles the savepoints on errors:
https://bitbucket.org/zzzeek/sqlalchemy/issues/2696/misleading-exception-triggered-on
So we need to look for this particular exception in our retry wrapper since
the real cause is likely a deadlock error.
To manage notifications about this bug go to:
https://bugs.launchpad.net/neutron/+bug/1590298/+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
