yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1612353] [NEW] [master] instance launch failing on ESXi and KVM

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Prashant Shetty <prashantshetty@xxxxxxxxxx>
Date: Thu, 11 Aug 2016 17:13:23 -0000
Reply-to: Bug 1612353 <1612353@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

setup:

1 controller
2 network nodes(q-dhcp)
1 ESXi nova compute
3 KVM ubuntu compute

Instance cirros launch is failing on both ESXi and KVM.

vmware@cntr1:~$ nova service-list 
+----+------------------+-----------+----------+---------+-------+----------------------------+-----------------+
| Id | Binary           | Host      | Zone     | Status  | State | Updated_at                 | Disabled Reason |
+----+------------------+-----------+----------+---------+-------+----------------------------+-----------------+
| 5  | nova-conductor   | cntr1     | internal | enabled | up    | 2016-08-11T16:36:49.000000 | -               |
| 7  | nova-compute     | esx-comp1 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
| 8  | nova-compute     | kvm-comp3 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
| 9  | nova-compute     | kvm-comp2 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
| 10 | nova-compute     | kvm-comp1 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
| 11 | nova-scheduler   | cntr1     | internal | enabled | up    | 2016-08-11T16:36:46.000000 | -               |
| 12 | nova-consoleauth | cntr1     | internal | enabled | up    | 2016-08-11T16:36:46.000000 | -               |
+----+------------------+-----------+----------+---------+-------+----------------------------+-----------------+
vmware@cntr1:~$ 
 
n-cpu.log:2016-08-11 21:56:06.902 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "d7316f88-1cce-471c-90ac-3e8d9f405cbd" acquired by "nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
n-cpu.log:2016-08-11 21:56:06.930 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Starting instance... _do_build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1749
n-cpu.log:2016-08-11 21:56:07.035 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Attempting claim: memory 512 MB, disk 1 GB, vcpus 1 CPU
n-cpu.log:2016-08-11 21:56:07.035 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Total memory: 128918 MB, used: 512.00 MB
n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] memory limit: 193377.00 MB, free: 192865.00 MB
n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Total disk: 226 GB, used: 0.00 GB
n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] disk limit: 226.00 GB, free: 226.00 GB
n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Total vcpu: 16 VCPU, used: 0.00 VCPU
n-cpu.log:2016-08-11 21:56:07.037 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] vcpu limit not specified, defaulting to unlimited
n-cpu.log:2016-08-11 21:56:07.037 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Claim successful
n-cpu.log:2016-08-11 21:56:07.278 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start building networks asynchronously for instance. _build_resources /opt/stack/nova/nova/compute/manager.py:2016
n-cpu.log:2016-08-11 21:56:07.400 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Allocating IP information in the background. _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1383
n-cpu.log:2016-08-11 21:56:07.401 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Acquired semaphore "refresh_cache-d7316f88-1cce-471c-90ac-3e8d9f405cbd" lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
n-cpu.log:2016-08-11 21:56:07.417 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start building block device mappings for instance. _build_resources /opt/stack/nova/nova/compute/manager.py:2042
n-cpu.log:2016-08-11 21:56:07.584 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start spawning the instance on the hypervisor. _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1914
n-cpu.log:2016-08-11 21:56:07.585 31615 INFO nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Creating image
n-cpu.log:2016-08-11 21:56:07.722 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): cp -r /opt/stack/data/nova/instances/_base/fece570a52d852019d6ebfcea7d90221ea36594f /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:07.745 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "cp -r /opt/stack/data/nova/instances/_base/fece570a52d852019d6ebfcea7d90221ea36594f /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel" returned: 0 in 0.023s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:07.748 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:07.812 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel" returned: 0 in 0.065s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:07.814 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
n-cpu.log:2016-08-11 21:56:07.815 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
n-cpu.log:2016-08-11 21:56:07.924 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): cp -r /opt/stack/data/nova/instances/_base/c9b553c7c3ff5f4d67325a93e0b1772585672a93 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:07.945 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "cp -r /opt/stack/data/nova/instances/_base/c9b553c7c3ff5f4d67325a93e0b1772585672a93 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk" returned: 0 in 0.020s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:07.947 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:08.006 31615 DEBUG nova.compute.manager [req-484901e8-4f0a-431a-b30b-62d350cfb9d9 - -] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Skipping network cache update for instance because it is Building. _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5703
n-cpu.log:2016-08-11 21:56:08.010 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk" returned: 0 in 0.063s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:08.011 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
n-cpu.log:2016-08-11 21:56:08.011 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
n-cpu.log:2016-08-11 21:56:08.012 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
n-cpu.log:2016-08-11 21:56:08.013 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
n-cpu.log:2016-08-11 21:56:08.251 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/cd2dbe3befe946be3c9cbf83372e23f03915d318 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:08.305 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/cd2dbe3befe946be3c9cbf83372e23f03915d318 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk" returned: 0 in 0.055s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:08.306 31615 DEBUG nova.virt.disk.api [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Checking if we can resize image /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk. size=1073741824 can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214
n-cpu.log:2016-08-11 21:56:08.307 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:08.370 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk" returned: 0 in 0.063s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:08.371 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): qemu-img resize /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk 1073741824 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:08.411 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "qemu-img resize /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk 1073741824" returned: 0 in 0.040s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:08.477 31615 DEBUG nova.virt.disk.api [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Checking if we can resize image /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk. size=1073741824 can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214
n-cpu.log:2016-08-11 21:56:08.478 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:56:08.547 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk" returned: 0 in 0.069s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:56:08.549 31615 DEBUG nova.virt.disk.api [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Cannot resize image /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk to a smaller size. can_resize_image /opt/stack/nova/nova/virt/disk/api.py:220
n-cpu.log:2016-08-11 21:56:08.550 31615 DEBUG nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Ensure instance console log exists: /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/console.log _ensure_console_log_for_instance /opt/stack/nova/nova/virt/libvirt/driver.py:2913
n-cpu.log:2016-08-11 21:57:07.404 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Releasing semaphore "refresh_cache-d7316f88-1cce-471c-90ac-3e8d9f405cbd" lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Instance failed to spawn
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Traceback (most recent call last):
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 2075, in _build_resources
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     yield resources
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1919, in _build_and_run_instance
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     block_device_info=block_device_info)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2658, in spawn
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     write_to_disk=True)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4679, in _get_guest_xml
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     network_info_str = str(network_info)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/model.py", line 524, in __str__
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return self._sync_wrapper(fn, *args, **kwargs)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/model.py", line 507, in _sync_wrapper
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self.wait()
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/model.py", line 539, in wait
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self[:] = self._gt.wait()
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 175, in wait
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return self._exit_event.wait()
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return hubs.get_hub().switch()
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return self.greenlet.switch()
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 214, in main
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     result = function(*args, **kwargs)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/utils.py", line 1052, in context_wrapper
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return func(*args, **kwargs)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1413, in _allocate_network_async
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     six.reraise(*exc_info)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1396, in _allocate_network_async
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     bind_host_id=bind_host_id)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/base_api.py", line 77, in wrapper
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     res = f(self, context, *args, **kwargs)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/api.py", line 265, in allocate_for_instance
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     nw_info = self.network_rpcapi.allocate_for_instance(context, **args)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/rpcapi.py", line 157, in allocate_for_instance
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     macs=jsonutils.to_primitive(macs))
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=self.retry)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 96, in _send
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     timeout=timeout, retry=retry)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=retry)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     result = self._waiter.wait(msg_id, timeout)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     message = self.waiters.get(msg_id, timeout=timeout)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     'to message ID %s' % msg_id)
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] MessagingTimeout: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc
n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] 
n-cpu.log:2016-08-11 21:57:07.410 31615 INFO nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Terminating instance
n-cpu.log:2016-08-11 21:57:07.412 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start destroying the instance on the hypervisor. _shutdown_instance /opt/stack/nova/nova/compute/manager.py:2188
n-cpu.log:2016-08-11 21:57:07.419 31615 INFO nova.virt.libvirt.driver [-] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] During wait destroy, instance disappeared.
n-cpu.log:2016-08-11 21:57:07.420 31615 INFO nova.virt.libvirt.firewall [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Attempted to unfilter instance which is not filtered
n-cpu.log:2016-08-11 21:57:07.420 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): mv /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
n-cpu.log:2016-08-11 21:57:07.441 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "mv /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del" returned: 0 in 0.021s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
n-cpu.log:2016-08-11 21:57:07.442 31615 INFO nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deleting instance files /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del
n-cpu.log:2016-08-11 21:57:07.444 31615 INFO nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deletion of /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del complete
n-cpu.log:2016-08-11 21:57:07.535 31615 INFO nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Took 0.12 seconds to destroy the instance on the hypervisor.
n-cpu.log:2016-08-11 21:57:07.535 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deallocating network for instance _deallocate_network /opt/stack/nova/nova/compute/manager.py:1658
n-cpu.log:2016-08-11 21:57:09.998 31615 DEBUG nova.compute.manager [req-484901e8-4f0a-431a-b30b-62d350cfb9d9 - -] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Skipping network cache update for instance because it is Building. _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5703
n-cpu.log:2016-08-11 21:58:07.540 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Failed to deallocate network for instance. Error: Timed out waiting for a reply to message ID c42a2af13d264fc29665d0c056509cd0
n-cpu.log:2016-08-11 21:58:07.772 31615 DEBUG nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Aborting claim: [Claim: 512 MB memory, 1 GB disk] abort /opt/stack/nova/nova/compute/claims.py:123
n-cpu.log:2016-08-11 21:58:07.943 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1936
n-cpu.log:2016-08-11 21:58:07.944 31615 DEBUG nova.compute.utils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc notify_about_instance_usage /opt/stack/nova/nova/compute/utils.py:313
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Traceback (most recent call last):
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1778, in _do_build_and_run_instance
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     filter_properties)
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1938, in _build_and_run_instance
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     'create.error', fault=e)
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self.force_reraise()
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     six.reraise(self.type_, self.value, self.tb)
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1922, in _build_and_run_instance
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     instance=instance)
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/lib/python2.7/contextlib.py", line 35, in __exit__
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self.gen.throw(type, value, traceback)
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 2101, in _build_resources
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     reason=six.text_type(exc))
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] BuildAbortException: Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc
n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] 
n-cpu.log:2016-08-11 21:58:07.946 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deallocating network for instance _deallocate_network /opt/stack/nova/nova/compute/manager.py:1658
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Failed to deallocate networks
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Traceback (most recent call last):
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 2106, in _cleanup_allocated_networks
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self._deallocate_network(context, instance, requested_networks)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1661, in _deallocate_network
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     context, instance, requested_networks=requested_networks)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/api.py", line 297, in deallocate_for_instance
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     requested_networks=requested_networks)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/rpcapi.py", line 177, in deallocate_for_instance
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return cctxt.call(ctxt, 'deallocate_for_instance', **kwargs)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=self.retry)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 96, in _send
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     timeout=timeout, retry=retry)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=retry)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     result = self._waiter.wait(msg_id, timeout)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     message = self.waiters.get(msg_id, timeout=timeout)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     'to message ID %s' % msg_id)
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] MessagingTimeout: Timed out waiting for a reply to message ID eaadafca0f6a44c99b9341a9aa4fb95c
n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] 
n-cpu.log:2016-08-11 21:59:07.952 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] terminating bdm BlockDeviceMapping(boot_index=0,connection_info=None,created_at=2016-08-11T16:26:02Z,delete_on_termination=True,deleted=False,deleted_at=None,destination_type='local',device_name='/dev/vda',device_type='disk',disk_bus=None,guest_format=None,id=305,image_id='fbfbb67f-0201-40f6-841c-41635cda7bff',instance=<?>,instance_uuid=d7316f88-1cce-471c-90ac-3e8d9f405cbd,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=2016-08-11T16:26:03Z,volume_id=None,volume_size=None) _cleanup_volumes /opt/stack/nova/nova/compute/manager.py:2256
n-cpu.log:2016-08-11 21:59:08.110 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "d7316f88-1cce-471c-90ac-3e8d9f405cbd" released by "nova.compute.manager._locked_do_build_and_run_instance" :: held 181.208s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282


nova.conf:

[DEFAULT]
vif_plugging_timeout = 300
vif_plugging_is_fatal = True
firewall_driver = nova.virt.firewall.NoopFirewallDriver
use_neutron = True
dhcpbridge_flagfile = /etc/nova/nova-dhcpbridge.conf
graceful_shutdown_timeout = 5
metadata_workers = 3
osapi_compute_workers = 3
transport_url = rabbit://stackrabbit:vmware@192.168.2.141:5672/
logging_user_identity_format = %(user_name)s %(project_name)s
force_config_drive = True
send_arp_for_ha = True
multi_host = True
instances_path = /opt/stack/data/nova/instances
state_path = /opt/stack/data/nova
enabled_apis = osapi_compute,metadata
s3_listen = 0.0.0.0
metadata_listen = 0.0.0.0
osapi_compute_listen = 0.0.0.0
instance_name_template = instance-%08x
my_ip = 192.168.2.141
s3_port = 3333
s3_host = 192.168.2.141
default_floating_pool = public
force_dhcp_release = True
scheduler_default_filters = RetryFilter,AvailabilityZoneFilter,RamFilter,DiskFilter,ComputeFilter,ComputeCapabilitiesFilter,ImagePropertiesFilter,ServerGroupAntiAffinityFilter,ServerGroupAffinityFilter,SameHostFilter,DifferentHostFilter
scheduler_driver = filter_scheduler
rootwrap_config = /etc/nova/rootwrap.conf
allow_resize_to_same_host = True
debug = True

[wsgi]
api_paste_config = /etc/nova/api-paste.ini

[database]
connection = mysql+pymysql://root:vmware@127.0.0.1/nova?charset=utf8

[api_database]
connection = mysql+pymysql://root:vmware@127.0.0.1/nova_api?charset=utf8

[keystone_authtoken]
memcached_servers = 192.168.2.141:11211
signing_dir = /var/cache/nova
cafile = /opt/stack/data/ca-bundle.pem
auth_uri = http://192.168.2.141/identity
project_domain_name = Default
project_name = service
user_domain_name = Default
password = vmware
username = nova
auth_url = http://192.168.2.141/identity_v2_admin
auth_type = password

[oslo_concurrency]
lock_path = /opt/stack/data/nova

[vnc]
xvpvncproxy_host = 0.0.0.0
novncproxy_host = 0.0.0.0
vncserver_proxyclient_address = 127.0.0.1
vncserver_listen = 127.0.0.1
enabled = true

[spice]
enabled = false

[glance]
api_servers = http://192.168.2.141:9292

[conductor]
workers = 3

[cinder]
os_region_name = RegionOne

[neutron]
service_metadata_proxy = True
url = http://192.168.2.141:9696
region_name = RegionOne
auth_strategy = keystone
project_domain_name = Default
project_name = service
user_domain_name = Default
password = vmware
username = neutron
auth_url = http://192.168.2.141/identity_v2_admin/v3
auth_type = password

[key_manager]
fixed_key = 2483b40c5c14c188ecc38aaee7167423a11144d405d551b575091aca02ba6857


localrc compute:

GIT_BASE=https://git.openstack.org/
enable_plugin vmware-nsx https://git.openstack.org/openstack/vmware-nsx master
Q_PLUGIN=vmware_nsx_v3
ENABLED_SERVICES=n-cpu
SERVICE_HOST=192.168.2.141
MYSQL_HOST=$SERVICE_HOST
RABBIT_HOST=$SERVICE_HOST
Q_HOST=$SERVICE_HOST
DATABASE_PASSWORD=vmware
RABBIT_PASSWORD=vmware
SERVICE_TOKEN=vmware
SERVICE_PASSWORD=vmware
ADMIN_PASSWORD=vmware
RECLONE=yes
OVS_BRIDGE=nsx-managed
IPV6_ENABLED=False
IP_VERSION=4
HOST_IP=192.168.2.145
MULTI_HOST=1
NOVA_VNC_ENABLED=True
NOVNCPROXY_URL="http://$SERVICE_HOST:6080/vnc_auto.html";
VNCSERVER_LISTEN=$HOST_IP
VNCSERVER_PROXYCLIENT_ADDRESS=$VNCSERVER_LISTEN
NSX_MANAGER=192.168.2.187
NSX_USER=admin
NSX_PASSWORD=Vmware123!
disable_service zookeeper
#DEBUG=False
#DEFAULT_VLAN_TZ_UUID=changeme   # Optional, for VLAN provider networks

** Affects: nova
     Importance: Undecided
         Status: New

-- 
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/1612353

Title:
  [master] instance launch failing on ESXi and KVM

Status in OpenStack Compute (nova):
  New

Bug description:
  setup:

  1 controller
  2 network nodes(q-dhcp)
  1 ESXi nova compute
  3 KVM ubuntu compute

  Instance cirros launch is failing on both ESXi and KVM.

  vmware@cntr1:~$ nova service-list 
  +----+------------------+-----------+----------+---------+-------+----------------------------+-----------------+
  | Id | Binary           | Host      | Zone     | Status  | State | Updated_at                 | Disabled Reason |
  +----+------------------+-----------+----------+---------+-------+----------------------------+-----------------+
  | 5  | nova-conductor   | cntr1     | internal | enabled | up    | 2016-08-11T16:36:49.000000 | -               |
  | 7  | nova-compute     | esx-comp1 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
  | 8  | nova-compute     | kvm-comp3 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
  | 9  | nova-compute     | kvm-comp2 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
  | 10 | nova-compute     | kvm-comp1 | nova     | enabled | up    | 2016-08-11T16:36:41.000000 | -               |
  | 11 | nova-scheduler   | cntr1     | internal | enabled | up    | 2016-08-11T16:36:46.000000 | -               |
  | 12 | nova-consoleauth | cntr1     | internal | enabled | up    | 2016-08-11T16:36:46.000000 | -               |
  +----+------------------+-----------+----------+---------+-------+----------------------------+-----------------+
  vmware@cntr1:~$ 
   
  n-cpu.log:2016-08-11 21:56:06.902 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "d7316f88-1cce-471c-90ac-3e8d9f405cbd" acquired by "nova.compute.manager._locked_do_build_and_run_instance" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
  n-cpu.log:2016-08-11 21:56:06.930 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Starting instance... _do_build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1749
  n-cpu.log:2016-08-11 21:56:07.035 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Attempting claim: memory 512 MB, disk 1 GB, vcpus 1 CPU
  n-cpu.log:2016-08-11 21:56:07.035 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Total memory: 128918 MB, used: 512.00 MB
  n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] memory limit: 193377.00 MB, free: 192865.00 MB
  n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Total disk: 226 GB, used: 0.00 GB
  n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] disk limit: 226.00 GB, free: 226.00 GB
  n-cpu.log:2016-08-11 21:56:07.036 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Total vcpu: 16 VCPU, used: 0.00 VCPU
  n-cpu.log:2016-08-11 21:56:07.037 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] vcpu limit not specified, defaulting to unlimited
  n-cpu.log:2016-08-11 21:56:07.037 31615 INFO nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Claim successful
  n-cpu.log:2016-08-11 21:56:07.278 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start building networks asynchronously for instance. _build_resources /opt/stack/nova/nova/compute/manager.py:2016
  n-cpu.log:2016-08-11 21:56:07.400 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Allocating IP information in the background. _allocate_network_async /opt/stack/nova/nova/compute/manager.py:1383
  n-cpu.log:2016-08-11 21:56:07.401 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Acquired semaphore "refresh_cache-d7316f88-1cce-471c-90ac-3e8d9f405cbd" lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
  n-cpu.log:2016-08-11 21:56:07.417 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start building block device mappings for instance. _build_resources /opt/stack/nova/nova/compute/manager.py:2042
  n-cpu.log:2016-08-11 21:56:07.584 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start spawning the instance on the hypervisor. _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1914
  n-cpu.log:2016-08-11 21:56:07.585 31615 INFO nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Creating image
  n-cpu.log:2016-08-11 21:56:07.722 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): cp -r /opt/stack/data/nova/instances/_base/fece570a52d852019d6ebfcea7d90221ea36594f /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:07.745 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "cp -r /opt/stack/data/nova/instances/_base/fece570a52d852019d6ebfcea7d90221ea36594f /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel" returned: 0 in 0.023s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:07.748 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:07.812 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/kernel" returned: 0 in 0.065s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:07.814 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
  n-cpu.log:2016-08-11 21:56:07.815 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
  n-cpu.log:2016-08-11 21:56:07.924 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): cp -r /opt/stack/data/nova/instances/_base/c9b553c7c3ff5f4d67325a93e0b1772585672a93 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:07.945 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "cp -r /opt/stack/data/nova/instances/_base/c9b553c7c3ff5f4d67325a93e0b1772585672a93 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk" returned: 0 in 0.020s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:07.947 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:08.006 31615 DEBUG nova.compute.manager [req-484901e8-4f0a-431a-b30b-62d350cfb9d9 - -] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Skipping network cache update for instance because it is Building. _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5703
  n-cpu.log:2016-08-11 21:56:08.010 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/ramdisk" returned: 0 in 0.063s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:08.011 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
  n-cpu.log:2016-08-11 21:56:08.011 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
  n-cpu.log:2016-08-11 21:56:08.012 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" acquired by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: waited 0.000s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
  n-cpu.log:2016-08-11 21:56:08.013 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "/opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk.info" released by "nova.virt.libvirt.imagebackend.write_to_disk_info_file" :: held 0.001s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
  n-cpu.log:2016-08-11 21:56:08.251 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/cd2dbe3befe946be3c9cbf83372e23f03915d318 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:08.305 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/cd2dbe3befe946be3c9cbf83372e23f03915d318 /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk" returned: 0 in 0.055s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:08.306 31615 DEBUG nova.virt.disk.api [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Checking if we can resize image /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk. size=1073741824 can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214
  n-cpu.log:2016-08-11 21:56:08.307 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:08.370 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk" returned: 0 in 0.063s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:08.371 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): qemu-img resize /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk 1073741824 execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:08.411 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "qemu-img resize /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk 1073741824" returned: 0 in 0.040s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:08.477 31615 DEBUG nova.virt.disk.api [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Checking if we can resize image /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk. size=1073741824 can_resize_image /opt/stack/nova/nova/virt/disk/api.py:214
  n-cpu.log:2016-08-11 21:56:08.478 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): /usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:56:08.547 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "/usr/bin/python -m oslo_concurrency.prlimit --as=1073741824 --cpu=2 -- env LC_ALL=C LANG=C qemu-img info /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk" returned: 0 in 0.069s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:56:08.549 31615 DEBUG nova.virt.disk.api [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Cannot resize image /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/disk to a smaller size. can_resize_image /opt/stack/nova/nova/virt/disk/api.py:220
  n-cpu.log:2016-08-11 21:56:08.550 31615 DEBUG nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Ensure instance console log exists: /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd/console.log _ensure_console_log_for_instance /opt/stack/nova/nova/virt/libvirt/driver.py:2913
  n-cpu.log:2016-08-11 21:57:07.404 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Releasing semaphore "refresh_cache-d7316f88-1cce-471c-90ac-3e8d9f405cbd" lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Instance failed to spawn
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Traceback (most recent call last):
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 2075, in _build_resources
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     yield resources
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1919, in _build_and_run_instance
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     block_device_info=block_device_info)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 2658, in spawn
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     write_to_disk=True)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/virt/libvirt/driver.py", line 4679, in _get_guest_xml
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     network_info_str = str(network_info)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/model.py", line 524, in __str__
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return self._sync_wrapper(fn, *args, **kwargs)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/model.py", line 507, in _sync_wrapper
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self.wait()
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/model.py", line 539, in wait
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self[:] = self._gt.wait()
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 175, in wait
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return self._exit_event.wait()
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/event.py", line 121, in wait
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return hubs.get_hub().switch()
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/hubs/hub.py", line 294, in switch
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return self.greenlet.switch()
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/eventlet/greenthread.py", line 214, in main
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     result = function(*args, **kwargs)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/utils.py", line 1052, in context_wrapper
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return func(*args, **kwargs)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1413, in _allocate_network_async
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     six.reraise(*exc_info)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1396, in _allocate_network_async
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     bind_host_id=bind_host_id)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/base_api.py", line 77, in wrapper
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     res = f(self, context, *args, **kwargs)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/api.py", line 265, in allocate_for_instance
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     nw_info = self.network_rpcapi.allocate_for_instance(context, **args)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/rpcapi.py", line 157, in allocate_for_instance
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     macs=jsonutils.to_primitive(macs))
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=self.retry)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 96, in _send
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     timeout=timeout, retry=retry)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=retry)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     result = self._waiter.wait(msg_id, timeout)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     message = self.waiters.get(msg_id, timeout=timeout)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     'to message ID %s' % msg_id)
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] MessagingTimeout: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc
  n-cpu.log:2016-08-11 21:57:07.408 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] 
  n-cpu.log:2016-08-11 21:57:07.410 31615 INFO nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Terminating instance
  n-cpu.log:2016-08-11 21:57:07.412 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Start destroying the instance on the hypervisor. _shutdown_instance /opt/stack/nova/nova/compute/manager.py:2188
  n-cpu.log:2016-08-11 21:57:07.419 31615 INFO nova.virt.libvirt.driver [-] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] During wait destroy, instance disappeared.
  n-cpu.log:2016-08-11 21:57:07.420 31615 INFO nova.virt.libvirt.firewall [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Attempted to unfilter instance which is not filtered
  n-cpu.log:2016-08-11 21:57:07.420 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Running cmd (subprocess): mv /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
  n-cpu.log:2016-08-11 21:57:07.441 31615 DEBUG oslo_concurrency.processutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] CMD "mv /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del" returned: 0 in 0.021s execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
  n-cpu.log:2016-08-11 21:57:07.442 31615 INFO nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deleting instance files /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del
  n-cpu.log:2016-08-11 21:57:07.444 31615 INFO nova.virt.libvirt.driver [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deletion of /opt/stack/data/nova/instances/d7316f88-1cce-471c-90ac-3e8d9f405cbd_del complete
  n-cpu.log:2016-08-11 21:57:07.535 31615 INFO nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Took 0.12 seconds to destroy the instance on the hypervisor.
  n-cpu.log:2016-08-11 21:57:07.535 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deallocating network for instance _deallocate_network /opt/stack/nova/nova/compute/manager.py:1658
  n-cpu.log:2016-08-11 21:57:09.998 31615 DEBUG nova.compute.manager [req-484901e8-4f0a-431a-b30b-62d350cfb9d9 - -] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Skipping network cache update for instance because it is Building. _heal_instance_info_cache /opt/stack/nova/nova/compute/manager.py:5703
  n-cpu.log:2016-08-11 21:58:07.540 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Failed to deallocate network for instance. Error: Timed out waiting for a reply to message ID c42a2af13d264fc29665d0c056509cd0
  n-cpu.log:2016-08-11 21:58:07.772 31615 DEBUG nova.compute.claims [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Aborting claim: [Claim: 512 MB memory, 1 GB disk] abort /opt/stack/nova/nova/compute/claims.py:123
  n-cpu.log:2016-08-11 21:58:07.943 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc _build_and_run_instance /opt/stack/nova/nova/compute/manager.py:1936
  n-cpu.log:2016-08-11 21:58:07.944 31615 DEBUG nova.compute.utils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc notify_about_instance_usage /opt/stack/nova/nova/compute/utils.py:313
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Traceback (most recent call last):
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1778, in _do_build_and_run_instance
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     filter_properties)
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1938, in _build_and_run_instance
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     'create.error', fault=e)
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self.force_reraise()
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     six.reraise(self.type_, self.value, self.tb)
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1922, in _build_and_run_instance
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     instance=instance)
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/lib/python2.7/contextlib.py", line 35, in __exit__
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self.gen.throw(type, value, traceback)
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 2101, in _build_resources
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     reason=six.text_type(exc))
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] BuildAbortException: Build of instance d7316f88-1cce-471c-90ac-3e8d9f405cbd aborted: Timed out waiting for a reply to message ID 10d3e3e794f24427bca39364db5b76cc
  n-cpu.log:2016-08-11 21:58:07.945 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] 
  n-cpu.log:2016-08-11 21:58:07.946 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Deallocating network for instance _deallocate_network /opt/stack/nova/nova/compute/manager.py:1658
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Failed to deallocate networks
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] Traceback (most recent call last):
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 2106, in _cleanup_allocated_networks
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     self._deallocate_network(context, instance, requested_networks)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/compute/manager.py", line 1661, in _deallocate_network
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     context, instance, requested_networks=requested_networks)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/api.py", line 297, in deallocate_for_instance
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     requested_networks=requested_networks)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/opt/stack/nova/nova/network/rpcapi.py", line 177, in deallocate_for_instance
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     return cctxt.call(ctxt, 'deallocate_for_instance', **kwargs)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=self.retry)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 96, in _send
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     timeout=timeout, retry=retry)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 464, in send
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     retry=retry)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 453, in _send
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     result = self._waiter.wait(msg_id, timeout)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 336, in wait
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     message = self.waiters.get(msg_id, timeout=timeout)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]   File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 238, in get
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd]     'to message ID %s' % msg_id)
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] MessagingTimeout: Timed out waiting for a reply to message ID eaadafca0f6a44c99b9341a9aa4fb95c
  n-cpu.log:2016-08-11 21:59:07.950 31615 ERROR nova.compute.manager [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] 
  n-cpu.log:2016-08-11 21:59:07.952 31615 DEBUG nova.compute.manager [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] [instance: d7316f88-1cce-471c-90ac-3e8d9f405cbd] terminating bdm BlockDeviceMapping(boot_index=0,connection_info=None,created_at=2016-08-11T16:26:02Z,delete_on_termination=True,deleted=False,deleted_at=None,destination_type='local',device_name='/dev/vda',device_type='disk',disk_bus=None,guest_format=None,id=305,image_id='fbfbb67f-0201-40f6-841c-41635cda7bff',instance=<?>,instance_uuid=d7316f88-1cce-471c-90ac-3e8d9f405cbd,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=2016-08-11T16:26:03Z,volume_id=None,volume_size=None) _cleanup_volumes /opt/stack/nova/nova/compute/manager.py:2256
  n-cpu.log:2016-08-11 21:59:08.110 31615 DEBUG oslo_concurrency.lockutils [req-ba3c3657-1bde-4afa-821b-4abc0b5d514b admin demo] Lock "d7316f88-1cce-471c-90ac-3e8d9f405cbd" released by "nova.compute.manager._locked_do_build_and_run_instance" :: held 181.208s inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282

  
  nova.conf:

  [DEFAULT]
  vif_plugging_timeout = 300
  vif_plugging_is_fatal = True
  firewall_driver = nova.virt.firewall.NoopFirewallDriver
  use_neutron = True
  dhcpbridge_flagfile = /etc/nova/nova-dhcpbridge.conf
  graceful_shutdown_timeout = 5
  metadata_workers = 3
  osapi_compute_workers = 3
  transport_url = rabbit://stackrabbit:vmware@192.168.2.141:5672/
  logging_user_identity_format = %(user_name)s %(project_name)s
  force_config_drive = True
  send_arp_for_ha = True
  multi_host = True
  instances_path = /opt/stack/data/nova/instances
  state_path = /opt/stack/data/nova
  enabled_apis = osapi_compute,metadata
  s3_listen = 0.0.0.0
  metadata_listen = 0.0.0.0
  osapi_compute_listen = 0.0.0.0
  instance_name_template = instance-%08x
  my_ip = 192.168.2.141
  s3_port = 3333
  s3_host = 192.168.2.141
  default_floating_pool = public
  force_dhcp_release = True
  scheduler_default_filters = RetryFilter,AvailabilityZoneFilter,RamFilter,DiskFilter,ComputeFilter,ComputeCapabilitiesFilter,ImagePropertiesFilter,ServerGroupAntiAffinityFilter,ServerGroupAffinityFilter,SameHostFilter,DifferentHostFilter
  scheduler_driver = filter_scheduler
  rootwrap_config = /etc/nova/rootwrap.conf
  allow_resize_to_same_host = True
  debug = True

  [wsgi]
  api_paste_config = /etc/nova/api-paste.ini

  [database]
  connection = mysql+pymysql://root:vmware@127.0.0.1/nova?charset=utf8

  [api_database]
  connection = mysql+pymysql://root:vmware@127.0.0.1/nova_api?charset=utf8

  [keystone_authtoken]
  memcached_servers = 192.168.2.141:11211
  signing_dir = /var/cache/nova
  cafile = /opt/stack/data/ca-bundle.pem
  auth_uri = http://192.168.2.141/identity
  project_domain_name = Default
  project_name = service
  user_domain_name = Default
  password = vmware
  username = nova
  auth_url = http://192.168.2.141/identity_v2_admin
  auth_type = password

  [oslo_concurrency]
  lock_path = /opt/stack/data/nova

  [vnc]
  xvpvncproxy_host = 0.0.0.0
  novncproxy_host = 0.0.0.0
  vncserver_proxyclient_address = 127.0.0.1
  vncserver_listen = 127.0.0.1
  enabled = true

  [spice]
  enabled = false

  [glance]
  api_servers = http://192.168.2.141:9292

  [conductor]
  workers = 3

  [cinder]
  os_region_name = RegionOne

  [neutron]
  service_metadata_proxy = True
  url = http://192.168.2.141:9696
  region_name = RegionOne
  auth_strategy = keystone
  project_domain_name = Default
  project_name = service
  user_domain_name = Default
  password = vmware
  username = neutron
  auth_url = http://192.168.2.141/identity_v2_admin/v3
  auth_type = password

  [key_manager]
  fixed_key = 2483b40c5c14c188ecc38aaee7167423a11144d405d551b575091aca02ba6857

  
  localrc compute:

  GIT_BASE=https://git.openstack.org/
  enable_plugin vmware-nsx https://git.openstack.org/openstack/vmware-nsx master
  Q_PLUGIN=vmware_nsx_v3
  ENABLED_SERVICES=n-cpu
  SERVICE_HOST=192.168.2.141
  MYSQL_HOST=$SERVICE_HOST
  RABBIT_HOST=$SERVICE_HOST
  Q_HOST=$SERVICE_HOST
  DATABASE_PASSWORD=vmware
  RABBIT_PASSWORD=vmware
  SERVICE_TOKEN=vmware
  SERVICE_PASSWORD=vmware
  ADMIN_PASSWORD=vmware
  RECLONE=yes
  OVS_BRIDGE=nsx-managed
  IPV6_ENABLED=False
  IP_VERSION=4
  HOST_IP=192.168.2.145
  MULTI_HOST=1
  NOVA_VNC_ENABLED=True
  NOVNCPROXY_URL="http://$SERVICE_HOST:6080/vnc_auto.html";
  VNCSERVER_LISTEN=$HOST_IP
  VNCSERVER_PROXYCLIENT_ADDRESS=$VNCSERVER_LISTEN
  NSX_MANAGER=192.168.2.187
  NSX_USER=admin
  NSX_PASSWORD=Vmware123!
  disable_service zookeeper
  #DEBUG=False
  #DEFAULT_VLAN_TZ_UUID=changeme   # Optional, for VLAN provider networks

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1612353/+subscriptions
Follow ups

[Bug 1612353] Re: [master] instance launch failing on ESXi and KVM
From: Gary Kotton, 2016-08-14