Bug 2119199 - neutron does not catch revision number conflicts when updates occur in quick succession
Summary: neutron does not catch revision number conflicts when updates occur in quick ...
Keywords:
Status: CLOSED INSUFFICIENT_DATA
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-neutron
Version: 16.2 (Train)
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: ---
Assignee: Rodolfo Alonso
QA Contact: Eran Kuris
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-08-17 20:54 UTC by Andreas Karis
Modified: 2023-10-28 04:25 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2023-06-29 08:36:13 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker OSP-18248 0 None None None 2022-08-17 20:54:56 UTC

Description Andreas Karis 2022-08-17 20:54:23 UTC
Description of problem:

~~~
[root@standalone ~]# podman ps | grep neutron
c0f71c87753a  registry-proxy.engineering.redhat.com/rh-osbs/rhosp16-openstack-neutron-server-ovn:16.2_20220609.1          kolla_start           5 weeks ago  Up 5 weeks ago          neutron_api
8002f415d5c4  registry-proxy.engineering.redhat.com/rh-osbs/rhosp16-openstack-neutron-metadata-agent-ovn:16.2_20220609.1  kolla_start           5 weeks ago  Up 5 weeks ago          ovn_metadata_agent
0bc5974e8fb8  registry-proxy.engineering.redhat.com/rh-osbs/rhosp16-openstack-neutron-metadata-agent-ovn:16.2_20220609.1  /bin/bash -c HAPR...  5 weeks ago  Up 5 weeks ago          neutron-haproxy-ovnmeta-b9cfe6b5-831b-419c-bc25-49ba01a33c84
578bb7cab9d2  registry-proxy.engineering.redhat.com/rh-osbs/rhosp16-openstack-neutron-metadata-agent-ovn:16.2_20220609.1  /bin/bash -c HAPR...  4 weeks ago  Up 4 weeks ago          neutron-haproxy-ovnmeta-ed889e25-f8fa-4684-a9c4-54fff8de37b8
[root@standalone ~]# 
~~~

neutron's revision number handling for ports is broken. It doesn't catch conflicts for updates that happen with short delays:

Here's the client log (just because it's easier to read). The client sends 2 conflicting updates with revision number 131 in short succession, and both updates are accepted by neutron:
~~~
"PUT /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nContent-Length: 225\r\nAccept: application/json\r\nContent-Type: application/json\r\nIf-Match: revision_number=131\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n{\"port\":{\"allowed_address_pairs\":[{\"ip_address\":\"10.196.0.5\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.0.7\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.10.101\",\"mac_address\":\"fa:16:3e:fe:80:35\"}]}}
~~~

And:
~~~
"PUT /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nContent-Length: 225\r\nAccept: application/json\r\nContent-Type: application/json\r\nIf-Match: revision_number=131\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n{\"port\":{\"allowed_address_pairs\":[{\"ip_address\":\"10.196.0.5\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.0.7\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.10.100\",\"mac_address\":\"fa:16:3e:fe:80:35\"}]}}"
~~~

Full client log:
~~~
"GET /v2.0/ports?device_id=382c107f-a082-4e9b-8adb-2ba45323c479&device_owner=compute%3Anova HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9
dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n"
I0817 20:39:34.480120       1 controller.go:182] Assigning key: 10.196.10.101 to cloud-private-ip-config workqueue
I0817 20:39:34.484610       1 cloudprivateipconfig_controller.go:187] CloudPrivateIPConfig: "10.196.10.101" will be deleted from node: "ostest-lq27s-worker-0-cz6gw"
"GET /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3
PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n"
I0817 20:39:34.492376       1 controller.go:182] Assigning key: 10.196.10.101 to cloud-private-ip-config workqueue
"GET /v2.0/ports?device_id=382c107f-a082-4e9b-8adb-2ba45323c479&device_owner=compute%3Anova HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n""GET /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n"
I0817 20:39:34.586995       1 openstack.go:659]  ---- (10.196.10.100)----------- Running unallow, got port &{2ec4488a-35c2-4a14-adfb-a9ec3af61154 ed889e25-f8fa-4684-a9c4-54fff8de37b8 ostest-lq27s-worker-0-cz6gw-0 Created by cluster-api-provider-openstack cluster openshift-machine-api-ostest-lq27s true ACTIVE fa:16:3e:fe:80:35 [{ba4e5cdb-a0e3-47f2-9233-47d5a444412c 10.196.2.215}] 6f69c87fe95b469c8c7709382818acf6 6f69c87fe95b469c8c7709382818acf6 compute:nova [d426fa6b-74e1-4272-95c0-e7edd4978cef] 382c107f-a082-4e9b-8adb-2ba45323c479 [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.100 fa:16:3e:fe:80:35} {10.196.10.101 fa:16:3e:fe:80:35}] [cluster-api-provider-openstack openshift-machine-api-ostest-lq27s openshiftClusterID=ostest-lq27s] 131}
I0817 20:39:34.587033       1 openstack.go:660]  ---- (10.196.10.100)----------- Running unallow, got port revision number 131
I0817 20:39:34.587039       1 openstack.go:661]  ---- (10.196.10.100)----------- Running unallow, got port allowed address pairs [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.100 fa:16:3e:fe:80:35} {10.196.10.101 fa:16:3e:fe:80:35}]
I0817 20:39:34.587053       1 openstack.go:678]  ---- (10.196.10.100)----------- built new allowedPairs [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.101 fa:16:3e:fe:80:35}]
I0817 20:39:34.587063       1 openstack.go:687]  ---- (10.196.10.100)----------- sending update p.ID: 2ec4488a-35c2-4a14-adfb-a9ec3af61154, opts.AllowedAddressPairs: [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.101 fa:16:3e:fe:80:35}], opts.RevisionNumber: 131
"PUT /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nContent-Length: 225\r\nAccept: application/json\r\nContent-Type: application/json\r\nIf-Match: revision_number=131\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n{\"port\":{\"allowed_address_pairs\":[{\"ip_address\":\"10.196.0.5\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.0.7\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.10.101\",\"mac_address\":\"fa:16:3e:fe:80:35\"}]}}"
I0817 20:39:34.668150       1 openstack.go:659]  ---- (10.196.10.101)----------- Running unallow, got port &{2ec4488a-35c2-4a14-adfb-a9ec3af61154 ed889e25-f8fa-4684-a9c4-54fff8de37b8 ostest-lq27s-worker-0-cz6gw-0 Created by cluster-api-provider-openstack cluster openshift-machine-api-ostest-lq27s true ACTIVE fa:16:3e:fe:80:35 [{ba4e5cdb-a0e3-47f2-9233-47d5a444412c 10.196.2.215}] 6f69c87fe95b469c8c7709382818acf6 6f69c87fe95b469c8c7709382818acf6 compute:nova [d426fa6b-74e1-4272-95c0-e7edd4978cef] 382c107f-a082-4e9b-8adb-2ba45323c479 [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.100 fa:16:3e:fe:80:35} {10.196.10.101 fa:16:3e:fe:80:35}] [cluster-api-provider-openstack openshift-machine-api-ostest-lq27s openshiftClusterID=ostest-lq27s] 131}
I0817 20:39:34.668192       1 openstack.go:660]  ---- (10.196.10.101)----------- Running unallow, got port revision number 131
I0817 20:39:34.668201       1 openstack.go:661]  ---- (10.196.10.101)----------- Running unallow, got port allowed address pairs [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.100 fa:16:3e:fe:80:35} {10.196.10.101 fa:16:3e:fe:80:35}]
I0817 20:39:34.668216       1 openstack.go:678]  ---- (10.196.10.101)----------- built new allowedPairs [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.100 fa:16:3e:fe:80:35}]
I0817 20:39:34.668226       1 openstack.go:687]  ---- (10.196.10.101)----------- sending update p.ID: 2ec4488a-35c2-4a14-adfb-a9ec3af61154, opts.AllowedAddressPairs: [{10.196.0.5 fa:16:3e:fe:80:35} {10.196.0.7 fa:16:3e:fe:80:35} {10.196.10.100 fa:16:3e:fe:80:35}], opts.RevisionNumber: 131
"PUT /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nContent-Length: 225\r\nAccept: application/json\r\nContent-Type: application/json\r\nIf-Match: revision_number=131\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n{\"port\":{\"allowed_address_pairs\":[{\"ip_address\":\"10.196.0.5\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.0.7\",\"mac_address\":\"fa:16:3e:fe:80:35\"},{\"ip_address\":\"10.196.10.100\",\"mac_address\":\"fa:16:3e:fe:80:35\"}]}}"
I0817 20:39:35.613084       1 openstack.go:703]  ---- (10.196.10.100)----------- done with update, err: <nil>
"GET /v2.0/subnets?network_id=ed889e25-f8fa-4684-a9c4-54fff8de37b8 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n""GET /v2.0/ports?network_id=ed889e25-f8fa-4684-a9c4-54fff8de37b8 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n"
I0817 20:39:35.848105       1 openstack.go:703]  ---- (10.196.10.101)----------- done with update, err: <nil>
"GET /v2.0/subnets?network_id=ed889e25-f8fa-4684-a9c4-54fff8de37b8 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n""DELETE /v2.0/ports/dbcf5cf7-4bf4-4b1b-adb8-48db663dac0d HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n""GET /v2.0/ports?network_id=ed889e25-f8fa-4684-a9c4-54fff8de37b8 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n""DELETE /v2.0/ports/4de9645e-d49b-4f02-a873-186645e1ea23 HTTP/1.1\r\nHost: 10.1.8.109:13696\r\nUser-Agent: gophercloud/2.0.0\r\nAccept: application/json\r\nX-Auth-Token: gAAAAABi_VJdMWYkBokiAWe2dfR4bxiRddzESQ47nbMKHHDQq3P8lNCacfRNP0ugdNpCb3PLFhuD1S7HElmB2oizSyczoHTwWACQ9W1wZ1E-Ias9dx_9wqRGkZCHqO8DJ7qwAdk3zY776fgcbqvlnUf0V2yvpr4hHxwJ9_GFx3TKMeWSwpsCaS0\r\nAccept-Encoding: gzip\r\n\r\n"
I0817 20:39:36.753163       1 cloudprivateipconfig_controller.go:242] CloudPrivateIPConfig: 10.196.10.101 object has been marked for complete deletion
I0817 20:39:36.753210       1 cloudprivateipconfig_controller.go:249] Cleaning up IP address and finalizer for CloudPrivateIPConfig: "10.196.10.101", deleting it completely
I0817 20:39:36.764505       1 controller.go:160] Dropping key '10.196.10.101' from the cloud-private-ip-config workqueue
I0817 20:39:36.766042       1 controller.go:182] Assigning key: 10.196.10.101 to cloud-private-ip-config workqueue
I0817 20:39:36.768778       1 cloudprivateipconfig_controller.go:421] CloudPrivateIPConfig: "10.196.10.101" in work queue no longer exists
~~~

Here is the neutron log for that; it accepts both updates with revision number 131, and then bumps the revision to 132 and 133 respectively:
~~~
[root@standalone ~]# grep req-196744ef-304f-426e-9fa3-16137eafb0af /var/log/containers/neutron/server.log
2022-08-17 20:41:45.516 21 DEBUG neutron.api.v2.base [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Request body: {'port': {'allowed_address_pairs': [{'ip_address': '10.196.0.5', 'mac_address': 'fa:16:3e:fe:80:35'}, {'ip_address': '10.196.0.7', 'mac_address': 'fa:16:3e:fe:80:35'}, {'ip_address': '10.196.10.101', 'mac_address': 'fa:16:3e:fe:80:35'}]}} prepare_request_body /usr/lib/python3.6/site-packages/neutron/api/v2/base.py:719
2022-08-17 20:41:45.763 21 DEBUG neutron_lib.callbacks.manager [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.plugins.ml2.plugin.SecurityGroupDbMixin._ensure_default_security_group_handler-3170459', 'networking_ovn.l3.l3_ovn.OVNL3RouterPlugin._port_update--9223363258570713375'] for port, before_update _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.232 21 DEBUG neutron.plugins.ml2.db [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] For port 2ec4488a-35c2-4a14-adfb-a9ec3af61154, host standalone.shiftstack, got binding levels [PortBindingLevel(driver='ovn',host='standalone.shiftstack',level=0,port_id=2ec4488a-35c2-4a14-adfb-a9ec3af61154,segment=NetworkSegment(498d3767-87ec-4ae6-a7d0-0c315e928f01),segment_id=498d3767-87ec-4ae6-a7d0-0c315e928f01)] get_binding_level_objs /usr/lib/python3.6/site-packages/neutron/plugins/ml2/db.py:99
2022-08-17 20:41:46.284 21 DEBUG neutron_lib.callbacks.manager [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.services.qos.qos_plugin.QoSPlugin._validate_update_port_callback-687895'] for port, precommit_update _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.285 21 DEBUG networking_ovn.ml2.mech_driver [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] No provisioning block for port 2ec4488a-35c2-4a14-adfb-a9ec3af61154 since it is active _is_port_provisioning_required /usr/lib/python3.6/site-packages/networking_ovn/ml2/mech_driver.py:598
2022-08-17 20:41:46.287 21 DEBUG neutron_lib.callbacks.manager [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.plugins.ml2.plugin.SecurityGroupServerNotifierRpcMixin.notify_sg_on_port_change-3170336', 'neutron.plugins.ml2.extensions.dns_integration._update_port_in_external_dns_service-8778285656554', 'neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-1755367', 'neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification-14770236', 'neutron.db.l3_db.L3RpcNotifierMixin._notify_gateway_port_ip_changed--9223363258569049204', 'networking_ovn.l3.l3_ovn.OVNL3RouterPlugin._port_update--9223363258570713375', 'neutron.services.trunk.plugin.TrunkPlugin._trigger_trunk_status_change--9223372036854647104', 'neutron.services.segments.plugin.NovaSegmentNotifier._notify_port_updated--9223372036853128850', 'neutron.services.portforwarding.pf_plugin.PortForwardingPlugin._process_port_request-16707852', 'neutron.services.segments.plugin.NovaSegmentNotifier._notify_port_updated--9223372036839036187'] for port, after_update _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.324 21 DEBUG neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Network ed889e25-f8fa-4684-a9c4-54fff8de37b8 is not hosted by any dhcp agent _notify_agents /usr/lib/python3.6/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py:227
2022-08-17 20:41:46.384 21 DEBUG neutron.api.rpc.handlers.resources_rpc [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - - -] Pushing event updated for resources: {'Port': ['ID=2ec4488a-35c2-4a14-adfb-a9ec3af61154,revision_number=132']} push /usr/lib/python3.6/site-packages/neutron/api/rpc/handlers/resources_rpc.py:243
2022-08-17 20:41:46.439 21 DEBUG networking_ovn.common.ovn_client [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Parent port 2ec4488a-35c2-4a14-adfb-a9ec3af61154 found for virtual port dbcf5cf7-4bf4-4b1b-adb8-48db663dac0d _set_unset_virtual_port_type /usr/lib/python3.6/site-packages/networking_ovn/common/ovn_client.py:457
2022-08-17 20:41:46.523 21 INFO networking_ovn.db.revision [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Successfully bumped revision number for resource 2ec4488a-35c2-4a14-adfb-a9ec3af61154 (type: ports) to 132
2022-08-17 20:41:46.535 21 DEBUG neutron.pecan_wsgi.hooks.policy_enforcement [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Attributes excluded by policy engine: ['binding:profile', 'binding:host_id', 'binding:vif_type', 'binding:vif_details', 'resource_request'] _exclude_attributes_by_policy /usr/lib/python3.6/site-packages/neutron/pecan_wsgi/hooks/policy_enforcement.py:256
2022-08-17 20:41:46.535 21 DEBUG neutron_lib.callbacks.manager [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.notifiers.nova.Notifier._send_nova_notification-1632080'] for port, before_response _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.536 21 INFO neutron.wsgi [req-196744ef-304f-426e-9fa3-16137eafb0af 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] 192.168.24.1 "PUT /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1" status: 200  len: 1639 time: 1.0243335
~~~

~~~
[root@standalone ~]# grep req-460b66b3-5111-4822-b55e-f8bb3067bafb /var/log/containers/neutron/server.log
2022-08-17 20:41:45.597 26 DEBUG neutron.api.v2.base [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Request body: {'port': {'allowed_address_pairs': [{'ip_address': '10.196.0.5', 'mac_address': 'fa:16:3e:fe:80:35'}, {'ip_address': '10.196.0.7', 'mac_address': 'fa:16:3e:fe:80:35'}, {'ip_address': '10.196.10.100', 'mac_address': 'fa:16:3e:fe:80:35'}]}} prepare_request_body /usr/lib/python3.6/site-packages/neutron/api/v2/base.py:719
2022-08-17 20:41:45.846 26 DEBUG neutron_lib.callbacks.manager [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.plugins.ml2.plugin.SecurityGroupDbMixin._ensure_default_security_group_handler-3170459', 'networking_ovn.l3.l3_ovn.OVNL3RouterPlugin._port_update--9223363258570713375'] for port, before_update _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.398 26 DEBUG neutron.plugins.ml2.db [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] For port 2ec4488a-35c2-4a14-adfb-a9ec3af61154, host standalone.shiftstack, got binding levels [PortBindingLevel(driver='ovn',host='standalone.shiftstack',level=0,port_id=2ec4488a-35c2-4a14-adfb-a9ec3af61154,segment=NetworkSegment(498d3767-87ec-4ae6-a7d0-0c315e928f01),segment_id=498d3767-87ec-4ae6-a7d0-0c315e928f01)] get_binding_level_objs /usr/lib/python3.6/site-packages/neutron/plugins/ml2/db.py:99
2022-08-17 20:41:46.455 26 DEBUG neutron_lib.callbacks.manager [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.services.qos.qos_plugin.QoSPlugin._validate_update_port_callback-687895'] for port, precommit_update _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.456 26 DEBUG networking_ovn.ml2.mech_driver [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] No provisioning block for port 2ec4488a-35c2-4a14-adfb-a9ec3af61154 since it is active _is_port_provisioning_required /usr/lib/python3.6/site-packages/networking_ovn/ml2/mech_driver.py:598
2022-08-17 20:41:46.459 26 DEBUG neutron_lib.callbacks.manager [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.plugins.ml2.plugin.SecurityGroupServerNotifierRpcMixin.notify_sg_on_port_change-3170336', 'neutron.plugins.ml2.extensions.dns_integration._update_port_in_external_dns_service-8778285656554', 'neutron.plugins.ml2.ovo_rpc._ObjectChangeHandler.handle_event-1755367', 'neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api.DhcpAgentNotifyAPI._native_event_send_dhcp_notification-14770236', 'neutron.db.l3_db.L3RpcNotifierMixin._notify_gateway_port_ip_changed--9223363258569049204', 'networking_ovn.l3.l3_ovn.OVNL3RouterPlugin._port_update--9223363258570713375', 'neutron.services.trunk.plugin.TrunkPlugin._trigger_trunk_status_change--9223372036854647104', 'neutron.services.segments.plugin.NovaSegmentNotifier._notify_port_updated--9223372036853128850', 'neutron.services.portforwarding.pf_plugin.PortForwardingPlugin._process_port_request-16707852', 'neutron.services.segments.plugin.NovaSegmentNotifier._notify_port_updated-15298048'] for port, after_update _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.520 26 DEBUG neutron.api.rpc.agentnotifiers.dhcp_rpc_agent_api [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Network ed889e25-f8fa-4684-a9c4-54fff8de37b8 is not hosted by any dhcp agent _notify_agents /usr/lib/python3.6/site-packages/neutron/api/rpc/agentnotifiers/dhcp_rpc_agent_api.py:227
2022-08-17 20:41:46.561 26 DEBUG neutron.api.rpc.handlers.resources_rpc [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - - -] Pushing event updated for resources: {'Port': ['ID=2ec4488a-35c2-4a14-adfb-a9ec3af61154,revision_number=133']} push /usr/lib/python3.6/site-packages/neutron/api/rpc/handlers/resources_rpc.py:243
2022-08-17 20:41:46.632 26 DEBUG networking_ovn.common.ovn_client [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Parent port 2ec4488a-35c2-4a14-adfb-a9ec3af61154 found for virtual port dbcf5cf7-4bf4-4b1b-adb8-48db663dac0d _set_unset_virtual_port_type /usr/lib/python3.6/site-packages/networking_ovn/common/ovn_client.py:457
2022-08-17 20:41:46.683 26 DEBUG networking_ovn.common.ovn_client [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Parent port 2ec4488a-35c2-4a14-adfb-a9ec3af61154 found for virtual port 4de9645e-d49b-4f02-a873-186645e1ea23 _set_unset_virtual_port_type /usr/lib/python3.6/site-packages/networking_ovn/common/ovn_client.py:457
2022-08-17 20:41:46.758 26 INFO networking_ovn.db.revision [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Successfully bumped revision number for resource 2ec4488a-35c2-4a14-adfb-a9ec3af61154 (type: ports) to 133
2022-08-17 20:41:46.769 26 DEBUG neutron.pecan_wsgi.hooks.policy_enforcement [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Attributes excluded by policy engine: ['binding:profile', 'binding:host_id', 'binding:vif_type', 'binding:vif_details', 'resource_request'] _exclude_attributes_by_policy /usr/lib/python3.6/site-packages/neutron/pecan_wsgi/hooks/policy_enforcement.py:256
2022-08-17 20:41:46.770 26 DEBUG neutron_lib.callbacks.manager [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Notify callbacks ['neutron.notifiers.nova.Notifier._send_nova_notification-1632080'] for port, before_response _notify_loop /usr/lib/python3.6/site-packages/neutron_lib/callbacks/manager.py:193
2022-08-17 20:41:46.771 26 INFO neutron.wsgi [req-460b66b3-5111-4822-b55e-f8bb3067bafb 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] 192.168.24.1 "PUT /v2.0/ports/2ec4488a-35c2-4a14-adfb-a9ec3af61154 HTTP/1.1" status: 200  len: 1639 time: 1.1779168
~~~

I do know for a fact that the revision number conflict detection does work from time to time because sometimes it does show up in the logs:
~~~
2022-08-17 19:49:44.221 22 INFO networking_ovn.db.revision [req-7d32fd8e-4732-4bb4-ab12-3635a0ec334e 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Successfully bumped revision number for resource 2e
c4488a-35c2-4a14-adfb-a9ec3af61154 (type: ports) to 98
2022-08-17 19:49:44.222 16 ERROR ovsdbapp.backend.ovs_idl.transaction [req-c14b8ded-600b-45f5-bfe1-bb0e1596f9a7 3c88c234ba004865bbae69a2a28f0dfe 6f69c87fe95b469c8c7709382818acf6 - default default] Traceback (most recent call last):
  File "/usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/connection.py", line 130, in run
    txn.results.put(txn.do_commit())
  File "/usr/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py", line 91, in do_commit
    command.run_idl(txn)
  File "/usr/lib/python3.6/site-packages/networking_ovn/ovsdb/commands.py", line 938, in run_idl
    resource_id=self.name, resource_type=self.resource_type)
networking_ovn.common.exceptions.RevisionConflict: OVN revision number for 2ec4488a-35c2-4a14-adfb-a9ec3af61154 (type: ports) is equal or higher than the given resource. Skipping update
~~~




Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 20 Red Hat Bugzilla 2023-10-28 04:25:08 UTC
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 120 days


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