1946262 – stale logical_swith_port in OVN NBDB after port got deleted from neutron DB

Bug 1946262 - stale logical_swith_port in OVN NBDB after port got deleted from neutron DB

Summary: stale logical_swith_port in OVN NBDB after port got deleted from neutron DB

Keywords:
Status:	CLOSED DUPLICATE of bug 1955545
Alias:	None
Product:	Red Hat OpenStack
Classification:	Red Hat
Component:	python-ovsdbapp
Sub Component:
Version:	16.1 (Train)
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	z7
Target Release:	16.1 (Train on RHEL 8.2)
Assignee:	Terry Wilson
QA Contact:	Toni Freger
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2021-04-05 15:34 UTC by anil venkata
Modified:	2023-01-20 10:14 UTC (History)
CC List:	17 users (show)
Fixed In Version:	python-ovsdbapp-0.17.4-1.20210505093301.el8ost
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2021-07-14 13:56:30 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
nova conductor log (4.03 MB, text/plain) 2021-04-05 15:40 UTC, anil venkata	no flags	Details
View All

Links
System	ID	Priority	Status	Summary	Last Updated
Launchpad	1922934	None	None	None	2021-04-07 16:32:12 UTC
OpenStack gerrit	785433	None	MERGED	Add an active wait in the "Backend.lookup"	2021-05-17 07:46:15 UTC
Red Hat Issue Tracker	OSP-1798	None	None	None	2022-08-30 11:58:07 UTC

Description anil venkata 2021-04-05 15:34:45 UTC

Description of problem:
Compute node failed to update port during vif plugging with below error

s.<locals>._sync.<locals>.query_driver_power_state_and_sync" :: held 0.548s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:339
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager [req-22be1cb5-a5f4-4a55-a66a-73e03b273557 c40f3cf142f940849dd9a194d2207eb6 8395558a804c4925b228208b173c8c1e - default default] Instance failed network setup after 1 attempt(s): neutronclient.common.exceptions.InternalServerError: Request Failed: internal server error while processing your request.
Neutron server returns request_ids: ['req-6a779bc6-1edf-4c4e-b0d7-3adbed93e274']
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager Traceback (most recent call last):
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/compute/manager.py", line 1692, in _allocate_network_async
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     resource_provider_mapping=resource_provider_mapping)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 1040, in allocate_for_instance
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     bind_host_id, requested_ports_dict)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 1169, in _update_ports_for_instance
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     vif.destroy()
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 220, in __exit__
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     self.force_reraise()
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/oslo_utils/excutils.py", line 196, in force_reraise
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     six.reraise(self.type_, self.value, self.tb)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/six.py", line 675, in reraise
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     raise value
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 1139, in _update_ports_for_instance
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     port_client, instance, port_id, port_req_body)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 511, in _update_port
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     port_response = port_client.update_port(port_id, port_req_body)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 121, in wrapper
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 808, in update_port
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     revision_number=revision_number)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 121, in wrapper
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 2399, in _update_resource
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     return self.put(path, **kwargs)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 121, in wrapper
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 363, in put
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     headers=headers, params=params)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     headers=headers, params=params)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 121, in wrapper
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 331, in retry_request
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     headers=headers, params=params)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 121, in wrapper
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 294, in do_request
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     self._handle_fault_response(status_code, replybody, resp)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/nova/network/neutronv2/api.py", line 121, in wrapper
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     ret = obj(*args, **kwargs)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 269, in _handle_fault_response
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     exception_handler_v20(status_code, error_body)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager   File "/usr/lib/python3.6/site-packages/neutronclient/v2_0/client.py", line 93, in exception_handler_v20
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager     request_ids=request_ids)
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager neutronclient.common.exceptions.InternalServerError: Request Failed: internal server error while processing your request.
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager Neutron server returns request_ids: ['req-6a779bc6-1edf-4c4e-b0d7-3adbed93e274']
2021-04-01 15:51:00.781 7 ERROR nova.compute.manager


as networking-ovn is unable to find the corresponding logical switch port

2021-04-01 15:50:58.958 32 DEBUG neutron.api.v2.base [req-6a779bc6-1edf-4c4e-b0d7-3adbed93e274 6431325621b04c168af1fd7a3cf528d8 d5543274db4d4322baffdb8e8c9a003c - default default] Request body: {'port': {'device_id': 'a1b0f829-59bd-4950-aed3-788d4464edf7', 'device_owner': 'compute:nova', 'binding:host_id': 'compute1029p-4.redhat.local', 'dns_name': 's-rally-417a3408-vfboyojs'}} prepare_request_body /usr/lib/python3.6/site-packages/neutron/api/v2/base.py:719
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers [req-6a779bc6-1edf-4c4e-b0d7-3adbed93e274 6431325621b04c168af1fd7a3cf528d8 d5543274db4d4322baffdb8e8c9a003c - default default] Mechanism driver 'ovn' failed in update_port_postcommit: ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find Logical_Switch_Port with name=97d18e89-223d-4e6b-b22b-eb1a70ac8e85
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers Traceback (most recent call last):
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers   File "/usr/lib/python3.6/site-packages/neutron/plugins/ml2/managers.py", line 477, in _call_on_drivers
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers     getattr(driver.obj, method_name)(context)
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers   File "/usr/lib/python3.6/site-packages/networking_ovn/ml2/mech_driver.py", line 660, in update_port_postcommit
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers     self._ovn_client.update_port(port, port_object=original_port)
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers   File "/usr/lib/python3.6/site-packages/networking_ovn/common/ovn_client.py", line 512, in update_port
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers     ovn_port = self._nb_idl.lookup('Logical_Switch_Port', port['id'])
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers   File "/usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/__init__.py", line 172, in lookup
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers     return self._lookup(table, record)
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers   File "/usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/__init__.py", line 215, in _lookup
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers     row = idlutils.row_by_value(self, rl.table, rl.column, record)
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers   File "/usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/idlutils.py", line 130, in row_by_value
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers     raise RowNotFound(table=table, col=column, match=match)
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers ovsdbapp.backend.ovs_idl.idlutils.RowNotFound: Cannot find Logical_Switch_Port with name=97d18e89-223d-4e6b-b22b-eb1a70ac8e85
2021-04-01 15:50:59.659 32 ERROR neutron.plugins.ml2.managers
2021-04-01 15:50:59.661 32 ERROR neutron.plugins.ml2.plugin [req-6a779bc6-1edf-4c4e-b0d7-3adbed93e274 6431325621b04c168af1fd7a3cf528d8 d5543274db4d4322baffdb8e8c9a003c - default default] mechanism_manager.update_port_postcommit failed for port 97d18e89-223d-4e6b-b22b-eb1a70ac8e85: neutron.plugins.ml2.common.exceptions.MechanismDriverError

Looks like this port is added later in OVN NBDB

2021-04-01 15:50:57.964 33 DEBUG neutron.db.db_base_plugin_common [req-02c44c96-e6b2-4de6-bb24-2646eb75084c c40f3cf142f940849dd9a194d2207eb6 8395558a804c4925b228208b173c8c1e - default default] Allocated IP 27.2.43.35 (ec0d6584-c644-4dcd-b989-bb5d09f417f0/f00f2309-440a-439c-b4b9-03a75ccaa454/97d18e89-223d-4e6b-b22b-eb1a70ac8e85) _store_ip_allocation /usr/lib/python3.6/site-packages/neutron/db/db_base_plugin_common.py:137
2021-04-01 15:50:58.643 33 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=0): AddLSwitchPortCommand(lport=97d18e89-223d-4e6b-b22b-eb1a70ac8e85, lswitch=neutron-ec0d6584-c644-4dcd-b989-bb5d09f417f0, may_exist=True, columns={'addresses': ['fa:16:3e:18:53:ee 27.2.43.35'], 'external_ids': {'neutron:port_name': '', 'neutron:device_id': 'a1b0f829-59bd-4950-aed3-788d4464edf7', 'neutron:project_id': '8395558a804c4925b228208b173c8c1e', 'neutron:cidrs': '27.2.43.35/24', 'neutron:device_owner': '', 'neutron:network_name': 'neutron-ec0d6584-c644-4dcd-b989-bb5d09f417f0', 'neutron:security_group_ids': '28adacbd-bb49-4145-8e1c-224cc1944c59', 'neutron:revision_number': '1'}, 'parent_name': [], 'tag': [], 'enabled': True, 'options': {'requested-chassis': ''}, 'type': '', 'port_security': ['fa:16:3e:18:53:ee 27.2.43.35'], 'dhcpv4_options': [UUID('3e2c719e-ac30-487c-abb5-fb1488bc9150')], 'dhcpv6_options': []}) do_commit /usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
2021-04-01 15:50:58.645 33 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=1): PgAddPortCommand(port_group=neutron_pg_drop, lsp=[<networking_ovn.ovsdb.commands.AddLSwitchPortCommand object at 0x7f6473c48080>], if_exists=False) do_commit /usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
2021-04-01 15:50:58.646 33 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=2): PgAddPortCommand(port_group=pg_28adacbd_bb49_4145_8e1c_224cc1944c59, lsp=[<networking_ovn.ovsdb.commands.AddLSwitchPortCommand object at 0x7f6473c48080>], if_exists=False) do_commit /usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
2021-04-01 15:50:58.647 33 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=3): QoSDelCommand(switch=neutron-ec0d6584-c644-4dcd-b989-bb5d09f417f0, conditions=[('direction', '=', 'to-lport'), ('priority', '=', 2002), ('match', '=', 'outport == "97d18e89-223d-4e6b-b22b-eb1a70ac8e85"')]) do_commit /usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84
2021-04-01 15:50:58.647 33 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=4): QoSDelCommand(switch=neutron-ec0d6584-c644-4dcd-b989-bb5d09f417f0, conditions=[('direction', '=', 'from-lport'), ('priority', '=', 2002), ('match', '=', 'inport == "97d18e89-223d-4e6b-b22b-eb1a70ac8e85"')]) do_commit /usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:84


Nova compute is deleting the port from that compute node (because of above failures) and rescheduling the VM on different compute node

2021-04-01 15:51:01.327 7 DEBUG nova.compute.utils [req-22be1cb5-a5f4-4a55-a66a-73e03b273557 c40f3cf142f940849dd9a194d2207eb6 8395558a804c4925b228208b173c8c1e - default default] [instance: a1b0f829-59bd-4950-aed3-788d4464edf7] InternalServerError notify_about_instance_usage /usr/lib/python3.6/site-packages/nova/compute/utils.py:431
2021-04-01 15:51:01.332 7 DEBUG nova.compute.manager [req-22be1cb5-a5f4-4a55-a66a-73e03b273557 c40f3cf142f940849dd9a194d2207eb6 8395558a804c4925b228208b173c8c1e - default default] [instance: a1b0f829-59bd-4950-aed3-788d4464edf7] Build of instance a1b0f829-59bd-4950-aed3-788d4464edf7 was re-scheduled: Request Failed: internal server error while processing your request.
2021-04-01 15:51:01.332 7 DEBUG nova.compute.manager [req-22be1cb5-a5f4-4a55-a66a-73e03b273557 c40f3cf142f940849dd9a194d2207eb6 8395558a804c4925b228208b173c8c1e - default default] [instance: a1b0f829-59bd-4950-aed3-788d4464edf7] Unplugging VIFs for instance _cleanup_allocated_networks /usr/lib/python3.6/site-packages/nova/compute/manager.py:2698
2021-04-01 15:51:01.633 7 INFO nova.compute.manager [req-22be1cb5-a5f4-4a55-a66a-73e03b273557 c40f3cf142f940849dd9a194d2207eb6 8395558a804c4925b228208b173c8c1e - default default] [instance: a1b0f829-59bd-4950-aed3-788d4464edf7] Took 0.06 seconds to deallocate network for instance.


We can see port 97d18e89-223d-4e6b-b22b-eb1a70ac8e85 still exists in OVN NBDB though it is deleted in neutron DB

()[root@controller-0 /]$ ovn-nbctl --bare --columns external_ids list logical_switch_port 97d18e89-223d-4e6b-b22b-eb1a70ac8e85
neutron:cidrs=27.2.43.35/24 neutron:device_id=a1b0f829-59bd-4950-aed3-788d4464edf7 neutron:device_owner= neutron:network_name=neutron-ec0d6584-c644-4dcd-b989-bb5d09f417f0 neutron:port_name= neutron:project_id=8395558a804c4925b228208b173c8c1e neutron:revision_number=1 neutron:security_group_ids=28adacbd-bb49-4145-8e1c-224cc1944c59

()[root@controller-0 /]$ ovn-nbctl --bare --columns external_ids list logical_switch_port 1e791699-137e-430b-bcb3-d57f0e9459e1
neutron:cidrs=27.2.43.32/24 neutron:device_id=a1b0f829-59bd-4950-aed3-788d4464edf7 neutron:device_owner=compute:nova neutron:network_name=neutron-ec0d6584-c644-4dcd-b989-bb5d09f417f0 neutron:port_name= neutron:project_id=8395558a804c4925b228208b173c8c1e neutron:revision_number=4 neutron:security_group_ids=28adacbd-bb49-4145-8e1c-224cc1944c59

(overcloud) [stack@undercloud ~]$ neutron port-list | grep 97d18e89-223d-4e6b-b22b-eb1a70ac8e85
neutron CLI is deprecated and will be removed in the future. Use openstack CLI instead.
(overcloud) [stack@undercloud ~]$ neutron port-list | grep 1e791699-137e-430b-bcb3-d57f0e9459e1
neutron CLI is deprecated and will be removed in the future. Use openstack CLI instead.
| 1e791699-137e-430b-bcb3-d57f0e9459e1 |      | 8395558a804c4925b228208b173c8c1e | fa:16:3e:10:76:29 | {"subnet_id": "f00f2309-440a-439c-b4b9-03a75ccaa454", "ip_address": "27.2.43.32"}  |

Comment 1 anil venkata 2021-04-05 15:40:10 UTC

Created attachment 1769300 [details]
nova conductor log

Comment 5 Rodolfo Alonso 2021-04-15 13:28:41 UTC

*** Bug 1949943 has been marked as a duplicate of this bug. ***

Comment 14 Jakub Libosvar 2021-07-14 13:56:30 UTC


*** This bug has been marked as a duplicate of bug 1955545 ***

Note You need to log in before you can comment on or make changes to this bug.