test_add_router_interfaces_on_overlapping_subnets_returns_400 failed when retrying router interface removal after API timeout; (pymysql.err.OperationalError) (1205, 'Lock wait timeout exceeded; try restarting transaction') in neutron log

[Ihar Hrachyshka]

Failure here:

ft1.1: tempest.api.network.test_routers_negative.RoutersNegativeIpV6Test.test_add_router_interfaces_on_overlapping_subnets_returns_400[id-957751a3-3c68-4fa2-93b6-eb52ea10db6e,negative]testtools.testresult.real._StringException: pythonlogging:'': {{{
2024-09-30 18:50:09,236 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:test_add_router_interfaces_on_overlapping_subnets_returns_400): 201 POST https://[2001:41d0:302:1000::9e7]/networking/v2.0/networks 0.570s
2024-09-30 18:50:09,236 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"network": {"name": "tempest-router-network01--1466802867"}}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:50:08 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '573', 'x-openstack-request-id': 'req-289396ba-afdc-4dd9-8538-9a4213985b21', 'connection': 'close', 'status': '201', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/networks'}
        Body: b'{"network":{"id":"4a3d5446-c98b-4327-a0d3-62c2be199194","name":"tempest-router-network01--1466802867","tenant_id":"17e56b8c51624d2e910dea6995e4003f","admin_state_up":true,"mtu":1352,"status":"ACTIVE","subnets":[],"shared":false,"project_id":"17e56b8c51624d2e910dea6995e4003f","port_security_enabled":true,"router:external":false,"is_default":false,"availability_zone_hints":[],"availability_zones":[],"ipv4_address_scope":null,"ipv6_address_scope":null,"description":"","tags":[],"created_at":"2024-09-30T18:50:08Z","updated_at":"2024-09-30T18:50:08Z","revision_number":1}}'
2024-09-30 18:50:09,844 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:test_add_router_interfaces_on_overlapping_subnets_returns_400): 201 POST https://[2001:41d0:302:1000::9e7]/networking/v2.0/networks 0.607s
2024-09-30 18:50:09,845 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"network": {"name": "tempest-router-network02--2017064160"}}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:50:09 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '573', 'x-openstack-request-id': 'req-73800b2e-ef0a-4591-9f41-1d41c0766d63', 'connection': 'close', 'status': '201', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/networks'}
        Body: b'{"network":{"id":"a2a0b2fb-5643-492e-937a-795142d160a0","name":"tempest-router-network02--2017064160","tenant_id":"17e56b8c51624d2e910dea6995e4003f","admin_state_up":true,"mtu":1352,"status":"ACTIVE","subnets":[],"shared":false,"project_id":"17e56b8c51624d2e910dea6995e4003f","port_security_enabled":true,"router:external":false,"is_default":false,"availability_zone_hints":[],"availability_zones":[],"ipv4_address_scope":null,"ipv6_address_scope":null,"description":"","tags":[],"created_at":"2024-09-30T18:50:09Z","updated_at":"2024-09-30T18:50:09Z","revision_number":1}}'
2024-09-30 18:50:10,214 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:test_add_router_interfaces_on_overlapping_subnets_returns_400): 201 POST https://[2001:41d0:302:1000::9e7]/networking/v2.0/subnets 0.368s
2024-09-30 18:50:10,214 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"subnet": {"network_id": "4a3d5446-c98b-4327-a0d3-62c2be199194", "cidr": "2001:db8::/64", "ip_version": 6, "gateway_ip": "2001:db8::1"}}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:50:09 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '646', 'x-openstack-request-id': 'req-15bb4af0-20fd-4264-acaf-5a42ac72e5e7', 'connection': 'close', 'status': '201', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/subnets'}
        Body: b'{"subnet":{"id":"e431775b-293e-45fd-90b9-2453400019ce","name":"","tenant_id":"17e56b8c51624d2e910dea6995e4003f","network_id":"4a3d5446-c98b-4327-a0d3-62c2be199194","ip_version":6,"subnetpool_id":null,"enable_dhcp":true,"ipv6_ra_mode":null,"ipv6_address_mode":null,"gateway_ip":"2001:db8::1","cidr":"2001:db8::/64","allocation_pools":[{"start":"2001:db8::2","end":"2001:db8::ffff:ffff:ffff:ffff"}],"host_routes":[],"dns_nameservers":[],"description":"","router:external":false,"service_types":[],"tags":[],"created_at":"2024-09-30T18:50:10Z","updated_at":"2024-09-30T18:50:10Z","revision_number":0,"project_id":"17e56b8c51624d2e910dea6995e4003f"}}'
2024-09-30 18:50:10,522 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:test_add_router_interfaces_on_overlapping_subnets_returns_400): 201 POST https://[2001:41d0:302:1000::9e7]/networking/v2.0/subnets 0.307s
2024-09-30 18:50:10,523 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"subnet": {"network_id": "a2a0b2fb-5643-492e-937a-795142d160a0", "cidr": "2001:db8::/64", "ip_version": 6, "gateway_ip": "2001:db8::1"}}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:50:10 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '646', 'x-openstack-request-id': 'req-f647cf8f-4d5a-4ea3-8378-59f3d2d4a7cd', 'connection': 'close', 'status': '201', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/subnets'}
        Body: b'{"subnet":{"id":"6fa7a9fe-acc5-433a-8e4f-08f5f5930879","name":"","tenant_id":"17e56b8c51624d2e910dea6995e4003f","network_id":"a2a0b2fb-5643-492e-937a-795142d160a0","ip_version":6,"subnetpool_id":null,"enable_dhcp":true,"ipv6_ra_mode":null,"ipv6_address_mode":null,"gateway_ip":"2001:db8::1","cidr":"2001:db8::/64","allocation_pools":[{"start":"2001:db8::2","end":"2001:db8::ffff:ffff:ffff:ffff"}],"host_routes":[],"dns_nameservers":[],"description":"","router:external":false,"service_types":[],"tags":[],"created_at":"2024-09-30T18:50:10Z","updated_at":"2024-09-30T18:50:10Z","revision_number":0,"project_id":"17e56b8c51624d2e910dea6995e4003f"}}'
2024-09-30 18:50:11,946 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:test_add_router_interfaces_on_overlapping_subnets_returns_400): 200 PUT https://[2001:41d0:302:1000::9e7]/networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/add_router_interface 1.422s
2024-09-30 18:50:11,946 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"subnet_id": "e431775b-293e-45fd-90b9-2453400019ce"}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:50:10 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '309', 'x-openstack-request-id': 'req-bca5466d-611f-4033-805c-10fb91a8beac', 'connection': 'close', 'status': '200', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/add_router_interface'}
        Body: b'{"id": "a1897b1f-7220-4ab7-9e42-c07e2bf73450", "tenant_id": "17e56b8c51624d2e910dea6995e4003f", "port_id": "aea79fab-2aae-4bf2-ae30-7d0232533f82", "network_id": "4a3d5446-c98b-4327-a0d3-62c2be199194", "subnet_id": "e431775b-293e-45fd-90b9-2453400019ce", "subnet_ids": ["e431775b-293e-45fd-90b9-2453400019ce"]}'
2024-09-30 18:50:12,461 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:test_add_router_interfaces_on_overlapping_subnets_returns_400): 400 PUT https://[2001:41d0:302:1000::9e7]/networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/add_router_interface 0.514s
2024-09-30 18:50:12,462 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"subnet_id": "6fa7a9fe-acc5-433a-8e4f-08f5f5930879"}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:50:11 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '235', 'x-openstack-request-id': 'req-401abb6e-144f-4c44-a14e-a6ce507041af', 'connection': 'close', 'status': '400', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/add_router_interface'}
        Body: b'{"NeutronError": {"type": "BadRequest", "message": "Bad router request: Cidr 2001:db8::/64 of subnet 6fa7a9fe-acc5-433a-8e4f-08f5f5930879 overlaps with cidr 2001:db8::/64 of subnet e431775b-293e-45fd-90b9-2453400019ce.", "detail": ""}}'
2024-09-30 18:51:42,533 75502 WARNING [urllib3.connectionpool] Retrying (Retry(total=9, connect=None, read=None, redirect=5, status=None)) after connection broken by 'ReadTimeoutError("HTTPSConnectionPool(host='2001:41d0:302:1000::9e7', port=443): Read timed out. (read timeout=90)")': /networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/remove_router_interface
2024-09-30 18:51:42,945 75502 INFO [tempest.lib.common.rest_client] Request (RoutersNegativeIpV6Test:_run_cleanups): 404 PUT https://[2001:41d0:302:1000::9e7]/networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/remove_router_interface 90.482s
2024-09-30 18:51:42,945 75502 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Content-Type': 'application/json', 'Accept': 'application/json', 'X-Auth-Token': '<omitted>'}
        Body: {"subnet_id": "e431775b-293e-45fd-90b9-2453400019ce"}
    Response - Headers: {'date': 'Mon, 30 Sep 2024 18:51:42 GMT', 'server': 'Apache/2.4.52 (Ubuntu)', 'content-type': 'application/json', 'content-length': '198', 'x-openstack-request-id': 'req-2c7dfc18-f1df-48a4-a39b-13538ddbfab0', 'connection': 'close', 'status': '404', 'content-location': 'https://[2001:41d0:302:1000::9e7]/networking/v2.0/routers/a1897b1f-7220-4ab7-9e42-c07e2bf73450/remove_router_interface'}
        Body: b'{"NeutronError": {"type": "RouterInterfaceNotFoundForSubnet", "message": "Router a1897b1f-7220-4ab7-9e42-c07e2bf73450 has no interface on subnet e431775b-293e-45fd-90b9-2453400019ce", "detail": ""}}'
}}}

Traceback (most recent call last):
  File "/opt/stack/tempest/tempest/lib/services/network/routers_client.py", line 82, in remove_router_interface
    return self.update_resource(uri, kwargs)
  File "/opt/stack/tempest/tempest/lib/services/network/base.py", line 77, in update_resource
    resp, body = self.put(req_uri, req_post_data)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 392, in put
    return self.request('PUT', url, extra_headers, headers, body, chunked)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 762, in request
    self._error_checker(resp, resp_body)
  File "/opt/stack/tempest/tempest/lib/common/rest_client.py", line 872, in _error_checker
    raise exceptions.NotFound(resp_body, resp=resp)
tempest.lib.exceptions.NotFound: Object not found
Details: {'type': 'RouterInterfaceNotFoundForSubnet', 'message': 'Router a1897b1f-7220-4ab7-9e42-c07e2bf73450 has no interface on subnet e431775b-293e-45fd-90b9-2453400019ce', 'detail': ''}

The test scenario attempts to clean up the subnet interface from a router. First attempt fails; it retries - but the interface is gone (it was actually removed by neutron-server from db).

In logs, the failed request can be traced: https://7a5854cdc73e90042b49-88701ef6bf8de11ee3b199ef1b631f6f.ssl.cf5.rackcdn.com/927634/4/gate/neutron-ovn-tempest-ipv6-only-ovs-release/bec43f6/controller/logs/screen-neutron-api.txt

Req-ID: req-5616cffd-21fe-4f95-9c8d-cb462b8f265f

The following message happens after a minute from the request initialized:

Sep 30 18:51:03.326181 np0038662357 <email address hidden>[59416]: DEBUG neutron_lib.db.api [None req-5616cffd-21fe-4f95-9c8d-cb462b8f265f tempest-RoutersNegativeIpV6Test-474032475 tempest-RoutersNegativeIpV6Test-474032475-project-member] Retry wrapper got retriable exception: (pymysql.err.OperationalError) (1205, 'Lock wait timeout exceeded; try restarting transaction')
Sep 30 18:51:03.326181 np0038662357 <email address hidden>[59416]: [SQL: DELETE FROM ports WHERE ports.id = %(id)s]
Sep 30 18:51:03.326181 np0038662357 <email address hidden>[59416]: [parameters: {'id': 'aea79fab-2aae-4bf2-ae30-7d0232533f82'}]
Sep 30 18:51:03.326181 np0038662357 <email address hidden>[59416]: (Background on this error at: https://sqlalche.me/e/20/e3q8) {{(pid=59416) wrapped /opt/stack/data/venv/lib/python3.10/site-packages/neutron_lib/db/api.py:185}}

[yatin (yatinkarel)]

Also seen in other tests
https://9fc08b4308a330f341b7-ee326d1edc43244c4c522686856ef03c.ssl.cf2.rackcdn.com/periodic/opendev.org/openstack/neutron/master/neutron-ovn-tempest-ovs-release-with-oslo-master/07d3aa7/testr_results.html
https://8059d9eb12f46e379447-cfcb5348d0a5bd4d7cf82711ec310965.ssl.cf5.rackcdn.com/periodic/opendev.org/openstack/neutron/master/neutron-ovn-tempest-ovs-release-with-oslo-master/152641b/testr_results.html

possible suspect to check https://review.opendev.org/c/openstack/neutron/+/924317

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Hello all:

There is a race condition between the router interface creation (port) and the deletion. When the "remove_router_interface" call is done, the port is still being processed. The port is still not active and the Neutron API is in the middle of a "port_update" call. This is why we can see DB retry calls [1] in the "port_delete" command, that is issued in the API call "remove_router_interface".

The patch [2] should make the Neutron API faster but in this case we see a slower reaction, at least in the port binding process.

A fix for that could be to wait for the router interfaces to be ACTIVE (as we do in other tests).

Regards.

[1]https://paste.opendev.org/show/bXRg1PQs2j7uUqb1iDZQ/
[2]https://review.opendev.org/c/openstack/neutron/+/924317

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Patch proposed: https://review.opendev.org/c/openstack/tempest/+/931765

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Patch merged, closing the bug.

[yatin (yatinkarel)]

Some new occurances after fixes merged, so re opening to check further

https://8f5091142d0d93e54bb3-66f76d6fb4c84b410723fddf17d0dbe7.ssl.cf5.rackcdn.com/periodic/opendev.org/openstack/neutron/master/neutron-ovn-tempest-mariadb-full/933107e/testr_results.html
https://32e6a1c8c02fba10617a-55d9f2ceb06593bca2aa650f4fd06759.ssl.cf1.rackcdn.com/932071/4/check/neutron-ovn-tempest-ovs-release/761d63d/testr_results.html

[yatin (yatinkarel)]

Another recent occurrence https://df0cceafb057f67e6c7c-70474520a2e562b88d6ff63e0bb37737.ssl.cf2.rackcdn.com/932181/1/gate/neutron-ovn-tempest-ipv6-only-ovs-release/e413acd/testr_results.html

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Same as in [1], we need to implement the same logic for ``RoutersNegativeTest``.

[1]https://review.opendev.org/c/openstack/tempest/+/931765

[Rodolfo Alonso (rodolfo-alonso-hernandez)]

Patch proposed: https://review.opendev.org/c/openstack/tempest/+/936337

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/neutron/+/936829

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/tempest 2023.1-last Antelope release.

[OpenStack Infra (hudson-openstack)]

Change abandoned by "yatin <email address hidden>" on branch: master
Review: https://review.opendev.org/c/openstack/neutron/+/936829
Reason: No longer needed, couple of issues already handled