OpenStack Compute (nova)

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

Series pike
Bug #1719915

Bug #1719915 reported by Matt Riedemann on 2017-09-27

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Medium	Balazs Gibizer
	Pike	Fix Committed	Low	Balazs Gibizer

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 2017-09-27 03:02:34.847678 2017-09-27 03:02:34.847684 |
2017-09-27 03:02:34.847696 2017-09-27 03:02:34.847708 2017-09-27 03:02:34.847761 | 2017-09-27 03:02:34.847789 | 2017-09-27 03:02:34.847818 | 2017-09-27 03:02:34.847848 | 2017-09-27 03:02:34.847875 | 2017-09-27 03:02:34.847931 | 2017-09-27 03:02:34.847981 | 2017-09-27 03:02:34.848014 | 2017-09-27 03:02:34.848059 | 2017-09-27 03:02:34.848120 | 2017-09-27 03:02:34.848166 | 2017-09-27 03:02:34.848253 | 2017-09-27 03:02:34.848331 | 2017-09-27 03:02:34.848388 | 2017-09-27 03:02:34.848455 | 2017-09-27 03:02:34.848511 | 2017-09-27 03:02:34.848573 | 2017-09-27 03:02:34.848631 | 2017-09-27 03:02:34.848688 | 2017-09-27 03:02:34.848717 | 2017-09-27 03:02:34.848744 | 2017-09-27 03:02:34.848799 | 2017-09-27 03:02:34.848848 | 2017-09-27 03:02:34.848880 | 2017-09-27 03:02:34.848924 | 2017-09-27 03:02:34.848978 | 2017-09-27 03:02:34.849022 | 2017-09-27 03:02:34.849087 | 2017-09-27 03:02:34.849143 | 2017-09-27 03:02:34.849204 | 2017-09-27 03:02:34.849261 | 2017-09-27 03:02:34.849325 | 2017-09-27 03:02:34.849377 | 2017-09-27 03:02:34.849442 | 2017-09-27 03:02:34.849499 | 2017-09-27 03:02:34.849538 | 2017-09-27 03:02:34.849591 | 2017-09-27 03:02:34.849642 | 2017-09-27 03:02:34.849702 | 2017-09-27 03:02:34.849763 | 2017-09-27 03:02:34.849789 | 2017-09-27 03:02:34.849840 | 2017-09-27 03:02:34.849899 | 2017-09-27 03:02:34.849957 | 2017-09-27 03:02:34.849991 | 2017-09-27 03:02:34.850042 | 2017-09-27 03:02:34.850094 | 2017-09-27 03:02:34.850133 | 2017-09-27 03:02:34.850162 | 2017-09-27 03:02:34.850194 | 2017-09-27 03:02:34.850222 | 2017-09-27 03:02:34.850253 | 2017-09-27 03:02:34.850281 | 2017-09-27 03:02:34.850312 | 2017-09-27 03:02:34.850338 | 2017-09-27 03:02:34.850395 | 2017-09-27 03:02:34.850455 | 2017-09-27 03:02:34.850511 | 2017-09-27 03:02:34.850545 | 2017-09-27 03:02:34.850573 | 2017-09-27 03:02:34.850613 | 2017-09-27 03:02:34.850672 | 2017-09-27 03:02:34.850733 | 2017-09-27 03:02:34.850793 | 2017-09-27 03:02:34.850848 | 2017-09-27 03:02:34.850903 | 2017-09-27 03:02:34.850955 | 2017-09-27 03:02:34.850987 | 2017-09-27 03:02:34.851043 | 2017-09-27 03:02:34.851099 | 2017-09-27 03:02:34.851159 | 2017-09-27 03:02:34.851214 | 2017-09-27 03:02:34.851270 | 2017-09-27 03:02:34.851326 | 2017-09-27 03:02:34.851358 | 2017-09-27 03:02:34.851414 | 2017-09-27 03:02:34.851481 | 2017-09-27 03:02:34.851535 | 2017-09-27 03:02:34.851588 | 2017-09-27 03:02:34.851642 | 2017-09-27 03:02:34.851710 | 2017-09-27 03:02:34.851739 | 2017-09-27 03:02:34.851794 | 2017-09-27 03:02:34.851849 | 2017-09-27 03:02:34.851901 | 2017-09-27 03:02:34.851961 | 2017-09-27 03:02:34.852013 | 2017-09-27 03:02:34.852071 | 2017-09-27 03:02:34.852111 | 2017-09-27 03:02:34.852140 | 2017-09-27 03:02:34.852191 | 2017-09-27 03:02:34.852254 | 2017-09-27 03:02:34.852309 | 2017-09-27 03:02:34.852372 | 2017-09-27 03:02:34.852432 | 2017-09-27 03:02:34.852484 | 2017-09-27 03:02:34.852551 | 2017-09-27 03:02:34.852621 | 2017-09-27 03:02:34.852653 | 2017-09-27 03:02:34.852709 | 2017-09-27 03:02:34.852765 | 2017-09-27 03:02:34.852822 | 2017-09-27 03:02:34.852876 | 2017-09-27 03:02:34.852933 | 2017-09-27 03:02:34.852989 | 2017-09-27 03:02:34.853021 | 2017-09-27 03:02:34.853077 | 2017-09-27 03:02:34.853137 | 2017-09-27 03:02:34.853194 | 2017-09-27 03:02:34.853249 | 2017-09-27 03:02:34.853305 | 2017-09-27 03:02:34.853361 | 2017-09-27 03:02:34.853389 | 2017-09-27 03:02:34.853441 | 2017-09-27 03:02:34.853449 |
2017-09-27 03:02:34.853455 |
2017-09-27 03:02:34.870262 2017-09-27 03:02:34.870318 2017-09-27 03:02:34.870338 | 2017-09-27 03:02:34.870386 | 2017-09-27 03:02:34.870404 | 2017-09-27 03:02:34.870431 | 2017-09-27 03:02:34.870450 | 2017-09-27 03:02:34.870497 | 2017-09-27 03:02:34.870517 | 2017-09-27 03:02:34.870565 | 2017-09-27 03:02:34.870578 | 2017-09-27 03:02:34.870596 | | nova.tests.functional.test_servers.ServerMovingTests.test_live_migrate_delete
| -----------------------------------------------------------------------------
| Captured pythonlogging:
| ~~~~~~~~~~~~~~~~~~~~~~~
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 02:57:17,027 INFO [nova.service] Starting conductor node (version 16.0.0)
2017-09-27 02:57:17,051 INFO [nova.service] Starting scheduler node (version 16.0.0)
2017-09-27 02:57:17,101 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver'
2017-09-27 02:57:17,102 INFO [nova.service] Starting compute node (version 16.0.0)
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 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 02:57:17,140 WARNING [nova.compute.resource_tracker] No compute node record for host1:host1
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 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 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 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 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 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 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 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 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 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 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 02:57:17,687 INFO [nova.virt.driver] Loading compute driver 'fake.MediumFakeDriver'
2017-09-27 02:57:17,687 INFO [nova.service] Starting compute node (version 16.0.0)
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 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 02:57:17,722 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2
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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 02:57:18,146 INFO [nova.tests.functional.test_servers] booting on host1
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 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 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 02:57:18,531 INFO [nova.scheduler.host_manager] Host filter forcing available hosts to host1
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 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 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 02:57:18,787 INFO [nova.compute.claims] Total memory: 8192 MB, used: 512.00 MB
2017-09-27 02:57:18,787 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited
2017-09-27 02:57:18,787 INFO [nova.compute.claims] Total disk: 1028 GB, used: 0.00 GB
2017-09-27 02:57:18,787 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited
2017-09-27 02:57:18,787 INFO [nova.compute.claims] Total vcpu: 10 VCPU, used: 0.00 VCPU
2017-09-27 02:57:18,787 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited
2017-09-27 02:57:18,788 INFO [nova.compute.claims] Claim successful on node host1
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 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 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 02:57:19,197 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.
2017-09-27 02:57:19,251 INFO [nova.compute.manager] Took 0.48 seconds to build instance.
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 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 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 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 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 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 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 02:57:19,760 INFO [nova.tests.functional.test_servers] Running periodic for compute1 (host1)
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 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 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 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 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 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 02:57:19,838 INFO [nova.tests.functional.test_servers] Running periodic for compute2 (host2)
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 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 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 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 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 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 02:57:19,913 INFO [nova.tests.functional.test_servers] Finished with periodics
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 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 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 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 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 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 02:57:20,197 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2
2017-09-27 02:57:20,197 INFO [nova.scheduler.host_manager] Host filter ignoring hosts:
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 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 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 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 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 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 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 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 02:57:21,431 INFO [nova.tests.functional.test_servers] Running periodic for compute1 (host1)
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 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 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 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 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 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 02:57:21,519 INFO [nova.tests.functional.test_servers] Running periodic for compute2 (host2)
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 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 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 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 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 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 02:57:21,595 INFO [nova.tests.functional.test_servers] Finished with periodics
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
| Captured traceback:
| ~~~~~~~~~~~~~~~~~~~
Traceback (most recent call last):
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
return func(*args, **keywargs)
File "nova/tests/functional/test_servers.py", line 2459, in test_live_migrate_delete
self.assertEqual(2, len(allocations))
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
self.assertThat(observed, matcher, message)
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
raise mismatch_error
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.

Tags:

Balazs Gibizer (balazs-gibizer) on 2017-09-27

Changed in nova:
assignee:	nobody → Balazs Gibizer (balazs-gibizer)

Revision history for this message

Balazs Gibizer (balazs-gibizer) wrote on 2017-09-27:

I cannot reproduce this on master locally. In the other hand both patches [1][2] that were hit by this failure according to logstash [3] are failing constantly for me locally. So I don't think we saw this race on the master if the any race at all.

[1] https://review.openstack.org/#/c/507638
[2] https://review.openstack.org/#/c/507687
[3] http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22self.assertEqual(2%2C%20len(allocations))%5C%22

Revision history for this message

Matt Riedemann (mriedem) wrote on 2017-09-27:

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22%5Bnova.api.openstack.requestlog%5D%20127.0.0.1%20%5C%5C%5C%22DELETE%20%2Fv2.1%2F%5C%22%20AND%20message%3A%5C%22%2Fmigrations%2F1%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

Revision history for this message

Balazs Gibizer (balazs-gibizer) wrote on 2017-09-27:

OK, that is a different failure than what was posted on the bug report. This failure did hit some unrelated changes on the gate.

Revision history for this message

Balazs Gibizer (balazs-gibizer) wrote on 2017-09-27:

So these race happens at the delete of the instance:
Captured traceback:
2017-09-27 13:53:01.197304 | ~~~~~~~~~~~~~~~~~~~
2017-09-27 13:53:01.197349 | b'Traceback (most recent call last):'
2017-09-27 13:53:01.197462 | b' File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/.tox/functional-py35/lib/python3.5/site-packages/mock/mock.py", line 1305, in patched'
2017-09-27 13:53:01.197510 | b' return func(*args, **keywargs)'
2017-09-27 13:53:01.197625 | b' File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/nova/tests/functional/test_servers.py", line 2426, in test_live_migrate_delete'
2017-09-27 13:53:01.197676 | b' server, source_rp_uuid, dest_rp_uuid)'
2017-09-27 13:53:01.197786 | b' File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/nova/tests/functional/test_servers.py", line 1331, in _delete_and_check_allocations'
2017-09-27 13:53:01.197850 | b" 'DISK_GB': 0}, source_usages)"
2017-09-27 13:53:01.197965 | b' File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/.tox/functional-py35/lib/python3.5/site-packages/testtools/testcase.py", line 411, in assertEqual'
2017-09-27 13:53:01.198019 | b' self.assertThat(observed, matcher, message)'
2017-09-27 13:53:01.198132 | b' File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/.tox/functional-py35/lib/python3.5/site-packages/testtools/testcase.py", line 498, in assertThat'
2017-09-27 13:53:01.198173 | b' raise mismatch_error'
2017-09-27 13:53:01.198220 | b'testtools.matchers._impl.MismatchError: !=:'
2017-09-27 13:53:01.198273 | b"reference = {'DISK_GB': 0, 'MEMORY_MB': 0, 'VCPU': 0}"
2017-09-27 13:53:01.198327 | b"actual = {'DISK_GB': 1, 'MEMORY_MB': 512, 'VCPU': 1}"
2017-09-27 13:53:01.198354 | b''
2017-09-27 13:53:01.198381 | b''

Most probably the instance already disappeared from the REST API, as that is what _wait_unit_deleted waits for, but the allocation hasn't been deleted.

So these race happens at the delete of the instance:
Captured traceback:
2017-09-27 13:53:01.197304 | ~~~~~~~~~~~~~~~~~~~
2017-09-27 13:53:01.197349 |     b'Traceback (most recent call last):'
2017-09-27 13:53:01.197462 |     b'  File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/.tox/functional-py35/lib/python3.5/site-packages/mock/mock.py", line 1305, in patched'
2017-09-27 13:53:01.197510 |     b'    return func(*args, **keywargs)'
2017-09-27 13:53:01.197625 |     b'  File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/nova/tests/functional/test_servers.py", line 2426, in test_live_migrate_delete'
2017-09-27 13:53:01.197676 |     b'    server, source_rp_uuid, dest_rp_uuid)'
2017-09-27 13:53:01.197786 |     b'  File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/nova/tests/functional/test_servers.py", line 1331, in _delete_and_check_allocations'
2017-09-27 13:53:01.197850 |     b"    'DISK_GB': 0}, source_usages)"
2017-09-27 13:53:01.197965 |     b'  File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/.tox/functional-py35/lib/python3.5/site-packages/testtools/testcase.py", line 411, in assertEqual'
2017-09-27 13:53:01.198019 |     b'    self.assertThat(observed, matcher, message)'
2017-09-27 13:53:01.198132 |     b'  File "/home/jenkins/workspace/gate-nova-tox-functional-py35-ubuntu-xenial/.tox/functional-py35/lib/python3.5/site-packages/testtools/testcase.py", line 498, in assertThat'
2017-09-27 13:53:01.198173 |     b'    raise mismatch_error'
2017-09-27 13:53:01.198220 |     b'testtools.matchers._impl.MismatchError: !=:'
2017-09-27 13:53:01.198273 |     b"reference = {'DISK_GB': 0, 'MEMORY_MB': 0, 'VCPU': 0}"
2017-09-27 13:53:01.198327 |     b"actual    = {'DISK_GB': 1, 'MEMORY_MB': 512, 'VCPU': 1}"
2017-09-27 13:53:01.198354 |     b''
2017-09-27 13:53:01.198381 |     b''

Most probably the instance already disappeared from the REST API, as that is what _wait_unit_deleted waits for, but the allocation hasn't been deleted.

Revision history for this message

Balazs Gibizer (balazs-gibizer) wrote on 2017-09-27:

Nova destroys the instance object in the compute/manager [1] _before_ removes the allocation [2]. This is the root cause of the race condition at instance delete. Fortunately we have the instance.delete notification emitted[3] _after_ the allocation is deleted so we can modify the _wait_until_deleted to wait for the deleted notification as well.

[1] https://github.com/openstack/nova/blob/faede889d3620f8ff0131a7a4c6b9c1bc844cd06/nova/compute/manager.py#L2425
[2] https://github.com/openstack/nova/blob/faede889d3620f8ff0131a7a4c6b9c1bc844cd06/nova/compute/manager.py#L734
[3]https://github.com/openstack/nova/blob/faede889d3620f8ff0131a7a4c6b9c1bc844cd06/nova/compute/manager.py#L738

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-09-27: Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/507911

Changed in nova:
status:	Confirmed → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-10-02: Fix merged to nova (master)

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 address hidden>
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

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-10-02: Fix proposed to nova (stable/pike)

Fix proposed to branch: stable/pike
Review: https://review.openstack.org/508872

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-10-24: Fix included in openstack/nova 17.0.0.0b1

This issue was fixed in the openstack/nova 17.0.0.0b1 development milestone.

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-12-01: Fix merged to nova (stable/pike)

#10

Reviewed: https://review.openstack.org/508872
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=aabf0b0bf60c513accc32a5084bb42093b65eb31
Submitter: Zuul
Branch: stable/pike

commit aabf0b0bf60c513accc32a5084bb42093b65eb31
Author: Balazs Gibizer <email address hidden>
Date: Wed Sep 27 17:56:17 2017 +0200

Fix race in delete allocation in ServerMovingTests

    Change-Id: I4ffd8eae73600eb2d4f6929ee6a7768adb80081d
    Closes-Bug: #1719915
    (cherry picked from commit 8a435c081df1653620cff5918ea66643d3487fd7)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2017-12-18: Fix included in openstack/nova 16.0.4

#11

This issue was fixed in the openstack/nova 16.0.4 release.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.