nova.tests.functional.libvirt.test_vpmem.VPMEMTests.test_create_servers_with_vpmem fails intermittently

Bug #1856902 reported by Matt Riedemann
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
Medium
Matt Riedemann

Bug Description

Seen here:

https://748441c9eeeb89eb36db-b17eeb704755458252956ad3afd603fe.ssl.cf5.rackcdn.com/697670/3/gate/nova-tox-functional-py36/54fe49d/testr_results.html.gz

ft1.1: nova.tests.functional.libvirt.test_vpmem.VPMEMTests.test_create_servers_with_vpmemtesttools.testresult.real._StringException: pythonlogging:'': {{{
2019-12-18 17:05:18,534 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring.
2019-12-18 17:05:18,885 INFO [nova.service] Starting conductor node (version 20.1.0)
2019-12-18 17:05:18,917 INFO [nova.service] Starting scheduler node (version 20.1.0)
2019-12-18 17:05:18,981 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/flavors/detail" status: 200 len: 2605 microversion: 2.81 time: 0.020144
2019-12-18 17:05:18,996 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/flavors" status: 200 len: 464 microversion: 2.81 time: 0.012445
2019-12-18 17:05:19,018 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/flavors/99512851/os-extra_specs" status: 200 len: 37 microversion: 2.81 time: 0.018592
2019-12-18 17:05:19,035 INFO [nova.virt.driver] Loading compute driver 'libvirt.LibvirtDriver'
2019-12-18 17:05:19,038 WARNING [os_brick.initiator.connectors.remotefs] Connection details not present. RemoteFsClient may not initialize properly.
2019-12-18 17:05:19,040 INFO [nova.service] Starting compute node (version 20.1.0)
2019-12-18 17:05:19,058 WARNING [nova.compute.manager] Compute node host1 not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning.
2019-12-18 17:05:19,063 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host
2019-12-18 17:05:19,073 WARNING [nova.compute.manager] No compute node record found for host host1. If this is the first time this service is starting on this host, then you can ignore this warning.
2019-12-18 17:05:19,082 WARNING [nova.compute.resource_tracker] No compute node record for host1:host1
2019-12-18 17:05:19,086 INFO [nova.compute.resource_tracker] Compute node record created for host1:host1 with uuid: 56a25de3-2d91-48a3-9e77-a66f1b5d65b5
2019-12-18 17:05:19,123 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=56a25de3-2d91-48a3-9e77-a66f1b5d65b5" status: 200 len: 26 microversion: 1.14
2019-12-18 17:05:19,131 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20
2019-12-18 17:05:19,132 INFO [nova.scheduler.client.report] [req-54d75b29-ade3-4f2a-8911-d1147ef449fc] Created resource provider record via placement API for resource provider with UUID 56a25de3-2d91-48a3-9e77-a66f1b5d65b5 and name host1.
2019-12-18 17:05:19,133 INFO [nova.virt.libvirt.host] kernel doesn't support AMD SEV
2019-12-18 17:05:19,149 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_classes/CUSTOM_PMEM_NAMESPACE_SMALL" status: 201 len: 0 microversion: 1.7
2019-12-18 17:05:19,159 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_classes/CUSTOM_PMEM_NAMESPACE_4GB" status: 201 len: 0 microversion: 1.7
2019-12-18 17:05:19,173 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/56a25de3-2d91-48a3-9e77-a66f1b5d65b5/inventories" status: 200 len: 665 microversion: 1.26
2019-12-18 17:05:19,181 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_IMAGE_TYPE_AMI,HW_CPU_X86_VMX,HW_CPU_X86_AESNI,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_IMAGE_TYPE_AKI,COMPUTE_IMAGE_TYPE_ISO,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_IMAGE_TYPE_ARI,COMPUTE_IMAGE_TYPE_RAW,COMPUTE_DEVICE_TAGGING,HW_CPU_HYPERTHREADING,COMPUTE_VOLUME_EXTEND,COMPUTE_IMAGE_TYPE_QCOW2,COMPUTE_TRUSTED_CERTS,COMPUTE_NODE" status: 200 len: 432 microversion: 1.6
2019-12-18 17:05:19,200 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/56a25de3-2d91-48a3-9e77-a66f1b5d65b5/traits" status: 200 len: 467 microversion: 1.6
2019-12-18 17:05:19,224 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.81 time: 0.019077
2019-12-18 17:05:19,236 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/56a25de3-2d91-48a3-9e77-a66f1b5d65b5/inventories" status: 200 len: 665 microversion: 1.0
2019-12-18 17:05:19,253 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.81 time: 0.014420
2019-12-18 17:05:19,255 INFO [nova.tests.functional.libvirt.test_vpmem] booting on host1
2019-12-18 17:05:19,329 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 414 microversion: 2.81 time: 0.071830
2019-12-18 17:05:19,352 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 200 len: 1778 microversion: 2.81 time: 0.019663
2019-12-18 17:05:19,473 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?in_tree=56a25de3-2d91-48a3-9e77-a66f1b5d65b5&limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=CUSTOM_PMEM_NAMESPACE_SMALL%3A1%2CDISK_GB%3A1%2CMEMORY_MB%3A1024%2CVCPU%3A1" status: 200 len: 1087 microversion: 1.34
2019-12-18 17:05:19,495 INFO [nova.scheduler.host_manager] Host filter forcing available hosts to host1
2019-12-18 17:05:19,503 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 200 len: 19 microversion: 1.28
2019-12-18 17:05:19,530 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 204 len: 0 microversion: 1.34
2019-12-18 17:05:19,724 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 200 len: 265 microversion: 1.28
2019-12-18 17:05:19,731 INFO [nova.compute.claims] Claim successful on node host1
2019-12-18 17:05:19,985 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.
2019-12-18 17:05:20,077 INFO [nova.compute.manager] Took 0.36 seconds to build instance.
2019-12-18 17:05:20,087 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 200 len: 1875 microversion: 2.81 time: 0.227589
2019-12-18 17:05:20,122 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList.
2019-12-18 17:05:20,679 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 200 len: 1880 microversion: 2.81 time: 0.087029
2019-12-18 17:05:20,690 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/3a085e4e-52ba-49cc-be7c-6eca2974765a" status: 200 len: 169 microversion: 1.0
2019-12-18 17:05:20,691 INFO [nova.tests.functional.libvirt.test_vpmem] booting on host1
2019-12-18 17:05:20,766 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 414 microversion: 2.81 time: 0.072347
2019-12-18 17:05:20,786 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 1778 microversion: 2.81 time: 0.017267
2019-12-18 17:05:20,902 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?in_tree=56a25de3-2d91-48a3-9e77-a66f1b5d65b5&limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=CUSTOM_PMEM_NAMESPACE_SMALL%3A1%2CDISK_GB%3A1%2CMEMORY_MB%3A1024%2CVCPU%3A1" status: 200 len: 1090 microversion: 1.34
2019-12-18 17:05:20,922 INFO [nova.scheduler.host_manager] Host filter forcing available hosts to host1
2019-12-18 17:05:20,930 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 19 microversion: 1.28
2019-12-18 17:05:20,955 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 204 len: 0 microversion: 1.34
2019-12-18 17:05:21,131 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 265 microversion: 1.28
2019-12-18 17:05:21,138 INFO [nova.compute.claims] Claim successful on node host1
2019-12-18 17:05:21,391 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.
2019-12-18 17:05:21,450 INFO [nova.compute.manager] Took 0.33 seconds to build instance.
2019-12-18 17:05:21,490 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 1863 microversion: 2.81 time: 0.183892
2019-12-18 17:05:22,075 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 1880 microversion: 2.81 time: 0.080401
2019-12-18 17:05:22,084 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 169 microversion: 1.0
2019-12-18 17:05:22,085 INFO [nova.tests.functional.libvirt.test_vpmem] booting on host1
2019-12-18 17:05:22,162 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 414 microversion: 2.81 time: 0.074114
2019-12-18 17:05:22,183 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/afeb21d7-a89d-40ea-ac6e-28a7b80cec95" status: 200 len: 1778 microversion: 2.81 time: 0.018034
2019-12-18 17:05:22,283 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?in_tree=56a25de3-2d91-48a3-9e77-a66f1b5d65b5&limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=CUSTOM_PMEM_NAMESPACE_SMALL%3A1%2CDISK_GB%3A1%2CMEMORY_MB%3A1024%2CVCPU%3A1" status: 200 len: 53 microversion: 1.34
2019-12-18 17:05:22,284 INFO [nova.scheduler.manager] Got no allocation candidates from the Placement API. This could be due to insufficient resources or a temporary occurrence as compute nodes start up.
2019-12-18 17:05:22,284 ERROR [nova.conductor.manager] Failed to schedule instances
Traceback (most recent call last):
  File "/home/zuul/src/opendev.org/openstack/nova/nova/conductor/manager.py", line 1412, in schedule_and_build_instances
    instance_uuids, return_alternates=True)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/conductor/manager.py", line 855, in _schedule_instances
    return_alternates=return_alternates)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/client/query.py", line 42, in select_destinations
    instance_uuids, return_objects, return_alternates)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/rpcapi.py", line 160, in select_destinations
    return cctxt.call(ctxt, 'select_destinations', **msg_args)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 181, in call
    transport_options=self.transport_options)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/transport.py", line 129, in _send
    transport_options=transport_options)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send
    transport_options)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_fake.py", line 208, in _send
    raise failure
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 235, in inner
    return func(*args, **kwargs)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/manager.py", line 199, in select_destinations
    raise exception.NoValidHost(reason="")
nova.exception.NoValidHost: No valid host was found.
2019-12-18 17:05:22,325 WARNING [nova.scheduler.utils] Failed to compute_task_build_instances: No valid host was found.
2019-12-18 17:05:22,325 WARNING [nova.scheduler.utils] Setting instance to ERROR state.
2019-12-18 17:05:22,773 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/afeb21d7-a89d-40ea-ac6e-28a7b80cec95" status: 200 len: 3749 microversion: 2.81 time: 0.084113
2019-12-18 17:05:22,899 INFO [nova.api.openstack.requestlog] 127.0.0.1 "DELETE /v2.1/servers/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 204 len: 0 microversion: 2.81 time: 0.122724
2019-12-18 17:05:22,901 INFO [nova.tests.functional.libvirt.test_vpmem] booting on host1
2019-12-18 17:05:22,952 INFO [nova.compute.manager] Terminating instance
2019-12-18 17:05:22,968 INFO [nova.virt.libvirt.driver] Instance destroyed successfully.
2019-12-18 17:05:22,976 INFO [nova.virt.libvirt.driver] Deletion of /home/zuul/src/opendev.org/openstack/nova/instances/68f4cbad-7c69-492a-a173-6869dfa312d7_del complete
2019-12-18 17:05:23,042 INFO [nova.compute.manager] Took 0.08 seconds to destroy the instance on the hypervisor.
2019-12-18 17:05:23,051 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 414 microversion: 2.81 time: 0.147582
2019-12-18 17:05:23,077 INFO [nova.compute.manager] Took 0.02 seconds to deallocate network for instance.
2019-12-18 17:05:23,095 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 1778 microversion: 2.81 time: 0.040906
2019-12-18 17:05:23,179 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 200 len: 265 microversion: 1.28
2019-12-18 17:05:23,204 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?in_tree=56a25de3-2d91-48a3-9e77-a66f1b5d65b5&limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=CUSTOM_PMEM_NAMESPACE_SMALL%3A1%2CDISK_GB%3A1%2CMEMORY_MB%3A1024%2CVCPU%3A1" status: 200 len: 53 microversion: 1.34
2019-12-18 17:05:23,205 INFO [nova.scheduler.manager] Got no allocation candidates from the Placement API. This could be due to insufficient resources or a temporary occurrence as compute nodes start up.
2019-12-18 17:05:23,208 ERROR [nova.conductor.manager] Failed to schedule instances
Traceback (most recent call last):
  File "/home/zuul/src/opendev.org/openstack/nova/nova/conductor/manager.py", line 1412, in schedule_and_build_instances
    instance_uuids, return_alternates=True)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/conductor/manager.py", line 855, in _schedule_instances
    return_alternates=return_alternates)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/client/query.py", line 42, in select_destinations
    instance_uuids, return_objects, return_alternates)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/rpcapi.py", line 160, in select_destinations
    return cctxt.call(ctxt, 'select_destinations', **msg_args)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 181, in call
    transport_options=self.transport_options)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/transport.py", line 129, in _send
    transport_options=transport_options)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send
    transport_options)
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_fake.py", line 208, in _send
    raise failure
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 235, in inner
    return func(*args, **kwargs)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/manager.py", line 199, in select_destinations
    raise exception.NoValidHost(reason="")
nova.exception.NoValidHost: No valid host was found.
2019-12-18 17:05:23,240 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/68f4cbad-7c69-492a-a173-6869dfa312d7" status: 204 len: 0 microversion: 1.28
2019-12-18 17:05:23,241 INFO [nova.scheduler.client.report] Deleted allocation for instance 68f4cbad-7c69-492a-a173-6869dfa312d7
2019-12-18 17:05:23,312 WARNING [nova.scheduler.utils] Failed to compute_task_build_instances: No valid host was found.
2019-12-18 17:05:23,313 WARNING [nova.scheduler.utils] Setting instance to ERROR state.
2019-12-18 17:05:23,696 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.094132
2019-12-18 17:05:24,254 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.053813
2019-12-18 17:05:24,817 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.058160
2019-12-18 17:05:25,376 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.054598
2019-12-18 17:05:25,943 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.062802
2019-12-18 17:05:26,502 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.054831
2019-12-18 17:05:27,067 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.060461
2019-12-18 17:05:27,629 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.057168
2019-12-18 17:05:28,199 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847" status: 200 len: 3749 microversion: 2.81 time: 0.065318
2019-12-18 17:05:28,339 INFO [oslo_db.sqlalchemy.provision] DROP ALL OBJECTS, BACKEND sqlite://
2019-12-18 17:05:28,372 INFO [oslo_db.sqlalchemy.provision] DISPOSE ENGINE Engine(sqlite://)
}}}

Traceback (most recent call last):
  File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/libvirt/test_vpmem.py", line 191, in test_create_servers_with_vpmem
    self._wait_for_state_change(server3, 'ACTIVE')
  File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 98, in _wait_for_state_change
    server, {'status': expected_status}, max_retries)
  File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 91, in _wait_for_server_parameter
    expected_params, server))
  File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/unittest2/case.py", line 690, in fail
    raise self.failureException(msg)
AssertionError: Wait for state change failed, expected_params={'status': 'ACTIVE'}, server={'id': 'e67add72-1327-466a-8f96-7e5025fb9847', 'name': 'some-server', 'status': 'ERROR', 'tenant_id': '6f70656e737461636b20342065766572', 'user_id': 'admin', 'metadata': {}, 'hostId': '', 'image': {'id': '155d900f-4e14-4e4c-a73d-069cbf4541e6', 'links': [{'rel': 'bookmark', 'href': 'http://2a542091-42cb-4ba0-a2eb-9ed61b4b29da/images/155d900f-4e14-4e4c-a73d-069cbf4541e6'}]}, 'flavor': {'vcpus': 1, 'ram': 1024, 'disk': 1, 'ephemeral': 0, 'swap': 0, 'original_name': 'flavorBGI1I584', 'extra_specs': {'hw:pmem': 'SMALL'}}, 'created': '2019-12-18T17:05:23Z', 'updated': '2019-12-18T17:05:23Z', 'addresses': {}, 'accessIPv4': '', 'accessIPv6': '', 'links': [{'rel': 'self', 'href': 'http://2a542091-42cb-4ba0-a2eb-9ed61b4b29da/v2.1/servers/e67add72-1327-466a-8f96-7e5025fb9847'}, {'rel': 'bookmark', 'href': 'http://2a542091-42cb-4ba0-a2eb-9ed61b4b29da/servers/e67add72-1327-466a-8f96-7e5025fb9847'}], 'OS-DCF:diskConfig': 'MANUAL', 'fault': {'code': 500, 'created': '2019-12-18T17:05:23Z', 'message': 'No valid host was found. ', 'details': 'Traceback (most recent call last):\n File "/home/zuul/src/opendev.org/openstack/nova/nova/conductor/manager.py", line 1412, in schedule_and_build_instances\n instance_uuids, return_alternates=True)\n File "/home/zuul/src/opendev.org/openstack/nova/nova/conductor/manager.py", line 855, in _schedule_instances\n return_alternates=return_alternates)\n File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/client/query.py", line 42, in select_destinations\n instance_uuids, return_objects, return_alternates)\n File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/rpcapi.py", line 160, in select_destinations\n return cctxt.call(ctxt, \'select_destinations\', **msg_args)\n File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/rpc/client.py", line 181, in call\n transport_options=self.transport_options)\n File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/transport.py", line 129, in _send\n transport_options=transport_options)\n File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send\n transport_options)\n File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/_drivers/impl_fake.py", line 208, in _send\n raise failure\n File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_messaging/rpc/server.py", line 235, in inner\n return func(*args, **kwargs)\n File "/home/zuul/src/opendev.org/openstack/nova/nova/scheduler/manager.py", line 199, in select_destinations\n raise exception.NoValidHost(reason="")\nnova.exception.NoValidHost: No valid host was found. \n'}, 'OS-EXT-AZ:availability_zone': 'nova', 'config_drive': '', 'key_name': None, 'OS-SRV-USG:launched_at': None, 'OS-SRV-USG:terminated_at': None, 'OS-EXT-SRV-ATTR:host': None, 'OS-EXT-SRV-ATTR:instance_name': 'instance-00000002', 'OS-EXT-SRV-ATTR:hypervisor_hostname': None, 'OS-EXT-SRV-ATTR:reservation_id': 'r-e4t4h5f5', 'OS-EXT-SRV-ATTR:launch_index': 0, 'OS-EXT-SRV-ATTR:hostname': 'some-server', 'OS-EXT-SRV-ATTR:kernel_id': '', 'OS-EXT-SRV-ATTR:ramdisk_id': '', 'OS-EXT-SRV-ATTR:root_device_name': None, 'OS-EXT-SRV-ATTR:user_data': None, 'OS-EXT-STS:task_state': None, 'OS-EXT-STS:vm_state': 'error', 'OS-EXT-STS:power_state': 0, 'os-extended-volumes:volumes_attached': [], 'host_status': '', 'locked': False, 'locked_reason': None, 'description': None, 'tags': [], 'trusted_image_certificates': None, 'server_groups': []}

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22'extra_specs'%3A%20%7B'hw%3Apmem'%3A%20'SMALL'%7D%7D%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

18 hits in 7 days, check and gate, all failures.

Matt Riedemann (mriedem)
Changed in nova:
status: New → Confirmed
importance: Undecided → Medium
tags: added: gate-failure testing
Revision history for this message
Matt Riedemann (mriedem) wrote :

Interestingly this test is trying to create 3 servers and there are only 2 available CUSTOM_PMEM_NAMESPACE_SMALL resources available so the test expects the 3rd server to fail and go to ERROR status, which it appears it does from the logs.

Then it deletes one of the servers holding a resource and tries to create another server which fails and I think this is because it's not waiting for the deleted server to actually be gone which is likely a result of the delete server functional test code being refactored to move away from ServersTestBase.

Revision history for this message
Matt Riedemann (mriedem) wrote :

Actually it looks like this test was just always racy. I'll post a fix.

Changed in nova:
assignee: nobody → Matt Riedemann (mriedem)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.opendev.org/699997

Changed in nova:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to nova (master)

Reviewed: https://review.opendev.org/699997
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=40950f9c87681a1db0f3819530dd0b89ac5f6553
Submitter: Zuul
Branch: master

commit 40950f9c87681a1db0f3819530dd0b89ac5f6553
Author: Matt Riedemann <email address hidden>
Date: Thu Dec 19 09:41:18 2019 -0500

    Fix race in test_create_servers_with_vpmem

    This test creates 2 servers which take up all of the
    CUSTOM_PMEM_NAMESPACE_SMALL resources on the sole host in
    the test. Then it tries to create a 3rd server which it
    expects to fail and it does. Then it deletes the second
    server to free up one CUSTOM_PMEM_NAMESPACE_SMALL resource
    on the host and schedules another server which it expects
    to work. The problem is the test doesn't wait for the
    second server to be fully deleted so the test intermittently
    fails when the CUSTOM_PMEM_NAMESPACE_SMALL resource isn't
    yet freed up when the fourth server goes through scheduling.

    This adds a simple wait call for the deleted server to actually
    be gone before creating the fourth server.

    Change-Id: Id3389038b5fed1e70dd12c7ed9cef2c0950625cf
    Closes-Bug: #1856902

Changed in nova:
status: In Progress → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.