Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

Regarding Block Live Migration on DevStack-Nova Error

I'm using Devstack-mitaka branch to set up a in-house multi-node cloud with 1 controller node and 5 compute node. The set-up process was quite easy and controller node can launch vm's across compute nodes and these can be accessed across the subnet. As I'm experimenting on these systems, I haven't set up shared storage server. I'm now trying to achieve Block Live migration across these nodes but the active log states on dashboard shows error for this particular operation. Going through n-cpu.log log (nova compute log), I find this particular exception related to oslo_messaging rpc - " 2016-11-15 13:53:00.810 [01;31mERROR oslo_messaging.rpc.dispatcher [ [01;36mreq-e3a2f83c-fbc1-4677-86ea-f9f07416e33a [00;36madmin admin [01;31m] [01;35m [01;31mException during message handling: Remote error: ProcessExecutionError Unexpected error while running command. " with few DEBUG comments. I searched online for solution, but couldn't find any satisfying solution. Is there place I can look for help i.e website or people I can contact regarding this matter.

The system configuration on each system is, i7 processor , 8GB RAM, 1TB harddisk, Ubuntu 14.04 Desktop connected via a small Dlink 100 Mbps router.

n-cpu.log with only log related to block live migration request-Id "req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a" below

2016-11-15 13:51:42.335 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'vcpu_model' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895 2016-11-15 13:51:42.341 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Instance launched has CPU info: {"vendor": "Intel", "model": "Haswell", "arch": "x86_64", "features": ["pge", "avx", "clflush", "sep", "rtm", "vme", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "fma", "tsc-deadline", "mmx", "osxsave", "cx8", "mce", "de", "tm2", "ht", "pse", "lahf_lm", "abm", "popcnt", "mca", "pdpe1gb", "apic", "sse", "f16c", "ds", "pni", "rdtscp", "avx2", "aes", "sse2", "ss", "ds_cpl", "bmi1", "bmi2", "pcid", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand", "x2apic"], "topology": {"cores": 4, "cells": 1, "threads": 2, "sockets": 1}} 2016-11-15 13:51:42.342 DEBUG nova.virt.libvirt.config [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Generated XML ('<cpu>\n <arch>x86_64</arch>\n <model>Haswell</model>\n <vendor>Intel</vendor>\n <topology sockets="1" cores="4" threads="2"/>\n <feature name="abm"/>\n <feature name="acpi"/>\n <feature name="aes"/>\n <feature name="apic"/>\n <feature name="avx"/>\n <feature name="avx2"/>\n <feature name="bmi1"/>\n <feature name="bmi2"/>\n <feature name="clflush"/>\n <feature name="cmov"/>\n <feature name="cx16"/>\n <feature name="cx8"/>\n <feature name="de"/>\n <feature name="ds"/>\n <feature name="ds_cpl"/>\n <feature name="dtes64"/>\n <feature name="erms"/>\n <feature name="est"/>\n <feature name="f16c"/>\n <feature name="fma"/>\n <feature name="fpu"/>\n <feature name="fsgsbase"/>\n <feature name="fxsr"/>\n <feature name="hle"/>\n <feature name="ht"/>\n <feature name="invpcid"/>\n <feature name="lahf_lm"/>\n <feature name="lm"/>\n <feature name="mca"/>\n <feature name="mce"/>\n <feature name="mmx"/>\n <feature name="monitor"/>\n <feature name="movbe"/>\n <feature name="msr"/>\n <feature name="mtrr"/>\n <feature name="nx"/>\n <feature name="osxsave"/>\n <feature name="pae"/>\n <feature name="pat"/>\n <feature name="pbe"/>\n <feature name="pcid"/>\n <feature name="pclmuldq"/>\n <feature name="pdcm"/>\n <feature name="pdpe1gb"/>\n <feature name="pge"/>\n <feature name="pni"/>\n <feature name="popcnt"/>\n <feature name="pse"/>\n <feature name="pse36"/>\n <feature name="rdrand"/>\n <feature name="rdtscp"/>\n <feature name="rtm"/>\n <feature name="sep"/>\n <feature name="smep"/>\n <feature name="smx"/>\n <feature name="ss"/>\n <feature name="sse"/>\n <feature name="sse2"/>\n <feature name="sse4.1"/>\n <feature name="sse4.2"/>\n <feature name="ssse3"/>\n <feature name="syscall"/>\n <feature name="tm"/>\n <feature name="tm2"/>\n <feature name="tsc"/>\n <feature name="tsc-deadline"/>\n <feature name="vme"/>\n <feature name="vmx"/>\n <feature name="x2apic"/>\n <feature name="xsave"/>\n <feature name="xtpr"/>\n</cpu>\n',)  from (pid=21881) to_xml /opt/stack/nova/nova/virt/libvirt/config.py:82 2016-11-15 13:51:42.343 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Creating tmpfile /opt/stack/data/nova/instances/tmphpTnza to notify to other compute nodes that they should mount the same storage. from (pid=21881) _create_shared_storage_test_file /opt/stack/nova/nova/virt/libvirt/driver.py:5743 2016-11-15 13:51:42.343 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] destination check data is LibvirtLiveMigrateData(bdms=,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=,graphics_listen_addr_vnc=,image_type='default',instance_relative_path=,is_shared_block_storage=,is_shared_instance_path=,is_volume_backed=,migration=,serial_listen_addr=,target_connect_addr=) from (pid=21881) _do_check_can_live_migrate_destination /opt/stack/nova/nova/compute/manager.py:5175 2016-11-15 13:51:43.073 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] pre_live_migration data is LibvirtLiveMigrateData(bdms=,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=,graphics_listen_addr_vnc=,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=,serial_listen_addr=,target_connect_addr=) from (pid=21881) pre_live_migration /opt/stack/nova/nova/compute/manager.py:5233 2016-11-15 13:51:43.082 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212 2016-11-15 13:51:43.082 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'flavor' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895 2016-11-15 13:51:43.172 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43 2016-11-15 13:51:43.180 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225 2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] migrate_data in pre_live_migration: LibvirtLiveMigrateData(bdms=,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=,graphics_listen_addr_vnc=,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=,serial_listen_addr=,target_connect_addr=) from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6646 2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating instance directory: /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6659 2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating disk.info with the contents: {u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config': u'raw', u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk': u'qcow2'} from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6673 2016-11-15 13:51:43.182 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Checking to make sure images and backing files are present before live migration. from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6683 2016-11-15 13:51:43.182 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.271 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.089s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.272 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.299 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.300 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270 2016-11-15 13:51:43.301 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.329 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.330 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.525 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.195s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.526 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Checking if we can resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk. size=25165824 from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:203 2016-11-15 13:51:43.526 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.555 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.556 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Cannot resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk to a smaller size. from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:209 2016-11-15 13:51:43.556 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.256s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282 2016-11-15 13:51:43.556 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.595 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128" returned: 0 in 0.010s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.640 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.669 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.713 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:51:43.747 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part" returned: 0 in 0.034s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:51:43.748 DEBUG nova.virt.libvirt.volume.remotefs [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Copying file pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config to /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) copy_file /opt/stack/nova/nova/virt/libvirt/volume/remotefs.py:121 2016-11-15 13:51:43.749 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): scp pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:52:43.538 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212 2016-11-15 13:52:43.574 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43 2016-11-15 13:52:43.581 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225 2016-11-15 13:53:00.511 ERROR nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] An error occurred while deallocating network. 2016-11-15 13:53:00.521 DEBUG nova.virt.libvirt.vif [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='True',created_at=2016-11-15T04:29:17Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name='myvm1',ec2_ids=,ephemeral_gb=0,ephemeral_key_uuid=None,fault=,flavor=Flavor(7),host='pgcne-18',hostname='myvm1',id=2,image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',key_data=None,key_name=None,launch_index=0,launched_at=2016-11-15T04:29:24Z,launched_on='pgcne-18',locked=False,locked_by=None,memory_mb=128,metadata={},migration_context=,new_flavor=Flavor(7),node='pgcne-18',numa_topology=,old_flavor=None,os_type=None,pci_devices=,pci_requests=,power_state=1,progress=0,project_id='a49c5a5cf4ff43eb906f28203d5be96f',ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',reservation_id='r-r0yk2c3p',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=,shutdown_terminate=False,system_metadata={clean_attempts='5',image_base_image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',image_container_format='ami',image_disk_format='ami',image_kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',image_min_disk='0',image_min_ram='0',image_ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',old_vm_state='active'},tags=,task_state=None,terminated_at=None,updated_at=2016-11-15T08:21:42Z,user_data=None,user_id='3a8a019c345347fda6906087db767727',uuid=1b79133c-5933-4997-8db4-5aa485336c34,vcpu_model=,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:7b:9a:76', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.4.131.255', 'type': u'fixed'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None}) from (pid=21881) unplug /opt/stack/nova/nova/virt/libvirt/vif.py:957 2016-11-15 13:53:00.522 INFO nova.virt.libvirt.firewall [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Attempted to unfilter instance which is not filtered 2016-11-15 13:53:00.522 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344 2016-11-15 13:53:00.527 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del" returned: 0 in 0.005s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374 2016-11-15 13:53:00.528 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deleting instance files /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del 2016-11-15 13:53:00.529 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deletion of /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del complete 2016-11-15 13:53:00.810 ERROR oslo_messaging.rpc.dispatcher [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Exception during message handling: Remote error: ProcessExecutionError Unexpected error while running command.

Regarding Block Live Migration on DevStack-Nova Error

I'm using Devstack-mitaka branch to set up a in-house multi-node cloud with 1 controller node and 5 compute node. The set-up process was quite easy and controller node can launch vm's across compute nodes and these can be accessed across the subnet. As I'm experimenting on these systems, I haven't set up shared storage server. I'm now trying to achieve Block Live migration across these nodes but the active log states on dashboard shows error for this particular operation. Going through n-cpu.log log (nova compute log), I find this particular exception related to oslo_messaging rpc - " 2016-11-15 13:53:00.810 [01;31mERROR oslo_messaging.rpc.dispatcher [ [01;36mreq-e3a2f83c-fbc1-4677-86ea-f9f07416e33a [00;36madmin admin [01;31m] [01;35m [01;31mException during message handling: Remote error: ProcessExecutionError Unexpected error while running command. " with few DEBUG comments. I searched online for solution, but couldn't find any satisfying solution. Is there place I can look for help i.e website or people I can contact regarding this matter.

The system configuration on each system is, i7 processor , 8GB RAM, 1TB harddisk, Ubuntu 14.04 Desktop connected via a small Dlink 100 Mbps router.

n-cpu.log with only log related to block live migration request-Id "req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a" below

2016-11-15 13:51:42.335 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'vcpu_model' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895
2016-11-15 13:51:42.341 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Instance launched has CPU info: {"vendor": "Intel", "model": "Haswell", "arch": "x86_64", "features": ["pge", "avx", "clflush", "sep", "rtm", "vme", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "fma", "tsc-deadline", "mmx", "osxsave", "cx8", "mce", "de", "tm2", "ht", "pse", "lahf_lm", "abm", "popcnt", "mca", "pdpe1gb", "apic", "sse", "f16c", "ds", "pni", "rdtscp", "avx2", "aes", "sse2", "ss", "ds_cpl", "bmi1", "bmi2", "pcid", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand", "x2apic"], "topology": {"cores": 4, "cells": 1, "threads": 2, "sockets": 1}}
2016-11-15 13:51:42.342 DEBUG nova.virt.libvirt.config [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Generated XML ('<cpu>\n  <arch>x86_64</arch>\n  <model>Haswell</model>\n  <vendor>Intel</vendor>\n  <topology sockets="1" cores="4" threads="2"/>\n  <feature name="abm"/>\n  <feature name="acpi"/>\n  <feature name="aes"/>\n  <feature name="apic"/>\n  <feature name="avx"/>\n  <feature name="avx2"/>\n  <feature name="bmi1"/>\n  <feature name="bmi2"/>\n  <feature name="clflush"/>\n  <feature name="cmov"/>\n  <feature name="cx16"/>\n  <feature name="cx8"/>\n  <feature name="de"/>\n  <feature name="ds"/>\n  <feature name="ds_cpl"/>\n  <feature name="dtes64"/>\n  <feature name="erms"/>\n  <feature name="est"/>\n  <feature name="f16c"/>\n  <feature name="fma"/>\n  <feature name="fpu"/>\n  <feature name="fsgsbase"/>\n  <feature name="fxsr"/>\n  <feature name="hle"/>\n  <feature name="ht"/>\n  <feature name="invpcid"/>\n  <feature name="lahf_lm"/>\n  <feature name="lm"/>\n  <feature name="mca"/>\n  <feature name="mce"/>\n  <feature name="mmx"/>\n  <feature name="monitor"/>\n  <feature name="movbe"/>\n  <feature name="msr"/>\n  <feature name="mtrr"/>\n  <feature name="nx"/>\n  <feature name="osxsave"/>\n  <feature name="pae"/>\n  <feature name="pat"/>\n  <feature name="pbe"/>\n  <feature name="pcid"/>\n  <feature name="pclmuldq"/>\n  <feature name="pdcm"/>\n  <feature name="pdpe1gb"/>\n  <feature name="pge"/>\n  <feature name="pni"/>\n  <feature name="popcnt"/>\n  <feature name="pse"/>\n  <feature name="pse36"/>\n  <feature name="rdrand"/>\n  <feature name="rdtscp"/>\n  <feature name="rtm"/>\n  <feature name="sep"/>\n  <feature name="smep"/>\n  <feature name="smx"/>\n  <feature name="ss"/>\n  <feature name="sse"/>\n  <feature name="sse2"/>\n  <feature name="sse4.1"/>\n  <feature name="sse4.2"/>\n  <feature name="ssse3"/>\n  <feature name="syscall"/>\n  <feature name="tm"/>\n  <feature name="tm2"/>\n  <feature name="tsc"/>\n  <feature name="tsc-deadline"/>\n  <feature name="vme"/>\n  <feature name="vmx"/>\n  <feature name="x2apic"/>\n  <feature name="xsave"/>\n  <feature name="xtpr"/>\n</cpu>\n',)  from (pid=21881) to_xml /opt/stack/nova/nova/virt/libvirt/config.py:82
2016-11-15 13:51:42.343 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Creating tmpfile /opt/stack/data/nova/instances/tmphpTnza to notify to other compute nodes that they should mount the same storage. from (pid=21881) _create_shared_storage_test_file /opt/stack/nova/nova/virt/libvirt/driver.py:5743
2016-11-15 13:51:42.343 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] destination check data is LibvirtLiveMigrateData(bdms=,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=,graphics_listen_addr_vnc=,image_type='default',instance_relative_path=,is_shared_block_storage=,is_shared_instance_path=,is_volume_backed=,migration=,serial_listen_addr=,target_connect_addr=) LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path=<?>,is_shared_block_storage=<?>,is_shared_instance_path=<?>,is_volume_backed=<?>,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) _do_check_can_live_migrate_destination /opt/stack/nova/nova/compute/manager.py:5175
2016-11-15 13:51:43.073 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] pre_live_migration data is LibvirtLiveMigrateData(bdms=,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=,graphics_listen_addr_vnc=,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=,serial_listen_addr=,target_connect_addr=) LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) pre_live_migration /opt/stack/nova/nova/compute/manager.py:5233
2016-11-15 13:51:43.082 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-11-15 13:51:43.082 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'flavor' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895
2016-11-15 13:51:43.172 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43
2016-11-15 13:51:43.180 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] migrate_data in pre_live_migration: LibvirtLiveMigrateData(bdms=,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=,graphics_listen_addr_vnc=,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=,serial_listen_addr=,target_connect_addr=) LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6646
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating instance directory: /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6659
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating disk.info with the contents: {u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config': u'raw', u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk': u'qcow2'} from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6673
2016-11-15 13:51:43.182 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Checking to make sure images and backing files are present before live migration. from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6683
2016-11-15 13:51:43.182 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.271 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.089s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.272 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.299 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.300 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-11-15 13:51:43.301 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.329 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.330 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.525 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.195s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.526 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Checking if we can resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk. size=25165824 from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:203
2016-11-15 13:51:43.526 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.555 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.556 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Cannot resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk to a smaller size. from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:209
2016-11-15 13:51:43.556 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.256s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-11-15 13:51:43.556 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.595 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128" returned: 0 in 0.010s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.640 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.669 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.713 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.747 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part" returned: 0 in 0.034s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.748 DEBUG nova.virt.libvirt.volume.remotefs [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Copying file pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config to /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) copy_file /opt/stack/nova/nova/virt/libvirt/volume/remotefs.py:121
2016-11-15 13:51:43.749 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): scp pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:52:43.538 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-11-15 13:52:43.574 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43
2016-11-15 13:52:43.581 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-11-15 13:53:00.511 ERROR nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] An error occurred while deallocating network.
2016-11-15 13:53:00.521 DEBUG nova.virt.libvirt.vif [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='True',created_at=2016-11-15T04:29:17Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name='myvm1',ec2_ids=,ephemeral_gb=0,ephemeral_key_uuid=None,fault=,flavor=Flavor(7),host='pgcne-18',hostname='myvm1',id=2,image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',key_data=None,key_name=None,launch_index=0,launched_at=2016-11-15T04:29:24Z,launched_on='pgcne-18',locked=False,locked_by=None,memory_mb=128,metadata={},migration_context=,new_flavor=Flavor(7),node='pgcne-18',numa_topology=,old_flavor=None,os_type=None,pci_devices=,pci_requests=,power_state=1,progress=0,project_id='a49c5a5cf4ff43eb906f28203d5be96f',ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',reservation_id='r-r0yk2c3p',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=,shutdown_terminate=False,system_metadata={clean_attempts='5',image_base_image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',image_container_format='ami',image_disk_format='ami',image_kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',image_min_disk='0',image_min_ram='0',image_ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',old_vm_state='active'},tags=,task_state=None,terminated_at=None,updated_at=2016-11-15T08:21:42Z,user_data=None,user_id='3a8a019c345347fda6906087db767727',uuid=1b79133c-5933-4997-8db4-5aa485336c34,vcpu_model=,vcpus=1,vm_mode=None,vm_state='active') instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='True',created_at=2016-11-15T04:29:17Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name='myvm1',ec2_ids=<?>,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(7),host='pgcne-18',hostname='myvm1',id=2,image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',key_data=None,key_name=None,launch_index=0,launched_at=2016-11-15T04:29:24Z,launched_on='pgcne-18',locked=False,locked_by=None,memory_mb=128,metadata={},migration_context=<?>,new_flavor=Flavor(7),node='pgcne-18',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='a49c5a5cf4ff43eb906f28203d5be96f',ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',reservation_id='r-r0yk2c3p',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={clean_attempts='5',image_base_image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',image_container_format='ami',image_disk_format='ami',image_kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',image_min_disk='0',image_min_ram='0',image_ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',old_vm_state='active'},tags=<?>,task_state=None,terminated_at=None,updated_at=2016-11-15T08:21:42Z,user_data=None,user_id='3a8a019c345347fda6906087db767727',uuid=1b79133c-5933-4997-8db4-5aa485336c34,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:7b:9a:76', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.4.131.255', 'type': u'fixed'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None}) from (pid=21881) unplug /opt/stack/nova/nova/virt/libvirt/vif.py:957
2016-11-15 13:53:00.522 INFO nova.virt.libvirt.firewall [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Attempted to unfilter instance which is not filtered
2016-11-15 13:53:00.522 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:53:00.527 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del" returned: 0 in 0.005s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:53:00.528 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deleting instance files /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del
2016-11-15 13:53:00.529 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deletion of /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del complete
2016-11-15 13:53:00.810 ERROR oslo_messaging.rpc.dispatcher [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Exception during message handling: Remote error: ProcessExecutionError Unexpected error while running command.

command.

Regarding Block Live Migration on DevStack-Nova Error

I'm using Devstack-mitaka branch to set up a in-house multi-node cloud with 1 controller node and 5 compute node. The set-up process was quite easy and controller node can launch vm's across compute nodes and these can be accessed across the subnet. As I'm experimenting on these systems, I haven't set up shared storage server. I'm now trying to achieve Block Live migration across these nodes but the active log states on dashboard shows error for this particular operation. Going through n-cpu.log log (nova compute log), I find this particular exception related to oslo_messaging rpc - " 2016-11-15 13:53:00.810 [01;31mERROR oslo_messaging.rpc.dispatcher [ [01;36mreq-e3a2f83c-fbc1-4677-86ea-f9f07416e33a [00;36madmin admin [01;31m] [01;35m [01;31mException during message handling: Remote error: ProcessExecutionError Unexpected error while running command. " with few DEBUG comments. I searched online for solution, but couldn't find any satisfying solution. Is there place I can look for help i.e website or people I can contact regarding this matter.

The system configuration on each system is, i7 processor , 8GB RAM, 1TB harddisk, Ubuntu 14.04 Desktop connected via a small Dlink 100 Mbps router.

n-cpu.log with only log related to block live migration request-Id "req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a" below

2016-11-15 13:51:42.335 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'vcpu_model' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895
2016-11-15 13:51:42.341 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Instance launched has CPU info: {"vendor": "Intel", "model": "Haswell", "arch": "x86_64", "features": ["pge", "avx", "clflush", "sep", "rtm", "vme", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "fma", "tsc-deadline", "mmx", "osxsave", "cx8", "mce", "de", "tm2", "ht", "pse", "lahf_lm", "abm", "popcnt", "mca", "pdpe1gb", "apic", "sse", "f16c", "ds", "pni", "rdtscp", "avx2", "aes", "sse2", "ss", "ds_cpl", "bmi1", "bmi2", "pcid", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand", "x2apic"], "topology": {"cores": 4, "cells": 1, "threads": 2, "sockets": 1}}
2016-11-15 13:51:42.342 DEBUG nova.virt.libvirt.config [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Generated XML ('<cpu>\n  <arch>x86_64</arch>\n  <model>Haswell</model>\n  <vendor>Intel</vendor>\n  <topology sockets="1" cores="4" threads="2"/>\n  <feature name="abm"/>\n  <feature name="acpi"/>\n  <feature name="aes"/>\n  <feature name="apic"/>\n  <feature name="avx"/>\n  <feature name="avx2"/>\n  <feature name="bmi1"/>\n  <feature name="bmi2"/>\n  <feature name="clflush"/>\n  <feature name="cmov"/>\n  <feature name="cx16"/>\n  <feature name="cx8"/>\n  <feature name="de"/>\n  <feature name="ds"/>\n  <feature name="ds_cpl"/>\n  <feature name="dtes64"/>\n  <feature name="erms"/>\n  <feature name="est"/>\n  <feature name="f16c"/>\n  <feature name="fma"/>\n  <feature name="fpu"/>\n  <feature name="fsgsbase"/>\n  <feature name="fxsr"/>\n  <feature name="hle"/>\n  <feature name="ht"/>\n  <feature name="invpcid"/>\n  <feature name="lahf_lm"/>\n  <feature name="lm"/>\n  <feature name="mca"/>\n  <feature name="mce"/>\n  <feature name="mmx"/>\n  <feature name="monitor"/>\n  <feature name="movbe"/>\n  <feature name="msr"/>\n  <feature name="mtrr"/>\n  <feature name="nx"/>\n  <feature name="osxsave"/>\n  <feature name="pae"/>\n  <feature name="pat"/>\n  <feature name="pbe"/>\n  <feature name="pcid"/>\n  <feature name="pclmuldq"/>\n  <feature name="pdcm"/>\n  <feature name="pdpe1gb"/>\n  <feature name="pge"/>\n  <feature name="pni"/>\n  <feature name="popcnt"/>\n  <feature name="pse"/>\n  <feature name="pse36"/>\n  <feature name="rdrand"/>\n  <feature name="rdtscp"/>\n  <feature name="rtm"/>\n  <feature name="sep"/>\n  <feature name="smep"/>\n  <feature name="smx"/>\n  <feature name="ss"/>\n  <feature name="sse"/>\n  <feature name="sse2"/>\n  <feature name="sse4.1"/>\n  <feature name="sse4.2"/>\n  <feature name="ssse3"/>\n  <feature name="syscall"/>\n  <feature name="tm"/>\n  <feature name="tm2"/>\n  <feature name="tsc"/>\n  <feature name="tsc-deadline"/>\n  <feature name="vme"/>\n  <feature name="vmx"/>\n  <feature name="x2apic"/>\n  <feature name="xsave"/>\n  <feature name="xtpr"/>\n</cpu>\n',)  from (pid=21881) to_xml /opt/stack/nova/nova/virt/libvirt/config.py:82
2016-11-15 13:51:42.343 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Creating tmpfile /opt/stack/data/nova/instances/tmphpTnza to notify to other compute nodes that they should mount the same storage. from (pid=21881) _create_shared_storage_test_file /opt/stack/nova/nova/virt/libvirt/driver.py:5743
2016-11-15 13:51:42.343 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] destination check data is LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path=<?>,is_shared_block_storage=<?>,is_shared_instance_path=<?>,is_volume_backed=<?>,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) _do_check_can_live_migrate_destination /opt/stack/nova/nova/compute/manager.py:5175
2016-11-15 13:51:43.073 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] pre_live_migration data is LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) pre_live_migration /opt/stack/nova/nova/compute/manager.py:5233
2016-11-15 13:51:43.082 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-11-15 13:51:43.082 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'flavor' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895
2016-11-15 13:51:43.172 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43
2016-11-15 13:51:43.180 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] migrate_data in pre_live_migration: LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6646
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating instance directory: /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6659
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating disk.info with the contents: {u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config': u'raw', u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk': u'qcow2'} from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6673
2016-11-15 13:51:43.182 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Checking to make sure images and backing files are present before live migration. from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6683
2016-11-15 13:51:43.182 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.271 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.089s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.272 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.299 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.300 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-11-15 13:51:43.301 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.329 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.330 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.525 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.195s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.526 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Checking if we can resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk. size=25165824 from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:203
2016-11-15 13:51:43.526 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.555 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.556 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Cannot resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk to a smaller size. from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:209
2016-11-15 13:51:43.556 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.256s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-11-15 13:51:43.556 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.595 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128" returned: 0 in 0.010s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.640 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.669 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.713 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.747 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part" returned: 0 in 0.034s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.748 DEBUG nova.virt.libvirt.volume.remotefs [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Copying file pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config to /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) copy_file /opt/stack/nova/nova/virt/libvirt/volume/remotefs.py:121
2016-11-15 13:51:43.749 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): scp pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:52:43.538 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-11-15 13:52:43.574 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43
2016-11-15 13:52:43.581 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-11-15 13:53:00.511 ERROR nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] An error occurred while deallocating network.
2016-11-15 13:53:00.521 DEBUG nova.virt.libvirt.vif [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='True',created_at=2016-11-15T04:29:17Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name='myvm1',ec2_ids=<?>,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(7),host='pgcne-18',hostname='myvm1',id=2,image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',key_data=None,key_name=None,launch_index=0,launched_at=2016-11-15T04:29:24Z,launched_on='pgcne-18',locked=False,locked_by=None,memory_mb=128,metadata={},migration_context=<?>,new_flavor=Flavor(7),node='pgcne-18',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='a49c5a5cf4ff43eb906f28203d5be96f',ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',reservation_id='r-r0yk2c3p',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={clean_attempts='5',image_base_image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',image_container_format='ami',image_disk_format='ami',image_kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',image_min_disk='0',image_min_ram='0',image_ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',old_vm_state='active'},tags=<?>,task_state=None,terminated_at=None,updated_at=2016-11-15T08:21:42Z,user_data=None,user_id='3a8a019c345347fda6906087db767727',uuid=1b79133c-5933-4997-8db4-5aa485336c34,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:7b:9a:76', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.4.131.255', 'type': u'fixed'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None}) from (pid=21881) unplug /opt/stack/nova/nova/virt/libvirt/vif.py:957
2016-11-15 13:53:00.522 INFO nova.virt.libvirt.firewall [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Attempted to unfilter instance which is not filtered
2016-11-15 13:53:00.522 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:53:00.527 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del" returned: 0 in 0.005s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:53:00.528 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deleting instance files /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del
2016-11-15 13:53:00.529 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deletion of /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del complete
2016-11-15 13:53:00.810 ERROR oslo_messaging.rpc.dispatcher [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Exception during message handling: Remote error: ProcessExecutionError Unexpected error while running command.

Regarding Block Live Migration on DevStack-Nova Error

I'm using Devstack-mitaka branch to set up a in-house multi-node cloud with 1 controller node and 5 compute node. The set-up process was quite easy and controller node can launch vm's across compute nodes and these can be accessed across the subnet. As I'm experimenting on these systems, I haven't set up shared storage server. I'm now trying to achieve Block Live migration across these nodes but the active log states on dashboard shows error for this particular operation. Going through n-cpu.log log (nova compute log), I find this particular exception related to oslo_messaging rpc - " -

2016-11-15 13:53:00.810 [01;31mERROR oslo_messaging.rpc.dispatcher [ [01;36mreq-e3a2f83c-fbc1-4677-86ea-f9f07416e33a [00;36madmin admin [01;31m] [01;35m [01;31mException during message handling: Remote error: ProcessExecutionError Unexpected error while running command. "   command.

with few DEBUG comments. I searched online for solution, but couldn't find any satisfying solution. Is there place I can look for help i.e website or people I can contact regarding this matter.

The system configuration on each system is, i7 processor , 8GB RAM, 1TB harddisk, Ubuntu 14.04 Desktop connected via a small Dlink 100 Mbps router.

n-cpu.log with only log related to block live migration request-Id "req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a" below

2016-11-15 13:51:42.335 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'vcpu_model' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895
2016-11-15 13:51:42.341 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Instance launched has CPU info: {"vendor": "Intel", "model": "Haswell", "arch": "x86_64", "features": ["pge", "avx", "clflush", "sep", "rtm", "vme", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "xtpr", "cmov", "hle", "smep", "ssse3", "est", "pat", "monitor", "smx", "pbe", "lm", "msr", "nx", "fxsr", "syscall", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "fma", "tsc-deadline", "mmx", "osxsave", "cx8", "mce", "de", "tm2", "ht", "pse", "lahf_lm", "abm", "popcnt", "mca", "pdpe1gb", "apic", "sse", "f16c", "ds", "pni", "rdtscp", "avx2", "aes", "sse2", "ss", "ds_cpl", "bmi1", "bmi2", "pcid", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand", "x2apic"], "topology": {"cores": 4, "cells": 1, "threads": 2, "sockets": 1}}
2016-11-15 13:51:42.342 DEBUG nova.virt.libvirt.config [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Generated XML ('<cpu>\n  <arch>x86_64</arch>\n  <model>Haswell</model>\n  <vendor>Intel</vendor>\n  <topology sockets="1" cores="4" threads="2"/>\n  <feature name="abm"/>\n  <feature name="acpi"/>\n  <feature name="aes"/>\n  <feature name="apic"/>\n  <feature name="avx"/>\n  <feature name="avx2"/>\n  <feature name="bmi1"/>\n  <feature name="bmi2"/>\n  <feature name="clflush"/>\n  <feature name="cmov"/>\n  <feature name="cx16"/>\n  <feature name="cx8"/>\n  <feature name="de"/>\n  <feature name="ds"/>\n  <feature name="ds_cpl"/>\n  <feature name="dtes64"/>\n  <feature name="erms"/>\n  <feature name="est"/>\n  <feature name="f16c"/>\n  <feature name="fma"/>\n  <feature name="fpu"/>\n  <feature name="fsgsbase"/>\n  <feature name="fxsr"/>\n  <feature name="hle"/>\n  <feature name="ht"/>\n  <feature name="invpcid"/>\n  <feature name="lahf_lm"/>\n  <feature name="lm"/>\n  <feature name="mca"/>\n  <feature name="mce"/>\n  <feature name="mmx"/>\n  <feature name="monitor"/>\n  <feature name="movbe"/>\n  <feature name="msr"/>\n  <feature name="mtrr"/>\n  <feature name="nx"/>\n  <feature name="osxsave"/>\n  <feature name="pae"/>\n  <feature name="pat"/>\n  <feature name="pbe"/>\n  <feature name="pcid"/>\n  <feature name="pclmuldq"/>\n  <feature name="pdcm"/>\n  <feature name="pdpe1gb"/>\n  <feature name="pge"/>\n  <feature name="pni"/>\n  <feature name="popcnt"/>\n  <feature name="pse"/>\n  <feature name="pse36"/>\n  <feature name="rdrand"/>\n  <feature name="rdtscp"/>\n  <feature name="rtm"/>\n  <feature name="sep"/>\n  <feature name="smep"/>\n  <feature name="smx"/>\n  <feature name="ss"/>\n  <feature name="sse"/>\n  <feature name="sse2"/>\n  <feature name="sse4.1"/>\n  <feature name="sse4.2"/>\n  <feature name="ssse3"/>\n  <feature name="syscall"/>\n  <feature name="tm"/>\n  <feature name="tm2"/>\n  <feature name="tsc"/>\n  <feature name="tsc-deadline"/>\n  <feature name="vme"/>\n  <feature name="vmx"/>\n  <feature name="x2apic"/>\n  <feature name="xsave"/>\n  <feature name="xtpr"/>\n</cpu>\n',)  from (pid=21881) to_xml /opt/stack/nova/nova/virt/libvirt/config.py:82
2016-11-15 13:51:42.343 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Creating tmpfile /opt/stack/data/nova/instances/tmphpTnza to notify to other compute nodes that they should mount the same storage. from (pid=21881) _create_shared_storage_test_file /opt/stack/nova/nova/virt/libvirt/driver.py:5743
2016-11-15 13:51:42.343 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] destination check data is LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path=<?>,is_shared_block_storage=<?>,is_shared_instance_path=<?>,is_volume_backed=<?>,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) _do_check_can_live_migrate_destination /opt/stack/nova/nova/compute/manager.py:5175
2016-11-15 13:51:43.073 DEBUG nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] pre_live_migration data is LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) pre_live_migration /opt/stack/nova/nova/compute/manager.py:5233
2016-11-15 13:51:43.082 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-11-15 13:51:43.082 DEBUG nova.objects.instance [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lazy-loading 'flavor' on Instance uuid 1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) obj_load_attr /opt/stack/nova/nova/objects/instance.py:895
2016-11-15 13:51:43.172 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43
2016-11-15 13:51:43.180 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] migrate_data in pre_live_migration: LibvirtLiveMigrateData(bdms=<?>,block_migration=True,disk_available_mb=858112,disk_over_commit=False,filename='tmphpTnza',graphics_listen_addr_spice=<?>,graphics_listen_addr_vnc=<?>,image_type='default',instance_relative_path='1b79133c-5933-4997-8db4-5aa485336c34',is_shared_block_storage=False,is_shared_instance_path=False,is_volume_backed=False,migration=<?>,serial_listen_addr=<?>,target_connect_addr=<?>) from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6646
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating instance directory: /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6659
2016-11-15 13:51:43.181 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Creating disk.info with the contents: {u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config': u'raw', u'/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk': u'qcow2'} from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6673
2016-11-15 13:51:43.182 DEBUG nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Checking to make sure images and backing files are present before live migration. from (pid=21881) pre_live_migration /opt/stack/nova/nova/virt/libvirt/driver.py:6683
2016-11-15 13:51:43.182 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.271 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf touch -c /opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.089s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.272 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.299 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.300 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" acquired by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: waited 0.000s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:270
2016-11-15 13:51:43.301 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.329 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.330 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.525 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f qcow2 -o backing_file=/opt/stack/data/nova/instances/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.195s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.526 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Checking if we can resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk. size=25165824 from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:203
2016-11-15 13:51:43.526 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.555 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/disk" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.556 DEBUG nova.virt.disk.api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Cannot resize image /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk to a smaller size. from (pid=21881) can_resize_image /opt/stack/nova/nova/virt/disk/api.py:209
2016-11-15 13:51:43.556 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Lock "37d0a3c466c926930653206d3b3c7f9adcdf0c50" released by "nova.virt.libvirt.imagebackend.copy_qcow2_image" :: held 0.256s from (pid=21881) inner /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:282
2016-11-15 13:51:43.556 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/_base/37d0a3c466c926930653206d3b3c7f9adcdf0c50" returned: 0 in 0.028s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.584 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.595 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "qemu-img create -f raw /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config 432128" returned: 0 in 0.010s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.640 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.669 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/kernel.part" returned: 0 in 0.029s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.713 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:51:43.747 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] 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/1b79133c-5933-4997-8db4-5aa485336c34/ramdisk.part" returned: 0 in 0.034s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:51:43.748 DEBUG nova.virt.libvirt.volume.remotefs [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Copying file pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config to /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) copy_file /opt/stack/nova/nova/virt/libvirt/volume/remotefs.py:121
2016-11-15 13:51:43.749 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): scp pgcne-18:/opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34/disk.config /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:52:43.538 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Acquired semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-11-15 13:52:43.574 DEBUG nova.network.base_api [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Updating instance_info_cache with network_info: [VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': u'fixed', 'floating_ips': [], 'address': u'10.4.131.255'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None})] from (pid=21881) update_instance_cache_with_nw_info /opt/stack/nova/nova/network/base_api.py:43
2016-11-15 13:52:43.581 DEBUG oslo_concurrency.lockutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Releasing semaphore "refresh_cache-1b79133c-5933-4997-8db4-5aa485336c34" from (pid=21881) lock /usr/local/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:225
2016-11-15 13:53:00.511 ERROR nova.compute.manager [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] An error occurred while deallocating network.
2016-11-15 13:53:00.521 DEBUG nova.virt.libvirt.vif [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] vif_type=bridge instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=False,availability_zone=None,cell_name=None,cleaned=True,config_drive='True',created_at=2016-11-15T04:29:17Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description=None,display_name='myvm1',ec2_ids=<?>,ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(7),host='pgcne-18',hostname='myvm1',id=2,image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',info_cache=InstanceInfoCache,instance_type_id=7,kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',key_data=None,key_name=None,launch_index=0,launched_at=2016-11-15T04:29:24Z,launched_on='pgcne-18',locked=False,locked_by=None,memory_mb=128,metadata={},migration_context=<?>,new_flavor=Flavor(7),node='pgcne-18',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='a49c5a5cf4ff43eb906f28203d5be96f',ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',reservation_id='r-r0yk2c3p',root_device_name='/dev/vda',root_gb=0,security_groups=SecurityGroupList,services=<?>,shutdown_terminate=False,system_metadata={clean_attempts='5',image_base_image_ref='fb9c3f71-284e-41e9-b5a3-6dc44b8d2dde',image_container_format='ami',image_disk_format='ami',image_kernel_id='04706a61-82c3-4f2c-bf0d-03fd474cb38c',image_min_disk='0',image_min_ram='0',image_ramdisk_id='031ee0ad-5aac-47f2-8f92-0300bdd1789e',old_vm_state='active'},tags=<?>,task_state=None,terminated_at=None,updated_at=2016-11-15T08:21:42Z,user_data=None,user_id='3a8a019c345347fda6906087db767727',uuid=1b79133c-5933-4997-8db4-5aa485336c34,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': None, 'ovs_interfaceid': None, 'preserve_on_delete': False, 'network': Network({'bridge': u'br100', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:7b:9a:76', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.4.131.255', 'type': u'fixed'})], 'version': 4, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [IP({'meta': {}, 'version': 4, 'type': u'dns', 'address': u'8.8.4.4'})], 'routes': [], 'cidr': u'10.4.128.0/20', 'gateway': IP({'meta': {}, 'version': 4, 'type': u'gateway', 'address': u'10.4.128.1'})}), Subnet({'ips': [], 'version': None, 'meta': {u'dhcp_server': u'10.4.129.255'}, 'dns': [], 'routes': [], 'cidr': None, 'gateway': IP({'meta': {}, 'version': None, 'type': u'gateway', 'address': None})})], 'meta': {u'tenant_id': None, u'multi_host': True, u'should_create_bridge': True, u'bridge_interface': u'eth0'}, 'id': u'3bd836e4-384d-4daa-b349-98b61984ec3e', 'label': u'private'}), 'devname': None, 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {}, 'address': u'fa:16:3e:7b:9a:76', 'active': False, 'type': u'bridge', 'id': u'eafc2b2d-0aff-4e7e-83d5-ada2f827a578', 'qbg_params': None}) from (pid=21881) unplug /opt/stack/nova/nova/virt/libvirt/vif.py:957
2016-11-15 13:53:00.522 INFO nova.virt.libvirt.firewall [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Attempted to unfilter instance which is not filtered
2016-11-15 13:53:00.522 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Running cmd (subprocess): mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:344
2016-11-15 13:53:00.527 DEBUG oslo_concurrency.processutils [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] CMD "mv /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34 /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del" returned: 0 in 0.005s from (pid=21881) execute /usr/local/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:374
2016-11-15 13:53:00.528 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deleting instance files /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del
2016-11-15 13:53:00.529 INFO nova.virt.libvirt.driver [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] [instance: 1b79133c-5933-4997-8db4-5aa485336c34] Deletion of /opt/stack/data/nova/instances/1b79133c-5933-4997-8db4-5aa485336c34_del complete
2016-11-15 13:53:00.810 ERROR oslo_messaging.rpc.dispatcher [req-e3a2f83c-fbc1-4677-86ea-f9f07416e33a admin admin] Exception during message handling: Remote error: ProcessExecutionError Unexpected error while running command.