yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1719915] [NEW] test_live_migrate_delete race fail when checking allocations: MismatchError: 2 != 1

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Matt Riedemann <mriedem.os@xxxxxxxxx>
Date: Wed, 27 Sep 2017 14:32:27 -0000
Reply-to: Bug 1719915 <1719915@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

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.

** Affects: nova
     Importance: Medium
     Assignee: Balazs Gibizer (balazs-gibizer)
         Status: Confirmed


** Tags: live-migration 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/1719915

Title:
  test_live_migrate_delete race fail when checking allocations:
  MismatchError: 2 != 1

Status in OpenStack Compute (nova):
  Confirmed

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
Follow ups

[Bug 1719915] Re: test_live_migrate_delete race fail when checking allocations: MismatchError: 2 != 1
From: Matt Riedemann, 2017-10-02
[Bug 1719915] Re: test_live_migrate_delete race fail when checking allocations: MismatchError: 2 != 1
From: OpenStack Infra, 2017-10-02