yahoo-eng-team team mailing list archive
-
yahoo-eng-team team
-
Mailing list archive
-
Message #81178
[Bug 1858667] [NEW] 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.
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
Follow ups
