yahoo-eng-team team mailing list archive

Thread
Date
[Bug 2125598] [NEW] nova-next migration scheduling failure due to only the source host is available

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Balazs Gibizer <2125598@xxxxxxxxxxxxxxxxxx>
Date: Wed, 24 Sep 2025 16:07:49 -0000
Reply-to: Bug 2125598 <2125598@xxxxxxxxxxxxxxxxxx>
Sender: noreply@xxxxxxxxxxxxx
Public bug reported:

Tempest migration test cases are failing with no valid host. The
scheduler log shows that only the source host of the migration is
available but of course that is filtered out. But the dest host is also
up and usable instances scheduled to it before the failure and after the
failure. So it almost seems like in some scheduling attempts the
scheduler does not get the other node's HostState from scatter-gather.

So far I only see this in nova-next and found no similar failure in our
nova-live-migration and nova-live-migration-ceph jobs. So I feel it
might be related to threading mode of the scheduler.

Example run
https://zuul.opendev.org/t/openstack/build/ff95e0b2c14b4db7a1f7ebea806ce807/logs

relevant scheduler logs:

Sep 19 13:41:17.330482 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Starting to schedule for instances: ['0748dac2-0978-4bce-bd8b-ed2d0ac23467'] {{(pid=85267) select_destinations /opt/stack/nova/nova/scheduler/manager.py:187}}
Sep 19 13:41:17.330482 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] require_image_type_support request filter added required trait COMPUTE_IMAGE_TYPE_QCOW2 {{(pid=85267) require_image_type_support /opt/stack/nova/nova/scheduler/request_filter.py:192}}
Sep 19 13:41:17.331477 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'require_image_type_support' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] compute_status_filter request filter added forbidden trait COMPUTE_STATUS_DISABLED {{(pid=85267) compute_status_filter /opt/stack/nova/nova/scheduler/request_filter.py:253}}
Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'compute_status_filter' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'accelerators_filter' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'packed_virtqueue_filter' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: WARNING neutronclient.v2_0.client [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] The python binding code in neutronclient is deprecated in favor of OpenstackSDK, please use that as this will be removed in a future release.
Sep 19 13:41:17.410166 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'remote_managed_ports_filter' took 0.1 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
Sep 19 13:41:17.411895 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] ephemeral_encryption_filter skipped {{(pid=85267) ephemeral_encryption_filter /opt/stack/nova/nova/scheduler/request_filter.py:426}}
Sep 19 13:41:17.412575 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] virtio_sound_filter skipped {{(pid=85267) virtio_sound_filter /opt/stack/nova/nova/scheduler/request_filter.py:460}}
Sep 19 13:41:17.521509 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Acquiring lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:405}}
Sep 19 13:41:17.522829 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:410}}
Sep 19 13:41:17.522829 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.000s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:424}}
Sep 19 13:41:17.522829 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.utils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] State of Process-1.cell_worker ThreadPoolExecutor when submitting a new task: max_workers: 5, workers: 4, idle workers: 4, queued work: 0, stats: <ExecutorStatistics object at 0x7584fc1bebc0 (failures=0, executed=4, runtime=0.11, cancelled=0)> {{(pid=85267) _log_executor_stats /opt/stack/nova/nova/utils.py:1235}}
Sep 19 13:41:17.540745 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Acquiring lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:405}}
Sep 19 13:41:17.541783 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:410}}
Sep 19 13:41:17.543522 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:424}}
Sep 19 13:41:17.547908 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Acquiring lock "('np74dd92d2ee964', 'np74dd92d2ee964')" by "nova.scheduler.host_manager.HostState.update.<locals>._locked_update" {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:405}}
Sep 19 13:41:17.548612 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "('np74dd92d2ee964', 'np74dd92d2ee964')" acquired by "nova.scheduler.host_manager.HostState.update.<locals>._locked_update" :: waited 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:410}}
Sep 19 13:41:17.549849 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state from compute node: ComputeNode(cpu_allocation_ratio=4.0,cpu_info='{"arch": "x86_64", "model": "SandyBridge-IBRS", "vendor": "Intel", "topology": {"cells": 1, "sockets": 8, "cores": 1, "threads": 1}, "maxphysaddr": {"mode": "emulate", "bits": 46}, "features": ["de", "hypervisor", "rdtscp", "flush-l1d", "pat", "lm", "fxsr", "ibpb", "vme", "sse2", "xsaveopt", "tsc", "pae", "avx", "sse4.2", "mce", "xsave", "mmx", "acpi", "clflush", "cx16", "pse36", "sep", "pdpe1gb", "cx8", "lahf_lm", "ssse3", "msr", "pse", "pge", "nx", "ssbd", "syscall", "aes", "md-clear", "x2apic", "mtrr", "spec-ctrl", "mca", "sse4.1", "fpu", "pcid", "pni", "pclmuldq", "stibp", "popcnt", "apic", "tsc-deadline", "sse", "cmov"]}',created_at=2025-09-19T13:26:34Z,current_workload=0,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=51,free_disk_gb=65,free_ram_mb=6653,host='np74dd92d2ee964',host_ip=10.210.65.91,hypervisor_hostname='np74dd92d2ee964',hypervisor_type='QEMU',hypervisor_version=8002002,id=1,local_gb=69,local_gb_used=4,mapped=1,memory_mb=7933,memory_mb_used=1280,metrics='[]',numa_topology='{"nova_object.name": "NUMATopology", "nova_object.namespace": "nova", "nova_object.version": "1.2", "nova_object.data": {"cells": [{"nova_object.name": "NUMACell", "nova_object.namespace": "nova", "nova_object.version": "1.5", "nova_object.data": {"id": 0, "cpuset": [0, 1, 2, 3, 4, 5, 6, 7], "pcpuset": [0, 1, 2, 3, 4, 5, 6, 7], "memory": 7933, "cpu_usage": 0, "memory_usage": 0, "pinned_cpus": [], "siblings": [[6], [2], [5], [4], [1], [7], [0], [3]], "mempages": [{"nova_object.name": "NUMAPagesTopology", "nova_object.namespace": "nova", "nova_object.version": "1.1", "nova_object.data": {"size_kb": 4, "total": 2031022, "used": 0, "reserved": 0}, "nova_object.changes": ["reserved", "total", "size_kb", "used"]}, {"nova_object.name": "NUMAPagesTopology", "nova_object.namespace": "nova", "nova_object.version": "1.1", "nova_object.data": {"size_kb": 2048, "total": 0, "used": 0, "reserved": 0}, "nova_object.changes": ["reserved", "total", "size_kb", "used"]}, {"nova_object.name": "NUMAPagesTopology", "nova_object.namespace": "nova", "nova_object.version": "1.1", "nova_object.data": {"size_kb": 1048576, "total": 0, "used": 0, "reserved": 0}, "nova_object.changes": ["reserved", "total", "size_kb", "used"]}], "network_metadata": {"nova_object.name": "NetworkMetadata", "nova_object.namespace": "nova", "nova_object.version": "1.0", "nova_object.data": {"physnets": [], "tunneled": false}, "nova_object.changes": ["tunneled", "physnets"]}, "socket": null}, "nova_object.changes": ["mempages", "memory", "cpuset", "pcpuset", "socket", "cpu_usage", "pinned_cpus", "network_metadata", "memory_usage", "siblings", "id"]}]}, "nova_object.changes": ["cells"]}',pci_device_pools=PciDevicePoolList,ram_allocation_ratio=1.0,running_vms=4,service_id=3,stats={failed_builds='0',io_workload='2',num_instances='4',num_os_type_None='4',num_proj_4a10c0da93e24706b4efeb4fbe2a29a2='1',num_proj_5483dc209cd242e8b8fd355baedad102='1',num_proj_7c2b14b591ad42a79e83eee97bf99af1='1',num_proj_b3e4736ea6594943a2f4c4a42373e68b='1',num_task_None='4',num_vm_active='2',num_vm_building='2',uptime=' 13:40:44 up 44 min,  2 users,  load average: 5.48, 2.36, 1.44
Sep 19 13:41:17.549849 np74dd92d2ee964 nova-scheduler[85267]: '},supported_hv_specs=[HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec],updated_at=2025-09-19T13:41:01Z,uuid=5f9c1994-bac2-47ea-ab92-155b9293a0b4,vcpus=8,vcpus_used=4) {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:169}}
Sep 19 13:41:17.551821 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state with aggregates: [] {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:172}}
Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state with service dict: {'id': 3, 'uuid': 'e6236119-690e-41c2-8ac3-ae307bef64e4', 'host': 'np74dd92d2ee964', 'binary': 'nova-compute', 'topic': 'compute', 'report_count': 8, 'disabled': False, 'disabled_reason': None, 'last_seen_up': datetime.datetime(2025, 9, 19, 13, 40, 43, tzinfo=datetime.timezone.utc), 'forced_down': False, 'version': 70, 'created_at': datetime.datetime(2025, 9, 19, 13, 26, 33, tzinfo=datetime.timezone.utc), 'updated_at': datetime.datetime(2025, 9, 19, 13, 40, 43, tzinfo=datetime.timezone.utc), 'deleted_at': None, 'deleted': False} {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:175}}
Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state with instances: ['edba8873-7aa7-4eb7-b8ba-2deaf74d3f81', '9a1d1b16-579a-4975-84f4-2adf91713f09', 'd8b418a5-3d7c-4088-9d68-f79bbd5b0590', '0748dac2-0978-4bce-bd8b-ed2d0ac23467'] {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:178}}
Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "('np74dd92d2ee964', 'np74dd92d2ee964')" "released" by "nova.scheduler.host_manager.HostState.update.<locals>._locked_update" :: held 0.004s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:424}}
Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: INFO nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Host filter ignoring hosts: np74dd92d2ee964
Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Filtered [] {{(pid=85267) _get_sorted_hosts /opt/stack/nova/nova/scheduler/manager.py:720}}
Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] There are 0 hosts available but 1 instances requested to build. {{(pid=85267) _ensure_sufficient_hosts /opt/stack/nova/nova/scheduler/manager.py:539}}

** Affects: nova
     Importance: Undecided
         Status: New


** Tags: scheduler

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/2125598

Title:
  nova-next migration scheduling failure due to only the source host is
  available

Status in OpenStack Compute (nova):
  New

Bug description:
  Tempest migration test cases are failing with no valid host. The
  scheduler log shows that only the source host of the migration is
  available but of course that is filtered out. But the dest host is
  also up and usable instances scheduled to it before the failure and
  after the failure. So it almost seems like in some scheduling attempts
  the scheduler does not get the other node's HostState from scatter-
  gather.

  So far I only see this in nova-next and found no similar failure in
  our nova-live-migration and nova-live-migration-ceph jobs. So I feel
  it might be related to threading mode of the scheduler.

  Example run
  https://zuul.opendev.org/t/openstack/build/ff95e0b2c14b4db7a1f7ebea806ce807/logs

  relevant scheduler logs:

  Sep 19 13:41:17.330482 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Starting to schedule for instances: ['0748dac2-0978-4bce-bd8b-ed2d0ac23467'] {{(pid=85267) select_destinations /opt/stack/nova/nova/scheduler/manager.py:187}}
  Sep 19 13:41:17.330482 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] require_image_type_support request filter added required trait COMPUTE_IMAGE_TYPE_QCOW2 {{(pid=85267) require_image_type_support /opt/stack/nova/nova/scheduler/request_filter.py:192}}
  Sep 19 13:41:17.331477 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'require_image_type_support' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
  Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] compute_status_filter request filter added forbidden trait COMPUTE_STATUS_DISABLED {{(pid=85267) compute_status_filter /opt/stack/nova/nova/scheduler/request_filter.py:253}}
  Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'compute_status_filter' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
  Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'accelerators_filter' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
  Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'packed_virtqueue_filter' took 0.0 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
  Sep 19 13:41:17.335478 np74dd92d2ee964 nova-scheduler[85267]: WARNING neutronclient.v2_0.client [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] The python binding code in neutronclient is deprecated in favor of OpenstackSDK, please use that as this will be removed in a future release.
  Sep 19 13:41:17.410166 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Request filter 'remote_managed_ports_filter' took 0.1 seconds {{(pid=85267) wrapper /opt/stack/nova/nova/scheduler/request_filter.py:46}}
  Sep 19 13:41:17.411895 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] ephemeral_encryption_filter skipped {{(pid=85267) ephemeral_encryption_filter /opt/stack/nova/nova/scheduler/request_filter.py:426}}
  Sep 19 13:41:17.412575 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.request_filter [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] virtio_sound_filter skipped {{(pid=85267) virtio_sound_filter /opt/stack/nova/nova/scheduler/request_filter.py:460}}
  Sep 19 13:41:17.521509 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Acquiring lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:405}}
  Sep 19 13:41:17.522829 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:410}}
  Sep 19 13:41:17.522829 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.000s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:424}}
  Sep 19 13:41:17.522829 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.utils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] State of Process-1.cell_worker ThreadPoolExecutor when submitting a new task: max_workers: 5, workers: 4, idle workers: 4, queued work: 0, stats: <ExecutorStatistics object at 0x7584fc1bebc0 (failures=0, executed=4, runtime=0.11, cancelled=0)> {{(pid=85267) _log_executor_stats /opt/stack/nova/nova/utils.py:1235}}
  Sep 19 13:41:17.540745 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Acquiring lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:405}}
  Sep 19 13:41:17.541783 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" acquired by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: waited 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:410}}
  Sep 19 13:41:17.543522 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "7cce5cd9-0631-4d44-be9b-b70174353c2a" "released" by "nova.context.set_target_cell.<locals>.get_or_set_cached_cell_and_set_connections" :: held 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:424}}
  Sep 19 13:41:17.547908 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Acquiring lock "('np74dd92d2ee964', 'np74dd92d2ee964')" by "nova.scheduler.host_manager.HostState.update.<locals>._locked_update" {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:405}}
  Sep 19 13:41:17.548612 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "('np74dd92d2ee964', 'np74dd92d2ee964')" acquired by "nova.scheduler.host_manager.HostState.update.<locals>._locked_update" :: waited 0.001s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:410}}
  Sep 19 13:41:17.549849 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state from compute node: ComputeNode(cpu_allocation_ratio=4.0,cpu_info='{"arch": "x86_64", "model": "SandyBridge-IBRS", "vendor": "Intel", "topology": {"cells": 1, "sockets": 8, "cores": 1, "threads": 1}, "maxphysaddr": {"mode": "emulate", "bits": 46}, "features": ["de", "hypervisor", "rdtscp", "flush-l1d", "pat", "lm", "fxsr", "ibpb", "vme", "sse2", "xsaveopt", "tsc", "pae", "avx", "sse4.2", "mce", "xsave", "mmx", "acpi", "clflush", "cx16", "pse36", "sep", "pdpe1gb", "cx8", "lahf_lm", "ssse3", "msr", "pse", "pge", "nx", "ssbd", "syscall", "aes", "md-clear", "x2apic", "mtrr", "spec-ctrl", "mca", "sse4.1", "fpu", "pcid", "pni", "pclmuldq", "stibp", "popcnt", "apic", "tsc-deadline", "sse", "cmov"]}',created_at=2025-09-19T13:26:34Z,current_workload=0,deleted=False,deleted_at=None,disk_allocation_ratio=1.0,disk_available_least=51,free_disk_gb=65,free_ram_mb=6653,host='np74dd92d2ee964',host_ip=10.210.65.91,hypervisor_hostname='np74dd92d2ee964',hypervisor_type='QEMU',hypervisor_version=8002002,id=1,local_gb=69,local_gb_used=4,mapped=1,memory_mb=7933,memory_mb_used=1280,metrics='[]',numa_topology='{"nova_object.name": "NUMATopology", "nova_object.namespace": "nova", "nova_object.version": "1.2", "nova_object.data": {"cells": [{"nova_object.name": "NUMACell", "nova_object.namespace": "nova", "nova_object.version": "1.5", "nova_object.data": {"id": 0, "cpuset": [0, 1, 2, 3, 4, 5, 6, 7], "pcpuset": [0, 1, 2, 3, 4, 5, 6, 7], "memory": 7933, "cpu_usage": 0, "memory_usage": 0, "pinned_cpus": [], "siblings": [[6], [2], [5], [4], [1], [7], [0], [3]], "mempages": [{"nova_object.name": "NUMAPagesTopology", "nova_object.namespace": "nova", "nova_object.version": "1.1", "nova_object.data": {"size_kb": 4, "total": 2031022, "used": 0, "reserved": 0}, "nova_object.changes": ["reserved", "total", "size_kb", "used"]}, {"nova_object.name": "NUMAPagesTopology", "nova_object.namespace": "nova", "nova_object.version": "1.1", "nova_object.data": {"size_kb": 2048, "total": 0, "used": 0, "reserved": 0}, "nova_object.changes": ["reserved", "total", "size_kb", "used"]}, {"nova_object.name": "NUMAPagesTopology", "nova_object.namespace": "nova", "nova_object.version": "1.1", "nova_object.data": {"size_kb": 1048576, "total": 0, "used": 0, "reserved": 0}, "nova_object.changes": ["reserved", "total", "size_kb", "used"]}], "network_metadata": {"nova_object.name": "NetworkMetadata", "nova_object.namespace": "nova", "nova_object.version": "1.0", "nova_object.data": {"physnets": [], "tunneled": false}, "nova_object.changes": ["tunneled", "physnets"]}, "socket": null}, "nova_object.changes": ["mempages", "memory", "cpuset", "pcpuset", "socket", "cpu_usage", "pinned_cpus", "network_metadata", "memory_usage", "siblings", "id"]}]}, "nova_object.changes": ["cells"]}',pci_device_pools=PciDevicePoolList,ram_allocation_ratio=1.0,running_vms=4,service_id=3,stats={failed_builds='0',io_workload='2',num_instances='4',num_os_type_None='4',num_proj_4a10c0da93e24706b4efeb4fbe2a29a2='1',num_proj_5483dc209cd242e8b8fd355baedad102='1',num_proj_7c2b14b591ad42a79e83eee97bf99af1='1',num_proj_b3e4736ea6594943a2f4c4a42373e68b='1',num_task_None='4',num_vm_active='2',num_vm_building='2',uptime=' 13:40:44 up 44 min,  2 users,  load average: 5.48, 2.36, 1.44
  Sep 19 13:41:17.549849 np74dd92d2ee964 nova-scheduler[85267]: '},supported_hv_specs=[HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec,HVSpec],updated_at=2025-09-19T13:41:01Z,uuid=5f9c1994-bac2-47ea-ab92-155b9293a0b4,vcpus=8,vcpus_used=4) {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:169}}
  Sep 19 13:41:17.551821 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state with aggregates: [] {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:172}}
  Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state with service dict: {'id': 3, 'uuid': 'e6236119-690e-41c2-8ac3-ae307bef64e4', 'host': 'np74dd92d2ee964', 'binary': 'nova-compute', 'topic': 'compute', 'report_count': 8, 'disabled': False, 'disabled_reason': None, 'last_seen_up': datetime.datetime(2025, 9, 19, 13, 40, 43, tzinfo=datetime.timezone.utc), 'forced_down': False, 'version': 70, 'created_at': datetime.datetime(2025, 9, 19, 13, 26, 33, tzinfo=datetime.timezone.utc), 'updated_at': datetime.datetime(2025, 9, 19, 13, 40, 43, tzinfo=datetime.timezone.utc), 'deleted_at': None, 'deleted': False} {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:175}}
  Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Update host state with instances: ['edba8873-7aa7-4eb7-b8ba-2deaf74d3f81', '9a1d1b16-579a-4975-84f4-2adf91713f09', 'd8b418a5-3d7c-4088-9d68-f79bbd5b0590', '0748dac2-0978-4bce-bd8b-ed2d0ac23467'] {{(pid=85267) _locked_update /opt/stack/nova/nova/scheduler/host_manager.py:178}}
  Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG oslo_concurrency.lockutils [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Lock "('np74dd92d2ee964', 'np74dd92d2ee964')" "released" by "nova.scheduler.host_manager.HostState.update.<locals>._locked_update" :: held 0.004s {{(pid=85267) inner /opt/stack/data/venv/lib/python3.12/site-packages/oslo_concurrency/lockutils.py:424}}
  Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: INFO nova.scheduler.host_manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Host filter ignoring hosts: np74dd92d2ee964
  Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] Filtered [] {{(pid=85267) _get_sorted_hosts /opt/stack/nova/nova/scheduler/manager.py:720}}
  Sep 19 13:41:17.554190 np74dd92d2ee964 nova-scheduler[85267]: DEBUG nova.scheduler.manager [None req-331f43b6-ce5c-4b18-ad81-f15446535f91 tempest-MigrationsAdminTest-39244249 tempest-MigrationsAdminTest-39244249-project-member] There are 0 hosts available but 1 instances requested to build. {{(pid=85267) _ensure_sufficient_hosts /opt/stack/nova/nova/scheduler/manager.py:539}}

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/2125598/+subscriptions