Policy target group deletion failing due to DBDeadlock

[Sireesha]

GBP version: openstack-neutron-gbp-2014.2.5~dev8-95.el7.noarch

Policy target group deletion is failing with DBDeadlock issue. This issue is not seen consistently, but observing it multiple times while running regression tests.

Snapshot of neutron server log:
-------------------------------------------------
2015-11-23 09:08:00.488 26976 INFO requests.packages.urllib3.connectionpool [-] Starting new HTTP connection (1): 10.30.120.52
2015-11-23 09:08:00.609 26976 ERROR gbpservice.neutron.services.grouppolicy.policy_driver_manager [-] Policy driver 'chain_mapping' failed in update_policy_target_group_postcommit
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager Traceback (most recent call last):
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/policy_driver_manager.py", line 119, in _call_on_drivers
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager getattr(driver.obj, method_name)(context)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return method(*args, **kwargs)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/drivers/chain_mapping.py", line 185, in update_policy_target_group_postcommit
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self._cleanup_redirect_action(context)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/drivers/chain_mapping.py", line 492, in _cleanup_redirect_action
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager ctx, ptg_chain.servicechain_instance_id)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/network/neutronv2/local_api.py", line 502, in _delete_servicechain_instance
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager 'servicechain_instance', sci_id, False)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/network/neutronv2/local_api.py", line 138, in _delete_resource
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager obj_deleter(context, resource_id)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return method(*args, **kwargs)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/plugin.py", line 135, in delete_servicechain_instance
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self._destroy_servicechain_nodes(context, destroyers)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/plugin.py", line 420, in _destroy_servicechain_nodes
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self.plumber.unplug_services(context, destroyers.values())
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/ne2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/node_plumbers/admin_owned_resources_apic_tscp.py", line 68, in unplug_services
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context, deployment)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/node_plumbers/traffic_stitching_plumber.py", line 135, in unplug_services
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self._delete_service_targets(context, part)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/plumber_base.py", line 118, in _delete_service_targets
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context.elevated(), pt.policy_target_id)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return method(*args, **kwargs)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/plugin.py", line 391, in delete_policy_target
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context, policy_target_id)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return method(*args, **kwargs)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/db/grouppolicy/group_policy_db.py", line 1164, in delete_policy_target
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context.session.delete(pt_db)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self.rollback()
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager compat.reraise(exc_type, exc_value, exc_tb)
utron/services/servicechain/plugins/ncp/node_plumbers/admin_owned_resources_apic_tscp.py", line 68, in unplug_services
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context, deployment)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/node_plumbers/traffic_stitching_plumber.py", line 135, in unplug_services
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self._delete_service_targets(context, part)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/servicechain/plugins/ncp/plumber_base.py", line 118, in _delete_service_targets
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context.elevated(), pt.policy_target_id)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return method(*args, **kwargs)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/plugin.py", line 391, in delete_policy_target
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context, policy_target_id)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return method(*args, **kwargs)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib/python2.7/site-packages/gbpservice/neutron/db/grouppolicy/group_policy_db.py", line 1164, in delete_policy_target
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context.session.delete(pt_db)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 470, in __exit__
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self.rollback()
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 60, in __exit__
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager compat.reraise(exc_type, exc_value, exc_tb)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 2001, in _flush
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager flush_context.execute()
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 372, in execute
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager rec.execute(self)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line 555, in execute
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager uow
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 117, in delete_obj
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager cached_connections, mapper, table, delete)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 694, in _emit_delete_statements
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager c = connection.execute(statement, del_objects)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 729, in execute
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return meth(self, multiparams, params)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 322, in _execute_on_connection
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager return connection._execute_clauseelement(self, multiparams, params)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager compiled_sql, distilled_params
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 958, in _execute_context
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1155, in _handle_dbapi_exception
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager util.raise_from_cause(newraise, exc_info)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager reraise(type(exception), exception, tb=exc_tb)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager context)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 436, in do_execute
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager cursor.execute(statement, parameters)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/MySQLdb/cursors.py", line 174, in execute
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager self.errorhandler(self, exc, value)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager File "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager raise errorclass, errorvalue
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager DBDeadlock: (OperationalError) (1213, 'Deadlock found when trying to get lock; try restarting transaction') 'DELETE FROM gp_policy_targets WHERE gp_policy_targets.id = %s' ('cd6e6fe4-d9f0-4e67-be38-d3710f157363',)
2015-11-23 09:08:00.609 26976 TRACE gbpservice.neutron.services.grouppolicy.policy_driver_manager
2015-11-23 09:08:00.613 26976 ERROR neutron.api.v2.resource [-] delete failed
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource Traceback (most recent call last):
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/resource.py", line 87, in resource
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource result = method(request=request, **args)
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/api/v2/base.py", line 476, in delete
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource obj_deleter(request.context, id, **kwargs)
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource return method(*args, **kwargs)
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/plugin.py", line 502, in delete_policy_target_group
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource 'consumed_policy_rule_sets': {}}})
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/neutron/common/log.py", line 34, in wrapper
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource return method(*args, **kwargs)
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/plugin.py", line 475, in update_policy_target_group
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource policy_context)
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/policy_driver_manager.py", line 166, in update_policy_target_group_postcommit
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource self._call_on_drivers("update_policy_target_group_postcommit", context)
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource File "/usr/lib/python2.7/site-packages/gbpservice/neutron/services/grouppolicy/policy_driver_manager.py", line 134, in _call_on_drivers
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource method=method_name
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource GroupPolicyDriverError: update_policy_target_group_postcommit failed.
2015-11-23 09:08:00.613 26976 TRACE neutron.api.v2.resource
2015-11-23 09:08:00.614 26976 INFO neutron.wsgi [-] 10.30.120.52 - - [23/Nov/2015 09:08:00] "DELETE /v2.0//grouppolicy/policy_target_groups/cfd74e8b-2c24-458f-9412-ad7e91d8fbd2.json HTTP/1.1" 500 335 12.524095

[Sireesha (sireesha-mandava)]

After sometime, when the same operation is tried deletion succeeds.

[Sumit Naiksatam (snaiksat)]

Can you please provide the sequence of operations which leads to this scenario?

[Sireesha (sireesha-mandava)]

As part of our automation tests, we perform service insertions and traffic validation for different service chains. After the service insertion, we clean up all the resources created in the below order

1) Delete members(policy targets) in the policy target groups(PTG).
2) Delete the provider and consumer PTGs
3) Delete PRS
4) Delete Policy rules
5) Delete actions and classifiers
6) Delete spec & node.

As part of step#2, we are sometimes seeing this issue while deleting PTGs.

[Magesh GV (magesh-gv)]

My suspicion is that in Juno deleting VM/ detaching interface deletes the neutron port. Apic mapping acts on this event and tries to delete the policy target. At the same time the plumber may also invoke the delete policy target api which results in deadlock if they both coincide

[Sumit Naiksatam (snaiksat)]

Sireesha, thanks for providing the steps.

Magesh, that is a good theory. However, based on the input provided by Sireesha, it seems that they are hitting the deadlock in Step 2 and not Step 1 (which would most likely be the outcome of what you are suggesting).

The most likely workaround to this would be something similar to what is being done in Nova:
https://review.openstack.org/#/c/22276

which essentially automates the retries.

Depending on how prevalent this issue is, some people in the team are of the opinion that the automated retry might not be warranted.

[Magesh GV (magesh-gv)]

Hi Sumit,

On further investigation, the issue only happens with the PTs created for Service VM (We attach and detach these interfaces on Nova VM). As part of PTG deletion, the chain is deleted and the Service PTs are unplugged from Nova. Nova interface detach is an asynchronous operation which returns success (Request Accepted) and we return immediately in our code after which the plumber tries to delete the PTs. At the same time Nova also tries to delete the Port.

We are having the deadlock if both the deletes came concurrently, whereas we have issue with Nova interface detach not happening if the plumber deletes the PTs before nova detach completes.

One more thing to note is this issue only occurs in Juno whereas is master, Nova does not delete the port that is not implicitly created by Nova.