Ask Your Question

Revision history [back]

click to hide/show revision 1
initial version

I am working on Openstack Kilo on ubuntu 14.04 server.Live migration with block migrate is not working.

Error is: Live Migration failure: operation failed: Failed to connect to remote libvirt URI qemu+tcp://compute2/system:authentication failed:No authentication callback available.

I get a success message on horizon (openstack dashboard) but instance doesnt get migrated. Live migration with block migrate was performed on instance at compute1 to be migrated to compute2.

CONFIGURATION FILES:

/etc/nova/nova.conf :

[DEFAULT]
dhcpbridge_flagfile=/etc/nova/nova.conf
dhcpbridge=/usr/bin/nova-dhcpbridge
logdir=/var/log/nova
state_path=/var/lib/nova
lock_path=/var/lock/nova
force_dhcp_release=True
libvirt_use_virtio_for_bridges=True
verbose=True
ec2_private_dns_show_ip=True
api_paste_config=/etc/nova/api-paste.ini
enabled_apis=ec2,osapi_compute,metadata

rpc_backend = rabbit
auth_strategy = keystone
my_ip = 10.0.30.32
vnc_enabled = True
vncserver_listen = 0.0.0.0
vncserver_proxyclient_address = 10.0.30.32
novncproxy_base_url = http://controller:6080/vnc_auto.html

network_api_class = nova.network.neutronv2.api.API
security_group_api = neutron
linuxnet_interface_driver = nova.network.linux_net.LinuxOVSInterfaceDriver
firewall_driver = nova.virt.firewall.NoopFirewallDriver
live_migration_retry_count = 30
#libvirt_type = kvm
#compute_driver = libvirt.LibvirtDriver
#allow_resize_to_same_host=True

debug = True

[keystone_authtoken]
auth_uri = http://controller:5000
auth_url = http://controller:35357
auth_plugin = password
project_domain_id = default
user_domain_id = default
project_name = service
username = nova
password = novauser
[oslo_messaging_rabbit]

rabbit_host = controller
rabbit_userid = openstack
rabbit_password = stackrabbit

[glance]
host = controller

[oslo_concurrency]
lock_path = /var/lib/nova/tmp

[neutron]
url = http://controller:9696
auth_strategy = keystone
admin_auth_url = http://controller:35357/v2.0
admin_tenant_name = service
admin_username = neutron
admin_password = neutronuser
[libvirt]
#added for live migration
live_migration_bandwidth = 0
live_migration_uri = qemu+tcp://%s/system
#connection_uri=qemu+tcp://%s/system
live_migration_flag = VIR_MIGRATE_UNDEFINE_SOURCE,VIR_MIGRATE_PEER2PEER, VIR_MIGRATE_LIVE, VIR_MIGRATE_TUNNELLED
block_migration_flag=VIR_MIGRATE_UNDEFINE_SOURCE,VIR_MIGRATE_PEER2PEER,VIR_MIGRATE_NON_SHARED_INC, VIR_MIGRATE_LIVE
virt_type = kvm

/etc/libvirt/libvirtd.conf :

listen_tls = 0    
listen_tcp = 1    
# auth_tcp="none"

/etc/default/libvirt-bin:

# Defaults for libvirt-bin initscript (/etc/init.d/libvirt-bin)
# This is a POSIX shell fragment

# Start libvirtd to handle qemu/kvm:
start_libvirtd="yes"

# options passed to libvirtd, add "-l" to listen on tcp
#libvirtd_opts="-d"
#libvirtd_opts="-d -l"
libvirtd_opts="-d -l -f /etc/libvirt/libvirtd.conf"

# pass in location of kerberos keytab
#export KRB5_KTNAME=/etc/libvirt/libvirt.keytab

LOG FILES:

/var/log/nova/nova-compute.log [compute1]:

2016-04-21 12:33:45.039 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.090 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.052s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.091 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.142 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.051s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.179 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.232 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.053s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.233 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.284 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.051s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.404 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Starting monitoring of live migration _live_migration /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5710
2016-04-21 12:33:46.407 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Operation thread is still running _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5562
2016-04-21 12:33:46.408 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Migration not running yet _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5593
2016-04-21 12:33:46.412 2150 ERROR nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Live Migration failure: operation failed: Failed to connect to remote libvirt URI qemu+tcp://compute2/system: authentication failed: No authentication callback available
2016-04-21 12:33:46.413 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Migration operation thread notification thread_finished /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5701
2016-04-21 12:33:46.911 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] VM running on src, migration failed _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5568
2016-04-21 12:33:46.912 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Fixed incorrect job type to be 4 _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5588
2016-04-21 12:33:46.913 2150 ERROR nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Migration operation has aborted
2016-04-21 12:33:46.991 2150 DEBUG nova.openstack.common.periodic_task [req-5653375b-94d8-4ba4-adfa-f1627a3b35e7 - - - - -] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/dist-packages/nova/openstack/common/periodic_task.py:219
2016-04-21 12:33:46.993 2150 INFO nova.compute.resource_tracker [req-5653375b-94d8-4ba4-adfa-f1627a3b35e7 - - - - -] Auditing locally available compute resources for node compute1
2016-04-21 12:33:47.003 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Live migration monitoring is all done _live_migration /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5721

/var/log/nova/nova-compute.log [compute2]:

2016-04-21 12:33:44.997 2151 DEBUG nova.objects.instance [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lazy-loading `vcpu_model' on Instance uuid 9091834f-b695-4198-9e9b-1b17c65807fb obj_load_attr /usr/lib/python2.7/dist-packages/nova/objects/instance.py:1015
2016-04-21 12:33:45.008 2151 INFO nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Instance launched has CPU info: {"vendor": "Intel", "model": "Nehalem", "arch": "x86_64", "features": ["pge", "clflush", "sep", "syscall", "tsc-deadline", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "xtpr", "cmov", "ssse3", "est", "pat", "monitor", "pcid", "lm", "msr", "nx", "fxsr", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "vme", "mmx", "osxsave", "cx8", "mce", "de", "rdtscp", "ht", "pse", "lahf_lm", "abm", "popcnt", "mca", "pdpe1gb", "apic", "sse", "ds", "invtsc", "pni", "tm2", "sse2", "ss", "ds_cpl", "pbe", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand"], "topology": {"cores": 2, "threads": 1, "sockets": 1}}
2016-04-21 12:33:45.010 2151 DEBUG nova.virt.libvirt.config [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Generated XML ('<cpu>\n  <arch>x86_64</arch>\n  <model>Nehalem</model>\n  <vendor>Intel</vendor>\n  <topology sockets="1" cores="2" threads="1"/>\n  <feature name="abm"/>\n  <feature name="acpi"/>\n  <feature name="apic"/>\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="fpu"/>\n  <feature name="fsgsbase"/>\n  <feature name="fxsr"/>\n  <feature name="ht"/>\n  <feature name="invpcid"/>\n  <feature name="invtsc"/>\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="sep"/>\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="xsave"/>\n  <feature name="xtpr"/>\n</cpu>\n',)  to_xml /usr/lib/python2.7/dist-packages/nova/virt/libvirt/config.py:82
2016-04-21 12:33:45.012 2151 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Creating tmpfile /var/lib/nova/instances/tmpWuqFRb to notify to other compute nodes that they should mount the same storage. _create_shared_storage_test_file /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5220
2016-04-21 12:33:45.310 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:45.311 2151 DEBUG nova.network.neutronv2.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py:760
2016-04-21 12:33:45.312 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:45.313 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:45.315 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?tenant_id=ea8ed6a98bd948889fa058fa6c29168a&device_id=9091834f-b695-4198-9e9b-1b17c65807fb -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.335 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 735 x-openstack-request-id: req-19b58c18-1b08-4839-8244-27b30bc36c94 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "compute1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:nova", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.22"}], "id": "68541105-dbad-46f2-8cef-04bed53d56d4", "security_groups": ["6b49a431-5423-41b1-affb-ceb36f8615db"], "device_id": "9091834f-b695-4198-9e9b-1b17c65807fb", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:59:20:a0"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.336 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/networks.json?id=ecd2bd85-8d82-41e6-91fd-41238c983468 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.350 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 381 x-openstack-request-id: req-ca93f874-8449-4862-b26a-993eda0cbf26 
RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["22aaba17-129c-4baf-97f1-ecc53c8d4488"], "name": "admin-net", "provider:physical_network": null, "router:external": false, "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "admin_state_up": true, "mtu": 0, "shared": false, "provider:network_type": "gre", "id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "provider:segmentation_id": 25}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.351 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/floatingips.json?fixed_ip_address=172.18.38.22&port_id=68541105-dbad-46f2-8cef-04bed53d56d4 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.358 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-c8c7de10-53c9-40be-be86-b91c857950f1 
RESP BODY: {"floatingips": []}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.359 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/subnets.json?id=22aaba17-129c-4baf-97f1-ecc53c8d4488 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.369 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 467 x-openstack-request-id: req-4db0fad4-3f4f-4379-b9af-d115e2fc44c7 
RESP BODY: {"subnets": [{"name": "admin-subnet", "enable_dhcp": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "dns_nameservers": [], "gateway_ip": "172.18.38.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "172.18.38.2", "end": "172.18.38.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "172.18.38.0/24", "id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "subnetpool_id": null}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.370 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?network_id=ecd2bd85-8d82-41e6-91fd-41238c983468&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.384 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 736 x-openstack-request-id: req-361775de-0da5-45cf-be47-73e6c9beeadf 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "network", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "network:dhcp", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.2"}], "id": "0dd242b2-f870-477c-a3e3-beb483007f72", "security_groups": [], "device_id": "dhcp7b60c1d9-602e-5110-8c89-a9475b89732c-ecd2bd85-8d82-41e6-91fd-41238c983468", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:79:d5:a7"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.385 2151 DEBUG nova.network.base_api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Updating cache with info: [VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'172.18.38.22'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/dist-packages/nova/network/base_api.py:42
2016-04-21 12:33:45.402 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:45.413 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "/var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk.info" acquired by "write_to_disk_info_file" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
2016-04-21 12:33:45.414 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "/var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk.info" released by "write_to_disk_info_file" :: held 0.001s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456
2016-04-21 12:33:45.415 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.469 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" returned: 0 in 0.055s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.471 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired file lock "/var/lib/nova/instances/locks/nova-adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" after waiting 0.000s acquire /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-04-21 12:33:45.471 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" acquired by "copy_qcow2_image" :: waited 0.001s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
2016-04-21 12:33:45.471 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.525 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" returned: 0 in 0.054s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.526 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.695 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.169s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.695 2151 DEBUG nova.virt.disk.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Checking if we can resize image /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk. size=1073741824 can_resize_image /usr/lib/python2.7/dist-packages/nova/virt/disk/api.py:213
2016-04-21 12:33:45.696 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.747 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.051s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.748 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): qemu-img resize /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk 1073741824 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.882 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "qemu-img resize /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk 1073741824" returned: 0 in 0.134s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.882 2151 DEBUG nova.virt.disk.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Checking if we can extend filesystem inside /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk. CoW=True is_image_extendable /usr/lib/python2.7/dist-packages/nova/virt/disk/api.py:227
2016-04-21 12:33:45.882 2151 DEBUG nova.virt.disk.vfs.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Instance for image imgfile=/var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk imgfmt=qcow2 partition=None instance_for_image /usr/lib/python2.7/dist-packages/nova/virt/disk/vfs/api.py:46
2016-04-21 12:33:45.883 2151 DEBUG nova.virt.disk.vfs.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Using primary VFSGuestFS instance_for_image /usr/lib/python2.7/dist-packages/nova/virt/disk/vfs/api.py:50
2016-04-21 12:33:45.934 2151 WARNING nova.virt.disk.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Unable to mount image /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk with error libguestfs installed but not usable (cannot find any suitable libguestfs supermin, fixed or old-style appliance on LIBGUESTFS_PATH (search path: /usr/lib/guestfs)). Cannot resize.
2016-04-21 12:33:45.934 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing file lock "/var/lib/nova/instances/locks/nova-adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" after holding it for 0.463s release /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:227
2016-04-21 12:33:45.934 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" released by "copy_qcow2_image" :: held 0.463s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456
2016-04-21 12:33:45.935 2151 DEBUG nova.virt.libvirt.vif [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=True,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2016-04-06T09:28:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='inst1',display_name='inst1',ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(2),host='compute1',hostname='inst1',id=47,image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data=None,key_name=None,launch_index=0,launched_at=2016-04-06T09:28:07Z,launched_on='compute1',locked=False,locked_by=None,memory_mb=512,metadata={},new_flavor=Flavor(2),node='compute1',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='ea8ed6a98bd948889fa058fa6c29168a',ramdisk_id='',reservation_id='r-qf84fipq',root_device_name='/dev/vda',root_gb=1,scheduled_at=None,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='11',image_base_image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0',old_vm_state='active'},tags=<?>,task_state='migrating',terminated_at=None,updated_at=2016-04-21T07:03:44Z,user_data=None,user_id='3874aa8ef1a0488c85d269ced5cf6fd3',uuid=9091834f-b695-4198-9e9b-1b17c65807fb,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:59:20:a0', 'floating_ips': [], 'label': u'admin-net', 'meta': {}, 'address': u'172.18.38.22', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None}) plug /usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py:597
2016-04-21 12:33:45.936 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr qbr68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.973 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr qbr68541105-db" returned: 0 in 0.037s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.974 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd qbr68541105-db 0 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.015 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd qbr68541105-db 0" returned: 0 in 0.041s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.016 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp qbr68541105-db off execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.052 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp qbr68541105-db off" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.053 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/qbr68541105-db/bridge/multicast_snooping execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.088 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/qbr68541105-db/bridge/multicast_snooping" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.089 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link add qvb68541105-db type veth peer name qvo68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.127 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link add qvb68541105-db type veth peer name qvo68541105-db" returned: 0 in 0.038s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.127 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db up execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.174 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db up" returned: 0 in 0.046s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.175 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db promisc on execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.211 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db promisc on" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.211 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db up execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.247 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db up" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.248 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db promisc on execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.284 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db promisc on" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.285 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db up execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.320 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db up" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.321 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif qbr68541105-db qvb68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.358 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif qbr68541105-db qvb68541105-db" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.358 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvo68541105-db -- add-port br-int qvo68541105-db -- set Interface qvo68541105-db external-ids:iface-id=68541105-dbad-46f2-8cef-04bed53d56d4 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:59:20:a0 external-ids:vm-uuid=9091834f-b695-4198-9e9b-1b17c65807fb execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.397 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvo68541105-db -- add-port br-int qvo68541105-db -- set Interface qvo68541105-db external-ids:iface-id=68541105-dbad-46f2-8cef-04bed53d56d4 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:59:20:a0 external-ids:vm-uuid=9091834f-b695-4198-9e9b-1b17c65807fb" returned: 0 in 0.039s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.012 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:47.013 2151 DEBUG nova.network.neutronv2.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py:760
2016-04-21 12:33:47.014 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:47.015 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:47.017 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?tenant_id=ea8ed6a98bd948889fa058fa6c29168a&device_id=9091834f-b695-4198-9e9b-1b17c65807fb -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.035 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 735 x-openstack-request-id: req-ccb69753-d3ad-450e-a202-3f96c0747285 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "compute1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:nova", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.22"}], "id": "68541105-dbad-46f2-8cef-04bed53d56d4", "security_groups": ["6b49a431-5423-41b1-affb-ceb36f8615db"], "device_id": "9091834f-b695-4198-9e9b-1b17c65807fb", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:59:20:a0"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.036 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/networks.json?id=ecd2bd85-8d82-41e6-91fd-41238c983468 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.050 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 381 x-openstack-request-id: req-be74f031-0f1b-44d7-9042-48e13c0c2797 
RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["22aaba17-129c-4baf-97f1-ecc53c8d4488"], "name": "admin-net", "provider:physical_network": null, "router:external": false, "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "admin_state_up": true, "mtu": 0, "shared": false, "provider:network_type": "gre", "id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "provider:segmentation_id": 25}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.051 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/floatingips.json?fixed_ip_address=172.18.38.22&port_id=68541105-dbad-46f2-8cef-04bed53d56d4 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.058 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-eecea6cd-b76b-45a9-bcca-1f1ccd841d35 
RESP BODY: {"floatingips": []}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.059 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/subnets.json?id=22aaba17-129c-4baf-97f1-ecc53c8d4488 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.068 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 467 x-openstack-request-id: req-bb498117-e64b-4120-9bcc-58b39d39f7a1 
RESP BODY: {"subnets": [{"name": "admin-subnet", "enable_dhcp": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "dns_nameservers": [], "gateway_ip": "172.18.38.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "172.18.38.2", "end": "172.18.38.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "172.18.38.0/24", "id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "subnetpool_id": null}]}
_http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.070 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?network_id=ecd2bd85-8d82-41e6-91fd-41238c983468&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.083 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 736 x-openstack-request-id: req-6ad867c9-c24d-47f2-94ad-bfcc39ea94a1 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "network", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "network:dhcp", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.2"}], "id": "0dd242b2-f870-477c-a3e3-beb483007f72", "security_groups": [], "device_id": "dhcp7b60c1d9-602e-5110-8c89-a9475b89732c-ecd2bd85-8d82-41e6-91fd-41238c983468", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:79:d5:a7"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.084 2151 DEBUG nova.network.base_api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Updating cache with info: [VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'172.18.38.22'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/dist-packages/nova/network/base_api.py:42
2016-04-21 12:33:47.094 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:47.107 2151 INFO nova.virt.libvirt.driver [-] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] During wait destroy, instance disappeared.
2016-04-21 12:33:47.108 2151 DEBUG nova.virt.libvirt.vif [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=True,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2016-04-06T09:28:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='inst1',display_name='inst1',ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(2),host='compute1',hostname='inst1',id=47,image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data=None,key_name=None,launch_index=0,launched_at=2016-04-06T09:28:07Z,launched_on='compute1',locked=False,locked_by=None,memory_mb=512,metadata={},new_flavor=Flavor(2),node='compute1',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='ea8ed6a98bd948889fa058fa6c29168a',ramdisk_id='',reservation_id='r-qf84fipq',root_device_name='/dev/vda',root_gb=1,scheduled_at=None,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='11',image_base_image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0',old_vm_state='active'},tags=<?>,task_state=None,terminated_at=None,updated_at=2016-04-21T07:03:46Z,user_data=None,user_id='3874aa8ef1a0488c85d269ced5cf6fd3',uuid=9091834f-b695-4198-9e9b-1b17c65807fb,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:59:20:a0', 'floating_ips': [], 'label': u'admin-net', 'meta': {}, 'address': u'172.18.38.22', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None}) unplug /usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py:774
2016-04-21 12:33:47.110 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr68541105-db qvb68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.167 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr68541105-db qvb68541105-db" returned: 0 in 0.057s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.168 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db down execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.215 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db down" returned: 0 in 0.047s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.216 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delbr qbr68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.275 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delbr qbr68541105-db" returned: 0 in 0.060s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.276 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port br-int qvo68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.315 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port br-int qvo68541105-db" returned: 0 in 0.039s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.315 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link delete qvo68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.375 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link delete qvo68541105-db" returned: 0 in 0.060s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.376 2151 DEBUG nova.network.linux_net [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Net device removed: 'qvo68541105-db' delete_net_dev /usr/lib/python2.7/dist-packages/nova/network/linux_net.py:1422
2016-04-21 12:33:47.376 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): mv /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.382 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "mv /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del" returned: 0 in 0.006s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.383 2151 INFO nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Deleting instance files /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del
2016-04-21 12:33:47.383 2151 INFO nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Deletion of /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del complete

/var/log/libvirt/libvirtd.log (compute1):

2016-04-21 07:03:07.662+0000: 9539: info : libvirt version: 1.2.12, package: 1.2.12-0ubuntu14.2~cloud0
2016-04-21 07:03:07.662+0000: 9539: warning : processNicRxFilterChangedEvent:4221 : ignore NIC_RX_FILTER_CHANGED event for network device net0 in domain instance-0000002f
2016-04-21 07:03:46.411+0000: 1924: error : remoteAuthInteract:4276 : authentication failed: No authentication callback available
2016-04-21 07:03:46.411+0000: 1924: error : doPeer2PeerMigrate:4698 : operation failed: Failed to connect to remote libvirt URI qemu+tcp://compute2/system:authentication failed: No authentication callback available

/var/log/libvirt/libvirtd.log (compute2):

2016-04-21 07:03:13.255+0000: 9465: info : libvirt version: 1.2.12, package: 1.2.12-0ubuntu14.2~cloud0
2016-04-21 07:03:13.255+0000: 9465: warning : processNicRxFilterChangedEvent:4221 : ignore NIC_RX_FILTER_CHANGED event for network device net0 in domain instance-0000002d
2016-04-21 07:03:46.426+0000: 1913: error : virNetSocketReadWire:1579 : End of file while reading data: Input/output error

I am new at this and any help will be really appreciated.

Thanks.

Neha.

I am working on Openstack Kilo on ubuntu 14.04 server.Live migration with block migrate is not working.

Working on Openstack Kilo on ubuntu server 14.04. Facing an issue in live migration using block migrate.

Error is: Live Migration failure: operation failed: Failed to connect to remote libvirt URI qemu+tcp://compute2/system:authentication failed:No authentication callback available.

I get a success message on horizon (openstack dashboard) but instance doesnt get migrated. Live migration with block migrate was performed on instance at compute1 to be migrated to compute2.

CONFIGURATION FILES:

/etc/nova/nova.conf :

[DEFAULT]
dhcpbridge_flagfile=/etc/nova/nova.conf
dhcpbridge=/usr/bin/nova-dhcpbridge
logdir=/var/log/nova
state_path=/var/lib/nova
lock_path=/var/lock/nova
force_dhcp_release=True
libvirt_use_virtio_for_bridges=True
verbose=True
ec2_private_dns_show_ip=True
api_paste_config=/etc/nova/api-paste.ini
enabled_apis=ec2,osapi_compute,metadata

rpc_backend = rabbit
auth_strategy = keystone
my_ip = 10.0.30.32
vnc_enabled = True
vncserver_listen = 0.0.0.0
vncserver_proxyclient_address = 10.0.30.32
novncproxy_base_url = http://controller:6080/vnc_auto.html

network_api_class = nova.network.neutronv2.api.API
security_group_api = neutron
linuxnet_interface_driver = nova.network.linux_net.LinuxOVSInterfaceDriver
firewall_driver = nova.virt.firewall.NoopFirewallDriver
live_migration_retry_count = 30
#libvirt_type = kvm
#compute_driver = libvirt.LibvirtDriver
#allow_resize_to_same_host=True

debug = True

[keystone_authtoken]
auth_uri = http://controller:5000
auth_url = http://controller:35357
auth_plugin = password
project_domain_id = default
user_domain_id = default
project_name = service
username = nova
password = novauser
[oslo_messaging_rabbit]

rabbit_host = controller
rabbit_userid = openstack
rabbit_password = stackrabbit

[glance]
host = controller

[oslo_concurrency]
lock_path = /var/lib/nova/tmp

[neutron]
url = http://controller:9696
auth_strategy = keystone
admin_auth_url = http://controller:35357/v2.0
admin_tenant_name = service
admin_username = neutron
admin_password = neutronuser
[libvirt]
#added for live migration
live_migration_bandwidth = 0
live_migration_uri = qemu+tcp://%s/system
#connection_uri=qemu+tcp://%s/system
live_migration_flag = VIR_MIGRATE_UNDEFINE_SOURCE,VIR_MIGRATE_PEER2PEER, VIR_MIGRATE_LIVE, VIR_MIGRATE_TUNNELLED
block_migration_flag=VIR_MIGRATE_UNDEFINE_SOURCE,VIR_MIGRATE_PEER2PEER,VIR_MIGRATE_NON_SHARED_INC, VIR_MIGRATE_LIVE
virt_type = kvm

/etc/libvirt/libvirtd.conf :

listen_tls = 0    
listen_tcp = 1    
# auth_tcp="none"

/etc/default/libvirt-bin:

# Defaults for libvirt-bin initscript (/etc/init.d/libvirt-bin)
# This is a POSIX shell fragment

# Start libvirtd to handle qemu/kvm:
start_libvirtd="yes"

# options passed to libvirtd, add "-l" to listen on tcp
#libvirtd_opts="-d"
#libvirtd_opts="-d -l"
libvirtd_opts="-d -l -f /etc/libvirt/libvirtd.conf"

# pass in location of kerberos keytab
#export KRB5_KTNAME=/etc/libvirt/libvirt.keytab

LOG FILES:

/var/log/nova/nova-compute.log [compute1]:

2016-04-21 12:33:45.039 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.090 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.052s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.091 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.142 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.051s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.179 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.232 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.053s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.233 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.284 2150 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.051s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.404 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Starting monitoring of live migration _live_migration /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5710
2016-04-21 12:33:46.407 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Operation thread is still running _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5562
2016-04-21 12:33:46.408 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Migration not running yet _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5593
2016-04-21 12:33:46.412 2150 ERROR nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Live Migration failure: operation failed: Failed to connect to remote libvirt URI qemu+tcp://compute2/system: authentication failed: No authentication callback available
2016-04-21 12:33:46.413 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Migration operation thread notification thread_finished /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5701
2016-04-21 12:33:46.911 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] VM running on src, migration failed _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5568
2016-04-21 12:33:46.912 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Fixed incorrect job type to be 4 _live_migration_monitor /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5588
2016-04-21 12:33:46.913 2150 ERROR nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Migration operation has aborted
2016-04-21 12:33:46.991 2150 DEBUG nova.openstack.common.periodic_task [req-5653375b-94d8-4ba4-adfa-f1627a3b35e7 - - - - -] Running periodic task ComputeManager.update_available_resource run_periodic_tasks /usr/lib/python2.7/dist-packages/nova/openstack/common/periodic_task.py:219
2016-04-21 12:33:46.993 2150 INFO nova.compute.resource_tracker [req-5653375b-94d8-4ba4-adfa-f1627a3b35e7 - - - - -] Auditing locally available compute resources for node compute1
2016-04-21 12:33:47.003 2150 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Live migration monitoring is all done _live_migration /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5721

/var/log/nova/nova-compute.log [compute2]:

2016-04-21 12:33:44.997 2151 DEBUG nova.objects.instance [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lazy-loading `vcpu_model' on Instance uuid 9091834f-b695-4198-9e9b-1b17c65807fb obj_load_attr /usr/lib/python2.7/dist-packages/nova/objects/instance.py:1015
2016-04-21 12:33:45.008 2151 INFO nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Instance launched has CPU info: {"vendor": "Intel", "model": "Nehalem", "arch": "x86_64", "features": ["pge", "clflush", "sep", "syscall", "tsc-deadline", "dtes64", "invpcid", "tsc", "fsgsbase", "xsave", "vmx", "erms", "xtpr", "cmov", "ssse3", "est", "pat", "monitor", "pcid", "lm", "msr", "nx", "fxsr", "tm", "sse4.1", "pae", "sse4.2", "pclmuldq", "acpi", "vme", "mmx", "osxsave", "cx8", "mce", "de", "rdtscp", "ht", "pse", "lahf_lm", "abm", "popcnt", "mca", "pdpe1gb", "apic", "sse", "ds", "invtsc", "pni", "tm2", "sse2", "ss", "ds_cpl", "pbe", "fpu", "cx16", "pse36", "mtrr", "movbe", "pdcm", "rdrand"], "topology": {"cores": 2, "threads": 1, "sockets": 1}}
2016-04-21 12:33:45.010 2151 DEBUG nova.virt.libvirt.config [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Generated XML ('<cpu>\n  <arch>x86_64</arch>\n  <model>Nehalem</model>\n  <vendor>Intel</vendor>\n  <topology sockets="1" cores="2" threads="1"/>\n  <feature name="abm"/>\n  <feature name="acpi"/>\n  <feature name="apic"/>\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="fpu"/>\n  <feature name="fsgsbase"/>\n  <feature name="fxsr"/>\n  <feature name="ht"/>\n  <feature name="invpcid"/>\n  <feature name="invtsc"/>\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="sep"/>\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="xsave"/>\n  <feature name="xtpr"/>\n</cpu>\n',)  to_xml /usr/lib/python2.7/dist-packages/nova/virt/libvirt/config.py:82
2016-04-21 12:33:45.012 2151 DEBUG nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Creating tmpfile /var/lib/nova/instances/tmpWuqFRb to notify to other compute nodes that they should mount the same storage. _create_shared_storage_test_file /usr/lib/python2.7/dist-packages/nova/virt/libvirt/driver.py:5220
2016-04-21 12:33:45.310 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:45.311 2151 DEBUG nova.network.neutronv2.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py:760
2016-04-21 12:33:45.312 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:45.313 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:45.315 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?tenant_id=ea8ed6a98bd948889fa058fa6c29168a&device_id=9091834f-b695-4198-9e9b-1b17c65807fb -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.335 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 735 x-openstack-request-id: req-19b58c18-1b08-4839-8244-27b30bc36c94 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "compute1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:nova", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.22"}], "id": "68541105-dbad-46f2-8cef-04bed53d56d4", "security_groups": ["6b49a431-5423-41b1-affb-ceb36f8615db"], "device_id": "9091834f-b695-4198-9e9b-1b17c65807fb", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:59:20:a0"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.336 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/networks.json?id=ecd2bd85-8d82-41e6-91fd-41238c983468 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.350 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 381 x-openstack-request-id: req-ca93f874-8449-4862-b26a-993eda0cbf26 
RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["22aaba17-129c-4baf-97f1-ecc53c8d4488"], "name": "admin-net", "provider:physical_network": null, "router:external": false, "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "admin_state_up": true, "mtu": 0, "shared": false, "provider:network_type": "gre", "id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "provider:segmentation_id": 25}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.351 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/floatingips.json?fixed_ip_address=172.18.38.22&port_id=68541105-dbad-46f2-8cef-04bed53d56d4 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.358 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-c8c7de10-53c9-40be-be86-b91c857950f1 
RESP BODY: {"floatingips": []}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.359 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/subnets.json?id=22aaba17-129c-4baf-97f1-ecc53c8d4488 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.369 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 467 x-openstack-request-id: req-4db0fad4-3f4f-4379-b9af-d115e2fc44c7 
RESP BODY: {"subnets": [{"name": "admin-subnet", "enable_dhcp": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "dns_nameservers": [], "gateway_ip": "172.18.38.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "172.18.38.2", "end": "172.18.38.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "172.18.38.0/24", "id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "subnetpool_id": null}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.370 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?network_id=ecd2bd85-8d82-41e6-91fd-41238c983468&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:45.384 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:45 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 736 x-openstack-request-id: req-361775de-0da5-45cf-be47-73e6c9beeadf 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "network", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "network:dhcp", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.2"}], "id": "0dd242b2-f870-477c-a3e3-beb483007f72", "security_groups": [], "device_id": "dhcp7b60c1d9-602e-5110-8c89-a9475b89732c-ecd2bd85-8d82-41e6-91fd-41238c983468", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:79:d5:a7"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:45.385 2151 DEBUG nova.network.base_api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Updating cache with info: [VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'172.18.38.22'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/dist-packages/nova/network/base_api.py:42
2016-04-21 12:33:45.402 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:45.413 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "/var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk.info" acquired by "write_to_disk_info_file" :: waited 0.000s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
2016-04-21 12:33:45.414 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "/var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk.info" released by "write_to_disk_info_file" :: held 0.001s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456
2016-04-21 12:33:45.415 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.469 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" returned: 0 in 0.055s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.471 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired file lock "/var/lib/nova/instances/locks/nova-adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" after waiting 0.000s acquire /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:212
2016-04-21 12:33:45.471 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" acquired by "copy_qcow2_image" :: waited 0.001s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:444
2016-04-21 12:33:45.471 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.525 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" returned: 0 in 0.054s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.526 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.695 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "qemu-img create -f qcow2 -o backing_file=/var/lib/nova/instances/_base/adbed3a236f173d8ca9ca4f60ca6d0a5d9758005 /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.169s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.695 2151 DEBUG nova.virt.disk.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Checking if we can resize image /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk. size=1073741824 can_resize_image /usr/lib/python2.7/dist-packages/nova/virt/disk/api.py:213
2016-04-21 12:33:45.696 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.747 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "env LC_ALL=C LANG=C qemu-img info /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk" returned: 0 in 0.051s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.748 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): qemu-img resize /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk 1073741824 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.882 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "qemu-img resize /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk 1073741824" returned: 0 in 0.134s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.882 2151 DEBUG nova.virt.disk.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Checking if we can extend filesystem inside /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk. CoW=True is_image_extendable /usr/lib/python2.7/dist-packages/nova/virt/disk/api.py:227
2016-04-21 12:33:45.882 2151 DEBUG nova.virt.disk.vfs.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Instance for image imgfile=/var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk imgfmt=qcow2 partition=None instance_for_image /usr/lib/python2.7/dist-packages/nova/virt/disk/vfs/api.py:46
2016-04-21 12:33:45.883 2151 DEBUG nova.virt.disk.vfs.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Using primary VFSGuestFS instance_for_image /usr/lib/python2.7/dist-packages/nova/virt/disk/vfs/api.py:50
2016-04-21 12:33:45.934 2151 WARNING nova.virt.disk.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Unable to mount image /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb/disk with error libguestfs installed but not usable (cannot find any suitable libguestfs supermin, fixed or old-style appliance on LIBGUESTFS_PATH (search path: /usr/lib/guestfs)). Cannot resize.
2016-04-21 12:33:45.934 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing file lock "/var/lib/nova/instances/locks/nova-adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" after holding it for 0.463s release /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:227
2016-04-21 12:33:45.934 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Lock "adbed3a236f173d8ca9ca4f60ca6d0a5d9758005" released by "copy_qcow2_image" :: held 0.463s inner /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:456
2016-04-21 12:33:45.935 2151 DEBUG nova.virt.libvirt.vif [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=True,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2016-04-06T09:28:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='inst1',display_name='inst1',ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(2),host='compute1',hostname='inst1',id=47,image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data=None,key_name=None,launch_index=0,launched_at=2016-04-06T09:28:07Z,launched_on='compute1',locked=False,locked_by=None,memory_mb=512,metadata={},new_flavor=Flavor(2),node='compute1',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='ea8ed6a98bd948889fa058fa6c29168a',ramdisk_id='',reservation_id='r-qf84fipq',root_device_name='/dev/vda',root_gb=1,scheduled_at=None,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='11',image_base_image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0',old_vm_state='active'},tags=<?>,task_state='migrating',terminated_at=None,updated_at=2016-04-21T07:03:44Z,user_data=None,user_id='3874aa8ef1a0488c85d269ced5cf6fd3',uuid=9091834f-b695-4198-9e9b-1b17c65807fb,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:59:20:a0', 'floating_ips': [], 'label': u'admin-net', 'meta': {}, 'address': u'172.18.38.22', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None}) plug /usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py:597
2016-04-21 12:33:45.936 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr qbr68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:45.973 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addbr qbr68541105-db" returned: 0 in 0.037s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:45.974 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd qbr68541105-db 0 execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.015 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl setfd qbr68541105-db 0" returned: 0 in 0.041s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.016 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp qbr68541105-db off execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.052 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl stp qbr68541105-db off" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.053 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/qbr68541105-db/bridge/multicast_snooping execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.088 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf tee /sys/class/net/qbr68541105-db/bridge/multicast_snooping" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.089 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link add qvb68541105-db type veth peer name qvo68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.127 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link add qvb68541105-db type veth peer name qvo68541105-db" returned: 0 in 0.038s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.127 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db up execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.174 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db up" returned: 0 in 0.046s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.175 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db promisc on execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.211 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvb68541105-db promisc on" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.211 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db up execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.247 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db up" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.248 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db promisc on execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.284 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qvo68541105-db promisc on" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.285 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db up execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.320 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db up" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.321 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif qbr68541105-db qvb68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.358 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl addif qbr68541105-db qvb68541105-db" returned: 0 in 0.036s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:46.358 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvo68541105-db -- add-port br-int qvo68541105-db -- set Interface qvo68541105-db external-ids:iface-id=68541105-dbad-46f2-8cef-04bed53d56d4 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:59:20:a0 external-ids:vm-uuid=9091834f-b695-4198-9e9b-1b17c65807fb execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:46.397 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port qvo68541105-db -- add-port br-int qvo68541105-db -- set Interface qvo68541105-db external-ids:iface-id=68541105-dbad-46f2-8cef-04bed53d56d4 external-ids:iface-status=active external-ids:attached-mac=fa:16:3e:59:20:a0 external-ids:vm-uuid=9091834f-b695-4198-9e9b-1b17c65807fb" returned: 0 in 0.039s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.012 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:47.013 2151 DEBUG nova.network.neutronv2.api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] _get_instance_nw_info() _get_instance_nw_info /usr/lib/python2.7/dist-packages/nova/network/neutronv2/api.py:760
2016-04-21 12:33:47.014 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Acquired semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:391
2016-04-21 12:33:47.015 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "neutron_admin_auth_token_lock" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:47.017 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?tenant_id=ea8ed6a98bd948889fa058fa6c29168a&device_id=9091834f-b695-4198-9e9b-1b17c65807fb -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.035 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 735 x-openstack-request-id: req-ccb69753-d3ad-450e-a202-3f96c0747285 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "compute1", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "compute:nova", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.22"}], "id": "68541105-dbad-46f2-8cef-04bed53d56d4", "security_groups": ["6b49a431-5423-41b1-affb-ceb36f8615db"], "device_id": "9091834f-b695-4198-9e9b-1b17c65807fb", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:59:20:a0"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.036 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/networks.json?id=ecd2bd85-8d82-41e6-91fd-41238c983468 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.050 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 381 x-openstack-request-id: req-be74f031-0f1b-44d7-9042-48e13c0c2797 
RESP BODY: {"networks": [{"status": "ACTIVE", "subnets": ["22aaba17-129c-4baf-97f1-ecc53c8d4488"], "name": "admin-net", "provider:physical_network": null, "router:external": false, "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "admin_state_up": true, "mtu": 0, "shared": false, "provider:network_type": "gre", "id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "provider:segmentation_id": 25}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.051 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/floatingips.json?fixed_ip_address=172.18.38.22&port_id=68541105-dbad-46f2-8cef-04bed53d56d4 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}dec9dc94e29f084539b0439a713601a3b485cee3" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.058 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 19 x-openstack-request-id: req-eecea6cd-b76b-45a9-bcca-1f1ccd841d35 
RESP BODY: {"floatingips": []}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.059 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/subnets.json?id=22aaba17-129c-4baf-97f1-ecc53c8d4488 -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.068 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 467 x-openstack-request-id: req-bb498117-e64b-4120-9bcc-58b39d39f7a1 
RESP BODY: {"subnets": [{"name": "admin-subnet", "enable_dhcp": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "dns_nameservers": [], "gateway_ip": "172.18.38.1", "ipv6_ra_mode": null, "allocation_pools": [{"start": "172.18.38.2", "end": "172.18.38.254"}], "host_routes": [], "ip_version": 4, "ipv6_address_mode": null, "cidr": "172.18.38.0/24", "id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "subnetpool_id": null}]}
_http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.070 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] REQ: curl -g -i -X GET http://controller:9696/v2.0/ports.json?network_id=ecd2bd85-8d82-41e6-91fd-41238c983468&device_owner=network%3Adhcp -H "User-Agent: python-neutronclient" -H "Accept: application/json" -H "X-Auth-Token: {SHA1}d4db7e07da19fb85212b7ddf8d28ed5e81857aee" _http_log_request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:195
2016-04-21 12:33:47.083 2151 DEBUG keystoneclient.session [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] RESP: [200] date: Thu, 21 Apr 2016 07:03:47 GMT connection: keep-alive content-type: application/json; charset=UTF-8 content-length: 736 x-openstack-request-id: req-6ad867c9-c24d-47f2-94ad-bfcc39ea94a1 
RESP BODY: {"ports": [{"status": "ACTIVE", "binding:host_id": "network", "allowed_address_pairs": [], "extra_dhcp_opts": [], "device_owner": "network:dhcp", "binding:profile": {}, "fixed_ips": [{"subnet_id": "22aaba17-129c-4baf-97f1-ecc53c8d4488", "ip_address": "172.18.38.2"}], "id": "0dd242b2-f870-477c-a3e3-beb483007f72", "security_groups": [], "device_id": "dhcp7b60c1d9-602e-5110-8c89-a9475b89732c-ecd2bd85-8d82-41e6-91fd-41238c983468", "name": "", "admin_state_up": true, "network_id": "ecd2bd85-8d82-41e6-91fd-41238c983468", "tenant_id": "ea8ed6a98bd948889fa058fa6c29168a", "binding:vif_details": {"port_filter": true, "ovs_hybrid_plug": true}, "binding:vnic_type": "normal", "binding:vif_type": "ovs", "mac_address": "fa:16:3e:79:d5:a7"}]}
 _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:223
2016-04-21 12:33:47.084 2151 DEBUG nova.network.base_api [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Updating cache with info: [VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed', 'floating_ips': [], 'address': u'172.18.38.22'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None})] update_instance_cache_with_nw_info /usr/lib/python2.7/dist-packages/nova/network/base_api.py:42
2016-04-21 12:33:47.094 2151 DEBUG oslo_concurrency.lockutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Releasing semaphore "refresh_cache-9091834f-b695-4198-9e9b-1b17c65807fb" lock /usr/lib/python2.7/dist-packages/oslo_concurrency/lockutils.py:404
2016-04-21 12:33:47.107 2151 INFO nova.virt.libvirt.driver [-] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] During wait destroy, instance disappeared.
2016-04-21 12:33:47.108 2151 DEBUG nova.virt.libvirt.vif [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] vif_type=ovs instance=Instance(access_ip_v4=None,access_ip_v6=None,architecture=None,auto_disk_config=True,availability_zone='nova',cell_name=None,cleaned=True,config_drive='',created_at=2016-04-06T09:28:02Z,default_ephemeral_device=None,default_swap_device=None,deleted=False,deleted_at=None,disable_terminate=False,display_description='inst1',display_name='inst1',ephemeral_gb=0,ephemeral_key_uuid=None,fault=<?>,flavor=Flavor(2),host='compute1',hostname='inst1',id=47,image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',info_cache=InstanceInfoCache,instance_type_id=2,kernel_id='',key_data=None,key_name=None,launch_index=0,launched_at=2016-04-06T09:28:07Z,launched_on='compute1',locked=False,locked_by=None,memory_mb=512,metadata={},new_flavor=Flavor(2),node='compute1',numa_topology=<?>,old_flavor=None,os_type=None,pci_devices=<?>,pci_requests=<?>,power_state=1,progress=0,project_id='ea8ed6a98bd948889fa058fa6c29168a',ramdisk_id='',reservation_id='r-qf84fipq',root_device_name='/dev/vda',root_gb=1,scheduled_at=None,security_groups=SecurityGroupList,shutdown_terminate=False,system_metadata={clean_attempts='11',image_base_image_ref='371ebe10-428b-4b4a-bd6f-58f8971d129e',image_container_format='bare',image_disk_format='qcow2',image_min_disk='1',image_min_ram='0',old_vm_state='active'},tags=<?>,task_state=None,terminated_at=None,updated_at=2016-04-21T07:03:46Z,user_data=None,user_id='3874aa8ef1a0488c85d269ced5cf6fd3',uuid=9091834f-b695-4198-9e9b-1b17c65807fb,vcpu_model=<?>,vcpus=1,vm_mode=None,vm_state='active') vif=VIF({'profile': {}, 'ovs_interfaceid': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets': [Subnet({'ips': [FixedIP({'version': 4, 'vif_mac': u'fa:16:3e:59:20:a0', 'floating_ips': [], 'label': u'admin-net', 'meta': {}, 'address': u'172.18.38.22', 'type': 'fixed'})], 'version': 4, 'meta': {'dhcp_server': u'172.18.38.2'}, 'dns': [], 'routes': [], 'cidr': u'172.18.38.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway', 'address': u'172.18.38.1'})})], 'meta': {'injected': False, 'tenant_id': u'ea8ed6a98bd948889fa058fa6c29168a'}, 'id': u'ecd2bd85-8d82-41e6-91fd-41238c983468', 'label': u'admin-net'}), 'devname': u'tap68541105-db', 'vnic_type': u'normal', 'qbh_params': None, 'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address': u'fa:16:3e:59:20:a0', 'active': True, 'type': u'ovs', 'id': u'68541105-dbad-46f2-8cef-04bed53d56d4', 'qbg_params': None}) unplug /usr/lib/python2.7/dist-packages/nova/virt/libvirt/vif.py:774
2016-04-21 12:33:47.110 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr68541105-db qvb68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.167 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delif qbr68541105-db qvb68541105-db" returned: 0 in 0.057s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.168 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db down execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.215 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link set qbr68541105-db down" returned: 0 in 0.047s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.216 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delbr qbr68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.275 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf brctl delbr qbr68541105-db" returned: 0 in 0.060s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.276 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port br-int qvo68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.315 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ovs-vsctl --timeout=120 -- --if-exists del-port br-int qvo68541105-db" returned: 0 in 0.039s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.315 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): sudo nova-rootwrap /etc/nova/rootwrap.conf ip link delete qvo68541105-db execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.375 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "sudo nova-rootwrap /etc/nova/rootwrap.conf ip link delete qvo68541105-db" returned: 0 in 0.060s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.376 2151 DEBUG nova.network.linux_net [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Net device removed: 'qvo68541105-db' delete_net_dev /usr/lib/python2.7/dist-packages/nova/network/linux_net.py:1422
2016-04-21 12:33:47.376 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] Running cmd (subprocess): mv /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:223
2016-04-21 12:33:47.382 2151 DEBUG oslo_concurrency.processutils [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] CMD "mv /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del" returned: 0 in 0.006s execute /usr/lib/python2.7/dist-packages/oslo_concurrency/processutils.py:254
2016-04-21 12:33:47.383 2151 INFO nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Deleting instance files /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del
2016-04-21 12:33:47.383 2151 INFO nova.virt.libvirt.driver [req-9731cbf7-46b5-4074-a53f-a6993f868d6e 3874aa8ef1a0488c85d269ced5cf6fd3 ea8ed6a98bd948889fa058fa6c29168a - - -] [instance: 9091834f-b695-4198-9e9b-1b17c65807fb] Deletion of /var/lib/nova/instances/9091834f-b695-4198-9e9b-1b17c65807fb_del complete

/var/log/libvirt/libvirtd.log (compute1):

2016-04-21 07:03:07.662+0000: 9539: info : libvirt version: 1.2.12, package: 1.2.12-0ubuntu14.2~cloud0
2016-04-21 07:03:07.662+0000: 9539: warning : processNicRxFilterChangedEvent:4221 : ignore NIC_RX_FILTER_CHANGED event for network device net0 in domain instance-0000002f
2016-04-21 07:03:46.411+0000: 1924: error : remoteAuthInteract:4276 : authentication failed: No authentication callback available
2016-04-21 07:03:46.411+0000: 1924: error : doPeer2PeerMigrate:4698 : operation failed: Failed to connect to remote libvirt URI qemu+tcp://compute2/system:authentication failed: No authentication callback available

/var/log/libvirt/libvirtd.log (compute2):

2016-04-21 07:03:13.255+0000: 9465: info : libvirt version: 1.2.12, package: 1.2.12-0ubuntu14.2~cloud0
2016-04-21 07:03:13.255+0000: 9465: warning : processNicRxFilterChangedEvent:4221 : ignore NIC_RX_FILTER_CHANGED event for network device net0 in domain instance-0000002d
2016-04-21 07:03:46.426+0000: 1913: error : virNetSocketReadWire:1579 : End of file while reading data: Input/output error

I am new at this and any help will be really appreciated.

Thanks.

Neha.