1567627 – DBAPI and DBDealock errors when trying to update agents

Bug 1567627 - DBAPI and DBDealock errors when trying to update agents

Summary: DBAPI and DBDealock errors when trying to update agents

Keywords:
Status:	CLOSED INSUFFICIENT_DATA
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	openstack-neutron
Sub Component:
Version:	13.0 (Queens)
Hardware:	Unspecified
OS:	Linux
Priority:	unspecified
Severity:	high
Target Milestone:	---
Target Release:	---
Assignee:	Assaf Muller
QA Contact:	Toni Freger
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2018-04-15 15:46 UTC by Sai Sindhur Malleni
Modified:	2023-10-06 17:46 UTC (History)
CC List:	11 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2019-04-29 13:53:11 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Description Sai Sindhur Malleni 2018-04-15 15:46:16 UTC

Description of problem: When running scale tests to create 100s of neutron resources we see the following DBAPI and DBDeadlock errors.

2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters [req-69f1c132-d775-43eb-8087-8f27191f0683 ec4fa895e60e4d6895e13f6924579aa5 39275abb657f4e85b80f77f6e6467e9d - default default] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_6 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_6'] (Background on this error at: http://sqlalche.me/e/2j85): InternalError: (1305, u'SAVEPOINT sa_savepoint_6 does not exist')
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     context)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1014, in _read_packet
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters     raise errorclass(errno, errval)
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_6 does not exist')
2018-04-15 15:02:00.445 35 ERROR oslo_db.sqlalchemy.exc_filters
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters [req-69f1c132-d775-43eb-8087-8f27191f0683 ec4fa895e60e4d6895e13f6924579aa5 39275abb657f4e85b80f77f6e6467e9d - default default] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_5 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_5'] (Background on this error at: http://sqlalche.me/e/2j85): InternalError: (1305, u'SAVEPOINT sa_savepoint_5 does not exist')
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     context)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1014, in _read_packet
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters     raise errorclass(errno, errval)
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_5 does not exist')
2018-04-15 15:02:00.449 35 ERROR oslo_db.sqlalchemy.exc_filters
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters [req-69f1c132-d775-43eb-8087-8f27191f0683 ec4fa895e60e4d6895e13f6924579aa5 39275abb657f4e85b80f77f6e6467e9d - default default] DBAPIError exception wrapped from (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_4 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_4'] (Background on this error at: http://sqlalche.me/e/2j85): InternalError: (1305, u'SAVEPOINT sa_savepoint_4 does not exist')
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters Traceback (most recent call last):
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     context)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     cursor.execute(statement, parameters)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     result = self._query(query)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     conn.query(q)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     result.read()
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     first_packet = self.connection._read_packet()
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1014, in _read_packet
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     packet.check_error()
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     err.raise_mysql_exception(self._data)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters   File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters     raise errorclass(errno, errval)
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters InternalError: (1305, u'SAVEPOINT sa_savepoint_4 does not exist')
2018-04-15 15:02:00.451 35 ERROR oslo_db.sqlalchemy.exc_filters
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager [req-69f1c132-d775-43eb-8087-8f27191f0683 ec4fa895e60e4d6895e13f6924579aa5 39275abb657f4e85b80f77f6e6467e9d - default default] Error during notification for neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification-1687107 port, after_create: DBError: (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_4 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_4'] (Background on this error at: http://sqlalche.me/e/2j85)
  DBError: (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_5 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_5'] (Background on this error at: http://sqlalche.me/e/2j85)
    DBError: (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_6 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_6'] (Background on this error at: http://sqlalche.me/e/2j85)
      DBDeadlock: (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE agents SET `load`=%(load)s WHERE agents.id = %(agents_id)s'] [parameters: {'load': 20, 'agents_id': u'5f976e47-3630-44cd-b518-8bd6245e5c07'}] (Background on this error at: http://sqlalche.me/e/2j85)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager Traceback (most recent call last):
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron_lib/callbacks/manager.py", line 171, in _notify_loop
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     callback(resource, event, trigger, **kwargs)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py", line 247, in _native_event_send_dhcp_notification
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self.notify(context, data, method_name)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py", line 299, in notify
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self._notify_agents(context, method_name, data, network_id)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py", line 180, in _notify_agents
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     agents = self._schedule_network(admin_ctx, network, agents)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py", line 99, in _schedule_network
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     new_agents = self.plugin.schedule_network(context, network) or []
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/db/agentschedulers_db.py", line 467, in schedule_network
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self, context, created_network)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/scheduler/base_scheduler.py", line 50, in schedule
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self.resource_filter.bind(context, chosen_agents, resource['id'])
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/scheduler/dhcp_agent_scheduler.py", line 189, in bind
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     super(DhcpFilter, self).bind(context, bound_agents, network_id)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/scheduler/base_resource_filter.py", line 42, in bind
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     agent.update()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/objects/base.py", line 322, in decorator
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     return res
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/contextlib.py", line 35, in __exit__
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self.gen.throw(type, value, traceback)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/neutron/db/api.py", line 206, in autonested_transaction
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     yield tx
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 574, in __exit__
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self.rollback()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 532, in rollback
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     util.reraise(*rollback_err)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 497, in rollback
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     t[1].rollback()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1632, in rollback
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self._do_rollback()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1694, in _do_rollback
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self._savepoint, self._parent)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 753, in _rollback_to_savepoint_impl
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self.engine.dialect.do_rollback_to_savepoint(self, name)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 498, in do_rollback_to_savepoint
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     connection.execute(expression.RollbackToSavepointClause(name))
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 948, in execute
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     return meth(self, multiparams, params)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 269, in _execute_on_connection
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     return connection._execute_clauseelement(self, multiparams, params)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1060, in _execute_clauseelement
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     compiled_sql, distilled_params
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1200, in _execute_context
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     context)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1409, in _handle_dbapi_exception
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     util.raise_from_cause(newraise, exc_info)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     reraise(type(exception), exception, tb=exc_tb, cause=cause)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1193, in _execute_context
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     context)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 507, in do_execute
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     cursor.execute(statement, parameters)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 166, in execute
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     result = self._query(query)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/cursors.py", line 322, in _query
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     conn.query(q)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 856, in query
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     self._affected_rows = self._read_query_result(unbuffered=unbuffered)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1057, in _read_query_result
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     result.read()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1340, in read
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     first_packet = self.connection._read_packet()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 1014, in _read_packet
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     packet.check_error()
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/connections.py", line 393, in check_error
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     err.raise_mysql_exception(self._data)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   File "/usr/lib/python2.7/site-packages/pymysql/err.py", line 107, in raise_mysql_exception
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     raise errorclass(errno, errval)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager DBError: (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_4 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_4'] (Background on this error at: http://sqlalche.me/e/2j85)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager   DBError: (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_5 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_5'] (Background on this error at: http://sqlalche.me/e/2j85)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager     DBError: (pymysql.err.InternalError) (1305, u'SAVEPOINT sa_savepoint_6 does not exist') [SQL: u'ROLLBACK TO SAVEPOINT sa_savepoint_6'] (Background on this error at: http://sqlalche.me/e/2j85)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager       DBDeadlock: (pymysql.err.InternalError) (1213, u'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'UPDATE agents SET `load`=%(load)s WHERE agents.id = %(agents_id)s'] [parameters: {'load': 20, 'agents_id': u'5f976e47-3630-44cd-b518-8bd6245e5c07'}] (Background on this error at: http://sqlalche.me/e/2j85)
2018-04-15 15:02:00.452 35 ERROR neutron_lib.callbacks.manager

================================================================================


(overcloud) [stack@dhcp23-20 ansible]$ openstack network agent list
+--------------------------------------+----------------+-------------------------------------+-------------------+-------+-------+------------------------------+
| ID                                   | Agent Type     | Host                                | Availability Zone | Alive | State | Binary                       |
+--------------------------------------+----------------+-------------------------------------+-------------------+-------+-------+------------------------------+
| 126b2afb-8ae1-43f1-9dad-055eed4483ed | DHCP agent     | overcloud-controller-2.localdomain  | nova              | :-)   | UP    | neutron-dhcp-agent           |
| 175aa876-6bb2-465f-89a2-d30a6cfc8047 | Metadata agent | overcloud-controller-1.localdomain  | None              | :-)   | UP    | neutron-metadata-agent       |
| 1ba8d629-89d3-4c9e-820f-909979d6e53f | Metadata agent | overcloud-controller-0.localdomain  | None              | :-)   | UP    | neutron-metadata-agent       |
| 56524f65-8d0c-4434-98ee-1297cdc22b67 | ODL L2         | overcloud-controller-0.localdomain  | None              | :-)   | UP    | neutron-odlagent-portbinding |
| 5f976e47-3630-44cd-b518-8bd6245e5c07 | DHCP agent     | overcloud-controller-1.localdomain  | nova              | :-)   | UP    | neutron-dhcp-agent           |
| 65e2a374-432a-48dc-8853-d35ee1ba6291 | DHCP agent     | overcloud-controller-0.localdomain  | nova              | :-)   | UP    | neutron-dhcp-agent           |
| 7a4f5484-aabe-412f-8ee8-3d333ff6c5b0 | ODL L2         | overcloud-controller-1.localdomain  | None              | :-)   | UP    | neutron-odlagent-portbinding |
| 90e05942-cc7f-4510-b423-85726a553e54 | ODL L2         | overcloud-novacompute-1.localdomain | None              | :-)   | UP    | neutron-odlagent-portbinding |
| bf824396-e064-48c8-a069-8f59427db487 | ODL L2         | overcloud-novacompute-0.localdomain | None              | :-)   | UP    | neutron-odlagent-portbinding |
| c3dffcc6-2d7b-484f-92c6-c034a2a54e97 | Metadata agent | overcloud-controller-2.localdomain  | None              | :-)   | UP    | neutron-metadata-agent       |
| e1afe669-d054-45ca-9647-5a56484517cc | ODL L2         | overcloud-controller-2.localdomain  | None              | :-)   | UP    | neutron-odlagent-portbinding |
+--------------------------------------+----------------+-------------------------------------+-------------------+-------+-------+------------------------------+

Version-Release number of selected component (if applicable):
OSP 13
python-networking-odl-12.0.1-0.20180228140714.8733cf6.el7ost.noarch
opendaylight-8.0.0-5.el7ost.noarch

How reproducible: 100% at scale


Steps to Reproduce:
1. Install OSP 13
2. Run neutron scale tests
3.

Actual results:
DBExceptions

Expected results:
No exceptions

Additional info:

Comment 1 Assaf Muller 2018-04-16 11:45:12 UTC

1) Can you please attach sosreport of all controllers during active load and the occurrence of these exceptions?
2) Can you please describe what kind of workload were you running to cause these errors? (Preferably a link to the Rally scenarios including parameters and how you ran it).

Comment 2 Sai Sindhur Malleni 2018-04-24 19:14:39 UTC

Hey Assaf,

I don't have the environment available now however the tests I ran are here using Browbeat (which uses Rally).
https://github.com/openstack/browbeat/blob/master/browbeat-config.yaml#L144-L165

I ran the neutro ntests above with concurrencies of 8,16 and 32 and with times set to 500.

Comment 3 Assaf Muller 2018-04-25 13:59:35 UTC

I don't think a developer would be able to reproduce this easily, if you get the chance to reproduce this in the future on a environment could you ping a developer on the Networking DFG / Neutron squad so they'd be able to hop on the environment live?

Comment 4 Sai Sindhur Malleni 2018-04-25 17:31:04 UTC

Hey Assaf,

I did manage to reproduce it, here are the sosreports for the controllers (neutron was in debug)
http://elk.browbeatproject.org:9090/~smalleni/sosreports/


I also have a hunch this could be triggering https://bugzilla.redhat.com/show_bug.cgi?id=1571499

Comment 5 Sai Sindhur Malleni 2018-04-25 17:50:23 UTC

Actually, that link now has sosreports for the 3 controllers as well as the 6 computes. If you are only interested in controllers, look for the following files in the above link
sosreport-SaiMalleni-20180425124105.tar.xz
sosreport-SaiMalleni-20180425124134.tar.xz
sosreport-SaiMalleni-20180425124202.tar.xz

Comment 6 Assaf Muller 2018-05-21 13:42:49 UTC

We're trying to determine if this issue is related to 1571499, the one you linked in comment 4. Is it possible to workaround 1571499 and rerun the tests to see if you still see the Neutron DB exceptions? Maybe disable telemetry?

Comment 7 Miguel Angel Ajo 2018-06-07 07:53:36 UTC

This reminds me of issues we have seen in the past and that were recoverable messages of neutron talking to the database. (DB retries, etc..). But it deserves at least an investigation once we figure out what Assaf commented on 6.

Comment 8 Brian Haley 2018-08-24 20:57:06 UTC

Sai - I have not looked through the sosreports yet, but do you know if this is still reproducible after disabling telemetry?

Comment 12 Priscila 2019-04-24 17:17:52 UTC

Also, wouldn't https://review.opendev.org/#/c/326927/ fix it?

Comment 13 Nate Johnston 2019-04-29 13:53:11 UTC

Priscila, you reopened an existing bug that is for something unrelated.  Please create a new bug.  I am re-closing this bug now.

Comment 14 Priscila 2019-04-29 23:09:32 UTC

(In reply to Nate Johnston from comment #13)
> Priscila, you reopened an existing bug that is for something unrelated. 
> Please create a new bug.  I am re-closing this bug now.

Hi.

I opened https://bugzilla.redhat.com/show_bug.cgi?id=1704497

Note You need to log in before you can comment on or make changes to this bug.