Deadlock in update_port_precommit

[Shaun Crampton]

Saw the following traceback in a CI run (Ubuntu kilo). Calico's driver doesn't seem to be in the traceback.

2017-02-28 23:44:36.671 19759 ERROR neutron.api.v2.resource [req-58b493ae-3169-4cfd-aa66-2df110168956 ] create failed
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource Traceback (most recent call last):
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/resource.py", line 83, in resource
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource result = method(request=request, **args)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/base.py", line 464, in create
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource obj = obj_creator(request.context, **kwargs)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 131, in wrapper
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource return f(*args, **kwargs)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 988, in create_port
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource bound_context = self._bind_port_if_needed(mech_context)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 291, in _bind_port_if_needed
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource plugin_context, port_id, binding, bind_context)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 412, in _commit_port_binding
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self.mechanism_manager.update_port_precommit(cur_context)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self.gen.next()
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/contextlib.py", line 121, in nested
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource if exit(*exc):
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self.rollback()
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 467, in __exit__
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self.commit()
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 377, in commit
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self._prepare_impl()
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 357, in _prepare_impl
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self.session.flush()
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1919, in flush
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self._flush(objects)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2037, in _flush
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource transaction.rollback(_capture_exception=True)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2001, in _flush
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource flush_context.execute()
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource rec.execute(self)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource uow
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 65, in save_obj
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource mapper, table, insert)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 570, in _emit_insert_statements
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource execute(statement, multiparams)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 729, in execute
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource return meth(self, multiparams, params)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 322, in _execute_on_connection
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource return connection._execute_clauseelement(self, multiparams, params)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource compiled_sql, distilled_params
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 958, in _execute_context
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource context)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_db/sqlalchemy/compat/handle_error.py", line 261, in _handle_dbapi_exception
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource e, statement, parameters, cursor, context)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1155, in _handle_dbapi_exception
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource util.raise_from_cause(newraise, exc_info)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource reraise(type(exception), exception, tb=exc_tb)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource context)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 436, in do_execute
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource cursor.execute(statement, parameters)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource self.errorhandler(self, exc, value)
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource raise errorclass, errorvalue
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'INSERT INTO ml2_port_binding_levels (port_id, host, level, driver, segment_id) VALUES (%s, %s, %s, %s, %s)' ('8fe3d811-92d9-48dd-87c2-bd25b37e7fff', 'jenkins-fv-prb-1051-ubuntu-kilo-compute-node01', 0, 'calico', 'e2119c82-6e59-4258-87fb-2f3a0679cd07')
2017-02-28 23:44:36.671 19759 TRACE neutron.api.v2.resource

[Nell Jerram (neil-jerram)]

Another instance, with Kilo on Ubuntu:

2017-03-03 00:52:23.799 19437 WARNING networking_calico.plugins.ml2.drivers.calico.mech_calico [req-14b3e0a3-e85f-4107-8099-75ecc653892c ] Missing ports: set([])
2017-03-03 00:52:23.799 19437 WARNING networking_calico.plugins.ml2.drivers.calico.mech_calico [req-14b3e0a3-e85f-4107-8099-75ecc653892c ] Extra ports: set([u'e13902a4-eb8a-48d3-8214-10fd7da6b3e8'])
2017-03-03 00:52:25.398 19437 WARNING neutron.plugins.ml2.plugin [req-f2ae6591-69f9-428e-9305-1b2f62f6613c ] Port e13902a4-eb8a-48d3-8214-10fd7da6b3e8 updated up by agent not found
2017-03-03 00:52:28.063 19456 ERROR neutron.api.v2.resource [req-7d3cf55c-097d-4b57-ad60-e51edae1f901 ] create failed
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource Traceback (most recent call last):
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/resource.py", line 83, in resource
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource result = method(request=request, **args)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/base.py", line 464, in create
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource obj = obj_creator(request.context, **kwargs)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 131, in wrapper
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource return f(*args, **kwargs)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 970, in create_port
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource result, mech_context = self._create_port_db(context, port)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 944, in _create_port_db
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource result = super(Ml2Plugin, self).create_port(context, port)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/db/db_base_plugin_v2.py", line 1850, in create_port
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource context, ip_address, network_id, subnet_id, port_id)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource self.rollback()
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 467, in __exit__
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource self.commit()
2017-03-03 00:52:28.063 19456 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packag...

[Nell Jerram (neil-jerram)]

And another occurrence (again with Kilo on Ubuntu Trusty):

2017-03-03 12:07:31.212 19359 ERROR neutron.api.v2.resource [req-1537ba93-5ce8-443e-bfa9-cceb1c9a4039 ] create failed
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource Traceback (most recent call last):
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/resource.py", line 83, in resource
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource result = method(request=request, **args)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/api/v2/base.py", line 464, in create
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource obj = obj_creator(request.context, **kwargs)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/oslo_db/api.py", line 131, in wrapper
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource return f(*args, **kwargs)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 970, in create_port
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource result, mech_context = self._create_port_db(context, port)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/plugins/ml2/plugin.py", line 944, in _create_port_db
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource result = super(Ml2Plugin, self).create_port(context, port)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/neutron/db/db_base_plugin_v2.py", line 1850, in create_port
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource context, ip_address, network_id, subnet_id, port_id)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource self.rollback()
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource compat.reraise(exc_type, exc_value, exc_tb)
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 467, in __exit__
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource self.commit()
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 377, in commit
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource self._prepare_impl()
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 357, in _prepare_impl
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource self.session.flush()
2017-03-03 12:07:31.212 19359 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1919, in fl...