stable/zed nova.tests.functional.wsgi.test_services.TestServicesAPI.test_resize_revert_after_deleted_source_compute sporadic failures

[Alexey Stupnikov]

A strange failure happens for one of my patches: nova.tests.functional.wsgi.test_services.TestServicesAPI.test_resize_revert_after_deleted_source_compute test fails because of OpenStackApiNotFoundException error.

Logs and traces are available at https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_ab9/870053/2/gate/nova-tox-functional-py38/ab97c5a/job-output.txt

2023-04-21 06:27:36.066489 | ubuntu-focal | Captured traceback:
2023-04-21 06:27:36.066493 | ubuntu-focal | ~~~~~~~~~~~~~~~~~~~
2023-04-21 06:27:36.066497 | ubuntu-focal | Traceback (most recent call last):
2023-04-21 06:27:36.066502 | ubuntu-focal |
2023-04-21 06:27:36.066506 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/wsgi/test_services.py", line 218, in test_resize_revert_after_deleted_source_compute
2023-04-21 06:27:36.066511 | ubuntu-focal | server = self._boot_and_check_allocations(flavor1, 'host1')
2023-04-21 06:27:36.066516 | ubuntu-focal |
2023-04-21 06:27:36.066520 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 932, in _boot_and_check_allocations
2023-04-21 06:27:36.066552 | ubuntu-focal | server = self._wait_for_state_change(created_server, 'ACTIVE')
2023-04-21 06:27:36.066556 | ubuntu-focal |
2023-04-21 06:27:36.066560 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 144, in _wait_for_state_change
2023-04-21 06:27:36.066564 | ubuntu-focal | return self._wait_for_server_parameter(
2023-04-21 06:27:36.066569 | ubuntu-focal |
2023-04-21 06:27:36.066573 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 130, in _wait_for_server_parameter
2023-04-21 06:27:36.066578 | ubuntu-focal | server = api.get_server(server['id'])
2023-04-21 06:27:36.066582 | ubuntu-focal |
2023-04-21 06:27:36.066586 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/api/client.py", line 248, in get_server
2023-04-21 06:27:36.066591 | ubuntu-focal | return self.api_get('/servers/%s' % server_id).body['server']
2023-04-21 06:27:36.066595 | ubuntu-focal |
2023-04-21 06:27:36.066599 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/api/client.py", line 205, in api_get
2023-04-21 06:27:36.066603 | ubuntu-focal | return APIResponse(self.api_request(relative_uri, **kwargs))
2023-04-21 06:27:36.066608 | ubuntu-focal |
2023-04-21 06:27:36.066612 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/api/client.py", line 187, in api_request
2023-04-21 06:27:36.066616 | ubuntu-focal | raise OpenStackApiNotFoundException(response=response)
2023-04-21 06:27:36.066621 | ubuntu-focal |
2023-04-21 06:27:36.066625 | ubuntu-focal | nova.tests.functional.api.client.OpenStackApiNotFoundException: Item not found

In Nova logs I can see that hypervisor and instance itself simply disappeared after successfull startup, so nova-api returned 404:

2023-04-21 06:26:17.760125 | ubuntu-focal | 2023-04-21 06:26:14,598 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 200 len: 1770 microversion: 2.93 time: 0.026509
2023-04-21 06:26:17.760129 | ubuntu-focal | 2023-04-21 06:26:14,683 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?in_tree=7cf25e47-3e14-4944-91ea-ee3c5377f440&limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1&root_required=%21COMPUTE_STATUS_DISABLED" status: 200 len: 793 microversion: 1.36
2023-04-21 06:26:17.760136 | ubuntu-focal | 2023-04-21 06:26:14,711 INFO [nova.scheduler.host_manager] Host filter forcing available hosts to host1
2023-04-21 06:26:17.760140 | ubuntu-focal | 2023-04-21 06:26:14,718 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 200 len: 19 microversion: 1.28
2023-04-21 06:26:17.760148 | ubuntu-focal | 2023-04-21 06:26:14,764 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 204 len: 0 microversion: 1.36
2023-04-21 06:26:17.760152 | ubuntu-focal | 2023-04-21 06:26:17,081 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 200 len: 1787 microversion: 2.93 time: 0.504291
2023-04-21 06:26:17.760156 | ubuntu-focal | 2023-04-21 06:26:17,128 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 200 len: 230 microversion: 1.28
2023-04-21 06:26:17.760160 | ubuntu-focal | 2023-04-21 06:26:17,131 INFO [nova.compute.claims] Claim successful on node host1
2023-04-21 06:26:17.760167 | ubuntu-focal | 2023-04-21 06:26:17,169 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/7cf25e47-3e14-4944-91ea-ee3c5377f440/allocations" status: 200 len: 152 microversion: 1.0
2023-04-21 06:26:17.760171 | ubuntu-focal | 2023-04-21 06:26:17,176 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 200 len: 230 microversion: 1.28
2023-04-21 06:26:17.760175 | ubuntu-focal | 2023-04-21 06:26:17,260 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.
2023-04-21 06:26:17.760179 | ubuntu-focal | 2023-04-21 06:26:17,281 INFO [nova.compute.manager] Took 0.16 seconds to build instance.
2023-04-21 06:26:17.760183 | ubuntu-focal | 2023-04-21 06:26:17,331 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList.
2023-04-21 06:26:17.760187 | ubuntu-focal | 2023-04-21 06:26:17,592 INFO [nova.api.openstack.wsgi] HTTP exception thrown: Instance 6fe74316-77a0-4c99-826a-3c4b85613ee5 could not be found.
2023-04-21 06:26:17.760191 | ubuntu-focal | 2023-04-21 06:26:17,594 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/6fe74316-77a0-4c99-826a-3c4b85613ee5" status: 404 len: 111 microversion: 2.93 time: 0.008478

[Alexey Stupnikov (astupnikov)]

I took a look at history of nova-tox-functional-py38 tests for stable/zed and it looks like this failure is rare (I wasn't able to find same failures). At the same time it looks like clear race condition that deserves a second look.