Example failure: https://zuul.opendev.org/t/openstack/build/99a1e4f3deb4478cb6fa19ed666a950f/log/job-output.txt
Recently this test started failing frequently. In the last 7 days from 8 failed functional test run 6 was due to this in nova. But this happened as far back as 14th of February.
Signature: https://paste.opendev.org/show/btHI7ErFfhKYFGdfoujl/
Stack trace:
2022-03-09 14:37:34.960791 | ubuntu-focal | {7} nova.tests.functional.regressions.test_bug_1944619.TestRollbackWithHWOffloadedOVS.test_rollback_pre_live_migration [5.854784s] ... FAILED
2022-03-09 14:37:34.960833 | ubuntu-focal |
2022-03-09 14:37:34.960849 | ubuntu-focal | Captured traceback:
2022-03-09 14:37:34.960861 | ubuntu-focal | ~~~~~~~~~~~~~~~~~~~
2022-03-09 14:37:34.960872 | ubuntu-focal | Traceback (most recent call last):
2022-03-09 14:37:34.960883 | ubuntu-focal |
2022-03-09 14:37:34.960894 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/regressions/test_bug_1944619.py", line 87, in test_rollback_pre_live_migration
2022-03-09 14:37:34.960906 | ubuntu-focal | self.libvirt_mock.mock.assert_called_once()
2022-03-09 14:37:34.960917 | ubuntu-focal |
2022-03-09 14:37:34.960929 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 891, in assert_called_once
2022-03-09 14:37:34.960959 | ubuntu-focal | raise AssertionError(msg)
2022-03-09 14:37:34.960972 | ubuntu-focal |
2022-03-09 14:37:34.960985 | ubuntu-focal | AssertionError: Expected 'rollback_live_migration_at_source' to have been called once. Called 0 times.
2022-03-09 14:37:34.960996 | ubuntu-focal |
2022-03-09 14:37:34.961005 | ubuntu-focal |
2022-03-09 14:37:34.961015 | ubuntu-focal | Captured pythonlogging:
2022-03-09 14:37:34.961025 | ubuntu-focal | ~~~~~~~~~~~~~~~~~~~~~~~
2022-03-09 14:37:34.961036 | ubuntu-focal | 2022-03-09 14:37:29,292 WARNING [oslo_policy.policy] JSON formatted policy_file support is deprecated since Victoria release. You need to use YAML format which will be default in future. You can use ``oslopolicy-convert-json-to-yaml`` tool to convert existing JSON-formatted policy file to YAML-formatted in backward compatible way: https://docs.openstack.org/oslo.policy/latest/cli/oslopolicy-convert-json-to-yaml.html.
2022-03-09 14:37:34.961048 | ubuntu-focal | 2022-03-09 14:37:29,293 WARNING [oslo_policy.policy] JSON formatted policy_file support is deprecated since Victoria release. You need to use YAML format which will be default in future. You can use ``oslopolicy-convert-json-to-yaml`` tool to convert existing JSON-formatted policy file to YAML-formatted in backward compatible way: https://docs.openstack.org/oslo.policy/latest/cli/oslopolicy-convert-json-to-yaml.html.
2022-03-09 14:37:34.961071 | ubuntu-focal | 2022-03-09 14:37:29,296 WARNING [oslo_policy.policy] Policy Rules ['os_compute_api:extensions', 'os_compute_api:os-floating-ip-pools', 'os_compute_api:os-quota-sets:defaults', 'os_compute_api:os-availability-zone:list', 'os_compute_api:limits', 'project_admin_api', 'project_member_api', 'project_reader_api', 'project_reader_or_admin', 'os_compute_api:limits:other_project', 'os_compute_api:os-lock-server:unlock:unlock_override', 'os_compute_api:servers:create:zero_disk_flavor', 'compute:servers:resize:cross_cell'] specified in policy files are the same as the defaults provided by the service. You can remove these rules from policy files which will make maintenance easier. You can detect these redundant rules by ``oslopolicy-list-redundant`` tool also.
2022-03-09 14:37:34.961108 | ubuntu-focal | 2022-03-09 14:37:29,301 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring.
2022-03-09 14:37:34.961121 | ubuntu-focal | 2022-03-09 14:37:29,406 INFO [nova.service] Starting conductor node (version 24.1.0)
2022-03-09 14:37:34.961133 | ubuntu-focal | 2022-03-09 14:37:29,463 INFO [nova.service] Starting scheduler node (version 24.1.0)
2022-03-09 14:37:34.961144 | ubuntu-focal | 2022-03-09 14:37:31,524 INFO [nova.virt.driver] Loading compute driver 'libvirt.LibvirtDriver'
2022-03-09 14:37:34.961153 | ubuntu-focal | 2022-03-09 14:37:31,527 INFO [nova.compute.provider_config] No provider configs found in /etc/nova/provider_config/. If files are present, ensure the Nova process has access.
2022-03-09 14:37:34.961175 | ubuntu-focal | 2022-03-09 14:37:31,536 INFO [nova.service] Starting compute node (version 24.1.0)
2022-03-09 14:37:34.961183 | ubuntu-focal | 2022-03-09 14:37:31,554 INFO [nova.virt.libvirt.host] Secure Boot support detected
2022-03-09 14:37:34.961189 | ubuntu-focal | 2022-03-09 14:37:31,558 WARNING [nova.virt.libvirt.driver] my_ip address (149.202.187.126) was not found on any of the interfaces:
2022-03-09 14:37:34.961201 | ubuntu-focal | 2022-03-09 14:37:31,559 WARNING [nova.virt.libvirt.driver] Running Nova with a libvirt version less than 7.0.0 is deprecated. The required minimum version of libvirt will be raised to 7.0.0 in the next release.
2022-03-09 14:37:34.961213 | ubuntu-focal | 2022-03-09 14:37:31,559 WARNING [nova.virt.libvirt.driver] Running Nova with a QEMU version less than 5.2.0 is deprecated. The required minimum version of QEMU will be raised to 5.2.0 in the next release.
2022-03-09 14:37:34.961250 | ubuntu-focal | 2022-03-09 14:37:31,598 WARNING [nova.compute.manager] Compute node src not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning.
2022-03-09 14:37:34.961257 | ubuntu-focal | 2022-03-09 14:37:31,606 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host
2022-03-09 14:37:34.961270 | ubuntu-focal | 2022-03-09 14:37:31,624 WARNING [nova.compute.manager] No compute node record found for host src. If this is the first time this service is starting on this host, then you can ignore this warning.
2022-03-09 14:37:34.961276 | ubuntu-focal | 2022-03-09 14:37:31,632 WARNING [nova.compute.resource_tracker] No compute node record for src:src
2022-03-09 14:37:34.961282 | ubuntu-focal | 2022-03-09 14:37:31,639 INFO [nova.compute.resource_tracker] Compute node record created for src:src with uuid: 7f41f57e-1c75-4533-beb4-2e1f31ce4327
2022-03-09 14:37:34.961288 | ubuntu-focal | 2022-03-09 14:37:31,707 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=7f41f57e-1c75-4533-beb4-2e1f31ce4327" status: 200 len: 26 microversion: 1.14
2022-03-09 14:37:34.961293 | ubuntu-focal | 2022-03-09 14:37:31,717 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 826 microversion: 1.20
2022-03-09 14:37:34.961299 | ubuntu-focal | 2022-03-09 14:37:31,718 INFO [nova.scheduler.client.report] [req-d4bdf881-be30-4d23-bd99-cf75934974ab] Created resource provider
2022-03-09 14:37:34.961305 | ubuntu-focal | record via placement API for resource provider with UUID 7f41f57e-1c75-4533-beb4-2e1f31ce4327 and name src.
2022-03-09 14:37:34.961310 | ubuntu-focal | 2022-03-09 14:37:31,719 INFO [nova.virt.libvirt.host] kernel doesn't support AMD SEV
2022-03-09 14:37:34.961316 | ubuntu-focal | 2022-03-09 14:37:31,742 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7f41f57e-1c75-4533-beb4-2e1f31ce4327/inventories" status: 200 len: 407 microversion: 1.26
2022-03-09 14:37:34.961323 | ubuntu-focal | 2022-03-09 14:37:31,757 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_IMAGE_TYPE_ISO,COMPUTE_NODE,COMPUTE_IMAGE_TYPE_ARI,COMPUTE_IMAGE_TYPE_AMI,HW_CPU_X86_INTEL_VMX,COMPUTE_SECURITY_UEFI_SECURE_BOOT,COMPUTE_GRAPHICS_MODEL_QXL,COMPUTE_GRAPHICS_MODEL_NONE,COMPUTE_VOLUME_EXTEND,COMPUTE_STORAGE_BUS_FDC,HW_CPU_X86_AESNI,HW_CPU_X86_VMX,COMPUTE_DEVICE_TAGGING,COMPUTE_STORAGE_BUS_SATA,COMPUTE_GRAPHICS_MODEL_VMVGA,COMPUTE_NET_VIF_MODEL_PCNET,COMPUTE_NET_VIF_MODEL_E1000E,COMPUTE_SOCKET_PCI_NUMA_AFFINITY,COMPUTE_RESCUE_BFV,COMPUTE_IMAGE_TYPE_AKI,COMPUTE_NET_VIF_MODEL_VIRTIO,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_GRAPHICS_MODEL_BOCHS,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_GRAPHICS_MODEL_VIRTIO,COMPUTE_NET_VIF_MODEL_RTL8139,COMPUTE_IMAGE_TYPE_QCOW2,COMPUTE_GRAPHICS_MODEL_VGA,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_TRUSTED_CERTS,COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_NET_VIF_MODEL_VMXNET3,COMPUTE_IMAGE_TYPE_RAW,COMPUTE_STORAGE_BUS_IDE,COMPUTE_NET_VIF_MODEL_NE2K_PCI,COMPUTE_STORAGE_BUS_SCSI,COMPUTE_NET_VIF_MODEL_SPAPR_VLAN,COMPUTE_ACCELERATORS,COMPUTE_STORAGE_BUS_USB,COMPUTE_NET_VIF_MODEL_E1000,COMPUTE_GRAPHICS_MODEL_CIRRUS,COMPUTE_STORAGE_BUS_VIRTIO" status: 200 len: 1231 microversion: 1.6
2022-03-09 14:37:34.961330 | ubuntu-focal | 2022-03-09 14:37:31,793 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7f41f57e-1c75-4533-beb4-2e1f31ce4327/traits" status: 200 len: 1266 microversion: 1.6
2022-03-09 14:37:34.961347 | ubuntu-focal | 2022-03-09 14:37:31,807 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?name=src" status: 200 len: 430 microversion: 1.0
2022-03-09 14:37:34.961355 | ubuntu-focal | 2022-03-09 14:37:31,820 INFO [nova.virt.driver] Loading compute driver 'libvirt.LibvirtDriver'
2022-03-09 14:37:34.961361 | ubuntu-focal | 2022-03-09 14:37:31,822 INFO [nova.compute.provider_config] No provider configs found in /etc/nova/provider_config/. If files are present, ensure the Nova process has access.
2022-03-09 14:37:34.961366 | ubuntu-focal | 2022-03-09 14:37:31,829 INFO [nova.service] Starting compute node (version 24.1.0)
2022-03-09 14:37:34.961372 | ubuntu-focal | 2022-03-09 14:37:31,845 INFO [nova.virt.libvirt.host] Secure Boot support detected
2022-03-09 14:37:34.961378 | ubuntu-focal | 2022-03-09 14:37:31,846 WARNING [nova.virt.libvirt.driver] my_ip address (149.202.187.126) was not found on any of the interfaces:
2022-03-09 14:37:34.961383 | ubuntu-focal | 2022-03-09 14:37:31,847 WARNING [nova.virt.libvirt.driver] Running Nova with a libvirt version less than 7.0.0 is deprecated. The required minimum version of libvirt will be raised to 7.0.0 in the next release.
2022-03-09 14:37:34.961389 | ubuntu-focal | 2022-03-09 14:37:31,847 WARNING [nova.virt.libvirt.driver] Running Nova with a QEMU version less than 5.2.0 is deprecated. The required minimum version of QEMU will be raised to 5.2.0 in the next release.
2022-03-09 14:37:34.961395 | ubuntu-focal | 2022-03-09 14:37:31,859 WARNING [nova.compute.manager] Compute node dest not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning.
2022-03-09 14:37:34.961401 | ubuntu-focal | 2022-03-09 14:37:31,863 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host
2022-03-09 14:37:34.961412 | ubuntu-focal | 2022-03-09 14:37:31,877 WARNING [nova.compute.manager] No compute node record found for host dest. If this is the first time this service is starting on this host, then you can ignore this warning.
2022-03-09 14:37:34.961418 | ubuntu-focal | 2022-03-09 14:37:31,885 WARNING [nova.compute.resource_tracker] No compute node record for dest:dest
2022-03-09 14:37:34.961424 | ubuntu-focal | 2022-03-09 14:37:31,890 INFO [nova.compute.resource_tracker] Compute node record created for dest:dest with uuid: 656a0c68-a66b-41c6-bf12-a76a9254c623
2022-03-09 14:37:34.961430 | ubuntu-focal | 2022-03-09 14:37:31,929 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=656a0c68-a66b-41c6-bf12-a76a9254c623" status: 200 len: 26 microversion: 1.14
2022-03-09 14:37:34.961435 | ubuntu-focal | 2022-03-09 14:37:31,941 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 827 microversion: 1.20
2022-03-09 14:37:34.961441 | ubuntu-focal | 2022-03-09 14:37:31,942 INFO [nova.scheduler.client.report] [req-bf
2022-03-09 14:37:34.961447 | ubuntu-focal | 6d495f-00a1-4a16-bfb0-fca447e478a6] Created resource provider record via placement API for resource provider with UUID 656a0c68-a66b-41c6-bf12-a76a9254c623 and name dest.
2022-03-09 14:37:34.961452 | ubuntu-focal | 2022-03-09 14:37:31,957 INFO [nova.virt.libvirt.host] kernel doesn't support AMD SEV
2022-03-09 14:37:34.961458 | ubuntu-focal | 2022-03-09 14:37:31,992 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/656a0c68-a66b-41c6-bf12-a76a9254c623/inventories" status: 200 len: 407 microversion: 1.26
2022-03-09 14:37:34.961464 | ubuntu-focal | 2022-03-09 14:37:32,010 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_IMAGE_TYPE_ISO,COMPUTE_NODE,COMPUTE_IMAGE_TYPE_ARI,COMPUTE_IMAGE_TYPE_AMI,HW_CPU_X86_INTEL_VMX,COMPUTE_SECURITY_UEFI_SECURE_BOOT,COMPUTE_GRAPHICS_MODEL_QXL,COMPUTE_GRAPHICS_MODEL_NONE,COMPUTE_VOLUME_EXTEND,COMPUTE_STORAGE_BUS_FDC,HW_CPU_X86_AESNI,HW_CPU_X86_VMX,COMPUTE_DEVICE_TAGGING,COMPUTE_STORAGE_BUS_SATA,COMPUTE_GRAPHICS_MODEL_VMVGA,COMPUTE_NET_VIF_MODEL_PCNET,COMPUTE_NET_VIF_MODEL_E1000E,COMPUTE_SOCKET_PCI_NUMA_AFFINITY,COMPUTE_RESCUE_BFV,COMPUTE_IMAGE_TYPE_AKI,COMPUTE_NET_VIF_MODEL_VIRTIO,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_GRAPHICS_MODEL_BOCHS,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_GRAPHICS_MODEL_VIRTIO,COMPUTE_NET_VIF_MODEL_RTL8139,COMPUTE_IMAGE_TYPE_QCOW2,COMPUTE_GRAPHICS_MODEL_VGA,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_TRUSTED_CERTS,COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_NET_VIF_MODEL_VMXNET3,COMPUTE_IMAGE_TYPE_RAW,COMPUTE_STORAGE_BUS_IDE,COMPUTE_NET_VIF_MODEL_NE2K_PCI,COMPUTE_STORAGE_BUS_SCSI,COMPUTE_NET_VIF_MODEL_SPAPR_VLAN,COMPUTE_ACCELERATORS,COMPUTE_STORAGE_BUS_USB,COMPUTE_NET_VIF_MODEL_E1000,COMPUTE_GRAPHICS_MODEL_CIRRUS,COMPUTE_STORAGE_BUS_VIRTIO" status: 200 len: 1231 microversion: 1.6
2022-03-09 14:37:34.961491 | ubuntu-focal | 2022-03-09 14:37:32,054 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/656a0c68-a66b-41c6-bf12-a76a9254c623/traits" status: 200 len: 1266 microversion: 1.6
2022-03-09 14:37:34.961499 | ubuntu-focal | 2022-03-09 14:37:32,069 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?name=dest" status: 200 len: 431 microversion: 1.0
2022-03-09 14:37:34.961505 | ubuntu-focal | 2022-03-09 14:37:32,094 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/images/detail" status: 200 len: 5173 microversion: 2.35 time: 0.018258
2022-03-09 14:37:34.961510 | ubuntu-focal | 2022-03-09 14:37:32,122 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/flavors/detail" status: 200 len: 2605 microversion: 2.90 time: 0.023321
2022-03-09 14:37:34.961516 | ubuntu-focal | 2022-03-09 14:37:32,421 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?in_tree=7f41f57e-1c75-4533-beb4-2e1f31ce4327&limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1&root_required=%21COMPUTE_STATUS_DISABLED" status: 200 len: 1735 microversion: 1.36
2022-03-09 14:37:34.961523 | ubuntu-focal | 2022-03-09 14:37:32,456 INFO [nova.scheduler.host_manager] Host filter only checking host src and node src
2022-03-09 14:37:34.961528 | ubuntu-focal | 2022-03-09 14:37:32,485 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 19 microversion: 1.28
2022-03-09 14:37:34.961534 | ubuntu-focal | 2022-03-09 14:37:32,541 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 204 len: 0 microversion: 1.36
2022-03-09 14:37:34.961540 | ubuntu-focal | 2022-03-09 14:37:32,737 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 414 microversion: 2.90 time: 0.609876
2022-03-09 14:37:34.961550 | ubuntu-focal | 2022-03-09 14:37:32,901 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.961556 | ubuntu-focal | 2022-03-09 14:37:32,907 INFO [nova.compute.claims] Claim successful on node src
2022-03-09 14:37:34.961564 | ubuntu-focal | 2022-03-09 14:37:32,973 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 1779 microversion: 2.90 time: 0.231145
2022-03-09 14:37:34.961570 | ubuntu-focal | 2022-03-09 14:37:33,208 INFO [nova.virt.libvirt.driver] Instance spawned successfully.
2022-03-09 14:37:34.961575 | ubuntu-focal | 2022-03-09 14:37:33,250 INFO [nova.compute.manager] Took 0.13 seconds to spawn the instance on the hypervisor.
2022-03-09 14:37:34.961581 | ubuntu-focal | 2022-03-09 14:37:33,293 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'src'. Re-created its InstanceList.
2022-03-09 14:37:34.961618 | ubuntu-focal | 2022-03-09 14:37:33,298 INFO [nova.compute.manager] Took 0.48 seconds to build instance.
2022-03-09 14:37:34.961626 | ubuntu-focal | 2022-03-09 14:37:33,591 INFO [nova.api.openstack.requestlog
2022-03-09 14:37:34.961634 | ubuntu-focal | ] 127.0.0.1 "GET /v2.1/servers/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 1868 microversion: 2.90 time: 0.106982
2022-03-09 14:37:34.961640 | ubuntu-focal | 2022-03-09 14:37:33,885 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.961645 | ubuntu-focal | 2022-03-09 14:37:33,901 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.961660 | ubuntu-focal | 2022-03-09 14:37:33,912 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/f2ee6ad9-dfbf-47fa-8d54-d6e56095894f" status: 200 len: 19 microversion: 1.28
2022-03-09 14:37:34.961667 | ubuntu-focal | 2022-03-09 14:37:33,969 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28
2022-03-09 14:37:34.961673 | ubuntu-focal | 2022-03-09 14:37:34,066 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1&root_required=%21COMPUTE_STATUS_DISABLED" status: 200 len: 3423 microversion: 1.36
2022-03-09 14:37:34.961681 | ubuntu-focal | 2022-03-09 14:37:34,106 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: src
2022-03-09 14:37:34.961686 | ubuntu-focal | 2022-03-09 14:37:34,119 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 19 microversion: 1.28
2022-03-09 14:37:34.961692 | ubuntu-focal | 2022-03-09 14:37:34,158 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 204 len: 0 microversion: 1.36
2022-03-09 14:37:34.961719 | ubuntu-focal | 2022-03-09 14:37:34,263 INFO [nova.virt.libvirt.driver] Instance launched has CPU info: {"arch": "x86_64", "model": "Penryn", "vendor": "Intel", "topology": {"cells": 1, "sockets": 1, "cores": 4, "threads": 1}, "features": ["tm", "pbe", "est", "aes", "ds_cpl", "xtpr", "monitor", "vmx", "vme", "ss", "acpi", "ds", "ht", "tm2"]}
2022-03-09 14:37:34.961748 | ubuntu-focal | 2022-03-09 14:37:34,280 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.961761 | ubuntu-focal | 2022-03-09 14:37:34,494 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers/c8e381b7-df10-46f5-8aac-aa6d52f64b4a/action" status: 202 len: 0 microversion: 2.90 time: 0.897295
2022-03-09 14:37:34.961780 | ubuntu-focal | 2022-03-09 14:37:34,596 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 1878 microversion: 2.90 time: 0.097029
2022-03-09 14:37:34.961794 | ubuntu-focal | 2022-03-09 14:37:34,633 ERROR [oslo_messaging.rpc.server] Exception during message handling
2022-03-09 14:37:34.961805 | ubuntu-focal | Traceback (most recent call last):
2022-03-09 14:37:34.961815 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
2022-03-09 14:37:34.961820 | ubuntu-focal | res = self.dispatcher.dispatch(message)
2022-03-09 14:37:34.961826 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/dispatcher.py", line 309, in dispatch
2022-03-09 14:37:34.961831 | ubuntu-focal | return self._do_dispatch(endpoint, method, ctxt, args)
2022-03-09 14:37:34.961838 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/dispatcher.py", line 229, in _do_dispatch
2022-03-09 14:37:34.961843 | ubuntu-focal | result = func(ctxt, **new_args)
2022-03-09 14:37:34.961849 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/exception_wrapper.py", line 71, in wrapped
2022-03-09 14:37:34.961854 | ubuntu-focal | _emit_versioned_exception_notification(
2022-03-09 14:37:34.961866 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 227, in __exit__
2022-03-09 14:37:34.961881 | ubuntu-focal | self.force_reraise()
2022-03-09 14:37:34.961899 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2022-03-09 14:37:34.961910 | ubuntu-focal | raise self.value
2022-03-09 14:37:34.961920 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/exception_wrapper.py", line 63, in wrapped
2022-03-09 14:37:34.961930 | ubuntu-focal | return f(self, context, *args, **kw)
2022-03-09 14:37:34.961939 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/utils.py", line 1439, in decorated_function
2022-03-09 14:37:34.961972 | ubuntu-focal | return function(self, context, *args, **kwargs)
2022-03-09 14:37:34.961985 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 211, in decorated_function
2022-03-09 14:37:34.961994 | ubuntu-focal | compute_utils.add_instance_fault_from_exc(context,
2022-03-09 14:37:34.962004 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/e
2022-03-09 14:37:34.962013 | ubuntu-focal | xcutils.py", line 227, in __exit__
2022-03-09 14:37:34.962021 | ubuntu-focal | self.force_reraise()
2022-03-09 14:37:34.962032 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2022-03-09 14:37:34.962041 | ubuntu-focal | raise self.value
2022-03-09 14:37:34.962051 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 200, in decorated_function
2022-03-09 14:37:34.962060 | ubuntu-focal | return function(self, context, *args, **kwargs)
2022-03-09 14:37:34.962069 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8347, in pre_live_migration
2022-03-09 14:37:34.962078 | ubuntu-focal | bdm.save()
2022-03-09 14:37:34.962088 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 227, in __exit__
2022-03-09 14:37:34.962097 | ubuntu-focal | self.force_reraise()
2022-03-09 14:37:34.962107 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2022-03-09 14:37:34.962115 | ubuntu-focal | raise self.value
2022-03-09 14:37:34.962125 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8303, in pre_live_migration
2022-03-09 14:37:34.962133 | ubuntu-focal | migrate_data = self.driver.pre_live_migration(context,
2022-03-09 14:37:34.962142 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 1100, in __call__
2022-03-09 14:37:34.962152 | ubuntu-focal | return _mock_self._mock_call(*args, **kwargs)
2022-03-09 14:37:34.962161 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 1104, in _mock_call
2022-03-09 14:37:34.962170 | ubuntu-focal | return _mock_self._execute_mock_call(*args, **kwargs)
2022-03-09 14:37:34.962178 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 1161, in _execute_mock_call
2022-03-09 14:37:34.962186 | ubuntu-focal | raise effect
2022-03-09 14:37:34.962195 | ubuntu-focal | nova.exception.DestinationDiskExists: The supplied disk path (/var/non/existent) already exists, it is expected not to exist.
2022-03-09 14:37:34.962206 | ubuntu-focal | 2022-03-09 14:37:34,642 ERROR [nova.compute.manager] Pre live migration failed at dest
2022-03-09 14:37:34.962216 | ubuntu-focal | Traceback (most recent call last):
2022-03-09 14:37:34.962227 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8478, in _do_pre_live_migration_from_source
2022-03-09 14:37:34.962236 | ubuntu-focal | migrate_data = self.compute_rpcapi.pre_live_migration(
2022-03-09 14:37:34.962243 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/rpcapi.py", line 945, in pre_live_migration
2022-03-09 14:37:34.962248 | ubuntu-focal | return cctxt.call(ctxt, 'pre_live_migration',
2022-03-09 14:37:34.962253 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/client.py", line 189, in call
2022-03-09 14:37:34.962259 | ubuntu-focal | result = self.transport._send(
2022-03-09 14:37:34.962264 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/transport.py", line 123, in _send
2022-03-09 14:37:34.962270 | ubuntu-focal | return self._driver.send(target, ctxt, message,
2022-03-09 14:37:34.962275 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/_drivers/impl_fake.py", line 222, in send
2022-03-09 14:37:34.962296 | ubuntu-focal | return self._send(target, ctxt, message, wait_for_reply, timeout,
2022-03-09 14:37:34.962304 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/_drivers/impl_fake.py", line 209, in _send
2022-03-09 14:37:34.962309 | ubuntu-focal | raise failure
2022-03-09 14:37:34.962315 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/server.py", line 165, in _process_incoming
2022-03-09 14:37:34.962320 | ubuntu-focal | res = self.dispatcher.dispatch(message)
2022-03-09 14:37:34.962333 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/dispatcher.py", line 309, in dispatch
2022-03-09 14:37:34.962339 | ubuntu-focal | return self._do_dispatch(endpoint, method, ctxt, args)
2022-03-09 14:37:34.962345 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_messaging/rpc/dispatcher.py", line 229, in _do_dispatch
2022-03-09 14:37:34.962350 | ubuntu-focal | result = func(ctxt, **new_args)
2022-03-09 14:37:34.962356 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/exception_wrapper.py", line 71, in wrapped
2022-03-09 14:37:34.962361 | ubuntu-focal | _emit_versioned_exception_notification(
2022-03-09 14:37:34.962366 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 227, in __exit__
2022-03-09 14:37:34.962372 | ubuntu-focal | self.force_reraise()
2022-03-09 14:37:34.962378 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2022-03-09 14:37:34.962386 | ubuntu-focal | raise self.value
2022-03-09 14:37:34.962392 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/no
2022-03-09 14:37:34.962397 | ubuntu-focal | va/nova/exception_wrapper.py", line 63, in wrapped
2022-03-09 14:37:34.962403 | ubuntu-focal | return f(self, context, *args, **kw)
2022-03-09 14:37:34.962408 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/utils.py", line 1439, in decorated_function
2022-03-09 14:37:34.962416 | ubuntu-focal | return function(self, context, *args, **kwargs)
2022-03-09 14:37:34.962421 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 211, in decorated_function
2022-03-09 14:37:34.962427 | ubuntu-focal | compute_utils.add_instance_fault_from_exc(context,
2022-03-09 14:37:34.962432 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 227, in __exit__
2022-03-09 14:37:34.962447 | ubuntu-focal | self.force_reraise()
2022-03-09 14:37:34.962454 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2022-03-09 14:37:34.962459 | ubuntu-focal | raise self.value
2022-03-09 14:37:34.962465 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 200, in decorated_function
2022-03-09 14:37:34.962470 | ubuntu-focal | return function(self, context, *args, **kwargs)
2022-03-09 14:37:34.962476 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8347, in pre_live_migration
2022-03-09 14:37:34.962482 | ubuntu-focal | bdm.save()
2022-03-09 14:37:34.962493 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 227, in __exit__
2022-03-09 14:37:34.962502 | ubuntu-focal | self.force_reraise()
2022-03-09 14:37:34.962512 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/oslo_utils/excutils.py", line 200, in force_reraise
2022-03-09 14:37:34.962521 | ubuntu-focal | raise self.value
2022-03-09 14:37:34.962531 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/nova/compute/manager.py", line 8303, in pre_live_migration
2022-03-09 14:37:34.962541 | ubuntu-focal | migrate_data = self.driver.pre_live_migration(context,
2022-03-09 14:37:34.962550 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 1100, in __call__
2022-03-09 14:37:34.962579 | ubuntu-focal | return _mock_self._mock_call(*args, **kwargs)
2022-03-09 14:37:34.962592 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 1104, in _mock_call
2022-03-09 14:37:34.962603 | ubuntu-focal | return _mock_self._execute_mock_call(*args, **kwargs)
2022-03-09 14:37:34.962613 | ubuntu-focal | File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py38/lib/python3.8/site-packages/mock/mock.py", line 1161, in _execute_mock_call
2022-03-09 14:37:34.962623 | ubuntu-focal | raise effect
2022-03-09 14:37:34.962632 | ubuntu-focal | nova.exception.DestinationDiskExists: The supplied disk path (/var/non/existent) already exists, it is expected not to exist.
2022-03-09 14:37:34.962641 | ubuntu-focal | 2022-03-09 14:37:34,686 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-migrations" status: 200 len: 510 microversion: 2.90 time: 0.084727
2022-03-09 14:37:34.962651 | ubuntu-focal | 2022-03-09 14:37:34,692 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/f2ee6ad9-dfbf-47fa-8d54-d6e56095894f" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.962661 | ubuntu-focal | 2022-03-09 14:37:34,694 INFO [nova.compute.manager] Swapping old allocation on dict_keys(['7f41f57e-1c75-4533-beb4-2e1f31ce4327']) held by migration f2ee6ad9-dfbf-47fa-8d54-d6e56095894f for instance
2022-03-09 14:37:34.962671 | ubuntu-focal | 2022-03-09 14:37:34,707 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/f2ee6ad9-dfbf-47fa-8d54-d6e56095894f" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.962680 | ubuntu-focal | 2022-03-09 14:37:34,720 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/c8e381b7-df10-46f5-8aac-aa6d52f64b4a" status: 200 len: 230 microversion: 1.28
2022-03-09 14:37:34.962691 | ubuntu-focal | 2022-03-09 14:37:34,780 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28
2022-03-09 14:37:34.962702 | ubuntu-focal | 2022-03-09 14:37:34,805 WARNING [nova.compute.manager] Unable to cancel live migration.
This test was introduced recently by https:/ /review. opendev. org/c/openstack /nova/+ /821840