2015-09-26 14:51:20.444 DEBUG oslo_concurrency.lockutils [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Lock "compute_resources" acquired by "nova.compute.resource_tracker._update_available_resource" :: waited 0.000s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 14:51:20.561 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Total usable vcpus: 1, total allocated vcpus: 1 2015-09-26 14:51:20.562 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Final resource view: name=devstack1 phys_ram=7984MB used_ram=1024MB phys_disk=4GB used_disk=1GB total_vcpus=1 used_vcpus=1 pci_stats=None 2015-09-26 14:51:20.620 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Compute_service record updated for devstack1:devstack1 2015-09-26 14:51:20.621 DEBUG oslo_concurrency.lockutils [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Lock "compute_resources" released by "nova.compute.resource_tracker._update_available_resource" :: held 0.177s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 14:51:37.369 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._sync_scheduler_instance_info from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:51:42.492 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._instance_usage_audit from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:51:44.390 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._poll_volume_usage from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:51:44.391 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._reclaim_queued_deletes from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:51:44.392 DEBUG nova.compute.manager [req-c72f9452-7591-4d78-b451-23f220e365cd None None] CONF.reclaim_instance_interval <= 0, skipping... from (pid=5984) _reclaim_queued_deletes /home/stack/src/cloud/nova/nova/compute/manager.py:6084 2015-09-26 14:51:47.369 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._check_instance_build_time from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:52:00.165 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:00.274 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.108s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:00.276 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:00.381 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.105s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:00.388 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:00.398 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._poll_unconfirmed_resizes from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:52:00.498 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.110s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:00.499 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:00.607 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.108s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:00.988 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:01.104 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.116s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:01.106 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:01.224 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "env LC_ALL=C LANG=C qemu-img info /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c/disk" returned: 0 in 0.118s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:02.390 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._poll_rescued_instances from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:52:04.102 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Starting monitoring of live migration from (pid=5984) _live_migration /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6050 2015-09-26 14:52:04.102 DEBUG nova.objects.instance [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lazy-loading `flavor' on Instance uuid 3d6a16d5-6678-474e-9710-682473d1d98c from (pid=5984) obj_load_attr /home/stack/src/cloud/nova/nova/objects/instance.py:845 2015-09-26 14:52:04.231 INFO nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Increasing downtime to 46ms after 0 sec elapsed time 2015-09-26 14:52:04.614 INFO nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Migration running for 0 secs, memory 100% remaining; (bytes processed=0, remaining=0, total=0) 2015-09-26 14:52:07.807 DEBUG nova.virt.driver [req-1866fa02-f8a5-48dc-be23-2a9dbadde118 None None] Emitting event Paused> from (pid=5984) emit_event /home/stack/src/cloud/nova/nova/virt/driver.py:1303 2015-09-26 14:52:07.808 INFO nova.compute.manager [req-1866fa02-f8a5-48dc-be23-2a9dbadde118 None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] VM Paused (Lifecycle Event) 2015-09-26 14:52:07.914 DEBUG nova.compute.manager [req-1866fa02-f8a5-48dc-be23-2a9dbadde118 None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Checking state from (pid=5984) _get_power_state /home/stack/src/cloud/nova/nova/compute/manager.py:1328 2015-09-26 14:52:07.920 DEBUG nova.compute.manager [req-1866fa02-f8a5-48dc-be23-2a9dbadde118 None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Synchronizing instance power state after lifecycle event "Paused"; current vm_state: active, current task_state: migrating, current DB power_state: 1, VM power_state: 3 from (pid=5984) handle_lifecycle_event /home/stack/src/cloud/nova/nova/compute/manager.py:1257 2015-09-26 14:52:08.148 DEBUG nova.virt.libvirt.host [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Domain has shutdown/gone away: Requested operation is not valid: domain is not running from (pid=5984) for_domain /home/stack/src/cloud/nova/nova/virt/libvirt/host.py:180 2015-09-26 14:52:08.149 INFO nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Migration operation has completed 2015-09-26 14:52:08.150 INFO nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] _post_live_migration() is started.. 2015-09-26 14:52:08.173 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Migration operation thread has finished from (pid=5984) _live_migration_operation /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:5686 2015-09-26 14:52:08.173 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Migration operation thread notification from (pid=5984) thread_finished /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6041 2015-09-26 14:52:08.223 INFO nova.compute.manager [req-1866fa02-f8a5-48dc-be23-2a9dbadde118 None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] During sync_power_state the instance has a pending task (migrating). Skip. 2015-09-26 14:52:08.244 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf cat /etc/iscsi/initiatorname.iscsi from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:08.392 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._poll_rebooting_instances from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:52:08.460 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf cat /etc/iscsi/initiatorname.iscsi" returned: 0 in 0.217s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:08.461 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:08.603 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v" returned: 1 in 0.142s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:08.605 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] u'sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v' failed. Not Retrying. from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:308 2015-09-26 14:52:08.605 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:08.710 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v" returned: 1 in 0.104s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:08.711 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] u'sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v' failed. Not Retrying. from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:308 2015-09-26 14:52:08.712 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf cat /etc/iscsi/initiatorname.iscsi from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:08.831 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf cat /etc/iscsi/initiatorname.iscsi" returned: 0 in 0.119s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:08.832 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:08.943 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v" returned: 1 in 0.111s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:08.944 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] u'sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v' failed. Not Retrying. from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:308 2015-09-26 14:52:08.945 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:09.054 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v" returned: 1 in 0.109s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:09.055 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] u'sudo nova-rootwrap /etc/nova/rootwrap.conf systool -c fc_host -v' failed. Not Retrying. from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:308 2015-09-26 14:52:09.056 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=5984) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 14:52:09.056 DEBUG nova.network.neutronv2.api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] _get_instance_nw_info() from (pid=5984) _get_instance_nw_info /home/stack/src/cloud/nova/nova/network/neutronv2/api.py:922 2015-09-26 14:52:09.078 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Acquired semaphore "neutron_admin_auth_token_lock" from (pid=5984) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:198 2015-09-26 14:52:09.084 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "neutron_admin_auth_token_lock" from (pid=5984) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 14:52:09.085 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?tenant_id=c392e44c09ce4cc9b3e77e79df76a81f&device_id=3d6a16d5-6678-474e-9710-682473d1d98c -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}7ecc2e35480e36382fe0ec58e0ef69fb3483a2df" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.184 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1006 x-openstack-request-id: req-ab58ed14-af43-4c5b-a20d-e1b94019bb1a RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-3", "ip_address": "10.1.0.3", "fqdn": "host-10-1-0-3.openstacklocal."}], "device_owner": "compute:None", "port_security_enabled": true, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.3"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa"}], "id": "da4ab1e3-be0d-4c24-8a90-d863aa189577", "security_groups": ["81ff7d2b-1c00-4afb-ae1c-a73085b2ba65"], "device_id": "3d6a16d5-6678-474e-9710-682473d1d98c", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:83:44:aa"}]}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.185 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/networks.json?id=c16b9c17-a4c6-41ec-adcc-2800accbb727 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.334 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 454 x-openstack-request-id: req-be40fa01-5e47-4076-9e4d-bd4d61dca388 RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["ef534dcc-7e40-461c-865f-b64199d5a8a0", "288075d8-b675-44d1-a50b-8832986c7d96"], "name": "private", "provider:physical_network": null, "admin_state_up": true, "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mtu": 0, "router:external": false, "shared": false, "port_security_enabled": true, "provider:network_type": "vxlan", "id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "provider:segmentation_id": 1041}]}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.335 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=10.1.0.3&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}7ecc2e35480e36382fe0ec58e0ef69fb3483a2df" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.355 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-f2421499-ee02-4b24-bd0c-8a91166e2eaf RESP BODY: {"floatingips": []}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.356 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/floatingips.json?fixed_ip_address=fdbd%3A4e3b%3Ace09%3A0%3Af816%3A3eff%3Afe83%3A44aa&port_id=da4ab1e3-be0d-4c24-8a90-d863aa189577 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}7ecc2e35480e36382fe0ec58e0ef69fb3483a2df" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.375 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-178c2438-f616-42a9-9864-641f10c8d6fa RESP BODY: {"floatingips": []}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.377 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/subnets.json?id=288075d8-b675-44d1-a50b-8832986c7d96&id=ef534dcc-7e40-461c-865f-b64199d5a8a0 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.426 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 964 x-openstack-request-id: req-b88e6415-4c5d-43dc-bcee-310544d11c0e RESP BODY: {"subnets": [{"name": "private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "10.1.0.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "10.1.0.2", "end": "10.1.0.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "10.1.0.0/24", "id": "288075d8-b675-44d1-a50b-8832986c7d96", "subnetpool_id": null}, {"name": "ipv6-private-subnet", "enable_dhcp": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "dns_nameservers": [], "gateway_ip": "fdbd:4e3b:ce09::1", "ipv6_ra_mode": "slaac", "allocation_pools": [{"start": "fdbd:4e3b:ce09::2", "end": "fdbd:4e3b:ce09:0:ffff:ffff:ffff:ffff"}], "host_routes": [], "ip_version": 6, "ipv6_address_mode": "slaac", "cidr": "fdbd:4e3b:ce09::/64", "id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "subnetpool_id": null}]}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.427 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.563 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-fd058533-f6c3-408d-a1fe-1d84160b650e RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.564 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] REQ: curl -g -i -X GET http://192.169.143.120:9696/v2.0/ports.json?network_id=c16b9c17-a4c6-41ec-adcc-2800accbb727&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}1dfc72f2e3e9d672a27584e71053295433ff0461" from (pid=5984) _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:198 2015-09-26 14:52:09.736 DEBUG keystoneclient.session [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] RESP: [200] date: Sat, 26 Sep 2015 12:52:09 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 1010 x-openstack-request-id: req-30ccd8c2-34b7-402d-a25f-0078b6572b89 RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "devstack1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "dns_assignment": [{"hostname": "host-10-1-0-2", "ip_address": "10.1.0.2", "fqdn": "host-10-1-0-2.openstacklocal."}], "device_owner": "network:dhcp", "port_security_enabled": false, "binding:profile": {}, "fixed_ips": [{"subnet_id": "288075d8-b675-44d1-a50b-8832986c7d96", "ip_address": "10.1.0.2"}, {"subnet_id": "ef534dcc-7e40-461c-865f-b64199d5a8a0", "ip_address": "fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8"}], "id": "22c20e9c-12e9-4b52-9103-fca0e9a47013", "security_groups": [], "device_id": "dhcp6d13ba27-f5a3-57ff-8437-9fbb02a7daef-c16b9c17-a4c6-41ec-adcc-2800accbb727", "name": "", "admin_state_up": true, "network_id": "c16b9c17-a4c6-41ec-adcc-2800accbb727", "dns_name": "", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "tenant_id": "c392e44c09ce4cc9b3e77e79df76a81f", "mac_address": "fa:16:3e:fa:be:c8"}]}  from (pid=5984) _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:215 2015-09-26 14:52:09.738 DEBUG nova.network.base_api [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Updating instance_info_cache with network_info: [VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'10.1.0.3'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'meta': {}, 'version': 6, 'type': 'fixed', 'floating_ips': [], 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None})] from (pid=5984) update_instance_cache_with_nw_info /home/stack/src/cloud/nova/nova/network/base_api.py:43 2015-09-26 14:52:09.765 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Releasing semaphore "refresh_cache-3d6a16d5-6678-474e-9710-682473d1d98c" from (pid=5984) lock /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:211 2015-09-26 14:52:09.768 DEBUG nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Calling driver.unfilter_instance from _post_live_migration from (pid=5984) _post_live_migration /home/stack/src/cloud/nova/nova/compute/manager.py:5171 2015-09-26 14:52:09.769 DEBUG nova.virt.libvirt.vif [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] vif_type=ovs 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='',created_at=2015-09-21T14:30:15Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='vm1',display_name='vm1',ec2_ids=,ephemeral_gb=0,ephemeral_key_uuid=None,fault=,flavor=Flavor(2),host='devstack1',hostname='vm1',id=1,image_ref='8a2538dc-00a2-42bf-9f9e-6747235ea0db',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data='ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQCf2XROOJlSLcFyoGJYecfQGaVa8hSyrnvq4SyVkZ78IpLsgKDp1BoZl3pIHpjaHNPrxbsOaAGno2V/Ux+4JGku9cBrmHtDJ5CzPTE74uffqxayGeM0MYmcJ+Z5cGlQFUxLzYmhSnZtrT9jG+V2lu7HI+ORX6YKQaFlPCWWdTTt0Bty8jgVvAyc9L+isGYcouMWj8/CTWpY0UmIflNhuVeQl7LCG06DdohQtnEjUWrasgY8G8Cz0zIke6OWAzYREN+6L+M++D+9SvPFANdDJ0xV3RXp1FJ9iwNg6YUJrnq5f+nJol3GjwgegbMz6/eaOeiPpm5q0Ldg/wTez3SyBaPX Generated-by-Nova',key_name='oskey1',launch_index=0,launched_at=2015-09-21T14:30:26Z,launched_on='devstack1',locked=False,locked_by=None,memory_mb=512,metadata={},migration_context=,new_flavor=None,node='devstack1',numa_topology=,old_flavor=None,os_type=None,pci_devices=,pci_requests=,power_state=1,progress=0,project_id='c392e44c09ce4cc9b3e77e79df76a81f',ramdisk_id='',reservation_id='r-oi2xpo6i',root_device_name='/dev/vda',root_gb=1,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='2',image_base_image_ref='8a2538dc-00a2-42bf-9f9e-6747235ea0db',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0'},tags=,task_state='migrating',terminated_at=None,updated_at=2015-09-26T12:51:59Z,user_data=None,user_id='0457270a4f9a461b8b3d6599ce31f96b',uuid=3d6a16d5-6678-474e-9710-682473d1d98c,vcpu_model=,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'10.1.0.3', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'10.1.0.2'}, 'dns': [], 'routes': [], 'cidr': u'10.1.0.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'10.1.0.1'})}), Subnet({'ips': [FixedIP({'version': 6, 'vif_mac': u'fa:16:3e:83:44:aa', 'floating_ips': [], 'label': u'private', 'meta': {}, 'address': u'fdbd:4e3b:ce09:0:f816:3eff:fe83:44aa', 'type': 'fixed'})], 'version': 6, 'meta': {'dhcp_server': u'fdbd:4e3b:ce09:0:f816:3eff:fefa:bec8'}, 'dns': [], 'routes': [], 'cidr': u'fdbd:4e3b:ce09::/64', 'gateway': IP({'meta': {}, 'version': 6, 'type': 'gateway', 'address': u'fdbd:4e3b:ce09::1'})})], 'meta': {'injected': False, 'tenant_id': u'c392e44c09ce4cc9b3e77e79df76a81f'}, 'id': u'c16b9c17-a4c6-41ec-adcc-2800accbb727', 'label': u'private'}), 'devname': u'tapda4ab1e3-be', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:83:44:aa', 'active': True, 'type': u'ovs', 'id': u'da4ab1e3-be0d-4c24-8a90-d863aa189577', 'qbg_params': None}) from (pid=5984) unplug /home/stack/src/cloud/nova/nova/virt/libvirt/vif.py:919 2015-09-26 14:52:09.771 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbrda4ab1e3-be qvbda4ab1e3-be from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:09.885 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbrda4ab1e3-be qvbda4ab1e3-be" returned: 0 in 0.114s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:09.886 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbrda4ab1e3-be down from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:09.999 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbrda4ab1e3-be down" returned: 0 in 0.112s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:10.002 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delbr qbrda4ab1e3-be from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:10.137 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delbr qbrda4ab1e3-be" returned: 0 in 0.135s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:10.139 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port br-int qvoda4ab1e3-be from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:10.298 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port br-int qvoda4ab1e3-be" returned: 0 in 0.159s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:10.301 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link delete qvoda4ab1e3-be from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:10.419 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link delete qvoda4ab1e3-be" returned: 0 in 0.119s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:10.420 DEBUG nova.network.linux_net [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Net device removed: 'qvoda4ab1e3-be' from (pid=5984) delete_net_dev /home/stack/src/cloud/nova/nova/network/linux_net.py:1424 2015-09-26 14:52:10.428 DEBUG nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Calling driver.cleanup from _post_live_migration from (pid=5984) _post_live_migration /home/stack/src/cloud/nova/nova/compute/manager.py:5202 2015-09-26 14:52:10.429 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Running cmd (subprocess): mv /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c_del from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:230 2015-09-26 14:52:10.470 DEBUG oslo_concurrency.processutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] CMD "mv /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c_del" returned: 0 in 0.041s from (pid=5984) execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:260 2015-09-26 14:52:10.471 INFO nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Deleting instance files /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c_del 2015-09-26 14:52:10.473 INFO nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Deletion of /home/stack/src/cloud/data/nova/instances/3d6a16d5-6678-474e-9710-682473d1d98c_del complete 2015-09-26 14:52:10.693 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "3d6a16d5-6678-474e-9710-682473d1d98c-events" acquired by "nova.compute.manager._clear_events" :: waited 0.000s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 14:52:10.695 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "3d6a16d5-6678-474e-9710-682473d1d98c-events" released by "nova.compute.manager._clear_events" :: held 0.002s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 14:52:10.737 INFO nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Auditing locally available compute resources for node devstack1 2015-09-26 14:52:10.820 DEBUG nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Hypervisor: free VCPUs: 1 from (pid=5984) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:570 2015-09-26 14:52:10.823 DEBUG nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Hypervisor: assignable PCI devices: [{"dev_id": "pci_0000_00_00_0", "product_id": "1237", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_1237", "address": "0000:00:00.0"}, {"dev_id": "pci_0000_00_01_0", "product_id": "7000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7000", "address": "0000:00:01.0"}, {"dev_id": "pci_0000_00_01_1", "product_id": "7010", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7010", "address": "0000:00:01.1"}, {"dev_id": "pci_0000_00_01_3", "product_id": "7113", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7113", "address": "0000:00:01.3"}, {"dev_id": "pci_0000_00_02_0", "product_id": "1000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1000", "address": "0000:00:02.0"}, {"dev_id": "pci_0000_00_03_0", "product_id": "1003", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1003", "address": "0000:00:03.0"}, {"dev_id": "pci_0000_00_04_0", "product_id": "2934", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2934", "address": "0000:00:04.0"}, {"dev_id": "pci_0000_00_04_1", "product_id": "2935", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2935", "address": "0000:00:04.1"}, {"dev_id": "pci_0000_00_04_2", "product_id": "2936", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2936", "address": "0000:00:04.2"}, {"dev_id": "pci_0000_00_04_7", "product_id": "293a", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_293a", "address": "0000:00:04.7"}, {"dev_id": "pci_0000_00_05_0", "product_id": "1001", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1001", "address": "0000:00:05.0"}, {"dev_id": "pci_0000_00_06_0", "product_id": "1002", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1002", "address": "0000:00:06.0"}] from (pid=5984) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:578 2015-09-26 14:52:10.825 DEBUG nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Hypervisor/Node resource view: name=devstack1 free_ram=5536MB free_disk=0GB free_vcpus=1 pci_devices=[{"dev_id": "pci_0000_00_00_0", "product_id": "1237", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_1237", "address": "0000:00:00.0"}, {"dev_id": "pci_0000_00_01_0", "product_id": "7000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7000", "address": "0000:00:01.0"}, {"dev_id": "pci_0000_00_01_1", "product_id": "7010", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7010", "address": "0000:00:01.1"}, {"dev_id": "pci_0000_00_01_3", "product_id": "7113", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7113", "address": "0000:00:01.3"}, {"dev_id": "pci_0000_00_02_0", "product_id": "1000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1000", "address": "0000:00:02.0"}, {"dev_id": "pci_0000_00_03_0", "product_id": "1003", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1003", "address": "0000:00:03.0"}, {"dev_id": "pci_0000_00_04_0", "product_id": "2934", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2934", "address": "0000:00:04.0"}, {"dev_id": "pci_0000_00_04_1", "product_id": "2935", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2935", "address": "0000:00:04.1"}, {"dev_id": "pci_0000_00_04_2", "product_id": "2936", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2936", "address": "0000:00:04.2"}, {"dev_id": "pci_0000_00_04_7", "product_id": "293a", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_293a", "address": "0000:00:04.7"}, {"dev_id": "pci_0000_00_05_0", "product_id": "1001", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1001", "address": "0000:00:05.0"}, {"dev_id": "pci_0000_00_06_0", "product_id": "1002", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1002", "address": "0000:00:06.0"}] from (pid=5984) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:592 2015-09-26 14:52:10.828 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "compute_resources" acquired by "nova.compute.resource_tracker._update_available_resource" :: waited 0.000s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 14:52:11.012 INFO nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Total usable vcpus: 1, total allocated vcpus: 0 2015-09-26 14:52:11.013 INFO nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Final resource view: name=devstack1 phys_ram=7984MB used_ram=1024MB phys_disk=4GB used_disk=1GB total_vcpus=1 used_vcpus=0 pci_stats=None 2015-09-26 14:52:11.089 INFO nova.compute.resource_tracker [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Compute_service record updated for devstack1:devstack1 2015-09-26 14:52:11.090 DEBUG oslo_concurrency.lockutils [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] Lock "compute_resources" released by "nova.compute.resource_tracker._update_available_resource" :: held 0.262s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 14:52:11.115 INFO nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Migrating instance to devstack2 finished successfully. 2015-09-26 14:52:11.116 INFO nova.compute.manager [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] You may see the error "libvirt: QEMU error: Domain not found: no domain with matching name." This error can be safely ignored. 2015-09-26 14:52:11.163 DEBUG nova.virt.libvirt.driver [req-166192f8-72f2-4967-a4ff-608fd6455917 admin demo] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Live migration monitoring is all done from (pid=5984) _live_migration /home/stack/src/cloud/nova/nova/virt/libvirt/driver.py:6061 2015-09-26 14:52:16.390 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager._heal_instance_info_cache from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:52:16.391 DEBUG nova.compute.manager [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Starting heal instance info cache from (pid=5984) _heal_instance_info_cache /home/stack/src/cloud/nova/nova/compute/manager.py:5412 2015-09-26 14:52:16.391 DEBUG nova.compute.manager [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Rebuilding the list of instances to heal from (pid=5984) _heal_instance_info_cache /home/stack/src/cloud/nova/nova/compute/manager.py:5416 2015-09-26 14:52:16.436 DEBUG nova.compute.manager [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Didn't find any instances for network info cache update. from (pid=5984) _heal_instance_info_cache /home/stack/src/cloud/nova/nova/compute/manager.py:5487 2015-09-26 14:52:20.437 DEBUG oslo_service.periodic_task [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Running periodic task ComputeManager.update_available_resource from (pid=5984) run_periodic_tasks /usr/lib/python2.7/site-packages/oslo_service/periodic_task.py:213 2015-09-26 14:52:20.486 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Auditing locally available compute resources for node devstack1 2015-09-26 14:52:20.549 DEBUG nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Hypervisor: free VCPUs: 1 from (pid=5984) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:570 2015-09-26 14:52:20.550 DEBUG nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Hypervisor: assignable PCI devices: [{"dev_id": "pci_0000_00_00_0", "product_id": "1237", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_1237", "address": "0000:00:00.0"}, {"dev_id": "pci_0000_00_01_0", "product_id": "7000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7000", "address": "0000:00:01.0"}, {"dev_id": "pci_0000_00_01_1", "product_id": "7010", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7010", "address": "0000:00:01.1"}, {"dev_id": "pci_0000_00_01_3", "product_id": "7113", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7113", "address": "0000:00:01.3"}, {"dev_id": "pci_0000_00_02_0", "product_id": "1000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1000", "address": "0000:00:02.0"}, {"dev_id": "pci_0000_00_03_0", "product_id": "1003", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1003", "address": "0000:00:03.0"}, {"dev_id": "pci_0000_00_04_0", "product_id": "2934", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2934", "address": "0000:00:04.0"}, {"dev_id": "pci_0000_00_04_1", "product_id": "2935", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2935", "address": "0000:00:04.1"}, {"dev_id": "pci_0000_00_04_2", "product_id": "2936", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2936", "address": "0000:00:04.2"}, {"dev_id": "pci_0000_00_04_7", "product_id": "293a", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_293a", "address": "0000:00:04.7"}, {"dev_id": "pci_0000_00_05_0", "product_id": "1001", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1001", "address": "0000:00:05.0"}, {"dev_id": "pci_0000_00_06_0", "product_id": "1002", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1002", "address": "0000:00:06.0"}] from (pid=5984) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:578 2015-09-26 14:52:20.551 DEBUG nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Hypervisor/Node resource view: name=devstack1 free_ram=5535MB free_disk=0GB free_vcpus=1 pci_devices=[{"dev_id": "pci_0000_00_00_0", "product_id": "1237", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_1237", "address": "0000:00:00.0"}, {"dev_id": "pci_0000_00_01_0", "product_id": "7000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7000", "address": "0000:00:01.0"}, {"dev_id": "pci_0000_00_01_1", "product_id": "7010", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7010", "address": "0000:00:01.1"}, {"dev_id": "pci_0000_00_01_3", "product_id": "7113", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_7113", "address": "0000:00:01.3"}, {"dev_id": "pci_0000_00_02_0", "product_id": "1000", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1000", "address": "0000:00:02.0"}, {"dev_id": "pci_0000_00_03_0", "product_id": "1003", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1003", "address": "0000:00:03.0"}, {"dev_id": "pci_0000_00_04_0", "product_id": "2934", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2934", "address": "0000:00:04.0"}, {"dev_id": "pci_0000_00_04_1", "product_id": "2935", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2935", "address": "0000:00:04.1"}, {"dev_id": "pci_0000_00_04_2", "product_id": "2936", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_2936", "address": "0000:00:04.2"}, {"dev_id": "pci_0000_00_04_7", "product_id": "293a", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "8086", "label": "label_8086_293a", "address": "0000:00:04.7"}, {"dev_id": "pci_0000_00_05_0", "product_id": "1001", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1001", "address": "0000:00:05.0"}, {"dev_id": "pci_0000_00_06_0", "product_id": "1002", "dev_type": "type-PCI", "numa_node": null, "vendor_id": "1af4", "label": "label_1af4_1002", "address": "0000:00:06.0"}] from (pid=5984) _report_hypervisor_resource_view /home/stack/src/cloud/nova/nova/compute/resource_tracker.py:592 2015-09-26 14:52:20.551 DEBUG oslo_concurrency.lockutils [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Lock "compute_resources" acquired by "nova.compute.resource_tracker._update_available_resource" :: waited 0.000s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:253 2015-09-26 14:52:20.667 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Total usable vcpus: 1, total allocated vcpus: 0 2015-09-26 14:52:20.674 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Final resource view: name=devstack1 phys_ram=7984MB used_ram=512MB phys_disk=4GB used_disk=0GB total_vcpus=1 used_vcpus=0 pci_stats=None 2015-09-26 14:52:20.740 INFO nova.compute.resource_tracker [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Compute_service record updated for devstack1:devstack1 2015-09-26 14:52:20.740 DEBUG oslo_concurrency.lockutils [req-c72f9452-7591-4d78-b451-23f220e365cd None None] Lock "compute_resources" released by "nova.compute.resource_tracker._update_available_resource" :: held 0.189s from (pid=5984) inner /usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py:265 2015-09-26 14:52:23.225 DEBUG nova.virt.driver [-] Emitting event Stopped> from (pid=5984) emit_event /home/stack/src/cloud/nova/nova/virt/driver.py:1303 2015-09-26 14:52:23.226 INFO nova.compute.manager [-] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] VM Stopped (Lifecycle Event) 2015-09-26 14:52:23.314 DEBUG nova.compute.manager [req-926a6c39-8637-4f81-8279-2c108d3e78c2 None None] [instance: 3d6a16d5-6678-474e-9710-682473d1d98c] Checking state from (pid=5984) _get_power_state /home/stack/src/cloud/nova/nova/compute/manager.py:1328