neutron

DB semantic violation seen in neutron-tempest-plugin-openvswitch logs deleting router

Bug #2074312 reported by Brian Haley
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
neutron
In Progress
Low
Brian Haley

Bug Description

While looking at logs for another issue I noticed this warning and traceback:

WARNING neutron.plugins.ml2.ovo_rpc [None req-14fa03ae-ce7a-4dfe-ad16-dbc556fcf002 admin admin] This handler is supposed to handle AFTER events, as in 'AFTER it's committed', not BEFORE. Offending resource event: port, after_delete. Location:
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/greenthread.py", line 265, in main
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: result = function(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/wsgi.py", line 869, in process_request
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: proto.__init__(conn_state, self)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/wsgi.py", line 359, in __init__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: self.handle()
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/wsgi.py", line 392, in handle
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: self.handle_one_request()
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/wsgi.py", line 488, in handle_one_request
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: self.handle_one_response()
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/eventlet/wsgi.py", line 598, in handle_one_response
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: result = self.application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/paste/urlmap.py", line 211, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return app(environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/base.py", line 124, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: response = req.get_response(self.application)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: status, headers, app_iter = self.call_application(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: app_iter = application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/base.py", line 124, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: response = req.get_response(self.application)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: status, headers, app_iter = self.call_application(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: app_iter = application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/request_id.py", line 58, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: response = req.get_response(self.application)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: status, headers, app_iter = self.call_application(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: app_iter = application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_middleware/catch_errors.py", line 40, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: response = req.get_response(self.application)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: status, headers, app_iter = self.call_application(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: app_iter = application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/osprofiler/web.py", line 111, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return request.get_response(self.application)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: status, headers, app_iter = self.call_application(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: app_iter = application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/keystonemiddleware/auth_token/__init__.py", line 340, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: response = req.get_response(self._app)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1313, in send
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: status, headers, app_iter = self.call_application(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/request.py", line 1278, in call_application
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: app_iter = application(self.environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 143, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return resp(environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 143, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return resp(environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/routes/middleware.py", line 153, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: response = self.app(environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 143, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return resp(environ, start_response)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 129, in __call__
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: resp = self.call_func(req, *args, **kw)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/webob/dec.py", line 193, in call_func
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self.func(req, *args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/api/v2/resource.py", line 97, in resource
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: result = method(request=request, **args)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/api/v2/base.py", line 578, in delete
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return self._delete(request, id, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 135, in wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line 142, in wrapper
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 181, in wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*dup_args, **dup_kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/api/v2/base.py", line 606, in _delete
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: obj_deleter(request.context, id, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/db/l3_db.py", line 2243, in delete_router
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: super(L3_NAT_db_mixin, self).delete_router(context, id)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 223, in wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f_with_retry(*args, **kwargs,
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 135, in wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line 142, in wrapper
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 181, in wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*dup_args, **dup_kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/db/l3_db.py", line 645, in delete_router
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: self._core_plugin.delete_port(context.elevated(), rp_id,
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/common/utils.py", line 723, in inner
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 221, in wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return f(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/plugins/ml2/plugin.py", line 2225, in delete_port
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: self._post_delete_port(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/plugins/ml2/plugin.py", line 2230, in _post_delete_port
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: registry.publish(resources.PORT, events.AFTER_DELETE, self,
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/callbacks/registry.py", line 56, in publish
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: _get_callback_manager().publish(resource, event, trigger, payload=payload)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/utils.py", line 104, in _wrapped
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: return function(*args, **kwargs)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/callbacks/manager.py", line 157, in publish
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: errors = self._notify_loop(resource, event, trigger, payload)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/callbacks/manager.py", line 189, in _notify_loop
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: callback.method(resource, event, trigger, payload=payload)
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/plugins/ml2/ovo_rpc.py", line 101, in handle_event
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: if self._is_session_semantic_violated(
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: File "/opt/stack/neutron/neutron/plugins/ml2/ovo_rpc.py", line 85, in _is_session_semantic_violated
Jul 16 13:58:21.657161 np0037990670 neutron-server[58960]: stack = traceback.extract_stack()

I realize the above could look ugly when wrapped, but in short this is coming from delete_router() when there are still ports associated with it. I've seen it in every run looking in controller/logs/screen-q-svc.txt, for example, here:

https://274c59a40e2543723248-8e40407516a8c23d7cf04400cc86fdf3.ssl.cf5.rackcdn.com/915370/8/check/neutron-tempest-plugin-openvswitch/ba21d08/controller/logs/screen-q-svc.txt

The one above happens twice per run, there's also a create_security_group() one I'll have to file another bug for.

While there is a note in the code:

    # TODO(ralonsoh): move this section (port deletion) out of the DB
    # transaction.

And what looks like the correct setting to disable the warning:

    if db_api.is_session_active(context.session):
        context.GUARD_TRANSACTION = False

And it looks like it is setting it on the context correctly, so unclear why the traceback is happening.

Not sure if we should just fix the TODO, but assume it's not simple or it might have been done already.

Tags: db
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to neutron (master)

Fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/neutron/+/925066

Changed in neutron:
status: New → In Progress
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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