neutron

[master][ml2-ovn] Multiple Unexpected exception in notify_loop: neutron_lib.exceptions.PortNotFound

Bug #2073567 reported by yatin
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
neutron
Fix Released
High
Miro Tomaska

Bug Description

Multiple traces can be seen in ovn job like below:-
Jul 18 19:35:46.623330 np0038010972 neutron-server[84540]: WARNING neutron.plugins.ml2.drivers.ovn.mech_driver.ovsdb.ovn_client [None req-fbcd2914-d4f5-4f87-a685-96f16cc4f5f2 None None] No port found with ID 40c61c6b-8569-4bbd-a71d-4bf9a0917d19: RuntimeError: No port found with ID 40c61c6b-8569-4bbd-a71d-4bf9a0917d19
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event [None req-fbcd2914-d4f5-4f87-a685-96f16cc4f5f2 None None] Unexpected exception in notify_loop: neutron_lib.exceptions.PortNotFound: Port 40c61c6b-8569-4bbd-a71d-4bf9a0917d19 could not be found.
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event Traceback (most recent call last):
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/db/db_base_plugin_common.py", line 295, in _get_port
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event port = model_query.get_by_id(context, models_v2.Port, id,
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/model_query.py", line 178, in get_by_id
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return query.filter(model.id == object_id).one()
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/orm/query.py", line 2778, in one
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return self._iter().one() # type: ignore
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/engine/result.py", line 1810, in one
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return self._only_one_row(
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/engine/result.py", line 752, in _only_one_row
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise exc.NoResultFound(
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event sqlalchemy.exc.NoResultFound: No row was found when one was required
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event During handling of the above exception, another exception occurred:
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event Traceback (most recent call last):
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/event.py", line 177, in notify_loop
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event match.run(event, row, updates)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/ovsdb_monitor.py", line 581, in run
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event port = self.driver._plugin.get_port(self.admin_context, row.name)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 223, in wrapped
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f_with_retry(*args, **kwargs,
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 137, in wrapped
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event with excutils.save_and_reraise_exception():
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 227, in __exit__
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event self.force_reraise()
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise self.value
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 135, in wrapped
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f(*args, **kwargs)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line 144, in wrapper
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event with excutils.save_and_reraise_exception() as ectxt:
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 227, in __exit__
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event self.force_reraise()
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise self.value
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line 142, in wrapper
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f(*args, **kwargs)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 183, in wrapped
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event with excutils.save_and_reraise_exception():
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 227, in __exit__
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event self.force_reraise()
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise self.value
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 181, in wrapped
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f(*dup_args, **dup_kwargs)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 998, in wrapper
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return fn(*args, **kwargs)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1626, in get_port
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event port = self._get_port(context, id, lazy_fields=lazy_fields)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 998, in wrapper
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return fn(*args, **kwargs)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/db/db_base_plugin_common.py", line 298, in _get_port
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise exceptions.PortNotFound(port_id=id)
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event neutron_lib.exceptions.PortNotFound: Port 40c61c6b-8569-4bbd-a71d-4bf9a0917d19 could not be found.
Jul 18 19:35:46.630294 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event [None req-fbcd2914-d4f5-4f87-a685-96f16cc4f5f2 None None] Unexpected exception in notify_loop: neutron_lib.exceptions.PortNotFound: Port 40c61c6b-8569-4bbd-a71d-4bf9a0917d19 could not be found.
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event Traceback (most recent call last):
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/db/db_base_plugin_common.py", line 295, in _get_port
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event port = model_query.get_by_id(context, models_v2.Port, id,
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/model_query.py", line 178, in get_by_id
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return query.filter(model.id == object_id).one()
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/orm/query.py", line 2778, in one
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return self._iter().one() # type: ignore
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/engine/result.py", line 1810, in one
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return self._only_one_row(
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/sqlalchemy/engine/result.py", line 752, in _only_one_row
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise exc.NoResultFound(
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event sqlalchemy.exc.NoResultFound: No row was found when one was required
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event During handling of the above exception, another exception occurred:
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event Traceback (most recent call last):
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/ovsdbapp/event.py", line 177, in notify_loop
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event match.run(event, row, updates)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/plugins/ml2/drivers/ovn/mech_driver/ovsdb/ovsdb_monitor.py", line 581, in run
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event port = self.driver._plugin.get_port(self.admin_context, row.name)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 223, in wrapped
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f_with_retry(*args, **kwargs,
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 137, in wrapped
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event with excutils.save_and_reraise_exception():
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 227, in __exit__
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event self.force_reraise()
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise self.value
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 135, in wrapped
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f(*args, **kwargs)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line 144, in wrapper
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event with excutils.save_and_reraise_exception() as ectxt:
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 227, in __exit__
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event self.force_reraise()
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise self.value
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/api.py", line 142, in wrapper
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f(*args, **kwargs)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 183, in wrapped
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event with excutils.save_and_reraise_exception():
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 227, in __exit__
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event self.force_reraise()
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise self.value
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py", line 181, in wrapped
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return f(*dup_args, **dup_kwargs)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 998, in wrapper
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return fn(*args, **kwargs)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1626, in get_port
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event port = self._get_port(context, id, lazy_fields=lazy_fields)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/data/venv/lib/python3.10/site-packages/oslo_db/sqlalchemy/enginefacade.py", line 998, in wrapper
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event return fn(*args, **kwargs)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event File "/opt/stack/neutron/neutron/db/db_base_plugin_common.py", line 298, in _get_port
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event raise exceptions.PortNotFound(port_id=id)
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event neutron_lib.exceptions.PortNotFound: Port 40c61c6b-8569-4bbd-a71d-4bf9a0917d19 could not be found.
Jul 18 19:35:46.637822 np0038010972 neutron-server[84540]: ERROR ovsdbapp.event

Sample Log:- https://f3720cbaa64e3cd59c51-f4d168cdb20f40841821e4b213645c0f.ssl.cf5.rackcdn.com/907313/25/check/neutron-tempest-plugin-ovn/9a6e468/controller/logs/screen-q-svc.txt

Can be seen any run of job neutron-tempest-plugin-ovn

Would be good to avoid polluting logs with such traces when port is no longer available. Only affects master as included as part of addition of new event in https://review.opendev.org/c/openstack/neutron/+/912349

Miro Tomaska (mtomaska)
Changed in neutron:
importance: Undecided → High
Miro Tomaska (mtomaska)
Changed in neutron:
assignee: nobody → Miro Tomaska (mtomaska)
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/+/925039

Changed in neutron:
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to neutron (master)

Reviewed: https://review.opendev.org/c/openstack/neutron/+/925039
Committed: https://opendev.org/openstack/neutron/commit/c1b88fc5f52283380261f4fdc1562ff56ea06a29
Submitter: "Zuul (22348)"
Branch: master

commit c1b88fc5f52283380261f4fdc1562ff56ea06a29
Author: Miro Tomaska <email address hidden>
Date: Fri Jul 26 10:50:40 2024 -0400

    Only query for port do not get directly

    It was observed in the tempest tests that the port could be already
    deleted by some other concurrent event when the `run` is called.
    This caused a flood of exception logs. Thus, with this patch we only
    query for the port and only update_router_port when the port was
    found.

    Closes-Bug: #2073567
    Change-Id: I54d027f7cb5014d296a99029cfa0a13a7800da0a

Changed in neutron:
status: In Progress → Fix Released
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.