Public bug reported: Seen here:
http://logs.openstack.org/47/638047/9/check/nova-tox-functional/71f64ae /job-output.txt.gz#_2019-04-02_00_07_32_290065 2019-04-02 00:07:32.290065 | ubuntu-bionic | {2} nova.tests.functional.notification_sample_tests.test_instance.TestInstanceNotificationSampleWithMultipleComputeOldAttachFlow.test_multiple_compute_actions [14.302238s] ... FAILED 2019-04-02 00:07:32.290219 | ubuntu-bionic | 2019-04-02 00:07:32.290275 | ubuntu-bionic | Captured traceback: 2019-04-02 00:07:32.290318 | ubuntu-bionic | ~~~~~~~~~~~~~~~~~~~ 2019-04-02 00:07:32.290378 | ubuntu-bionic | Traceback (most recent call last): 2019-04-02 00:07:32.290525 | ubuntu-bionic | File "nova/tests/functional/notification_sample_tests/test_instance.py", line 68, in test_multiple_compute_actions 2019-04-02 00:07:32.290569 | ubuntu-bionic | action(server) 2019-04-02 00:07:32.290726 | ubuntu-bionic | File "nova/tests/functional/notification_sample_tests/test_instance.py", line 311, in _test_live_migration_force_complete 2019-04-02 00:07:32.290822 | ubuntu-bionic | self.assertEqual(6, len(fake_notifier.VERSIONED_NOTIFICATIONS)) 2019-04-02 00:07:32.291011 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual 2019-04-02 00:07:32.291148 | ubuntu-bionic | self.assertThat(observed, matcher, message) 2019-04-02 00:07:32.291351 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat 2019-04-02 00:07:32.291402 | ubuntu-bionic | raise mismatch_error 2019-04-02 00:07:32.291475 | ubuntu-bionic | testtools.matchers._impl.MismatchError: 6 != 7 2019-04-02 00:07:32.291497 | ubuntu-bionic | 2019-04-02 00:07:32.291515 | ubuntu-bionic | 2019-04-02 00:07:32.291558 | ubuntu-bionic | Captured pythonlogging: 2019-04-02 00:07:32.291602 | ubuntu-bionic | ~~~~~~~~~~~~~~~~~~~~~~~ 2019-04-02 00:07:32.291737 | ubuntu-bionic | 2019-04-02 00:07:19,024 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring. 2019-04-02 00:07:32.291908 | ubuntu-bionic | 2019-04-02 00:07:19,053 INFO [nova.service] Starting conductor node (version 19.1.0) 2019-04-02 00:07:32.292181 | ubuntu-bionic | 2019-04-02 00:07:19,073 INFO [nova.service] Starting scheduler node (version 19.1.0) 2019-04-02 00:07:32.292326 | ubuntu-bionic | 2019-04-02 00:07:19,089 INFO [nova.network.driver] Loading network driver 'nova.network.linux_net' 2019-04-02 00:07:32.292438 | ubuntu-bionic | 2019-04-02 00:07:19,090 INFO [nova.service] Starting network node (version 19.1.0) 2019-04-02 00:07:32.292606 | ubuntu-bionic | 2019-04-02 00:07:19,118 INFO [nova.virt.driver] Loading compute driver 'fake.FakeLiveMigrateDriver' 2019-04-02 00:07:32.292820 | ubuntu-bionic | 2019-04-02 00:07:19,118 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors). 2019-04-02 00:07:32.292945 | ubuntu-bionic | 2019-04-02 00:07:19,119 INFO [nova.service] Starting compute node (version 19.1.0) 2019-04-02 00:07:32.293174 | ubuntu-bionic | 2019-04-02 00:07:19,141 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. 2019-04-02 00:07:32.293304 | ubuntu-bionic | 2019-04-02 00:07:19,144 WARNING [nova.compute.resource_tracker] No compute node record for compute:fake-mini 2019-04-02 00:07:32.293484 | ubuntu-bionic | 2019-04-02 00:07:19,148 INFO [nova.compute.resource_tracker] Compute node record created for compute:fake-mini with uuid: 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 2019-04-02 00:07:32.293687 | ubuntu-bionic | 2019-04-02 00:07:19,187 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=109a2d73-cdf9-4d76-8e6e-74dc79ff7359" status: 200 len: 26 microversion: 1.14 2019-04-02 00:07:32.293848 | ubuntu-bionic | 2019-04-02 00:07:19,193 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 832 microversion: 1.20 2019-04-02 00:07:32.294112 | ubuntu-bionic | 2019-04-02 00:07:19,194 INFO [nova.scheduler.client.report] [req-5b6c791d-5709-4f36-8fbe-c3e02869e35d] Created resource provider record via placement API for resource provider with UUID 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 and name fake-mini. 2019-04-02 00:07:32.294321 | ubuntu-bionic | 2019-04-02 00:07:19,208 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/inventories" status: 200 len: 413 microversion: 1.26 2019-04-02 00:07:32.294693 | ubuntu-bionic | 2019-04-02 00:07:19,220 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_VOLUME_EXTEND,COMPUTE_DEVICE_TAGGING" status: 200 len: 226 microversion: 1.6 2019-04-02 00:07:32.294944 | ubuntu-bionic | 2019-04-02 00:07:19,234 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/traits" status: 200 len: 261 microversion: 1.6 2019-04-02 00:07:32.295159 | ubuntu-bionic | 2019-04-02 00:07:19,239 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000296 2019-04-02 00:07:32.295377 | ubuntu-bionic | 2019-04-02 00:07:19,364 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/flavors" status: 200 len: 611 microversion: 2.72 time: 0.122205 2019-04-02 00:07:32.297249 | ubuntu-bionic | 2019-04-02 00:07:19,367 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000239 2019-04-02 00:07:32.297541 | ubuntu-bionic | 2019-04-02 00:07:19,386 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.72 time: 0.017107 2019-04-02 00:07:32.297859 | ubuntu-bionic | 2019-04-02 00:07:19,413 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/os-keypairs" status: 201 len: 379 microversion: 2.72 time: 0.024532 2019-04-02 00:07:32.298070 | ubuntu-bionic | 2019-04-02 00:07:19,512 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 32 microversion: 2.72 time: 0.096062 2019-04-02 00:07:32.298335 | ubuntu-bionic | 2019-04-02 00:07:19,574 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers?reservation_id=r-hnbz5gim" status: 200 len: 404 microversion: 2.72 time: 0.058885 2019-04-02 00:07:32.298570 | ubuntu-bionic | 2019-04-02 00:07:19,614 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 674 microversion: 1.29 2019-04-02 00:07:32.298808 | ubuntu-bionic | 2019-04-02 00:07:19,637 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 1872 microversion: 2.72 time: 0.059987 2019-04-02 00:07:32.298997 | ubuntu-bionic | 2019-04-02 00:07:19,652 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.299252 | ubuntu-bionic | 2019-04-02 00:07:19,673 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.299417 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] Attempting claim on node fake-mini: memory 512 MB, disk 1 GB, vcpus 1 CPU 2019-04-02 00:07:32.299532 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] Total memory: 800000 MB, used: 512.00 MB 2019-04-02 00:07:32.299656 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited 2019-04-02 00:07:32.299765 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] Total disk: 600000 GB, used: 0.00 GB 2019-04-02 00:07:32.299893 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited 2019-04-02 00:07:32.300038 | ubuntu-bionic | 2019-04-02 00:07:19,883 INFO [nova.compute.claims] Total vcpu: 1000 VCPU, used: 0.00 VCPU 2019-04-02 00:07:32.300191 | ubuntu-bionic | 2019-04-02 00:07:19,883 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited 2019-04-02 00:07:32.300309 | ubuntu-bionic | 2019-04-02 00:07:19,883 INFO [nova.compute.claims] Claim successful on node fake-mini 2019-04-02 00:07:32.300504 | ubuntu-bionic | 2019-04-02 00:07:20,069 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.300635 | ubuntu-bionic | 2019-04-02 00:07:20,112 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor. 2019-04-02 00:07:32.300751 | ubuntu-bionic | 2019-04-02 00:07:20,171 INFO [nova.compute.manager] Took 0.30 seconds to build instance. 2019-04-02 00:07:32.300911 | ubuntu-bionic | 2019-04-02 00:07:20,229 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'compute'. Re-created its InstanceList. 2019-04-02 00:07:32.301157 | ubuntu-bionic | 2019-04-02 00:07:20,258 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2118 microversion: 2.72 time: 0.103617 2019-04-02 00:07:32.301410 | ubuntu-bionic | 2019-04-02 00:07:20,347 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/tags" status: 200 len: 18 microversion: 2.72 time: 0.082867 2019-04-02 00:07:32.301678 | ubuntu-bionic | 2019-04-02 00:07:20,426 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/os-volume_attachments" status: 200 len: 207 microversion: 2.72 time: 0.076133 2019-04-02 00:07:32.301824 | ubuntu-bionic | 2019-04-02 00:07:20,468 INFO [nova.compute.manager] Attaching volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 to /dev/sdb 2019-04-02 00:07:32.301945 | ubuntu-bionic | 2019-04-02 00:07:20,562 INFO [nova.virt.driver] Loading compute driver 'fake.FakeLiveMigrateDriver' 2019-04-02 00:07:32.302148 | ubuntu-bionic | 2019-04-02 00:07:20,564 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors). 2019-04-02 00:07:32.302287 | ubuntu-bionic | 2019-04-02 00:07:20,565 INFO [nova.service] Starting compute node (version 19.1.0) 2019-04-02 00:07:32.302553 | ubuntu-bionic | 2019-04-02 00:07:20,586 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. 2019-04-02 00:07:32.302686 | ubuntu-bionic | 2019-04-02 00:07:20,591 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2 2019-04-02 00:07:32.302861 | ubuntu-bionic | 2019-04-02 00:07:20,594 INFO [nova.compute.resource_tracker] Compute node record created for host2:host2 with uuid: e30090d2-c1ab-4528-a338-62182708f6c6 2019-04-02 00:07:32.303114 | ubuntu-bionic | 2019-04-02 00:07:20,625 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=e30090d2-c1ab-4528-a338-62182708f6c6" status: 200 len: 26 microversion: 1.14 2019-04-02 00:07:32.303290 | ubuntu-bionic | 2019-04-02 00:07:20,631 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20 2019-04-02 00:07:32.303558 | ubuntu-bionic | 2019-04-02 00:07:20,632 INFO [nova.scheduler.client.report] [req-5b6c791d-5709-4f36-8fbe-c3e02869e35d] Created resource provider record via placement API for resource provider with UUID e30090d2-c1ab-4528-a338-62182708f6c6 and name host2. 2019-04-02 00:07:32.303767 | ubuntu-bionic | 2019-04-02 00:07:20,641 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/e30090d2-c1ab-4528-a338-62182708f6c6/inventories" status: 200 len: 413 microversion: 1.26 2019-04-02 00:07:32.304155 | ubuntu-bionic | 2019-04-02 00:07:20,647 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_VOLUME_EXTEND,COMPUTE_DEVICE_TAGGING" status: 200 len: 226 microversion: 1.6 2019-04-02 00:07:32.304376 | ubuntu-bionic | 2019-04-02 00:07:20,658 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/e30090d2-c1ab-4528-a338-62182708f6c6/traits" status: 200 len: 261 microversion: 1.6 2019-04-02 00:07:32.304620 | ubuntu-bionic | 2019-04-02 00:07:20,739 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.076845 2019-04-02 00:07:32.304811 | ubuntu-bionic | 2019-04-02 00:07:20,769 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.305007 | ubuntu-bionic | 2019-04-02 00:07:20,776 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.305201 | ubuntu-bionic | 2019-04-02 00:07:20,782 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b8bed8a2-cd41-4511-86cd-8563dbeb2072" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.305351 | ubuntu-bionic | 2019-04-02 00:07:20,815 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.305591 | ubuntu-bionic | 2019-04-02 00:07:20,880 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.305725 | ubuntu-bionic | 2019-04-02 00:07:20,908 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.305834 | ubuntu-bionic | 2019-04-02 00:07:20,908 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.306029 | ubuntu-bionic | 2019-04-02 00:07:20,917 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.306223 | ubuntu-bionic | 2019-04-02 00:07:20,937 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.306379 | ubuntu-bionic | 2019-04-02 00:07:21,162 ERROR [nova.compute.manager] Pre live migration failed at host2 2019-04-02 00:07:32.306447 | ubuntu-bionic | Traceback (most recent call last): 2019-04-02 00:07:32.306535 | ubuntu-bionic | File "nova/compute/manager.py", line 7236, in _do_live_migration 2019-04-02 00:07:32.306602 | ubuntu-bionic | block_migration, disk, dest, migrate_data) 2019-04-02 00:07:32.306767 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/mock/mock.py", line 1062, in __call__ 2019-04-02 00:07:32.306860 | ubuntu-bionic | return _mock_self._mock_call(*args, **kwargs) 2019-04-02 00:07:32.307071 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/mock/mock.py", line 1118, in _mock_call 2019-04-02 00:07:32.307122 | ubuntu-bionic | raise effect 2019-04-02 00:07:32.307250 | ubuntu-bionic | DestinationDiskExists: The supplied disk path (path) already exists, it is expected not to exist. 2019-04-02 00:07:32.307440 | ubuntu-bionic | 2019-04-02 00:07:21,175 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b8bed8a2-cd41-4511-86cd-8563dbeb2072" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.307658 | ubuntu-bionic | 2019-04-02 00:07:21,176 INFO [nova.compute.manager] Swapping old allocation on 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 held by migration b8bed8a2-cd41-4511-86cd-8563dbeb2072 for instance 2019-04-02 00:07:32.307881 | ubuntu-bionic | 2019-04-02 00:07:21,184 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b8bed8a2-cd41-4511-86cd-8563dbeb2072" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.308078 | ubuntu-bionic | 2019-04-02 00:07:21,191 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.308539 | ubuntu-bionic | 2019-04-02 00:07:21,192 WARNING [nova.scheduler.client.report] Overwriting current allocation {u'project_id': u'6f70656e737461636b20342065766572', u'consumer_generation': 1, u'user_id': u'fake', u'allocations': {u'e30090d2-c1ab-4528-a338-62182708f6c6': {u'generation': 3, u'resources': {u'VCPU': 1, u'DISK_GB': 1, u'MEMORY_MB': 512}}}} on consumer dc76de5a-d330-462a-9b6b-a15d59ac9199 2019-04-02 00:07:32.308733 | ubuntu-bionic | 2019-04-02 00:07:21,225 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.308911 | ubuntu-bionic | 2019-04-02 00:07:21,322 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb 2019-04-02 00:07:32.309032 | ubuntu-bionic | 2019-04-02 00:07:21,322 WARNING [nova.virt.block_device] Detaching volume from unknown instance 2019-04-02 00:07:32.309277 | ubuntu-bionic | 2019-04-02 00:07:21,654 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.124296 2019-04-02 00:07:32.309521 | ubuntu-bionic | 2019-04-02 00:07:21,738 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.080526 2019-04-02 00:07:32.309772 | ubuntu-bionic | 2019-04-02 00:07:21,823 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2212 microversion: 2.72 time: 0.082117 2019-04-02 00:07:32.309962 | ubuntu-bionic | 2019-04-02 00:07:21,868 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.310215 | ubuntu-bionic | 2019-04-02 00:07:21,875 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 18 microversion: 2.72 time: 0.049653 2019-04-02 00:07:32.310434 | ubuntu-bionic | 2019-04-02 00:07:21,879 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.310669 | ubuntu-bionic | 2019-04-02 00:07:21,885 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.310836 | ubuntu-bionic | 2019-04-02 00:07:21,911 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.311666 | ubuntu-bionic | 2019-04-02 00:07:21,968 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.311831 | ubuntu-bionic | 2019-04-02 00:07:21,993 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.311945 | ubuntu-bionic | 2019-04-02 00:07:21,993 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.312161 | ubuntu-bionic | 2019-04-02 00:07:22,002 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.312360 | ubuntu-bionic | 2019-04-02 00:07:22,020 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.312509 | ubuntu-bionic | 2019-04-02 00:07:22,274 INFO [nova.compute.manager] Took 0.10 seconds for pre_live_migration on destination host host2. 2019-04-02 00:07:32.312765 | ubuntu-bionic | 2019-04-02 00:07:22,424 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 540 microversion: 2.72 time: 0.046006 2019-04-02 00:07:32.313057 | ubuntu-bionic | 2019-04-02 00:07:22,468 INFO [nova.api.openstack.requestlog] 127.0.0.1 "DELETE /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations/2" status: 202 len: 0 microversion: 2.72 time: 0.041235 2019-04-02 00:07:32.313305 | ubuntu-bionic | 2019-04-02 00:07:22,582 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2212 microversion: 2.72 time: 0.070385 2019-04-02 00:07:32.313501 | ubuntu-bionic | 2019-04-02 00:07:22,609 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.313708 | ubuntu-bionic | 2019-04-02 00:07:22,611 INFO [nova.compute.manager] Swapping old allocation on 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 held by migration cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc for instance 2019-04-02 00:07:32.313902 | ubuntu-bionic | 2019-04-02 00:07:22,624 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.314144 | ubuntu-bionic | 2019-04-02 00:07:22,641 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.314574 | ubuntu-bionic | 2019-04-02 00:07:22,642 WARNING [nova.scheduler.client.report] Overwriting current allocation {u'project_id': u'6f70656e737461636b20342065766572', u'consumer_generation': 1, u'user_id': u'fake', u'allocations': {u'e30090d2-c1ab-4528-a338-62182708f6c6': {u'generation': 4, u'resources': {u'VCPU': 1, u'DISK_GB': 1, u'MEMORY_MB': 512}}}} on consumer dc76de5a-d330-462a-9b6b-a15d59ac9199 2019-04-02 00:07:32.314728 | ubuntu-bionic | 2019-04-02 00:07:22,686 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.314900 | ubuntu-bionic | 2019-04-02 00:07:22,742 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb 2019-04-02 00:07:32.315023 | ubuntu-bionic | 2019-04-02 00:07:22,742 WARNING [nova.virt.block_device] Detaching volume from unknown instance 2019-04-02 00:07:32.315310 | ubuntu-bionic | 2019-04-02 00:07:23,197 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.109925 2019-04-02 00:07:32.315594 | ubuntu-bionic | 2019-04-02 00:07:23,295 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.081375 2019-04-02 00:07:32.315855 | ubuntu-bionic | 2019-04-02 00:07:23,391 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.092867 2019-04-02 00:07:32.316045 | ubuntu-bionic | 2019-04-02 00:07:23,421 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.316270 | ubuntu-bionic | 2019-04-02 00:07:23,430 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.316456 | ubuntu-bionic | 2019-04-02 00:07:23,437 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/1ef7333e-9209-46e5-8997-2372a7a2c1ca" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.316604 | ubuntu-bionic | 2019-04-02 00:07:23,472 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.316817 | ubuntu-bionic | 2019-04-02 00:07:23,536 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.316941 | ubuntu-bionic | 2019-04-02 00:07:23,568 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.317042 | ubuntu-bionic | 2019-04-02 00:07:23,568 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.317219 | ubuntu-bionic | 2019-04-02 00:07:23,577 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.317398 | ubuntu-bionic | 2019-04-02 00:07:23,600 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.317530 | ubuntu-bionic | 2019-04-02 00:07:23,894 INFO [nova.compute.manager] Took 0.11 seconds for pre_live_migration on destination host host2. 2019-04-02 00:07:32.317769 | ubuntu-bionic | 2019-04-02 00:07:23,984 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 540 microversion: 2.72 time: 0.048497 2019-04-02 00:07:32.317876 | ubuntu-bionic | 2019-04-02 00:07:28,907 INFO [nova.compute.manager] _post_live_migration() is started.. 2019-04-02 00:07:32.317985 | ubuntu-bionic | 2019-04-02 00:07:29,062 INFO [nova.compute.manager] Post operation of migration started 2019-04-02 00:07:32.318104 | ubuntu-bionic | 2019-04-02 00:07:29,203 WARNING [nova.compute.resource_tracker] Instance not resizing, skipping migration. 2019-04-02 00:07:32.318305 | ubuntu-bionic | 2019-04-02 00:07:29,221 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/allocations" status: 200 len: 152 microversion: 1.0 2019-04-02 00:07:32.318422 | ubuntu-bionic | 2019-04-02 00:07:29,243 INFO [nova.compute.manager] Migrating instance to host2 finished successfully. 2019-04-02 00:07:32.318600 | ubuntu-bionic | 2019-04-02 00:07:29,260 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/1ef7333e-9209-46e5-8997-2372a7a2c1ca" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.318782 | ubuntu-bionic | 2019-04-02 00:07:29,356 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/1ef7333e-9209-46e5-8997-2372a7a2c1ca" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.318924 | ubuntu-bionic | 2019-04-02 00:07:29,357 INFO [nova.scheduler.client.report] Deleted allocation for migration 1ef7333e-9209-46e5-8997-2372a7a2c1ca 2019-04-02 00:07:32.319202 | ubuntu-bionic | 2019-04-02 00:07:29,391 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2196 microversion: 2.72 time: 0.110748 2019-04-02 00:07:32.319474 | ubuntu-bionic | 2019-04-02 00:07:29,414 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-services?binary=nova-compute&host=host2&" status: 200 len: 248 microversion: 2.72 time: 0.019628 2019-04-02 00:07:32.319730 | ubuntu-bionic | 2019-04-02 00:07:29,442 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/os-services/8b2330ad-82ec-40d7-98c8-facd2a4c415b" status: 200 len: 246 microversion: 2.72 time: 0.025102 2019-04-02 00:07:32.319962 | ubuntu-bionic | 2019-04-02 00:07:29,572 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 200 len: 0 microversion: 2.72 time: 0.127196 2019-04-02 00:07:32.320210 | ubuntu-bionic | 2019-04-02 00:07:29,668 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2207 microversion: 2.72 time: 0.093253 2019-04-02 00:07:32.320431 | ubuntu-bionic | 2019-04-02 00:07:29,786 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.320654 | ubuntu-bionic | 2019-04-02 00:07:29,801 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2207 microversion: 2.72 time: 0.129291 2019-04-02 00:07:32.320790 | ubuntu-bionic | 2019-04-02 00:07:29,815 INFO [nova.scheduler.host_manager] Host filter only checking host compute and node fake-mini 2019-04-02 00:07:32.320891 | ubuntu-bionic | 2019-04-02 00:07:29,815 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.321074 | ubuntu-bionic | 2019-04-02 00:07:29,825 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.321249 | ubuntu-bionic | 2019-04-02 00:07:29,854 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.321336 | ubuntu-bionic | 2019-04-02 00:07:29,903 INFO [nova.compute.manager] Evacuating instance 2019-04-02 00:07:32.321472 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Attempting claim on node fake-mini: memory 512 MB, disk 1 GB, vcpus 1 CPU 2019-04-02 00:07:32.321578 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Total memory: 800000 MB, used: 512.00 MB 2019-04-02 00:07:32.321732 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited 2019-04-02 00:07:32.321848 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Total disk: 600000 GB, used: 0.00 GB 2019-04-02 00:07:32.321965 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited 2019-04-02 00:07:32.322101 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Total vcpu: 1000 VCPU, used: 0.00 VCPU 2019-04-02 00:07:32.322223 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited 2019-04-02 00:07:32.322323 | ubuntu-bionic | 2019-04-02 00:07:29,914 INFO [nova.compute.claims] Claim successful on node fake-mini 2019-04-02 00:07:32.322471 | ubuntu-bionic | 2019-04-02 00:07:29,958 INFO [nova.compute.resource_tracker] Updating resource usage from migration 668cec00-b769-40a9-9dba-c6b5d09c7c36 2019-04-02 00:07:32.322625 | ubuntu-bionic | 2019-04-02 00:07:29,967 INFO [nova.compute.manager] disk not on shared storage, evacuating from image: '155d900f-4e14-4e4c-a73d-069cbf4541e6' 2019-04-02 00:07:32.322803 | ubuntu-bionic | 2019-04-02 00:07:30,038 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.322928 | ubuntu-bionic | 2019-04-02 00:07:30,048 INFO [nova.compute.manager] Detaching volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 2019-04-02 00:07:32.323153 | ubuntu-bionic | 2019-04-02 00:07:30,049 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb 2019-04-02 00:07:32.323279 | ubuntu-bionic | 2019-04-02 00:07:30,049 WARNING [nova.virt.block_device] Detaching volume from unknown instance 2019-04-02 00:07:32.323472 | ubuntu-bionic | 2019-04-02 00:07:30,049 WARNING [nova.virt.block_device] Host mismatch detected, but stashed volume connector not found. Instance host is host2, but volume connector host is fakehost. 2019-04-02 00:07:32.323637 | ubuntu-bionic | 2019-04-02 00:07:30,093 INFO [nova.virt.block_device] Booting with volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 at /dev/sdb 2019-04-02 00:07:32.323886 | ubuntu-bionic | 2019-04-02 00:07:30,412 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.107966 2019-04-02 00:07:32.324138 | ubuntu-bionic | 2019-04-02 00:07:30,436 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/os-services/8b2330ad-82ec-40d7-98c8-facd2a4c415b" status: 200 len: 245 microversion: 2.72 time: 0.019086 2019-04-02 00:07:32.324378 | ubuntu-bionic | 2019-04-02 00:07:30,510 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.070536 2019-04-02 00:07:32.324607 | ubuntu-bionic | 2019-04-02 00:07:30,587 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.074523 2019-04-02 00:07:32.324830 | ubuntu-bionic | 2019-04-02 00:07:30,680 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2212 microversion: 2.72 time: 0.089958 2019-04-02 00:07:32.325012 | ubuntu-bionic | 2019-04-02 00:07:30,691 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.325190 | ubuntu-bionic | 2019-04-02 00:07:30,725 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.325427 | ubuntu-bionic | 2019-04-02 00:07:30,729 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 18 microversion: 2.72 time: 0.046856 2019-04-02 00:07:32.325603 | ubuntu-bionic | 2019-04-02 00:07:30,733 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/ec22d969-75a1-4a35-b571-1e1f7088b600" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.325745 | ubuntu-bionic | 2019-04-02 00:07:30,764 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.325963 | ubuntu-bionic | 2019-04-02 00:07:30,812 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1303 microversion: 1.29 2019-04-02 00:07:32.326088 | ubuntu-bionic | 2019-04-02 00:07:30,838 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.326191 | ubuntu-bionic | 2019-04-02 00:07:30,838 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.326369 | ubuntu-bionic | 2019-04-02 00:07:30,846 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.326547 | ubuntu-bionic | 2019-04-02 00:07:30,867 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.326681 | ubuntu-bionic | 2019-04-02 00:07:31,148 INFO [nova.compute.manager] Took 0.08 seconds for pre_live_migration on destination host host2. 2019-04-02 00:07:32.326950 | ubuntu-bionic | 2019-04-02 00:07:31,290 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 540 microversion: 2.72 time: 0.056536 2019-04-02 00:07:32.327254 | ubuntu-bionic | 2019-04-02 00:07:31,343 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations/5/action" status: 202 len: 0 microversion: 2.72 time: 0.049056 2019-04-02 00:07:32.327378 | ubuntu-bionic | 2019-04-02 00:07:31,882 INFO [nova.compute.manager] _post_live_migration() is started.. 2019-04-02 00:07:32.327480 | ubuntu-bionic | 2019-04-02 00:07:31,942 INFO [nova.compute.manager] Post operation of migration started 2019-04-02 00:07:32.327600 | ubuntu-bionic | 2019-04-02 00:07:32,069 WARNING [nova.compute.resource_tracker] Instance not resizing, skipping migration. 2019-04-02 00:07:32.327795 | ubuntu-bionic | 2019-04-02 00:07:32,086 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/allocations" status: 200 len: 153 microversion: 1.0 2019-04-02 00:07:32.327927 | ubuntu-bionic | 2019-04-02 00:07:32,094 WARNING [nova.compute.manager] Compute node 'fake-mini' not found in update_available_resource. 2019-04-02 00:07:32.328050 | ubuntu-bionic | 2019-04-02 00:07:32,105 INFO [nova.compute.manager] Migrating instance to host2 finished successfully. 2019-04-02 00:07:32.328290 | ubuntu-bionic | 2019-04-02 00:07:32,131 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/ec22d969-75a1-4a35-b571-1e1f7088b600" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.328473 | ubuntu-bionic | 2019-04-02 00:07:32,154 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/ec22d969-75a1-4a35-b571-1e1f7088b600" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.328605 | ubuntu-bionic | 2019-04-02 00:07:32,155 INFO [nova.scheduler.client.report] Deleted allocation for migration ec22d969-75a1-4a35-b571-1e1f7088b600 2019-04-02 00:07:32.328708 | ubuntu-bionic | 2019-04-02 00:07:32,230 INFO [oslo_db.sqlalchemy.provision] DROP ALL OBJECTS, BACKEND sqlite:// 2019-04-02 00:07:32.328813 | ubuntu-bionic | 2019-04-02 00:07:32,268 INFO [oslo_db.sqlalchemy.provision] DISPOSE ENGINE Engine(sqlite://) I've seen this hit in two changes in logstash: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22File%20%5C%5C%5C%22nova%2Ftests%2Ffunctional%2Fnotification_sample_tests%2Ftest_instance.py%5C%5C%5C%22%5C%22%20AND%20message%3A%5C%22in%20_test_live_migration_force_complete%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d But as far as I can tell those changes should have no relation to what this test is doing (NotificationSampleTestBase does not inherit from ProviderUsageBaseTestCase). We likely need to dump the notifications when this fails to get a better idea of what's going on. ** Affects: nova Importance: Medium Status: Confirmed ** Tags: notifications 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/1823215 Title: TestInstanceNotificationSampleWithMultipleComputeOldAttachFlow._test_live_migration_force_complete intermittent fails with MismatchError: 6 != 7 Status in OpenStack Compute (nova): Confirmed Bug description: Seen here: http://logs.openstack.org/47/638047/9/check/nova-tox- functional/71f64ae/job-output.txt.gz#_2019-04-02_00_07_32_290065 2019-04-02 00:07:32.290065 | ubuntu-bionic | {2} nova.tests.functional.notification_sample_tests.test_instance.TestInstanceNotificationSampleWithMultipleComputeOldAttachFlow.test_multiple_compute_actions [14.302238s] ... FAILED 2019-04-02 00:07:32.290219 | ubuntu-bionic | 2019-04-02 00:07:32.290275 | ubuntu-bionic | Captured traceback: 2019-04-02 00:07:32.290318 | ubuntu-bionic | ~~~~~~~~~~~~~~~~~~~ 2019-04-02 00:07:32.290378 | ubuntu-bionic | Traceback (most recent call last): 2019-04-02 00:07:32.290525 | ubuntu-bionic | File "nova/tests/functional/notification_sample_tests/test_instance.py", line 68, in test_multiple_compute_actions 2019-04-02 00:07:32.290569 | ubuntu-bionic | action(server) 2019-04-02 00:07:32.290726 | ubuntu-bionic | File "nova/tests/functional/notification_sample_tests/test_instance.py", line 311, in _test_live_migration_force_complete 2019-04-02 00:07:32.290822 | ubuntu-bionic | self.assertEqual(6, len(fake_notifier.VERSIONED_NOTIFICATIONS)) 2019-04-02 00:07:32.291011 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 411, in assertEqual 2019-04-02 00:07:32.291148 | ubuntu-bionic | self.assertThat(observed, matcher, message) 2019-04-02 00:07:32.291351 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/testtools/testcase.py", line 498, in assertThat 2019-04-02 00:07:32.291402 | ubuntu-bionic | raise mismatch_error 2019-04-02 00:07:32.291475 | ubuntu-bionic | testtools.matchers._impl.MismatchError: 6 != 7 2019-04-02 00:07:32.291497 | ubuntu-bionic | 2019-04-02 00:07:32.291515 | ubuntu-bionic | 2019-04-02 00:07:32.291558 | ubuntu-bionic | Captured pythonlogging: 2019-04-02 00:07:32.291602 | ubuntu-bionic | ~~~~~~~~~~~~~~~~~~~~~~~ 2019-04-02 00:07:32.291737 | ubuntu-bionic | 2019-04-02 00:07:19,024 WARNING [placement.db_api] TransactionFactory already started, not reconfiguring. 2019-04-02 00:07:32.291908 | ubuntu-bionic | 2019-04-02 00:07:19,053 INFO [nova.service] Starting conductor node (version 19.1.0) 2019-04-02 00:07:32.292181 | ubuntu-bionic | 2019-04-02 00:07:19,073 INFO [nova.service] Starting scheduler node (version 19.1.0) 2019-04-02 00:07:32.292326 | ubuntu-bionic | 2019-04-02 00:07:19,089 INFO [nova.network.driver] Loading network driver 'nova.network.linux_net' 2019-04-02 00:07:32.292438 | ubuntu-bionic | 2019-04-02 00:07:19,090 INFO [nova.service] Starting network node (version 19.1.0) 2019-04-02 00:07:32.292606 | ubuntu-bionic | 2019-04-02 00:07:19,118 INFO [nova.virt.driver] Loading compute driver 'fake.FakeLiveMigrateDriver' 2019-04-02 00:07:32.292820 | ubuntu-bionic | 2019-04-02 00:07:19,118 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors). 2019-04-02 00:07:32.292945 | ubuntu-bionic | 2019-04-02 00:07:19,119 INFO [nova.service] Starting compute node (version 19.1.0) 2019-04-02 00:07:32.293174 | ubuntu-bionic | 2019-04-02 00:07:19,141 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. 2019-04-02 00:07:32.293304 | ubuntu-bionic | 2019-04-02 00:07:19,144 WARNING [nova.compute.resource_tracker] No compute node record for compute:fake-mini 2019-04-02 00:07:32.293484 | ubuntu-bionic | 2019-04-02 00:07:19,148 INFO [nova.compute.resource_tracker] Compute node record created for compute:fake-mini with uuid: 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 2019-04-02 00:07:32.293687 | ubuntu-bionic | 2019-04-02 00:07:19,187 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=109a2d73-cdf9-4d76-8e6e-74dc79ff7359" status: 200 len: 26 microversion: 1.14 2019-04-02 00:07:32.293848 | ubuntu-bionic | 2019-04-02 00:07:19,193 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 832 microversion: 1.20 2019-04-02 00:07:32.294112 | ubuntu-bionic | 2019-04-02 00:07:19,194 INFO [nova.scheduler.client.report] [req-5b6c791d-5709-4f36-8fbe-c3e02869e35d] Created resource provider record via placement API for resource provider with UUID 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 and name fake-mini. 2019-04-02 00:07:32.294321 | ubuntu-bionic | 2019-04-02 00:07:19,208 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/inventories" status: 200 len: 413 microversion: 1.26 2019-04-02 00:07:32.294693 | ubuntu-bionic | 2019-04-02 00:07:19,220 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_VOLUME_EXTEND,COMPUTE_DEVICE_TAGGING" status: 200 len: 226 microversion: 1.6 2019-04-02 00:07:32.294944 | ubuntu-bionic | 2019-04-02 00:07:19,234 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/traits" status: 200 len: 261 microversion: 1.6 2019-04-02 00:07:32.295159 | ubuntu-bionic | 2019-04-02 00:07:19,239 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000296 2019-04-02 00:07:32.295377 | ubuntu-bionic | 2019-04-02 00:07:19,364 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/flavors" status: 200 len: 611 microversion: 2.72 time: 0.122205 2019-04-02 00:07:32.297249 | ubuntu-bionic | 2019-04-02 00:07:19,367 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1" status: 204 len: 0 microversion: - time: 0.000239 2019-04-02 00:07:32.297541 | ubuntu-bionic | 2019-04-02 00:07:19,386 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.72 time: 0.017107 2019-04-02 00:07:32.297859 | ubuntu-bionic | 2019-04-02 00:07:19,413 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/os-keypairs" status: 201 len: 379 microversion: 2.72 time: 0.024532 2019-04-02 00:07:32.298070 | ubuntu-bionic | 2019-04-02 00:07:19,512 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers" status: 202 len: 32 microversion: 2.72 time: 0.096062 2019-04-02 00:07:32.298335 | ubuntu-bionic | 2019-04-02 00:07:19,574 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers?reservation_id=r-hnbz5gim" status: 200 len: 404 microversion: 2.72 time: 0.058885 2019-04-02 00:07:32.298570 | ubuntu-bionic | 2019-04-02 00:07:19,614 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 674 microversion: 1.29 2019-04-02 00:07:32.298808 | ubuntu-bionic | 2019-04-02 00:07:19,637 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 1872 microversion: 2.72 time: 0.059987 2019-04-02 00:07:32.298997 | ubuntu-bionic | 2019-04-02 00:07:19,652 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.299252 | ubuntu-bionic | 2019-04-02 00:07:19,673 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.299417 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] Attempting claim on node fake-mini: memory 512 MB, disk 1 GB, vcpus 1 CPU 2019-04-02 00:07:32.299532 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] Total memory: 800000 MB, used: 512.00 MB 2019-04-02 00:07:32.299656 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited 2019-04-02 00:07:32.299765 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] Total disk: 600000 GB, used: 0.00 GB 2019-04-02 00:07:32.299893 | ubuntu-bionic | 2019-04-02 00:07:19,882 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited 2019-04-02 00:07:32.300038 | ubuntu-bionic | 2019-04-02 00:07:19,883 INFO [nova.compute.claims] Total vcpu: 1000 VCPU, used: 0.00 VCPU 2019-04-02 00:07:32.300191 | ubuntu-bionic | 2019-04-02 00:07:19,883 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited 2019-04-02 00:07:32.300309 | ubuntu-bionic | 2019-04-02 00:07:19,883 INFO [nova.compute.claims] Claim successful on node fake-mini 2019-04-02 00:07:32.300504 | ubuntu-bionic | 2019-04-02 00:07:20,069 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.300635 | ubuntu-bionic | 2019-04-02 00:07:20,112 INFO [nova.compute.manager] Took 0.00 seconds to spawn the instance on the hypervisor. 2019-04-02 00:07:32.300751 | ubuntu-bionic | 2019-04-02 00:07:20,171 INFO [nova.compute.manager] Took 0.30 seconds to build instance. 2019-04-02 00:07:32.300911 | ubuntu-bionic | 2019-04-02 00:07:20,229 INFO [nova.scheduler.host_manager] Received an update from an unknown host 'compute'. Re-created its InstanceList. 2019-04-02 00:07:32.301157 | ubuntu-bionic | 2019-04-02 00:07:20,258 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2118 microversion: 2.72 time: 0.103617 2019-04-02 00:07:32.301410 | ubuntu-bionic | 2019-04-02 00:07:20,347 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/tags" status: 200 len: 18 microversion: 2.72 time: 0.082867 2019-04-02 00:07:32.301678 | ubuntu-bionic | 2019-04-02 00:07:20,426 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/os-volume_attachments" status: 200 len: 207 microversion: 2.72 time: 0.076133 2019-04-02 00:07:32.301824 | ubuntu-bionic | 2019-04-02 00:07:20,468 INFO [nova.compute.manager] Attaching volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 to /dev/sdb 2019-04-02 00:07:32.301945 | ubuntu-bionic | 2019-04-02 00:07:20,562 INFO [nova.virt.driver] Loading compute driver 'fake.FakeLiveMigrateDriver' 2019-04-02 00:07:32.302148 | ubuntu-bionic | 2019-04-02 00:07:20,564 WARNING [nova.compute.monitors] Excluding nova.compute.monitors.cpu monitor virt_driver. Not in the list of enabled monitors (CONF.compute_monitors). 2019-04-02 00:07:32.302287 | ubuntu-bionic | 2019-04-02 00:07:20,565 INFO [nova.service] Starting compute node (version 19.1.0) 2019-04-02 00:07:32.302553 | ubuntu-bionic | 2019-04-02 00:07:20,586 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. 2019-04-02 00:07:32.302686 | ubuntu-bionic | 2019-04-02 00:07:20,591 WARNING [nova.compute.resource_tracker] No compute node record for host2:host2 2019-04-02 00:07:32.302861 | ubuntu-bionic | 2019-04-02 00:07:20,594 INFO [nova.compute.resource_tracker] Compute node record created for host2:host2 with uuid: e30090d2-c1ab-4528-a338-62182708f6c6 2019-04-02 00:07:32.303114 | ubuntu-bionic | 2019-04-02 00:07:20,625 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers?in_tree=e30090d2-c1ab-4528-a338-62182708f6c6" status: 200 len: 26 microversion: 1.14 2019-04-02 00:07:32.303290 | ubuntu-bionic | 2019-04-02 00:07:20,631 INFO [placement.requestlog] 127.0.0.1 "POST /placement/resource_providers" status: 200 len: 828 microversion: 1.20 2019-04-02 00:07:32.303558 | ubuntu-bionic | 2019-04-02 00:07:20,632 INFO [nova.scheduler.client.report] [req-5b6c791d-5709-4f36-8fbe-c3e02869e35d] Created resource provider record via placement API for resource provider with UUID e30090d2-c1ab-4528-a338-62182708f6c6 and name host2. 2019-04-02 00:07:32.303767 | ubuntu-bionic | 2019-04-02 00:07:20,641 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/e30090d2-c1ab-4528-a338-62182708f6c6/inventories" status: 200 len: 413 microversion: 1.26 2019-04-02 00:07:32.304155 | ubuntu-bionic | 2019-04-02 00:07:20,647 INFO [placement.requestlog] 127.0.0.1 "GET /placement/traits?name=in:COMPUTE_VOLUME_MULTI_ATTACH,COMPUTE_TRUSTED_CERTS,COMPUTE_NET_ATTACH_INTERFACE,COMPUTE_NET_ATTACH_INTERFACE_WITH_TAG,COMPUTE_VOLUME_ATTACH_WITH_TAG,COMPUTE_VOLUME_EXTEND,COMPUTE_DEVICE_TAGGING" status: 200 len: 226 microversion: 1.6 2019-04-02 00:07:32.304376 | ubuntu-bionic | 2019-04-02 00:07:20,658 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/resource_providers/e30090d2-c1ab-4528-a338-62182708f6c6/traits" status: 200 len: 261 microversion: 1.6 2019-04-02 00:07:32.304620 | ubuntu-bionic | 2019-04-02 00:07:20,739 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.076845 2019-04-02 00:07:32.304811 | ubuntu-bionic | 2019-04-02 00:07:20,769 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.305007 | ubuntu-bionic | 2019-04-02 00:07:20,776 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.305201 | ubuntu-bionic | 2019-04-02 00:07:20,782 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b8bed8a2-cd41-4511-86cd-8563dbeb2072" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.305351 | ubuntu-bionic | 2019-04-02 00:07:20,815 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.305591 | ubuntu-bionic | 2019-04-02 00:07:20,880 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.305725 | ubuntu-bionic | 2019-04-02 00:07:20,908 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.305834 | ubuntu-bionic | 2019-04-02 00:07:20,908 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.306029 | ubuntu-bionic | 2019-04-02 00:07:20,917 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.306223 | ubuntu-bionic | 2019-04-02 00:07:20,937 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.306379 | ubuntu-bionic | 2019-04-02 00:07:21,162 ERROR [nova.compute.manager] Pre live migration failed at host2 2019-04-02 00:07:32.306447 | ubuntu-bionic | Traceback (most recent call last): 2019-04-02 00:07:32.306535 | ubuntu-bionic | File "nova/compute/manager.py", line 7236, in _do_live_migration 2019-04-02 00:07:32.306602 | ubuntu-bionic | block_migration, disk, dest, migrate_data) 2019-04-02 00:07:32.306767 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/mock/mock.py", line 1062, in __call__ 2019-04-02 00:07:32.306860 | ubuntu-bionic | return _mock_self._mock_call(*args, **kwargs) 2019-04-02 00:07:32.307071 | ubuntu-bionic | File "/home/zuul/src/git.openstack.org/openstack/nova/.tox/functional/local/lib/python2.7/site-packages/mock/mock.py", line 1118, in _mock_call 2019-04-02 00:07:32.307122 | ubuntu-bionic | raise effect 2019-04-02 00:07:32.307250 | ubuntu-bionic | DestinationDiskExists: The supplied disk path (path) already exists, it is expected not to exist. 2019-04-02 00:07:32.307440 | ubuntu-bionic | 2019-04-02 00:07:21,175 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b8bed8a2-cd41-4511-86cd-8563dbeb2072" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.307658 | ubuntu-bionic | 2019-04-02 00:07:21,176 INFO [nova.compute.manager] Swapping old allocation on 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 held by migration b8bed8a2-cd41-4511-86cd-8563dbeb2072 for instance 2019-04-02 00:07:32.307881 | ubuntu-bionic | 2019-04-02 00:07:21,184 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/b8bed8a2-cd41-4511-86cd-8563dbeb2072" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.308078 | ubuntu-bionic | 2019-04-02 00:07:21,191 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.308539 | ubuntu-bionic | 2019-04-02 00:07:21,192 WARNING [nova.scheduler.client.report] Overwriting current allocation {u'project_id': u'6f70656e737461636b20342065766572', u'consumer_generation': 1, u'user_id': u'fake', u'allocations': {u'e30090d2-c1ab-4528-a338-62182708f6c6': {u'generation': 3, u'resources': {u'VCPU': 1, u'DISK_GB': 1, u'MEMORY_MB': 512}}}} on consumer dc76de5a-d330-462a-9b6b-a15d59ac9199 2019-04-02 00:07:32.308733 | ubuntu-bionic | 2019-04-02 00:07:21,225 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.308911 | ubuntu-bionic | 2019-04-02 00:07:21,322 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb 2019-04-02 00:07:32.309032 | ubuntu-bionic | 2019-04-02 00:07:21,322 WARNING [nova.virt.block_device] Detaching volume from unknown instance 2019-04-02 00:07:32.309277 | ubuntu-bionic | 2019-04-02 00:07:21,654 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.124296 2019-04-02 00:07:32.309521 | ubuntu-bionic | 2019-04-02 00:07:21,738 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.080526 2019-04-02 00:07:32.309772 | ubuntu-bionic | 2019-04-02 00:07:21,823 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2212 microversion: 2.72 time: 0.082117 2019-04-02 00:07:32.309962 | ubuntu-bionic | 2019-04-02 00:07:21,868 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.310215 | ubuntu-bionic | 2019-04-02 00:07:21,875 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 18 microversion: 2.72 time: 0.049653 2019-04-02 00:07:32.310434 | ubuntu-bionic | 2019-04-02 00:07:21,879 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.310669 | ubuntu-bionic | 2019-04-02 00:07:21,885 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.310836 | ubuntu-bionic | 2019-04-02 00:07:21,911 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.311666 | ubuntu-bionic | 2019-04-02 00:07:21,968 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.311831 | ubuntu-bionic | 2019-04-02 00:07:21,993 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.311945 | ubuntu-bionic | 2019-04-02 00:07:21,993 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.312161 | ubuntu-bionic | 2019-04-02 00:07:22,002 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.312360 | ubuntu-bionic | 2019-04-02 00:07:22,020 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.312509 | ubuntu-bionic | 2019-04-02 00:07:22,274 INFO [nova.compute.manager] Took 0.10 seconds for pre_live_migration on destination host host2. 2019-04-02 00:07:32.312765 | ubuntu-bionic | 2019-04-02 00:07:22,424 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 540 microversion: 2.72 time: 0.046006 2019-04-02 00:07:32.313057 | ubuntu-bionic | 2019-04-02 00:07:22,468 INFO [nova.api.openstack.requestlog] 127.0.0.1 "DELETE /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations/2" status: 202 len: 0 microversion: 2.72 time: 0.041235 2019-04-02 00:07:32.313305 | ubuntu-bionic | 2019-04-02 00:07:22,582 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2212 microversion: 2.72 time: 0.070385 2019-04-02 00:07:32.313501 | ubuntu-bionic | 2019-04-02 00:07:22,609 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.313708 | ubuntu-bionic | 2019-04-02 00:07:22,611 INFO [nova.compute.manager] Swapping old allocation on 109a2d73-cdf9-4d76-8e6e-74dc79ff7359 held by migration cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc for instance 2019-04-02 00:07:32.313902 | ubuntu-bionic | 2019-04-02 00:07:22,624 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/cab1a8d4-7a10-40ef-b57e-3bd9ea54dbcc" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.314144 | ubuntu-bionic | 2019-04-02 00:07:22,641 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.314574 | ubuntu-bionic | 2019-04-02 00:07:22,642 WARNING [nova.scheduler.client.report] Overwriting current allocation {u'project_id': u'6f70656e737461636b20342065766572', u'consumer_generation': 1, u'user_id': u'fake', u'allocations': {u'e30090d2-c1ab-4528-a338-62182708f6c6': {u'generation': 4, u'resources': {u'VCPU': 1, u'DISK_GB': 1, u'MEMORY_MB': 512}}}} on consumer dc76de5a-d330-462a-9b6b-a15d59ac9199 2019-04-02 00:07:32.314728 | ubuntu-bionic | 2019-04-02 00:07:22,686 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.314900 | ubuntu-bionic | 2019-04-02 00:07:22,742 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb 2019-04-02 00:07:32.315023 | ubuntu-bionic | 2019-04-02 00:07:22,742 WARNING [nova.virt.block_device] Detaching volume from unknown instance 2019-04-02 00:07:32.315310 | ubuntu-bionic | 2019-04-02 00:07:23,197 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.109925 2019-04-02 00:07:32.315594 | ubuntu-bionic | 2019-04-02 00:07:23,295 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.081375 2019-04-02 00:07:32.315855 | ubuntu-bionic | 2019-04-02 00:07:23,391 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.092867 2019-04-02 00:07:32.316045 | ubuntu-bionic | 2019-04-02 00:07:23,421 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.316270 | ubuntu-bionic | 2019-04-02 00:07:23,430 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.316456 | ubuntu-bionic | 2019-04-02 00:07:23,437 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/1ef7333e-9209-46e5-8997-2372a7a2c1ca" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.316604 | ubuntu-bionic | 2019-04-02 00:07:23,472 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.316817 | ubuntu-bionic | 2019-04-02 00:07:23,536 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.316941 | ubuntu-bionic | 2019-04-02 00:07:23,568 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.317042 | ubuntu-bionic | 2019-04-02 00:07:23,568 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.317219 | ubuntu-bionic | 2019-04-02 00:07:23,577 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.317398 | ubuntu-bionic | 2019-04-02 00:07:23,600 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.317530 | ubuntu-bionic | 2019-04-02 00:07:23,894 INFO [nova.compute.manager] Took 0.11 seconds for pre_live_migration on destination host host2. 2019-04-02 00:07:32.317769 | ubuntu-bionic | 2019-04-02 00:07:23,984 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 540 microversion: 2.72 time: 0.048497 2019-04-02 00:07:32.317876 | ubuntu-bionic | 2019-04-02 00:07:28,907 INFO [nova.compute.manager] _post_live_migration() is started.. 2019-04-02 00:07:32.317985 | ubuntu-bionic | 2019-04-02 00:07:29,062 INFO [nova.compute.manager] Post operation of migration started 2019-04-02 00:07:32.318104 | ubuntu-bionic | 2019-04-02 00:07:29,203 WARNING [nova.compute.resource_tracker] Instance not resizing, skipping migration. 2019-04-02 00:07:32.318305 | ubuntu-bionic | 2019-04-02 00:07:29,221 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/allocations" status: 200 len: 152 microversion: 1.0 2019-04-02 00:07:32.318422 | ubuntu-bionic | 2019-04-02 00:07:29,243 INFO [nova.compute.manager] Migrating instance to host2 finished successfully. 2019-04-02 00:07:32.318600 | ubuntu-bionic | 2019-04-02 00:07:29,260 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/1ef7333e-9209-46e5-8997-2372a7a2c1ca" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.318782 | ubuntu-bionic | 2019-04-02 00:07:29,356 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/1ef7333e-9209-46e5-8997-2372a7a2c1ca" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.318924 | ubuntu-bionic | 2019-04-02 00:07:29,357 INFO [nova.scheduler.client.report] Deleted allocation for migration 1ef7333e-9209-46e5-8997-2372a7a2c1ca 2019-04-02 00:07:32.319202 | ubuntu-bionic | 2019-04-02 00:07:29,391 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2196 microversion: 2.72 time: 0.110748 2019-04-02 00:07:32.319474 | ubuntu-bionic | 2019-04-02 00:07:29,414 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/os-services?binary=nova-compute&host=host2&" status: 200 len: 248 microversion: 2.72 time: 0.019628 2019-04-02 00:07:32.319730 | ubuntu-bionic | 2019-04-02 00:07:29,442 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/os-services/8b2330ad-82ec-40d7-98c8-facd2a4c415b" status: 200 len: 246 microversion: 2.72 time: 0.025102 2019-04-02 00:07:32.319962 | ubuntu-bionic | 2019-04-02 00:07:29,572 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 200 len: 0 microversion: 2.72 time: 0.127196 2019-04-02 00:07:32.320210 | ubuntu-bionic | 2019-04-02 00:07:29,668 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2207 microversion: 2.72 time: 0.093253 2019-04-02 00:07:32.320431 | ubuntu-bionic | 2019-04-02 00:07:29,786 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1301 microversion: 1.29 2019-04-02 00:07:32.320654 | ubuntu-bionic | 2019-04-02 00:07:29,801 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2207 microversion: 2.72 time: 0.129291 2019-04-02 00:07:32.320790 | ubuntu-bionic | 2019-04-02 00:07:29,815 INFO [nova.scheduler.host_manager] Host filter only checking host compute and node fake-mini 2019-04-02 00:07:32.320891 | ubuntu-bionic | 2019-04-02 00:07:29,815 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.321074 | ubuntu-bionic | 2019-04-02 00:07:29,825 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 229 microversion: 1.28 2019-04-02 00:07:32.321249 | ubuntu-bionic | 2019-04-02 00:07:29,854 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.321336 | ubuntu-bionic | 2019-04-02 00:07:29,903 INFO [nova.compute.manager] Evacuating instance 2019-04-02 00:07:32.321472 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Attempting claim on node fake-mini: memory 512 MB, disk 1 GB, vcpus 1 CPU 2019-04-02 00:07:32.321578 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Total memory: 800000 MB, used: 512.00 MB 2019-04-02 00:07:32.321732 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] memory limit not specified, defaulting to unlimited 2019-04-02 00:07:32.321848 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Total disk: 600000 GB, used: 0.00 GB 2019-04-02 00:07:32.321965 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] disk limit not specified, defaulting to unlimited 2019-04-02 00:07:32.322101 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] Total vcpu: 1000 VCPU, used: 0.00 VCPU 2019-04-02 00:07:32.322223 | ubuntu-bionic | 2019-04-02 00:07:29,913 INFO [nova.compute.claims] vcpu limit not specified, defaulting to unlimited 2019-04-02 00:07:32.322323 | ubuntu-bionic | 2019-04-02 00:07:29,914 INFO [nova.compute.claims] Claim successful on node fake-mini 2019-04-02 00:07:32.322471 | ubuntu-bionic | 2019-04-02 00:07:29,958 INFO [nova.compute.resource_tracker] Updating resource usage from migration 668cec00-b769-40a9-9dba-c6b5d09c7c36 2019-04-02 00:07:32.322625 | ubuntu-bionic | 2019-04-02 00:07:29,967 INFO [nova.compute.manager] disk not on shared storage, evacuating from image: '155d900f-4e14-4e4c-a73d-069cbf4541e6' 2019-04-02 00:07:32.322803 | ubuntu-bionic | 2019-04-02 00:07:30,038 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.322928 | ubuntu-bionic | 2019-04-02 00:07:30,048 INFO [nova.compute.manager] Detaching volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 2019-04-02 00:07:32.323153 | ubuntu-bionic | 2019-04-02 00:07:30,049 INFO [nova.virt.block_device] Attempting to driver detach volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 from mountpoint /dev/sdb 2019-04-02 00:07:32.323279 | ubuntu-bionic | 2019-04-02 00:07:30,049 WARNING [nova.virt.block_device] Detaching volume from unknown instance 2019-04-02 00:07:32.323472 | ubuntu-bionic | 2019-04-02 00:07:30,049 WARNING [nova.virt.block_device] Host mismatch detected, but stashed volume connector not found. Instance host is host2, but volume connector host is fakehost. 2019-04-02 00:07:32.323637 | ubuntu-bionic | 2019-04-02 00:07:30,093 INFO [nova.virt.block_device] Booting with volume a07f71dc-8151-4e7d-a0cc-cd24a3f11113 at /dev/sdb 2019-04-02 00:07:32.323886 | ubuntu-bionic | 2019-04-02 00:07:30,412 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.107966 2019-04-02 00:07:32.324138 | ubuntu-bionic | 2019-04-02 00:07:30,436 INFO [nova.api.openstack.requestlog] 127.0.0.1 "PUT /v2.1/6f70656e737461636b20342065766572/os-services/8b2330ad-82ec-40d7-98c8-facd2a4c415b" status: 200 len: 245 microversion: 2.72 time: 0.019086 2019-04-02 00:07:32.324378 | ubuntu-bionic | 2019-04-02 00:07:30,510 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2202 microversion: 2.72 time: 0.070536 2019-04-02 00:07:32.324607 | ubuntu-bionic | 2019-04-02 00:07:30,587 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/action" status: 202 len: 0 microversion: 2.72 time: 0.074523 2019-04-02 00:07:32.324830 | ubuntu-bionic | 2019-04-02 00:07:30,680 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 2212 microversion: 2.72 time: 0.089958 2019-04-02 00:07:32.325012 | ubuntu-bionic | 2019-04-02 00:07:30,691 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.325190 | ubuntu-bionic | 2019-04-02 00:07:30,725 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.325427 | ubuntu-bionic | 2019-04-02 00:07:30,729 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 18 microversion: 2.72 time: 0.046856 2019-04-02 00:07:32.325603 | ubuntu-bionic | 2019-04-02 00:07:30,733 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/ec22d969-75a1-4a35-b571-1e1f7088b600" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.325745 | ubuntu-bionic | 2019-04-02 00:07:30,764 INFO [placement.requestlog] 127.0.0.1 "POST /placement/allocations" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.325963 | ubuntu-bionic | 2019-04-02 00:07:30,812 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocation_candidates?limit=1000&resources=DISK_GB%3A1%2CMEMORY_MB%3A512%2CVCPU%3A1" status: 200 len: 1303 microversion: 1.29 2019-04-02 00:07:32.326088 | ubuntu-bionic | 2019-04-02 00:07:30,838 INFO [nova.scheduler.host_manager] Host filter only checking host host2 and node host2 2019-04-02 00:07:32.326191 | ubuntu-bionic | 2019-04-02 00:07:30,838 INFO [nova.scheduler.host_manager] Host filter ignoring hosts: 2019-04-02 00:07:32.326369 | ubuntu-bionic | 2019-04-02 00:07:30,846 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 200 len: 19 microversion: 1.28 2019-04-02 00:07:32.326547 | ubuntu-bionic | 2019-04-02 00:07:30,867 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/dc76de5a-d330-462a-9b6b-a15d59ac9199" status: 204 len: 0 microversion: 1.29 2019-04-02 00:07:32.326681 | ubuntu-bionic | 2019-04-02 00:07:31,148 INFO [nova.compute.manager] Took 0.08 seconds for pre_live_migration on destination host host2. 2019-04-02 00:07:32.326950 | ubuntu-bionic | 2019-04-02 00:07:31,290 INFO [nova.api.openstack.requestlog] 127.0.0.1 "GET /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations" status: 200 len: 540 microversion: 2.72 time: 0.056536 2019-04-02 00:07:32.327254 | ubuntu-bionic | 2019-04-02 00:07:31,343 INFO [nova.api.openstack.requestlog] 127.0.0.1 "POST /v2.1/6f70656e737461636b20342065766572/servers/dc76de5a-d330-462a-9b6b-a15d59ac9199/migrations/5/action" status: 202 len: 0 microversion: 2.72 time: 0.049056 2019-04-02 00:07:32.327378 | ubuntu-bionic | 2019-04-02 00:07:31,882 INFO [nova.compute.manager] _post_live_migration() is started.. 2019-04-02 00:07:32.327480 | ubuntu-bionic | 2019-04-02 00:07:31,942 INFO [nova.compute.manager] Post operation of migration started 2019-04-02 00:07:32.327600 | ubuntu-bionic | 2019-04-02 00:07:32,069 WARNING [nova.compute.resource_tracker] Instance not resizing, skipping migration. 2019-04-02 00:07:32.327795 | ubuntu-bionic | 2019-04-02 00:07:32,086 INFO [placement.requestlog] 127.0.0.1 "GET /placement/resource_providers/109a2d73-cdf9-4d76-8e6e-74dc79ff7359/allocations" status: 200 len: 153 microversion: 1.0 2019-04-02 00:07:32.327927 | ubuntu-bionic | 2019-04-02 00:07:32,094 WARNING [nova.compute.manager] Compute node 'fake-mini' not found in update_available_resource. 2019-04-02 00:07:32.328050 | ubuntu-bionic | 2019-04-02 00:07:32,105 INFO [nova.compute.manager] Migrating instance to host2 finished successfully. 2019-04-02 00:07:32.328290 | ubuntu-bionic | 2019-04-02 00:07:32,131 INFO [placement.requestlog] 127.0.0.1 "GET /placement/allocations/ec22d969-75a1-4a35-b571-1e1f7088b600" status: 200 len: 347 microversion: 1.28 2019-04-02 00:07:32.328473 | ubuntu-bionic | 2019-04-02 00:07:32,154 INFO [placement.requestlog] 127.0.0.1 "PUT /placement/allocations/ec22d969-75a1-4a35-b571-1e1f7088b600" status: 204 len: 0 microversion: 1.28 2019-04-02 00:07:32.328605 | ubuntu-bionic | 2019-04-02 00:07:32,155 INFO [nova.scheduler.client.report] Deleted allocation for migration ec22d969-75a1-4a35-b571-1e1f7088b600 2019-04-02 00:07:32.328708 | ubuntu-bionic | 2019-04-02 00:07:32,230 INFO [oslo_db.sqlalchemy.provision] DROP ALL OBJECTS, BACKEND sqlite:// 2019-04-02 00:07:32.328813 | ubuntu-bionic | 2019-04-02 00:07:32,268 INFO [oslo_db.sqlalchemy.provision] DISPOSE ENGINE Engine(sqlite://) I've seen this hit in two changes in logstash: http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22File%20%5C%5C%5C%22nova%2Ftests%2Ffunctional%2Fnotification_sample_tests%2Ftest_instance.py%5C%5C%5C%22%5C%22%20AND%20message%3A%5C%22in%20_test_live_migration_force_complete%5C%22%20AND%20tags%3A%5C%22console%5C%22&from=7d But as far as I can tell those changes should have no relation to what this test is doing (NotificationSampleTestBase does not inherit from ProviderUsageBaseTestCase). We likely need to dump the notifications when this fails to get a better idea of what's going on. To manage notifications about this bug go to: https://bugs.launchpad.net/nova/+bug/1823215/+subscriptions -- Mailing list: https://launchpad.net/~yahoo-eng-team Post to : [email protected] Unsubscribe : https://launchpad.net/~yahoo-eng-team More help : https://help.launchpad.net/ListHelp
