Public bug reported: Seen here:
https://35ea41893426ced4e7b7-c7b305d9ddba843cc11c9f16befc26b2.ssl.cf1.rackcdn.com/699291/4/check /nova-tox-functional-py36/6f68741/testr_results.html.gz ft1.12: nova.tests.functional.test_cross_cell_migrate.TestMultiCellMigrate.test_poll_unconfirmed_resizes_with_upcalltesttools.testresult.real._StringException: pythonlogging:'': {{{ 2020-01-07 12:39:14,920 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring. 2020-01-07 12:39:15,344 INFO [nova.service] Starting conductor node (version 20.1.0) 2020-01-07 12:39:15,379 INFO [nova.service] Starting scheduler node (version 20.1.0) 2020-01-07 12:39:15,425 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver' 2020-01-07 12:39:15,426 INFO [nova.service] Starting compute node (version 20.1.0) 2020-01-07 12:39:15,443 WARNING [nova.compute.manager] Compute node host1 not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,447 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host 2020-01-07 12:39:15,457 WARNING [nova.compute.manager] No compute node record found for host host1. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,462 WARNING [nova.compute.resource_tracker] No compute node record for host1:host1 2020-01-07 12:39:15,466 INFO [nova.compute.resource_tracker] Compute node record created for host1:host1 with uuid: 30117184-3985-48b6-8e7e-5611c45c112c 2020-01-07 12:39:15,509 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=30117184-3985-48b6-8e7e-5611c45c112c" status: 200 len: 26 microversion: 1.14 2020-01-07 12:39:15,518 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20 2020-01-07 12:39:15,519 INFO [nova.scheduler.client.report] [req-6c8c5604-6d3d-49b4-ae66-3aadfeb1ff27] Created resource provider record via placement API for resource provider with UUID 30117184-3985-48b6-8e7e-5611c45c112c and name host1. 2020-01-07 12:39:15,536 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/inventories" status: 200 len: 401 microversion: 1.26 2020-01-07 12:39:15,545 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_DEVICE_TAGGING,COMPUTE_VOLUME_EXTEND,COMPUTE_NODE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_IMAGE_TYPE_RAW" status: 200 len: 268 microversion: 1.6 2020-01-07 12:39:15,561 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/traits" status: 200 len: 303 microversion: 1.6 2020-01-07 12:39:15,589 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates" status: 200 len: 221 microversion: 2.81 time: 0.021327 2020-01-07 12:39:15,634 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?name=host1" status: 200 len: 432 microversion: 1.0 2020-01-07 12:39:15,643 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/aggregates" status: 200 len: 53 microversion: 1.19 2020-01-07 12:39:15,655 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/aggregates" status: 200 len: 91 microversion: 1.19 2020-01-07 12:39:15,665 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates/1/action" status: 200 len: 285 microversion: 2.81 time: 0.072452 2020-01-07 12:39:15,683 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver' 2020-01-07 12:39:15,684 INFO [nova.service] Starting compute node (version 20.1.0) 2020-01-07 12:39:15,703 WARNING [nova.compute.manager] Compute node host2 not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,708 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host 2020-01-07 12:39:15,718 WARNING [nova.compute.manager] No compute node record found for host host2. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,723 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2 2020-01-07 12:39:15,732 INFO [nova.compute.resource_tracker] Compute node record created for host2:host2 with uuid: 7e192b8c-5187-467c-8e7e-f8360fbce19e 2020-01-07 12:39:15,774 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=7e192b8c-5187-467c-8e7e-f8360fbce19e" status: 200 len: 26 microversion: 1.14 2020-01-07 12:39:15,782 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20 2020-01-07 12:39:15,783 INFO [nova.scheduler.client.report] [req-ddaf886c-9f05-4fa2-9c4d-b0317c78e47f] Created resource provider record via placement API for resource provider with UUID 7e192b8c-5187-467c-8e7e-f8360fbce19e and name host2. 2020-01-07 12:39:15,803 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/inventories" status: 200 len: 401 microversion: 1.26 2020-01-07 12:39:15,813 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_DEVICE_TAGGING,COMPUTE_VOLUME_EXTEND,COMPUTE_NODE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_IMAGE_TYPE_RAW" status: 200 len: 268 microversion: 1.6 2020-01-07 12:39:15,831 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/traits" status: 200 len: 303 microversion: 1.6 2020-01-07 12:39:15,850 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates" status: 200 len: 221 microversion: 2.81 time: 0.012939 2020-01-07 12:39:15,889 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?name=host2" status: 200 len: 432 microversion: 1.0 2020-01-07 12:39:15,899 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/aggregates" status: 200 len: 53 microversion: 1.19 2020-01-07 12:39:15,912 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/aggregates" status: 200 len: 91 microversion: 1.19 2020-01-07 12:39:15,927 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates/2/action" status: 200 len: 285 microversion: 2.81 time: 0.072743 2020-01-07 12:39:15,947 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/flavors/detail" status: 200 len: 2605 microversion: 2.81 time: 0.016728 2020-01-07 12:39:16,012 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 412 microversion: 2.81 time: 0.061068 2020-01-07 12:39:16,037 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 1774 microversion: 2.81 time: 0.020963 2020-01-07 12:39:16,141 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1491 microversion: 1.34 2020-01-07 12:39:16,188 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 19 microversion: 1.28 2020-01-07 12:39:16,220 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 204 len: 0 microversion: 1.34 2020-01-07 12:39:16,450 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 230 microversion: 1.28 2020-01-07 12:39:16,459 INFO [nova.compute.claims] Claim successful on node host1 2020-01-07 12:39:17,267 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 1852 microversion: 2.81 time: 0.715882 2020-01-07 12:39:17,324 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor. 2020-01-07 12:39:17,378 INFO [nova.compute.manager] Took 0.94 seconds to build instance. 2020-01-07 12:39:17,423 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList. 2020-01-07 12:39:17,858 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2049 microversion: 2.81 time: 0.085234 2020-01-07 12:39:17,888 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/limits" status: 200 len: 304 microversion: 2.81 time: 0.025623 2020-01-07 12:39:18,037 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/action" status: 202 len: 0 microversion: 2.81 time: 0.144296 2020-01-07 12:39:18,178 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2060 microversion: 2.81 time: 0.137591 2020-01-07 12:39:18,226 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 230 microversion: 1.28 2020-01-07 12:39:18,236 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 230 microversion: 1.28 2020-01-07 12:39:18,247 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/f6b8ee46-9d48-4baa-bea3-9cf8ab4e1337" status: 200 len: 19 microversion: 1.28 2020-01-07 12:39:18,309 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2020-01-07 12:39:18,363 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=DISK_GB%3A20%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 1497 microversion: 1.34 2020-01-07 12:39:18,396 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: host1 2020-01-07 12:39:18,406 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 19 microversion: 1.28 2020-01-07 12:39:18,433 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 204 len: 0 microversion: 1.34 2020-01-07 12:39:18,443 INFO [nova.conductor.tasks.migrate] Executing cross-cell resize task starting with target host: host2 2020-01-07 12:39:18,611 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 232 microversion: 1.28 2020-01-07 12:39:18,620 INFO [nova.compute.claims] Claim successful on node host2 2020-01-07 12:39:18,636 INFO [nova.compute.resource_tracker] Updating resource usage from migration f6b8ee46-9d48-4baa-bea3-9cf8ab4e1337 2020-01-07 12:39:18,901 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2060 microversion: 2.81 time: 0.211517 2020-01-07 12:39:18,951 INFO [nova.compute.manager] Preparing for snapshot based resize on source host host1. 2020-01-07 12:39:19,146 INFO [nova.compute.manager] Finishing snapshot based resize on destination host host2. 2020-01-07 12:39:19,218 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 232 microversion: 1.28 2020-01-07 12:39:19,368 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host2'. Re-created its InstanceList. 2020-01-07 12:39:19,579 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2064 microversion: 2.81 time: 0.162860 2020-01-07 12:39:20,173 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2062 microversion: 2.81 time: 0.088806 2020-01-07 12:39:20,385 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/detail" status: 200 len: 2044 microversion: 2.81 time: 0.207618 2020-01-07 12:39:20,423 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-migrations?instance_uuid=e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 520 microversion: 2.81 time: 0.034696 2020-01-07 12:39:20,468 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-instance-actions" status: 200 len: 645 microversion: 2.81 time: 0.040943 2020-01-07 12:39:20,517 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-instance-actions/req-f6f0b421-4a08-43c8-9227-679b3ab8f8bc" status: 200 len: 1338 microversion: 2.81 time: 0.045893 2020-01-07 12:39:20,567 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-instance-actions/req-0e5a96f5-1103-4878-8cb1-e12e458e37dc" status: 200 len: 607 microversion: 2.81 time: 0.045760 2020-01-07 12:39:20,595 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.81 time: 0.023762 2020-01-07 12:39:20,618 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/allocations" status: 200 len: 152 microversion: 1.0 2020-01-07 12:39:20,655 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors?hypervisor_hostname_pattern=host2" status: 200 len: 133 microversion: 2.81 time: 0.031607 2020-01-07 12:39:20,668 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/allocations" status: 200 len: 154 microversion: 1.0 2020-01-07 12:39:20,750 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-interface" status: 200 len: 303 microversion: 2.81 time: 0.046221 2020-01-07 12:39:20,770 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors/30117184-3985-48b6-8e7e-5611c45c112c" status: 200 len: 693 microversion: 2.53 time: 0.015973 2020-01-07 12:39:20,792 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors/7e192b8c-5187-467c-8e7e-f8360fbce19e" status: 200 len: 694 microversion: 2.53 time: 0.018579 2020-01-07 12:39:20,822 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/limits" status: 200 len: 305 microversion: 2.81 time: 0.026690 2020-01-07 12:39:20,827 WARNING [nova.tests.unit.image.fake] Unable to find image id 3f72d534-d153-49cd-aba8-226207886b17. Have images: {'155d900f-4e14-4e4c-a73d-069cbf4541e6': {'id': '155d900f-4e14-4e4c-a73d-069cbf4541e6', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': False, 'container_format': 'raw', 'disk_format': 'raw', 'size': '25165824', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': ['tag1', 'tag2'], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64'}}, 'a2459075-d96c-40d5-893e-577ff92e721c': {'id': 'a2459075-d96c-40d5-893e-577ff92e721c', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'ami', 'disk_format': 'ami', 'size': '58145823', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel'}}, '76fa36fc-c930-4bf3-8c8a-ea2a2420deb6': {'id': '76fa36fc-c930-4bf3-8c8a-ea2a2420deb6', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'bare', 'disk_format': 'raw', 'size': '83594576', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': ['tag3', 'tag4'], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64'}}, 'cedef40a-ed67-4d10-800e-17455edce175': {'id': 'cedef40a-ed67-4d10-800e-17455edce175', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'ami', 'disk_format': 'ami', 'size': '84035174', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel'}}, 'c905cedb-7281-47e4-8a62-f26bc5fc4c77': {'id': 'c905cedb-7281-47e4-8a62-f26bc5fc4c77', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'ami', 'disk_format': 'ami', 'size': '26360814', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': '155d900f-4e14-4e4c-a73d-069cbf4541e6', 'ramdisk_id': None}}, 'a440c04b-79fa-479c-bed1-0b816eaec379': {'id': 'a440c04b-79fa-479c-bed1-0b816eaec379', 'name': 'fakeimage6', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': False, 'container_format': 'ova', 'disk_format': 'vhd', 'size': '49163826', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64', 'auto_disk_config': 'False'}}, '70a599e0-31e7-49b7-b260-868f441e862b': {'id': '70a599e0-31e7-49b7-b260-868f441e862b', 'name': 'fakeimage7', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': False, 'container_format': 'ova', 'disk_format': 'vhd', 'size': '74185822', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64', 'auto_disk_config': 'True'}}} 2020-01-07 12:39:20,828 INFO [nova.api.openstack.wsgi] HTTP exception thrown: Image not found. 2020-01-07 12:39:20,829 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/images/3f72d534-d153-49cd-aba8-226207886b17" status: 404 len: 62 microversion: 2.1 time: 0.002381 2020-01-07 12:39:20,835 INFO [nova.compute.manager] Found 1 unconfirmed migrations older than 1 seconds 2020-01-07 12:39:20,835 INFO [nova.compute.manager] Automatically confirming migration 1 for instance e921fb5c-de9f-4f5e-a420-0e12fa4c99aa 2020-01-07 12:39:20,876 INFO [nova.compute.manager] Error auto-confirming resize: Reader <greenlet.greenlet object at 0x7f55c19dd048> to writer privilege escalation not allowed. Will retry later. 2020-01-07 12:39:20,964 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.084149 2020-01-07 12:39:21,613 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.141117 2020-01-07 12:39:22,211 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.092270 2020-01-07 12:39:22,812 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.094725 2020-01-07 12:39:23,446 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.128086 2020-01-07 12:39:24,076 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.122928 2020-01-07 12:39:24,691 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.108408 2020-01-07 12:39:25,311 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.111924 2020-01-07 12:39:25,917 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.101655 2020-01-07 12:39:26,519 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.092556 2020-01-07 12:39:26,721 WARNING [nova.service] Service killed that has no database entry 2020-01-07 12:39:26,723 INFO [oslo_db.sqlalchemy.provision] DROP ALL OBJECTS, BACKEND sqlite:// 2020-01-07 12:39:26,750 INFO [oslo_db.sqlalchemy.provision] DISPOSE ENGINE Engine(sqlite://) }}} stderr: {{{ /home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_policy/policy.py:706: UserWarning: Policy "os_compute_api:os-services":"rule:admin_api" was deprecated in 20.0.0 in favor of "os_compute_api:os-services:list":"rule:system_reader_api". Reason: Since Ussuri release, nova API policies are introducing new default roles with scope_type capabilities. These new changes improve the security level and manageability. New policies are more rich in term of handling access at system and project level token with read, write roles. Start using the new policies and enable the scope checks via config option ``nova.conf [oslo_policy] enforce_scope=True`` which is False by default. Old policies are marked as deprecated and silently going to be ignored in nova 23.0.0 (OpenStack W) release . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually. warnings.warn(deprecated_msg) /home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_policy/policy.py:706: UserWarning: Policy "os_compute_api:os-services":"rule:admin_api" was deprecated in 20.0.0 in favor of "os_compute_api:os-services:update":"rule:system_admin_api". Reason: Since Ussuri release, nova API policies are introducing new default roles with scope_type capabilities. These new changes improve the security level and manageability. New policies are more rich in term of handling access at system and project level token with read, write roles. Start using the new policies and enable the scope checks via config option ``nova.conf [oslo_policy] enforce_scope=True`` which is False by default. Old policies are marked as deprecated and silently going to be ignored in nova 23.0.0 (OpenStack W) release . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually. warnings.warn(deprecated_msg) /home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_policy/policy.py:706: UserWarning: Policy "os_compute_api:os-services":"rule:admin_api" was deprecated in 20.0.0 in favor of "os_compute_api:os-services:delete":"rule:system_admin_api". Reason: Since Ussuri release, nova API policies are introducing new default roles with scope_type capabilities. These new changes improve the security level and manageability. New policies are more rich in term of handling access at system and project level token with read, write roles. Start using the new policies and enable the scope checks via config option ``nova.conf [oslo_policy] enforce_scope=True`` which is False by default. Old policies are marked as deprecated and silently going to be ignored in nova 23.0.0 (OpenStack W) release . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually. warnings.warn(deprecated_msg) }}} Traceback (most recent call last): File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/test_cross_cell_migrate.py", line 994, in test_poll_unconfirmed_resizes_with_upcall self._wait_for_state_change(server, 'ACTIVE') File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 98, in _wait_for_state_change server, {'status': expected_status}, max_retries) File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 91, in _wait_for_server_parameter expected_params, server)) File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/unittest2/case.py", line 690, in fail raise self.failureException(msg) AssertionError: Wait for state change failed, expected_params={'status': 'ACTIVE'}, server={'id': 'e921fb5c-de9f-4f5e-a420-0e12fa4c99aa', 'name': 'test_cross_cell_resize', 'status': 'VERIFY_RESIZE', 'tenant_id': '6f70656e737461636b20342065766572', 'user_id': 'admin', 'metadata': {}, 'hostId': 'ad32f82f3048cef557b4ec2f5f3e952883df66e7dbb37f3f6c1352f2', 'image': {'id': '70a599e0-31e7-49b7-b260-868f441e862b', 'links': [{'rel': 'bookmark', 'href': 'http://bf1b95bb-0630-4eb8-bdee-fb96cef2c5ee/images/70a599e0-31e7-49b7-b260-868f441e862b'}]}, 'flavor': {'vcpus': 1, 'ram': 2048, 'disk': 20, 'ephemeral': 0, 'swap': 0, 'original_name': 'm1.small', 'extra_specs': {}}, 'created': '2020-01-07T12:39:15Z', 'updated': '2020-01-07T12:39:19Z', 'addresses': {'private': [{'version': 4, 'addr': '192.168.1.3', 'OS-EXT-IPS:type': 'fixed', 'OS-EXT-IPS-MAC:mac_addr': 'fa:16:3e:4c:2c:30'}]}, 'accessIPv4': '', 'accessIPv6': '', 'links': [{'rel': 'self', 'href': 'http://bf1b95bb-0630-4eb8-bdee-fb96cef2c5ee/v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa'}, {'rel': 'bookmark', 'href': 'http://bf1b95bb-0630-4eb8-bdee-fb96cef2c5ee/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa'}], 'OS-DCF:diskConfig': 'MANUAL', 'progress': 0, 'OS-EXT-AZ:availability_zone': 'cell2', 'config_drive': '', 'key_name': None, 'OS-SRV-USG:launched_at': '2020-01-07T12:39:19.232514', 'OS-SRV-USG:terminated_at': None, 'security_groups': [{'name': 'default'}], 'OS-EXT-SRV-ATTR:host': 'host2', 'OS-EXT-SRV-ATTR:instance_name': 'instance-00000001', 'OS-EXT-SRV-ATTR:hypervisor_hostname': 'host2', 'OS-EXT-SRV-ATTR:reservation_id': 'r-1ub2ah6i', 'OS-EXT-SRV-ATTR:launch_index': 0, 'OS-EXT-SRV-ATTR:hostname': 'test-cross-cell-resize', 'OS-EXT-SRV-ATTR:kernel_id': '', 'OS-EXT-SRV-ATTR:ramdisk_id': '', 'OS-EXT-SRV-ATTR:root_device_name': '/dev/sda', 'OS-EXT-SRV-ATTR:user_data': None, 'OS-EXT-STS:task_state': None, 'OS-EXT-STS:vm_state': 'resized', 'OS-EXT-STS:power_state': 1, 'os-extended-volumes:volumes_attached': [], 'host_status': 'UNKNOWN', 'locked': False, 'locked_reason': None, 'description': None, 'tags': ['test'], 'trusted_image_certificates': None, 'server_groups': []} Looks like it just recently showed up: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22%5Bnova.compute.manager%5D%20Error %20auto- confirming%20resize%3A%20Reader%20%3Cgreenlet.greenlet%5C%22%20AND%20message%3A%5C%22to%20writer%20privilege%20escalation%20not%20allowed.%20Will%20retry%20later.%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d Though the test has been merged for awhile: https://review.opendev.org/#/c/698322/ ** Affects: nova Importance: Undecided Status: Confirmed ** Tags: gate-failure testing -- You received this bug notification because you are a member of Yahoo! Engineering Team, which is subscribed to OpenStack Compute (nova). https://bugs.launchpad.net/bugs/1858667 Title: TestMultiCellMigrate.test_poll_unconfirmed_resizes_with_(no_)upcall race failing with greenlet error: Error auto-confirming resize: Reader <greenlet.greenlet object at 0x7f55c19dd048> to writer privilege escalation not allowed. Will retry later. Status in OpenStack Compute (nova): Confirmed Bug description: Seen here: https://35ea41893426ced4e7b7-c7b305d9ddba843cc11c9f16befc26b2.ssl.cf1.rackcdn.com/699291/4/check /nova-tox-functional-py36/6f68741/testr_results.html.gz ft1.12: nova.tests.functional.test_cross_cell_migrate.TestMultiCellMigrate.test_poll_unconfirmed_resizes_with_upcalltesttools.testresult.real._StringException: pythonlogging:'': {{{ 2020-01-07 12:39:14,920 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring. 2020-01-07 12:39:15,344 INFO [nova.service] Starting conductor node (version 20.1.0) 2020-01-07 12:39:15,379 INFO [nova.service] Starting scheduler node (version 20.1.0) 2020-01-07 12:39:15,425 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver' 2020-01-07 12:39:15,426 INFO [nova.service] Starting compute node (version 20.1.0) 2020-01-07 12:39:15,443 WARNING [nova.compute.manager] Compute node host1 not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,447 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host 2020-01-07 12:39:15,457 WARNING [nova.compute.manager] No compute node record found for host host1. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,462 WARNING [nova.compute.resource_tracker] No compute node record for host1:host1 2020-01-07 12:39:15,466 INFO [nova.compute.resource_tracker] Compute node record created for host1:host1 with uuid: 30117184-3985-48b6-8e7e-5611c45c112c 2020-01-07 12:39:15,509 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=30117184-3985-48b6-8e7e-5611c45c112c" status: 200 len: 26 microversion: 1.14 2020-01-07 12:39:15,518 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20 2020-01-07 12:39:15,519 INFO [nova.scheduler.client.report] [req-6c8c5604-6d3d-49b4-ae66-3aadfeb1ff27] Created resource provider record via placement API for resource provider with UUID 30117184-3985-48b6-8e7e-5611c45c112c and name host1. 2020-01-07 12:39:15,536 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/inventories" status: 200 len: 401 microversion: 1.26 2020-01-07 12:39:15,545 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_DEVICE_TAGGING,COMPUTE_VOLUME_EXTEND,COMPUTE_NODE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_IMAGE_TYPE_RAW" status: 200 len: 268 microversion: 1.6 2020-01-07 12:39:15,561 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/traits" status: 200 len: 303 microversion: 1.6 2020-01-07 12:39:15,589 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates" status: 200 len: 221 microversion: 2.81 time: 0.021327 2020-01-07 12:39:15,634 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?name=host1" status: 200 len: 432 microversion: 1.0 2020-01-07 12:39:15,643 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/aggregates" status: 200 len: 53 microversion: 1.19 2020-01-07 12:39:15,655 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/aggregates" status: 200 len: 91 microversion: 1.19 2020-01-07 12:39:15,665 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates/1/action" status: 200 len: 285 microversion: 2.81 time: 0.072452 2020-01-07 12:39:15,683 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver' 2020-01-07 12:39:15,684 INFO [nova.service] Starting compute node (version 20.1.0) 2020-01-07 12:39:15,703 WARNING [nova.compute.manager] Compute node host2 not found in the database. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,708 INFO [nova.compute.manager] Looking for unclaimed instances stuck in BUILDING status for nodes managed by this host 2020-01-07 12:39:15,718 WARNING [nova.compute.manager] No compute node record found for host host2. If this is the first time this service is starting on this host, then you can ignore this warning. 2020-01-07 12:39:15,723 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2 2020-01-07 12:39:15,732 INFO [nova.compute.resource_tracker] Compute node record created for host2:host2 with uuid: 7e192b8c-5187-467c-8e7e-f8360fbce19e 2020-01-07 12:39:15,774 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=7e192b8c-5187-467c-8e7e-f8360fbce19e" status: 200 len: 26 microversion: 1.14 2020-01-07 12:39:15,782 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20 2020-01-07 12:39:15,783 INFO [nova.scheduler.client.report] [req-ddaf886c-9f05-4fa2-9c4d-b0317c78e47f] Created resource provider record via placement API for resource provider with UUID 7e192b8c-5187-467c-8e7e-f8360fbce19e and name host2. 2020-01-07 12:39:15,803 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/inventories" status: 200 len: 401 microversion: 1.26 2020-01-07 12:39:15,813 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_DEVICE_TAGGING,COMPUTE_VOLUME_EXTEND,COMPUTE_NODE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_IMAGE_TYPE_RAW" status: 200 len: 268 microversion: 1.6 2020-01-07 12:39:15,831 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/traits" status: 200 len: 303 microversion: 1.6 2020-01-07 12:39:15,850 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates" status: 200 len: 221 microversion: 2.81 time: 0.012939 2020-01-07 12:39:15,889 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?name=host2" status: 200 len: 432 microversion: 1.0 2020-01-07 12:39:15,899 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/aggregates" status: 200 len: 53 microversion: 1.19 2020-01-07 12:39:15,912 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/aggregates" status: 200 len: 91 microversion: 1.19 2020-01-07 12:39:15,927 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/os-aggregates/2/action" status: 200 len: 285 microversion: 2.81 time: 0.072743 2020-01-07 12:39:15,947 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/flavors/detail" status: 200 len: 2605 microversion: 2.81 time: 0.016728 2020-01-07 12:39:16,012 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers" status: 202 len: 412 microversion: 2.81 time: 0.061068 2020-01-07 12:39:16,037 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 1774 microversion: 2.81 time: 0.020963 2020-01-07 12:39:16,141 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1491 microversion: 1.34 2020-01-07 12:39:16,188 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 19 microversion: 1.28 2020-01-07 12:39:16,220 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 204 len: 0 microversion: 1.34 2020-01-07 12:39:16,450 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 230 microversion: 1.28 2020-01-07 12:39:16,459 INFO [nova.compute.claims] Claim successful on node host1 2020-01-07 12:39:17,267 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 1852 microversion: 2.81 time: 0.715882 2020-01-07 12:39:17,324 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor. 2020-01-07 12:39:17,378 INFO [nova.compute.manager] Took 0.94 seconds to build instance. 2020-01-07 12:39:17,423 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList. 2020-01-07 12:39:17,858 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2049 microversion: 2.81 time: 0.085234 2020-01-07 12:39:17,888 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/limits" status: 200 len: 304 microversion: 2.81 time: 0.025623 2020-01-07 12:39:18,037 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/action" status: 202 len: 0 microversion: 2.81 time: 0.144296 2020-01-07 12:39:18,178 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2060 microversion: 2.81 time: 0.137591 2020-01-07 12:39:18,226 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 230 microversion: 1.28 2020-01-07 12:39:18,236 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 230 microversion: 1.28 2020-01-07 12:39:18,247 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/f6b8ee46-9d48-4baa-bea3-9cf8ab4e1337" status: 200 len: 19 microversion: 1.28 2020-01-07 12:39:18,309 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2020-01-07 12:39:18,363 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&required=%21COMPUTE_STATUS_DISABLED&resources=DISK_GB%3A20%2CMEMORY_MB%3A2048%2CVCPU%3A1" status: 200 len: 1497 microversion: 1.34 2020-01-07 12:39:18,396 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: host1 2020-01-07 12:39:18,406 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 19 microversion: 1.28 2020-01-07 12:39:18,433 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 204 len: 0 microversion: 1.34 2020-01-07 12:39:18,443 INFO [nova.conductor.tasks.migrate] Executing cross-cell resize task starting with target host: host2 2020-01-07 12:39:18,611 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 232 microversion: 1.28 2020-01-07 12:39:18,620 INFO [nova.compute.claims] Claim successful on node host2 2020-01-07 12:39:18,636 INFO [nova.compute.resource_tracker] Updating resource usage from migration f6b8ee46-9d48-4baa-bea3-9cf8ab4e1337 2020-01-07 12:39:18,901 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2060 microversion: 2.81 time: 0.211517 2020-01-07 12:39:18,951 INFO [nova.compute.manager] Preparing for snapshot based resize on source host host1. 2020-01-07 12:39:19,146 INFO [nova.compute.manager] Finishing snapshot based resize on destination host host2. 2020-01-07 12:39:19,218 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 232 microversion: 1.28 2020-01-07 12:39:19,368 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host2'. Re-created its InstanceList. 2020-01-07 12:39:19,579 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2064 microversion: 2.81 time: 0.162860 2020-01-07 12:39:20,173 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2062 microversion: 2.81 time: 0.088806 2020-01-07 12:39:20,385 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/detail" status: 200 len: 2044 microversion: 2.81 time: 0.207618 2020-01-07 12:39:20,423 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-migrations?instance_uuid=e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 520 microversion: 2.81 time: 0.034696 2020-01-07 12:39:20,468 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-instance-actions" status: 200 len: 645 microversion: 2.81 time: 0.040943 2020-01-07 12:39:20,517 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-instance-actions/req-f6f0b421-4a08-43c8-9227-679b3ab8f8bc" status: 200 len: 1338 microversion: 2.81 time: 0.045893 2020-01-07 12:39:20,567 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-instance-actions/req-0e5a96f5-1103-4878-8cb1-e12e458e37dc" status: 200 len: 607 microversion: 2.81 time: 0.045760 2020-01-07 12:39:20,595 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.81 time: 0.023762 2020-01-07 12:39:20,618 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/30117184-3985-48b6-8e7e-5611c45c112c/allocations" status: 200 len: 152 microversion: 1.0 2020-01-07 12:39:20,655 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors?hypervisor_hostname_pattern=host2" status: 200 len: 133 microversion: 2.81 time: 0.031607 2020-01-07 12:39:20,668 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/7e192b8c-5187-467c-8e7e-f8360fbce19e/allocations" status: 200 len: 154 microversion: 1.0 2020-01-07 12:39:20,750 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa/os-interface" status: 200 len: 303 microversion: 2.81 time: 0.046221 2020-01-07 12:39:20,770 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors/30117184-3985-48b6-8e7e-5611c45c112c" status: 200 len: 693 microversion: 2.53 time: 0.015973 2020-01-07 12:39:20,792 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/os-hypervisors/7e192b8c-5187-467c-8e7e-f8360fbce19e" status: 200 len: 694 microversion: 2.53 time: 0.018579 2020-01-07 12:39:20,822 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/limits" status: 200 len: 305 microversion: 2.81 time: 0.026690 2020-01-07 12:39:20,827 WARNING [nova.tests.unit.image.fake] Unable to find image id 3f72d534-d153-49cd-aba8-226207886b17. Have images: {'155d900f-4e14-4e4c-a73d-069cbf4541e6': {'id': '155d900f-4e14-4e4c-a73d-069cbf4541e6', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': False, 'container_format': 'raw', 'disk_format': 'raw', 'size': '25165824', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': ['tag1', 'tag2'], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64'}}, 'a2459075-d96c-40d5-893e-577ff92e721c': {'id': 'a2459075-d96c-40d5-893e-577ff92e721c', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'ami', 'disk_format': 'ami', 'size': '58145823', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel'}}, '76fa36fc-c930-4bf3-8c8a-ea2a2420deb6': {'id': '76fa36fc-c930-4bf3-8c8a-ea2a2420deb6', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'bare', 'disk_format': 'raw', 'size': '83594576', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': ['tag3', 'tag4'], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64'}}, 'cedef40a-ed67-4d10-800e-17455edce175': {'id': 'cedef40a-ed67-4d10-800e-17455edce175', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'ami', 'disk_format': 'ami', 'size': '84035174', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel'}}, 'c905cedb-7281-47e4-8a62-f26bc5fc4c77': {'id': 'c905cedb-7281-47e4-8a62-f26bc5fc4c77', 'name': 'fakeimage123456', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': True, 'container_format': 'ami', 'disk_format': 'ami', 'size': '26360814', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': '155d900f-4e14-4e4c-a73d-069cbf4541e6', 'ramdisk_id': None}}, 'a440c04b-79fa-479c-bed1-0b816eaec379': {'id': 'a440c04b-79fa-479c-bed1-0b816eaec379', 'name': 'fakeimage6', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': False, 'container_format': 'ova', 'disk_format': 'vhd', 'size': '49163826', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64', 'auto_disk_config': 'False'}}, '70a599e0-31e7-49b7-b260-868f441e862b': {'id': '70a599e0-31e7-49b7-b260-868f441e862b', 'name': 'fakeimage7', 'created_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'updated_at': datetime.datetime(2011, 1, 1, 1, 2, 3), 'deleted_at': None, 'deleted': False, 'status': 'active', 'is_public': False, 'container_format': 'ova', 'disk_format': 'vhd', 'size': '74185822', 'min_ram': 0, 'min_disk': 0, 'protected': False, 'visibility': 'public', 'tags': [], 'properties': {'kernel_id': 'nokernel', 'ramdisk_id': 'nokernel', 'architecture': 'x86_64', 'auto_disk_config': 'True'}}} 2020-01-07 12:39:20,828 INFO [nova.api.openstack.wsgi] HTTP exception thrown: Image not found. 2020-01-07 12:39:20,829 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/images/3f72d534-d153-49cd-aba8-226207886b17" status: 404 len: 62 microversion: 2.1 time: 0.002381 2020-01-07 12:39:20,835 INFO [nova.compute.manager] Found 1 unconfirmed migrations older than 1 seconds 2020-01-07 12:39:20,835 INFO [nova.compute.manager] Automatically confirming migration 1 for instance e921fb5c-de9f-4f5e-a420-0e12fa4c99aa 2020-01-07 12:39:20,876 INFO [nova.compute.manager] Error auto-confirming resize: Reader <greenlet.greenlet object at 0x7f55c19dd048> to writer privilege escalation not allowed. Will retry later. 2020-01-07 12:39:20,964 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.084149 2020-01-07 12:39:21,613 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.141117 2020-01-07 12:39:22,211 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.092270 2020-01-07 12:39:22,812 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.094725 2020-01-07 12:39:23,446 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.128086 2020-01-07 12:39:24,076 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.122928 2020-01-07 12:39:24,691 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.108408 2020-01-07 12:39:25,311 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.111924 2020-01-07 12:39:25,917 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.101655 2020-01-07 12:39:26,519 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa" status: 200 len: 2067 microversion: 2.81 time: 0.092556 2020-01-07 12:39:26,721 WARNING [nova.service] Service killed that has no database entry 2020-01-07 12:39:26,723 INFO [oslo_db.sqlalchemy.provision] DROP ALL OBJECTS, BACKEND sqlite:// 2020-01-07 12:39:26,750 INFO [oslo_db.sqlalchemy.provision] DISPOSE ENGINE Engine(sqlite://) }}} stderr: {{{ /home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_policy/policy.py:706: UserWarning: Policy "os_compute_api:os-services":"rule:admin_api" was deprecated in 20.0.0 in favor of "os_compute_api:os-services:list":"rule:system_reader_api". Reason: Since Ussuri release, nova API policies are introducing new default roles with scope_type capabilities. These new changes improve the security level and manageability. New policies are more rich in term of handling access at system and project level token with read, write roles. Start using the new policies and enable the scope checks via config option ``nova.conf [oslo_policy] enforce_scope=True`` which is False by default. Old policies are marked as deprecated and silently going to be ignored in nova 23.0.0 (OpenStack W) release . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually. warnings.warn(deprecated_msg) /home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_policy/policy.py:706: UserWarning: Policy "os_compute_api:os-services":"rule:admin_api" was deprecated in 20.0.0 in favor of "os_compute_api:os-services:update":"rule:system_admin_api". Reason: Since Ussuri release, nova API policies are introducing new default roles with scope_type capabilities. These new changes improve the security level and manageability. New policies are more rich in term of handling access at system and project level token with read, write roles. Start using the new policies and enable the scope checks via config option ``nova.conf [oslo_policy] enforce_scope=True`` which is False by default. Old policies are marked as deprecated and silently going to be ignored in nova 23.0.0 (OpenStack W) release . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually. warnings.warn(deprecated_msg) /home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/oslo_policy/policy.py:706: UserWarning: Policy "os_compute_api:os-services":"rule:admin_api" was deprecated in 20.0.0 in favor of "os_compute_api:os-services:delete":"rule:system_admin_api". Reason: Since Ussuri release, nova API policies are introducing new default roles with scope_type capabilities. These new changes improve the security level and manageability. New policies are more rich in term of handling access at system and project level token with read, write roles. Start using the new policies and enable the scope checks via config option ``nova.conf [oslo_policy] enforce_scope=True`` which is False by default. Old policies are marked as deprecated and silently going to be ignored in nova 23.0.0 (OpenStack W) release . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually. warnings.warn(deprecated_msg) }}} Traceback (most recent call last): File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/test_cross_cell_migrate.py", line 994, in test_poll_unconfirmed_resizes_with_upcall self._wait_for_state_change(server, 'ACTIVE') File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 98, in _wait_for_state_change server, {'status': expected_status}, max_retries) File "/home/zuul/src/opendev.org/openstack/nova/nova/tests/functional/integrated_helpers.py", line 91, in _wait_for_server_parameter expected_params, server)) File "/home/zuul/src/opendev.org/openstack/nova/.tox/functional-py36/lib/python3.6/site-packages/unittest2/case.py", line 690, in fail raise self.failureException(msg) AssertionError: Wait for state change failed, expected_params={'status': 'ACTIVE'}, server={'id': 'e921fb5c-de9f-4f5e-a420-0e12fa4c99aa', 'name': 'test_cross_cell_resize', 'status': 'VERIFY_RESIZE', 'tenant_id': '6f70656e737461636b20342065766572', 'user_id': 'admin', 'metadata': {}, 'hostId': 'ad32f82f3048cef557b4ec2f5f3e952883df66e7dbb37f3f6c1352f2', 'image': {'id': '70a599e0-31e7-49b7-b260-868f441e862b', 'links': [{'rel': 'bookmark', 'href': 'http://bf1b95bb-0630-4eb8-bdee-fb96cef2c5ee/images/70a599e0-31e7-49b7-b260-868f441e862b'}]}, 'flavor': {'vcpus': 1, 'ram': 2048, 'disk': 20, 'ephemeral': 0, 'swap': 0, 'original_name': 'm1.small', 'extra_specs': {}}, 'created': '2020-01-07T12:39:15Z', 'updated': '2020-01-07T12:39:19Z', 'addresses': {'private': [{'version': 4, 'addr': '192.168.1.3', 'OS-EXT-IPS:type': 'fixed', 'OS-EXT-IPS-MAC:mac_addr': 'fa:16:3e:4c:2c:30'}]}, 'accessIPv4': '', 'accessIPv6': '', 'links': [{'rel': 'self', 'href': 'http://bf1b95bb-0630-4eb8-bdee-fb96cef2c5ee/v2.1/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa'}, {'rel': 'bookmark', 'href': 'http://bf1b95bb-0630-4eb8-bdee-fb96cef2c5ee/servers/e921fb5c-de9f-4f5e-a420-0e12fa4c99aa'}], 'OS-DCF:diskConfig': 'MANUAL', 'progress': 0, 'OS-EXT-AZ:availability_zone': 'cell2', 'config_drive': '', 'key_name': None, 'OS-SRV-USG:launched_at': '2020-01-07T12:39:19.232514', 'OS-SRV-USG:terminated_at': None, 'security_groups': [{'name': 'default'}], 'OS-EXT-SRV-ATTR:host': 'host2', 'OS-EXT-SRV-ATTR:instance_name': 'instance-00000001', 'OS-EXT-SRV-ATTR:hypervisor_hostname': 'host2', 'OS-EXT-SRV-ATTR:reservation_id': 'r-1ub2ah6i', 'OS-EXT-SRV-ATTR:launch_index': 0, 'OS-EXT-SRV-ATTR:hostname': 'test-cross-cell-resize', 'OS-EXT-SRV-ATTR:kernel_id': '', 'OS-EXT-SRV-ATTR:ramdisk_id': '', 'OS-EXT-SRV-ATTR:root_device_name': '/dev/sda', 'OS-EXT-SRV-ATTR:user_data': None, 'OS-EXT-STS:task_state': None, 'OS-EXT-STS:vm_state': 'resized', 'OS-EXT-STS:power_state': 1, 'os-extended-volumes:volumes_attached': [], 'host_status': 'UNKNOWN', 'locked': False, 'locked_reason': None, 'description': None, 'tags': ['test'], 'trusted_image_certificates': None, 'server_groups': []} Looks like it just recently showed up: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22%5Bnova.compute.manager%5D%20Error %20auto- confirming%20resize%3A%20Reader%20%3Cgreenlet.greenlet%5C%22%20AND%20message%3A%5C%22to%20writer%20privilege%20escalation%20not%20allowed.%20Will%20retry%20later.%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d Though the test has been merged for awhile: https://review.opendev.org/#/c/698322/ To manage notifications about this bug go to: https://bugs.launchpad.net/nova/+bug/1858667/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : yahoo-eng-team@lists.launchpad.net Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
