Reviewed: https://review.openstack.org/507911 Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=8a435c081df1653620cff5918ea66643d3487fd7 Submitter: Zuul Branch: master
commit 8a435c081df1653620cff5918ea66643d3487fd7 Author: Balazs Gibizer <[email protected]> Date: Wed Sep 27 17:56:17 2017 +0200 Fix race in delete allocation in ServerMovingTests When an instance is deleted the allocation of that instance is freed after the instance is destroyed in the db. The functional tests that asserting resource allocation after instance delete are waiting for the instance to disappear from the REST API. This made such tests racy. Fortunately the instance.delete.end notification is emitted after the instance allocation is freed. This patch fixes the race in the test by waiting for the instance.delete.end notification before asserting that the allocation is freed properly. Change-Id: I4ffd8eae73600eb2d4f6929ee6a7768adb80081d Closes-Bug: #1719915 ** Changed in: nova Status: In Progress => Fix Released -- 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/1719915 Title: test_live_migrate_delete race fail when checking allocations: MismatchError: 2 != 1 Status in OpenStack Compute (nova): Fix Released Bug description: Seen here: http://logs.openstack.org/87/507687/2/check/gate-nova-tox-functional- ubuntu-xenial/90cc144/console.html#_2017-09-27_03_02_34_847653 This test was just recently added: https://review.openstack.org/#/c/499583/ 2017-09-27 03:02:34.847653 | nova.tests.functional.test_servers.ServerMovingTests.test_live_migrate_delete 2017-09-27 03:02:34.847678 | ----------------------------------------------------------------------------- 2017-09-27 03:02:34.847684 | 2017-09-27 03:02:34.847696 | Captured pythonlogging: 2017-09-27 03:02:34.847708 | ~~~~~~~~~~~~~~~~~~~~~~~ 2017-09-27 03:02:34.847761 | 2017-09-27 02:57:14,740 WARNING [oslo_config.cfg] Config option <oslo_config.cfg.OptGroup object at 0x7fd7cae6c290>.api_class is deprecated. Use option key_manager.backend instead. 2017-09-27 03:02:34.847789 | 2017-09-27 02:57:17,027 INFO [nova.service] Starting conductor node (version 16.0.0) 2017-09-27 03:02:34.847818 | 2017-09-27 02:57:17,051 INFO [nova.service] Starting scheduler node (version 16.0.0) 2017-09-27 03:02:34.847848 | 2017-09-27 02:57:17,101 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver' 2017-09-27 03:02:34.847875 | 2017-09-27 02:57:17,102 INFO [nova.service] Starting compute node (version 16.0.0) 2017-09-27 03:02:34.847931 | 2017-09-27 02:57:17,133 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. 2017-09-27 03:02:34.847981 | 2017-09-27 02:57:17,134 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors). 2017-09-27 03:02:34.848014 | 2017-09-27 02:57:17,140 WARNING [nova.compute.resource_tracker] No compute node record for host1:host1 2017-09-27 03:02:34.848059 | 2017-09-27 02:57:17,145 INFO [nova.compute.resource_tracker] Compute node record created for host1:host1 with uuid: dcc04100-765a-41f3-8ff9-14d9a3bbba83 2017-09-27 03:02:34.848120 | 2017-09-27 02:57:17,185 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83" status: 404 len: 227 microversion: 1.0 2017-09-27 03:02:34.848166 | 2017-09-27 02:57:17,193 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 201 len: 0 microversion: 1.0 2017-09-27 03:02:34.848253 | 2017-09-27 02:57:17,194 INFO [nova.scheduler.client.report] [req-1d3a8f2c-5565-43c8-a6a3-21c69e877fbe] Created resource provider record via placement API for resource provider with UUID dcc04100-765a-41f3-8ff9-14d9a3bbba83 and name host1. 2017-09-27 03:02:34.848331 | 2017-09-27 02:57:17,202 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.848388 | 2017-09-27 02:57:17,586 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 54 microversion: 1.0 2017-09-27 03:02:34.848455 | 2017-09-27 02:57:17,603 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.848511 | 2017-09-27 02:57:17,623 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/allocations" status: 200 len: 54 microversion: 1.0 2017-09-27 03:02:34.848573 | 2017-09-27 02:57:17,640 INFO [nova.compute.resource_tracker] Final resource view: name=host1 phys_ram=8192MB used_ram=512MB phys_disk=1028GB used_disk=0GB total_vcpus=10 used_vcpus=0 pci_stats=[] 2017-09-27 03:02:34.848631 | 2017-09-27 02:57:17,658 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.848688 | 2017-09-27 02:57:17,671 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.848717 | 2017-09-27 02:57:17,687 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver' 2017-09-27 03:02:34.848744 | 2017-09-27 02:57:17,687 INFO [nova.service] Starting compute node (version 16.0.0) 2017-09-27 03:02:34.848799 | 2017-09-27 02:57:17,715 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. 2017-09-27 03:02:34.848848 | 2017-09-27 02:57:17,716 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors). 2017-09-27 03:02:34.848880 | 2017-09-27 02:57:17,722 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2 2017-09-27 03:02:34.848924 | 2017-09-27 02:57:17,727 INFO [nova.compute.resource_tracker] Compute node record created for host2:host2 with uuid: d39773ff-4c93-4630-a503-ca36e379df1a 2017-09-27 03:02:34.848978 | 2017-09-27 02:57:17,746 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a" status: 404 len: 227 microversion: 1.0 2017-09-27 03:02:34.849022 | 2017-09-27 02:57:17,756 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 201 len: 0 microversion: 1.0 2017-09-27 03:02:34.849087 | 2017-09-27 02:57:17,757 INFO [nova.scheduler.client.report] [req-5dced627-58da-4338-a986-d3aae4360c71] Created resource provider record via placement API for resource provider with UUID d39773ff-4c93-4630-a503-ca36e379df1a and name host2. 2017-09-27 03:02:34.849143 | 2017-09-27 02:57:17,764 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.849204 | 2017-09-27 02:57:17,775 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 54 microversion: 1.0 2017-09-27 03:02:34.849261 | 2017-09-27 02:57:17,790 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.849325 | 2017-09-27 02:57:17,811 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/allocations" status: 200 len: 54 microversion: 1.0 2017-09-27 03:02:34.849377 | 2017-09-27 02:57:17,826 INFO [nova.compute.resource_tracker] Final resource view: name=host2 phys_ram=8192MB used_ram=512MB phys_disk=1028GB used_disk=0GB total_vcpus=10 used_vcpus=0 pci_stats=[] 2017-09-27 03:02:34.849442 | 2017-09-27 02:57:17,843 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.849499 | 2017-09-27 02:57:17,856 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.849538 | 2017-09-27 02:57:17,862 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000471 2017-09-27 03:02:34.849591 | 2017-09-27 02:57:18,055 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/flavors/detail" status: 200 len: 2747 microversion: 2.53 time: 0.189219 2017-09-27 03:02:34.849642 | 2017-09-27 02:57:18,091 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/flavors" status: 200 len: 574 microversion: 2.53 time: 0.031499 2017-09-27 03:02:34.849702 | 2017-09-27 02:57:18,120 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.53 time: 0.023180 2017-09-27 03:02:34.849763 | 2017-09-27 02:57:18,144 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-hypervisors?hypervisor_hostname_pattern=host2" status: 200 len: 133 microversion: 2.53 time: 0.020534 2017-09-27 03:02:34.849789 | 2017-09-27 02:57:18,146 INFO [nova.tests.functional.test_servers] booting on host1 2017-09-27 03:02:34.849840 | 2017-09-27 02:57:18,293 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 480 microversion: 2.53 time: 0.144479 2017-09-27 03:02:34.849899 | 2017-09-27 02:57:18,366 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 1771 microversion: 2.53 time: 0.068319 2017-09-27 03:02:34.849957 | 2017-09-27 02:57:18,471 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 713 microversion: 1.10 2017-09-27 03:02:34.849991 | 2017-09-27 02:57:18,531 INFO [nova.scheduler.host_manager] Host filter forcing available hosts to host1 2017-09-27 03:02:34.850042 | 2017-09-27 02:57:18,540 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 19 microversion: 1.0 2017-09-27 03:02:34.850094 | 2017-09-27 02:57:18,562 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 204 len: 0 microversion: 1.10 2017-09-27 03:02:34.850133 | 2017-09-27 02:57:18,786 INFO [nova.compute.claims] Attempting claim on node host1: memory 512 MB, disk 1 GB, vcpus 1 CPU 2017-09-27 03:02:34.850162 | 2017-09-27 02:57:18,787 INFO [nova.compute.claims] Total memory: 8192 MB, used: 512.00 MB 2017-09-27 03:02:34.850194 | 2017-09-27 02:57:18,787 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited 2017-09-27 03:02:34.850222 | 2017-09-27 02:57:18,787 INFO [nova.compute.claims] Total disk: 1028 GB, used: 0.00 GB 2017-09-27 03:02:34.850253 | 2017-09-27 02:57:18,787 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited 2017-09-27 03:02:34.850281 | 2017-09-27 02:57:18,787 INFO [nova.compute.claims] Total vcpu: 10 VCPU, used: 0.00 VCPU 2017-09-27 03:02:34.850312 | 2017-09-27 02:57:18,787 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited 2017-09-27 03:02:34.850338 | 2017-09-27 02:57:18,788 INFO [nova.compute.claims] Claim successful on node host1 2017-09-27 03:02:34.850395 | 2017-09-27 02:57:19,012 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.850455 | 2017-09-27 02:57:19,047 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 1844 microversion: 2.53 time: 0.172826 2017-09-27 03:02:34.850511 | 2017-09-27 02:57:19,051 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.850545 | 2017-09-27 02:57:19,197 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor. 2017-09-27 03:02:34.850573 | 2017-09-27 02:57:19,251 INFO [nova.compute.manager] Took 0.48 seconds to build instance. 2017-09-27 03:02:34.850613 | 2017-09-27 02:57:19,285 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'host1'. Re-created its InstanceList. 2017-09-27 03:02:34.850672 | 2017-09-27 02:57:19,701 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 1873 microversion: 2.53 time: 0.148685 2017-09-27 03:02:34.850733 | 2017-09-27 02:57:19,724 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-hypervisors?hypervisor_hostname_pattern=host1" status: 200 len: 133 microversion: 2.53 time: 0.019287 2017-09-27 03:02:34.850793 | 2017-09-27 02:57:19,740 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-hypervisors?hypervisor_hostname_pattern=host2" status: 200 len: 133 microversion: 2.53 time: 0.013623 2017-09-27 03:02:34.850848 | 2017-09-27 02:57:19,747 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/usages" status: 200 len: 90 microversion: 1.0 2017-09-27 03:02:34.850903 | 2017-09-27 02:57:19,753 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/usages" status: 200 len: 88 microversion: 1.0 2017-09-27 03:02:34.850955 | 2017-09-27 02:57:19,759 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 134 microversion: 1.0 2017-09-27 03:02:34.850987 | 2017-09-27 02:57:19,760 INFO [nova.tests.functional.test_servers] Running periodic for compute1 (host1) 2017-09-27 03:02:34.851043 | 2017-09-27 02:57:19,778 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.851099 | 2017-09-27 02:57:19,786 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.851159 | 2017-09-27 02:57:19,801 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/allocations" status: 200 len: 152 microversion: 1.0 2017-09-27 03:02:34.851214 | 2017-09-27 02:57:19,813 INFO [nova.compute.resource_tracker] Final resource view: name=host1 phys_ram=8192MB used_ram=1024MB phys_disk=1028GB used_disk=1GB total_vcpus=10 used_vcpus=1 pci_stats=[] 2017-09-27 03:02:34.851270 | 2017-09-27 02:57:19,830 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.851326 | 2017-09-27 02:57:19,838 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.851358 | 2017-09-27 02:57:19,838 INFO [nova.tests.functional.test_servers] Running periodic for compute2 (host2) 2017-09-27 03:02:34.851414 | 2017-09-27 02:57:19,855 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.851481 | 2017-09-27 02:57:19,864 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.851535 | 2017-09-27 02:57:19,879 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/allocations" status: 200 len: 54 microversion: 1.0 2017-09-27 03:02:34.851588 | 2017-09-27 02:57:19,891 INFO [nova.compute.resource_tracker] Final resource view: name=host2 phys_ram=8192MB used_ram=512MB phys_disk=1028GB used_disk=0GB total_vcpus=10 used_vcpus=0 pci_stats=[] 2017-09-27 03:02:34.851642 | 2017-09-27 02:57:19,903 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.851710 | 2017-09-27 02:57:19,912 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.851739 | 2017-09-27 02:57:19,913 INFO [nova.tests.functional.test_servers] Finished with periodics 2017-09-27 03:02:34.851794 | 2017-09-27 02:57:19,919 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/usages" status: 200 len: 90 microversion: 1.0 2017-09-27 03:02:34.851849 | 2017-09-27 02:57:19,925 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/usages" status: 200 len: 88 microversion: 1.0 2017-09-27 03:02:34.851901 | 2017-09-27 02:57:19,931 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 134 microversion: 1.0 2017-09-27 03:02:34.851961 | 2017-09-27 02:57:20,025 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648/action" status: 202 len: 0 microversion: 2.53 time: 0.090679 2017-09-27 03:02:34.852013 | 2017-09-27 02:57:20,040 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-migrations" status: 200 len: 18 microversion: 2.53 time: 0.011788 2017-09-27 03:02:34.852071 | 2017-09-27 02:57:20,157 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 715 microversion: 1.10 2017-09-27 03:02:34.852111 | 2017-09-27 02:57:20,197 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2017-09-27 03:02:34.852140 | 2017-09-27 02:57:20,197 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2017-09-27 03:02:34.852191 | 2017-09-27 02:57:20,207 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 134 microversion: 1.0 2017-09-27 03:02:34.852254 | 2017-09-27 02:57:20,225 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 204 len: 0 microversion: 1.10 2017-09-27 03:02:34.852309 | 2017-09-27 02:57:20,556 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-migrations" status: 200 len: 740 microversion: 2.53 time: 0.012252 2017-09-27 03:02:34.852372 | 2017-09-27 02:57:20,632 INFO [nova.api.openstack.requestlog] 127.0.0.1 "DELETE /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648/migrations/1" status: 202 len: 0 microversion: 2.53 time: 0.071777 2017-09-27 03:02:34.852432 | 2017-09-27 02:57:20,793 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 1883 microversion: 2.53 time: 0.156698 2017-09-27 03:02:34.852484 | 2017-09-27 02:57:21,067 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 251 microversion: 1.0 2017-09-27 03:02:34.852551 | 2017-09-27 02:57:21,089 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 204 len: 0 microversion: 1.10 2017-09-27 03:02:34.852621 | 2017-09-27 02:57:21,430 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 1873 microversion: 2.53 time: 0.131375 2017-09-27 03:02:34.852653 | 2017-09-27 02:57:21,431 INFO [nova.tests.functional.test_servers] Running periodic for compute1 (host1) 2017-09-27 03:02:34.852709 | 2017-09-27 02:57:21,453 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.852765 | 2017-09-27 02:57:21,462 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.852822 | 2017-09-27 02:57:21,485 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/allocations" status: 200 len: 152 microversion: 1.0 2017-09-27 03:02:34.852876 | 2017-09-27 02:57:21,497 INFO [nova.compute.resource_tracker] Final resource view: name=host1 phys_ram=8192MB used_ram=1024MB phys_disk=1028GB used_disk=1GB total_vcpus=10 used_vcpus=1 pci_stats=[] 2017-09-27 03:02:34.852933 | 2017-09-27 02:57:21,510 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.852989 | 2017-09-27 02:57:21,518 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/dcc04100-765a-41f3-8ff9-14d9a3bbba83/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.853021 | 2017-09-27 02:57:21,519 INFO [nova.tests.functional.test_servers] Running periodic for compute2 (host2) 2017-09-27 03:02:34.853077 | 2017-09-27 02:57:21,544 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.853137 | 2017-09-27 02:57:21,551 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.853194 | 2017-09-27 02:57:21,564 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/allocations" status: 200 len: 54 microversion: 1.0 2017-09-27 03:02:34.853249 | 2017-09-27 02:57:21,574 INFO [nova.compute.resource_tracker] Final resource view: name=host2 phys_ram=8192MB used_ram=512MB phys_disk=1028GB used_disk=0GB total_vcpus=10 used_vcpus=0 pci_stats=[] 2017-09-27 03:02:34.853305 | 2017-09-27 02:57:21,586 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/aggregates" status: 200 len: 18 microversion: 1.1 2017-09-27 03:02:34.853361 | 2017-09-27 02:57:21,594 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/d39773ff-4c93-4630-a503-ca36e379df1a/inventories" status: 200 len: 401 microversion: 1.0 2017-09-27 03:02:34.853389 | 2017-09-27 02:57:21,595 INFO [nova.tests.functional.test_servers] Finished with periodics 2017-09-27 03:02:34.853441 | 2017-09-27 02:57:21,601 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/f4a80162-6142-42c8-94c0-39c3787fd648" status: 200 len: 134 microversion: 1.0 2017-09-27 03:02:34.853449 | 2017-09-27 03:02:34.853455 | 2017-09-27 03:02:34.870262 | Captured traceback: 2017-09-27 03:02:34.870318 | ~~~~~~~~~~~~~~~~~~~ 2017-09-27 03:02:34.870338 | Traceback (most recent call last): 2017-09-27 03:02:34.870386 | File "/home/jenkins/workspace/gate-nova-tox-functional-ubuntu-xenial/.tox/functional/local/lib/python2.7/site-packages/mock/mock.py", line 1305, in patched 2017-09-27 03:02:34.870404 | return func(*args, **keywargs) 2017-09-27 03:02:34.870431 | File "nova/tests/functional/test_servers.py", line 2459, in test_live_migrate_delete 2017-09-27 03:02:34.870450 | self.assertEqual(2, len(allocations)) 2017-09-27 03:02:34.870497 | File "/home/jenkins/workspace/gate-nova-tox-functional-ubuntu-xenial/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual 2017-09-27 03:02:34.870517 | self.assertThat(observed, matcher, message) 2017-09-27 03:02:34.870565 | File "/home/jenkins/workspace/gate-nova-tox-functional-ubuntu-xenial/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat 2017-09-27 03:02:34.870578 | raise mismatch_error 2017-09-27 03:02:34.870596 | testtools.matchers._impl.MismatchError: 2 != 1 There is likely a race between the time we are waiting for the migration and/or instance status to change and when the allocations are actually written. To manage notifications about this bug go to: https://bugs.launchpad.net/nova/+bug/1719915/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
