2022-04-27 22:01:03.099 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lock "71971196-9aea-42bb-9a33-7f0dcff07c90" acquired by "nova.compute.manager.ComputeManager.build_and_run_instance.<locals>._locked_do_build_and_run_instance" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:359
2022-04-27 22:01:03.119 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Starting instance... _do_build_and_run_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2197
2022-04-27 22:01:03.249 7 INFO nova.compute.claims [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Claim successful on node cmp01.dev.example.com
2022-04-27 22:01:03.441 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Start building networks asynchronously for instance. _build_resources /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2576
2022-04-27 22:01:03.523 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Allocating IP information in the background. _allocate_network_async /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:1756
2022-04-27 22:01:03.524 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] allocate_for_instance() allocate_for_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:1119
2022-04-27 22:01:03.538 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Start building block device mappings for instance. _build_resources /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2611
2022-04-27 22:01:03.687 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Start spawning the instance on the hypervisor. _build_and_run_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2396
2022-04-27 22:01:03.689 7 DEBUG nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Creating instance directory _create_image /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py:4528
2022-04-27 22:01:03.690 7 INFO nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Creating image
2022-04-27 22:01:03.692 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lock "/var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk.info" acquired by "nova.virt.libvirt.imagebackend.Image.resolve_driver_format.<locals>.write_to_disk_info_file" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:359
2022-04-27 22:01:03.695 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lock "/var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk.info" released by "nova.virt.libvirt.imagebackend.Image.resolve_driver_format.<locals>.write_to_disk_info_file" :: held 0.003s inner /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:371
2022-04-27 22:01:03.969 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/331c3ebdfb1bc6b12f27c7beae4c1196263daf2f,backing_fmt=raw /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:01:04.006 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] CMD "qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/331c3ebdfb1bc6b12f27c7beae4c1196263daf2f,backing_fmt=raw /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk" returned: 0 in 0.036s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:01:04.007 7 DEBUG nova.virt.disk.api [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Checking if we can resize image /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk. size=1073741824 can_resize_image /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/disk/api.py:167
2022-04-27 22:01:04.007 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:01:04.107 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.099s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:01:04.107 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Running cmd (subprocess): qemu-img resize /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk 1073741824 execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:01:04.136 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] CMD "qemu-img resize /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk 1073741824" returned: 0 in 0.028s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:01:04.215 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Successfully created port: 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 _create_port_minimal /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:533
2022-04-27 22:01:04.239 7 DEBUG nova.virt.disk.api [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Checking if we can resize image /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk. size=1073741824 can_resize_image /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/disk/api.py:167
2022-04-27 22:01:04.240 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:01:04.337 7 DEBUG oslo_concurrency.processutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.097s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:01:04.338 7 DEBUG nova.virt.disk.api [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Cannot resize image /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk to a smaller size. can_resize_image /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/disk/api.py:173
2022-04-27 22:01:04.338 7 DEBUG nova.objects.instance [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lazy-loading 'migration_context' on Instance uuid 71971196-9aea-42bb-9a33-7f0dcff07c90 obj_load_attr /var/lib/kolla/venv/lib/python3.6/site-packages/nova/objects/instance.py:1101
2022-04-27 22:01:04.360 7 DEBUG nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Created local disks _create_image /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py:4655
2022-04-27 22:01:04.360 7 DEBUG nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Ensure instance console log exists: /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/console.log _ensure_console_log_for_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py:4419
2022-04-27 22:01:05.291 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Successfully updated port: 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 _update_port /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:571
2022-04-27 22:01:05.304 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Acquired lock "refresh_cache-71971196-9aea-42bb-9a33-7f0dcff07c90" lock /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:266
2022-04-27 22:01:05.304 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Building network info cache for instance _get_instance_nw_info /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:1883
2022-04-27 22:01:05.375 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Instance cache missing network info. _get_preexisting_port_ids /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:3159
2022-04-27 22:01:05.606 7 DEBUG nova.compute.resource_tracker [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Instance 71971196-9aea-42bb-9a33-7f0dcff07c90 actively managed on this compute host and has allocations in placement: {'resources': {'DISK_GB': 1, 'MEMORY_MB': 1024, 'VCPU': 1}}. _remove_deleted_instances_allocations /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/resource_tracker.py:1559
2022-04-27 22:01:05.728 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Updating instance_info_cache with network_info: [{"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}}] update_instance_cache_with_nw_info /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:118
2022-04-27 22:01:05.744 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Releasing lock "refresh_cache-71971196-9aea-42bb-9a33-7f0dcff07c90" lock /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:282
2022-04-27 22:01:05.745 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Instance network_info: |[{"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}}]| _allocate_network_async /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:1771
2022-04-27 22:01:05.746 7 DEBUG nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Start _get_guest_xml network_info=[{"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}}] disk_info={'disk_bus': 'virtio', 'cdrom_bus': 'ide', 'mapping': {'root': {'bus': 'virtio', 'type': 'disk', 'dev': 'vda', 'boot_index': '1'}, 'disk': {'bus': 'virtio', 'type': 'disk', 'dev': 'vda', 'boot_index': '1'}}} image_meta=ImageMeta(checksum='b874c39491a2377b8490f5f1e89761a4',container_format='bare',created_at=2022-04-27T11:39:34Z,direct_url=<?>,disk_format='qcow2',id=d0842e59-243a-4a8b-b092-7f3ff67b862e,min_disk=0,min_ram=0,name='Cirros-0.5.2',owner='ea71b4f46dc3428382e74d009bc857dc',properties=ImageMetaProps,protected=<?>,size=16300544,status='active',tags=<?>,updated_at=2022-04-27T11:39:34Z,virtual_size=<?>,visibility=<?>) rescue=None block_device_info={'root_device_name': '/dev/vda', 'ephemerals': [], 'block_device_mapping': [], 'swap': None} _get_guest_xml /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py:7063
2022-04-27 22:01:05.763 7 DEBUG nova.virt.libvirt.vif [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2022-04-27T19:01:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='s_rally_b673429f_y9geXNk8',display_name='s_rally_b673429f_y9geXNk8',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(525),hidden=False,host='cmp01.dev.example.com',hostname='s-rally-b673429f-y9gexnk8',id=4143,image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',info_cache=InstanceInfoCache,instance_type_id=525,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='cmp01.dev.example.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=None,new_flavor=None,node='cmp01.dev.example.com',numa_topology=None,old_flavor=None,os_type='linux',pci_devices=<?>,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='1c168227db7d4053abb49960a6033124',ramdisk_id='',reservation_id='r-9i0hurwj',resources=None,root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member',image_base_image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',image_container_format='bare',image_disk_format='qcow2',image_hw_machine_type='pc',image_min_disk='1',image_min_ram='0',image_os_type='linux',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/Cirros-0.5.2',image_owner_specified.openstack.sha256='',network_allocated='True',owner_project_name='c_rally_b673429f_9DrFtYSf',owner_user_name='c_rally_b673429f_r952EXk9'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2022-04-27T19:01:03Z,user_data=None,user_id='f08d31bec4e648e0a70a7a6df4eeea0e',uuid=71971196-9aea-42bb-9a33-7f0dcff07c90,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} virt_type=kvm get_config /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/vif.py:575
2022-04-27 22:01:05.767 7 DEBUG nova.objects.instance [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lazy-loading 'pci_devices' on Instance uuid 71971196-9aea-42bb-9a33-7f0dcff07c90 obj_load_attr /var/lib/kolla/venv/lib/python3.6/site-packages/nova/objects/instance.py:1101
2022-04-27 22:01:05.791 7 DEBUG nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] End _get_guest_xml xml=<domain type="kvm">
  <uuid>71971196-9aea-42bb-9a33-7f0dcff07c90</uuid>
      <entry name="serial">71971196-9aea-42bb-9a33-7f0dcff07c90</entry>
      <entry name="uuid">71971196-9aea-42bb-9a33-7f0dcff07c90</entry>
      <source file="/var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk"/>
      <log file="/var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/console.log" append="off"/>
2022-04-27 22:01:05.792 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Preparing to wait for external event network-vif-plugged-13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 prepare_for_instance_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:281
2022-04-27 22:01:05.793 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lock "71971196-9aea-42bb-9a33-7f0dcff07c90-events" acquired by "nova.compute.manager.InstanceEvents.prepare_for_instance_event.<locals>._create_or_get_event" :: waited 0.000s inner /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:359
2022-04-27 22:01:05.793 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lock "71971196-9aea-42bb-9a33-7f0dcff07c90-events" released by "nova.compute.manager.InstanceEvents.prepare_for_instance_event.<locals>._create_or_get_event" :: held 0.001s inner /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:371
2022-04-27 22:01:05.795 7 DEBUG nova.virt.libvirt.vif [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2022-04-27T19:01:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='s_rally_b673429f_y9geXNk8',display_name='s_rally_b673429f_y9geXNk8',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(525),hidden=False,host='cmp01.dev.example.com',hostname='s-rally-b673429f-y9gexnk8',id=4143,image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',info_cache=InstanceInfoCache,instance_type_id=525,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='cmp01.dev.example.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=None,new_flavor=None,node='cmp01.dev.example.com',numa_topology=None,old_flavor=None,os_type='linux',pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='1c168227db7d4053abb49960a6033124',ramdisk_id='',reservation_id='r-9i0hurwj',resources=None,root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member',image_base_image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',image_container_format='bare',image_disk_format='qcow2',image_hw_machine_type='pc',image_min_disk='1',image_min_ram='0',image_os_type='linux',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/Cirros-0.5.2',image_owner_specified.openstack.sha256='',network_allocated='True',owner_project_name='c_rally_b673429f_9DrFtYSf',owner_user_name='c_rally_b673429f_r952EXk9'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2022-04-27T19:01:03Z,user_data=None,user_id='f08d31bec4e648e0a70a7a6df4eeea0e',uuid=71971196-9aea-42bb-9a33-7f0dcff07c90,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} plug /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/vif.py:721
2022-04-27 22:01:05.805 7 DEBUG ovsdbapp.backend.ovs_idl.transaction [-] Running txn n=1 command(idx=1): DbSetCommand(table=Interface, record=tap13c6ac02-b1, col_values=(('external_ids', {'iface-id': '13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36', 'iface-status': 'active', 'attached-mac': 'fa:16:3e:b1:c2:c1', 'vm-uuid': '71971196-9aea-42bb-9a33-7f0dcff07c90'}),)) do_commit /var/lib/kolla/venv/lib/python3.6/site-packages/ovsdbapp/backend/ovs_idl/transaction.py:91
2022-04-27 22:01:06.824 7 DEBUG nova.virt.driver [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] Emitting event <LifecycleEvent: 1651086066.8240051, 71971196-9aea-42bb-9a33-7f0dcff07c90 => Started> emit_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/driver.py:1609
2022-04-27 22:01:06.825 7 INFO nova.compute.manager [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] VM Started (Lifecycle Event)
2022-04-27 22:01:06.846 7 DEBUG nova.compute.manager [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Checking state _get_power_state /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:1564
2022-04-27 22:01:06.850 7 DEBUG nova.virt.driver [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] Emitting event <LifecycleEvent: 1651086066.8256304, 71971196-9aea-42bb-9a33-7f0dcff07c90 => Paused> emit_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/driver.py:1609
2022-04-27 22:01:06.851 7 INFO nova.compute.manager [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] VM Paused (Lifecycle Event)
2022-04-27 22:01:06.883 7 DEBUG nova.compute.manager [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Checking state _get_power_state /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:1564
2022-04-27 22:01:06.895 7 DEBUG nova.compute.manager [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Synchronizing instance power state after lifecycle event "Paused"; current vm_state: building, current task_state: spawning, current DB power_state: 0, VM power_state: 3 handle_lifecycle_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:1294
2022-04-27 22:01:06.922 7 INFO nova.compute.manager [req-e8474a31-19e0-46b4-b8fa-13b7f0eec5f9 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] During sync_power_state the instance has a pending task (spawning). Skip.
2022-04-27 22:01:07.209 7 DEBUG nova.compute.manager [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Received event network-changed-13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 external_instance_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:10483
2022-04-27 22:01:07.209 7 DEBUG nova.compute.manager [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Refreshing instance network info cache due to event network-changed-13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36. external_instance_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:10487
2022-04-27 22:01:07.210 7 DEBUG oslo_concurrency.lockutils [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] Acquired lock "refresh_cache-71971196-9aea-42bb-9a33-7f0dcff07c90" lock /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:266
2022-04-27 22:01:07.210 7 DEBUG nova.network.neutron [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Refreshing network info cache for port 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36 _get_instance_nw_info /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:1880
2022-04-27 22:01:07.678 7 DEBUG nova.network.neutron [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Updated VIF entry in instance network info cache for port 13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36. _build_network_info_model /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:3294
2022-04-27 22:01:07.679 7 DEBUG nova.network.neutron [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Updating instance_info_cache with network_info: [{"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}}] update_instance_cache_with_nw_info /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:118
2022-04-27 22:01:07.695 7 DEBUG oslo_concurrency.lockutils [req-86b71455-579c-4a53-b946-83bc6a710940 302de995f0ee4a52b12c4bfb456eff74 7b7fdf198f674397ae0a9e7038b6cc07 - default default] Releasing lock "refresh_cache-71971196-9aea-42bb-9a33-7f0dcff07c90" lock /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:282
2022-04-27 22:02:02.061 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:02:02.162 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.101s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:02:02.164 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:02:02.260 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.095s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:02:11.012 7 DEBUG nova.compute.resource_tracker [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Instance 71971196-9aea-42bb-9a33-7f0dcff07c90 actively managed on this compute host and has allocations in placement: {'resources': {'DISK_GB': 1, 'MEMORY_MB': 1024, 'VCPU': 1}}. _remove_deleted_instances_allocations /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/resource_tracker.py:1559
2022-04-27 22:03:03.748 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:03:03.862 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.114s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:03:03.865 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:03:03.972 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.107s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:03:13.582 7 DEBUG nova.compute.resource_tracker [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Instance 71971196-9aea-42bb-9a33-7f0dcff07c90 actively managed on this compute host and has allocations in placement: {'resources': {'DISK_GB': 1, 'MEMORY_MB': 1024, 'VCPU': 1}}. _remove_deleted_instances_allocations /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/resource_tracker.py:1559
2022-04-27 22:04:05.911 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:04:06.014 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.103s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:04:06.016 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:04:06.115 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.099s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:04:16.011 7 DEBUG nova.compute.resource_tracker [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Instance 71971196-9aea-42bb-9a33-7f0dcff07c90 actively managed on this compute host and has allocations in placement: {'resources': {'DISK_GB': 1, 'MEMORY_MB': 1024, 'VCPU': 1}}. _remove_deleted_instances_allocations /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/resource_tracker.py:1559
2022-04-27 22:04:58.265 7 DEBUG nova.compute.manager [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Skipping network cache update for instance because it is Building. _heal_instance_info_cache /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:9328
2022-04-27 22:05:05.720 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:05:05.826 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.106s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:05:05.828 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:05:05.930 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.101s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:05:15.924 7 DEBUG nova.compute.resource_tracker [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Instance 71971196-9aea-42bb-9a33-7f0dcff07c90 actively managed on this compute host and has allocations in placement: {'resources': {'DISK_GB': 1, 'MEMORY_MB': 1024, 'VCPU': 1}}. _remove_deleted_instances_allocations /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/resource_tracker.py:1559
2022-04-27 22:05:20.769 7 DEBUG nova.virt.libvirt.imagecache [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] 71971196-9aea-42bb-9a33-7f0dcff07c90 is a valid instance name _list_backing_images /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/imagecache.py:126
2022-04-27 22:05:20.770 7 DEBUG nova.virt.libvirt.imagecache [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] 71971196-9aea-42bb-9a33-7f0dcff07c90 has a disk file _list_backing_images /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/imagecache.py:129
2022-04-27 22:05:20.770 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Running cmd (subprocess): /var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:384
2022-04-27 22:05:20.864 7 DEBUG oslo_concurrency.processutils [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] CMD "/var/lib/kolla/venv/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 --cpu=30 -- env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90/disk --force-share --output=json" returned: 0 in 0.093s execute /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/processutils.py:423
2022-04-27 22:05:20.865 7 DEBUG nova.virt.libvirt.imagecache [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Instance 71971196-9aea-42bb-9a33-7f0dcff07c90 is backed by 331c3ebdfb1bc6b12f27c7beae4c1196263daf2f _list_backing_images /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/imagecache.py:144
2022-04-27 22:06:06.825 7 WARNING nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Timeout waiting for [('network-vif-plugged', '13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36')] for instance with vm_state building and task_state spawning: eventlet.timeout.Timeout: 300 seconds
2022-04-27 22:06:07.302 7 DEBUG nova.virt.libvirt.vif [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=False,config_drive='',created_at=2022-04-27T19:01:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='s_rally_b673429f_y9geXNk8',display_name='s_rally_b673429f_y9geXNk8',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(525),hidden=False,host='cmp01.dev.example.com',hostname='s-rally-b673429f-y9gexnk8',id=4143,image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',info_cache=InstanceInfoCache,instance_type_id=525,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='cmp01.dev.example.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=None,new_flavor=None,node='cmp01.dev.example.com',numa_topology=None,old_flavor=None,os_type='linux',pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='1c168227db7d4053abb49960a6033124',ramdisk_id='',reservation_id='r-9i0hurwj',resources=None,root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member',image_base_image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',image_container_format='bare',image_disk_format='qcow2',image_hw_machine_type='pc',image_min_disk='1',image_min_ram='0',image_os_type='linux',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/Cirros-0.5.2',image_owner_specified.openstack.sha256='',network_allocated='True',owner_project_name='c_rally_b673429f_9DrFtYSf',owner_user_name='c_rally_b673429f_r952EXk9'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2022-04-27T19:01:03Z,user_data=None,user_id='f08d31bec4e648e0a70a7a6df4eeea0e',uuid=71971196-9aea-42bb-9a33-7f0dcff07c90,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} unplug /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/vif.py:839
2022-04-27 22:06:07.344 7 INFO nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Deleting instance files /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90_del
2022-04-27 22:06:07.348 7 INFO nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Deletion of /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90_del complete
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Instance failed to spawn: nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Traceback (most recent call last):
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 7265, in _create_guest_with_network
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     post_xml_callback=post_xml_callback)
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/usr/lib64/python3.6/contextlib.py", line 88, in __exit__
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     next(self.gen)
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py", line 479, in wait_for_instance_event
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     actual_event = event.wait()
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/eventlet/event.py", line 125, in wait
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     result = hub.switch()
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/eventlet/hubs/hub.py", line 313, in switch
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     return self.greenlet.switch()
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] eventlet.timeout.Timeout: 300 seconds
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] 
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] During handling of the above exception, another exception occurred:
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] 
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Traceback (most recent call last):
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py", line 2638, in _build_resources
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     yield resources
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py", line 2402, in _build_and_run_instance
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     accel_info=accel_info)
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 4230, in spawn
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     cleanup_instance_disks=created_disks)
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 7288, in _create_guest_with_network
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     raise exception.VirtualInterfaceCreateException()
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
2022-04-27 22:06:07.440 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] 
2022-04-27 22:06:07.443 7 INFO nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Terminating instance
2022-04-27 22:06:07.445 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Start destroying the instance on the hypervisor. _shutdown_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2895
2022-04-27 22:06:07.450 7 DEBUG nova.virt.libvirt.driver [-] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] During wait destroy, instance disappeared. _wait_for_destroy /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py:1388
2022-04-27 22:06:07.450 7 INFO nova.virt.libvirt.driver [-] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Instance destroyed successfully.
2022-04-27 22:06:07.452 7 DEBUG nova.virt.libvirt.vif [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2022-04-27T19:01:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='s_rally_b673429f_y9geXNk8',display_name='s_rally_b673429f_y9geXNk8',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(525),hidden=False,host='cmp01.dev.example.com',hostname='s-rally-b673429f-y9gexnk8',id=4143,image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',info_cache=InstanceInfoCache,instance_type_id=525,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='cmp01.dev.example.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=None,new_flavor=None,node='cmp01.dev.example.com',numa_topology=None,old_flavor=None,os_type='linux',pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='1c168227db7d4053abb49960a6033124',ramdisk_id='',reservation_id='r-9i0hurwj',resources=None,root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member',clean_attempts='1',image_base_image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',image_container_format='bare',image_disk_format='qcow2',image_hw_machine_type='pc',image_min_disk='1',image_min_ram='0',image_os_type='linux',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/Cirros-0.5.2',image_owner_specified.openstack.sha256='',network_allocated='True',owner_project_name='c_rally_b673429f_9DrFtYSf',owner_user_name='c_rally_b673429f_r952EXk9'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2022-04-27T19:01:03Z,user_data=None,user_id='f08d31bec4e648e0a70a7a6df4eeea0e',uuid=71971196-9aea-42bb-9a33-7f0dcff07c90,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} unplug /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/vif.py:839
2022-04-27 22:06:07.462 7 INFO nova.virt.libvirt.driver [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Deletion of /var/lib/nova/instances/71971196-9aea-42bb-9a33-7f0dcff07c90_del complete
2022-04-27 22:06:07.538 7 INFO nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Took 0.09 seconds to destroy the instance on the hypervisor.
2022-04-27 22:06:07.540 7 DEBUG nova.compute.claims [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Aborting claim: <nova.compute.claims.Claim object at 0x7fe445d429b0> abort /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/claims.py:84
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Failed to allocate network(s): nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Traceback (most recent call last):
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 7265, in _create_guest_with_network
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     post_xml_callback=post_xml_callback)
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/usr/lib64/python3.6/contextlib.py", line 88, in __exit__
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     next(self.gen)
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py", line 479, in wait_for_instance_event
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     actual_event = event.wait()
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/eventlet/event.py", line 125, in wait
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     result = hub.switch()
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/eventlet/hubs/hub.py", line 313, in switch
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     return self.greenlet.switch()
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] eventlet.timeout.Timeout: 300 seconds
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] 
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] During handling of the above exception, another exception occurred:
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] 
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Traceback (most recent call last):
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py", line 2402, in _build_and_run_instance
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     accel_info=accel_info)
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 4230, in spawn
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     cleanup_instance_disks=created_disks)
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]   File "/var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/driver.py", line 7288, in _create_guest_with_network
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90]     raise exception.VirtualInterfaceCreateException()
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] nova.exception.VirtualInterfaceCreateException: Virtual Interface creation failed
2022-04-27 22:06:07.703 7 ERROR nova.compute.manager [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] 
2022-04-27 22:06:07.704 7 DEBUG nova.compute.utils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Virtual Interface creation failed notify_about_instance_usage /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/utils.py:426
2022-04-27 22:06:07.705 7 ERROR nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Build of instance 71971196-9aea-42bb-9a33-7f0dcff07c90 aborted: Failed to allocate the network(s), not rescheduling.: nova.exception.BuildAbortException: Build of instance 71971196-9aea-42bb-9a33-7f0dcff07c90 aborted: Failed to allocate the network(s), not rescheduling.
2022-04-27 22:06:07.706 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Unplugging VIFs for instance _cleanup_allocated_networks /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2750
2022-04-27 22:06:07.707 7 DEBUG nova.virt.libvirt.vif [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2022-04-27T19:01:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,device_metadata=None,disable_terminate=False,display_description='s_rally_b673429f_y9geXNk8',display_name='s_rally_b673429f_y9geXNk8',ec2_ids=EC2Ids,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(525),hidden=False,host='cmp01.dev.example.com',hostname='s-rally-b673429f-y9gexnk8',id=4143,image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',info_cache=InstanceInfoCache,instance_type_id=525,kernel_id='',key_data=None,key_name=None,keypairs=KeyPairList,launch_index=0,launched_at=None,launched_on='cmp01.dev.example.com',locked=False,locked_by=None,memory_mb=1024,metadata={},migration_context=None,new_flavor=None,node='cmp01.dev.example.com',numa_topology=None,old_flavor=None,os_type='linux',pci_devices=PciDeviceList,pci_requests=InstancePCIRequests,power_state=0,progress=0,project_id='1c168227db7d4053abb49960a6033124',ramdisk_id='',reservation_id='r-9i0hurwj',resources=None,root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={boot_roles='reader,member',clean_attempts='2',image_base_image_ref='d0842e59-243a-4a8b-b092-7f3ff67b862e',image_container_format='bare',image_disk_format='qcow2',image_hw_machine_type='pc',image_min_disk='1',image_min_ram='0',image_os_type='linux',image_owner_specified.openstack.md5='',image_owner_specified.openstack.object='images/Cirros-0.5.2',image_owner_specified.openstack.sha256='',network_allocated='True',owner_project_name='c_rally_b673429f_9DrFtYSf',owner_user_name='c_rally_b673429f_r952EXk9'},tags=TagList,task_state='spawning',terminated_at=None,trusted_certs=None,updated_at=2022-04-27T19:06:07Z,user_data=None,user_id='f08d31bec4e648e0a70a7a6df4eeea0e',uuid=71971196-9aea-42bb-9a33-7f0dcff07c90,vcpu_model=VirtCPUModel,vcpus=1,vm_mode=None,vm_state='building') vif={"id": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "address": "fa:16:3e:b1:c2:c1", "network": {"id": "0c6f5ab8-5bad-41f0-b6aa-72b98b85c175", "bridge": "br-int", "label": "c_rally_b673429f_r7h1dXHt", "subnets": [{"cidr": "1.20.0.0/16", "dns": [{"address": "8.8.8.8", "type": "dns", "version": 4, "meta": {}}, {"address": "8.8.4.4", "type": "dns", "version": 4, "meta": {}}], "gateway": {"address": "1.20.0.1", "type": "gateway", "version": 4, "meta": {}}, "ips": [{"address": "1.20.1.216", "type": "fixed", "version": 4, "meta": {}, "floating_ips": []}], "routes": [], "version": 4, "meta": {"dhcp_server": "1.20.0.1"}}], "meta": {"injected": false, "tenant_id": "1c168227db7d4053abb49960a6033124", "mtu": 1450, "physical_network": null, "tunneled": true}}, "type": "ovs", "details": {"port_filter": true, "connectivity": "l2"}, "devname": "tap13c6ac02-b1", "ovs_interfaceid": "13c6ac02-b1fa-4d8a-90e4-bdb3a4dd8a36", "qbh_params": null, "qbg_params": null, "active": false, "vnic_type": "normal", "profile": {}, "preserve_on_delete": false, "delegate_create": true, "meta": {}} unplug /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/libvirt/vif.py:839
2022-04-27 22:06:07.718 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Unplugged VIFs for instance _cleanup_allocated_networks /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2786
2022-04-27 22:06:07.718 7 DEBUG nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Deallocating network for instance _deallocate_network /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:2057
2022-04-27 22:06:07.719 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] deallocate_for_instance() deallocate_for_instance /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:1675
2022-04-27 22:06:07.726 7 WARNING nova.virt.libvirt.driver [req-2711a01e-9822-4f66-a4bc-1a6091edb2aa - - - - -] Error from libvirt while getting description of instance-0000102f: [Error Code 42] Domain not found: no domain with matching uuid '71971196-9aea-42bb-9a33-7f0dcff07c90' (instance-0000102f): libvirt.libvirtError: Domain not found: no domain with matching uuid '71971196-9aea-42bb-9a33-7f0dcff07c90' (instance-0000102f)
2022-04-27 22:06:08.218 7 DEBUG nova.network.neutron [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Updating instance_info_cache with network_info: [] update_instance_cache_with_nw_info /var/lib/kolla/venv/lib/python3.6/site-packages/nova/network/neutron.py:118
2022-04-27 22:06:08.236 7 INFO nova.compute.manager [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Took 0.52 seconds to deallocate network for instance.
2022-04-27 22:06:08.489 7 INFO nova.scheduler.client.report [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Deleted allocations for instance 71971196-9aea-42bb-9a33-7f0dcff07c90
2022-04-27 22:06:08.490 7 DEBUG oslo_concurrency.lockutils [req-be79d0ca-7aaf-4514-96b5-ec553777a322 f08d31bec4e648e0a70a7a6df4eeea0e 1c168227db7d4053abb49960a6033124 - default default] Lock "71971196-9aea-42bb-9a33-7f0dcff07c90" released by "nova.compute.manager.ComputeManager.build_and_run_instance.<locals>._locked_do_build_and_run_instance" :: held 305.391s inner /var/lib/kolla/venv/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:371
2022-04-27 22:06:22.297 7 DEBUG nova.virt.driver [-] Emitting event <LifecycleEvent: 1651086367.2943962, 71971196-9aea-42bb-9a33-7f0dcff07c90 => Stopped> emit_event /var/lib/kolla/venv/lib/python3.6/site-packages/nova/virt/driver.py:1609
2022-04-27 22:06:22.298 7 INFO nova.compute.manager [-] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] VM Stopped (Lifecycle Event)
2022-04-27 22:06:22.317 7 DEBUG nova.compute.manager [req-ae04c341-00b4-41a1-b7db-819564093846 - - - - -] [instance: 71971196-9aea-42bb-9a33-7f0dcff07c90] Checking state _get_power_state /var/lib/kolla/venv/lib/python3.6/site-packages/nova/compute/manager.py:1564