OpenStack Compute (nova)

test_live_migration_actions functional test randomly fails with "AssertionError: The migration table left empty."

Bug #1736976 reported by Matt Riedemann on 2017-12-07

This bug affects 2 people

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Undecided	Balazs Gibizer

Bug Description

Seen here:

http://logs.openstack.org/85/330285/175/check/openstack-tox-functional-py35/9a23bfd/testr_results.html.gz

ft1.1: nova.tests.functional.notification_sample_tests.test_instance.TestInstanceNotificationSampleWithMultipleComputeOldAttachFlow.test_live_migration_actions_StringException: pythonlogging:'': {{{
2017-12-07 10:10:57,771 WARNING [oslo_config.cfg] Config option key_manager.api_class is deprecated. Use option key_manager.backend instead.
2017-12-07 10:10:59,554 INFO [nova.service] Starting conductor node (version 17.0.0)
2017-12-07 10:10:59,571 INFO [nova.service] Starting scheduler node (version 17.0.0)
2017-12-07 10:10:59,595 INFO [nova.network.driver] Loading network driver 'nova.network.linux_net'
2017-12-07 10:10:59,596 INFO [nova.service] Starting network node (version 17.0.0)
2017-12-07 10:10:59,624 INFO [nova.virt.driver] Loading compute driver 'fake.FakeLiveMigrateDriver'
2017-12-07 10:10:59,624 INFO [nova.service] Starting compute node (version 17.0.0)
2017-12-07 10:10:59,647 WARNING [nova.compute.manager] No compute node record found for host compute. If this is the first time this service is starting on this host, then you can ignore this warning.
2017-12-07 10:10:59,647 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors).
2017-12-07 10:10:59,651 WARNING [nova.compute.resource_tracker] No compute node record for compute:fake-mini
2017-12-07 10:10:59,654 INFO [nova.compute.resource_tracker] Compute node record created for compute:fake-mini with uuid: 6dfc5763-1a0b-47e1-941f-af8b88f2cf6e
2017-12-07 10:10:59,672 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e" status: 404 len: 227 microversion: 1.0
2017-12-07 10:10:59,677 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 201 len: 0 microversion: 1.0
2017-12-07 10:10:59,678 INFO [nova.scheduler.client.report] [req-583c10f0-5400-48e0-9e17-9ca12bbd4c98] Created resource provider record via placement API for resource provider with UUID 6dfc5763-1a0b-47e1-941f-af8b88f2cf6e and name fake-mini.
2017-12-07 10:10:59,684 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e/aggregates" status: 200 len: 18 microversion: 1.1
2017-12-07 10:10:59,692 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e/inventories" status: 200 len: 54 microversion: 1.0
2017-12-07 10:10:59,702 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e/inventories" status: 200 len: 413 microversion: 1.0
2017-12-07 10:10:59,725 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e/allocations" status: 200 len: 54 microversion: 1.0
2017-12-07 10:10:59,726 INFO [nova.compute.resource_tracker] Final resource view: name=fake-mini phys_ram=800000MB used_ram=512MB phys_disk=600000GB used_disk=0GB total_vcpus=1000 used_vcpus=0 pci_stats=[]
2017-12-07 10:10:59,739 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e/inventories" status: 200 len: 413 microversion: 1.0
2017-12-07 10:10:59,744 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000319
2017-12-07 10:10:59,755 WARNING [nova.policy] Start using the new action 'os_compute_api:os-flavor-manage:create'. The existing action 'os_compute_api:os-flavor-manage' is being deprecated and will be removed in future release.
2017-12-07 10:10:59,769 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/flavors" status: 200 len: 592 microversion: 2.56 time: 0.022701
2017-12-07 10:10:59,772 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000249
2017-12-07 10:10:59,792 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/flavors/a22d5517-147c-4147-a0d1-e698df5cd4e3/os-extra_specs" status: 200 len: 51 microversion: 2.56 time: 0.018083
2017-12-07 10:10:59,823 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/os-keypairs" status: 201 len: 379 microversion: 2.56 time: 0.027772
2017-12-07 10:10:59,918 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 32 microversion: 2.56 time: 0.091302
2017-12-07 10:10:59,992 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers?reservation_id=r-os80yaw0" status: 200 len: 404 microversion: 2.56 time: 0.070785
2017-12-07 10:11:00,046 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 1815 microversion: 2.56 time: 0.051105
2017-12-07 10:11:00,059 INFO [nova.objects.resource_provider] Synced traits from os_traits into API DB: {'HW_GPU_API_DIRECT3D_V11_3', 'HW_NIC_SRIOV_QOS_TX', 'HW_GPU_API_DIRECT3D_V11_0', 'HW_GPU_API_DIRECT3D_V7_0', 'HW_GPU_API_DIRECTX_V11', 'HW_GPU_API_DIRECT3D_V9_0L', 'HW_CPU_X86_AESNI', 'HW_GPU_API_CUDA_V2_0', 'HW_GPU_RESOLUTION_W1024H768', 'HW_GPU_RESOLUTION_W1280H800', 'HW_NIC_DCB_PFC', 'HW_NIC_OFFLOAD_GENEVE', 'HW_GPU_API_DIRECT3D_V9_0C', 'HW_GPU_API_OPENGL_V2_1', 'HW_NIC_OFFLOAD_VXLAN', 'HW_GPU_API_CUDA_V5_3', 'HW_CPU_X86_TSX', 'HW_GPU_API_CUDA_V3_5', 'HW_CPU_X86_AVX512BW', 'HW_GPU_API_OPENGL_V1_5', 'STORAGE_DISK_HDD', 'HW_GPU_API_OPENGL_V2_0', 'HW_GPU_API_DIRECT3D_V9_0', 'HW_NIC_OFFLOAD_FDF', 'HW_NIC_OFFLOAD_SCS', 'HW_GPU_API_OPENGL_V3_0', 'HW_GPU_API_OPENCL_V2_1', 'HW_NIC_SRIOV', 'HW_NIC_ACCEL_TLS', 'HW_CPU_X86_VMX', 'HW_GPU_API_CUDA_V1_0', 'HW_CPU_X86_ASF', 'HW_CPU_X86_XOP', 'HW_GPU_API_CUDA_V6_0', 'HW_GPU_RESOLUTION_W1600H900', 'HW_CPU_X86_TBM', 'HW_GPU_API_OPENGL_V4_3', 'HW_GPU_API_OPENCL_V2_0', 'HW_NIC_OFFLOAD_QINQ', 'HW_NIC_OFFLOAD_LSO', 'HW_GPU_API_DIRECT3D_V11_1', 'HW_NIC_ACCEL_LZS', 'HW_NIC_DCB_QCN', 'HW_NIC_ACCEL_SSL', 'HW_GPU_API_CUDA_V3_0', 'HW_NIC_OFFLOAD_RX', 'HW_NIC_PROGRAMMABLE_PIPELINE', 'HW_GPU_API_DIRECTX_V12', 'HW_CPU_X86_SVM', 'HW_GPU_RESOLUTION_W1360H768', 'HW_CPU_X86_AVX512DQ', 'HW_GPU_API_CUDA_V2_1', 'HW_GPU_API_DIRECT3D_V10_1', 'HW_CPU_X86_AVX512F', 'HW_GPU_API_CUDA_V7_1', 'HW_NIC_SRIOV_MULTIQUEUE', 'HW_NIC_OFFLOAD_SG', 'HW_CPU_X86_SSE4A', 'HW_CPU_X86_AVX512VL', 'HW_CPU_X86_SGX', 'HW_GPU_API_DIRECT3D_V6_0', 'HW_NIC_ACCEL_ECC', 'HW_GPU_API_CUDA_V6_1', 'HW_NIC_OFFLOAD_RDMA', 'HW_GPU_API_OPENGL_V4_4', 'STORAGE_DISK_SSD', 'HW_GPU_API_OPENGL_V4_0', 'HW_GPU_API_DIRECT3D_V8_0', 'HW_GPU_RESOLUTION_W1600H1200', 'HW_NIC_ACCEL_IPSEC', 'HW_CPU_X86_AVX512PF', 'HW_CPU_X86_SSSE3', 'HW_CPU_X86_SSE3', 'HW_GPU_RESOLUTION_W1280H768', 'HW_CPU_X86_SSE41', 'HW_GPU_RESOLUTION_W1152H864', 'HW_CPU_X86_AVX512ER', 'HW_NIC_OFFLOAD_GSO', 'HW_GPU_RESOLUTION_W320H240', 'HW_CPU_X86_BMI', 'HW_CPU_X86_3DNOW', 'HW_CPU_X86_ABM', 'HW_GPU_API_OPENGL_V4_2', 'HW_GPU_API_OPENGL_V1_4', 'HW_NIC_OFFLOAD_GRE', 'HW_GPU_RESOLUTION_W7680H4320', 'HW_GPU_RESOLUTION_W2560H1440', 'HW_NIC_OFFLOAD_RXVLAN', 'HW_GPU_API_VULKAN', 'HW_GPU_API_OPENGL_V1_2', 'HW_CPU_X86_SSE', 'HW_NIC_OFFLOAD_TSO', 'HW_GPU_API_CUDA_V1_2', 'HW_CPU_X86_MMX', 'HW_NIC_OFFLOAD_UFO', 'HW_GPU_RESOLUTION_W1366H768', 'HW_GPU_API_DIRECT3D_V12_0', 'HW_GPU_API_OPENGL_V1_1', 'HW_GPU_RESOLUTION_W1440H900', 'HW_NIC_VMDQ', 'HW_CPU_X86_AVX2', 'HW_GPU_API_OPENCL_V1_0', 'HW_NIC_OFFLOAD_L2CRC', 'HW_NIC_DCB_ETS', 'HW_NIC_MULTIQUEUE', 'HW_CPU_X86_CLMUL', 'HW_CPU_X86_SSE2', 'HW_GPU_API_OPENGL_V1_3', 'HW_CPU_X86_FMA4', 'HW_NIC_OFFLOAD_LRO', 'HW_GPU_API_CUDA_V1_3', 'HW_GPU_API_DIRECTX_V10', 'HW_NIC_ACCEL_DIFFIEH', 'HW_GPU_RESOLUTION_W1920H1080', 'HW_GPU_API_CUDA_V3_2', 'MISC_SHARES_VIA_AGGREGATE', 'HW_GPU_RESOLUTION_W1280H1024', 'HW_GPU_API_DIRECT3D_V11_2', 'HW_CPU_X86_F16C', 'HW_GPU_API_DIRECT2D', 'HW_NIC_OFFLOAD_TX', 'HW_NIC_OFFLOAD_TCS', 'HW_GPU_API_OPENGL_V4_1', 'HW_GPU_API_DIRECT3D_V10_0', 'HW_GPU_API_OPENGL_V3_3', 'HW_GPU_API_CUDA_V5_2', 'HW_GPU_API_DIRECT3D_V9_0B', 'HW_GPU_API_OPENGL_V3_2', 'HW_GPU_API_CUDA_V7_0', 'HW_GPU_RESOLUTION_W640H480', 'HW_GPU_RESOLUTION_W3840H2160', 'HW_GPU_RESOLUTION_W1920H1200', 'HW_GPU_API_OPENCL_V2_2', 'HW_CPU_X86_FMA3', 'HW_GPU_API_OPENCL_V1_2', 'HW_GPU_API_CUDA_V1_1', 'HW_GPU_API_DIRECT3D_V8_1', 'HW_GPU_RESOLUTION_W800H600', 'HW_CPU_X86_MPX', 'HW_GPU_API_CUDA_V6_2', 'HW_GPU_RESOLUTION_W1680H1050', 'HW_GPU_API_OPENGL_V3_1', 'HW_GPU_API_DXVA', 'HW_GPU_API_OPENCL_V1_1', 'HW_NIC_ACCEL_DEFLATE', 'HW_CPU_X86_AVX', 'HW_NIC_ACCEL_RSA', 'HW_GPU_API_CUDA_V3_7', 'HW_CPU_X86_AVX512CD', 'HW_GPU_RESOLUTION_W1280H720', 'HW_GPU_API_CUDA_V5_0', 'HW_CPU_X86_BMI2', 'HW_NIC_OFFLOAD_GRO', 'HW_CPU_X86_SHA', 'HW_GPU_API_OPENGL_V4_5', 'HW_NIC_OFFLOAD_RXHASH', 'HW_NIC_OFFLOAD_TXUDP', 'HW_GPU_RESOLUTION_W1024H600', 'HW_NIC_OFFLOAD_TXVLAN', 'HW_CPU_X86_SSE42', 'HW_NIC_OFFLOAD_UCS', 'HW_NIC_SRIOV_QOS_RX', 'HW_GPU_RESOLUTION_W2560H1600'}
2017-12-07 10:11:00,083 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: 387 microversion: 1.10
2017-12-07 10:11:00,116 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 19 microversion: 1.0
2017-12-07 10:11:00,131 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 204 len: 0 microversion: 1.10
2017-12-07 10:11:00,292 INFO [nova.compute.claims] Attempting claim on node fake-mini: memory 512 MB, disk 1 GB, vcpus 1 CPU
2017-12-07 10:11:00,292 INFO [nova.compute.claims] Total memory: 800000 MB, used: 512.00 MB
2017-12-07 10:11:00,292 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited
2017-12-07 10:11:00,292 INFO [nova.compute.claims] Total disk: 600000 GB, used: 0.00 GB
2017-12-07 10:11:00,292 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited
2017-12-07 10:11:00,292 INFO [nova.compute.claims] Total vcpu: 1000 VCPU, used: 0.00 VCPU
2017-12-07 10:11:00,293 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited
2017-12-07 10:11:00,293 INFO [nova.compute.claims] Claim successful on node fake-mini
2017-12-07 10:11:00,349 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/6dfc5763-1a0b-47e1-941f-af8b88f2cf6e/inventories" status: 200 len: 413 microversion: 1.0
2017-12-07 10:11:00,450 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 134 microversion: 1.0
2017-12-07 10:11:00,491 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor.
2017-12-07 10:11:00,541 INFO [nova.compute.manager] Took 0.26 seconds to build instance.
2017-12-07 10:11:00,648 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 2061 microversion: 2.56 time: 0.097998
2017-12-07 10:11:00,658 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'compute'. Re-created its InstanceList.
2017-12-07 10:11:00,734 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/tags" status: 200 len: 18 microversion: 2.56 time: 0.083215
2017-12-07 10:11:00,782 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/os-volume_attachments" status: 200 len: 194 microversion: 2.56 time: 0.044636
2017-12-07 10:11:00,827 INFO [nova.compute.manager] Attaching volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 to /dev/sdb
2017-12-07 10:11:00,888 INFO [nova.virt.driver] Loading compute driver 'fake.FakeLiveMigrateDriver'
2017-12-07 10:11:00,888 INFO [nova.service] Starting compute node (version 17.0.0)
2017-12-07 10:11:00,907 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-12-07 10:11:00,907 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors).
2017-12-07 10:11:00,911 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2
2017-12-07 10:11:00,914 INFO [nova.compute.resource_tracker] Compute node record created for host2:host2 with uuid: ce8a2998-42ff-4779-9c53-d783abfc7f09
2017-12-07 10:11:00,929 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/ce8a2998-42ff-4779-9c53-d783abfc7f09" status: 404 len: 227 microversion: 1.0
2017-12-07 10:11:00,935 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 201 len: 0 microversion: 1.0
2017-12-07 10:11:00,936 INFO [nova.scheduler.client.report] [req-ff261f06-0071-4103-b17c-0b8977aafd50] Created resource provider record via placement API for resource provider with UUID ce8a2998-42ff-4779-9c53-d783abfc7f09 and name host2.
2017-12-07 10:11:00,943 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/ce8a2998-42ff-4779-9c53-d783abfc7f09/aggregates" status: 200 len: 18 microversion: 1.1
2017-12-07 10:11:00,951 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/ce8a2998-42ff-4779-9c53-d783abfc7f09/inventories" status: 200 len: 54 microversion: 1.0
2017-12-07 10:11:00,963 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/ce8a2998-42ff-4779-9c53-d783abfc7f09/inventories" status: 200 len: 413 microversion: 1.0
2017-12-07 10:11:00,986 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/ce8a2998-42ff-4779-9c53-d783abfc7f09/allocations" status: 200 len: 54 microversion: 1.0
2017-12-07 10:11:00,987 INFO [nova.compute.resource_tracker] Final resource view: name=host2 phys_ram=800000MB used_ram=512MB phys_disk=600000GB used_disk=0GB total_vcpus=1000 used_vcpus=0 pci_stats=[]
2017-12-07 10:11:01,001 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/ce8a2998-42ff-4779-9c53-d783abfc7f09/inventories" status: 200 len: 413 microversion: 1.0
2017-12-07 10:11:01,090 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/action" status: 202 len: 0 microversion: 2.56 time: 0.084449
2017-12-07 10:11:01,480 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 134 microversion: 1.0
2017-12-07 10:11:01,488 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 134 microversion: 1.0
2017-12-07 10:11:01,509 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 204 len: 0 microversion: 1.10
2017-12-07 10:11:01,557 ERROR [nova.compute.manager] Pre live migration failed at host2
Traceback (most recent call last):
  File "/home/zuul/src/git.openstack.org/openstack/nova/nova/compute/manager.py", line 5901, in _do_live_migration
    block_migration, disk, dest, migrate_data)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional-py35/lib/python3.5/site-packages/mock/mock.py", line 1062, in __call__
    return _mock_self._mock_call(*args, **kwargs)
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional-py35/lib/python3.5/site-packages/mock/mock.py", line 1118, in _mock_call
    raise effect
nova.exception.LiveMigrationWithOldNovaNotSupported: Live migration with API v2.25 requires all the Mitaka upgrade to be complete before it is available.
2017-12-07 10:11:01,602 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 251 microversion: 1.0
2017-12-07 10:11:01,617 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 204 len: 0 microversion: 1.10
2017-12-07 10:11:01,710 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb
2017-12-07 10:11:01,711 WARNING [nova.virt.block_device] Detaching volume from unknown instance
2017-12-07 10:11:01,837 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 2145 microversion: 2.56 time: 0.112645
2017-12-07 10:11:01,918 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/action" status: 202 len: 0 microversion: 2.56 time: 0.077696
2017-12-07 10:11:02,019 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 2155 microversion: 2.56 time: 0.098812
2017-12-07 10:11:02,069 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.046757
2017-12-07 10:11:02,124 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.051718
2017-12-07 10:11:02,171 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.043789
2017-12-07 10:11:02,220 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.045979
2017-12-07 10:11:02,268 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.045756
2017-12-07 10:11:02,308 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.036329
2017-12-07 10:11:02,352 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.040897
2017-12-07 10:11:02,399 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.044295
2017-12-07 10:11:02,443 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.041734
2017-12-07 10:11:02,490 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 134 microversion: 1.0
2017-12-07 10:11:02,496 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.050253
2017-12-07 10:11:02,505 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "GET /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 200 len: 134 microversion: 1.0
2017-12-07 10:11:02,551 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.052349
2017-12-07 10:11:02,560 INFO [nova.api.openstack.placement.requestlog] 127.0.0.1 "PUT /placement/allocations/76be29c3-9f8b-4ce0-a788-790a1e86a52a" status: 204 len: 0 microversion: 1.10
2017-12-07 10:11:02,597 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.043768
2017-12-07 10:11:02,636 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.035920
2017-12-07 10:11:02,680 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 18 microversion: 2.56 time: 0.041373
2017-12-07 10:11:02,726 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 494 microversion: 2.56 time: 0.042453
2017-12-07 10:11:02,765 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 494 microversion: 2.56 time: 0.036300
2017-12-07 10:11:02,808 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 494 microversion: 2.56 time: 0.040401
2017-12-07 10:11:02,856 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 494 microversion: 2.56 time: 0.045650
2017-12-07 10:11:02,926 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 494 microversion: 2.56 time: 0.066809
2017-12-07 10:11:02,976 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/76be29c3-9f8b-4ce0-a788-790a1e86a52a/migrations" status: 200 len: 494 microversion: 2.56 time: 0.047373
}}}

...

Traceback (most recent call last):
  File "/home/zuul/src/git.openstack.org/openstack/nova/nova/tests/functional/notification_sample_tests/test_instance.py", line 63, in test_live_migration_actions
    action(server)
  File "/home/zuul/src/git.openstack.org/openstack/nova/nova/tests/functional/notification_sample_tests/test_instance.py", line 139, in _test_live_migration_abort
    migrations = self._wait_and_get_migrations(server)
  File "/home/zuul/src/git.openstack.org/openstack/nova/nova/tests/functional/notification_sample_tests/notification_sample_base.py", line 267, in _wait_and_get_migrations
    self.fail('The migration table left empty.')
  File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional-py35/lib/python3.5/site-packages/unittest2/case.py", line 690, in fail
    raise self.failureException(msg)
AssertionError: The migration table left empty.

This stands out:

WARNING [nova.virt.block_device] Detaching volume from unknown instance

We probably have some kind of race, or maybe an issue in the CinderFixture used in this test.

Tags:

Revision history for this message

Matt Riedemann (mriedem) wrote on 2017-12-07:

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22AssertionError%3A%20The%20migration%20table%20left%20empty.%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d

6 hits in 7 days, check and gate, all failures.

Balazs Gibizer (balazs-gibizer) on 2017-12-11

tags:

added: notifications

Revision history for this message

Balazs Gibizer (balazs-gibizer) wrote on 2017-12-12:

The log line
WARNING [nova.virt.block_device] Detaching volume from unknown instance
visible in a successful test run as well [1] So I think it is unrelated.

In the other hand the _wait_and_get_migrations tries to get the migration from the nova API 20 times but it does not apply any wait between trials. In a successful run it took 1.5 seconds to have the migration appear on the API while in the failed run the util function was fast enough to give up in about 1 second. So I feel that the problem is simply a timing issue. Our test utils gives up too early as it tries to fast to get the ongoing migration to delete.

[1]http://paste.openstack.org/show/628733/

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

Revision history for this message

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

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

Changed in nova:
status:	New → In Progress

Revision history for this message

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

Reviewed: https://review.openstack.org/527440
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=937db90146f04783183644bfeff78b1f6bf854b8
Submitter: Zuul
Branch: master

commit 937db90146f04783183644bfeff78b1f6bf854b8
Author: Balazs Gibizer <email address hidden>
Date: Tue Dec 12 16:33:55 2017 +0100

Stabilize test_live_migration_abort func test

    The test_live_migration_abort test step in the
    test_live_migration_actions notification sample test was unstable.
    The test starts a live migration and then deletes the migration object
    via the REST API to abort it. The test randomly failed to find the
    migration object on the REST API. Based on the comparision of the logs
    of the successful and unsuccesful runs it was visible that in the
    unsuccesful case the test gave up to wait for the migration object too
    early. In a succesful run it took 1.5 seconds after the the migration
    API call to have the migration object appear on the API while in an
    unsuccessful case the test gave up after 1 second.

    This early give up was cause by the fact that the loop trying to
    get a migration does not applied any delay between such trials and
    therefore the 20 attempts run out quickly.

This patch introduces a short sleep between trials to stabilize the
test.

Change-Id: I6be3b236d8eadcde5714c08069708dff303dfd4d
Closes-Bug: #1736976

Changed in nova:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-01-26: Fix included in openstack/nova 17.0.0.0b3

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

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.