yahoo-eng-team team mailing list archive

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

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: OpenStack Infra <1719915@xxxxxxxxxxxxxxxxxx>
Date: Mon, 02 Oct 2017 12:03:13 -0000
Reply-to: Bug 1719915 <1719915@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
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 <balazs.gibizer@xxxxxxxxxxxx>
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
References

[Bug 1719915] [NEW] test_live_migrate_delete race fail when checking allocations: MismatchError: 2 != 1
From: Matt Riedemann, 2017-09-27