senlin

Deadlock was found when adding action depedency

Bug #1580416 reported by Yanyan Hu on 2016-05-11

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	senlin	Fix Released	High	Qiming Teng	senlin newton-1

Bug Description

Deadlock error happened when adding action dependency during cluster creation. This error happened occasionally.

2016-05-10 22:25:59.769 31832 ERROR senlin.engine.actions.base [req-73722bc4-d2d4-4a98-90c8-e2172cb9bdf5 28198ebf0e56421da7a54a9147d9c080 9afdd59e748542eebdb2160e7062bdb7 - - - None] Unexpected exception occurred during action CLUSTER_CREATE (7c58c8e9-8f1d-49d9-bd96-025a4fdb4665) execution: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'INSERT INTO dependency (id, depended, dependent) VALUES (%s, %s, %s)'] [parameters: ('768813b8-4040-485f-9862-f024afcd963e', '1eb51bc9-bfac-4eb6-b398-5d1765b3ca14', '7c58c8e9-8f1d-49d9-bd96-025a4fdb4665')]
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base Traceback (most recent call last):
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/engine/actions/base.py", line 518, in ActionProc
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base result, reason = action.execute()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/engine/actions/cluster_action.py", line 845, in execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base res, reason = self._execute(**kwargs)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/engine/actions/cluster_action.py", line 813, in _execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base result, reason = method()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/engine/actions/cluster_action.py", line 186, in do_create
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base result, reason = self._create_nodes(self.cluster.desired_capacity)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/engine/actions/cluster_action.py", line 151, in _create_nodes
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base db_api.dependency_add(self.context, [a for a in child], self.id)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/db/api.py", line 336, in dependency_add
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base return IMPL.dependency_add(context, depended, dependent)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/openstack_repo/openstack/senlin/senlin/db/sqlalchemy/api.py", line 906, in dependency_add
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base synchronize_session=False)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/query.py", line 3176, in update
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base update_op.exec_()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1125, in exec_
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base self._do_pre()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "<string>", line 1, in <lambda>
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 1163, in _do_pre
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base session._autoflush()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1305, in _autoflush
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base self.flush()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2027, in flush
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base self._flush(objects)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2145, in _flush
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base transaction.rollback(_capture_exception=True)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base compat.reraise(exc_type, exc_value, exc_tb)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 2109, in _flush
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base flush_context.execute()
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 373, in execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base rec.execute(self)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 532, in execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base uow
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 174, in save_obj
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base mapper, table, insert)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 800, in _emit_insert_statements
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base execute(statement, params)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 914, in execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base return meth(self, multiparams, params)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base return connection._execute_clauseelement(self, multiparams, params)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1010, in _execute_clauseelement
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base compiled_sql, distilled_params
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1146, in _execute_context
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base context)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1337, in _handle_dbapi_exception
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base util.raise_from_cause(newraise, exc_info)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 200, in raise_from_cause
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base reraise(type(exception), exception, tb=exc_tb)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1139, in _execute_context
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base context)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 450, in do_execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base cursor.execute(statement, parameters)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/MySQLdb/cursors.py", line 205, in execute
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base self.errorhandler(self, exc, value)
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base File "/home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base raise errorclass, errorvalue
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base DBDeadlock: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'INSERT INTO dependency (id, depended, dependent) VALUES (%s, %s, %s)'] [parameters: ('768813b8-4040-485f-9862-f024afcd963e', '1eb51bc9-bfac-4eb6-b398-5d1765b3ca14', '7c58c8e9-8f1d-49d9-bd96-025a4fdb4665')]
2016-05-10 22:25:59.769 31832 TRACE senlin.engine.actions.base
2016-05-10 22:26:00.118 31832 DEBUG oslo_messaging._drivers.amqpdriver [-] received message msg_id: 786376c3e9174e948eb57f04f842af6d reply to reply_e3fccdd46f5d41ab88fd47aed2c10575 __call__ /home/stack/huyanyan/python/virtualenv/SENLINENV/lib/python2.7/site-packages/oslo_messaging/_drivers/amqpdriver.py:201
2016-05-10 22:26:00.123 31831 INFO senlin.engine.event [req-828a2578-e219-422d-a5bf-12bb119ac06d 172fee46b32647f797b9dcb4e352f31a c85f512b8a8e46baa7cc8ad6b86f49d7 - - - None] tempest-created-node-761359952 [74df0834] NODE_CHECK - SUCCEEDED: Node status is ACTIVE.
2016-05-10 22:26:00.323 31832 ERROR senlin.engine.event [req-73722bc4-d2d4-4a98-90c8-e2172cb9bdf5 28198ebf0e56421da7a54a9147d9c080 9afdd59e748542eebdb2160e7062bdb7 - - - None] tempest-created-cluster-1702857632 [7b53a755] CLUSTER_CREATE - FAILED: (_mysql_exceptions.OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') [SQL: u'INSERT INTO dependency (id, depended, dependent) VALUES (%s, %s, %s)'] [parameters: ('768813b8-4040-485f-9862-f024afcd963e', '1eb51bc9-bfac-4eb6-b398-5d1765b3ca14', '7c58c8e9-8f1d-49d9-bd96-025a4fdb4665')]

Qiming Teng (tengqim) on 2016-05-18

Changed in senlin:
assignee:	nobody → Qiming Teng (tengqim)
importance:	Undecided → High
milestone:	none → newton-1
status:	New → Triaged

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-05-18: Fix proposed to senlin (master)

Fix proposed to branch: master
Review: https://review.openstack.org/318115

Changed in senlin:
status:	Triaged → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2016-05-19: Fix merged to senlin (master)

Reviewed: https://review.openstack.org/318115
Committed: https://git.openstack.org/cgit/openstack/senlin/commit/?id=1b16ba706c11f9c625fdf3427a276502357c274b
Submitter: Jenkins
Branch: master

commit 1b16ba706c11f9c625fdf3427a276502357c274b
Author: tengqm <email address hidden>
Date: Wed May 18 09:58:53 2016 -0400

Add DB retry decorator for DeadLock problem

This patch adds some retry logic so that DB APIs can be retried in face
of DeadLock situation.

Change-Id: I9cda0a355d9023e4872d342fdf58413c1a4cf6e6
Closes-Bug: 1580416

Changed in senlin:
status:	In Progress → Fix Released

Revision history for this message

Doug Hellmann (doug-hellmann) wrote on 2016-06-03: Fix included in openstack/senlin 2.0.0.0b1

This issue was fixed in the openstack/senlin 2.0.0.0b1 development milestone.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.