Race condition in OVN ml2 driver? (create_subnet_postcommit)

[Cédric OLLIVIER]

Detected on Functest Gates (OpenStack Train - devstack) [1]
It may been undetected via classical OpenStack Neutron Rally tasks because the tasks slightly differ:

   NeutronNetworks.create_and_delete_subnets:
     -
       args:
         network_create_args: {}
         subnet_cidr_start: "1.1.0.0/30"
         subnet_create_args: {}
         subnets_per_network: 1
       context:
         {% call user_context(tenants_amount, users_amount, use_existing_users) %}
+ network:
+ router: {}
         quotas:
           neutron:
             network: -1
             subnet: -1
         {% endcall %}
       runner:
         {{ constant_runner(concurrency=concurrency, times=iterations, is_smoke=smoke) }}
       sla:
         {{ no_failures_sla() }}

Here is the traceback:
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers oslo_db.exception.DBReferenceError: (pymysql.err.IntegrityError) (1452, 'Cannot add or update a child row: a foreign key constraint fails (`neutron`.`ipamallocations`, CONSTRAINT `ipamallocations_ibfk_1` FOREIGN KEY (`ipam_subnet_id`) REFERENCES `ipamsubnets` (`id`) ON DELETE CASCADE)')
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers [SQL: INSERT INTO ipamallocations (ip_address, status, ipam_subnet_id) VALUES (%(ip_address)s, %(status)s, %(ipam_subnet_id)s)]
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers [parameters: {'ip_address': '1.1.0.26', 'status': 'ALLOCATED', 'ipam_subnet_id': '11376b38-90f8-4f2c-87b3-c74076fe52b6'}]
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers (Background on this error at: http://sqlalche.me/e/gkpj)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers During handling of the above exception, another exception occurred:
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers Traceback (most recent call last):
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/plugins/ml2/managers.py", line 477, in _call_on_drivers
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers getattr(driver.obj, method_name)(context)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/networking-ovn/networking_ovn/ml2/mech_driver.py", line 408, in create_subnet_postcommit
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers context.network.current)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/networking-ovn/networking_ovn/common/ovn_client.py", line 2090, in create_subnet
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers self.update_metadata_port(context, network['id'])
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/networking-ovn/networking_ovn/common/ovn_client.py", line 2277, in update_metadata_port
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers metadata_port['id'], port)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/common/utils.py", line 685, in inner
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return f(self, context, *args, **kwargs)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py", line 233, in wrapped
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return method(*args, **kwargs)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py", line 139, in wrapped
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers setattr(e, '_RETRY_EXCEEDED', True)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers self.force_reraise()
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers six.reraise(self.type_, self.value, self.tb)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers raise value
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py", line 135, in wrapped
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return f(*args, **kwargs)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_db/api.py", line 154, in wrapper
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers ectxt.value = e.inner_exc
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers self.force_reraise()
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers six.reraise(self.type_, self.value, self.tb)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers raise value
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_db/api.py", line 142, in wrapper
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return f(*args, **kwargs)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py", line 183, in wrapped
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers LOG.debug("Retry wrapper got retriable exception: %s", e)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers self.force_reraise()
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers six.reraise(self.type_, self.value, self.tb)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers raise value
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py", line 179, in wrapped
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return f(*dup_args, **dup_kwargs)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/plugins/ml2/plugin.py", line 1691, in update_port
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers port)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/neutron_lib/db/api.py", line 233, in wrapped
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return method(*args, **kwargs)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/db/db_base_plugin_v2.py", line 1500, in update_port
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers new_port=new_port)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/db/ipam_backend_mixin.py", line 699, in update_port
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers new_port.get('mac_address'))
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/db/ipam_pluggable_backend.py", line 428, in update_port_with_ips
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers new_mac)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/db/ipam_pluggable_backend.py", line 378, in _update_ips_for_port
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers port, to_add)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/db/ipam_pluggable_backend.py", line 164, in _ipam_allocate_ips
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers "external system for %s", addresses)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers self.force_reraise()
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers six.reraise(self.type_, self.value, self.tb)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/usr/local/lib/python3.6/dist-packages/six.py", line 693, in reraise
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers raise value
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/db/ipam_pluggable_backend.py", line 138, in _ipam_allocate_ips
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers ip_address, subnet_id = ipam_allocator.allocate(ip_request)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/ipam/subnet_alloc.py", line 237, in allocate
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers return ipam_subnet.allocate(address_request), subnet_id
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers File "/opt/stack/neutron/neutron/ipam/drivers/neutrondb_ipam/driver.py", line 264, in allocate
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers subnet_id=self.subnet_manager.neutron_id)
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers neutron_lib.exceptions.SubnetNotFound: Subnet 0b29d26f-4055-405a-9f54-aa3b08d66c27 could not be found.
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers
Apr 08 10:53:57 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.plugin [None req-6c92966c-c01a-4d62-aec0-3ee05fd72a39 c_rally_25408a4d_OGTeHmFK c_rally_25408a4d_POyJg9Rk] mechanism_manager.create_subnet_postcommit failed, deleting subnet 'd1f816d0-2ec4-451a-b62f-83e09d48b4d1': neutron.plugins.ml2.common.exceptions.MechanismDriverError
Apr 08 10:56:56 pod4-node2 neutron-server[1583211]: ERROR neutron.plugins.ml2.managers [None req-160a27b6-ef5b-4a1d-a273-15d3a60a7088 c_rally_bd0e4080_MXokqHQ3 c_rally_bd0e4080_BiuyExzS] Mechanism driver 'ovn' failed in create_subnet_postcommit: neutron_lib.exceptions.SubnetNotFound: Subnet 85572311-bc3e-42d4-b77e-6fff2ed077ca could not be found.

[1] http://artifacts.opnfv.org/functest/O9YCUPRWNJO5/functest-ovn-opnfv-functest-benchmarking-jerma-rally_full-run-27/rally_full/rally_full.html

[Cédric OLLIVIER (m.col)]

opnfv@pod4-node2:/opt/stack/neutron$ git show
commit 7b406a832cec99a900f108a7480af96f57ca9c89 (HEAD -> stable/train, origin/stable/train)
Merge: 3e1c472cce 03e88cd72a
Author: Zuul <email address hidden>
Date: Fri Mar 27 22:42:55 2020 +0000

    Merge "DHCPv6 - Use addr6_list in dnsmasq" into stable/train

opnfv@pod4-node2:/opt/stack/networking-ovn$ git show
commit 4114bc5b8a135f46ba8da2bbc755fceaa148b547 (HEAD -> stable/train, origin/stable/train)
Merge: 3806faca 9479b528
Author: Zuul <email address hidden>
Date: Fri Apr 3 17:48:39 2020 +0000

    Merge "[OVN] Reduce the number of watched tables in MetadataProxyHandler" into stable/train

opnfv@pod4-node2:/opt/stack/ovn$ git show
commit 1d0c6732d0e49f7f89f5e6a00ac9cdf6d3117e8d (HEAD -> master, origin/master, origin/HEAD)
Author: Dumitru Ceara <email address hidden>
Date: Tue Mar 31 13:47:04 2020 +0200

    ovn-controller: Fix potential segfault with "virtual" port bindings.

    Even though ovn-controller tries to set port_binding->chassis to NULL
    every time port_binding->virtual_parent is set to NULL for bindings of
    type="virtual", there's no way to enforce that an operator doesn't
    manually clear the "virtual_parent" column in the Southbound database.

    In such scenario ovn-controller would crash because of trying to
    dereference the NULL port_binding->virtual_parent column.

    Add an extra check and release "virtual" port bindings that have
    "virtual_parent" NULL.

    Reported-at: https://bugzilla.redhat.com/1818844
    CC: Numan Siddique <email address hidden>
    Fixes: 054f4c85c413 ("Add a new logical switch port type - 'virtual'")
    Signed-off-by: Dumitru Ceara <email address hidden>
    Signed-off-by: Numan Siddique <email address hidden>

[Cédric OLLIVIER (m.col)]

bash-5.0# pip3 freeze |grep rally
rally==3.0.0
rally-openstack==1.7.1.dev21