DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'DELETE FROM ipallocationpools WHERE ipallocationpools.id

[Matt Riedemann]

http://logs.openstack.org/78/163978/1/check/check-tempest-dsvm-neutron-full/792a4e4/logs/screen-q-svc.txt.gz?level=TRACE#_2015-03-13_16_07_36_406

2015-03-13 16:07:36.406 ERROR oslo_messaging.rpc.dispatcher [req-d42b66e6-5ee7-4e08-b59d-318aebfe92d7 None None] Exception during message handling: UPDATE statement on table 'ports' expected to update 1 row(s); 0 were matched.
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher Traceback (most recent call last):
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 142, in _dispatch_and_reply
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher executor_callback))
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 186, in _dispatch
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher executor_callback)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 130, in _do_dispatch
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher result = func(ctxt, **new_args)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/plugins/ml2/rpc.py", line 118, in get_devices_details_list
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher for device in kwargs.pop('devices', [])
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/plugins/ml2/rpc.py", line 95, in get_device_details
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher host)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py", line 1255, in update_port_status
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher original_port['network_id'])
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/plugins/ml2/plugin.py", line 642, in get_network
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher result = super(Ml2Plugin, self).get_network(context, id, None)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 915, in get_network
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher network = self._get_network(context, id)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/db/db_base_plugin_v2.py", line 87, in _get_network
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher network = self._get_by_id(context, models_v2.Network, id)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/opt/stack/new/neutron/neutron/db/common_db_mixin.py", line 130, in _get_by_id
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher return query.filter(model.id == id).one()
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2398, in one
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher ret = list(self)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2440, in __iter__
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher self.session._autoflush()
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1264, in _autoflush
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher self.flush()
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 1985, in flush
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher self._flush(objects)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2103, in _flush
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher transaction.rollback(_capture_exception=True)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher compat.reraise(exc_type, exc_value, exc_tb)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/session.py", line 2067, in _flush
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher flush_context.execute()
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher rec.execute(self)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/unitofwork.py", line 526, in execute
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher uow
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 60, in save_obj
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher mapper, table, update)
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher File "/usr/local/lib/python2.7/dist-packages/sqlalchemy/orm/persistence.py", line 536, in _emit_update_statements
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher (table.description, len(update), rows))
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher StaleDataError: UPDATE statement on table 'ports' expected to update 1 row(s); 0 were matched.
2015-03-13 16:07:36.406 22946 TRACE oslo_messaging.rpc.dispatcher

Looks like this just started spiking in the last 24 hours:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiU3RhbGVEYXRhRXJyb3I6IFVQREFURSBzdGF0ZW1lbnQgb24gdGFibGUgJ3BvcnRzJyBleHBlY3RlZCB0byB1cGRhdGUgMSByb3cocyk7IDAgd2VyZSBtYXRjaGVkLlwiIEFORCB0YWdzOlwic2NyZWVuLXEtc3ZjLnR4dFwiIiwiZmllbGRzIjpbXSwib2Zmc2V0IjowLCJ0aW1lZnJhbWUiOiI2MDQ4MDAiLCJncmFwaG1vZGUiOiJjb3VudCIsInRpbWUiOnsidXNlcl9pbnRlcnZhbCI6MH0sInN0YW1wIjoxNDI2Mjg0NjA3MDUwfQ==

[Matt Riedemann (mriedem)]

Not sure if it would be related but oslo.db 1.7.0 was released yesterday:

https://pypi.python.org/pypi/oslo.db/1.7.0

[Matt Riedemann (mriedem)]

Looking at things that merged recently, this looks suspect:

https://review.openstack.org/#/c/149261/

[Matt Riedemann (mriedem)]

Also seeing this:

http://logs.openstack.org/78/163978/1/check/check-tempest-dsvm-neutron-full/792a4e4/logs/screen-q-svc.txt.gz?level=TRACE#_2015-03-13_16_14_02_595

[Matt Riedemann (mriedem)]

Ahh it's this:

http://logstash.openstack.org/#eyJzZWFyY2giOiJtZXNzYWdlOlwiREJEZWFkbG9jazogKE9wZXJhdGlvbmFsRXJyb3IpICgxMjEzLCAnRGVhZGxvY2sgZm91bmQgd2hlbiB0cnlpbmcgdG8gZ2V0IGxvY2s7IHRyeSByZXN0YXJ0aW5nIHRyYW5zYWN0aW9uJykgJ0RFTEVURSBGUk9NIGlwYWxsb2NhdGlvbnBvb2xzIFdIRVJFIGlwYWxsb2NhdGlvbnBvb2xzLmlkXCIgQU5EIHRhZ3M6XCJzY3JlZW4tcS1zdmMudHh0XCIiLCJmaWVsZHMiOltdLCJvZmZzZXQiOjAsInRpbWVmcmFtZSI6IjYwNDgwMCIsImdyYXBobW9kZSI6ImNvdW50IiwidGltZSI6eyJ1c2VyX2ludGVydmFsIjowfSwic3RhbXAiOjE0MjYyODUwOTMwNTN9

http://logs.openstack.org/78/163978/1/check/check-tempest-dsvm-neutron-full/792a4e4/logs/screen-q-svc.txt.gz?level=TRACE#_2015-03-13_16_15_21_786

Tempest fails when trying to cleanup resources because it hits that DBDeadlock error.

[Matt Riedemann (mriedem)]

e-r query: https://review.openstack.org/#/c/164358/

[Matt Riedemann (mriedem)]

Possible related fix: https://review.openstack.org/#/c/164363/