DBAPIError

[Christoph Manns]

Hiho,
we recently discovered that our neutron server are throwing exception upon various DB operations.

2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters [req-1eacbfed-9560-4fba-b1fa-bfcf0136d504 - - - - -] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_28 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_28'] (Background on this error at: http://sqlalche.me/e/2j85): InternalError: (1305, u'SAVEPOINT sa_savepoint_28 does not exist')
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters context)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters cursor.execute(statement, parameters)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 170, in execute
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters result = self._query(query)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 328, in _query
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters conn.query(q)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 893, in query
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1103, in _read_query_result
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters result.read()
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1396, in read
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters first_packet = self.connection._read_packet()
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1059, in _read_packet
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters packet.check_error()
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 384, in check_error
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters err.raise_mysql_exception(self._data)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 109, in raise_mysql_exception
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters raise errorclass(errno, errval)
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_28 does not exist')
2018-10-02 13:32:45.384 6479 ERROR oslo_db.sqlalchemy.exc_filters

------------------------
LATEST DETECTED DEADLOCK
------------------------
2018-10-02 13:32:45 7f2c88915700
*** (1) TRANSACTION:
TRANSACTION 221633832, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1184, 3 row lock(s), undo log entries 2
MySQL thread id 35685062, OS thread handle 0x7f2c993bc700, query id 528303451 $hostname $ip neutron updating
UPDATE standardattributes SET revision_number=6, updated_at='2018-10-02 11:32:45' WHERE standardattributes.id = 291182 AND standardattributes.revision_number = 5
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 401 page no 17 n bits 368 index `PRIMARY` of table `neutron`.`standardattributes` trx id 221633832 lock_mode X locks rec but not gap waiting
*** (2) TRANSACTION:
TRANSACTION 221633901, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 35700724, OS thread handle 0x7f2c88915700, query id 528303621 $hostname $ip neutron updating
UPDATE standardattributes SET revision_number=7, updated_at='2018-10-02 11:32:45' WHERE standardattributes.id = 291212 AND standardattributes.revision_number = 6
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 401 page no 17 n bits 368 index `PRIMARY` of table `neutron`.`standardattributes` trx id 221633901 lock_mode X locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 401 page no 17 n bits 368 index `PRIMARY` of table `neutron`.`standardattributes` trx id 221633901 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (2)

Any help is greatly appreciated.

[Brian Haley (brian-haley)]

Hi,

Can you give information on what version of neutron you are running? If you can reproduce this on the master branch or even Rocky that would be good info to have. Thanks.

[Christoph Manns (christoph-manns)]

Sorry, of course I forgot to provide the version.
We're running the latest tagged queens release.

[Launchpad Janitor (janitor)]

[Expired for neutron because there has been no activity for 60 days.]